Handle exception on UnicodeDecodError in logging of request

If the logging of an HTTP request causes a UnicodeDecodeError,
modify the log entry using oslo_utils.encodeutils.safe_decode
with errors='replace' and try again

Co-Authored-By: Nikita Konovalov <nkonovalov@mirantis.com>

Change-Id: Ic365c654ebca4045208c6c30e232665145db7b4c
Closes-Bug: #1453953

2 files changed, 50 insertions, 2 deletions

diff --git a/keystoneclient/session.py b/keystoneclient/session.py
index 7c35247..35ccbda 100644
--- a/keystoneclient/session.py
+++ b/keystoneclient/session.py
@@ -22,6 +22,7 @@ import warnings
 from debtcollector import removals
 from oslo_config import cfg
 from oslo_serialization import jsonutils
+from oslo_utils import encodeutils
 from oslo_utils import importutils
 from oslo_utils import strutils
 from positional import positional
@@ -192,10 +193,18 @@ class Session(object):
             for header in six.iteritems(headers):
                 string_parts.append('-H "%s: %s"'
                                     % self._process_header(header))
+
         if data:
             string_parts.append("-d '%s'" % data)
-
-        logger.debug(' '.join(string_parts))
+        try:
+            logger.debug(' '.join(string_parts))
+        except UnicodeDecodeError:
+            logger.debug("Replaced characters that could not be decoded"
+                         " in log output, original caused UnicodeDecodeError")
+            string_parts = [
+                encodeutils.safe_decode(
+                    part, errors='replace') for part in string_parts]
+            logger.debug(' '.join(string_parts))
 
     def _http_log_response(self, response, logger):
         if not logger.isEnabledFor(logging.DEBUG):
diff --git a/keystoneclient/tests/unit/test_session.py b/keystoneclient/tests/unit/test_session.py
index ded925b..4169373 100644
--- a/keystoneclient/tests/unit/test_session.py
+++ b/keystoneclient/tests/unit/test_session.py
@@ -186,6 +186,45 @@ class SessionTests(utils.TestCase):
         self.assertEqual(resp.status_code, 400)
         self.assertIn(body, self.logger.output)
 
+    def test_unicode_data_in_debug_output(self):
+        """Verify that ascii-encodable data is logged without modification."""
+
+        session = client_session.Session(verify=False)
+
+        body = 'RESP'
+        data = u'unicode_data'
+        self.stub_url('POST', text=body)
+        session.post(self.TEST_URL, data=data)
+
+        self.assertIn("'%s'" % data, self.logger.output)
+
+    def test_binary_data_not_in_debug_output(self):
+        """Verify that non-ascii-encodable data causes replacement."""
+
+        if six.PY2:
+            data = "my data" + chr(255)
+        else:
+            # Python 3 logging handles binary data well.
+            return
+
+        session = client_session.Session(verify=False)
+
+        body = 'RESP'
+        self.stub_url('POST', text=body)
+
+        # Forced mixed unicode and byte strings in request
+        # elements to make sure that all joins are appropriately
+        # handled (any join of unicode and byte strings should
+        # raise a UnicodeDecodeError)
+        session.post(unicode(self.TEST_URL), data=data)
+
+        self.assertIn("Replaced characters that could not be decoded"
+                      " in log output", self.logger.output)
+
+        # Our data payload should have changed to
+        # include the replacement char
+        self.assertIn(u"-d 'my data\ufffd'", self.logger.output)
+
     def test_logging_cacerts(self):
         path_to_certs = '/path/to/certs'
         session = client_session.Session(verify=path_to_certs)