feat!: support string-encoded json (#339)

Author: daniel-sanche

google/cloud/logging_v2/handlers/handlers.py

@@ -192,13 +192,8 @@ def emit(self, record):
         """
         resource = record._resource or self.resource
         labels = record._labels
-        message = None
-        if isinstance(record.msg, collections.abc.Mapping):
-            # if input is a dictionary, pass as-is for structured logging
-            message = record.msg
-        elif record.msg:
-            # otherwise, format message string based on superclass
-            message = super(CloudLoggingHandler, self).format(record)
+        message = _format_and_parse_message(record, self)
+
         if resource.type == _GAE_RESOURCE_TYPE and record._trace is not None:
             # add GAE-specific label
             labels = {_GAE_TRACE_ID_LABEL: record._trace, **(labels or {})}
@@ -215,6 +210,35 @@ def emit(self, record):
         )
 
 
+def _format_and_parse_message(record, formatter_handler):
+    """
+    Helper function to apply formatting to a LogRecord message,
+    and attempt to parse encoded JSON into a dictionary object.
+
+    Resulting output will be of type (str | dict | None)
+
+    Args:
+        record (logging.LogRecord): The record object representing the log
+        formatter_handler (logging.Handler): The handler used to format the log
+    """
+    # if message is a dictionary, return as-is
+    if isinstance(record.msg, collections.abc.Mapping):
+        return record.msg
+    # format message string based on superclass
+    message = formatter_handler.format(record)
+    try:
+        # attempt to parse encoded json into dictionary
+        if message[0] == "{":
+            json_message = json.loads(message)
+            if isinstance(json_message, collections.abc.Mapping):
+                message = json_message
+    except (json.decoder.JSONDecodeError, IndexError):
+        # log string is not valid json
+        pass
+    # if formatted message contains no content, return None
+    return message if message != "None" else None
+
+
 def setup_logging(
     handler, *, excluded_loggers=EXCLUDED_LOGGER_DEFAULTS, log_level=logging.INFO
 ):

tests/unit/handlers/test_handlers.py

@@ -311,6 +311,20 @@ def test_emit(self):
             ),
         )
 
+    def test_emit_minimal(self):
+        from google.cloud.logging_v2.logger import _GLOBAL_RESOURCE
+
+        client = _Client(self.PROJECT)
+        handler = self._make_one(
+            client, transport=_Transport, resource=_GLOBAL_RESOURCE
+        )
+        record = logging.LogRecord(None, logging.INFO, None, None, None, None, None)
+        handler.handle(record)
+        self.assertEqual(
+            handler.transport.send_called_with,
+            (record, None, _GLOBAL_RESOURCE, None, None, None, None, None,),
+        )
+
     def test_emit_manual_field_override(self):
         from google.cloud.logging_v2.logger import _GLOBAL_RESOURCE
         from google.cloud.logging_v2.resource import Resource
@@ -401,6 +415,70 @@ def test_emit_with_custom_formatter(self):
             ),
         )
 
+    def test_emit_dict(self):
+        """
+        Handler should support logging dictionaries
+        """
+        from google.cloud.logging_v2.logger import _GLOBAL_RESOURCE
+
+        client = _Client(self.PROJECT)
+        handler = self._make_one(
+            client, transport=_Transport, resource=_GLOBAL_RESOURCE,
+        )
+        message = {"x": "test"}
+        logname = "logname"
+        expected_label = {"python_logger": logname}
+        record = logging.LogRecord(
+            logname, logging.INFO, None, None, message, None, None
+        )
+        handler.handle(record)
+
+        self.assertEqual(
+            handler.transport.send_called_with,
+            (
+                record,
+                message,
+                _GLOBAL_RESOURCE,
+                expected_label,
+                None,
+                None,
+                None,
+                None,
+            ),
+        )
+
+    def test_emit_with_encoded_json(self):
+        """
+        Handler should parse json encoded as a string
+        """
+        from google.cloud.logging_v2.logger import _GLOBAL_RESOURCE
+
+        client = _Client(self.PROJECT)
+        handler = self._make_one(
+            client, transport=_Transport, resource=_GLOBAL_RESOURCE,
+        )
+        logFormatter = logging.Formatter(fmt='{ "x" : "%(name)s" }')
+        handler.setFormatter(logFormatter)
+        logname = "logname"
+        expected_result = {"x": logname}
+        expected_label = {"python_logger": logname}
+        record = logging.LogRecord(logname, logging.INFO, None, None, None, None, None)
+        handler.handle(record)
+
+        self.assertEqual(
+            handler.transport.send_called_with,
+            (
+                record,
+                expected_result,
+                _GLOBAL_RESOURCE,
+                expected_label,
+                None,
+                None,
+                None,
+                None,
+            ),
+        )
+
     def test_format_with_arguments(self):
         """
         Handler should support format string arguments
@@ -425,6 +503,112 @@ def test_format_with_arguments(self):
         )
 
 
