Hide Forgot
When debugging problems it would be helpful to know in a response what the request ID was so that it is easier to find it when searching Candlepin log files. This request is to return a new HTTP header that includes the request id on every http request to Candlepin.
I think this RFE may have already been implemented then removed then enabled again. The most recent record of it I have found is the following bug: https://bugzilla.redhat.com/show_bug.cgi?id=1173139 As can be seen from Filip's comments it seems that this feature still exists. I believe the only change necessary here is to ensure that python-rhsm logs the request uuid with every request.
I'm moving this to subscription-manager with an update that this header should always be logged with the request response. This value is being returned in the x-candlepin-request-uuid header.
This is implemented in upstream already. I think the only RFE here might be to log what method and handler were used in the request along with the request ID (in the same log message). The logic for this is there can be a lot being written to the rhsm.log at the same time. This makes it a bit hard to see what method and handler a particular request went with. Another potential change would be to reduce the log level from DEBUG to INFO on this particular log statement. Other than the above there appears to be nothing to do for this RFE.
Demonstrating that on RHEL 73 , the rhsm.log didnot contain any request IDs ========================================================================== # subscription-manager version server type: Red Hat Subscription Management subscription management server: 0.9.51.21-1 subscription management rules: 5.15.1 subscription-manager: 1.17.15-1.el7 python-rhsm: 1.17.9-1.el7 [root@dhcp35-220 ~]# subscription-manager register Registering to: subscription.rhn.stage.redhat.com:443/subscription Username:stage_test_rhel74 Password: 2017-05-09 13:31:21,090 [INFO] subscription-manager:27433:MainThread @managercli.py:384 - Client Versions: {'python-rhsm': '1.17.9-1.el7', 'subscription-manager': '1.17.15-1.el7'} 2017-05-09 13:31:21,091 [INFO] subscription-manager:27433:MainThread @connection.py:830 - Connection built: host=subscription.rhn.stage.redhat.com port=443 handler=/subscription auth=identity_cert ca_dir=/etc/rhsm/ca/ verify=False 2017-05-09 13:31:21,091 [INFO] subscription-manager:27433:MainThread @connection.py:830 - Connection built: host=subscription.rhn.stage.redhat.com port=443 handler=/subscription auth=none 2017-05-09 13:31:21,092 [INFO] subscription-manager:27433:MainThread @managercli.py:384 - Client Versions: {'python-rhsm': '1.17.9-1.el7', 'subscription-manager': '1.17.15-1.el7'} 2017-05-09 13:31:21,104 [INFO] subscription-manager:27433:MainThread @managercli.py:359 - Consumer Identity name=None uuid=None 2017-05-09 13:31:21,108 [INFO] subscription-manager:27433:MainThread @managercli.py:359 - Consumer Identity name=None uuid=None 2017-05-09 13:31:30,169 [INFO] subscription-manager:27433:MainThread @connection.py:830 - Connection built: host=subscription.rhn.stage.redhat.com port=443 handler=/subscription auth=basic username=stage_test_rhel74 2017-05-09 13:31:30,235 [INFO] subscription-manager:27433:MainThread @hwprobe.py:916 - collected virt facts: virt.is_guest=True, virt.host_type=kvm, virt.uuid=d5700f2b-0cf9-e976-f085-ee83f3510c31 The system has been registered with ID: fd6ecf3d-717e-42e4-a913-ce3124dcd282 2017-05-09 13:31:38,240 [INFO] subscription-manager:27433:MainThread @managerlib.py:77 - Consumer created: {'consumer_name': 'dhcp35-220.lab.eng.blr.redhat.com', 'uuid': 'fd6ecf3d-717e-42e4-a913-ce3124dcd282'} 2017-05-09 13:31:38,243 [INFO] subscription-manager:27433:MainThread @connection.py:830 - Connection built: host=subscription.rhn.stage.redhat.com port=443 handler=/subscription auth=identity_cert ca_dir=/etc/rhsm/ca/ verify=False 2017-05-09 13:31:40,904 [INFO] subscription-manager:27433:MainThread @managercli.py:395 - Server Versions: {'rules-version': '5.15.1', 'candlepin': '0.9.51.21-1', 'server-type': 'Red Hat Subscription Management'} 2017-05-09 13:31:42,155 [INFO] rhsmd:27472:MainThread @rhsmd:261 - rhsmd started 2017-05-09 13:31:42,268 [INFO] rhsmd:27472:MainThread @connection.py:830 - Connection built: host=subscription.rhn.stage.redhat.com port=443 handler=/subscription auth=identity_cert ca_dir=/etc/rhsm/ca/ verify=False 2017-05-09 13:31:43,785 [INFO] rhsmd:27472:MainThread @cert_sorter.py:205 - Product status: valid_products= partial_products= expired_products= unentitled_producs=69 and 251 future_products= valid_until=None 2017-05-09 13:31:45,950 [INFO] subscription-manager:27433:MainThread @cert_sorter.py:205 - Product status: valid_products= partial_products= expired_products= unentitled_producs=69 and 251 future_products= valid_until=None 2017-05-09 13:31:46,084 [INFO] rhsmd:27485:MainThread @rhsmd:261 - rhsmd started 2017-05-09 13:31:46,134 [INFO] rhsmd:27485:MainThread @connection.py:830 - Connection built: host=subscription.rhn.stage.redhat.com port=443 handler=/subscription auth=identity_cert ca_dir=/etc/rhsm/ca/ verify=False 2017-05-09 13:31:47,640 [INFO] rhsmd:27485:MainThread @cert_sorter.py:205 - Product status: valid_products= partial_products= expired_products= unentitled_producs=69 and 251 future_products= valid_until=None ^^ No requestIDs displayed in the rhsm.log Retesting with RHEL 74 ====================== # subscription-manager version server type: Red Hat Subscription Management subscription management server: 0.9.51.21-1 subscription management rules: 5.15.1 subscription-manager: 1.19.12-1.el7 python-rhsm: 1.19.6-1.el7 [root@dhcp151-211 ~]# subscription-manager register Registering to: subscription.rhsm.stage.redhat.com:443/subscription Username:stage_test_rhel74 Password: rhsm.log ========= 2017-05-09 03:59:20,450 [INFO] subscription-manager:28360:MainThread @managercli.py:522 - X-Correlation-ID: 3f7da34d4bf44b6d876b0c5e04548f21 2017-05-09 03:59:20,451 [INFO] subscription-manager:28360:MainThread @managercli.py:411 - Client Versions: {'python-rhsm': '1.19.6-1.el7', 'subscription-manager': '1.19.12-1.el7'} 2017-05-09 03:59:20,452 [INFO] subscription-manager:28360:MainThread @connection.py:780 - Connection built: host=subscription.rhsm.stage.redhat.com port=443 handler=/subscription auth=identity_cert ca_dir=/etc/rhsm/ca/ insecure=False 2017-05-09 03:59:20,453 [INFO] subscription-manager:28360:MainThread @connection.py:780 - Connection built: host=subscription.rhsm.stage.redhat.com port=443 handler=/subscription auth=none 2017-05-09 03:59:20,454 [INFO] subscription-manager:28360:MainThread @managercli.py:411 - Client Versions: {'python-rhsm': '1.19.6-1.el7', 'subscription-manager': '1.19.12-1.el7'} 2017-05-09 03:59:20,472 [INFO] subscription-manager:28360:MainThread @managercli.py:386 - Consumer Identity name=None uuid=None 2017-05-09 03:59:20,474 [INFO] subscription-manager:28360:MainThread @managercli.py:386 - Consumer Identity name=None uuid=None 2017-05-09 03:59:34,462 [INFO] subscription-manager:28360:MainThread @connection.py:780 - Connection built: host=subscription.rhsm.stage.redhat.com port=443 handler=/subscription auth=basic username=stage_test_rhel74 2017-05-09 03:59:34,497 [INFO] subscription-manager:28360:MainThread @dmiinfo.py:75 - Using dmidecode dump file: /dev/mem 2017-05-09 03:59:36,342 [INFO] subscription-manager:28360:MainThread @connection.py:520 - Response: status=200, requestUuid=4fbbd0ba-abd0-4c08-b1f5-304dd198434f, request="GET /subscription/users/stage_test_rhel74/owners" 2017-05-09 03:59:36,797 [INFO] subscription-manager:28360:MainThread @connection.py:520 - Response: status=200, request="GET /subscription/" The system has been registered with ID: f4a4b498-4167-4535-aa3e-ca0f70692222 2017-05-09 03:59:38,953 [INFO] subscription-manager:28360:MainThread @connection.py:520 - Response: status=200, requestUuid=73f957fc-556d-4365-b9a4-2da42c708692, request="POST /subscription/consumers?owner=10917755" 2017-05-09 03:59:38,958 [INFO] subscription-manager:28360:MainThread @managerlib.py:76 - Consumer created: {'consumer_name': u'dhcp151-211.mpc.lab.eng.bos.redhat.com', 'uuid': 'f4a4b498-4167-4535-aa3e-ca0f70692222'} 2017-05-09 03:59:38,960 [INFO] subscription-manager:28360:MainThread @connection.py:780 - Connection built: host=subscription.rhsm.stage.redhat.com port=443 handler=/subscription auth=identity_cert ca_dir=/etc/rhsm/ca/ insecure=False 2017-05-09 03:59:39,418 [INFO] subscription-manager:28360:MainThread @connection.py:520 - Response: status=200, request="GET /subscription/" 2017-05-09 03:59:39,992 [INFO] subscription-manager:28360:MainThread @connection.py:520 - Response: status=200, requestUuid=3aa6dee6-964c-4bf5-9a57-67f1152f1157, request="GET /subscription/status" 2017-05-09 03:59:39,993 [INFO] subscription-manager:28360:MainThread @managercli.py:422 - Server Versions: {'rules-version': u'5.15.1', 'candlepin': u'0.9.51.21-1', 'server-type': 'Red Hat Subscription Management'} 2017-05-09 03:59:40,451 [INFO] subscription-manager:28360:MainThread @connection.py:520 - Response: status=200, request="GET /subscription/" 2017-05-09 03:59:41,515 [INFO] subscription-manager:28360:MainThread @connection.py:520 - Response: status=204, request="PUT /subscription/consumers/f4a4b498-4167-4535-aa3e-ca0f70692222/packages" 2017-05-09 03:59:42,137 [INFO] subscription-manager:28360:MainThread @connection.py:520 - Response: status=200, requestUuid=64e7adbc-d378-40b2-8626-cce2e74682b1, request="GET /subscription/status" 2017-05-09 03:59:42,138 [INFO] subscription-manager:28360:MainThread @managercli.py:1260 - System registered, updating entitlements if needed 2017-05-09 03:59:42,762 [INFO] subscription-manager:28360:MainThread @connection.py:520 - Response: status=200, requestUuid=586db60a-d91c-4056-a51f-ed08e642b88f, request="GET /subscription/consumers/f4a4b498-4167-4535-aa3e-ca0f70692222/certificates/serials" 2017-05-09 03:59:42,763 [INFO] subscription-manager:28360:MainThread @entcertlib.py:130 - certs updated: Total updates: 0 Found (local) serial# [] Expected (UEP) serial# [] Added (new) <NONE> Deleted (rogue): <NONE> 2017-05-09 03:59:43,388 [INFO] subscription-manager:28360:MainThread @connection.py:520 - Response: status=200, requestUuid=8c61089a-215a-4b85-87d5-d7893750e312, request="GET /subscription/consumers/f4a4b498-4167-4535-aa3e-ca0f70692222/compliance" 2017-05-09 03:59:43,390 [INFO] subscription-manager:28360:MainThread @cert_sorter.py:205 - Product status: valid_products= partial_products= expired_products= unentitled_producs=69 future_products= valid_until=None 2017-05-09 03:59:43,905 [INFO] rhsmd:26295:MainThread @connection.py:780 - Connection built: host=subscription.rhsm.stage.redhat.com port=443 handler=/subscription auth=identity_cert ca_dir=/etc/rhsm/ca/ insecure=False 2017-05-09 03:59:44,532 [INFO] rhsmd:26295:MainThread @connection.py:520 - Response: status=200, requestUuid=15bb9d3f-f5c5-4144-abff-a225cde52c9e, request="GET /subscription/consumers/f4a4b498-4167-4535-aa3e-ca0f70692222/compliance" ^^ Observed that now request UUIDS are printed in the rhsm.log with "INFO" level Moving the bug to Verified!!
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHBA-2017:2083