Merge "x-openstack-request-id logged twice in logs"

glanceclient/common/http.py

@@ -92,16 +92,6 @@ class _BaseHTTPClient(object):
         return data
 
     def _handle_response(self, resp):
-        # log request-id for each api cal
-        request_id = resp.headers.get('x-openstack-request-id')
-        if request_id:
-            LOG.debug('%(method)s call to glance-api for '
-                      '%(url)s used request id '
-                      '%(response_request_id)s',
-                      {'method': resp.request.method,
-                       'url': resp.url,
-                       'response_request_id': request_id})
-
         if not resp.ok:
             LOG.debug("Request returned failure status %s.", resp.status_code)
             raise exc.from_response(resp, resp.content)
@@ -274,6 +264,16 @@ class HTTPClient(_BaseHTTPClient):
                        {'endpoint': endpoint, 'e': e})
             raise exc.CommunicationError(message=message)
 
+        # log request-id for each api call
+        request_id = resp.headers.get('x-openstack-request-id')
+        if request_id:
+            LOG.debug('%(method)s call to image for '
+                      '%(url)s used request id '
+                      '%(response_request_id)s',
+                      {'method': resp.request.method,
+                       'url': resp.url,
+                       'response_request_id': request_id})
+
         resp, body_iter = self._handle_response(resp)
         self.log_http_response(resp)
         return resp, body_iter

glanceclient/tests/unit/test_http.py

@@ -14,7 +14,9 @@
 #    under the License.
 import functools
 import json
+import logging
 
+import fixtures
 from keystoneauth1 import session
 from keystoneauth1 import token_endpoint
 import mock
@@ -378,6 +380,22 @@ class TestClient(testtools.TestCase):
                         matchers.Not(matchers.MatchesRegex(token_regex)),
                         'token found in LOG.debug parameter')
 
+    def test_log_request_id_once(self):
+        logger = self.useFixture(fixtures.FakeLogger(level=logging.DEBUG))
+        data = "TEST"
+        path = '/v1/images/'
+        self.mock.get(self.endpoint + path, body=six.StringIO(data),
+                      headers={"Content-Type": "application/octet-stream",
+                               'x-openstack-request-id': "1234"})
+
+        resp, body = self.client.get(path)
+        self.assertIsInstance(body, types.GeneratorType)
+        self.assertEqual([data], list(body))
+        expected_log = ("GET call to image "
+                        "for http://example.com:9292/v1/images/ "
+                        "used request id 1234")
+        self.assertEqual(1, logger.output.count(expected_log))
+
     def test_expired_token_has_changed(self):
         # instantiate client with some token
         fake_token = b'fake-token'