+class TestFormatAndParseMessage(unittest.TestCase):
+    def test_none(self):
+        """
+        None messages with no special formatting should return
+        None after formatting
+        """
+        from google.cloud.logging_v2.handlers.handlers import _format_and_parse_message
+
+        message = None
+        record = logging.LogRecord(None, None, None, None, message, None, None)
+        handler = logging.StreamHandler()
+        result = _format_and_parse_message(record, handler)
+        self.assertEqual(result, None)
+
+    def test_none_formatted(self):
+        """
+        None messages with formatting rules should return formatted string
+        """
+        from google.cloud.logging_v2.handlers.handlers import _format_and_parse_message
+
+        message = None
+        record = logging.LogRecord("logname", None, None, None, message, None, None)
+        handler = logging.StreamHandler()
+        formatter = logging.Formatter("name: %(name)s")
+        handler.setFormatter(formatter)
+        result = _format_and_parse_message(record, handler)
+        self.assertEqual(result, "name: logname")
+
+    def test_unformatted_string(self):
+        """
+        Unformated strings should be returned unchanged
+        """
+        from google.cloud.logging_v2.handlers.handlers import _format_and_parse_message
+
+        message = '"test"'
+        record = logging.LogRecord("logname", None, None, None, message, None, None)
+        handler = logging.StreamHandler()
+        result = _format_and_parse_message(record, handler)
+        self.assertEqual(result, message)
+
+    def test_empty_string(self):
+        """
+        Empty strings should be returned unchanged
+        """
+        from google.cloud.logging_v2.handlers.handlers import _format_and_parse_message
+
+        message = ""
+        record = logging.LogRecord("logname", None, None, None, message, None, None)
+        handler = logging.StreamHandler()
+        result = _format_and_parse_message(record, handler)
+        self.assertEqual(result, message)
+
+    def test_string_formatted_with_args(self):
+        """
+        string messages should properly apply formatting and arguments
+        """
+        from google.cloud.logging_v2.handlers.handlers import _format_and_parse_message
+
+        message = "argument: %s"
+        arg = "test"
+        record = logging.LogRecord("logname", None, None, None, message, arg, None)
+        handler = logging.StreamHandler()
+        formatter = logging.Formatter("name: %(name)s :: message: %(message)s")
+        handler.setFormatter(formatter)
+        result = _format_and_parse_message(record, handler)
+        self.assertEqual(result, "name: logname :: message: argument: test")
+
+    def test_dict(self):
+        """
+        dict messages should be unchanged
+        """
+        from google.cloud.logging_v2.handlers.handlers import _format_and_parse_message
+
+        message = {"a": "b"}
+        record = logging.LogRecord("logname", None, None, None, message, None, None)
+        handler = logging.StreamHandler()
+        formatter = logging.Formatter("name: %(name)s")
+        handler.setFormatter(formatter)
+        result = _format_and_parse_message(record, handler)
+        self.assertEqual(result, message)
+
+    def test_string_encoded_dict(self):
+        """
+        dicts should be extracted from string messages
+        """
+        from google.cloud.logging_v2.handlers.handlers import _format_and_parse_message
+
+        message = '{ "x": { "y" : "z"  } }'
+        record = logging.LogRecord("logname", None, None, None, message, None, None)
+        handler = logging.StreamHandler()
+        result = _format_and_parse_message(record, handler)
+        self.assertEqual(result, {"x": {"y": "z"}})
+
+    def test_broken_encoded_dict(self):
+        """
+        unparseable encoded dicts should be kept as strings
+        """
+        from google.cloud.logging_v2.handlers.handlers import _format_and_parse_message
+
+        message = '{ "x": { "y" : '
+        record = logging.LogRecord("logname", None, None, None, message, None, None)
+        handler = logging.StreamHandler()
+        result = _format_and_parse_message(record, handler)
+        self.assertEqual(result, message)
+
+
 class TestSetupLogging(unittest.TestCase):
     def _call_fut(self, handler, excludes=None):
         from google.cloud.logging.handlers import setup_logging

tests/unit/handlers/test_structured_log.py

@@ -92,13 +92,16 @@ def test_format_minimal(self):
         record = logging.LogRecord(None, logging.INFO, None, None, None, None, None,)
         record.created = None
         expected_payload = {
+            "severity": "INFO",
             "logging.googleapis.com/trace": "",
+            "logging.googleapis.com/spanId": "",
             "logging.googleapis.com/sourceLocation": {},
             "httpRequest": {},
             "logging.googleapis.com/labels": {},
         }
         handler.filter(record)
         result = json.loads(handler.format(record))
+        self.assertEqual(set(expected_payload.keys()), set(result.keys()))
         for (key, value) in expected_payload.items():
             self.assertEqual(
                 value, result[key], f"expected_payload[{key}] != result[{key}]"
@@ -170,6 +173,44 @@ def test_format_with_custom_formatter(self):
         handler.filter(record)
         result = handler.format(record)
         self.assertIn(expected_result, result)
+        self.assertIn("message", result)
+
+    def test_dict(self):
+        """
+        Handler should parse json encoded as a string
+        """
+        import logging
+
+        handler = self._make_one()
+        message = {"x": "test"}
+        expected_result = '"x": "test"'
+        record = logging.LogRecord(
+            "logname", logging.INFO, None, None, message, None, None,
+        )
+        record.created = None
+        handler.filter(record)
+        result = handler.format(record)
+        self.assertIn(expected_result, result)
+        self.assertNotIn("message", result)
+
+    def test_encoded_json(self):
+        """
+        Handler should parse json encoded as a string
+        """
+        import logging
+
+        handler = self._make_one()
+        logFormatter = logging.Formatter(fmt='{ "name" : "%(name)s" }')
+        handler.setFormatter(logFormatter)
+        expected_result = '"name": "logname"'
+        record = logging.LogRecord(
+            "logname", logging.INFO, None, None, None, None, None,
+        )
+        record.created = None
+        handler.filter(record)
+        result = handler.format(record)
+        self.assertIn(expected_result, result)
+        self.assertNotIn("message", result)
 
     def test_format_with_arguments(self):
         """