From af658d0686fd6b61c9b4ada402156f31d7e1ab98 Mon Sep 17 00:00:00 2001 From: Abhishek Kekane Date: Wed, 22 Jun 2016 16:26:01 +0530 Subject: [PATCH] Log request-id for each api call Added support to log 'X-Openstack-Request-Id' or 'X-Compute-Request-Id' in case of Nova for each api call. If any python-*client which is using session is used from command line then following log will be logged on console if --debug flag is used. DEBUG (session:350) GET call to compute for http://10.232.48.201:8774/v2.1/servers/detail used request id req-c54b8f3e-a7e4-4085-a5e3-fd5244ef3ce5 If any python-*client which is using session is used in applications (e.g. Nova) then following log message will be logged in service logs. DEBUG keystoneauth.session [req-a6929d46-765c-44a9-8370-49ff0f1958ca admin admin] GET call to network for http://10.232.48.201:9696/v2.0/security-groups.json?id=040cc729-9086-4f41-8977-acb4ef71c7de used request id req-de6bfe07-22ac-4940-b65e-367cb0e8102d DocImpact: To use this feature user need to set 'default_log_levels' in third party application. For example in nova.conf 'default_log_levels' should be set as below: default_log_levels = keystoneauth1=DEBUG Closes-Bug: #1605488 Change-Id: If0c5a4eb7d51c601ba38149f846ebcd6116d18be --- keystoneauth1/session.py | 24 +++++++++++++++++++++ keystoneauth1/tests/unit/test_session.py | 27 ++++++++++++++++++++++++ 2 files changed, 51 insertions(+) diff --git a/keystoneauth1/session.py b/keystoneauth1/session.py index 42fa1f9f..32ff801d 100644 --- a/keystoneauth1/session.py +++ b/keystoneauth1/session.py @@ -605,6 +605,30 @@ class Session(object): resp = send(**kwargs) + # log callee and caller request-id for each api call + if log: + # service_name should be fetched from endpoint_filter if it is not + # present then use service_type as service_name. + service_name = None + if endpoint_filter: + service_name = endpoint_filter.get('service_name') + if not service_name: + service_name = endpoint_filter.get('service_type') + + # Nova uses 'x-compute-request-id' and other services like + # Glance, Cinder etc are using 'x-openstack-request-id' to store + # request-id in the header + request_id = (resp.headers.get('x-openstack-request-id') or + resp.headers.get('x-compute-request-id')) + if request_id: + logger.debug('%(method)s call to %(service_name)s for ' + '%(url)s used request id ' + '%(response_request_id)s', + {'method': resp.request.method, + 'service_name': service_name, + 'url': resp.url, + 'response_request_id': request_id}) + # handle getting a 401 Unauthorized response by invalidating the plugin # and then retrying the request. This is only tried once. if resp.status_code == 401 and authenticated and allow_reauth: diff --git a/keystoneauth1/tests/unit/test_session.py b/keystoneauth1/tests/unit/test_session.py index 4486feef..c46ff098 100644 --- a/keystoneauth1/tests/unit/test_session.py +++ b/keystoneauth1/tests/unit/test_session.py @@ -218,6 +218,33 @@ class SessionTests(utils.TestCase): self.assertEqual(v, resp.headers[k]) self.assertNotIn(v, self.logger.output) + def test_session_debug_output_logs_openstack_request_id(self): + """Test x-openstack-request-id is logged in debug logs.""" + def get_response(log=True): + session = client_session.Session(verify=False) + endpoint_filter = {'service_name': 'Identity'} + headers = {'X-OpenStack-Request-Id': 'req-1234'} + body = 'BODYRESPONSE' + data = 'BODYDATA' + all_headers = dict(itertools.chain(headers.items())) + self.stub_url('POST', text=body, headers=all_headers) + resp = session.post(self.TEST_URL, endpoint_filter=endpoint_filter, + headers=all_headers, data=data, log=log) + return resp + + # if log is disabled then request-id is not logged in debug logs + resp = get_response(log=False) + self.assertEqual(resp.status_code, 200) + + expected_log = ('POST call to Identity for %s used request ' + 'id req-1234' % self.TEST_URL) + self.assertNotIn(expected_log, self.logger.output) + + # if log is enabled then request-id is logged in debug logs + resp = get_response() + self.assertEqual(resp.status_code, 200) + self.assertIn(expected_log, self.logger.output) + def test_logs_failed_output(self): """Test that output is logged even for failed requests.""" session = client_session.Session()