From 6b10b74e2bf65ea406b10585a4c24078348483d2 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Tue, 20 Apr 2021 11:59:43 -0700 Subject: [PATCH] feat: Improve source location overrides (#258) --- google/cloud/logging_v2/handlers/handlers.py | 34 +++++++------ .../logging_v2/handlers/structured_log.py | 2 +- tests/environment | 2 +- tests/system/test_system.py | 2 + tests/unit/handlers/test_handlers.py | 40 ++++++++------- tests/unit/handlers/test_structured_log.py | 49 +++++++++++++++++++ 6 files changed, 94 insertions(+), 35 deletions(-) diff --git a/google/cloud/logging_v2/handlers/handlers.py b/google/cloud/logging_v2/handlers/handlers.py index 99346532..8e99632f 100644 --- a/google/cloud/logging_v2/handlers/handlers.py +++ b/google/cloud/logging_v2/handlers/handlers.py @@ -42,10 +42,21 @@ def __init__(self, project=None): def filter(self, record): # ensure record has all required fields set - record.lineno = 0 if record.lineno is None else record.lineno + 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", "") + 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 - record.funcName = "" if record.funcName is None else record.funcName - record.pathname = "" if record.pathname is None else record.pathname # find http request data inferred_http, inferred_trace = get_request_data() if inferred_trace is not None and self.project is not None: @@ -146,25 +157,16 @@ def emit(self, record): total_labels.update(user_labels) if len(total_labels) == 0: total_labels = None - # create source location object - if record.lineno and record.funcName and record.pathname: - source_location = { - "file": record.pathname, - "line": str(record.lineno), - "function": record.funcName, - } - else: - source_location = None # send off request self.transport.send( record, message, resource=getattr(record, "resource", self.resource), - labels=(total_labels if total_labels else None), - trace=(record.trace if record.trace else None), + labels=total_labels, + trace=getattr(record, "trace", None), span_id=getattr(record, "span_id", None), - http_request=(record.http_request if record.http_request else None), - source_location=source_location, + http_request=getattr(record, "http_request", None), + source_location=getattr(record, "source_location", None), ) diff --git a/google/cloud/logging_v2/handlers/structured_log.py b/google/cloud/logging_v2/handlers/structured_log.py index 56d032d0..4e780170 100644 --- a/google/cloud/logging_v2/handlers/structured_log.py +++ b/google/cloud/logging_v2/handlers/structured_log.py @@ -19,7 +19,7 @@ from google.cloud.logging_v2.handlers.handlers import CloudLoggingFilter -GCP_FORMAT = '{"message": "%(message)s", "severity": "%(levelname)s", "logging.googleapis.com/trace": "%(trace)s", "logging.googleapis.com/sourceLocation": { "file": "%(pathname)s", "line": "%(lineno)d", "function": "%(funcName)s"}, "httpRequest": {"requestMethod": "%(request_method)s", "requestUrl": "%(request_url)s", "userAgent": "%(user_agent)s", "protocol": "%(protocol)s"} }' +GCP_FORMAT = '{"message": "%(message)s", "severity": "%(levelname)s", "logging.googleapis.com/trace": "%(trace)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"} }' class StructuredLogHandler(logging.StreamHandler): diff --git a/tests/environment b/tests/environment index 273db6c6..cf9ccb49 160000 --- a/tests/environment +++ b/tests/environment @@ -1 +1 @@ -Subproject commit 273db6c60b8f39fa5092b01730ff4d2dffcca17e +Subproject commit cf9ccb495dd39555748c704963df93054d246050 diff --git a/tests/system/test_system.py b/tests/system/test_system.py index e6f5aa7c..cc6d0380 100644 --- a/tests/system/test_system.py +++ b/tests/system/test_system.py @@ -333,10 +333,12 @@ def test_handlers_w_extras(self): 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"}, } diff --git a/tests/unit/handlers/test_handlers.py b/tests/unit/handlers/test_handlers.py index c182a5b7..08b74cb4 100644 --- a/tests/unit/handlers/test_handlers.py +++ b/tests/unit/handlers/test_handlers.py @@ -67,10 +67,10 @@ def test_filter_record(self): success = filter_obj.filter(record) self.assertTrue(success) - self.assertEqual(record.lineno, lineno) + self.assertEqual(record.line, lineno) self.assertEqual(record.msg, message) - self.assertEqual(record.funcName, func) - self.assertEqual(record.pathname, pathname) + self.assertEqual(record.function, func) + self.assertEqual(record.file, pathname) self.assertEqual(record.trace, "") self.assertEqual(record.http_request, {}) self.assertEqual(record.request_method, "") @@ -91,10 +91,10 @@ def test_minimal_record(self): success = filter_obj.filter(record) self.assertTrue(success) - self.assertEqual(record.lineno, 0) + self.assertEqual(record.line, 0) self.assertEqual(record.msg, "") - self.assertEqual(record.funcName, "") - self.assertEqual(record.pathname, "") + self.assertEqual(record.function, "") + self.assertEqual(record.file, "") self.assertEqual(record.trace, "") self.assertEqual(record.http_request, {}) self.assertEqual(record.request_method, "") @@ -175,7 +175,16 @@ def test_user_overrides(self): "userAgent": overwritten_agent, "protocol": overwritten_protocol, } + overwritten_line = 22 + overwritten_function = "test-func" + overwritten_file = "test-file" + overwritten_source_location = { + "file": overwritten_file, + "line": overwritten_line, + "function": overwritten_function, + } record.http_request = overwritten_request_object + record.source_location = overwritten_source_location success = filter_obj.filter(record) self.assertTrue(success) @@ -185,6 +194,9 @@ def test_user_overrides(self): 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) class TestCloudLoggingHandler(unittest.TestCase): @@ -256,12 +268,13 @@ def test_emit(self): ) logname = "loggername" message = "hello world" + labels = {"test-key": "test-value"} record = logging.LogRecord(logname, logging, None, None, message, None, None) - handler.filter(record) + record.labels = labels handler.emit(record) self.assertEqual( handler.transport.send_called_with, - (record, message, _GLOBAL_RESOURCE, None, None, None, None, None), + (record, message, _GLOBAL_RESOURCE, labels, None, None, None, None), ) def test_emit_manual_field_override(self): @@ -282,19 +295,12 @@ def test_emit_manual_field_override(self): setattr(record, "span_id", expected_span) expected_http = {"reuqest_url": "manual"} setattr(record, "http_request", expected_http) + expected_source = {"file": "test-file"} + setattr(record, "source_location", expected_source) expected_resource = Resource(type="test", labels={}) setattr(record, "resource", expected_resource) expected_labels = {"test-label": "manual"} setattr(record, "labels", expected_labels) - expected_source = { - "file": "test-file", - "line": str(1), - "function": "test-func", - } - setattr(record, "lineno", int(expected_source["line"])) - setattr(record, "funcName", expected_source["function"]) - setattr(record, "pathname", expected_source["file"]) - handler.filter(record) handler.emit(record) self.assertEqual( diff --git a/tests/unit/handlers/test_structured_log.py b/tests/unit/handlers/test_structured_log.py index 64c63c02..09d6b14f 100644 --- a/tests/unit/handlers/test_structured_log.py +++ b/tests/unit/handlers/test_structured_log.py @@ -149,3 +149,52 @@ def test_format_with_request(self): result = json.loads(handler.format(record)) for (key, value) in expected_payload.items(): self.assertEqual(value, result[key]) + + def test_format_overrides(self): + """ + Allow users to override log fields using `logging.info("", extra={})` + + If supported fields were overriden by the user, those choices should + take precedence. + """ + import logging + import json + + handler = self._make_one() + logname = "loggername" + message = "hello world，嗨 世界" + record = logging.LogRecord(logname, logging.INFO, "", 0, message, None, None) + overwrite_path = "http://overwrite" + inferred_path = "http://testserver/123" + overwrite_trace = "456" + inferred_trace = "123" + overwrite_file = "test-file" + record.http_request = {"requestUrl": overwrite_path} + record.source_location = {"file": overwrite_file} + record.trace = overwrite_trace + expected_payload = { + "logging.googleapis.com/trace": overwrite_trace, + "logging.googleapis.com/sourceLocation": { + "file": overwrite_file, + "function": "", + "line": "0", + }, + "httpRequest": { + "requestMethod": "", + "requestUrl": overwrite_path, + "userAgent": "", + "protocol": "", + }, + } + + app = self.create_app() + with app.test_client() as c: + c.put( + path=inferred_path, + data="body", + headers={"X_CLOUD_TRACE_CONTEXT": inferred_trace}, + ) + handler.filter(record) + result = json.loads(handler.format(record)) + for (key, value) in expected_payload.items(): + self.assertEqual(value, result[key])