JSONFormatter convert unserializable with repr()

The JSONFormatter formatter now converts unserializable objects with
repr() to prevent JSON serialization errors on logging.

The fix requires oslo.serialization 2.21.1 or newer to get the new
fallback parameter of jsonutils.to_primitive().

Closes-Bug: #1593641
Change-Id: Ibda7d145af95903b2bf8d87113804350330a93b4

oslo_log/formatters.py

@@ -12,6 +12,7 @@
 
 import datetime
 import debtcollector
+import functools
 import itertools
 import logging
 import logging.config
@@ -32,6 +33,15 @@ if six.PY3:
     from functools import reduce
 
 
+try:
+    # Test if to_primitive() has the fallback parameter added
+    # in oslo.serialization 2.21.1
+    jsonutils.to_primitive(1, fallback=repr)
+    _HAVE_JSONUTILS_FALLBACK = True
+except TypeError:
+    _HAVE_JSONUTILS_FALLBACK = False
+
+
 def _dictify_context(context):
     if getattr(context, 'get_logging_values', None):
         return context.get_logging_values()
@@ -232,6 +242,15 @@ class JSONFormatter(logging.Formatter):
         if record.exc_info:
             message['traceback'] = self.formatException(record.exc_info)
 
+        if _HAVE_JSONUTILS_FALLBACK:
+            # Bug #1593641: If an object cannot be serialized to JSON, convert
+            # it using repr() to prevent serialization errors. Using repr() is
+            # not ideal, but serialization errors are unexpected on logs,
+            # especially when the code using logs is not aware that the
+            # JSONFormatter will be used.
+            convert = functools.partial(jsonutils.to_primitive, fallback=repr)
+            return jsonutils.dumps(message, default=convert)
+        else:
             return jsonutils.dumps(message)
 
 

oslo_log/tests/unit/test_log.py

@@ -522,6 +522,28 @@ class JSONFormatterTestCase(LogTestBase):
         self.assertIn('error_summary', data)
         self.assertEqual('', data['error_summary'])
 
+    def test_fallback(self):
+        if not formatters._HAVE_JSONUTILS_FALLBACK:
+            self.skipTest("need the fallback parameter of "
+                          "jsonutils.to_primitive() added in "
+                          "oslo_serialization 2.21.1")
+
+        class MyObject(object):
+            def __str__(self):
+                return 'str'
+
+            def __repr__(self):
+                return 'repr'
+
+        obj = MyObject()
+        self.log.debug('obj=%s', obj)
+
+        data = jsonutils.loads(self.stream.getvalue())
+        self.assertEqual('obj=str', data['message'])
+        # Bug #1593641: If an object of record.args cannot be serialized,
+        # convert it using repr() to prevent serialization error on logging.
+        self.assertEqual(['repr'], data['args'])
+
 
 def get_fake_datetime(retval):
     class FakeDateTime(datetime.datetime):

releasenotes/notes/jsonformatter-repr-fd616eb6fa6caeb3.yaml

@@ -0,0 +1,6 @@
+---
+fixes:
+  - |
+    The JSONFormatter formatter now converts unserializable objects with
+    repr() to prevent JSON serialization errors on logging. The fix requires
+    oslo.serialization 2.21.1 or newer. (Bug #1593641)