fix: structured log handler formatting issues (#319)

Author: daniel-sanche

google/cloud/logging_v2/handlers/structured_log.py

@@ -14,13 +14,13 @@
 
 """Logging handler for printing formatted structured logs to standard output.
 """
-
+import json
 import logging.handlers
 
 from google.cloud.logging_v2.handlers.handlers import CloudLoggingFilter
 
 GCP_FORMAT = (
-    '{"message": "%(_msg_str)s", '
+    '{"message": %(_formatted_msg)s, '
     '"severity": "%(levelname)s", '
     '"logging.googleapis.com/labels": %(_labels_str)s, '
     '"logging.googleapis.com/trace": "%(_trace_str)s", '
@@ -50,7 +50,7 @@ def __init__(self, *, labels=None, stream=None, project_id=None):
         self.addFilter(log_filter)
 
         # make logs appear in GCP structured logging format
-        self.formatter = logging.Formatter(GCP_FORMAT)
+        self._gcp_formatter = logging.Formatter(GCP_FORMAT)
 
     def format(self, record):
         """Format the message into structured log JSON.
@@ -59,6 +59,12 @@ def format(self, record):
         Returns:
             str: A JSON string formatted for GKE fluentd.
         """
-
-        payload = self.formatter.format(record)
-        return payload
+        # let other formatters alter the message
+        super_payload = None
+        if record.msg:
+            super_payload = super(StructuredLogHandler, self).format(record)
+        # properly break any formatting in string to make it json safe
+        record._formatted_msg = json.dumps(super_payload or "")
+        # convert to GCP structred logging format
+        gcp_payload = self._gcp_formatter.format(record)
+        return gcp_payload

tests/environment

@@ -291,7 +291,9 @@ def test_emit(self):
         )
         logname = "loggername"
         message = "hello world"
-        record = logging.LogRecord(logname, logging, None, None, message, None, None)
+        record = logging.LogRecord(
+            logname, logging.INFO, None, None, message, None, None
+        )
         handler.handle(record)
         self.assertEqual(
             handler.transport.send_called_with,
@@ -315,7 +317,9 @@ def test_emit_manual_field_override(self):
         )
         logname = "loggername"
         message = "hello world"
-        record = logging.LogRecord(logname, logging, None, None, message, None, None)
+        record = logging.LogRecord(
+            logname, logging.INFO, None, None, message, None, None
+        )
         # set attributes manually
         expected_trace = "123"
         setattr(record, "trace", expected_trace)
@@ -350,6 +354,53 @@ def test_emit_manual_field_override(self):
             ),
         )
 
+    def test_emit_with_custom_formatter(self):
+        """
+        Handler should respect custom formatters attached
+        """
+        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="%(name)s :: %(levelname)s :: %(message)s")
+        handler.setFormatter(logFormatter)
+        message = "test"
+        expected_result = "logname :: INFO :: test"
+        record = logging.LogRecord(
+            "logname", logging.INFO, None, None, message, None, None
+        )
+        handler.handle(record)
+
+        self.assertEqual(
+            handler.transport.send_called_with,
+            (record, expected_result, _GLOBAL_RESOURCE, None, None, None, None, None,),
+        )
+
+    def test_format_with_arguments(self):
+        """
+        Handler should support format string arguments
+        """
+        from google.cloud.logging_v2.logger import _GLOBAL_RESOURCE
+
+        client = _Client(self.PROJECT)
+        handler = self._make_one(
+            client, transport=_Transport, resource=_GLOBAL_RESOURCE,
+        )
+        message = "name: %s"
+        name_arg = "Daniel"
+        expected_result = "name: Daniel"
+        record = logging.LogRecord(
+            None, logging.INFO, None, None, message, name_arg, None
+        )
+        handler.handle(record)
+
+        self.assertEqual(
+            handler.transport.send_called_with,
+            (record, expected_result, _GLOBAL_RESOURCE, None, None, None, None, None,),
+        )
+
 
 class TestSetupLogging(unittest.TestCase):
     def _call_fut(self, handler, excludes=None):

tests/unit/handlers/test_handlers.py

@@ -109,17 +109,67 @@ def test_format_with_quotes(self):
         When logging a message containing quotes, escape chars should be added
         """
         import logging
-        import json
 
         handler = self._make_one()
         message = '"test"'
         expected_result = '\\"test\\"'
         record = logging.LogRecord(None, logging.INFO, None, None, message, None, None,)
         record.created = None
         handler.filter(record)
-        result = json.loads(handler.format(record))
-        result["message"] = expected_result
-        self.assertEqual(result["message"], expected_result)
+        result = handler.format(record)
+        self.assertIn(expected_result, result)
+
+    def test_format_with_line_break(self):
+        """
+        When logging a message containing \n, it should be properly escaped
+        """
+        import logging
+
+        handler = self._make_one()
+        message = "test\ntest"
+        expected_result = "test\\ntest"
+        record = logging.LogRecord(None, logging.INFO, None, None, message, None, None,)
+        record.created = None
+        handler.filter(record)
+        result = handler.format(record)
+        self.assertIn(expected_result, result)
+
+    def test_format_with_custom_formatter(self):
+        """
+        Handler should respect custom formatters attached
+        """
+        import logging
+
+        handler = self._make_one()
+        logFormatter = logging.Formatter(fmt="%(name)s :: %(levelname)s :: %(message)s")
+        handler.setFormatter(logFormatter)
+        message = "test"
+        expected_result = "logname :: INFO :: 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)
+
+    def test_format_with_arguments(self):
+        """
+        Handler should support format string arguments
+        """
+        import logging
+
+        handler = self._make_one()
+        message = "name: %s"
+        name_arg = "Daniel"
+        expected_result = "name: Daniel"
+        record = logging.LogRecord(
+            None, logging.INFO, None, None, message, name_arg, None,
+        )
+        record.created = None
+        handler.filter(record)
+        result = handler.format(record)
+        self.assertIn(expected_result, result)
 
     def test_format_with_request(self):
         import logging