[DRAFT] 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,26 @@ 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
+        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)
+        # set string payload values
+        encoded_string = json.dumps(record.msg or "", ensure_ascii=False)
+        if isinstance(record.msg, collections.abc.Mapping) and len(encoded_string) > 2:
+            # if dict input, extract key/value pairs
+            record._payload_str = encoded_string[1:-1]
+        else:
+            # otherwise, the message is the string value of the input
+            record._payload_str = '"message": {}'.format(encoded_string)
         return True
 
 
@@ -184,9 +196,14 @@ 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
+        if isinstance(record.msg, collections.abc.Mapping):
+            # if input is a dictionary, pass as-is for structured logging
+            message = record.msg
+        else:
+            # 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

@@ -20,7 +20,7 @@
 from google.cloud.logging_v2.handlers.handlers import CloudLoggingFilter
 
 GCP_FORMAT = (
-    '{"message": "%(_msg_str)s", '
+    "{%(_payload_str)s, "
     '"severity": "%(levelname)s", '
     '"logging.googleapis.com/labels": %(_labels_str)s, '
     '"logging.googleapis.com/trace": "%(_trace_str)s", '

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

@@ -276,6 +276,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"
 
@@ -290,7 +319,7 @@ def test_log_handler_async(self):
         cloud_logger.warn(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)
 
@@ -312,7 +341,7 @@ def test_log_handler_sync(self):
         cloud_logger.warn(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)
 
@@ -349,7 +378,9 @@ def test_handlers_w_extras(self):
         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].labels, {**extra["labels"], "python_logger": LOGGER_NAME}
+        )
         self.assertEqual(entries[0].resource.type, extra["resource"].type)
 
     def test_log_root_handler(self):
@@ -366,7 +397,7 @@ def test_log_root_handler(self):
         logging.warn(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)

tests/unit/handlers/test_handlers.py

@@ -63,6 +63,7 @@ def test_filter_record(self):
             "file": "testpath",
             "function": "test-function",
         }
+        expected_label = {"python_logger": logname}
         record = logging.LogRecord(
             logname,
             logging.INFO,
@@ -78,7 +79,7 @@ def test_filter_record(self):
         self.assertTrue(success)
 
         self.assertEqual(record.msg, message)
-        self.assertEqual(record._msg_str, message)
+        self.assertEqual(record._payload_str, '"message": "{}"'.format(message))
         self.assertEqual(record._source_location, expected_location)
         self.assertEqual(record._source_location_str, json.dumps(expected_location))
         self.assertIsNone(record._resource)
@@ -88,8 +89,8 @@ def test_filter_record(self):
         self.assertEqual(record._span_id_str, "")
         self.assertIsNone(record._http_request)
         self.assertEqual(record._http_request_str, "{}")
-        self.assertIsNone(record._labels)
-        self.assertEqual(record._labels_str, "{}")
+        self.assertEqual(record._labels, expected_label)
+        self.assertEqual(record._labels_str, json.dumps(expected_label))
 
     def test_minimal_record(self):
         """
@@ -105,7 +106,7 @@ def test_minimal_record(self):
         self.assertTrue(success)
 
         self.assertIsNone(record.msg)
-        self.assertEqual(record._msg_str, "")
+        self.assertEqual(record._payload_str, '"message": ""')
         self.assertIsNone(record._source_location)
         self.assertEqual(record._source_location_str, "{}")
         self.assertIsNone(record._resource)
@@ -295,7 +296,16 @@ def test_emit(self):
         handler.handle(record)
         self.assertEqual(
             handler.transport.send_called_with,
-            (record, message, _GLOBAL_RESOURCE, None, None, None, None, None),
+            (
+                record,
+                message,
+                _GLOBAL_RESOURCE,
+                {"python_logger": logname},
+                None,
+                None,
+                None,
+                None,
+            ),
         )
 
     def test_emit_manual_field_override(self):
@@ -332,6 +342,7 @@ def test_emit_manual_field_override(self):
             "default_key": "default-value",
             "overwritten_key": "new_value",
             "added_key": "added_value",
+            "python_logger": logname,
         }
         setattr(record, "labels", added_labels)
         handler.handle(record)

tests/unit/handlers/test_structured_log.py

@@ -60,6 +60,7 @@ def test_format(self):
         record = logging.LogRecord(
             logname, logging.INFO, pathname, lineno, message, None, None, func=func
         )
+        expected_labels = {**labels, "python_logger": logname}
         expected_payload = {
             "message": message,
             "severity": record.levelname,
@@ -71,7 +72,7 @@ def test_format(self):
                 "function": func,
             },
             "httpRequest": {},
-            "logging.googleapis.com/labels": labels,
+            "logging.googleapis.com/labels": expected_labels,
         }
         handler.filter(record)
         result = json.loads(handler.format(record))
@@ -197,6 +198,7 @@ def test_format_overrides(self):
                 "default_key": "default-value",
                 "overwritten_key": "new_value",
                 "added_key": "added_value",
+                "python_logger": logname,
             },
         }