Bug 1375858 - Clock skew warning is missing in rhsm.log when the system's clock behind the candlepin server's clock by big time drift.
Summary: Clock skew warning is missing in rhsm.log when the system's clock behind the ...
Keywords:
Status: CLOSED WORKSFORME
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: subscription-manager
Version: 7.3
Hardware: Unspecified
OS: Unspecified
medium
medium
Target Milestone: rc
: ---
Assignee: William Poteat
QA Contact: John Sefler
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-09-14 06:43 UTC by qianzhan
Modified: 2016-09-27 03:32 UTC (History)
5 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2016-09-27 03:32:51 UTC
Target Upstream Version:


Attachments (Terms of Use)

Description qianzhan 2016-09-14 06:43:50 UTC
Description of problem:
Clock skew warning is missing in rhsm.log when the system's clock behind the candlepin server's clock by is big drift.

Version-Release number of selected component (if applicable):
subscription-manager: 1.17.14-1.el7
python-rhsm: 1.17.9-1.el7
Satellite-6.2.0-RHEL-7-20160831.0

How reproducible:
always

Steps to Reproduce:
1. Make sure the same system times on RHEL7.3 and Satellite-6.2.0-RHEL-7-20160831.0.

2. Register RHEL7.3 against Satellite-6.2.0-RHEL-7-20160831.0
[root@dhcp-128-34 ~]# subscription-manager register
Registering to: tyan-gt24-03.rhts.eng.bos.redhat.com:443/rhsm
Username: admin
Password: 
The system has been registered with ID: ad87ef59-a8b1-46fc-b7d0-1b69f025692e 


3. Make the system's clock behind the candlepin server's clock by 7 hours.
[root@dhcp-128-34 ~]#  date -s "-7 hours"
Tue Sep 13 19:33:14 EDT 2016


4. Make response from the server, and check rhsm.log

[root@dhcp-128-34 ~]# subscription-manager version
server type: Red Hat Subscription Management
subscription management server: Unknown
subscription management rules: Unknown
subscription-manager: 1.17.14-1.el7
python-rhsm: 1.17.9-1.el7

