refactor: clean up CloudLoggingFilter (#281)

Author: daniel-sanche

google/cloud/logging_v2/handlers/_helpers.py

@@ -68,10 +68,7 @@ def get_request_data_from_flask():
     http_request = {
         "requestMethod": flask.request.method,
         "requestUrl": flask.request.url,
-        "requestSize": flask.request.content_length,
         "userAgent": flask.request.user_agent.string,
-        "remoteIp": flask.request.remote_addr,
-        "referer": flask.request.referrer,
         "protocol": flask.request.environ.get(_PROTOCOL_HEADER),
     }
 
@@ -96,20 +93,11 @@ def get_request_data_from_django():
     if request is None:
         return None, None, None
 
-    # convert content_length to int if it exists
-    content_length = None
-    try:
-        content_length = int(request.META.get(_DJANGO_CONTENT_LENGTH))
-    except (ValueError, TypeError):
-        content_length = None
     # build http_request
     http_request = {
         "requestMethod": request.method,
         "requestUrl": request.build_absolute_uri(),
-        "requestSize": content_length,
         "userAgent": request.META.get(_DJANGO_USERAGENT_HEADER),
-        "remoteIp": request.META.get(_DJANGO_REMOTE_ADDR_HEADER),
-        "referer": request.META.get(_DJANGO_REFERER_HEADER),
         "protocol": request.META.get(_PROTOCOL_HEADER),
     }
 

google/cloud/logging_v2/handlers/handlers.py

@@ -14,6 +14,7 @@
 
 """Python :mod:`logging` handlers for Cloud Logging."""
 
+import json
 import logging
 
 from google.cloud.logging_v2.logger import _GLOBAL_RESOURCE
@@ -32,50 +33,57 @@ class CloudLoggingFilter(logging.Filter):
     """Python standard ``logging`` Filter class to add Cloud Logging
     information to each LogRecord.
 
-    When attached to a LogHandler, each incoming log will receive trace and
-    http_request related to the request. This data can be overwritten using
-    the `extras` argument when writing logs.
+    When attached to a LogHandler, each incoming log will be modified
+    to include new Cloud Logging relevant data. This data can be manually
+    overwritten using the `extras` argument when writing logs.
     """
 
     def __init__(self, project=None, default_labels=None):
         self.project = project
         self.default_labels = default_labels if default_labels else {}
 
-    def filter(self, record):
-        # ensure record has all required fields set
+    @staticmethod
+    def _infer_source_location(record):
+        """Helper function to infer source location data from a LogRecord.
+        Will default to record.source_location if already set
+        """
         if hasattr(record, "source_location"):
-            record.line = int(record.source_location.get("line", 0))
-            record.file = record.source_location.get("file", "")
-            record.function = record.source_location.get("function", "")
+            return record.source_location
         else:
-            record.line = record.lineno if record.lineno else 0
-            record.file = record.pathname if record.pathname else ""
-            record.function = record.funcName if record.funcName else ""
-            if any([record.line, record.file, record.function]):
-                record.source_location = {
-                    "line": record.line,
-                    "file": record.file,
-                    "function": record.function,
-                }
-        record.msg = "" if record.msg is None else record.msg
-        # find http request data
+            name_map = [
+                ("line", "lineno"),
+                ("file", "pathname"),
+                ("function", "funcName"),
+            ]
+            output = {}
+            for (gcp_name, std_lib_name) in name_map:
+                value = getattr(record, std_lib_name, None)
+                if value is not None:
+                    output[gcp_name] = value
+            return output if output else None
+
+    def filter(self, record):
+        """
+        Add new Cloud Logging data to each LogRecord as it comes in
+        """
+        user_labels = getattr(record, "labels", {})
         inferred_http, inferred_trace, inferred_span = get_request_data()
         if inferred_trace is not None and self.project is not None:
             inferred_trace = f"projects/{self.project}/traces/{inferred_trace}"
-        # set labels
-        user_labels = getattr(record, "labels", {})
-        record.total_labels = {**self.default_labels, **user_labels}
-        record.total_labels_str = ", ".join(
-            [f'"{k}": "{v}"' for k, v in record.total_labels.items()]
-        )
-
-        record.trace = getattr(record, "trace", inferred_trace) or ""
-        record.span_id = getattr(record, "span_id", inferred_span) or ""
-        record.http_request = getattr(record, "http_request", inferred_http) or {}
-        record.request_method = record.http_request.get("requestMethod", "")
-        record.request_url = record.http_request.get("requestUrl", "")
-        record.user_agent = record.http_request.get("userAgent", "")
-        record.protocol = record.http_request.get("protocol", "")
+        # set new record values
+        record._resource = getattr(record, "resource", None)
+        record._trace = getattr(record, "trace", inferred_trace) or None
+        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
+        # create guaranteed string representations for structured logging
+        record._msg_str = record.msg or ""
+        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 {})
         return True
 
 
