Bug 1393010 - [RFE] Log the candlepin request ID with the request response
Summary: [RFE] Log the candlepin request ID with the request response
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: subscription-manager
Version: 7.4
Hardware: Unspecified
OS: Unspecified
high
unspecified
Target Milestone: rc
: ---
Assignee: Chris Snyder
QA Contact: John Sefler
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2016-11-08 16:54 UTC by Barnaby Court
Modified: 2017-08-01 19:20 UTC (History)
6 users (show)

Fixed In Version:
Doc Type: Enhancement
Doc Text:
Clone Of:
Environment:
Last Closed: 2017-08-01 19:20:42 UTC
Target Upstream Version:


Attachments (Terms of Use)


Links
System ID Priority Status Summary Last Updated
Github candlepin python-rhsm pull 190 None None None 2016-11-16 21:46:30 UTC
Red Hat Bugzilla 1173139 None None None Never
Red Hat Product Errata RHBA-2017:2083 normal SHIPPED_LIVE python-rhsm and subscription-manager bug fix and enhancement update 2017-08-01 18:14:19 UTC

Internal Links: 1173139

Description Barnaby Court 2016-11-08 16:54:17 UTC
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.

Comment 1 Chris Snyder 2016-11-11 00:42:36 UTC
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.

Comment 2 Barnaby Court 2016-11-16 16:28:15 UTC
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.

Comment 3 Chris Snyder 2016-11-16 19:23:59 UTC
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.

Comment 6 Rehana 2017-05-09 14:57:27 UTC
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!!

Comment 7 errata-xmlrpc 2017-08-01 19:20:42 UTC
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


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