fix: nested json with structured log handler (#636)

Author: daniel-sanche

google/cloud/logging_v2/handlers/structured_log.py

@@ -96,8 +96,10 @@ def format(self, record):
                     del message[key]
             # if input is a dictionary, encode it as a json string
             encoded_msg = json.dumps(message, ensure_ascii=False)
-            # strip out open and close parentheses
-            payload = encoded_msg.lstrip("{").rstrip("}") + ","
+            # all json.dumps strings should start and end with parentheses
+            # strip them out to embed these fields in the larger JSON payload
+            if len(encoded_msg) > 2:
+                payload = encoded_msg[1:-1] + ","
         elif message:
             # properly break any formatting in string to make it json safe
             encoded_message = json.dumps(message, ensure_ascii=False)
@@ -119,5 +121,5 @@ def emit(self, record):
 
     def emit_instrumentation_info(self):
         google.cloud.logging_v2._instrumentation_emitted = True
-        diagnostic_object = _create_diagnostic_entry().to_api_repr()
-        logging.info(diagnostic_object)
+        diagnostic_object = _create_diagnostic_entry()
+        logging.info(diagnostic_object.payload)

tests/environment

@@ -573,6 +573,47 @@ def test_emit_w_json_extras(self):
             ),
         )
 
+    def test_format_with_nested_json(self):
+        """
+        JSON can contain nested dictionaries of data
+        """
+        from google.cloud.logging_v2.logger import _GLOBAL_RESOURCE
+        import logging
+
+        client = _Client(self.PROJECT)
+        handler = self._make_one(
+            client,
+            transport=_Transport,
+            resource=_GLOBAL_RESOURCE,
+        )
+        json_fields = {"outer": {"inner": {"hello": "world"}}}
+        record = logging.LogRecord(
+            None,
+            logging.INFO,
+            None,
+            None,
+            None,
+            None,
+            None,
+        )
+        record.created = None
+        setattr(record, "json_fields", json_fields)
+        handler.handle(record)
+        self.assertEqual(
+            handler.transport.send_called_with,
+            (
+                record,
+                json_fields,
+                _GLOBAL_RESOURCE,
+                None,
+                None,
+                None,
+                False,
+                None,
+                None,
+            ),
+        )
+
     def test_emit_with_encoded_json(self):
         """
         Handler should parse json encoded as a string

tests/unit/handlers/test_handlers.py

@@ -487,6 +487,30 @@ def test_format_with_json_fields(self):
         self.assertEqual(result["hello"], "world")
         self.assertEqual(result["number"], 12)
 
+    def test_format_with_nested_json(self):
+        """
+        JSON can contain nested dictionaries of data
+        """
+        import logging
+        import json
+
+        handler = self._make_one()
+        json_fields = {"outer": {"inner": {"hello": "world"}}}
+        record = logging.LogRecord(
+            None,
+            logging.INFO,
+            None,
+            None,
+            None,
+            None,
+            None,
+        )
+        record.created = None
+        setattr(record, "json_fields", json_fields)
+        handler.filter(record)
+        result = json.loads(handler.format(record))
+        self.assertEqual(result["outer"], json_fields["outer"])
+
     def test_emits_instrumentation_info(self):
         import logging
         import mock
@@ -510,3 +534,51 @@ def side_effect():
 
             # emit_instrumentation_info should be called once
             emit_info.assert_called_once()
+
+    def test_valid_instrumentation_info(self):
+        import logging
+        import mock
+        import json
+
+        with mock.patch.object(logging, "info") as mock_log:
+            handler = self._make_one()
+            handler.emit_instrumentation_info()
+            mock_log.assert_called_once()
+            # ensure instrumentaiton payload is formatted as expected
+            called_payload = mock_log.call_args.args[0]
+            self.assertEqual(len(called_payload.keys()), 1)
+            self.assertIn("logging.googleapis.com/diagnostic", called_payload.keys())
+            inst_source_dict = called_payload["logging.googleapis.com/diagnostic"]
+            self.assertEqual(len(inst_source_dict.keys()), 1)
+            self.assertIn("instrumentation_source", inst_source_dict.keys())
+            source_list = inst_source_dict["instrumentation_source"]
+            self.assertEqual(
+                len(source_list), 1, "expected single instrumentation source"
+            )
+            for source_dict in source_list:
+                self.assertEqual(
+                    len(source_dict.keys()),
+                    2,
+                    f"expected two keys in payload: {source_dict.keys()}",
+                )
+                self.assertIn("name", source_dict.keys())
+                self.assertIn("version", source_dict.keys())
+                self.assertEqual(source_dict["name"], "python")
+            # ensure it is parsed properly by handler
+            record = logging.LogRecord(
+                None,
+                logging.INFO,
+                None,
+                None,
+                called_payload,
+                None,
+                None,
+            )
+            record.created = None
+            handler.filter(record)
+            result = json.loads(handler.format(record))
+            self.assertEqual(
+                result["logging.googleapis.com/diagnostic"],
+                inst_source_dict,
+                "instrumentation payload not logged properly",
+            )

tests/unit/handlers/test_structured_log.py

@@ -69,6 +69,29 @@ def test_send(self):
             resource=_GLOBAL_RESOURCE,
         )
 
+    def test_send_json(self):
+        from google.cloud.logging_v2.logger import _GLOBAL_RESOURCE
+
+        client = _Client(self.PROJECT)
+        name = "python_logger"
+
+        transport, _ = self._make_one(client, name)
+
+        python_logger_name = "mylogger"
+        message = {"hello": {"world": "!"}}
+
+        record = logging.LogRecord(
+            python_logger_name, logging.INFO, None, None, message, None, None
+        )
+
+        transport.send(record, message, resource=_GLOBAL_RESOURCE)
+
+        transport.worker.enqueue.assert_called_once_with(
+            record,
+            message,
+            resource=_GLOBAL_RESOURCE,
+        )
+
     def test_trace_send(self):
         from google.cloud.logging_v2.logger import _GLOBAL_RESOURCE
 

tests/unit/handlers/transports/test_background_thread.py

@@ -70,7 +70,7 @@ def test_send_struct(self):
         client_name = "python"
         python_logger_name = "mylogger"
         transport = self._make_one(client, client_name)
-        message = {"message": "hello world", "extra": "test"}
+        message = {"message": "hello world", "extra": "test", "nested": {"one": 2}}
         record = logging.LogRecord(
             python_logger_name, logging.INFO, None, None, message, None, None
         )

tests/unit/handlers/transports/test_sync.py

@@ -304,6 +304,28 @@ def test_log_struct_defaults(self):
 
         self.assertEqual(api._write_entries_called_with, (ENTRIES, None, None, None))
 
+    def test_log_nested_struct(self):
+        from google.cloud.logging_v2.handlers._monitored_resources import (
+            detect_resource,
+        )
+
+        STRUCT = {"message": "MESSAGE", "weather": "cloudy", "nested": {"one": 2}}
+        RESOURCE = detect_resource(self.PROJECT)._to_dict()
+        ENTRIES = [
+            {
+                "logName": "projects/%s/logs/%s" % (self.PROJECT, self.LOGGER_NAME),
+                "jsonPayload": STRUCT,
+                "resource": RESOURCE,
+            }
+        ]
+        client = _Client(self.PROJECT)
+        api = client.logging_api = _DummyLoggingAPI()
+        logger = self._make_one(self.LOGGER_NAME, client=client)
+
+        logger.log(STRUCT)
+
+        self.assertEqual(api._write_entries_called_with, (ENTRIES, None, None, None))
+
     def test_log_struct_w_default_labels(self):
         from google.cloud.logging_v2.handlers._monitored_resources import (
             detect_resource,