Make Messages unicode before hitting logging

Some of the log handlers in the python standard library
are hitting issues with Messages since they check for
basestring types only, and attempt to coerce anything else
to string. This leads to Messages being coerced to bad encodings,
resulting in unhandled exceptions.

This change adds a check that looks for non-basestring
objects and coerces them to unicode before they hit the problematic
logging areas.

bug 1225099

Change-Id: I0bff6b52205e3c88db38876b8c6de1bd820f460a
Co-authored-by: Luis A. Garcia <luis@linux.vnet.ibm.com>

openstack/common/log.py

@@ -249,6 +249,13 @@ def deprecated(self, msg, *args, **kwargs):
             self.warn(stdmsg, *args, **kwargs)
 
     def process(self, msg, kwargs):
+        # NOTE(mrodden): catch any Message/other object and
+        #                coerce to unicode before they can get
+        #                to the python logging and possibly
+        #                cause string encoding trouble
+        if not isinstance(msg, basestring):
+            msg = unicode(msg)
+
         if 'extra' not in kwargs:
             kwargs['extra'] = {}
         extra = kwargs['extra']

tests/unit/test_log.py

@@ -25,6 +25,7 @@
 from openstack.common import context
 from openstack.common.fixture import config
 from openstack.common.fixture import moxstubout
+from openstack.common import gettextutils
 from openstack.common import jsonutils
 from openstack.common import log
 from openstack.common import log_handler
@@ -263,6 +264,19 @@ def test_debugging_log(self):
         self.log.debug("baz")
         self.assertEqual("NOCTXT: baz --DBG\n", self.stream.getvalue())
 
+    def test_message_logging(self):
+        # NOTE(luisg): Logging message objects with unicode objects
+        # may cause trouble by the logging mechanism trying to coerce
+        # the Message object, with a wrong encoding. This test case
+        # tests that problem does not occur.
+        ctxt = _fake_context()
+        ctxt.request_id = unicode('99')
+        message = gettextutils.Message('test ' + unichr(128), 'test')
+        self.log.info(message, context=ctxt)
+        expected = "HAS CONTEXT [%s]: %s\n" % (ctxt.request_id,
+                                               unicode(message))
+        self.assertEqual(expected, self.stream.getvalue())
+
 
 class ExceptionLoggingTestCase(test.BaseTestCase):
     """Test that Exceptions are logged."""