Merge "Log request_id for each api call"

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).