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

3 files changed, 48 insertions, 1 deletions

diff --git a/oslo_log/formatters.py b/oslo_log/formatters.py
index ae2d04d..40d8654 100644
--- a/oslo_log/formatters.py
+++ b/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,7 +242,16 @@ class JSONFormatter(logging.Formatter):
         if record.exc_info:
             message['traceback'] = self.formatException(record.exc_info)
 
-        return jsonutils.dumps(message)
+        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)
 
 
 class FluentFormatter(logging.Formatter):
diff --git a/oslo_log/tests/unit/test_log.py b/oslo_log/tests/unit/test_log.py
index 1482de7..96fef6c 100644
--- a/oslo_log/tests/unit/test_log.py
+++ b/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):
diff --git a/releasenotes/notes/jsonformatter-repr-fd616eb6fa6caeb3.yaml b/releasenotes/notes/jsonformatter-repr-fd616eb6fa6caeb3.yaml
new file mode 100644
index 0000000..d6469a9
--- /dev/null
+++ b/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)