From 1714f445f6bb303f7b23e67cf760bc21a579916a Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Thu, 15 Apr 2021 14:04:58 -0700 Subject: [PATCH 01/10] improved source location handling --- google/cloud/logging_v2/handlers/handlers.py | 11 ++++++-- .../logging_v2/handlers/structured_log.py | 2 +- tests/environment | 2 +- tests/unit/handlers/test_handlers.py | 28 ++++++++++++++----- 4 files changed, 31 insertions(+), 12 deletions(-) diff --git a/google/cloud/logging_v2/handlers/handlers.py b/google/cloud/logging_v2/handlers/handlers.py index 175cd010..e8c50634 100644 --- a/google/cloud/logging_v2/handlers/handlers.py +++ b/google/cloud/logging_v2/handlers/handlers.py @@ -42,10 +42,15 @@ 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 "" 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: 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 f0e27265..97743137 160000 --- a/tests/environment +++ b/tests/environment @@ -1 +1 @@ -Subproject commit f0e2726579ef96f8e6b3ceaed8145d2bfbfa32bc +Subproject commit 97743137f68e09651a0ec444b69911f10f4e4c75 diff --git a/tests/unit/handlers/test_handlers.py b/tests/unit/handlers/test_handlers.py index 9772d7b0..859029d9 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,14 @@ def test_emit(self): ) logname = "loggername" message = "hello world" + labels = {'test-key': 'test-value'} record = logging.LogRecord(logname, logging, None, None, message, None, None) + record.labels = labels handler.emit(record) self.assertEqual( handler.transport.send_called_with, - (record, message, _GLOBAL_RESOURCE, None, None, None, None), + (record, message, _GLOBAL_RESOURCE, labels, None, None, None), ) def test_emit_manual_field_override(self): From 5edf4e48a7bf7b9e76c0eca4a7b4eddbc905ae25 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Thu, 15 Apr 2021 15:07:11 -0700 Subject: [PATCH 02/10] improved some tests --- tests/system/test_system.py | 2 + tests/unit/handlers/test_structured_log.py | 50 ++++++++++++++++++++++ 2 files changed, 52 insertions(+) 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_structured_log.py b/tests/unit/handlers/test_structured_log.py index 64c63c02..7bef4178 100644 --- a/tests/unit/handlers/test_structured_log.py +++ b/tests/unit/handlers/test_structured_log.py @@ -149,3 +149,53 @@ 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): + """ + Even if the environment provides source_location and http_request values, + the handler should prefer user inputs + """ + 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)) + breakpoint() + for (key, value) in expected_payload.items(): + self.assertEqual(value, result[key]) From d3570322b088b89b40d4f8fe60770640dafe4b72 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Thu, 15 Apr 2021 15:14:49 -0700 Subject: [PATCH 03/10] all handlers send source location --- google/cloud/logging_v2/handlers/handlers.py | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/google/cloud/logging_v2/handlers/handlers.py b/google/cloud/logging_v2/handlers/handlers.py index e8c50634..b6f92c9e 100644 --- a/google/cloud/logging_v2/handlers/handlers.py +++ b/google/cloud/logging_v2/handlers/handlers.py @@ -50,6 +50,12 @@ def filter(self, record): 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 inferred_http, inferred_trace = get_request_data() @@ -146,6 +152,7 @@ def emit(self, record): trace_id = getattr(record, "trace", None) span_id = getattr(record, "span_id", None) http_request = getattr(record, "http_request", None) + source_location = getattr(record "source_location", None) resource = getattr(record, "resource", self.resource) user_labels = getattr(record, "labels", {}) # merge labels @@ -162,6 +169,7 @@ def emit(self, record): trace=trace_id, span_id=span_id, http_request=http_request, + source_location=source_location, ) From 490d45568bf69e9be440e9d4994ac83016098827 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Thu, 15 Apr 2021 15:25:13 -0700 Subject: [PATCH 04/10] fixed missing , --- google/cloud/logging_v2/handlers/handlers.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/google/cloud/logging_v2/handlers/handlers.py b/google/cloud/logging_v2/handlers/handlers.py index b6f92c9e..7acc72a3 100644 --- a/google/cloud/logging_v2/handlers/handlers.py +++ b/google/cloud/logging_v2/handlers/handlers.py @@ -152,7 +152,7 @@ def emit(self, record): trace_id = getattr(record, "trace", None) span_id = getattr(record, "span_id", None) http_request = getattr(record, "http_request", None) - source_location = getattr(record "source_location", None) + source_location = getattr(record, "source_location", None) resource = getattr(record, "resource", self.resource) user_labels = getattr(record, "labels", {}) # merge labels From 9e173fd196234b645c2e8d8c2f71c9736f0646bd Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Thu, 15 Apr 2021 15:43:22 -0700 Subject: [PATCH 05/10] fixed issues with unit tests --- google/cloud/logging_v2/handlers/handlers.py | 2 +- tests/unit/handlers/test_handlers.py | 7 ++++++- tests/unit/handlers/test_structured_log.py | 1 - 3 files changed, 7 insertions(+), 3 deletions(-) diff --git a/google/cloud/logging_v2/handlers/handlers.py b/google/cloud/logging_v2/handlers/handlers.py index 7acc72a3..2a2a376d 100644 --- a/google/cloud/logging_v2/handlers/handlers.py +++ b/google/cloud/logging_v2/handlers/handlers.py @@ -50,7 +50,7 @@ def filter(self, record): 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): + if any([record.line, record.file, record.function]): record.source_location = { "line": record.line, "file": record.file, diff --git a/tests/unit/handlers/test_handlers.py b/tests/unit/handlers/test_handlers.py index 859029d9..ec5b4ac7 100644 --- a/tests/unit/handlers/test_handlers.py +++ b/tests/unit/handlers/test_handlers.py @@ -275,7 +275,7 @@ def test_emit(self): self.assertEqual( handler.transport.send_called_with, - (record, message, _GLOBAL_RESOURCE, labels, None, None, None), + (record, message, _GLOBAL_RESOURCE, labels, None, None, None, None), ) def test_emit_manual_field_override(self): @@ -296,6 +296,8 @@ 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"} @@ -312,6 +314,7 @@ def test_emit_manual_field_override(self): expected_trace, expected_span, expected_http, + expected_source, ), ) @@ -427,6 +430,7 @@ def send( trace=None, span_id=None, http_request=None, + source_location=None, ): self.send_called_with = ( record, @@ -436,4 +440,5 @@ def send( trace, span_id, http_request, + source_location, ) diff --git a/tests/unit/handlers/test_structured_log.py b/tests/unit/handlers/test_structured_log.py index 7bef4178..8ff17c68 100644 --- a/tests/unit/handlers/test_structured_log.py +++ b/tests/unit/handlers/test_structured_log.py @@ -196,6 +196,5 @@ def test_format_overrides(self): ) handler.filter(record) result = json.loads(handler.format(record)) - breakpoint() for (key, value) in expected_payload.items(): self.assertEqual(value, result[key]) From 21279a94c74176e41616c7b2fc8f6ec9eb6b7afe Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Thu, 15 Apr 2021 15:56:47 -0700 Subject: [PATCH 06/10] fixed lint issues --- tests/unit/handlers/test_handlers.py | 6 +++--- tests/unit/handlers/test_structured_log.py | 8 +++----- 2 files changed, 6 insertions(+), 8 deletions(-) diff --git a/tests/unit/handlers/test_handlers.py b/tests/unit/handlers/test_handlers.py index ec5b4ac7..ca1752d8 100644 --- a/tests/unit/handlers/test_handlers.py +++ b/tests/unit/handlers/test_handlers.py @@ -181,7 +181,7 @@ def test_user_overrides(self): overwritten_source_location = { "file": overwritten_file, "line": overwritten_line, - "function": overwritten_function + "function": overwritten_function, } record.http_request = overwritten_request_object record.source_location = overwritten_source_location @@ -268,7 +268,7 @@ def test_emit(self): ) logname = "loggername" message = "hello world" - labels = {'test-key': 'test-value'} + labels = {"test-key": "test-value"} record = logging.LogRecord(logname, logging, None, None, message, None, None) record.labels = labels handler.emit(record) @@ -296,7 +296,7 @@ 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'} + expected_source = {"file": "test-file"} setattr(record, "source_location", expected_source) expected_resource = Resource(type="test", labels={}) setattr(record, "resource", expected_resource) diff --git a/tests/unit/handlers/test_structured_log.py b/tests/unit/handlers/test_structured_log.py index 8ff17c68..b20ddbba 100644 --- a/tests/unit/handlers/test_structured_log.py +++ b/tests/unit/handlers/test_structured_log.py @@ -166,7 +166,7 @@ def test_format_overrides(self): inferred_path = "http://testserver/123" overwrite_trace = "456" inferred_trace = "123" - overwrite_file = 'test-file' + overwrite_file = "test-file" record.http_request = {"requestUrl": overwrite_path} record.source_location = {"file": overwrite_file} record.trace = overwrite_trace @@ -175,7 +175,7 @@ def test_format_overrides(self): "logging.googleapis.com/sourceLocation": { "file": overwrite_file, "function": "", - "line": "0" + "line": "0", }, "httpRequest": { "requestMethod": "", @@ -190,9 +190,7 @@ def test_format_overrides(self): c.put( path=inferred_path, data="body", - headers={ - "X_CLOUD_TRACE_CONTEXT": inferred_trace, - }, + headers={"X_CLOUD_TRACE_CONTEXT": inferred_trace}, ) handler.filter(record) result = json.loads(handler.format(record)) From 556ecd838435245feb3e6b57d72ac16d2cb60b96 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Thu, 15 Apr 2021 16:11:52 -0700 Subject: [PATCH 07/10] updated environment tests --- tests/environment | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/environment b/tests/environment index 97743137..470036ee 160000 --- a/tests/environment +++ b/tests/environment @@ -1 +1 @@ -Subproject commit 97743137f68e09651a0ec444b69911f10f4e4c75 +Subproject commit 470036ee643b9a44fdca113becaefaa8845f6538 From 3dccd1a15a35114aebcef161b90ae57121d89557 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Thu, 15 Apr 2021 16:41:49 -0700 Subject: [PATCH 08/10] add log filter to CloudLoggingHandler --- google/cloud/logging_v2/handlers/handlers.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/google/cloud/logging_v2/handlers/handlers.py b/google/cloud/logging_v2/handlers/handlers.py index 2a2a376d..c5a43b9c 100644 --- a/google/cloud/logging_v2/handlers/handlers.py +++ b/google/cloud/logging_v2/handlers/handlers.py @@ -137,6 +137,8 @@ def __init__( self.project_id = client.project self.resource = resource self.labels = labels + # add extra keys to log record + self.addFilter(CloudLoggingFilter(self.project_id)) def emit(self, record): """Actually log the specified logging record. From 7842536b28306b77d6a426ea295575a333c6d064 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Fri, 16 Apr 2021 11:15:02 -0700 Subject: [PATCH 09/10] updated tests --- tests/environment | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/environment b/tests/environment index 470036ee..cf9ccb49 160000 --- a/tests/environment +++ b/tests/environment @@ -1 +1 @@ -Subproject commit 470036ee643b9a44fdca113becaefaa8845f6538 +Subproject commit cf9ccb495dd39555748c704963df93054d246050 From 5e1f22b3dc5fa003d0836a1d3a84daca6f08b210 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Tue, 20 Apr 2021 11:59:02 -0700 Subject: [PATCH 10/10] added better comment --- tests/unit/handlers/test_structured_log.py | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/tests/unit/handlers/test_structured_log.py b/tests/unit/handlers/test_structured_log.py index b20ddbba..09d6b14f 100644 --- a/tests/unit/handlers/test_structured_log.py +++ b/tests/unit/handlers/test_structured_log.py @@ -152,8 +152,10 @@ def test_format_with_request(self): def test_format_overrides(self): """ - Even if the environment provides source_location and http_request values, - the handler should prefer user inputs + 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