diff --git a/google/cloud/logging_v2/handlers/handlers.py b/google/cloud/logging_v2/handlers/handlers.py index b554a6fdb..8d14852e1 100644 --- a/google/cloud/logging_v2/handlers/handlers.py +++ b/google/cloud/logging_v2/handlers/handlers.py @@ -192,13 +192,8 @@ def emit(self, record): """ resource = record._resource or self.resource labels = record._labels - message = None - if isinstance(record.msg, collections.abc.Mapping): - # if input is a dictionary, pass as-is for structured logging - message = record.msg - elif record.msg: - # otherwise, format message string based on superclass - message = super(CloudLoggingHandler, self).format(record) + message = _format_and_parse_message(record, self) + if resource.type == _GAE_RESOURCE_TYPE and record._trace is not None: # add GAE-specific label labels = {_GAE_TRACE_ID_LABEL: record._trace, **(labels or {})} @@ -215,6 +210,35 @@ def emit(self, record): ) +def _format_and_parse_message(record, formatter_handler): + """ + Helper function to apply formatting to a LogRecord message, + and attempt to parse encoded JSON into a dictionary object. + + Resulting output will be of type (str | dict | None) + + Args: + record (logging.LogRecord): The record object representing the log + formatter_handler (logging.Handler): The handler used to format the log + """ + # if message is a dictionary, return as-is + if isinstance(record.msg, collections.abc.Mapping): + return record.msg + # format message string based on superclass + message = formatter_handler.format(record) + try: + # attempt to parse encoded json into dictionary + if message[0] == "{": + json_message = json.loads(message) + if isinstance(json_message, collections.abc.Mapping): + message = json_message + except (json.decoder.JSONDecodeError, IndexError): + # log string is not valid json + pass + # if formatted message contains no content, return None + return message if message != "None" else None + + def setup_logging( handler, *, excluded_loggers=EXCLUDED_LOGGER_DEFAULTS, log_level=logging.INFO ): diff --git a/google/cloud/logging_v2/handlers/structured_log.py b/google/cloud/logging_v2/handlers/structured_log.py index c981a1f27..6ec83fade 100644 --- a/google/cloud/logging_v2/handlers/structured_log.py +++ b/google/cloud/logging_v2/handlers/structured_log.py @@ -19,6 +19,7 @@ import logging.handlers from google.cloud.logging_v2.handlers.handlers import CloudLoggingFilter +from google.cloud.logging_v2.handlers.handlers import _format_and_parse_message GCP_FORMAT = ( "{%(_payload_str)s" @@ -62,16 +63,16 @@ def format(self, record): str: A JSON string formatted for GCP structured logging. """ payload = None - if isinstance(record.msg, collections.abc.Mapping): + message = _format_and_parse_message(record, super(StructuredLogHandler, self)) + + if isinstance(message, collections.abc.Mapping): # if input is a dictionary, encode it as a json string - encoded_msg = json.dumps(record.msg, ensure_ascii=False) + encoded_msg = json.dumps(message, ensure_ascii=False) # strip out open and close parentheses payload = encoded_msg.lstrip("{").rstrip("}") + "," - elif record.msg: - # otherwise, format based on superclass - super_message = super(StructuredLogHandler, self).format(record) + elif message: # properly break any formatting in string to make it json safe - encoded_message = json.dumps(super_message, ensure_ascii=False) + encoded_message = json.dumps(message, ensure_ascii=False) payload = '"message": {},'.format(encoded_message) record._payload_str = payload or "" diff --git a/tests/environment b/tests/environment index 3b1d17e2e..c83d9e8a5 160000 --- a/tests/environment +++ b/tests/environment @@ -1 +1 @@ -Subproject commit 3b1d17e2ee5da599d72c56daa2e152c2679ed73f +Subproject commit c83d9e8a5cc87f08eeee0e99a7cb12e0cd18c0d0 diff --git a/tests/unit/handlers/test_handlers.py b/tests/unit/handlers/test_handlers.py index 74f5c6dd8..d36dc8959 100644 --- a/tests/unit/handlers/test_handlers.py +++ b/tests/unit/handlers/test_handlers.py @@ -311,6 +311,20 @@ def test_emit(self): ), ) + def test_emit_minimal(self): + from google.cloud.logging_v2.logger import _GLOBAL_RESOURCE + + client = _Client(self.PROJECT) + handler = self._make_one( + client, transport=_Transport, resource=_GLOBAL_RESOURCE + ) + record = logging.LogRecord(None, logging.INFO, None, None, None, None, None) + handler.handle(record) + self.assertEqual( + handler.transport.send_called_with, + (record, None, _GLOBAL_RESOURCE, None, None, None, None, None,), + ) + def test_emit_manual_field_override(self): from google.cloud.logging_v2.logger import _GLOBAL_RESOURCE from google.cloud.logging_v2.resource import Resource @@ -401,6 +415,70 @@ def test_emit_with_custom_formatter(self): ), ) + def test_emit_dict(self): + """ + Handler should support logging dictionaries + """ + from google.cloud.logging_v2.logger import _GLOBAL_RESOURCE + + client = _Client(self.PROJECT) + handler = self._make_one( + client, transport=_Transport, resource=_GLOBAL_RESOURCE, + ) + message = {"x": "test"} + logname = "logname" + expected_label = {"python_logger": logname} + record = logging.LogRecord( + logname, logging.INFO, None, None, message, None, None + ) + handler.handle(record) + + self.assertEqual( + handler.transport.send_called_with, + ( + record, + message, + _GLOBAL_RESOURCE, + expected_label, + None, + None, + None, + None, + ), + ) + + def test_emit_with_encoded_json(self): + """ + Handler should parse json encoded as a string + """ + 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='{ "x" : "%(name)s" }') + handler.setFormatter(logFormatter) + logname = "logname" + expected_result = {"x": logname} + expected_label = {"python_logger": logname} + record = logging.LogRecord(logname, logging.INFO, None, None, None, None, None) + handler.handle(record) + + self.assertEqual( + handler.transport.send_called_with, + ( + record, + expected_result, + _GLOBAL_RESOURCE, + expected_label, + None, + None, + None, + None, + ), + ) + def test_format_with_arguments(self): """ Handler should support format string arguments @@ -425,6 +503,112 @@ def test_format_with_arguments(self): ) +class TestFormatAndParseMessage(unittest.TestCase): + def test_none(self): + """ + None messages with no special formatting should return + None after formatting + """ + from google.cloud.logging_v2.handlers.handlers import _format_and_parse_message + + message = None + record = logging.LogRecord(None, None, None, None, message, None, None) + handler = logging.StreamHandler() + result = _format_and_parse_message(record, handler) + self.assertEqual(result, None) + + def test_none_formatted(self): + """ + None messages with formatting rules should return formatted string + """ + from google.cloud.logging_v2.handlers.handlers import _format_and_parse_message + + message = None + record = logging.LogRecord("logname", None, None, None, message, None, None) + handler = logging.StreamHandler() + formatter = logging.Formatter("name: %(name)s") + handler.setFormatter(formatter) + result = _format_and_parse_message(record, handler) + self.assertEqual(result, "name: logname") + + def test_unformatted_string(self): + """ + Unformated strings should be returned unchanged + """ + from google.cloud.logging_v2.handlers.handlers import _format_and_parse_message + + message = '"test"' + record = logging.LogRecord("logname", None, None, None, message, None, None) + handler = logging.StreamHandler() + result = _format_and_parse_message(record, handler) + self.assertEqual(result, message) + + def test_empty_string(self): + """ + Empty strings should be returned unchanged + """ + from google.cloud.logging_v2.handlers.handlers import _format_and_parse_message + + message = "" + record = logging.LogRecord("logname", None, None, None, message, None, None) + handler = logging.StreamHandler() + result = _format_and_parse_message(record, handler) + self.assertEqual(result, message) + + def test_string_formatted_with_args(self): + """ + string messages should properly apply formatting and arguments + """ + from google.cloud.logging_v2.handlers.handlers import _format_and_parse_message + + message = "argument: %s" + arg = "test" + record = logging.LogRecord("logname", None, None, None, message, arg, None) + handler = logging.StreamHandler() + formatter = logging.Formatter("name: %(name)s :: message: %(message)s") + handler.setFormatter(formatter) + result = _format_and_parse_message(record, handler) + self.assertEqual(result, "name: logname :: message: argument: test") + + def test_dict(self): + """ + dict messages should be unchanged + """ + from google.cloud.logging_v2.handlers.handlers import _format_and_parse_message + + message = {"a": "b"} + record = logging.LogRecord("logname", None, None, None, message, None, None) + handler = logging.StreamHandler() + formatter = logging.Formatter("name: %(name)s") + handler.setFormatter(formatter) + result = _format_and_parse_message(record, handler) + self.assertEqual(result, message) + + def test_string_encoded_dict(self): + """ + dicts should be extracted from string messages + """ + from google.cloud.logging_v2.handlers.handlers import _format_and_parse_message + + message = '{ "x": { "y" : "z" } }' + record = logging.LogRecord("logname", None, None, None, message, None, None) + handler = logging.StreamHandler() + result = _format_and_parse_message(record, handler) + self.assertEqual(result, {"x": {"y": "z"}}) + + def test_broken_encoded_dict(self): + """ + unparseable encoded dicts should be kept as strings + """ + from google.cloud.logging_v2.handlers.handlers import _format_and_parse_message + + message = '{ "x": { "y" : ' + record = logging.LogRecord("logname", None, None, None, message, None, None) + handler = logging.StreamHandler() + result = _format_and_parse_message(record, handler) + self.assertEqual(result, message) + + class TestSetupLogging(unittest.TestCase): def _call_fut(self, handler, excludes=None): from google.cloud.logging.handlers import setup_logging diff --git a/tests/unit/handlers/test_structured_log.py b/tests/unit/handlers/test_structured_log.py index dd09edbbf..1fc96b23b 100644 --- a/tests/unit/handlers/test_structured_log.py +++ b/tests/unit/handlers/test_structured_log.py @@ -92,13 +92,16 @@ def test_format_minimal(self): record = logging.LogRecord(None, logging.INFO, None, None, None, None, None,) record.created = None expected_payload = { + "severity": "INFO", "logging.googleapis.com/trace": "", + "logging.googleapis.com/spanId": "", "logging.googleapis.com/sourceLocation": {}, "httpRequest": {}, "logging.googleapis.com/labels": {}, } handler.filter(record) result = json.loads(handler.format(record)) + self.assertEqual(set(expected_payload.keys()), set(result.keys())) for (key, value) in expected_payload.items(): self.assertEqual( value, result[key], f"expected_payload[{key}] != result[{key}]" @@ -152,6 +155,44 @@ def test_format_with_custom_formatter(self): handler.filter(record) result = handler.format(record) self.assertIn(expected_result, result) + self.assertIn("message", result) + + def test_dict(self): + """ + Handler should parse json encoded as a string + """ + import logging + + handler = self._make_one() + message = {"x": "test"} + expected_result = '"x": "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) + self.assertNotIn("message", result) + + def test_encoded_json(self): + """ + Handler should parse json encoded as a string + """ + import logging + + handler = self._make_one() + logFormatter = logging.Formatter(fmt='{ "name" : "%(name)s" }') + handler.setFormatter(logFormatter) + expected_result = '"name": "logname"' + record = logging.LogRecord( + "logname", logging.INFO, None, None, None, None, None, + ) + record.created = None + handler.filter(record) + result = handler.format(record) + self.assertIn(expected_result, result) + self.assertNotIn("message", result) def test_format_with_arguments(self): """