Handle log messages where string representation is json

Author: AttilaGombosER

context_logger/filter.py

@@ -2,6 +2,7 @@
 # SPDX-FileCopyrightText: 2024 Attila Gombos <attila.gombos@effective-range.com>
 # SPDX-License-Identifier: MIT
 
+import json
 import socket
 from importlib.metadata import version, PackageNotFoundError
 from logging import Filter, LogRecord
@@ -22,16 +23,19 @@ def filter(self, record: LogRecord) -> bool:
                 record.msg = {self._message_field: record.msg % record.args if record.args else record.msg}
                 record.args = ()
 
-            record.msg['hostname'] = socket.gethostname()
-            record.msg['application'] = self._application_name
-            record.msg['app_version'] = self._get_application_version()
+            if isinstance(record.msg, dict):
+                record.msg['hostname'] = socket.gethostname()
+                record.msg['application'] = self._application_name
+                record.msg['app_version'] = self._get_application_version()
 
-            if 'process_name' in record.msg:
-                record.msg['process_name'] = record.processName
+                if 'process_name' in record.msg:
+                    record.msg['process_name'] = record.processName
 
-            for key, value in self._global_context.items():
-                if key not in record.msg:
-                    record.msg[key] = str(value)
+                for key, value in self._global_context.items():
+                    if key not in record.msg:
+                        record.msg[key] = str(value)
+            else:
+                record.msg = json.loads(str(record.msg))
 
         except Exception as exception:
             print('Failed to handle log record:', exception)

context_logger/logger.py

@@ -2,6 +2,7 @@
 # SPDX-FileCopyrightText: 2024 Attila Gombos <attila.gombos@effective-range.com>
 # SPDX-License-Identifier: MIT
 
+import json
 import logging.handlers
 import os
 import sys
@@ -161,7 +162,14 @@ def _ensure_directory_exists(self, log_file_path: str) -> None:
             os.makedirs(directory)
 
     def _enrich_stdlib_log(self, _: logging.Logger, __: str, event_dict: dict[Any, Any]) -> dict[Any, Any]:
-        event_dict.update(event_dict['_record'].msg)
+        try:
+            message = event_dict['_record'].msg
+            if isinstance(message, dict):
+                event_dict.update(message)
+            else:
+                event_dict.update(json.loads(str(message)))
+        except Exception as exception:
+            print('Failed to handle stdlib log record:', exception)
 
         return event_dict
 

tests/filterTest.py

@@ -70,6 +70,25 @@ def test_filter_handles_non_mapping_message(self):
         # Then
         self.assertTrue(result)
         self.assertEqual(123, record.msg)
+        print_mock.assert_not_called()
+
+    def test_filter_handles_unexpected_version_lookup_error(self):
+        # Given
+        filter_ = ContextSetupFilter('example-app', 'message')
+        record = logging.LogRecord('ExampleClass', logging.INFO, __file__, 10, 'Hello', (), None)
+
+        with patch('context_logger.filter.socket.gethostname', return_value='test-host'), \
+                patch.object(filter_, '_get_application_version', side_effect=RuntimeError('boom')), \
+                patch('builtins.print') as print_mock:
+            # When
+            result = filter_.filter(record)
+
+        # Then
+        self.assertTrue(result)
+        self.assertEqual('Hello', record.msg.get('message'))
+        self.assertEqual('test-host', record.msg.get('hostname'))
+        self.assertEqual('example-app', record.msg.get('application'))
+        self.assertNotIn('app_version', record.msg)
         print_mock.assert_called_once()
         self.assertEqual('Failed to handle log record:', print_mock.call_args.args[0])
 

tests/loggerFallbackTest.py

@@ -133,6 +133,67 @@ def test_ensure_directory_exists_does_not_create_existing_directory(self):
         # Then
         makedirs_mock.assert_not_called()
 
+    def test_enrich_stdlib_log_updates_event_dict_from_mapping_message(self):
+        # Given
+        logger = Logger('example-app', 'INFO', None, 1024, 1, False, 'message')
+        record = MagicMock()
+        record.msg = {'message': 'ok', 'code': 7}
+        event_dict = {'_record': record, 'existing': True}
+
+        # When
+        result = logger._enrich_stdlib_log(logging.getLogger('x'), 'info', event_dict)
+
+        # Then
+        self.assertIs(result, event_dict)
+        self.assertEqual('ok', event_dict.get('message'))
+        self.assertEqual(7, event_dict.get('code'))
+        self.assertTrue(event_dict.get('existing'))
+
+    def test_enrich_stdlib_log_updates_event_dict_from_json_message(self):
+        # Given
+        logger = Logger('example-app', 'INFO', None, 1024, 1, False, 'message')
+        record = MagicMock()
+        record.msg = '{"message": "ok", "code": 9}'
+        event_dict = {'_record': record}
+
+        # When
+        result = logger._enrich_stdlib_log(logging.getLogger('x'), 'info', event_dict)
+
+        # Then
+        self.assertIs(result, event_dict)
+        self.assertEqual('ok', event_dict.get('message'))
+        self.assertEqual(9, event_dict.get('code'))
+
+    def test_enrich_stdlib_log_handles_invalid_message(self):
+        # Given
+        logger = Logger('example-app', 'INFO', None, 1024, 1, False, 'message')
+        record = MagicMock()
+        record.msg = object()
+        event_dict = {'_record': record, 'untouched': 'value'}
+
+        with patch('builtins.print') as print_mock:
+            # When
+            result = logger._enrich_stdlib_log(logging.getLogger('x'), 'info', event_dict)
+
+        # Then
+        self.assertIs(result, event_dict)
+        self.assertEqual('value', event_dict.get('untouched'))
+        print_mock.assert_called_once()
+        self.assertEqual('Failed to handle stdlib log record:', print_mock.call_args.args[0])
+
+    def test_get_foreign_prechain_appends_stdlib_enricher(self):
+        # Given
+        logger = Logger('example-app', 'INFO', None, 1024, 1, False, 'message')
+        logger._shared_processors = ['p1', 'p2']
+
+        # When
+        prechain = logger._get_foreign_prechain()
+
+        # Then
+        self.assertEqual(['p1', 'p2'], prechain[:-1])
+        self.assertIs(prechain[-1].__self__, logger)
+        self.assertIs(prechain[-1].__func__, Logger._enrich_stdlib_log)
+
 
 if __name__ == '__main__':
     unittest.main()