Make available to log encoded strings as arguments

Pure python logging library allows to log encoded strings
but in oslo_log it causes UnicodeDecodeError for arguments
which contains unicode symbols.

Changes add additional check whether all arguments can be converted to
unicode. If it isn't possible then leave it as is.

Change-Id: I76e75c35a74b146fae52c0ea60156e1cf78540e7
Closes-Bug: #1563295

oslo_log/formatters.py

@@ -26,6 +26,7 @@ from six import moves
 
 from oslo_context import context as context_utils
 from oslo_serialization import jsonutils
+from oslo_utils import encodeutils
 
 
 def _dictify_context(context):
@@ -76,6 +77,19 @@ def _update_record_with_context(record):
     return context
 
 
+def _ensure_unicode(msg):
+    """Do our best to turn the input argument into a unicode object.
+    """
+    if isinstance(msg, six.text_type):
+        return msg
+    if not isinstance(msg, six.binary_type):
+        return six.text_type(msg)
+    return encodeutils.safe_decode(
+        msg,
+        incoming='utf-8',
+        errors='xmlcharrefreplace')
+
+
 class _ReplaceFalseValue(dict):
     def __getitem__(self, key):
         return dict.get(self, key, None) or '-'
@@ -189,11 +203,17 @@ class ContextFormatter(logging.Formatter):
     def format(self, record):
         """Uses contextstring if request_id is set, otherwise default."""
 
-        # NOTE(jecarey): If msg is not unicode, coerce it into unicode
-        #                before it can get to the python logging and
-        #                possibly cause string encoding trouble
-        if not isinstance(record.msg, six.text_type):
-            record.msg = six.text_type(record.msg)
+        if six.PY2:
+            should_use_unicode = True
+            for arg in record.args:
+                try:
+                    six.text_type(arg)
+                except UnicodeDecodeError:
+                    should_use_unicode = False
+                    break
+            if (not isinstance(record.msg, six.text_type)
+                    and should_use_unicode):
+                record.msg = _ensure_unicode(record.msg)
 
         # store project info
         record.project = self.project

oslo_log/log.py

@@ -40,7 +40,6 @@ except ImportError:
 import traceback
 
 from oslo_config import cfg
-from oslo_utils import encodeutils
 from oslo_utils import importutils
 import six
 from six import moves
@@ -92,21 +91,6 @@ class BaseLoggerAdapter(logging.LoggerAdapter):
         self.log(TRACE, msg, *args, **kwargs)
 
 
-def _ensure_unicode(msg):
-    """Do our best to turn the input argument into a unicode object.
-    """
-    if not isinstance(msg, six.text_type):
-        if isinstance(msg, six.binary_type):
-            msg = encodeutils.safe_decode(
-                msg,
-                incoming='utf-8',
-                errors='xmlcharrefreplace',
-            )
-        else:
-            msg = six.text_type(msg)
-    return msg
-
-
 class KeywordArgumentAdapter(BaseLoggerAdapter):
     """Logger adapter to add keyword arguments to log record's extra data
 
@@ -126,7 +110,6 @@ class KeywordArgumentAdapter(BaseLoggerAdapter):
     """
 
     def process(self, msg, kwargs):
-        msg = _ensure_unicode(msg)
         # Make a new extra dictionary combining the values we were
         # given when we were constructed and anything from kwargs.
         extra = {}

oslo_log/tests/unit/test_log.py

@@ -402,6 +402,14 @@ class JSONFormatterTestCase(LogTestBase):
         self.assertTrue(extra_keys[1] in data['extra'])
         self.assertEqual(special_user, data['extra'][extra_keys[1]])
 
+    def test_can_process_strings(self):
+        expected = b'\\u2622'
+        if six.PY3:
+            # see ContextFormatterTestCase.test_can_process_strings
+            expected = '\\\\xe2\\\\x98\\\\xa2'
+        self.log.info(b'%s', u'\u2622'.encode('utf8'))
+        self.assertIn(expected, self.stream.getvalue())
+
 
 def get_fake_datetime(retval):
     class FakeDateTime(datetime.datetime):
@@ -569,6 +577,16 @@ class ContextFormatterTestCase(LogTestBase):
 
         self.assertEqual(expected, self.stream.getvalue())
 
+    def test_can_process_strings(self):
+        expected = b'\xe2\x98\xa2'
+        if six.PY3:
+            # in PY3 logging format string should be unicode string
+            # or it will fail and inserting byte string in unicode string
+            # causes such formatting
+            expected = '\\xe2\\x98\\xa2'
+        self.log.info(b'%s', u'\u2622'.encode('utf8'))
+        self.assertIn(expected, self.stream.getvalue())
+
 
 class ExceptionLoggingTestCase(LogTestBase):
     """Test that Exceptions are logged."""
@@ -1238,20 +1256,20 @@ class UnicodeConversionTestCase(BaseTestCase):
     def test_ascii_to_unicode(self):
         msg = self._MSG
         enc_msg = msg.encode('utf-8')
-        result = log._ensure_unicode(enc_msg)
+        result = formatters._ensure_unicode(enc_msg)
         self.assertEqual(msg, result)
         self.assertIsInstance(result, six.text_type)
 
     def test_unicode_to_unicode(self):
         msg = self._MSG
-        result = log._ensure_unicode(msg)
+        result = formatters._ensure_unicode(msg)
         self.assertEqual(msg, result)
         self.assertIsInstance(result, six.text_type)
 
     def test_exception_to_unicode(self):
         msg = self._MSG
         exc = Exception(msg)
-        result = log._ensure_unicode(exc)
+        result = formatters._ensure_unicode(exc)
         self.assertEqual(msg, result)
         self.assertIsInstance(result, six.text_type)