@@ -163,12 +171,12 @@ def emit(self, record):
         self.transport.send(
             record,
             message,
-            resource=getattr(record, "resource", self.resource),
-            labels=getattr(record, "total_labels", None) or None,
-            trace=getattr(record, "trace", None) or None,
-            span_id=getattr(record, "span_id", None) or None,
-            http_request=getattr(record, "http_request", None) or None,
-            source_location=getattr(record, "source_location", None) or None,
+            resource=(record._resource or self.resource),
+            labels=record._labels,
+            trace=record._trace,
+            span_id=record._span_id,
+            http_request=record._http_request,
+            source_location=record._source_location,
         )
 
 

google/cloud/logging_v2/handlers/structured_log.py

@@ -20,13 +20,13 @@
 from google.cloud.logging_v2.handlers.handlers import CloudLoggingFilter
 
 GCP_FORMAT = (
-    '{"message": "%(message)s", '
+    '{"message": "%(_msg_str)s", '
     '"severity": "%(levelname)s", '
-    '"logging.googleapis.com/labels": { %(total_labels_str)s }, '
-    '"logging.googleapis.com/trace": "%(trace)s", '
-    '"logging.googleapis.com/spanId": "%(span_id)s", '
-    '"logging.googleapis.com/sourceLocation": { "file": "%(file)s", "line": "%(line)d", "function": "%(function)s"}, '
-    '"httpRequest": {"requestMethod": "%(request_method)s", "requestUrl": "%(request_url)s", "userAgent": "%(user_agent)s", "protocol": "%(protocol)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 }'
 )
 
 

tests/unit/handlers/test__helpers.py

@@ -94,9 +94,6 @@ def test_http_request_populated(self):
         self.assertEqual(http_request["requestMethod"], "PUT")
         self.assertEqual(http_request["requestUrl"], expected_path)
         self.assertEqual(http_request["userAgent"], expected_agent)
-        self.assertEqual(http_request["referer"], expected_referrer)
-        self.assertEqual(http_request["remoteIp"], expected_ip)
-        self.assertEqual(http_request["requestSize"], len(body_content))
         self.assertEqual(http_request["protocol"], "HTTP/1.1")
 
     def test_http_request_sparse(self):
@@ -191,9 +188,6 @@ def test_http_request_populated(self):
         self.assertEqual(http_request["requestMethod"], "PUT")
         self.assertEqual(http_request["requestUrl"], expected_path)
         self.assertEqual(http_request["userAgent"], expected_agent)
-        self.assertEqual(http_request["referer"], expected_referrer)
-        self.assertEqual(http_request["remoteIp"], "127.0.0.1")
-        self.assertEqual(http_request["requestSize"], len(body_content))
         self.assertEqual(http_request["protocol"], "HTTP/1.1")
 
     def test_http_request_sparse(self):
@@ -207,7 +201,6 @@ def test_http_request_sparse(self):
         http_request, *_ = self._call_fut()
         self.assertEqual(http_request["requestMethod"], "PUT")
         self.assertEqual(http_request["requestUrl"], expected_path)
-        self.assertEqual(http_request["remoteIp"], "127.0.0.1")
         self.assertEqual(http_request["protocol"], "HTTP/1.1")
 
 

tests/unit/handlers/test_handlers.py

@@ -16,6 +16,7 @@
 import unittest
 from unittest.mock import patch
 import mock
+import json
 
 from google.cloud.logging_v2.handlers._monitored_resources import (
     _FUNCTION_ENV_VARS,
@@ -57,26 +58,38 @@ def test_filter_record(self):
         filter_obj = self._make_one()
         logname = "loggername"
         message = "hello world，嗨 世界"
-        pathname = "testpath"
-        lineno = 1
-        func = "test-function"
+        expected_location = {
+            "line": 1,
+            "file": "testpath",
+            "function": "test-function",
+        }
         record = logging.LogRecord(
-            logname, logging.INFO, pathname, lineno, message, None, None, func=func
+            logname,
+            logging.INFO,
+            expected_location["file"],
+            expected_location["line"],
+            message,
+            None,
+            None,
+            func=expected_location["function"],
         )
 
         success = filter_obj.filter(record)
         self.assertTrue(success)
 
-        self.assertEqual(record.line, lineno)
         self.assertEqual(record.msg, message)
-        self.assertEqual(record.function, func)
-        self.assertEqual(record.file, pathname)
-        self.assertEqual(record.trace, "")
-        self.assertEqual(record.http_request, {})
-        self.assertEqual(record.request_method, "")
-        self.assertEqual(record.request_url, "")
-        self.assertEqual(record.user_agent, "")
-        self.assertEqual(record.protocol, "")
+        self.assertEqual(record._msg_str, message)
+        self.assertEqual(record._source_location, expected_location)
+        self.assertEqual(record._source_location_str, json.dumps(expected_location))
+        self.assertIsNone(record._resource)
+        self.assertIsNone(record._trace)
+        self.assertEqual(record._trace_str, "")
+        self.assertIsNone(record._span_id)
+        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, "{}")
 
     def test_minimal_record(self):
         """
@@ -91,16 +104,19 @@ def test_minimal_record(self):
         success = filter_obj.filter(record)
         self.assertTrue(success)
 
-        self.assertEqual(record.line, 0)
-        self.assertEqual(record.msg, "")
-        self.assertEqual(record.function, "")
-        self.assertEqual(record.file, "")
-        self.assertEqual(record.trace, "")
-        self.assertEqual(record.http_request, {})
-        self.assertEqual(record.request_method, "")
-        self.assertEqual(record.request_url, "")
-        self.assertEqual(record.user_agent, "")
-        self.assertEqual(record.protocol, "")
+        self.assertIsNone(record.msg)
+        self.assertEqual(record._msg_str, "")
+        self.assertIsNone(record._source_location)
+        self.assertEqual(record._source_location_str, "{}")
+        self.assertIsNone(record._resource)
+        self.assertIsNone(record._trace)
+        self.assertEqual(record._trace_str, "")
+        self.assertIsNone(record._span_id)
+        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, "{}")
 
     def test_record_with_request(self):
         """
