Log request_id for each api call

Add the function to log 'x-openstack-request-id' or
'x-compute-request-id' in each API call.
If the caller (e.g. heat) uses oslo.log,
the caller's request id in oslo.context and
the callee's request id can be output in the same
log message (same line).

Change-Id: I29312ce278ecfae41a688a0ddf76c24cfa0eaf6b
Implements: blueprint log-request-id

novaclient/client.py

@@ -73,6 +73,18 @@ class _ClientConnectionPool(object):
         return self._adapters[url]
 
 
+def _log_request_id(logger, resp, service_name):
+    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})
+
+
 class SessionClient(adapter.LegacyJsonAdapter):
 
     def __init__(self, *args, **kwargs):
@@ -93,6 +105,11 @@ class SessionClient(adapter.LegacyJsonAdapter):
                                                             method,
                                                             raise_exc=False,
                                                             **kwargs)
+
+        # if service name is None then use service_type for logging
+        service = self.service_name or self.service_type
+        _log_request_id(self.logger, resp, service)
+
         # TODO(andreykurilin): uncomment this line, when we will be able to
         #   check only nova-related calls
         # api_versions.check_headers(resp, self.api_version)
@@ -142,7 +159,8 @@ class HTTPClient(object):
                  http_log_debug=False, auth_system='keystone',
                  auth_plugin=None, auth_token=None,
                  cacert=None, tenant_id=None, user_id=None,
-                 connection_pool=False, api_version=None):
+                 connection_pool=False, api_version=None,
+                 logger=None):
         self.user = user
         self.user_id = user_id
         self.password = password
@@ -203,9 +221,10 @@ class HTTPClient(object):
         self.auth_plugin = auth_plugin
         self._session = None
         self._current_url = None
-        self._logger = logging.getLogger(__name__)
+        self._logger = logger or logging.getLogger(__name__)
 
-        if self.http_log_debug and not self._logger.handlers:
+        if (self.http_log_debug and logger is None and
+                not self._logger.handlers):
             # Logging level is already set on the root logger
             ch = logging.StreamHandler()
             self._logger.addHandler(ch)
@@ -320,6 +339,10 @@ class HTTPClient(object):
                                           'headers': resp.headers,
                                           'text': json.dumps(body)})
 
+        # if service name is None then use service_type for logging
+        service = self.service_name or self.service_type
+        _log_request_id(self._logger, resp, service)
+
     def open_session(self):
         if not self._connection_pool:
             self._session = requests.Session()
@@ -706,6 +729,7 @@ def _construct_http_client(username=None, password=None, project_id=None,
     else:
         # FIXME(jamielennox): username and password are now optional. Need
         # to test that they were provided in this mode.
+        logger = kwargs.get('logger')
         return HTTPClient(username,
                           password,
                           user_id=user_id,
@@ -730,7 +754,8 @@ def _construct_http_client(username=None, password=None, project_id=None,
                           http_log_debug=http_log_debug,
                           cacert=cacert,
                           connection_pool=connection_pool,
-                          api_version=api_version)
+                          api_version=api_version,
+                          logger=logger)
 
 
 def discover_extensions(version, only_contrib=False):

novaclient/shell.py

@@ -380,6 +380,9 @@ class NovaClientArgumentParser(argparse.ArgumentParser):
 class OpenStackComputeShell(object):
     times = []
 
+    def __init__(self):
+        self.client_logger = None
+
     def _append_global_identity_args(self, parser, argv):
         # Register the CLI arguments that have moved to the session object.
         loading.register_session_argparse_arguments(parser)
@@ -698,6 +701,11 @@ class OpenStackComputeShell(object):
                             format=streamformat)
         logging.getLogger('iso8601').setLevel(logging.WARNING)
 
+        self.client_logger = logging.getLogger(client.__name__)
+        ch = logging.StreamHandler()
+        self.client_logger.setLevel(logging.DEBUG)
+        self.client_logger.addHandler(ch)
+
     def main(self, argv):
         # Parse args once to find version and debug settings
         parser = self.get_base_parser(argv)
@@ -892,7 +900,8 @@ class OpenStackComputeShell(object):
             timings=args.timings, bypass_url=bypass_url,
             os_cache=os_cache, http_log_debug=args.debug,
             cacert=cacert, timeout=timeout,
-            session=keystone_session, auth=keystone_auth)
+            session=keystone_session, auth=keystone_auth,
+            logger=self.client_logger)
 
         if not skip_auth:
             if not api_version.is_latest():

novaclient/tests/unit/test_client.py

@@ -443,7 +443,8 @@ class ClientTest(utils.TestCase):
 class SessionClientTest(utils.TestCase):
 
     @mock.patch.object(adapter.LegacyJsonAdapter, 'request')
-    def test_timings(self, m_request):
+    @mock.patch.object(novaclient.client, '_log_request_id')
+    def test_timings(self, mock_log_request_id, m_request):
         m_request.return_value = (mock.MagicMock(status_code=200), None)
 
         client = novaclient.client.SessionClient(session=mock.MagicMock())
