Merge "Make available to log encoded strings as arguments"

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)