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