@@ -456,6 +457,17 @@ class SessionClientTest(utils.TestCase):
         self.assertEqual(1, len(client.times))
         self.assertEqual('GET http://no.where', client.times[0][0])
 
+    @mock.patch.object(adapter.LegacyJsonAdapter, 'request')
+    @mock.patch.object(novaclient.client, '_log_request_id')
+    def test_log_request_id(self, mock_log_request_id, mock_request):
+        response = mock.MagicMock(status_code=200)
+        mock_request.return_value = (response, None)
+        client = novaclient.client.SessionClient(session=mock.MagicMock(),
+                                                 service_name='compute')
+        client.request("http://no.where", 'GET')
+        mock_log_request_id.assert_called_once_with(client.logger, response,
+                                                    'compute')
+
 
 class DiscoverExtensionTest(utils.TestCase):
 

novaclient/tests/unit/test_http.py

@@ -71,15 +71,16 @@ retry_after_non_supporting_mock_request = mock.Mock(
     return_value=retry_after_non_supporting_response)
 
 
-def get_client():
+def get_client(**kwargs):
     cl = client.HTTPClient("username", "password",
                            "project_id",
-                           utils.AUTH_URL_V2)
+                           utils.AUTH_URL_V2,
+                           **kwargs)
     return cl
 
 
-def get_authed_client():
+def get_authed_client(**kwargs):
-    cl = get_client()
+    cl = get_client(**kwargs)
     cl.management_url = "http://example.com"
     cl.auth_token = "token"
     cl.get_service_url = mock.Mock(return_value="http://example.com")
@@ -164,14 +165,16 @@ class ClientTest(utils.TestCase):
 
         test_refused_call()
 
-    def test_client_logger(self):
+    @mock.patch.object(requests, "request", mock_request)
-        cl1 = client.HTTPClient("username", "password", "project_id",
+    @mock.patch.object(client, '_log_request_id')
-                                "auth_test", http_log_debug=True)
+    @mock.patch.object(client.HTTPClient, 'http_log_req')
-        self.assertEqual(1, len(cl1._logger.handlers))
+    def test_client_logger(self, mock_http_log_req, mock_log_request_id):
+        cl = get_authed_client(service_name='compute', http_log_debug=True)
+        self.assertIsNotNone(cl._logger)
 
-        cl2 = client.HTTPClient("username", "password", "project_id",
+        cl.post("/hi", body=[1, 2, 3])
-                                "auth_test", http_log_debug=True)
+        mock_log_request_id.assert_called_once_with(cl._logger, fake_response,
-        self.assertEqual(1, len(cl2._logger.handlers))
+                                                    'compute')
 
     @mock.patch.object(requests, 'request', unknown_error_mock_request)
     def test_unknown_server_error(self):

novaclient/v2/client.py

@@ -13,6 +13,8 @@
 #    License for the specific language governing permissions and limitations
 #    under the License.
 
+import logging
+
 from novaclient import api_versions
 from novaclient import client
 from novaclient.i18n import _LW
@@ -67,7 +69,7 @@ class Client(object):
                  auth_system='keystone', auth_plugin=None, auth_token=None,
                  cacert=None, tenant_id=None, user_id=None,
                  connection_pool=False, session=None, auth=None,
-                 api_version=None, direct_use=True, **kwargs):
+                 api_version=None, direct_use=True, logger=None, **kwargs):
         """Initialization of Client object.
 
         :param str username: Username
@@ -99,6 +101,8 @@ class Client(object):
         :param str session: Session
         :param str auth: Auth
         :param api_version: Compute API version
+        :param direct_use: Direct use
+        :param logger: Logger
         :type api_version: novaclient.api_versions.APIVersion
         """
         if direct_use:
@@ -174,6 +178,9 @@ class Client(object):
                     setattr(self, extension.name,
                             extension.manager_class(self))
 
+        if not logger:
+            logger = logging.getLogger(__name__)
+
         self.client = client._construct_http_client(
             username=username,
             password=password,
@@ -202,6 +209,7 @@ class Client(object):
             session=session,
             auth=auth,
             api_version=api_version,
+            logger=logger,
             **kwargs)
 
     @client._original_only

releasenotes/notes/log-request-id-ce106497e0520fad.yaml

@@ -0,0 +1,11 @@
+---
+prelude: >
+  - Log 'x-openstack-request-id' or 'x-compute-request-id'
+    in each API call. If the caller (e.g. heat) uses oslo.log,
+    the caller's request id in oslo.context and the callee's
+    request id can be output in the same log message (same line).
+features:
+  - Log 'x-openstack-request-id' or 'x-compute-request-id'
+    in each API call. If the caller (e.g. heat) uses oslo.log,
+    the caller's request id in oslo.context and the callee's
+    request id can be output in the same log message (same line).