Preserve log records when a value cannot be serialized

README.rst

@@ -35,12 +35,12 @@ The log file will contain the following log record (inline).
 
     {
         "message": "Sign up",
-        "time": "2015-09-01T06:06:26.524448",
+        "time": "2015-09-01T06:06:26.524448+00:00",
         "referral_code": "52d6ce"
     }
     {
         "message": "Request failed",
-        "time": "2015-09-01T06:06:26.524449",
+        "time": "2015-09-01T06:06:26.524449+00:00",
         "exc_info": "Traceback (most recent call last): ..."
     }
 
@@ -70,7 +70,7 @@ with ``VerboseJSONFormatter``.
         "thread": 4664270272,
         "threadName": "MainThread",
         "message": "An error has occured",
-        "time": "2021-07-04T21:05:42.767726"
+        "time": "2021-07-04T21:05:42.767726+00:00"
     }
 
 If you need to flatten complex objects as strings, use ``FlatJSONFormatter``.
@@ -108,9 +108,6 @@ You can use **ujson** or **simplejson** instead of built-in **json** library.
     formatter = json_log_formatter.JSONFormatter()
     formatter.json_lib = ujson
 
-Note, **ujson** doesn't support ``dumps(default=f)`` argument:
-if it can't serialize an attribute, it might fail with ``TypeError`` or skip an attribute.
-
 Django integration
 ------------------
 
@@ -169,16 +166,17 @@ To do so you should override ``JSONFormatter.json_record()``.
 
             return extra
 
-Let's say you want ``datetime`` to be serialized as timestamp.
-You can use **ujson** (which does it by default) and disable
-ISO8601 date mutation.
+Let's say you want ``datetime`` to be serialized as a timestamp.
+Override ``mutate_json_record`` to convert it.
 
 .. code-block:: python
 
     class CustomisedJSONFormatter(json_log_formatter.JSONFormatter):
-        json_lib = ujson
-
         def mutate_json_record(self, json_record):
+            for attr_name, attr in json_record.items():
+                if isinstance(attr, datetime):
+                    json_record[attr_name] = attr.timestamp()
+
             return json_record
 
 Tests

json_log_formatter/__init__.py

@@ -76,24 +76,42 @@ def to_json(self, record):
         """Converts record dict to a JSON string.
 
         It makes best effort to serialize a record (represents an object as a string)
-        instead of raising TypeError if json library supports default argument.
-        Note, ujson doesn't support it.
-        ValueError and OverflowError are also caught to avoid crashing an app,
-        e.g., due to circular reference.
+        instead of raising TypeError. ValueError and OverflowError are also
+        caught to avoid crashing an app, e.g., due to circular reference.
 
         Override this method to change the way dict is converted to JSON.
 
         """
         try:
             return self.json_lib.dumps(record, default=_json_serializable)
-        # ujson doesn't support default argument and raises TypeError.
-        # "ValueError: Circular reference detected" is raised
-        # when there is a reference to object inside the object itself.
         except (TypeError, ValueError, OverflowError):
-            try:
-                return self.json_lib.dumps(record)
-            except (TypeError, ValueError, OverflowError):
-                return '{}'
+            pass
+
+        # A single value can't be serialized, e.g., a Django request holding
+        # a circular reference via its file upload handlers.
+        # Stringify the offending values so the rest of the record is preserved.
+        if not isinstance(record, dict):
+            return '{}'
+
+        safe_record = {
+            k: self._safe_value(v)
+            for k, v in record.items()
+        }
+        try:
+            return self.json_lib.dumps(safe_record, default=_json_serializable)
+        except (TypeError, ValueError, OverflowError):
+            return '{}'
+
+    def _safe_value(self, value):
+        """Returns the value as is if it's JSON serializable,
+        its string representation otherwise.
+
+        """
+        try:
+            self.json_lib.dumps(value, default=_json_serializable)
+            return value
+        except (TypeError, ValueError, OverflowError):
+            return str(value)
 
     def extra_from_record(self, record):
         """Returns `extra` dict you passed to logger.

tests.py

@@ -107,6 +107,24 @@ class JsonLibTest(TestCase):
     def setUp(self):
         json_handler.setFormatter(JSONFormatter())
 
+    def test_request_with_circular_reference_does_not_drop_record(self):
+        request = WSGIRequest({
+            'PATH_INFO': 'bogus',
+            'REQUEST_METHOD': 'bogus',
+            'CONTENT_TYPE': 'text/html; charset=utf8',
+            'wsgi.input': BytesIO(b''),
+        })
+        request.upload_handlers
+
+        logger.log(level=logging.ERROR, msg='Django response error', extra={
+            'status_code': 500,
+            'request': request,
+        })
+        json_record = json.loads(log_buffer.getvalue())
+        self.assertEqual(json_record['message'], 'Django response error')
+        self.assertEqual(json_record['status_code'], 500)
+        self.assertEqual(json_record['request'], "<WSGIRequest: BOGUS '/bogus'>")
+
     def test_builtin_types_are_serialized(self):
         logger.log(level=logging.ERROR, msg='Payment was sent', extra={
             'first_name': 'bob',
@@ -155,7 +173,9 @@ def test_json_circular_reference_is_handled(self):
         d = {}
         d['circle'] = d
         logger.info('Referer checking', extra=d)
-        self.assertEqual('{}\n', log_buffer.getvalue())
+        json_record = json.loads(log_buffer.getvalue())
+        self.assertEqual(json_record['message'], 'Referer checking')
+        self.assertEqual(json_record['circle'], str(d))
 
 
 class UjsonLibTest(TestCase):
@@ -221,7 +241,9 @@ def test_json_circular_reference_is_handled(self):
         d = {}
         d['circle'] = d
         logger.info('Referer checking', extra=d)
-        self.assertEqual('{}\n', log_buffer.getvalue())
+        json_record = json.loads(log_buffer.getvalue())
+        self.assertEqual(json_record['message'], 'Referer checking')
+        self.assertEqual(json_record['circle'], str(d))
 
 
 class SimplejsonLibTest(TestCase):
@@ -285,7 +307,9 @@ def test_json_circular_reference_is_handled(self):
         d = {}
         d['circle'] = d
         logger.info('Referer checking', extra=d)
-        self.assertEqual('{}\n', log_buffer.getvalue())
+        json_record = json.loads(log_buffer.getvalue())
+        self.assertEqual(json_record['message'], 'Referer checking')
+        self.assertEqual(json_record['circle'], str(d))
 
 
 class VerboseJSONFormatterTest(TestCase):