[root@dhcp-128-34 ~]# cat /var/log/rhsm/rhsm.log
2016-09-14 02:31:45,020 [INFO] subscription-manager:5050:MainThread @managercli.py:384 - Client Versions: {'python-rhsm': '1.17.9-1.el7', 'subscription-manager': '1.17.14-1.el7'}
2016-09-14 02:31:45,021 [INFO] subscription-manager:5050:MainThread @connection.py:830 - Connection built: host=tyan-gt24-03.rhts.eng.bos.redhat.com port=443 handler=/rhsm auth=identity_cert ca_dir=/etc/rhsm/ca/ verify=False
2016-09-14 02:31:45,021 [INFO] subscription-manager:5050:MainThread @connection.py:830 - Connection built: host=tyan-gt24-03.rhts.eng.bos.redhat.com port=443 handler=/rhsm auth=none
2016-09-14 02:31:45,021 [INFO] subscription-manager:5050:MainThread @managercli.py:384 - Client Versions: {'python-rhsm': '1.17.9-1.el7', 'subscription-manager': '1.17.14-1.el7'}
2016-09-14 02:31:45,030 [INFO] subscription-manager:5050:MainThread @managercli.py:359 - Consumer Identity name=None uuid=None
2016-09-14 02:31:45,030 [INFO] subscription-manager:5050:MainThread @managercli.py:359 - Consumer Identity name=None uuid=None
2016-09-14 02:31:47,699 [INFO] subscription-manager:5050:MainThread @connection.py:830 - Connection built: host=tyan-gt24-03.rhts.eng.bos.redhat.com port=443 handler=/rhsm auth=basic username=admin
2016-09-14 02:31:48,180 [INFO] subscription-manager:5050:MainThread @hwprobe.py:916 - collected virt facts: virt.is_guest=True, virt.host_type=kvm, virt.uuid=c6de79c8-1c11-e213-48e9-6b6e7f71ec30
2016-09-14 02:32:00,142 [INFO] subscription-manager:5050:MainThread @managerlib.py:77 - Consumer created: {'consumer_name': 'dhcp-128-34.nay.redhat.com', 'uuid': 'ad87ef59-a8b1-46fc-b7d0-1b69f025692e'}
2016-09-14 02:32:00,142 [INFO] subscription-manager:5050:MainThread @connection.py:830 - Connection built: host=tyan-gt24-03.rhts.eng.bos.redhat.com port=443 handler=/rhsm auth=identity_cert ca_dir=/etc/rhsm/ca/ verify=False
2016-09-14 02:32:04,236 [INFO] subscription-manager:5050:MainThread @managercli.py:395 - Server Versions: {'rules-version': '5.15.2', 'candlepin': '3.0.0.78-Unknown', 'server-type': 'Red Hat Subscription Management'}
2016-09-14 02:32:18,687 [INFO] subscription-manager:5050:MainThread @cert_sorter.py:205 - Product status: valid_products= partial_products= expired_products= unentitled_producs= future_products= valid_until=None
2016-09-14 02:32:19,040 [INFO] rhsmd:5088:MainThread @rhsmd:261 - rhsmd started
2016-09-14 02:32:19,104 [INFO] rhsmd:5088:MainThread @connection.py:830 - Connection built: host=tyan-gt24-03.rhts.eng.bos.redhat.com port=443 handler=/rhsm auth=identity_cert ca_dir=/etc/rhsm/ca/ verify=False
2016-09-14 02:32:21,174 [INFO] rhsmd:5088:MainThread @cert_sorter.py:205 - Product status: valid_products= partial_products= expired_products= unentitled_producs= future_products= valid_until=None
2016-09-13 19:33:23,631 [INFO] subscription-manager:5112:MainThread @managercli.py:384 - Client Versions: {'python-rhsm': '1.17.9-1.el7', 'subscription-manager': '1.17.14-1.el7'}
2016-09-13 19:33:23,632 [INFO] subscription-manager:5112:MainThread @connection.py:830 - Connection built: host=tyan-gt24-03.rhts.eng.bos.redhat.com port=443 handler=/rhsm auth=identity_cert ca_dir=/etc/rhsm/ca/ verify=False
2016-09-13 19:33:23,632 [INFO] subscription-manager:5112:MainThread @connection.py:830 - Connection built: host=tyan-gt24-03.rhts.eng.bos.redhat.com port=443 handler=/rhsm auth=none
2016-09-13 19:33:24,268 [ERROR] subscription-manager:5112:MainThread @utils.py:273 - Error while checking server version: certificate verify failed
2016-09-13 19:33:24,268 [ERROR] subscription-manager:5112:MainThread @utils.py:275 - certificate verify failed
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/subscription_manager/utils.py", line 253, in get_server_versions
    if cp.supports_resource("status"):
  File "/usr/lib64/python2.7/site-packages/rhsm/connection.py", line 856, in supports_resource
    self._load_supported_resources()
  File "/usr/lib64/python2.7/site-packages/rhsm/connection.py", line 843, in _load_supported_resources
    resources_list = self.conn.request_get("/")
  File "/usr/lib64/python2.7/site-packages/rhsm/connection.py", line 694, in request_get
    return self._request("GET", method)
  File "/usr/lib64/python2.7/site-packages/rhsm/connection.py", line 584, in _request
    conn.request(request_type, handler, body=body, headers=headers)
  File "/usr/lib64/python2.7/httplib.py", line 1017, in request
    self._send_request(method, url, body, headers)
  File "/usr/lib64/python2.7/httplib.py", line 1051, in _send_request
    self.endheaders(body)
  File "/usr/lib64/python2.7/httplib.py", line 1013, in endheaders
    self._send_output(message_body)
  File "/usr/lib64/python2.7/httplib.py", line 864, in _send_output
    self.send(msg)
  File "/usr/lib64/python2.7/httplib.py", line 826, in send
    self.connect()
  File "/usr/lib64/python2.7/site-packages/rhsm/connection.py", line 250, in connect
    sock.connect((self.host, self.port))
  File "/usr/lib64/python2.7/site-packages/M2Crypto/SSL/Connection.py", line 185, in connect
    ret = self.connect_ssl()
  File "/usr/lib64/python2.7/site-packages/M2Crypto/SSL/Connection.py", line 178, in connect_ssl
    return m2.ssl_connect(self.ssl, self._timeout)
SSLError: certificate verify failed
2016-09-13 19:33:24,270 [INFO] subscription-manager:5112:MainThread @managercli.py:395 - Server Versions: {'rules-version': 'Unknown', 'candlepin': 'Unknown', 'server-type': 'Red Hat Subscription Management'}

5. Make the system's clock behind the candlepin server's clock by 7 hours.
[root@dhcp-128-34 ~]#  date -s "+14 hours"
Wed Sep 14 09:37:09 EDT 2016
[root@dhcp-128-34 ~]# rm -f /var/log/rhsm/rhsm.log

6. Make response from the server, and check rhsm.log
[root@dhcp-128-34 ~]# subscription-manager version
server type: Red Hat Subscription Management
subscription management server: 3.0.0.78-Unknown
subscription management rules: 5.15.2
subscription-manager: 1.17.14-1.el7
python-rhsm: 1.17.9-1.el7

[root@dhcp-128-34 ~]# cat /var/log/rhsm/rhsm.log
2016-09-14 09:37:21,513 [INFO] subscription-manager:5159:MainThread @managercli.py:384 - Client Versions: {'python-rhsm': '1.17.9-1.el7', 'subscription-manager': '1.17.14-1.el7'}
2016-09-14 09:37:21,514 [INFO] subscription-manager:5159:MainThread @connection.py:830 - Connection built: host=tyan-gt24-03.rhts.eng.bos.redhat.com port=443 handler=/rhsm auth=identity_cert ca_dir=/etc/rhsm/ca/ verify=False
2016-09-14 09:37:21,514 [INFO] subscription-manager:5159:MainThread @connection.py:830 - Connection built: host=tyan-gt24-03.rhts.eng.bos.redhat.com port=443 handler=/rhsm auth=none
2016-09-14 09:37:23,462 [WARNING] subscription-manager:5159:MainThread @connection.py:606 - Clock skew detected, please check your system time
2016-09-14 09:37:25,643 [WARNING] subscription-manager:5159:MainThread @connection.py:606 - Clock skew detected, please check your system time
2016-09-14 09:37:25,644 [INFO] subscription-manager:5159:MainThread @managercli.py:395 - Server Versions: {'rules-version': '5.15.2', 'candlepin': '3.0.0.78-Unknown', 'server-type': 'Red Hat Subscription Management'}
[root@dhcp-128-34 ~]# 


