From 536808c6f00ad2fc44a178bbd83010e635efdc08 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Mon, 7 Jun 2021 16:12:05 -0700 Subject: [PATCH 1/7] improved structured log formatting --- .../cloud/logging_v2/handlers/structured_log.py | 16 ++++++++++------ 1 file changed, 10 insertions(+), 6 deletions(-) diff --git a/google/cloud/logging_v2/handlers/structured_log.py b/google/cloud/logging_v2/handlers/structured_log.py index 0edb5c39e..40da01612 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,10 @@ def format(self, record): Returns: str: A JSON string formatted for GKE fluentd. """ - - payload = self.formatter.format(record) - return payload + # let other formatters alter to message + 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 From a1d830c581b56644ca7cf49b880d8d6014f9f43a Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Wed, 9 Jun 2021 13:29:49 -0700 Subject: [PATCH 2/7] fixed unit test --- google/cloud/logging_v2/handlers/structured_log.py | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/google/cloud/logging_v2/handlers/structured_log.py b/google/cloud/logging_v2/handlers/structured_log.py index 40da01612..f0b4c69ec 100644 --- a/google/cloud/logging_v2/handlers/structured_log.py +++ b/google/cloud/logging_v2/handlers/structured_log.py @@ -59,8 +59,10 @@ def format(self, record): Returns: str: A JSON string formatted for GKE fluentd. """ - # let other formatters alter to message - super_payload = super(StructuredLogHandler, self).format(record) + # 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 From e0e50332408f01f98d89e06dca69efe78d5490bd Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Wed, 9 Jun 2021 13:59:23 -0700 Subject: [PATCH 3/7] added unit tests for new functionality --- tests/unit/handlers/test_handlers.py | 71 +++++++++++++++++++++- tests/unit/handlers/test_structured_log.py | 56 ++++++++++++++++- 2 files changed, 122 insertions(+), 5 deletions(-) diff --git a/tests/unit/handlers/test_handlers.py b/tests/unit/handlers/test_handlers.py index 4ba052121..181c01821 100644 --- a/tests/unit/handlers/test_handlers.py +++ b/tests/unit/handlers/test_handlers.py @@ -291,7 +291,7 @@ 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 +315,7 @@ 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 +350,73 @@ 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 + from google.cloud.logging_v2.resource import 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 + from google.cloud.logging_v2.resource import 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 0536583a5..8867b2e82 100644 --- a/tests/unit/handlers/test_structured_log.py +++ b/tests/unit/handlers/test_structured_log.py @@ -117,9 +117,59 @@ 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 + import json + + 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 + import json + + 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 + import json + + 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 From 43084efba29ed54ee8a0ae407582c596646a82c1 Mon Sep 17 00:00:00 2001 From: Owl Bot Date: Wed, 9 Jun 2021 21:24:25 +0000 Subject: [PATCH 4/7] =?UTF-8?q?=F0=9F=A6=89=20Updates=20from=20OwlBot?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- tests/unit/handlers/test_handlers.py | 48 ++++++++-------------- tests/unit/handlers/test_structured_log.py | 10 +++-- 2 files changed, 24 insertions(+), 34 deletions(-) diff --git a/tests/unit/handlers/test_handlers.py b/tests/unit/handlers/test_handlers.py index 181c01821..e628d69d3 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.INFO, 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.INFO, 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) @@ -359,29 +363,20 @@ def test_emit_with_custom_formatter(self): client = _Client(self.PROJECT) handler = self._make_one( - client, - transport=_Transport, - resource=_GLOBAL_RESOURCE, + client, transport=_Transport, resource=_GLOBAL_RESOURCE, ) - logFormatter = logging.Formatter(fmt='%(name)s :: %(levelname)s :: %(message)s') + 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 = 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, - ), + (record, expected_result, _GLOBAL_RESOURCE, None, None, None, None, None,), ) def test_format_with_arguments(self): @@ -393,28 +388,19 @@ def test_format_with_arguments(self): client = _Client(self.PROJECT) handler = self._make_one( - client, - transport=_Transport, - resource=_GLOBAL_RESOURCE, + 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) + 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, - ), + (record, expected_result, _GLOBAL_RESOURCE, None, None, None, None, None,), ) diff --git a/tests/unit/handlers/test_structured_log.py b/tests/unit/handlers/test_structured_log.py index 8867b2e82..1017f69f3 100644 --- a/tests/unit/handlers/test_structured_log.py +++ b/tests/unit/handlers/test_structured_log.py @@ -144,11 +144,13 @@ def test_format_with_custom_formatter(self): import json handler = self._make_one() - logFormatter = logging.Formatter(fmt='%(name)s :: %(levelname)s :: %(message)s') + 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 = logging.LogRecord( + "logname", logging.INFO, None, None, message, None, None, + ) record.created = None handler.filter(record) result = handler.format(record) @@ -165,7 +167,9 @@ def test_format_with_arguments(self): message = "name: %s" name_arg = "Daniel" expected_result = "name: Daniel" - record = logging.LogRecord(None, logging.INFO, None, None, message, name_arg, None,) + record = logging.LogRecord( + None, logging.INFO, None, None, message, name_arg, None, + ) record.created = None handler.filter(record) result = handler.format(record) From efb79ab0b448b3888525dea8f1edf864dc155748 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Wed, 9 Jun 2021 15:18:26 -0700 Subject: [PATCH 5/7] updated environment tests --- tests/environment | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/environment b/tests/environment index 30d6a8083..77f8cfa9f 160000 --- a/tests/environment +++ b/tests/environment @@ -1 +1 @@ -Subproject commit 30d6a80838a1cae6fb3945f41f3e1d90e815c0c9 +Subproject commit 77f8cfa9fddfbf0afed9f4f3eb9ed193063e93db From c8ee04044b6bbc6e9e2f9752c9d801e64188cee0 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Wed, 9 Jun 2021 16:47:34 -0700 Subject: [PATCH 6/7] update environment test issue --- tests/environment | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/environment b/tests/environment index 77f8cfa9f..a0af8d102 160000 --- a/tests/environment +++ b/tests/environment @@ -1 +1 @@ -Subproject commit 77f8cfa9fddfbf0afed9f4f3eb9ed193063e93db +Subproject commit a0af8d102a3c711cdff0dd12e01c8bfd357b7a83 From 7b63137f3f9fa2b8918052ea3868cfef040b31c1 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Wed, 9 Jun 2021 17:10:54 -0700 Subject: [PATCH 7/7] fixed lint issues --- tests/unit/handlers/test_handlers.py | 2 -- tests/unit/handlers/test_structured_log.py | 4 ---- 2 files changed, 6 deletions(-) diff --git a/tests/unit/handlers/test_handlers.py b/tests/unit/handlers/test_handlers.py index e628d69d3..b7fef1b9e 100644 --- a/tests/unit/handlers/test_handlers.py +++ b/tests/unit/handlers/test_handlers.py @@ -359,7 +359,6 @@ def test_emit_with_custom_formatter(self): Handler should respect custom formatters attached """ from google.cloud.logging_v2.logger import _GLOBAL_RESOURCE - from google.cloud.logging_v2.resource import Resource client = _Client(self.PROJECT) handler = self._make_one( @@ -384,7 +383,6 @@ def test_format_with_arguments(self): Handler should support format string arguments """ from google.cloud.logging_v2.logger import _GLOBAL_RESOURCE - from google.cloud.logging_v2.resource import Resource client = _Client(self.PROJECT) handler = self._make_one( diff --git a/tests/unit/handlers/test_structured_log.py b/tests/unit/handlers/test_structured_log.py index 1017f69f3..3d1c11ab0 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"' @@ -125,7 +124,6 @@ def test_format_with_line_break(self): When logging a message containing \n, it should be properly escaped """ import logging - import json handler = self._make_one() message = "test\ntest" @@ -141,7 +139,6 @@ def test_format_with_custom_formatter(self): Handler should respect custom formatters attached """ import logging - import json handler = self._make_one() logFormatter = logging.Formatter(fmt="%(name)s :: %(levelname)s :: %(message)s") @@ -161,7 +158,6 @@ def test_format_with_arguments(self): Handler should support format string arguments """ import logging - import json handler = self._make_one() message = "name: %s"