feat!: support json logs

google/cloud/logging_v2/handlers/handlers.py

@@ -14,6 +14,7 @@
 
 """Python :mod:`logging` handlers for Cloud Logging."""
 
+import collections
 import json
 import logging
 
@@ -92,15 +93,19 @@ def filter(self, record):
         record._span_id = getattr(record, "span_id", inferred_span) or None
         record._http_request = getattr(record, "http_request", inferred_http)
         record._source_location = CloudLoggingFilter._infer_source_location(record)
-        record._labels = {**self.default_labels, **user_labels} or None
+        # add logger name as a label if possible
+        logger_label = {"python_logger": record.name} if record.name else {}
+        record._labels = {**logger_label, **self.default_labels, **user_labels} or None
         # create string representations for structured logging
         record._trace_str = record._trace or ""
         record._span_id_str = record._span_id or ""
-        record._http_request_str = json.dumps(record._http_request or {})
-        record._source_location_str = json.dumps(record._source_location or {})
-        record._labels_str = json.dumps(record._labels or {})
-        # break quotes for parsing through structured logging
-        record._msg_str = str(record.msg).replace('"', '\\"') if record.msg else ""
+        record._http_request_str = json.dumps(
+            record._http_request or {}, ensure_ascii=False
+        )
+        record._source_location_str = json.dumps(
+            record._source_location or {}, ensure_ascii=False
+        )
+        record._labels_str = json.dumps(record._labels or {}, ensure_ascii=False)
         return True
 
 
@@ -183,9 +188,15 @@ def emit(self, record):
         Args:
             record (logging.LogRecord): The record to be logged.
         """
-        message = super(CloudLoggingHandler, self).format(record)
-        labels = record._labels
         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)
         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 {})}

google/cloud/logging_v2/handlers/structured_log.py

@@ -14,19 +14,21 @@
 
 """Logging handler for printing formatted structured logs to standard output.
 """
+import collections
 import json
 import logging.handlers
 
 from google.cloud.logging_v2.handlers.handlers import CloudLoggingFilter
 
 GCP_FORMAT = (
-    '{"message": %(_formatted_msg)s, '
+    "{%(_payload_str)s"
     '"severity": "%(levelname)s", '
     '"logging.googleapis.com/labels": %(_labels_str)s, '
     '"logging.googleapis.com/trace": "%(_trace_str)s", '
     '"logging.googleapis.com/spanId": "%(_span_id_str)s", '
     '"logging.googleapis.com/sourceLocation": %(_source_location_str)s, '
-    '"httpRequest": %(_http_request_str)s }'
+    '"httpRequest": %(_http_request_str)s '
+    "}"
 )
 
 
@@ -59,12 +61,20 @@ def format(self, record):
         Returns:
             str: A JSON string formatted for GKE fluentd.
         """
-        # 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 "")
+        payload = None
+        if isinstance(record.msg, collections.abc.Mapping):
+            # if input is a dictionary, encode it as a json string
+            encoded_msg = json.dumps(record.msg, 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)
+            # properly break any formatting in string to make it json safe
+            encoded_message = json.dumps(super_message, ensure_ascii=False)
+            payload = '"message": {},'.format(encoded_message)
+
+        record._payload_str = payload or ""
         # convert to GCP structred logging format
         gcp_payload = self._gcp_formatter.format(record)
         return gcp_payload

google/cloud/logging_v2/handlers/transports/background_thread.py

@@ -138,7 +138,7 @@ def _thread_main(self):
                 if item is _WORKER_TERMINATOR:
                     done = True  # Continue processing items.
                 else:
-                    batch.log_struct(**item)
+                    batch.log(**item)
 
             self._safely_commit_batch(batch)
 
@@ -227,12 +227,18 @@ def enqueue(self, record, message, **kwargs):
 
         Args:
             record (logging.LogRecord): Python log record that the handler was called with.
