diff --git a/google/cloud/logging_v2/handlers/structured_log.py b/google/cloud/logging_v2/handlers/structured_log.py index 0edb5c39..f0b4c69e 100644 --- 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 index 30d6a808..a0af8d10 160000 --- a/tests/environment +++ b/tests/environment @@ -1 +1 @@ -Subproject commit 30d6a80838a1cae6fb3945f41f3e1d90e815c0c9 +Subproject commit a0af8d102a3c711cdff0dd12e01c8bfd357b7a83 diff --git a/tests/unit/handlers/test_handlers.py b/tests/unit/handlers/test_handlers.py index 4ba05212..b7fef1b9 100644 --- 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 index 0536583a..3d1c11ab 100644 --- a/tests/unit/handlers/test_structured_log.py +++ b/tests/unit/handlers/test_structured_log.py @@ -109,7 +109,6 @@ 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"' @@ -117,9 +116,60 @@ def test_format_with_quotes(self): 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