Only log application/json content typemitaka-eol2.3.2stable/mitaka

This is a combination of 2 commits. The first commit's
message is:

Prevent MemoryError when logging response bodies

Response bodies are loaded into memory prior to
being logged.

Loading huge response bodies may result in a
MemoryError.

This patch proposes that only JSON and TEXT
responses be logged, i.e when the Content-Type
header is application/json or application/text.

Responses that do not include or have a different
Content-Type header will have their body omitted.

This is a sort of backport of the fix for
keystoneauth sessions, see
I93b6fff73368c4f58bdebf8566c4948b50980cee

Co-Authored-By: Samuel de Medeiros Queiroz <samueldmq@gmail.com>

Closes-bug: 1616105

Change-Id: I8f43eee3a0b35041c6cf672e476f8151cf2f8d14
(cherry-picked from: 3e56e0d7e5e1a76d806a3bc1f6d5ef9070f95771)

Only log application/json in session to start

When whitelisting content types to debug print from session we chose
application/json and application/text. application/text is not a real
mime type, text is typically text/plain.

Rather than guess at mime types only print application/json to start
with, but make it easy for additional types to be added later.

Adapted from keystoneauth: Ica5fee076cdab8b1d5167161d28af7313fad9477
Related-Bug: 1616105

Change-Id: Ieaa8fb3ea8d25e09b89498f23b70b18c0f6153f1
(cherry-picked from: 51d16fa344829aadf454faf5e0c4535a8f96a7c8)

4 files changed, 93 insertions, 27 deletions

diff --git a/keystoneclient/session.py b/keystoneclient/session.py
index 43d04bd..5207952 100644
--- a/keystoneclient/session.py
+++ b/keystoneclient/session.py
@@ -37,6 +37,11 @@ osprofiler_web = importutils.try_import("osprofiler.web")
 
 USER_AGENT = 'python-keystoneclient'
 
+# NOTE(jamielennox): Clients will likely want to print more than json. Please
+# propose a patch if you have a content type you think is reasonable to print
+# here and we'll add it to the list as required.
+_LOG_CONTENT_TYPES = set(['application/json'])
+
 _logger = logging.getLogger(__name__)
 
 
@@ -221,7 +226,18 @@ class Session(object):
         if not logger.isEnabledFor(logging.DEBUG):
             return
 
-        text = _remove_service_catalog(response.text)
+        # NOTE(samueldmq): If the response does not provide enough info about
+        # the content type to decide whether it is useful and safe to log it
+        # or not, just do not log the body. Trying to# read the response body
+        # anyways may result on reading a long stream of bytes and getting an
+        # unexpected MemoryError. See bug 1616105 for further details.
+        content_type = response.headers.get('content-type', None)
+        if content_type in _LOG_CONTENT_TYPES:
+            text = _remove_service_catalog(response.text)
+        else:
+            text = ('Omitted, Content-Type is set to %s. Only '
+                    '%s responses have their bodies logged.')
+            text = text % (content_type, ', '.join(_LOG_CONTENT_TYPES))
 
         string_parts = [
             'RESP:',
@@ -229,9 +245,7 @@ class Session(object):
         ]
         for header in six.iteritems(response.headers):
             string_parts.append('%s: %s' % self._process_header(header))
-        if text:
-            string_parts.append('\nRESP BODY: %s\n' %
-                                strutils.mask_password(text))
+        string_parts.append('\nRESP BODY: %s\n' % strutils.mask_password(text))
 
         logger.debug(' '.join(string_parts))
 
diff --git a/keystoneclient/tests/unit/test_http.py b/keystoneclient/tests/unit/test_http.py
index 56f116c..6e0070a 100644
--- a/keystoneclient/tests/unit/test_http.py
+++ b/keystoneclient/tests/unit/test_http.py
@@ -166,22 +166,24 @@ class BasicRequestTests(utils.TestCase):
         self.addCleanup(self.logger.setLevel, level)
 
     def request(self, method='GET', response='Test Response', status_code=200,
-                url=None, **kwargs):
+                url=None, headers={}, **kwargs):
         if not url:
             url = self.url
 
         self.requests_mock.register_uri(method, url, text=response,
-                                        status_code=status_code)
+                                        status_code=status_code,
+                                        headers=headers)
 
         with self.deprecations.expect_deprecations_here():