-            message (str): The message from the ``LogRecord`` after being
+            message (str or dict): The message from the ``LogRecord`` after being
                         formatted by the associated log formatters.
             kwargs: Additional optional arguments for the logger
         """
+        # set python logger name as label if missing
+        labels = kwargs.pop("labels", {})
+        if record.name:
+            labels["python_logger"] = labels.get("python_logger", record.name)
+        kwargs["labels"] = labels
+        # enqueue new entry
         queue_entry = {
-            "info": {"message": message, "python_logger": record.name},
+            "message": message,
             "severity": _helpers._normalize_severity(record.levelno),
             "timestamp": datetime.datetime.utcfromtimestamp(record.created),
         }
@@ -286,7 +292,7 @@ def send(self, record, message, **kwargs):
 
         Args:
             record (logging.LogRecord): Python log record that the handler was called with.
-            message (str): The message from the ``LogRecord`` after being
+            message (str or dict): The message from the ``LogRecord`` after being
                 formatted by the associated log formatters.
             kwargs: Additional optional arguments for the logger
         """

google/cloud/logging_v2/handlers/transports/base.py

@@ -27,7 +27,7 @@ def send(self, record, message, **kwargs):
 
         Args:
             record (logging.LogRecord): Python log record that the handler was called with.
-            message (str): The message from the ``LogRecord`` after being
+            message (str or dict): The message from the ``LogRecord`` after being
                 formatted by the associated log formatters.
             kwargs: Additional optional arguments for the logger
         """

google/cloud/logging_v2/handlers/transports/sync.py

@@ -16,7 +16,6 @@
 
 Logs directly to the the Cloud Logging API with a synchronous call.
 """
-
 from google.cloud.logging_v2 import _helpers
 from google.cloud.logging_v2.handlers.transports.base import Transport
 
@@ -36,11 +35,18 @@ def send(self, record, message, **kwargs):
         Args:
             record (logging.LogRecord):
                 Python log record that the handler was called with.
-            message (str): The message from the ``LogRecord`` after being
+            message (str or dict): The message from the ``LogRecord`` after being
                 formatted by the associated log formatters.
             kwargs: Additional optional arguments for the logger
         """
-        info = {"message": message, "python_logger": record.name}
-        self.logger.log_struct(
-            info, severity=_helpers._normalize_severity(record.levelno), **kwargs,
+        # set python logger name as label if missing
+        labels = kwargs.pop("labels", {})
+        if record.name:
+            labels["python_logger"] = labels.get("python_logger", record.name)
+        # send log synchronously
+        self.logger.log(
+            message,
+            severity=_helpers._normalize_severity(record.levelno),
+            labels=labels,
+            **kwargs,
         )

google/cloud/logging_v2/logger.py

@@ -14,13 +14,16 @@
 
 """Define API Loggers."""
 
+import collections
+
 from google.cloud.logging_v2._helpers import _add_defaults_to_filter
 from google.cloud.logging_v2.entries import LogEntry
 from google.cloud.logging_v2.entries import ProtobufEntry
 from google.cloud.logging_v2.entries import StructEntry
 from google.cloud.logging_v2.entries import TextEntry
 from google.cloud.logging_v2.resource import Resource
 
+import google.protobuf.message
 
 _GLOBAL_RESOURCE = Resource(type="global", labels={})
 
@@ -197,6 +200,30 @@ def log_proto(self, message, *, client=None, **kw):
         """
         self._do_log(client, ProtobufEntry, message, **kw)
 
