Use dict arg values for unicode checks in ContextFormatter3.26.1

In ContextFormatter.format(), for python2 it checks each arg to
determine whether unicode should be used for the format message.
The problem is the code assumes the args are a list, when they can
also be a dict, for example:

  LOG.info('%(thing)s', {'thing': '...'})

and in that case, the dict keys were implicitly being used for the
checks. The checks will always pass on string dict keys, so the
format message gets converted to unicode even though the corresponding
args will ultimately fail decoding to unicode. Then, the logging fails
with:

  UnicodeDecodeError: 'ascii' codec can't decode byte 0xc6 in
  position 0: ordinal not in range(128)

when the unicode format message causes an implicit conversion attempt
of the args to unicode [1].

This adds a check for the args type and uses the dict values for the
unicode checks so that dict args with values that fail decoding will
have: should_use_unicode = False.

Closes-Bug: #1580728

[1] https://github.com/python/cpython/blob/2e576f5/Lib/logging/__init__.py#L338

Change-Id: I8c479e507efcf8acd3e3faa4a702fa6e1f18772f

2 files changed, 9 insertions, 1 deletions

diff --git a/oslo_log/formatters.py b/oslo_log/formatters.py
index 157dea5..b57e5aa 100644
--- a/oslo_log/formatters.py
+++ b/oslo_log/formatters.py
@@ -270,7 +270,9 @@ class ContextFormatter(logging.Formatter):
 
         if six.PY2:
             should_use_unicode = True
-            for arg in record.args or []:
+            args = (record.args.values() if isinstance(record.args, dict)
+                    else record.args)
+            for arg in args or []:
                 try:
                     six.text_type(arg)
                 except UnicodeDecodeError:
diff --git a/oslo_log/tests/unit/test_log.py b/oslo_log/tests/unit/test_log.py
index 4d8f2d0..d7c50f7 100644
--- a/oslo_log/tests/unit/test_log.py
+++ b/oslo_log/tests/unit/test_log.py
@@ -737,6 +737,12 @@ class ContextFormatterTestCase(LogTestBase):
         self.log.info(b'%s', u'\u2622'.encode('utf8'))
         self.assertIn(expected, self.stream.getvalue())
 
+    def test_dict_args_with_unicode(self):
+        msg = '%(thing)s'
+        arg = {'thing': '\xc6\x91\xc6\xa1\xc6\xa1'}
+        self.log.info(msg, arg)
+        self.assertIn(arg['thing'], self.stream.getvalue())
+
 
 class ExceptionLoggingTestCase(LogTestBase):
     """Test that Exceptions are logged."""