Restore automatic unicode conversion

Earlier versions of oslo.log tried to assume that getLogger() was not
generally being used and so we relied on the developer to ensure that
their log messages were valid unicode strings. Since then we have found
a lot of cases where non-unicode (indeed, non-string) objects are passed
to loggers as messages. To avoid the resulting unicode-related errors,
this patch restores the old behavior of having the adapter convert
messages to unicode before passing them down the stack to the
logger. The caveat that comes with relying on this is that it only works
for OpenStack code that calls oslo_log.log.getLogger, and not the
standard libary's logging.getLogger.

Change-Id: Ia74f4ea043c293106bf962fb4d5bd52065e42213

oslo_log/log.py

@@ -36,6 +36,7 @@ import sys
 import traceback
 
 from oslo_config import cfg
+from oslo_utils import encodeutils
 from oslo_utils import importutils
 import six
 from six import moves
@@ -83,6 +84,21 @@ class BaseLoggerAdapter(logging.LoggerAdapter):
             return super(BaseLoggerAdapter, self).isEnabledFor(level)
 
 
+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
 
@@ -102,6 +118,7 @@ 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

@@ -823,3 +823,26 @@ class KeywordArgumentAdapterTestCase(BaseTestCase):
                        'extra_keys': ['name']},
                 exc_info='exception',
             )
+
+
+class UnicodeConversionTestCase(BaseTestCase):
+
+    def test_ascii_to_unicode(self):
+        msg = u'Message with unicode char \ua000 in the middle'
+        enc_msg = msg.encode('utf-8')
+        result = log._ensure_unicode(enc_msg)
+        self.assertEqual(msg, result)
+        self.assertIsInstance(result, six.text_type)
+
+    def test_unicode_to_unicode(self):
+        msg = u'Message with unicode char \ua000 in the middle'
+        result = log._ensure_unicode(msg)
+        self.assertEqual(msg, result)
+        self.assertIsInstance(result, six.text_type)
+
+    def test_exception_to_unicode(self):
+        msg = u'Message with unicode char \ua000 in the middle'
+        exc = Exception(msg)
+        result = log._ensure_unicode(exc)
+        self.assertEqual(msg, result)
+        self.assertIsInstance(result, six.text_type)