+    def log(self, message=None, *, client=None, **kw):
+        """Log an arbitrary message via a POST request.
+        Type will be inferred based on the input message.
+
+        See
+        https://cloud.google.com/logging/docs/reference/v2/rest/v2/entries/list
+
+        Args:
+            message (Optional[str or dict or google.protobuf.Message]): The message. to log
+            client (Optional[~logging_v2.client.Client]):
+                The client to use.  If not passed, falls back to the
+                ``client`` stored on the current sink.
+            kw (Optional[dict]): additional keyword arguments for the entry.
+                See :class:`~logging_v2.entries.LogEntry`.
+        """
+        entry_type = LogEntry
+        if isinstance(message, google.protobuf.message.Message):
+            entry_type = ProtobufEntry
+        elif isinstance(message, collections.abc.Mapping):
+            entry_type = StructEntry
+        elif isinstance(message, str):
+            entry_type = TextEntry
+        self._do_log(client, entry_type, message, **kw)
+
     def delete(self, logger_name=None, *, client=None):
         """Delete all entries in a logger via a DELETE request
 
@@ -361,6 +388,24 @@ def log_proto(self, message, **kw):
         """
         self.entries.append(ProtobufEntry(payload=message, **kw))
 
+    def log(self, message=None, **kw):
+        """Add an arbitrary message to be logged during :meth:`commit`.
+        Type will be inferred based on the input message.
+
+        Args:
+            message (Optional[str or dict or google.protobuf.Message]): The message. to log
+            kw (Optional[dict]): Additional keyword arguments for the entry.
+                See :class:`~logging_v2.entries.LogEntry`.
+        """
+        entry_type = LogEntry
+        if isinstance(message, google.protobuf.message.Message):
+            entry_type = ProtobufEntry
+        elif isinstance(message, collections.abc.Mapping):
+            entry_type = StructEntry
+        elif isinstance(message, str):
+            entry_type = TextEntry
+        self.entries.append(entry_type(payload=message, **kw))
+
     def commit(self, *, client=None):
         """Send saved log entries as a single API call.
 

tests/system/test_system.py

@@ -32,7 +32,6 @@
 from google.api_core.exceptions import ServiceUnavailable
 import google.cloud.logging
 from google.cloud._helpers import UTC
-from google.cloud.logging_v2.handlers import AppEngineHandler
 from google.cloud.logging_v2.handlers import CloudLoggingHandler
 from google.cloud.logging_v2.handlers.transports import SyncTransport
 from google.cloud.logging_v2 import client
@@ -368,6 +367,35 @@ def test_log_struct_w_metadata(self):
         self.assertEqual(request["requestUrl"], URI)
         self.assertEqual(request["status"], STATUS)
 
+    def test_log_w_text(self):
+        TEXT_PAYLOAD = "System test: test_log_w_text"
+        logger = Config.CLIENT.logger(self._logger_name("log_w_text"))
+        self.to_delete.append(logger)
+        logger.log(TEXT_PAYLOAD)
+        entries = _list_entries(logger)
+        self.assertEqual(len(entries), 1)
+        self.assertEqual(entries[0].payload, TEXT_PAYLOAD)
+
+    def test_log_w_struct(self):
+        logger = Config.CLIENT.logger(self._logger_name("log_w_struct"))
+        self.to_delete.append(logger)
+
+        logger.log(self.JSON_PAYLOAD)
+        entries = _list_entries(logger)
+
+        self.assertEqual(len(entries), 1)
+        self.assertEqual(entries[0].payload, self.JSON_PAYLOAD)
+
+    def test_log_empty(self):
+        logger = Config.CLIENT.logger(self._logger_name("log_empty"))
+        self.to_delete.append(logger)
+
+        logger.log()
+        entries = _list_entries(logger)
+
+        self.assertEqual(len(entries), 1)
+        self.assertIsNone(entries[0].payload)
+
     def test_log_handler_async(self):
         LOG_MESSAGE = "It was the worst of times"
 
@@ -382,7 +410,7 @@ def test_log_handler_async(self):
         cloud_logger.warning(LOG_MESSAGE)
         handler.flush()
         entries = _list_entries(logger)
-        expected_payload = {"message": LOG_MESSAGE, "python_logger": handler.name}
+        expected_payload = LOG_MESSAGE
         self.assertEqual(len(entries), 1)
         self.assertEqual(entries[0].payload, expected_payload)
 
@@ -404,44 +432,46 @@ def test_log_handler_sync(self):
         cloud_logger.warning(LOG_MESSAGE)
 
         entries = _list_entries(logger)
-        expected_payload = {"message": LOG_MESSAGE, "python_logger": LOGGER_NAME}
+        expected_payload = LOG_MESSAGE
         self.assertEqual(len(entries), 1)
         self.assertEqual(entries[0].payload, expected_payload)
 
     def test_handlers_w_extras(self):
         LOG_MESSAGE = "Testing with injected extras."
+        LOGGER_NAME = "handler_extras"
+        handler_name = self._logger_name(LOGGER_NAME)
+
+        handler = CloudLoggingHandler(
+            Config.CLIENT, name=handler_name, transport=SyncTransport
+        )
+
+        # only create the logger to delete, hidden otherwise
+        logger = Config.CLIENT.logger(handler.name)
+        self.to_delete.append(logger)
 
-        for cls in [CloudLoggingHandler, AppEngineHandler]:
-            LOGGER_NAME = f"{cls.__name__}-handler_extras"
-            handler_name = self._logger_name(LOGGER_NAME)
-
-            handler = cls(Config.CLIENT, name=handler_name, transport=SyncTransport)
-
-            # only create the logger to delete, hidden otherwise
-            logger = Config.CLIENT.logger(handler.name)
-            self.to_delete.append(logger)
-
-            cloud_logger = logging.getLogger(LOGGER_NAME)
-            cloud_logger.addHandler(handler)
-            expected_request = {"requestUrl": "localhost"}
-            expected_source = {"file": "test.py"}
-            extra = {
-                "trace": "123",
-                "span_id": "456",
-                "http_request": expected_request,
-                "source_location": expected_source,
-                "resource": Resource(type="cloudiot_device", labels={}),
-                "labels": {"test-label": "manual"},
-            }
-            cloud_logger.warning(LOG_MESSAGE, extra=extra)
-
-            entries = _list_entries(logger)
-            self.assertEqual(len(entries), 1)
-            self.assertEqual(entries[0].trace, extra["trace"])
-            self.assertEqual(entries[0].span_id, extra["span_id"])
-            self.assertEqual(entries[0].http_request, expected_request)
-            self.assertEqual(entries[0].labels, extra["labels"])
-            self.assertEqual(entries[0].resource.type, extra["resource"].type)
+        cloud_logger = logging.getLogger(LOGGER_NAME)
+        cloud_logger.addHandler(handler)
+        expected_request = {"requestUrl": "localhost"}
+        expected_source = {"file": "test.py"}
+        extra = {
+            "trace": "123",
+            "span_id": "456",
+            "http_request": expected_request,
+            "source_location": expected_source,
+            "resource": Resource(type="cloudiot_device", labels={}),
+            "labels": {"test-label": "manual"},
+        }
+        cloud_logger.warn(LOG_MESSAGE, extra=extra)
+
+        entries = _list_entries(logger)
+        self.assertEqual(len(entries), 1)
+        self.assertEqual(entries[0].trace, extra["trace"])
+        self.assertEqual(entries[0].span_id, extra["span_id"])
+        self.assertEqual(entries[0].http_request, expected_request)
+        self.assertEqual(
+            entries[0].labels, {**extra["labels"], "python_logger": LOGGER_NAME}
+        )
+        self.assertEqual(entries[0].resource.type, extra["resource"].type)
 
     def test_log_root_handler(self):
         LOG_MESSAGE = "It was the best of times."
@@ -457,7 +487,7 @@ def test_log_root_handler(self):
         logging.warning(LOG_MESSAGE)
 
         entries = _list_entries(logger)
-        expected_payload = {"message": LOG_MESSAGE, "python_logger": "root"}
+        expected_payload = LOG_MESSAGE
 
         self.assertEqual(len(entries), 1)
         self.assertEqual(entries[0].payload, expected_payload)