Actual results:
As step 4, no clock skew warning in rhsm.log.

Expected results:
The results of step should be the same with that of step 6: clock skew warning is needed.

Additional info:

Comment 2 William Poteat 2016-09-26 14:54:48 UTC
I see the same messaging in both skew directions

2016-09-26 03:52:53,088 [INFO] subscription-manager:8869 @connection.py:830 - Connection built: host=wpoteat-desktop.usersys.redhat.com port=8443 handler=/candlepin auth=identity_cert ca_dir=/etc/rhsm/ca/ verify=True
2016-09-26 03:52:53,089 [INFO] subscription-manager:8869 @connection.py:830 - Connection built: host=wpoteat-desktop.usersys.redhat.com port=8443 handler=/candlepin auth=none
2016-09-26 03:52:53,110 [WARNING] subscription-manager:8869 @connection.py:606 - Clock skew detected, please check your system time
2016-09-26 03:52:53,133 [WARNING] subscription-manager:8869 @connection.py:606 - Clock skew detected, please check your system time
2016-09-26 03:52:53,135 [INFO] subscription-manager:8869 @managercli.py:395 - Server Versions: {'rules-version': '5.20', 'candlepin': '2.0.18-1', 'server-type': 'Red Hat Subscription Management'}
2016-09-26 17:53:26,437 [INFO] subscription-manager:8934 @managercli.py:384 - Client Versions: {'python-rhsm': '1.17.5-1.git.0.265c7c6.fc23', 'subscription-manager': '1.17.9-1.git.0.0914b4d.fc23'}
2016-09-26 17:53:26,438 [INFO] subscription-manager:8934 @connection.py:830 - Connection built: host=wpoteat-desktop.usersys.redhat.com port=8443 handler=/candlepin auth=identity_cert ca_dir=/etc/rhsm/ca/ verify=True
2016-09-26 17:53:26,439 [INFO] subscription-manager:8934 @connection.py:830 - Connection built: host=wpoteat-desktop.usersys.redhat.com port=8443 handler=/candlepin auth=none
2016-09-26 17:53:26,460 [WARNING] subscription-manager:8934 @connection.py:606 - Clock skew detected, please check your system time
2016-09-26 17:53:26,484 [WARNING] subscription-manager:8934 @connection.py:606 - Clock skew detected, please check your system time
2016-09-26 17:53:26,485 [INFO] subscription-manager:8934 @managercli.py:395 - Server Versions: {'rules-version': '5.20', 'candlepin': '2.0.18-1', 'server-type': 'Red Hat Subscription Management'}


Is there more information about the conditions of the test?

Comment 3 qianzhan 2016-09-27 03:32:51 UTC
(In reply to William Poteat from comment #2)
> I see the same messaging in both skew directions
> 
> 
> Is there more information about the conditions of the test?

I tried to reproduce this bug with Satellite-6.2.0-RHEL-7-20160907.6 and RHEL-7.3-Snapshot-5.0, but failed:

[root@dhcp-129-216 ~]# cat /var/log/rhsm/rhsm.log
2016-09-26 16:28:57,320 [INFO] subscription-manager:4626:MainThread @managercli.py:384 - Client Versions: {'python-rhsm': '1.17.9-1.el7', 'subscription-manager': '1.17.15-1.el7'}
2016-09-26 16:28:57,321 [INFO] subscription-manager:4626:MainThread @connection.py:830 - Connection built: host=hp-dl580g7-02.rhts.eng.bos.redhat.com port=443 handler=/rhsm auth=identity_cert ca_dir=/etc/rhsm/ca/ verify=False
2016-09-26 16:28:57,321 [INFO] subscription-manager:4626:MainThread @connection.py:830 - Connection built: host=hp-dl580g7-02.rhts.eng.bos.redhat.com port=443 handler=/rhsm auth=none
2016-09-26 16:28:59,261 [WARNING] subscription-manager:4626:MainThread @connection.py:606 - Clock skew detected, please check your system time
2016-09-26 16:29:01,424 [WARNING] subscription-manager:4626:MainThread @connection.py:606 - Clock skew detected, please check your system time
2016-09-26 16:29:01,425 [INFO] subscription-manager:4626:MainThread @managercli.py:395 - Server Versions: {'rules-version': '5.15.2', 'candlepin': '3.0.0.78-Unknown', 'server-type': 'Red Hat Subscription Management'}


So close this bug. When this issue is met again, I will reopen the bug.


Note You need to log in before you can comment on or make changes to this bug.