-            return httpclient.request(url, method, **kwargs)
+            return httpclient.request(url, method, headers=headers, **kwargs)
 
     def test_basic_params(self):
         method = 'GET'
         response = 'Test Response'
         status = 200
 
-        self.request(method=method, status_code=status, response=response)
+        self.request(method=method, status_code=status, response=response,
+                     headers={'Content-Type': 'application/json'})
 
         self.assertEqual(self.requests_mock.last_request.method, method)
 
@@ -209,7 +211,8 @@ class BasicRequestTests(utils.TestCase):
 
     def test_body(self):
         data = "BODY DATA"
-        self.request(response=data)
+        self.request(response=data,
+                     headers={'Content-Type': 'application/json'})
         logger_message = self.logger_message.getvalue()
         self.assertThat(logger_message, matchers.Contains('BODY:'))
         self.assertThat(logger_message, matchers.Contains(data))
diff --git a/keystoneclient/tests/unit/test_session.py b/keystoneclient/tests/unit/test_session.py
index 40e1827..faa7da9 100644
--- a/keystoneclient/tests/unit/test_session.py
+++ b/keystoneclient/tests/unit/test_session.py
@@ -151,13 +151,14 @@ class SessionTests(utils.TestCase):
         in order to redact secure headers while debug is true.
         """
         session = client_session.Session(verify=False)
-        headers = {'HEADERA': 'HEADERVALB'}
+        headers = {'HEADERA': 'HEADERVALB',
+                   'Content-Type': 'application/json'}
         security_headers = {'Authorization': uuid.uuid4().hex,
                             'X-Auth-Token': uuid.uuid4().hex,
                             'X-Subject-Token': uuid.uuid4().hex,
                             'X-Service-Token': uuid.uuid4().hex}
-        body = 'BODYRESPONSE'
-        data = 'BODYDATA'
+        body = '{"a": "b"}'
+        data = '{"c": "d"}'
         all_headers = dict(
             itertools.chain(headers.items(), security_headers.items()))
         self.stub_url('POST', text=body, headers=all_headers)
@@ -185,13 +186,48 @@ class SessionTests(utils.TestCase):
         """Test that output is logged even for failed requests"""
 
         session = client_session.Session()
-        body = uuid.uuid4().hex
+        body = {uuid.uuid4().hex: uuid.uuid4().hex}
 
-        self.stub_url('GET', text=body, status_code=400)
+        self.stub_url('GET', json=body, status_code=400,
+                      headers={'Content-Type': 'application/json'})
         resp = session.get(self.TEST_URL, raise_exc=False)
 
         self.assertEqual(resp.status_code, 400)
+        self.assertIn(list(body.keys())[0], self.logger.output)
+        self.assertIn(list(body.values())[0], self.logger.output)
+
+    def test_logging_body_only_for_specified_content_types(self):
+        """Verify response body is only logged in specific content types.
+
+        Response bodies are logged only when the response's Content-Type header
+        is set to application/json. This prevents us to get an unexpected
+        MemoryError when reading arbitrary responses, such as streams.
+        """
+        OMITTED_BODY = ('Omitted, Content-Type is set to %s. Only '
+                        'application/json responses have their bodies logged.')
+        session = client_session.Session(verify=False)
+
+        # Content-Type is not set
+        body = jsonutils.dumps({'token': {'id': '...'}})
+        self.stub_url('POST', text=body)
+        session.post(self.TEST_URL)
+        self.assertNotIn(body, self.logger.output)
+        self.assertIn(OMITTED_BODY % None, self.logger.output)
+
+        # Content-Type is set to text/xml
+        body = '<token><id>...</id></token>'
+        self.stub_url('POST', text=body, headers={'Content-Type': 'text/xml'})
+        session.post(self.TEST_URL)
+        self.assertNotIn(body, self.logger.output)
+        self.assertIn(OMITTED_BODY % 'text/xml', self.logger.output)
+
+        # Content-Type is set to application/json
+        body = jsonutils.dumps({'token': {'id': '...'}})
+        self.stub_url('POST', text=body,
+                      headers={'Content-Type': 'application/json'})
+        session.post(self.TEST_URL)
         self.assertIn(body, self.logger.output)
+        self.assertNotIn(OMITTED_BODY % 'application/json', self.logger.output)
 
     def test_unicode_data_in_debug_output(self):
         """Verify that ascii-encodable data is logged without modification."""
@@ -316,7 +352,8 @@ class SessionTests(utils.TestCase):
                     "auth_username": "verybadusername",
                     "auth_method": "CHAP"}}}
         body_json = jsonutils.dumps(body)
-        response = mock.Mock(text=body_json, status_code=200, headers={})
+        response = mock.Mock(text=body_json, status_code=200,
+                             headers={'content-type': 'application/json'})
         session._http_log_response(response, logger)
         self.assertEqual(1, logger.debug.call_count)
 
@@ -769,22 +806,24 @@ class SessionAuthTests(utils.TestCase):
 
         auth = AuthPlugin()
         sess = client_session.Session(auth=auth)
-        response = uuid.uuid4().hex
+        response = {uuid.uuid4().hex: uuid.uuid4().hex}
 
         self.stub_url('GET',
-                      text=response,
-                      headers={'Content-Type': 'text/html'})
+                      json=response,
+                      headers={'Content-Type': 'application/json'})
 
         resp = sess.get(self.TEST_URL, logger=logger)
 
-        self.assertEqual(response, resp.text)
+        self.assertEqual(response, resp.json())
         output = io.getvalue()
 
         self.assertIn(self.TEST_URL, output)
-        self.assertIn(response, output)
+        self.assertIn(list(response.keys())[0], output)
+        self.assertIn(list(response.values())[0], output)
 
         self.assertNotIn(self.TEST_URL, self.logger.output)
-        self.assertNotIn(response, self.logger.output)
+        self.assertNotIn(list(response.keys())[0], self.logger.output)
+        self.assertNotIn(list(response.values())[0], self.logger.output)
 
 
 class AdapterTest(utils.TestCase):
@@ -966,21 +1005,23 @@ class AdapterTest(utils.TestCase):
         sess = client_session.Session(auth=auth)
         adpt = adapter.Adapter(sess, auth=auth, logger=logger)
 
-        response = uuid.uuid4().hex
+        response = {uuid.uuid4().hex: uuid.uuid4().hex}
 
-        self.stub_url('GET', text=response,
-                      headers={'Content-Type': 'text/html'})
+        self.stub_url('GET', json=response,
+                      headers={'Content-Type': 'application/json'})
 
         resp = adpt.get(self.TEST_URL, logger=logger)
 
-        self.assertEqual(response, resp.text)
+        self.assertEqual(response, resp.json())
         output = io.getvalue()
 
         self.assertIn(self.TEST_URL, output)
-        self.assertIn(response, output)
+        self.assertIn(list(response.keys())[0], output)
+        self.assertIn(list(response.values())[0], output)
 
         self.assertNotIn(self.TEST_URL, self.logger.output)
-        self.assertNotIn(response, self.logger.output)
+        self.assertNotIn(list(response.keys())[0], self.logger.output)
+        self.assertNotIn(list(response.values())[0], self.logger.output)
 
 
 class ConfLoadingTests(utils.TestCase):
diff --git a/releasenotes/notes/bug-1616105-cc8b85eb056e99e2.yaml b/releasenotes/notes/bug-1616105-cc8b85eb056e99e2.yaml
new file mode 100644
index 0000000..e9c1c9c
--- /dev/null
+++ b/releasenotes/notes/bug-1616105-cc8b85eb056e99e2.yaml
@@ -0,0 +1,8 @@
+---
+fixes:
+  - >
+    [`bug 1616105 <https://bugs.launchpad.net/keystoneauth/+bug/1616105>`_]
+    Only log the response body when the ``Content-Type`` header is set to
+    ``application/json``. This avoids logging large binary objects (such as
+    images). Other ``Content-Type`` will not be logged. Additional
+    ``Content-Type`` strings can be added as required.