@@ -115,6 +131,8 @@ def test_record_with_request(self):
         expected_path = "http://testserver/123"
         expected_agent = "Mozilla/5.0"
         expected_trace = "123"
+        expected_span = "456"
+        combined_trace = f"{expected_trace}/{expected_span}"
         expected_request = {
             "requestMethod": "PUT",
             "requestUrl": expected_path,
@@ -129,19 +147,18 @@ def test_record_with_request(self):
                 data="body",
                 headers={
                     "User-Agent": expected_agent,
-                    "X_CLOUD_TRACE_CONTEXT": expected_trace,
+                    "X_CLOUD_TRACE_CONTEXT": combined_trace,
                 },
             )
             success = filter_obj.filter(record)
             self.assertTrue(success)
 
-            self.assertEqual(record.trace, expected_trace)
-            for key, val in expected_request.items():
-                self.assertEqual(record.http_request[key], val)
-            self.assertEqual(record.request_method, "PUT")
-            self.assertEqual(record.request_url, expected_path)
-            self.assertEqual(record.user_agent, expected_agent)
-            self.assertEqual(record.protocol, "HTTP/1.1")
+            self.assertEqual(record._trace, expected_trace)
+            self.assertEqual(record._trace_str, expected_trace)
+            self.assertEqual(record._span_id, expected_span)
+            self.assertEqual(record._span_id_str, expected_span)
+            self.assertEqual(record._http_request, expected_request)
+            self.assertEqual(record._http_request_str, json.dumps(expected_request))
 
     def test_user_overrides(self):
         """
@@ -163,8 +180,12 @@ def test_user_overrides(self):
                 headers={"User-Agent": "default", "X_CLOUD_TRACE_CONTEXT": "default"},
             )
             # override values
+            overwritten_resource = "test"
+            record.resource = overwritten_resource
             overwritten_trace = "456"
             record.trace = overwritten_trace
+            overwritten_span = "789"
+            record.span_id = overwritten_span
             overwritten_method = "GET"
             overwritten_url = "www.google.com"
             overwritten_agent = "custom"
@@ -188,15 +209,19 @@ def test_user_overrides(self):
             success = filter_obj.filter(record)
             self.assertTrue(success)
 
-            self.assertEqual(record.trace, overwritten_trace)
-            self.assertEqual(record.http_request, overwritten_request_object)
-            self.assertEqual(record.request_method, overwritten_method)
-            self.assertEqual(record.request_url, overwritten_url)
-            self.assertEqual(record.user_agent, overwritten_agent)
-            self.assertEqual(record.protocol, overwritten_protocol)
-            self.assertEqual(record.line, overwritten_line)
-            self.assertEqual(record.function, overwritten_function)
-            self.assertEqual(record.file, overwritten_file)
+            self.assertEqual(record._trace, overwritten_trace)
+            self.assertEqual(record._trace_str, overwritten_trace)
+            self.assertEqual(record._span_id, overwritten_span)
+            self.assertEqual(record._span_id_str, overwritten_span)
+            self.assertEqual(record._http_request, overwritten_request_object)
+            self.assertEqual(
+                record._http_request_str, json.dumps(overwritten_request_object)
+            )
+            self.assertEqual(record._source_location, overwritten_source_location)
+            self.assertEqual(
+                record._source_location_str, json.dumps(overwritten_source_location)
+            )
+            self.assertEqual(record._resource, overwritten_resource)
 
 
 class TestCloudLoggingHandler(unittest.TestCase):