Merge "Log request-id for each api call"

keystoneauth1/session.py

@@ -608,6 +608,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:

keystoneauth1/tests/unit/test_session.py

@@ -219,6 +219,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()