From 87e4f7646faac97b179a71e4f2221ad646644535 Mon Sep 17 00:00:00 2001
From: Abhishek Kekane <abhishek.kekane@nttdata.com>
Date: Wed, 18 Jan 2017 12:38:26 +0530
Subject: [PATCH] x-openstack-request-id logged twice in logs

In the recent release of keystoneauth1 2.18.0 provision is made to log
x-openstack-request-id for session client. Once this new library is synced
in openstack projects, the x-openstack-request-id will be logged twice
on the console if session client is used.

For example,
$ glance --debug image-list

DEBUG:keystoneauth.session:GET call to image for
http://10.232.48.204:9292/v2/schemas/image used request id
req-96a3f203-c605-4c96-a31d-f1199d41705c

DEBUG:glanceclient.common.http:GET call to glance-api for
http://10.232.48.204:9292/v2/schemas/image used request id
req-96a3f203-c605-4c96-a31d-f1199d41705c

Above log will be logged twice on the console.

Removed logging of x-openstack-request-id in case of SessionClient as it
is already logged in keystoneauth1. x-openstack-request-id will only be
logged once on console if HTTPClient is used.

Depends-On: I492b331ff3da8d0b91178bf0d5fe1d3702f15bd7
Closes-Bug: #1657351
Change-Id: I64258f997dc060113f53682aee74bdd40a346e54
---
 glanceclient/common/http.py          | 20 ++++++++++----------
 glanceclient/tests/unit/test_http.py | 18 ++++++++++++++++++
 2 files changed, 28 insertions(+), 10 deletions(-)

diff --git a/glanceclient/common/http.py b/glanceclient/common/http.py
index 67a8d067..f169a23b 100644
--- a/glanceclient/common/http.py
+++ b/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
diff --git a/glanceclient/tests/unit/test_http.py b/glanceclient/tests/unit/test_http.py
index ae192317..a806ce79 100644
--- a/glanceclient/tests/unit/test_http.py
+++ b/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'