googleapis · daniel-sanche · Jun 10, 2021 · Jun 7, 2021 · Jun 9, 2021 · Jun 9, 2021
diff --git a/google/cloud/logging_v2/handlers/structured_log.py b/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
diff --git a/tests/environment b/tests/environment
diff --git a/tests/unit/handlers/test_handlers.py b/tests/unit/handlers/test_handlers.py
@@ -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):

diff --git a/tests/unit/handlers/test_structured_log.py b/tests/unit/handlers/test_structured_log.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
+3 −2		deployable/nodejs/Dockerfile
+68 −20		deployable/nodejs/app.js
+3 −1		deployable/nodejs/package.json
+15 −0		deployable/python/snippets.py
+0 −3		envctl/env_scripts/go/kubernetes.sh
+89 −0		envctl/env_scripts/nodejs/appengine_standard.sh
+0 −1		envctl/env_scripts/nodejs/cloudrun.sh
+91 −0		envctl/env_scripts/nodejs/compute.sh
+1 −4		envctl/env_scripts/nodejs/functions.sh
+132 −0		envctl/env_scripts/nodejs/kubernetes.sh
+1 −1		tests/common/common.py
+40 −0		tests/common/python.py
+2 −2		tests/go/test_kubernetes.py
+29 −0		tests/nodejs/test_appengine_standard.py
+30 −0		tests/nodejs/test_compute.py
+30 −0		tests/nodejs/test_kubernetes.py