From 9fe2d8a9067abbd21bc92a7cbf9c86311cfd3553 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Mon, 22 Nov 2021 14:01:02 -0800 Subject: [PATCH 01/23] added trace_sampled detection --- google/cloud/logging_v2/handlers/_helpers.py | 53 +++++++++---------- .../cloud/logging_v2/handlers/app_engine.py | 4 +- google/cloud/logging_v2/handlers/handlers.py | 3 +- 3 files changed, 29 insertions(+), 31 deletions(-) diff --git a/google/cloud/logging_v2/handlers/_helpers.py b/google/cloud/logging_v2/handlers/_helpers.py index f5dfb7c55..583df44bb 100644 --- a/google/cloud/logging_v2/handlers/_helpers.py +++ b/google/cloud/logging_v2/handlers/_helpers.py @@ -63,9 +63,8 @@ def get_request_data_from_flask(): Returns: Tuple[Optional[dict], Optional[str], Optional[str]]: - Data related to the current http request, trace_id, and span_id for - the request. All fields will be None if a django request isn't - found. + Data related to the current http request, trace_id, span_id and trace_sampled + for the request. All fields will be None if a django request isn't found. """ if flask is None or not flask.request: return None, None, None @@ -80,19 +79,18 @@ def get_request_data_from_flask(): # find trace id and span id header = flask.request.headers.get(_FLASK_TRACE_HEADER) - trace_id, span_id = _parse_trace_span(header) + trace_id, span_id, trace_sampled = _parse_trace_span(header) - return http_request, trace_id, span_id + return http_request, trace_id, span_id, trace_sampled def get_request_data_from_django(): """Get http_request and trace data from django request headers. Returns: - Tuple[Optional[dict], Optional[str], Optional[str]]: - Data related to the current http request, trace_id, and span_id for - the request. All fields will be None if a django request isn't - found. + Tuple[Optional[dict], Optional[str], Optional[str], Optional[bool]]: + Data related to the current http request, trace_id, span_id, and trace_sampled + for the request. All fields will be None if a django request isn't found. """ request = _get_django_request() @@ -109,9 +107,9 @@ def get_request_data_from_django(): # find trace id and span id header = request.META.get(_DJANGO_TRACE_HEADER) - trace_id, span_id = _parse_trace_span(header) + trace_id, span_id, trace_sampled = _parse_trace_span(header) - return http_request, trace_id, span_id + return http_request, trace_id, span_id, trace_sampled def _parse_trace_span(header): @@ -120,22 +118,22 @@ def _parse_trace_span(header): Args: header (str): the string extracted from the X_CLOUD_TRACE header Returns: - Tuple[Optional[dict], Optional[str]]: - The trace_id and span_id extracted from the header + Tuple[Optional[dict], Optional[str], Optional[bool]]: + The trace_id, span_id and trace_sampled extracted from the header Each field will be None if not found. """ - trace_id = None - span_id = None + trace_id = span_id = trace_sampled = None + # see https://cloud.google.com/trace/docs/setup for X-Cloud-Trace_Context format if header: try: - split_header = header.split("/", 1) - trace_id = split_header[0] - header_suffix = split_header[1] - # the span is the set of alphanumeric characters after the / - span_id = re.findall(r"^\w+", header_suffix)[0] + regex = '([a-f\d]+)?(\/?([a-f\d]+))?(;?o=(\d))?' + match = re.match(regex, header) + trace_id = match.group(1) + span_id = match.group(3) + trace_sampled = match.group(5) == '1' except IndexError: pass - return trace_id, span_id + return trace_id, span_id, trace_sampled def get_request_data(): @@ -143,10 +141,9 @@ def get_request_data(): frameworks (currently supported: Flask and Django). Returns: - Tuple[Optional[dict], Optional[str], Optional[str]]: - Data related to the current http request, trace_id, and span_id for - the request. All fields will be None if a django request isn't - found. + Tuple[Optional[dict], Optional[str], Optional[str], Optional[bool]]: + Data related to the current http request, trace_id, span_id, and trace_sampled + for the request. All fields will be None if a django request isn't found. """ checkers = ( get_request_data_from_django, @@ -154,8 +151,8 @@ def get_request_data(): ) for checker in checkers: - http_request, trace_id, span_id = checker() + http_request, trace_id, span_id, trace_sampled = checker() if http_request is not None: - return http_request, trace_id, span_id + return http_request, trace_id, span_id, trace_sampled - return None, None, None + return None, None, None, None diff --git a/google/cloud/logging_v2/handlers/app_engine.py b/google/cloud/logging_v2/handlers/app_engine.py index abd16664f..a65d16a0e 100644 --- a/google/cloud/logging_v2/handlers/app_engine.py +++ b/google/cloud/logging_v2/handlers/app_engine.py @@ -98,7 +98,7 @@ def get_gae_labels(self): """ gae_labels = {} - _, trace_id, _ = get_request_data() + _, trace_id, _, _ = get_request_data() if trace_id is not None: gae_labels[_TRACE_ID_LABEL] = trace_id @@ -115,7 +115,7 @@ def emit(self, record): record (logging.LogRecord): The record to be logged. """ message = super(AppEngineHandler, self).format(record) - inferred_http, inferred_trace, _ = get_request_data() + inferred_http, inferred_trace, _, _ = get_request_data() if inferred_trace is not None: inferred_trace = f"projects/{self.project_id}/traces/{inferred_trace}" # allow user overrides diff --git a/google/cloud/logging_v2/handlers/handlers.py b/google/cloud/logging_v2/handlers/handlers.py index 8d14852e1..dba9c2893 100644 --- a/google/cloud/logging_v2/handlers/handlers.py +++ b/google/cloud/logging_v2/handlers/handlers.py @@ -82,7 +82,7 @@ def filter(self, record): """ user_labels = getattr(record, "labels", {}) # infer request data from the environment - inferred_http, inferred_trace, inferred_span = get_request_data() + inferred_http, inferred_trace, inferred_span, inferred_sampled = get_request_data() if inferred_trace is not None and self.project is not None: # add full path for detected trace inferred_trace = f"projects/{self.project}/traces/{inferred_trace}" @@ -90,6 +90,7 @@ def filter(self, record): 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._trace_sampled = getattr(record, "trace_sampled", inferred_sampled) or None record._http_request = getattr(record, "http_request", inferred_http) record._source_location = CloudLoggingFilter._infer_source_location(record) # add logger name as a label if possible From 3f464b5ea3664193dac904c51a75ee377f42f7e5 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Mon, 22 Nov 2021 14:16:27 -0800 Subject: [PATCH 02/23] implemented traceparent detection --- google/cloud/logging_v2/handlers/_helpers.py | 41 +++++++++++++++++--- 1 file changed, 35 insertions(+), 6 deletions(-) diff --git a/google/cloud/logging_v2/handlers/_helpers.py b/google/cloud/logging_v2/handlers/_helpers.py index 583df44bb..ffa443b85 100644 --- a/google/cloud/logging_v2/handlers/_helpers.py +++ b/google/cloud/logging_v2/handlers/_helpers.py @@ -78,8 +78,8 @@ def get_request_data_from_flask(): } # find trace id and span id - header = flask.request.headers.get(_FLASK_TRACE_HEADER) - trace_id, span_id, trace_sampled = _parse_trace_span(header) + x_cloud_header = flask.request.headers.get(_FLASK_TRACE_HEADER) + trace_id, span_id, trace_sampled = _parse_xcloud_trace(x_cloud_header) return http_request, trace_id, span_id, trace_sampled @@ -106,13 +106,42 @@ def get_request_data_from_django(): } # find trace id and span id - header = request.META.get(_DJANGO_TRACE_HEADER) - trace_id, span_id, trace_sampled = _parse_trace_span(header) + x_cloud_header = request.META.get(_DJANGO_TRACE_HEADER) + trace_id, span_id, trace_sampled = _parse_xcloud_trace(x_cloud_header) return http_request, trace_id, span_id, trace_sampled -def _parse_trace_span(header): +def _parse_trace_parent(header): + """Given a w3 traceparent header, extract the trace and span ids. + For more information see https://www.w3.org/TR/trace-context/ + + Args: + header (str): the string extracted from the traceparent header + Returns: + Tuple[Optional[dict], Optional[str], Optional[bool]]: + The trace_id, span_id and trace_sampled extracted from the header + Each field will be None if not found. + """ + trace_id = span_id = trace_sampled = None + # see https://cloud.google.com/trace/docs/setup for X-Cloud-Trace_Context format + if header: + try: + VERSION_PART = r'(?!ff)[\\da-f]{2}'; + TRACE_ID_PART = r'(?![0]{32})[\\da-f]{32}'; + PARENT_ID_PART = r'(?![0]{16})[\\da-f]{16}'; + FLAGS_PART = r'[\\da-f]{2}'; + regex = f'^\\s?({VERSION_PART})-({TRACE_ID_PART})-({PARENT_ID_PART})-({FLAGS_PART})(-.*)?\\s?$' + match = re.match(regex, header) + trace_id = match.group(2) + span_id = match.group(3) + trace_sampled = (int(match.group(5), 16) == 1) + except IndexError: + pass + return trace_id, span_id, trace_sampled + + +def _parse_xcloud_trace(header): """Given an X_CLOUD_TRACE header, extract the trace and span ids. Args: @@ -130,7 +159,7 @@ def _parse_trace_span(header): match = re.match(regex, header) trace_id = match.group(1) span_id = match.group(3) - trace_sampled = match.group(5) == '1' + trace_sampled = (match.group(5) == '1') except IndexError: pass return trace_id, span_id, trace_sampled From c77657ae67b1356ddd8586e47209de95e0d56113 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Mon, 22 Nov 2021 16:36:28 -0800 Subject: [PATCH 03/23] check for both header fields --- google/cloud/logging_v2/handlers/_helpers.py | 24 +++++++++++++++----- 1 file changed, 18 insertions(+), 6 deletions(-) diff --git a/google/cloud/logging_v2/handlers/_helpers.py b/google/cloud/logging_v2/handlers/_helpers.py index ffa443b85..c1d49d7ae 100644 --- a/google/cloud/logging_v2/handlers/_helpers.py +++ b/google/cloud/logging_v2/handlers/_helpers.py @@ -27,11 +27,13 @@ from google.cloud.logging_v2.handlers.middleware.request import _get_django_request _DJANGO_CONTENT_LENGTH = "CONTENT_LENGTH" -_DJANGO_TRACE_HEADER = "HTTP_X_CLOUD_TRACE_CONTEXT" +_DJANGO_XCLOUD_TRACE_HEADER = "HTTP_X_CLOUD_TRACE_CONTEXT" +_DJANGO_TRACEPARENT = "HTTP_TRACEPARENT" _DJANGO_USERAGENT_HEADER = "HTTP_USER_AGENT" _DJANGO_REMOTE_ADDR_HEADER = "REMOTE_ADDR" _DJANGO_REFERER_HEADER = "HTTP_REFERER" -_FLASK_TRACE_HEADER = "X_CLOUD_TRACE_CONTEXT" +_FLASK_XCLOUD_TRACE_HEADER = "X_CLOUD_TRACE_CONTEXT" +_FLASK_TRACEPARENT = "TRACEPARENT" _PROTOCOL_HEADER = "SERVER_PROTOCOL" @@ -78,8 +80,13 @@ def get_request_data_from_flask(): } # find trace id and span id - x_cloud_header = flask.request.headers.get(_FLASK_TRACE_HEADER) - trace_id, span_id, trace_sampled = _parse_xcloud_trace(x_cloud_header) + header = flask.request.headers.get(_FLASK_TRACEPARENT) + if header: + trace_id, span_id, trace_sampled = _parse_trace_parent(header) + else: + # w3 traceparent header not found. Check XCLOUD_TRACE_CONTEXT + header = flask.request.headers.get(_FLASK_XCLOUD_TRACE_HEADER) + trace_id, span_id, trace_sampled = _parse_xcloud_trace(x_cloud_header) return http_request, trace_id, span_id, trace_sampled @@ -106,8 +113,13 @@ def get_request_data_from_django(): } # find trace id and span id - x_cloud_header = request.META.get(_DJANGO_TRACE_HEADER) - trace_id, span_id, trace_sampled = _parse_xcloud_trace(x_cloud_header) + header = flask.request.headers.get(_DJANGO_TRACEPARENT) + if header: + trace_id, span_id, trace_sampled = _parse_trace_parent(header) + else: + # w3 traceparent header not found. Check XCLOUD_TRACE_CONTEXT + header = flask.request.headers.get(_DJANGO_XCLOUD_TRACE_HEADER) + trace_id, span_id, trace_sampled = _parse_xcloud_trace(x_cloud_header) return http_request, trace_id, span_id, trace_sampled From 310ae1383369dab6e94b731edcd5104db5f7e6ae Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Tue, 23 Nov 2021 15:14:21 -0800 Subject: [PATCH 04/23] fixed GKE handler --- google/cloud/logging_v2/client.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/google/cloud/logging_v2/client.py b/google/cloud/logging_v2/client.py index 92ab72a3a..3d5ea24fc 100644 --- a/google/cloud/logging_v2/client.py +++ b/google/cloud/logging_v2/client.py @@ -376,7 +376,7 @@ def get_default_handler(self, **kw): if monitored_resource.type == _GAE_RESOURCE_TYPE: return CloudLoggingHandler(self, resource=monitored_resource, **kw) elif monitored_resource.type == _GKE_RESOURCE_TYPE: - return ContainerEngineHandler(**kw) + return StructuredLogHandler(**kw, project_id=self.project) elif monitored_resource.type == _GCF_RESOURCE_TYPE: # __stdout__ stream required to support structured logging on Python 3.7 kw["stream"] = kw.get("stream", sys.__stdout__) From 98bd28cea4061fed32212349f4be640541a80316 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Tue, 23 Nov 2021 15:14:30 -0800 Subject: [PATCH 05/23] always return 4-tuple --- google/cloud/logging_v2/handlers/_helpers.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/google/cloud/logging_v2/handlers/_helpers.py b/google/cloud/logging_v2/handlers/_helpers.py index c1d49d7ae..7cff43d7f 100644 --- a/google/cloud/logging_v2/handlers/_helpers.py +++ b/google/cloud/logging_v2/handlers/_helpers.py @@ -69,7 +69,7 @@ def get_request_data_from_flask(): for the request. All fields will be None if a django request isn't found. """ if flask is None or not flask.request: - return None, None, None + return None, None, None, None # build http_request http_request = { @@ -86,7 +86,7 @@ def get_request_data_from_flask(): else: # w3 traceparent header not found. Check XCLOUD_TRACE_CONTEXT header = flask.request.headers.get(_FLASK_XCLOUD_TRACE_HEADER) - trace_id, span_id, trace_sampled = _parse_xcloud_trace(x_cloud_header) + trace_id, span_id, trace_sampled = _parse_xcloud_trace(header) return http_request, trace_id, span_id, trace_sampled @@ -102,7 +102,7 @@ def get_request_data_from_django(): request = _get_django_request() if request is None: - return None, None, None + return None, None, None, None # build http_request http_request = { @@ -119,7 +119,7 @@ def get_request_data_from_django(): else: # w3 traceparent header not found. Check XCLOUD_TRACE_CONTEXT header = flask.request.headers.get(_DJANGO_XCLOUD_TRACE_HEADER) - trace_id, span_id, trace_sampled = _parse_xcloud_trace(x_cloud_header) + trace_id, span_id, trace_sampled = _parse_xcloud_trace(header) return http_request, trace_id, span_id, trace_sampled From 93d0e61ebe45708c8bd9ad44ffc6ba662d7d2aed Mon Sep 17 00:00:00 2001 From: Owl Bot Date: Tue, 23 Nov 2021 23:17:03 +0000 Subject: [PATCH 06/23] =?UTF-8?q?=F0=9F=A6=89=20Updates=20from=20OwlBot?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit See https://github.com/googleapis/repo-automation-bots/blob/main/packages/owl-bot/README.md --- google/cloud/logging_v2/handlers/_helpers.py | 20 ++++++++++---------- google/cloud/logging_v2/handlers/handlers.py | 11 +++++++++-- 2 files changed, 19 insertions(+), 12 deletions(-) diff --git a/google/cloud/logging_v2/handlers/_helpers.py b/google/cloud/logging_v2/handlers/_helpers.py index 7cff43d7f..4dd44bfc8 100644 --- a/google/cloud/logging_v2/handlers/_helpers.py +++ b/google/cloud/logging_v2/handlers/_helpers.py @@ -80,7 +80,7 @@ def get_request_data_from_flask(): } # find trace id and span id - header = flask.request.headers.get(_FLASK_TRACEPARENT) + header = flask.request.headers.get(_FLASK_TRACEPARENT) if header: trace_id, span_id, trace_sampled = _parse_trace_parent(header) else: @@ -113,7 +113,7 @@ def get_request_data_from_django(): } # find trace id and span id - header = flask.request.headers.get(_DJANGO_TRACEPARENT) + header = flask.request.headers.get(_DJANGO_TRACEPARENT) if header: trace_id, span_id, trace_sampled = _parse_trace_parent(header) else: @@ -139,15 +139,15 @@ def _parse_trace_parent(header): # see https://cloud.google.com/trace/docs/setup for X-Cloud-Trace_Context format if header: try: - VERSION_PART = r'(?!ff)[\\da-f]{2}'; - TRACE_ID_PART = r'(?![0]{32})[\\da-f]{32}'; - PARENT_ID_PART = r'(?![0]{16})[\\da-f]{16}'; - FLAGS_PART = r'[\\da-f]{2}'; - regex = f'^\\s?({VERSION_PART})-({TRACE_ID_PART})-({PARENT_ID_PART})-({FLAGS_PART})(-.*)?\\s?$' + VERSION_PART = r"(?!ff)[\\da-f]{2}" + TRACE_ID_PART = r"(?![0]{32})[\\da-f]{32}" + PARENT_ID_PART = r"(?![0]{16})[\\da-f]{16}" + FLAGS_PART = r"[\\da-f]{2}" + regex = f"^\\s?({VERSION_PART})-({TRACE_ID_PART})-({PARENT_ID_PART})-({FLAGS_PART})(-.*)?\\s?$" match = re.match(regex, header) trace_id = match.group(2) span_id = match.group(3) - trace_sampled = (int(match.group(5), 16) == 1) + trace_sampled = int(match.group(5), 16) == 1 except IndexError: pass return trace_id, span_id, trace_sampled @@ -167,11 +167,11 @@ def _parse_xcloud_trace(header): # see https://cloud.google.com/trace/docs/setup for X-Cloud-Trace_Context format if header: try: - regex = '([a-f\d]+)?(\/?([a-f\d]+))?(;?o=(\d))?' + regex = "([a-f\d]+)?(\/?([a-f\d]+))?(;?o=(\d))?" match = re.match(regex, header) trace_id = match.group(1) span_id = match.group(3) - trace_sampled = (match.group(5) == '1') + trace_sampled = match.group(5) == "1" except IndexError: pass return trace_id, span_id, trace_sampled diff --git a/google/cloud/logging_v2/handlers/handlers.py b/google/cloud/logging_v2/handlers/handlers.py index dba9c2893..d4356111b 100644 --- a/google/cloud/logging_v2/handlers/handlers.py +++ b/google/cloud/logging_v2/handlers/handlers.py @@ -82,7 +82,12 @@ def filter(self, record): """ user_labels = getattr(record, "labels", {}) # infer request data from the environment - inferred_http, inferred_trace, inferred_span, inferred_sampled = get_request_data() + ( + inferred_http, + inferred_trace, + inferred_span, + inferred_sampled, + ) = get_request_data() if inferred_trace is not None and self.project is not None: # add full path for detected trace inferred_trace = f"projects/{self.project}/traces/{inferred_trace}" @@ -90,7 +95,9 @@ def filter(self, record): 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._trace_sampled = getattr(record, "trace_sampled", inferred_sampled) or None + record._trace_sampled = ( + getattr(record, "trace_sampled", inferred_sampled) or None + ) record._http_request = getattr(record, "http_request", inferred_http) record._source_location = CloudLoggingFilter._infer_source_location(record) # add logger name as a label if possible From e8785cb911c806d295d616cb565949fedf9f7258 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Wed, 1 Dec 2021 15:26:04 -0800 Subject: [PATCH 07/23] fixed unit tests --- google/cloud/logging_v2/handlers/_helpers.py | 12 +- tests/unit/handlers/test__helpers.py | 112 ++++++++++--------- tests/unit/handlers/test_app_engine.py | 6 +- 3 files changed, 72 insertions(+), 58 deletions(-) diff --git a/google/cloud/logging_v2/handlers/_helpers.py b/google/cloud/logging_v2/handlers/_helpers.py index 7cff43d7f..b07c30527 100644 --- a/google/cloud/logging_v2/handlers/_helpers.py +++ b/google/cloud/logging_v2/handlers/_helpers.py @@ -113,12 +113,12 @@ def get_request_data_from_django(): } # find trace id and span id - header = flask.request.headers.get(_DJANGO_TRACEPARENT) + header = request.META.get(_DJANGO_TRACEPARENT) if header: trace_id, span_id, trace_sampled = _parse_trace_parent(header) else: # w3 traceparent header not found. Check XCLOUD_TRACE_CONTEXT - header = flask.request.headers.get(_DJANGO_XCLOUD_TRACE_HEADER) + header = request.META.get(_DJANGO_XCLOUD_TRACE_HEADER) trace_id, span_id, trace_sampled = _parse_xcloud_trace(header) return http_request, trace_id, span_id, trace_sampled @@ -135,7 +135,8 @@ def _parse_trace_parent(header): The trace_id, span_id and trace_sampled extracted from the header Each field will be None if not found. """ - trace_id = span_id = trace_sampled = None + trace_id = span_id = None + trace_sampled = False # see https://cloud.google.com/trace/docs/setup for X-Cloud-Trace_Context format if header: try: @@ -163,11 +164,12 @@ def _parse_xcloud_trace(header): The trace_id, span_id and trace_sampled extracted from the header Each field will be None if not found. """ - trace_id = span_id = trace_sampled = None + trace_id = span_id = None + trace_sampled = False # see https://cloud.google.com/trace/docs/setup for X-Cloud-Trace_Context format if header: try: - regex = '([a-f\d]+)?(\/?([a-f\d]+))?(;?o=(\d))?' + regex = '([\w]+)?(\/?([\w]+))?(;?o=(\d))?' match = re.match(regex, header) trace_id = match.group(1) span_id = match.group(3) diff --git a/tests/unit/handlers/test__helpers.py b/tests/unit/handlers/test__helpers.py index d26e700e8..105e27012 100644 --- a/tests/unit/handlers/test__helpers.py +++ b/tests/unit/handlers/test__helpers.py @@ -16,10 +16,10 @@ import mock -_FLASK_TRACE_ID = "flask-id" +_FLASK_TRACE_ID = "flask0id" _FLASK_SPAN_ID = "span0flask" _FLASK_HTTP_REQUEST = {"requestUrl": "https://flask.palletsprojects.com/en/1.1.x/"} -_DJANGO_TRACE_ID = "django-id" +_DJANGO_TRACE_ID = "django0id" _DJANGO_SPAN_ID = "span0django" _DJANGO_HTTP_REQUEST = {"requestUrl": "https://www.djangoproject.com/"} @@ -29,7 +29,8 @@ class Test_get_request_data_from_flask(unittest.TestCase): def _call_fut(): from google.cloud.logging_v2.handlers import _helpers - return _helpers.get_request_data_from_flask() + http, trace, span, sampled = _helpers.get_request_data_from_flask() + return http, trace, span, sampled @staticmethod def create_app(): @@ -46,10 +47,11 @@ def index(): def test_no_context_header(self): app = self.create_app() with app.test_request_context(path="/", headers={}): - http_request, trace_id, span_id = self._call_fut() + http_request, trace_id, span_id, sampled = self._call_fut() self.assertIsNone(trace_id) self.assertIsNone(span_id) + self.assertEqual(sampled, False) self.assertEqual(http_request["requestMethod"], "GET") def test_valid_context_header(self): @@ -64,10 +66,11 @@ def test_valid_context_header(self): ) with context: - http_request, trace_id, span_id = self._call_fut() + http_request, trace_id, span_id, sampled = self._call_fut() self.assertEqual(trace_id, expected_trace_id) self.assertEqual(span_id, expected_span_id) + self.assertEqual(sampled, False) self.assertEqual(http_request["requestMethod"], "GET") def test_http_request_populated(self): @@ -106,7 +109,8 @@ class Test_get_request_data_from_django(unittest.TestCase): def _call_fut(): from google.cloud.logging_v2.handlers import _helpers - return _helpers.get_request_data_from_django() + http, trace, span, sampled = _helpers.get_request_data_from_django() + return http, trace, span, sampled def setUp(self): from django.conf import settings @@ -131,11 +135,12 @@ def test_no_context_header(self): middleware = request.RequestMiddleware(None) middleware.process_request(django_request) - http_request, trace_id, span_id = self._call_fut() + http_request, trace_id, span_id, sampled = self._call_fut() self.assertEqual(http_request["requestMethod"], "GET") self.assertIsNone(trace_id) self.assertIsNone(span_id) + self.assertEqual(sampled, False) def test_valid_context_header(self): from django.test import RequestFactory @@ -152,10 +157,11 @@ def test_valid_context_header(self): middleware = request.RequestMiddleware(None) middleware.process_request(django_request) - http_request, trace_id, span_id = self._call_fut() + http_request, trace_id, span_id, sampled = self._call_fut() self.assertEqual(trace_id, expected_trace_id) self.assertEqual(span_id, expected_span_id) + self.assertEqual(sampled, False) self.assertEqual(http_request["requestMethod"], "GET") def test_http_request_populated(self): @@ -203,7 +209,8 @@ class Test_get_request_data(unittest.TestCase): def _call_fut(): from google.cloud.logging_v2.handlers import _helpers - return _helpers.get_request_data() + http, trace, span, sampled = _helpers.get_request_data() + return http, trace, span, sampled def _helper(self, django_return, flask_return): django_patch = mock.patch( @@ -222,8 +229,8 @@ def _helper(self, django_return, flask_return): return django_mock, flask_mock, result def test_from_django(self): - django_expected = (_DJANGO_HTTP_REQUEST, _DJANGO_TRACE_ID, _DJANGO_SPAN_ID) - flask_expected = (None, None, None) + django_expected = (_DJANGO_HTTP_REQUEST, _DJANGO_TRACE_ID, _DJANGO_SPAN_ID, False) + flask_expected = (None, None, None, None) django_mock, flask_mock, output = self._helper(django_expected, flask_expected) self.assertEqual(output, django_expected) @@ -231,8 +238,8 @@ def test_from_django(self): flask_mock.assert_not_called() def test_from_flask(self): - django_expected = (None, None, None) - flask_expected = (_FLASK_HTTP_REQUEST, _FLASK_TRACE_ID, _FLASK_SPAN_ID) + django_expected = (None, None, None, None) + flask_expected = (_FLASK_HTTP_REQUEST, _FLASK_TRACE_ID, _FLASK_SPAN_ID, False) django_mock, flask_mock, output = self._helper(django_expected, flask_expected) self.assertEqual(output, flask_expected) @@ -241,8 +248,8 @@ def test_from_flask(self): flask_mock.assert_called_once_with() def test_from_django_and_flask(self): - django_expected = (_DJANGO_HTTP_REQUEST, _DJANGO_TRACE_ID, _DJANGO_SPAN_ID) - flask_expected = (_FLASK_HTTP_REQUEST, _FLASK_TRACE_ID, _FLASK_SPAN_ID) + django_expected = (_DJANGO_HTTP_REQUEST, _DJANGO_TRACE_ID, _DJANGO_SPAN_ID, False) + flask_expected = (_FLASK_HTTP_REQUEST, _FLASK_TRACE_ID, _FLASK_SPAN_ID, False) django_mock, flask_mock, output = self._helper(django_expected, flask_expected) @@ -253,19 +260,19 @@ def test_from_django_and_flask(self): flask_mock.assert_not_called() def test_missing_http_request(self): - flask_expected = (None, _FLASK_TRACE_ID, _FLASK_SPAN_ID) - django_expected = (None, _DJANGO_TRACE_ID, _DJANGO_TRACE_ID) + flask_expected = (None, _FLASK_TRACE_ID, _FLASK_SPAN_ID, True) + django_expected = (None, _DJANGO_TRACE_ID, _DJANGO_TRACE_ID, True) django_mock, flask_mock, output = self._helper(django_expected, flask_expected) # function only returns trace if http_request data is present - self.assertEqual(output, (None, None, None)) + self.assertEqual(output, (None, None, None, None)) django_mock.assert_called_once_with() flask_mock.assert_called_once_with() def test_missing_trace_id(self): - flask_expected = (_FLASK_HTTP_REQUEST, None, None) - django_expected = (None, _DJANGO_TRACE_ID, _DJANGO_SPAN_ID) + flask_expected = (_FLASK_HTTP_REQUEST, None, None, None) + django_expected = (None, _DJANGO_TRACE_ID, _DJANGO_SPAN_ID, True) django_mock, flask_mock, output = self._helper(django_expected, flask_expected) # trace_id is optional @@ -275,77 +282,82 @@ def test_missing_trace_id(self): flask_mock.assert_called_once_with() def test_missing_both(self): - flask_expected = (None, None, None) - django_expected = (None, None, None) + flask_expected = (None, None, None, None) + django_expected = (None, None, None, None) django_mock, flask_mock, output = self._helper(django_expected, flask_expected) - self.assertEqual(output, (None, None, None)) + self.assertEqual(output, (None, None, None, None)) django_mock.assert_called_once_with() flask_mock.assert_called_once_with() def test_wo_libraries(self): output = self._call_fut() - self.assertEqual(output, (None, None, None)) + self.assertEqual(output, (None, None, None, None)) -class Test__parse_trace_span(unittest.TestCase): +class Test__parse_xcloud_trace(unittest.TestCase): @staticmethod def _call_fut(header): from google.cloud.logging_v2.handlers import _helpers - return _helpers._parse_trace_span(header) + trace, span, sampled = _helpers._parse_xcloud_trace(header) + return trace, span, sampled def test_empty_header(self): header = "" - trace_id, span_id = self._call_fut(header) - self.assertEqual(trace_id, None) - self.assertEqual(span_id, None) + trace_id, span_id, sampled = self._call_fut(header) + self.assertIsNone(trace_id) + self.assertIsNone(span_id) + self.assertEqual(sampled, False) def test_no_span(self): header = "12345" - trace_id, span_id = self._call_fut(header) + trace_id, span_id, sampled = self._call_fut(header) self.assertEqual(trace_id, header) - self.assertEqual(span_id, None) + self.assertIsNone(span_id) + self.assertEqual(sampled, False) def test_no_trace(self): header = "/12345" - trace_id, span_id = self._call_fut(header) - self.assertEqual(trace_id, "") + trace_id, span_id, sampled = self._call_fut(header) + self.assertIsNone(trace_id) self.assertEqual(span_id, "12345") + self.assertEqual(sampled, False) def test_with_span(self): expected_trace = "12345" expected_span = "67890" header = f"{expected_trace}/{expected_span}" - trace_id, span_id = self._call_fut(header) + trace_id, span_id, sampled = self._call_fut(header) self.assertEqual(trace_id, expected_trace) self.assertEqual(span_id, expected_span) + self.assertEqual(sampled, False) def test_with_extra_characters(self): expected_trace = "12345" expected_span = "67890" - header = f"{expected_trace}/{expected_span};o=0" - trace_id, span_id = self._call_fut(header) + header = f"{expected_trace}/{expected_span};abc" + trace_id, span_id, sampled = self._call_fut(header) self.assertEqual(trace_id, expected_trace) self.assertEqual(span_id, expected_span) + self.assertEqual(sampled, False) - def test_with_unicode_span(self): - """ - Spans are expected to be alphanumeric - """ + def test_with_explicit_no_sampled(self): expected_trace = "12345" - header = f"{expected_trace}/😀123" - trace_id, span_id = self._call_fut(header) + expected_span = "67890" + header = f"{expected_trace}/{expected_span};o=0" + trace_id, span_id, sampled = self._call_fut(header) self.assertEqual(trace_id, expected_trace) - self.assertEqual(span_id, None) + self.assertEqual(span_id, expected_span) + self.assertEqual(sampled, False) - def test_with_unicode_trace(self): - """ - Spans are expected to be alphanumeric - """ - expected_trace = "12😀345" + def test_with__sampled(self): + expected_trace = "12345" expected_span = "67890" - header = f"{expected_trace}/{expected_span}" - trace_id, span_id = self._call_fut(header) + header = f"{expected_trace}/{expected_span};o=1" + trace_id, span_id, sampled = self._call_fut(header) self.assertEqual(trace_id, expected_trace) self.assertEqual(span_id, expected_span) + self.assertEqual(sampled, True) + + diff --git a/tests/unit/handlers/test_app_engine.py b/tests/unit/handlers/test_app_engine.py index c726c8496..8eedfad9b 100644 --- a/tests/unit/handlers/test_app_engine.py +++ b/tests/unit/handlers/test_app_engine.py @@ -97,7 +97,7 @@ def test_emit(self): expected_trace_id = f"projects/{self.PROJECT}/traces/{trace_id}" get_request_patch = mock.patch( "google.cloud.logging_v2.handlers.app_engine.get_request_data", - return_value=(expected_http_request, trace_id, None), + return_value=(expected_http_request, trace_id, None, None), ) with get_request_patch: # library integrations mocked to return test data @@ -135,7 +135,7 @@ def test_emit_manual_field_override(self): inferred_trace_id = "trace-test" get_request_patch = mock.patch( "google.cloud.logging_v2.handlers.app_engine.get_request_data", - return_value=(inferred_http_request, inferred_trace_id, None), + return_value=(inferred_http_request, inferred_trace_id, None, None), ) with get_request_patch: # library integrations mocked to return test data @@ -180,7 +180,7 @@ def test_emit_manual_field_override(self): def _get_gae_labels_helper(self, trace_id): get_request_patch = mock.patch( "google.cloud.logging_v2.handlers.app_engine.get_request_data", - return_value=(None, trace_id, None), + return_value=(None, trace_id, None, None), ) client = mock.Mock(project=self.PROJECT, spec=["project"]) From 3fd0899abcaabf7c3faa02cd1dba1b2c06a0b8e5 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Wed, 1 Dec 2021 16:17:19 -0800 Subject: [PATCH 08/23] added tests for w3c traceparent --- google/cloud/logging_v2/handlers/_helpers.py | 31 +++++++----- tests/unit/handlers/test__helpers.py | 53 ++++++++++++++++++++ 2 files changed, 71 insertions(+), 13 deletions(-) diff --git a/google/cloud/logging_v2/handlers/_helpers.py b/google/cloud/logging_v2/handlers/_helpers.py index b07c30527..c5b377e5e 100644 --- a/google/cloud/logging_v2/handlers/_helpers.py +++ b/google/cloud/logging_v2/handlers/_helpers.py @@ -64,7 +64,7 @@ def get_request_data_from_flask(): """Get http_request and trace data from flask request headers. Returns: - Tuple[Optional[dict], Optional[str], Optional[str]]: + Tuple[Optional[dict], Optional[str], Optional[str], bool]: Data related to the current http request, trace_id, span_id and trace_sampled for the request. All fields will be None if a django request isn't found. """ @@ -95,7 +95,7 @@ def get_request_data_from_django(): """Get http_request and trace data from django request headers. Returns: - Tuple[Optional[dict], Optional[str], Optional[str], Optional[bool]]: + Tuple[Optional[dict], Optional[str], Optional[str], bool]: Data related to the current http request, trace_id, span_id, and trace_sampled for the request. All fields will be None if a django request isn't found. """ @@ -130,26 +130,31 @@ def _parse_trace_parent(header): Args: header (str): the string extracted from the traceparent header + example: 00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01 Returns: - Tuple[Optional[dict], Optional[str], Optional[bool]]: + Tuple[Optional[dict], Optional[str], bool]: The trace_id, span_id and trace_sampled extracted from the header - Each field will be None if not found. + Each field will be None if header can't be parsed in expected format. """ trace_id = span_id = None trace_sampled = False - # see https://cloud.google.com/trace/docs/setup for X-Cloud-Trace_Context format + # see https://www.w3.org/TR/trace-context/ for W3C traceparent format if header: try: - VERSION_PART = r'(?!ff)[\\da-f]{2}'; - TRACE_ID_PART = r'(?![0]{32})[\\da-f]{32}'; - PARENT_ID_PART = r'(?![0]{16})[\\da-f]{16}'; - FLAGS_PART = r'[\\da-f]{2}'; + VERSION_PART = r'(?!ff)[a-f\d]{2}' + TRACE_ID_PART = r'(?![0]{32})[a-f\d]{32}' + PARENT_ID_PART = r'(?![0]{16})[a-f\d]{16}' + FLAGS_PART = r'[a-f\d]{2}' regex = f'^\\s?({VERSION_PART})-({TRACE_ID_PART})-({PARENT_ID_PART})-({FLAGS_PART})(-.*)?\\s?$' match = re.match(regex, header) trace_id = match.group(2) span_id = match.group(3) - trace_sampled = (int(match.group(5), 16) == 1) - except IndexError: + # trace-flag component is an 8-bit bit field. Read as an int + int_flag = int(match.group(4), 16) + # trace sampled is set if the right-most bit in flag component is set + trace_sampled = bool(int_flag & 1) + except (IndexError, AttributeError): + # could not parse header as expected. Return None pass return trace_id, span_id, trace_sampled @@ -160,7 +165,7 @@ def _parse_xcloud_trace(header): Args: header (str): the string extracted from the X_CLOUD_TRACE header Returns: - Tuple[Optional[dict], Optional[str], Optional[bool]]: + Tuple[Optional[dict], Optional[str], bool]: The trace_id, span_id and trace_sampled extracted from the header Each field will be None if not found. """ @@ -186,7 +191,7 @@ def get_request_data(): Returns: Tuple[Optional[dict], Optional[str], Optional[str], Optional[bool]]: Data related to the current http request, trace_id, span_id, and trace_sampled - for the request. All fields will be None if a django request isn't found. + for the request. All fields will be None if a http request isn't found. """ checkers = ( get_request_data_from_django, diff --git a/tests/unit/handlers/test__helpers.py b/tests/unit/handlers/test__helpers.py index 105e27012..0652fcda9 100644 --- a/tests/unit/handlers/test__helpers.py +++ b/tests/unit/handlers/test__helpers.py @@ -360,4 +360,57 @@ def test_with__sampled(self): self.assertEqual(span_id, expected_span) self.assertEqual(sampled, True) +class Test__parse_trace_parent(unittest.TestCase): + @staticmethod + def _call_fut(header): + from google.cloud.logging_v2.handlers import _helpers + + trace, span, sampled = _helpers._parse_trace_parent(header) + return trace, span, sampled + + def test_empty_header(self): + header = "" + trace_id, span_id, sampled = self._call_fut(header) + self.assertIsNone(trace_id) + self.assertIsNone(span_id) + self.assertEqual(sampled, False) + + def test_valid_header(self): + header = "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01" + trace_id, span_id, sampled = self._call_fut(header) + self.assertEqual(trace_id, "0af7651916cd43dd8448eb211c80319c") + self.assertEqual(span_id, "b7ad6b7169203331") + self.assertEqual(sampled, True) + + def test_not_sampled(self): + header = "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-00" + trace_id, span_id, sampled = self._call_fut(header) + self.assertEqual(trace_id, "0af7651916cd43dd8448eb211c80319c") + self.assertEqual(span_id, "b7ad6b7169203331") + self.assertEqual(sampled, False) + + def test_sampled_w_other_flags(self): + header = "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-09" + trace_id, span_id, sampled = self._call_fut(header) + self.assertEqual(trace_id, "0af7651916cd43dd8448eb211c80319c") + self.assertEqual(span_id, "b7ad6b7169203331") + self.assertEqual(sampled, True) + def test_invalid_headers(self): + invalid_headers = [ + "", + "test" + "ff-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01", # invalid version + "00-00000000000000000000000000000000-b7ad6b7169203331-01", # invalid trace + "00-0af7651916cd43dd8448eb211c80319c-0000000000000000-01", # invalid span + "00-af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-00", + "00-0af7651916cd43dd8448eb211c80319c-bad6b7169203331-00", + "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-0", + "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-", + "00-0af7651916cd43dd8448eb211c80319c-00", + ] + for header in invalid_headers: + trace_id, span_id, sampled = self._call_fut(header) + self.assertIsNone(trace_id) + self.assertIsNone(span_id) + self.assertEqual(sampled, False) From 899dd930cdec780c248fa028fdf040f6b15f7441 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Wed, 1 Dec 2021 16:25:44 -0800 Subject: [PATCH 09/23] added tests for different trace types --- tests/unit/handlers/test__helpers.py | 63 +++++++++++++++++++++++----- 1 file changed, 52 insertions(+), 11 deletions(-) diff --git a/tests/unit/handlers/test__helpers.py b/tests/unit/handlers/test__helpers.py index 0652fcda9..b039dbb35 100644 --- a/tests/unit/handlers/test__helpers.py +++ b/tests/unit/handlers/test__helpers.py @@ -54,11 +54,11 @@ def test_no_context_header(self): self.assertEqual(sampled, False) self.assertEqual(http_request["requestMethod"], "GET") - def test_valid_context_header(self): + def test_xcloud_header(self): flask_trace_header = "X_CLOUD_TRACE_CONTEXT" expected_trace_id = _FLASK_TRACE_ID expected_span_id = _FLASK_SPAN_ID - flask_trace_id = f"{expected_trace_id}/{expected_span_id}" + flask_trace_id = f"{expected_trace_id}/{expected_span_id};o=1" app = self.create_app() context = app.test_request_context( @@ -70,7 +70,26 @@ def test_valid_context_header(self): self.assertEqual(trace_id, expected_trace_id) self.assertEqual(span_id, expected_span_id) - self.assertEqual(sampled, False) + self.assertEqual(sampled, True) + self.assertEqual(http_request["requestMethod"], "GET") + + def test_traceparent_header(self): + flask_trace_header = "TRACEPARENT" + expected_trace_id = "4bf92f3577b34da6a3ce929d0e0e4736" + expected_span_id = "00f067aa0ba902b7" + flask_trace_id = f"00-{expected_trace_id}-{expected_span_id}-01" + + app = self.create_app() + context = app.test_request_context( + path="/", headers={flask_trace_header: flask_trace_id} + ) + + with context: + http_request, trace_id, span_id, sampled = self._call_fut() + + self.assertEqual(trace_id, expected_trace_id) + self.assertEqual(span_id, expected_span_id) + self.assertEqual(sampled, True) self.assertEqual(http_request["requestMethod"], "GET") def test_http_request_populated(self): @@ -142,14 +161,14 @@ def test_no_context_header(self): self.assertIsNone(span_id) self.assertEqual(sampled, False) - def test_valid_context_header(self): + def test_xcloud_header(self): from django.test import RequestFactory from google.cloud.logging_v2.handlers.middleware import request django_trace_header = "HTTP_X_CLOUD_TRACE_CONTEXT" expected_span_id = _DJANGO_SPAN_ID expected_trace_id = _DJANGO_TRACE_ID - django_trace_id = f"{expected_trace_id}/{expected_span_id}" + django_trace_id = f"{expected_trace_id}/{expected_span_id};o=1" django_request = RequestFactory().get( "/", **{django_trace_header: django_trace_id} @@ -161,7 +180,29 @@ def test_valid_context_header(self): self.assertEqual(trace_id, expected_trace_id) self.assertEqual(span_id, expected_span_id) - self.assertEqual(sampled, False) + self.assertEqual(sampled, True) + self.assertEqual(http_request["requestMethod"], "GET") + + def test_xcloud_header(self): + from django.test import RequestFactory + from google.cloud.logging_v2.handlers.middleware import request + + django_trace_header = "HTTP_TRACEPARENT" + expected_trace_id = "4bf92f3577b34da6a3ce929d0e0e4736" + expected_span_id = "00f067aa0ba902b7" + header = f"00-{expected_trace_id}-{expected_span_id}-01" + + django_request = RequestFactory().get( + "/", **{django_trace_header: header} + ) + + middleware = request.RequestMiddleware(None) + middleware.process_request(django_request) + http_request, trace_id, span_id, sampled = self._call_fut() + + self.assertEqual(trace_id, expected_trace_id) + self.assertEqual(span_id, expected_span_id) + self.assertEqual(sampled, True) self.assertEqual(http_request["requestMethod"], "GET") def test_http_request_populated(self): @@ -230,7 +271,7 @@ def _helper(self, django_return, flask_return): def test_from_django(self): django_expected = (_DJANGO_HTTP_REQUEST, _DJANGO_TRACE_ID, _DJANGO_SPAN_ID, False) - flask_expected = (None, None, None, None) + flask_expected = (None, None, None, False) django_mock, flask_mock, output = self._helper(django_expected, flask_expected) self.assertEqual(output, django_expected) @@ -238,7 +279,7 @@ def test_from_django(self): flask_mock.assert_not_called() def test_from_flask(self): - django_expected = (None, None, None, None) + django_expected = (None, None, None, False) flask_expected = (_FLASK_HTTP_REQUEST, _FLASK_TRACE_ID, _FLASK_SPAN_ID, False) django_mock, flask_mock, output = self._helper(django_expected, flask_expected) @@ -271,7 +312,7 @@ def test_missing_http_request(self): flask_mock.assert_called_once_with() def test_missing_trace_id(self): - flask_expected = (_FLASK_HTTP_REQUEST, None, None, None) + flask_expected = (_FLASK_HTTP_REQUEST, None, None, False) django_expected = (None, _DJANGO_TRACE_ID, _DJANGO_SPAN_ID, True) django_mock, flask_mock, output = self._helper(django_expected, flask_expected) @@ -282,8 +323,8 @@ def test_missing_trace_id(self): flask_mock.assert_called_once_with() def test_missing_both(self): - flask_expected = (None, None, None, None) - django_expected = (None, None, None, None) + flask_expected = (None, None, None, False) + django_expected = (None, None, None, False) django_mock, flask_mock, output = self._helper(django_expected, flask_expected) self.assertEqual(output, (None, None, None, None)) From cb8bdfbb3cc7229dac873548b5bf530c7d46220a Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Thu, 2 Dec 2021 12:57:41 -0800 Subject: [PATCH 10/23] added trace_sampled to structured log handler --- google/cloud/logging_v2/handlers/handlers.py | 4 +++- google/cloud/logging_v2/handlers/structured_log.py | 1 + 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/google/cloud/logging_v2/handlers/handlers.py b/google/cloud/logging_v2/handlers/handlers.py index dba9c2893..f17122e8f 100644 --- a/google/cloud/logging_v2/handlers/handlers.py +++ b/google/cloud/logging_v2/handlers/handlers.py @@ -90,7 +90,7 @@ def filter(self, record): 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._trace_sampled = getattr(record, "trace_sampled", inferred_sampled) or None + record._trace_sampled = getattr(record, "trace_sampled", inferred_sampled) or False record._http_request = getattr(record, "http_request", inferred_http) record._source_location = CloudLoggingFilter._infer_source_location(record) # add logger name as a label if possible @@ -99,6 +99,7 @@ def filter(self, record): # create string representations for structured logging record._trace_str = record._trace or "" record._span_id_str = record._span_id or "" + record._trace_sampled_str = "true" if record._trace_sampled else "false" record._http_request_str = json.dumps( record._http_request or {}, ensure_ascii=False ) @@ -206,6 +207,7 @@ def emit(self, record): labels=labels, trace=record._trace, span_id=record._span_id, + trace_sampled=record._trace_sampled, http_request=record._http_request, source_location=record._source_location, ) diff --git a/google/cloud/logging_v2/handlers/structured_log.py b/google/cloud/logging_v2/handlers/structured_log.py index 7fd835f77..ac7fad0ca 100644 --- a/google/cloud/logging_v2/handlers/structured_log.py +++ b/google/cloud/logging_v2/handlers/structured_log.py @@ -27,6 +27,7 @@ '"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/trace_sampled": "%(_trace_sampled_str)s", ' '"logging.googleapis.com/sourceLocation": %(_source_location_str)s, ' '"httpRequest": %(_http_request_str)s ' "}" From d652588f2f708240f7e627b21926e78e241b82ba Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Thu, 2 Dec 2021 13:25:17 -0800 Subject: [PATCH 11/23] added tests for structured log handler integration --- google/cloud/logging_v2/handlers/_helpers.py | 2 +- tests/unit/handlers/test_handlers.py | 63 +++++++++++++++++++- tests/unit/handlers/test_structured_log.py | 47 ++++++++++++++- 3 files changed, 106 insertions(+), 6 deletions(-) diff --git a/google/cloud/logging_v2/handlers/_helpers.py b/google/cloud/logging_v2/handlers/_helpers.py index c5b377e5e..07fc8ff55 100644 --- a/google/cloud/logging_v2/handlers/_helpers.py +++ b/google/cloud/logging_v2/handlers/_helpers.py @@ -174,7 +174,7 @@ def _parse_xcloud_trace(header): # see https://cloud.google.com/trace/docs/setup for X-Cloud-Trace_Context format if header: try: - regex = '([\w]+)?(\/?([\w]+))?(;?o=(\d))?' + regex = '([\w-]+)?(\/?([\w-]+))?(;?o=(\d))?' match = re.match(regex, header) trace_id = match.group(1) span_id = match.group(3) diff --git a/tests/unit/handlers/test_handlers.py b/tests/unit/handlers/test_handlers.py index d36dc8959..c57b5fdfb 100644 --- a/tests/unit/handlers/test_handlers.py +++ b/tests/unit/handlers/test_handlers.py @@ -84,6 +84,8 @@ def test_filter_record(self): self.assertIsNone(record._resource) self.assertIsNone(record._trace) self.assertEqual(record._trace_str, "") + self.assertFalse(record._trace_sampled) + self.assertEqual(record._trace_sampled_str, "false") self.assertIsNone(record._span_id) self.assertEqual(record._span_id_str, "") self.assertIsNone(record._http_request) @@ -112,6 +114,8 @@ def test_minimal_record(self): self.assertEqual(record._trace_str, "") self.assertIsNone(record._span_id) self.assertEqual(record._span_id_str, "") + self.assertFalse(record._trace_sampled) + self.assertEqual(record._trace_sampled_str, "false") self.assertIsNone(record._http_request) self.assertEqual(record._http_request_str, "{}") self.assertIsNone(record._labels) @@ -131,7 +135,7 @@ def test_record_with_request(self): expected_agent = "Mozilla/5.0" expected_trace = "123" expected_span = "456" - combined_trace = f"{expected_trace}/{expected_span}" + combined_trace = f"{expected_trace}/{expected_span};o=1" expected_request = { "requestMethod": "GET", "requestUrl": expected_path, @@ -154,6 +158,50 @@ def test_record_with_request(self): self.assertEqual(record._trace_str, expected_trace) self.assertEqual(record._span_id, expected_span) self.assertEqual(record._span_id_str, expected_span) + self.assertTrue(record._trace_sampled) + self.assertEqual(record._trace_sampled_str, "true") + self.assertEqual(record._http_request, expected_request) + self.assertEqual(record._http_request_str, json.dumps(expected_request)) + + def test_record_with_traceparent_request(self): + """ + test filter adds http request data when available + """ + import logging + + filter_obj = self._make_one() + record = logging.LogRecord(None, logging.INFO, None, None, None, None, None,) + record.created = None + + expected_path = "http://testserver/123" + expected_agent = "Mozilla/5.0" + expected_trace = "4bf92f3577b34da6a3ce929d0e0e4736" + expected_span = "00f067aa0ba902b7" + combined_trace = f"00-{expected_trace}-{expected_span}-03" + expected_request = { + "requestMethod": "GET", + "requestUrl": expected_path, + "userAgent": expected_agent, + "protocol": "HTTP/1.1", + } + + app = self.create_app() + with app.test_request_context( + expected_path, + headers={ + "User-Agent": expected_agent, + "TRACEPARENT": combined_trace, + }, + ): + success = filter_obj.filter(record) + self.assertTrue(success) + + 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.assertTrue(record._trace_sampled) + self.assertEqual(record._trace_sampled_str, "true") self.assertEqual(record._http_request, expected_request) self.assertEqual(record._http_request_str, json.dumps(expected_request)) @@ -306,6 +354,7 @@ def test_emit(self): {"python_logger": logname}, None, None, + False, None, None, ), @@ -322,7 +371,7 @@ def test_emit_minimal(self): handler.handle(record) self.assertEqual( handler.transport.send_called_with, - (record, None, _GLOBAL_RESOURCE, None, None, None, None, None,), + (record, None, _GLOBAL_RESOURCE, None, None, None, False, None, None,), ) def test_emit_manual_field_override(self): @@ -350,6 +399,8 @@ def test_emit_manual_field_override(self): setattr(record, "trace", expected_trace) expected_span = "456" setattr(record, "span_id", expected_span) + expected_sampled = True + setattr(record, "trace_sampled", expected_sampled) expected_http = {"reuqest_url": "manual"} setattr(record, "http_request", expected_http) expected_source = {"file": "test-file"} @@ -375,6 +426,7 @@ def test_emit_manual_field_override(self): expected_labels, expected_trace, expected_span, + expected_sampled, expected_http, expected_source, ), @@ -410,6 +462,7 @@ def test_emit_with_custom_formatter(self): expected_label, None, None, + False, None, None, ), @@ -442,6 +495,7 @@ def test_emit_dict(self): expected_label, None, None, + False, None, None, ), @@ -474,6 +528,7 @@ def test_emit_with_encoded_json(self): expected_label, None, None, + False, None, None, ), @@ -499,7 +554,7 @@ def test_format_with_arguments(self): self.assertEqual( handler.transport.send_called_with, - (record, expected_result, _GLOBAL_RESOURCE, None, None, None, None, None,), + (record, expected_result, _GLOBAL_RESOURCE, None, None, None, False, None, None,), ) @@ -719,6 +774,7 @@ def send( labels=None, trace=None, span_id=None, + trace_sampled=None, http_request=None, source_location=None, ): @@ -729,6 +785,7 @@ def send( labels, trace, span_id, + trace_sampled, http_request, source_location, ) diff --git a/tests/unit/handlers/test_structured_log.py b/tests/unit/handlers/test_structured_log.py index d9dfa2512..7f2c91e9c 100644 --- a/tests/unit/handlers/test_structured_log.py +++ b/tests/unit/handlers/test_structured_log.py @@ -66,6 +66,7 @@ def test_format(self): "severity": record.levelname, "logging.googleapis.com/trace": "", "logging.googleapis.com/spanId": "", + "logging.googleapis.com/trace_sampled": "false", "logging.googleapis.com/sourceLocation": { "file": pathname, "line": lineno, @@ -95,6 +96,7 @@ def test_format_minimal(self): "severity": "INFO", "logging.googleapis.com/trace": "", "logging.googleapis.com/spanId": "", + "logging.googleapis.com/trace_sampled": "false", "logging.googleapis.com/sourceLocation": {}, "httpRequest": {}, "logging.googleapis.com/labels": {}, @@ -242,10 +244,11 @@ def test_format_with_request(self): expected_agent = "Mozilla/5.0" expected_trace = "123" expected_span = "456" - trace_header = f"{expected_trace}/{expected_span};o=0" + trace_header = f"{expected_trace}/{expected_span};o=1" expected_payload = { "logging.googleapis.com/trace": expected_trace, "logging.googleapis.com/spanId": expected_span, + "logging.googleapis.com/trace_sampled": "true", "httpRequest": { "requestMethod": "GET", "requestUrl": expected_path, @@ -267,6 +270,44 @@ def test_format_with_request(self): for (key, value) in expected_payload.items(): self.assertEqual(value, result[key]) + def test_format_with_traceparent(self): + import logging + import json + + handler = self._make_one() + logname = "loggername" + message = "hello world，嗨 世界" + record = logging.LogRecord(logname, logging.INFO, "", 0, message, None, None) + expected_path = "http://testserver/123" + expected_agent = "Mozilla/5.0" + expected_trace = "4bf92f3577b34da6a3ce929d0e0e4736" + expected_span = "00f067aa0ba902b7" + trace_header = f"00-{expected_trace}-{expected_span}-09" + expected_payload = { + "logging.googleapis.com/trace": expected_trace, + "logging.googleapis.com/spanId": expected_span, + "logging.googleapis.com/trace_sampled": "true", + "httpRequest": { + "requestMethod": "GET", + "requestUrl": expected_path, + "userAgent": expected_agent, + "protocol": "HTTP/1.1", + }, + } + + app = self.create_app() + with app.test_request_context( + expected_path, + headers={ + "User-Agent": expected_agent, + "TRACEPARENT": trace_header, + }, + ): + handler.filter(record) + 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={})` @@ -289,17 +330,19 @@ def test_format_overrides(self): inferred_path = "http://testserver/123" overwrite_trace = "abc" overwrite_span = "def" - inferred_trace_span = "123/456;" + inferred_trace_span = "123/456;o=1" overwrite_file = "test-file" record.http_request = {"requestUrl": overwrite_path} record.source_location = {"file": overwrite_file} record.trace = overwrite_trace record.span_id = overwrite_span + record.trace_sampled = False added_labels = {"added_key": "added_value", "overwritten_key": "new_value"} record.labels = added_labels expected_payload = { "logging.googleapis.com/trace": overwrite_trace, "logging.googleapis.com/spanId": overwrite_span, + "logging.googleapis.com/trace_sampled": "false", "logging.googleapis.com/sourceLocation": {"file": overwrite_file}, "httpRequest": {"requestUrl": overwrite_path}, "logging.googleapis.com/labels": { From 0d530256243574074d53f181d9a92d7853717ab7 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Thu, 2 Dec 2021 13:54:25 -0800 Subject: [PATCH 12/23] updated submodule --- tests/environment | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/environment b/tests/environment index a201d48f1..01d50f2c6 160000 --- a/tests/environment +++ b/tests/environment @@ -1 +1 @@ -Subproject commit a201d48f163db4ff799305188d380f620ebf345a +Subproject commit 01d50f2c63ba64f3c1db75660862f179ec1a3b57 From c9bc7720d46183ddf9a07ac1031396c448fdf58b Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Thu, 2 Dec 2021 14:00:44 -0800 Subject: [PATCH 13/23] lint fixes --- google/cloud/logging_v2/handlers/_helpers.py | 16 ++++++------ google/cloud/logging_v2/handlers/handlers.py | 4 ++- tests/unit/handlers/test__helpers.py | 27 +++++++++++++------- tests/unit/handlers/test_handlers.py | 17 ++++++++---- tests/unit/handlers/test_structured_log.py | 5 +--- 5 files changed, 42 insertions(+), 27 deletions(-) diff --git a/google/cloud/logging_v2/handlers/_helpers.py b/google/cloud/logging_v2/handlers/_helpers.py index c2c0dfc4d..6981d01b1 100644 --- a/google/cloud/logging_v2/handlers/_helpers.py +++ b/google/cloud/logging_v2/handlers/_helpers.py @@ -113,7 +113,7 @@ def get_request_data_from_django(): } # find trace id and span id - header = request.META.get(_DJANGO_TRACEPARENT) + header = request.META.get(_DJANGO_TRACEPARENT) if header: trace_id, span_id, trace_sampled = _parse_trace_parent(header) else: @@ -141,11 +141,11 @@ def _parse_trace_parent(header): # see https://www.w3.org/TR/trace-context/ for W3C traceparent format if header: try: - VERSION_PART = r'(?!ff)[a-f\d]{2}' - TRACE_ID_PART = r'(?![0]{32})[a-f\d]{32}' - PARENT_ID_PART = r'(?![0]{16})[a-f\d]{16}' - FLAGS_PART = r'[a-f\d]{2}' - regex = f'^\\s?({VERSION_PART})-({TRACE_ID_PART})-({PARENT_ID_PART})-({FLAGS_PART})(-.*)?\\s?$' + VERSION_PART = r"(?!ff)[a-f\d]{2}" + TRACE_ID_PART = r"(?![0]{32})[a-f\d]{32}" + PARENT_ID_PART = r"(?![0]{16})[a-f\d]{16}" + FLAGS_PART = r"[a-f\d]{2}" + regex = f"^\\s?({VERSION_PART})-({TRACE_ID_PART})-({PARENT_ID_PART})-({FLAGS_PART})(-.*)?\\s?$" match = re.match(regex, header) trace_id = match.group(2) span_id = match.group(3) @@ -174,7 +174,7 @@ def _parse_xcloud_trace(header): # see https://cloud.google.com/trace/docs/setup for X-Cloud-Trace_Context format if header: try: - regex = '([\w-]+)?(\/?([\w-]+))?(;?o=(\d))?' + regex = r"([\w-]+)?(\/?([\w-]+))?(;?o=(\d))?" match = re.match(regex, header) trace_id = match.group(1) span_id = match.group(3) @@ -190,7 +190,7 @@ def get_request_data(): Returns: Tuple[Optional[dict], Optional[str], Optional[str], Optional[bool]]: - Data related to the current http request, trace_id, span_id, and trace_sampled + Data related to the current http request, trace_id, span_id, and trace_sampled for the request. All fields will be None if a http request isn't found. """ checkers = ( diff --git a/google/cloud/logging_v2/handlers/handlers.py b/google/cloud/logging_v2/handlers/handlers.py index b00ee168f..982814bae 100644 --- a/google/cloud/logging_v2/handlers/handlers.py +++ b/google/cloud/logging_v2/handlers/handlers.py @@ -95,7 +95,9 @@ def filter(self, record): 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._trace_sampled = getattr(record, "trace_sampled", inferred_sampled) or False + record._trace_sampled = ( + getattr(record, "trace_sampled", inferred_sampled) or False + ) record._http_request = getattr(record, "http_request", inferred_http) record._source_location = CloudLoggingFilter._infer_source_location(record) # add logger name as a label if possible diff --git a/tests/unit/handlers/test__helpers.py b/tests/unit/handlers/test__helpers.py index b039dbb35..57dcedfa6 100644 --- a/tests/unit/handlers/test__helpers.py +++ b/tests/unit/handlers/test__helpers.py @@ -183,7 +183,7 @@ def test_xcloud_header(self): self.assertEqual(sampled, True) self.assertEqual(http_request["requestMethod"], "GET") - def test_xcloud_header(self): + def test_traceparent_header(self): from django.test import RequestFactory from google.cloud.logging_v2.handlers.middleware import request @@ -192,9 +192,7 @@ def test_xcloud_header(self): expected_span_id = "00f067aa0ba902b7" header = f"00-{expected_trace_id}-{expected_span_id}-01" - django_request = RequestFactory().get( - "/", **{django_trace_header: header} - ) + django_request = RequestFactory().get("/", **{django_trace_header: header}) middleware = request.RequestMiddleware(None) middleware.process_request(django_request) @@ -270,7 +268,12 @@ def _helper(self, django_return, flask_return): return django_mock, flask_mock, result def test_from_django(self): - django_expected = (_DJANGO_HTTP_REQUEST, _DJANGO_TRACE_ID, _DJANGO_SPAN_ID, False) + django_expected = ( + _DJANGO_HTTP_REQUEST, + _DJANGO_TRACE_ID, + _DJANGO_SPAN_ID, + False, + ) flask_expected = (None, None, None, False) django_mock, flask_mock, output = self._helper(django_expected, flask_expected) self.assertEqual(output, django_expected) @@ -289,7 +292,12 @@ def test_from_flask(self): flask_mock.assert_called_once_with() def test_from_django_and_flask(self): - django_expected = (_DJANGO_HTTP_REQUEST, _DJANGO_TRACE_ID, _DJANGO_SPAN_ID, False) + django_expected = ( + _DJANGO_HTTP_REQUEST, + _DJANGO_TRACE_ID, + _DJANGO_SPAN_ID, + False, + ) flask_expected = (_FLASK_HTTP_REQUEST, _FLASK_TRACE_ID, _FLASK_SPAN_ID, False) django_mock, flask_mock, output = self._helper(django_expected, flask_expected) @@ -401,6 +409,7 @@ def test_with__sampled(self): self.assertEqual(span_id, expected_span) self.assertEqual(sampled, True) + class Test__parse_trace_parent(unittest.TestCase): @staticmethod def _call_fut(header): @@ -441,9 +450,9 @@ def test_invalid_headers(self): invalid_headers = [ "", "test" - "ff-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01", # invalid version - "00-00000000000000000000000000000000-b7ad6b7169203331-01", # invalid trace - "00-0af7651916cd43dd8448eb211c80319c-0000000000000000-01", # invalid span + "ff-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01", # invalid version + "00-00000000000000000000000000000000-b7ad6b7169203331-01", # invalid trace + "00-0af7651916cd43dd8448eb211c80319c-0000000000000000-01", # invalid span "00-af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-00", "00-0af7651916cd43dd8448eb211c80319c-bad6b7169203331-00", "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-0", diff --git a/tests/unit/handlers/test_handlers.py b/tests/unit/handlers/test_handlers.py index c57b5fdfb..dbf5def60 100644 --- a/tests/unit/handlers/test_handlers.py +++ b/tests/unit/handlers/test_handlers.py @@ -188,10 +188,7 @@ def test_record_with_traceparent_request(self): app = self.create_app() with app.test_request_context( expected_path, - headers={ - "User-Agent": expected_agent, - "TRACEPARENT": combined_trace, - }, + headers={"User-Agent": expected_agent, "TRACEPARENT": combined_trace}, ): success = filter_obj.filter(record) self.assertTrue(success) @@ -554,7 +551,17 @@ def test_format_with_arguments(self): self.assertEqual( handler.transport.send_called_with, - (record, expected_result, _GLOBAL_RESOURCE, None, None, None, False, None, None,), + ( + record, + expected_result, + _GLOBAL_RESOURCE, + None, + None, + None, + False, + None, + None, + ), ) diff --git a/tests/unit/handlers/test_structured_log.py b/tests/unit/handlers/test_structured_log.py index 7f2c91e9c..9041bd8a3 100644 --- a/tests/unit/handlers/test_structured_log.py +++ b/tests/unit/handlers/test_structured_log.py @@ -298,10 +298,7 @@ def test_format_with_traceparent(self): app = self.create_app() with app.test_request_context( expected_path, - headers={ - "User-Agent": expected_agent, - "TRACEPARENT": trace_header, - }, + headers={"User-Agent": expected_agent, "TRACEPARENT": trace_header}, ): handler.filter(record) result = json.loads(handler.format(record)) From d9b4f0adf20a05b9fa5bcdc4e2b0665fa493d56d Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Thu, 2 Dec 2021 14:19:11 -0800 Subject: [PATCH 14/23] added extra system test --- tests/system/test_system.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/tests/system/test_system.py b/tests/system/test_system.py index cde722bd6..ffeae6dc6 100644 --- a/tests/system/test_system.py +++ b/tests/system/test_system.py @@ -534,6 +534,7 @@ def test_handlers_w_extras(self): extra = { "trace": "123", "span_id": "456", + "trace_sampled": True, "http_request": expected_request, "source_location": expected_source, "resource": Resource(type="cloudiot_device", labels={}), @@ -545,6 +546,7 @@ def test_handlers_w_extras(self): self.assertEqual(len(entries), 1) self.assertEqual(entries[0].trace, extra["trace"]) self.assertEqual(entries[0].span_id, extra["span_id"]) + self.assertTrue(entries[0].trace_sampled) self.assertEqual(entries[0].http_request, expected_request) self.assertEqual( entries[0].labels, {**extra["labels"], "python_logger": LOGGER_NAME} From 86623388be264583b9bbd884e466f9e80e1735e5 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Thu, 2 Dec 2021 14:44:47 -0800 Subject: [PATCH 15/23] updated submodule --- tests/environment | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/environment b/tests/environment index 01d50f2c6..28a9ea4a4 160000 --- a/tests/environment +++ b/tests/environment @@ -1 +1 @@ -Subproject commit 01d50f2c63ba64f3c1db75660862f179ec1a3b57 +Subproject commit 28a9ea4a4373556899e9c9c2636da57a6b86862a From a874e9a49cfd92fe2a1e7788daa46f1bafacc39f Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Thu, 2 Dec 2021 15:47:09 -0800 Subject: [PATCH 16/23] fixed structured log handler string interpretation issue --- google/cloud/logging_v2/handlers/handlers.py | 4 +--- google/cloud/logging_v2/handlers/structured_log.py | 2 +- tests/unit/handlers/test_structured_log.py | 10 +++++----- 3 files changed, 7 insertions(+), 9 deletions(-) diff --git a/google/cloud/logging_v2/handlers/handlers.py b/google/cloud/logging_v2/handlers/handlers.py index 982814bae..4f0d75341 100644 --- a/google/cloud/logging_v2/handlers/handlers.py +++ b/google/cloud/logging_v2/handlers/handlers.py @@ -95,9 +95,7 @@ def filter(self, record): 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._trace_sampled = ( - getattr(record, "trace_sampled", inferred_sampled) or False - ) + record._trace_sampled = bool(getattr(record, "trace_sampled", inferred_sampled)) record._http_request = getattr(record, "http_request", inferred_http) record._source_location = CloudLoggingFilter._infer_source_location(record) # add logger name as a label if possible diff --git a/google/cloud/logging_v2/handlers/structured_log.py b/google/cloud/logging_v2/handlers/structured_log.py index ac7fad0ca..2d7c5e078 100644 --- a/google/cloud/logging_v2/handlers/structured_log.py +++ b/google/cloud/logging_v2/handlers/structured_log.py @@ -27,7 +27,7 @@ '"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/trace_sampled": "%(_trace_sampled_str)s", ' + '"logging.googleapis.com/trace_sampled": %(_trace_sampled_str)s, ' '"logging.googleapis.com/sourceLocation": %(_source_location_str)s, ' '"httpRequest": %(_http_request_str)s ' "}" diff --git a/tests/unit/handlers/test_structured_log.py b/tests/unit/handlers/test_structured_log.py index 9041bd8a3..f12bb1f7e 100644 --- a/tests/unit/handlers/test_structured_log.py +++ b/tests/unit/handlers/test_structured_log.py @@ -66,7 +66,7 @@ def test_format(self): "severity": record.levelname, "logging.googleapis.com/trace": "", "logging.googleapis.com/spanId": "", - "logging.googleapis.com/trace_sampled": "false", + "logging.googleapis.com/trace_sampled": False, "logging.googleapis.com/sourceLocation": { "file": pathname, "line": lineno, @@ -96,7 +96,7 @@ def test_format_minimal(self): "severity": "INFO", "logging.googleapis.com/trace": "", "logging.googleapis.com/spanId": "", - "logging.googleapis.com/trace_sampled": "false", + "logging.googleapis.com/trace_sampled": False, "logging.googleapis.com/sourceLocation": {}, "httpRequest": {}, "logging.googleapis.com/labels": {}, @@ -248,7 +248,7 @@ def test_format_with_request(self): expected_payload = { "logging.googleapis.com/trace": expected_trace, "logging.googleapis.com/spanId": expected_span, - "logging.googleapis.com/trace_sampled": "true", + "logging.googleapis.com/trace_sampled": True, "httpRequest": { "requestMethod": "GET", "requestUrl": expected_path, @@ -286,7 +286,7 @@ def test_format_with_traceparent(self): expected_payload = { "logging.googleapis.com/trace": expected_trace, "logging.googleapis.com/spanId": expected_span, - "logging.googleapis.com/trace_sampled": "true", + "logging.googleapis.com/trace_sampled": True, "httpRequest": { "requestMethod": "GET", "requestUrl": expected_path, @@ -339,7 +339,7 @@ def test_format_overrides(self): expected_payload = { "logging.googleapis.com/trace": overwrite_trace, "logging.googleapis.com/spanId": overwrite_span, - "logging.googleapis.com/trace_sampled": "false", + "logging.googleapis.com/trace_sampled": False, "logging.googleapis.com/sourceLocation": {"file": overwrite_file}, "httpRequest": {"requestUrl": overwrite_path}, "logging.googleapis.com/labels": { From 0286522a6f12d62db52a489682d906582f778e57 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Mon, 6 Dec 2021 13:45:55 -0800 Subject: [PATCH 17/23] updated submodule --- tests/environment | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/environment b/tests/environment index 28a9ea4a4..60eb669ba 160000 --- a/tests/environment +++ b/tests/environment @@ -1 +1 @@ -Subproject commit 28a9ea4a4373556899e9c9c2636da57a6b86862a +Subproject commit 60eb669ba12981393815ba0076979792db7dc607 From b30f9e798e73f51349984982d5a27cd226349ef1 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Tue, 7 Dec 2021 12:07:36 -0800 Subject: [PATCH 18/23] added more test cases --- tests/system/test_system.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/tests/system/test_system.py b/tests/system/test_system.py index ffeae6dc6..4033cfbf3 100644 --- a/tests/system/test_system.py +++ b/tests/system/test_system.py @@ -454,6 +454,7 @@ def test_log_empty(self): self.assertEqual(len(entries), 1) self.assertIsNone(entries[0].payload) + self.assertFalse(entries[0].trace_sampled) def test_log_struct_logentry_data(self): logger = Config.CLIENT.logger(self._logger_name("log_w_struct")) @@ -473,6 +474,7 @@ def test_log_struct_logentry_data(self): self.assertEqual(entries[0].severity, "WARNING") self.assertEqual(entries[0].trace, JSON_PAYLOAD["trace"]) self.assertEqual(entries[0].span_id, JSON_PAYLOAD["span_id"]) + self.assertFalse(entries[0].trace_sampled) def test_log_handler_async(self): LOG_MESSAGE = "It was the worst of times" From 7e521db1e9846a6cdf36fdb29dc8f0bae9be9251 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Tue, 7 Dec 2021 12:30:24 -0800 Subject: [PATCH 19/23] updated submodule --- tests/environment | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/environment b/tests/environment index 60eb669ba..229c6cf2a 160000 --- a/tests/environment +++ b/tests/environment @@ -1 +1 @@ -Subproject commit 60eb669ba12981393815ba0076979792db7dc607 +Subproject commit 229c6cf2abc907cf4b1762f797d5a0756c9009fa From 438b3eef60214be5fb49d31dc5589d38ad9e1e03 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Tue, 7 Dec 2021 12:55:27 -0800 Subject: [PATCH 20/23] default trace_sampled to False --- google/cloud/logging_v2/handlers/_helpers.py | 8 ++++---- tests/unit/handlers/test__helpers.py | 6 +++--- tests/unit/handlers/test_handlers.py | 1 + 3 files changed, 8 insertions(+), 7 deletions(-) diff --git a/google/cloud/logging_v2/handlers/_helpers.py b/google/cloud/logging_v2/handlers/_helpers.py index 6981d01b1..92126de0c 100644 --- a/google/cloud/logging_v2/handlers/_helpers.py +++ b/google/cloud/logging_v2/handlers/_helpers.py @@ -69,7 +69,7 @@ def get_request_data_from_flask(): for the request. All fields will be None if a django request isn't found. """ if flask is None or not flask.request: - return None, None, None, None + return None, None, None, False # build http_request http_request = { @@ -102,7 +102,7 @@ def get_request_data_from_django(): request = _get_django_request() if request is None: - return None, None, None, None + return None, None, None, False # build http_request http_request = { @@ -189,7 +189,7 @@ def get_request_data(): frameworks (currently supported: Flask and Django). Returns: - Tuple[Optional[dict], Optional[str], Optional[str], Optional[bool]]: + Tuple[Optional[dict], Optional[str], Optional[str], bool]: Data related to the current http request, trace_id, span_id, and trace_sampled for the request. All fields will be None if a http request isn't found. """ @@ -203,4 +203,4 @@ def get_request_data(): if http_request is not None: return http_request, trace_id, span_id, trace_sampled - return None, None, None, None + return None, None, None, False diff --git a/tests/unit/handlers/test__helpers.py b/tests/unit/handlers/test__helpers.py index 57dcedfa6..9946c8eb5 100644 --- a/tests/unit/handlers/test__helpers.py +++ b/tests/unit/handlers/test__helpers.py @@ -314,7 +314,7 @@ def test_missing_http_request(self): django_mock, flask_mock, output = self._helper(django_expected, flask_expected) # function only returns trace if http_request data is present - self.assertEqual(output, (None, None, None, None)) + self.assertEqual(output, (None, None, None, False)) django_mock.assert_called_once_with() flask_mock.assert_called_once_with() @@ -334,14 +334,14 @@ def test_missing_both(self): flask_expected = (None, None, None, False) django_expected = (None, None, None, False) django_mock, flask_mock, output = self._helper(django_expected, flask_expected) - self.assertEqual(output, (None, None, None, None)) + self.assertEqual(output, (None, None, None, False)) django_mock.assert_called_once_with() flask_mock.assert_called_once_with() def test_wo_libraries(self): output = self._call_fut() - self.assertEqual(output, (None, None, None, None)) + self.assertEqual(output, (None, None, None, False)) class Test__parse_xcloud_trace(unittest.TestCase): diff --git a/tests/unit/handlers/test_handlers.py b/tests/unit/handlers/test_handlers.py index dacd1dbf5..bbfacf59f 100644 --- a/tests/unit/handlers/test_handlers.py +++ b/tests/unit/handlers/test_handlers.py @@ -527,6 +527,7 @@ def test_emit_w_json_extras(self): expected_label, None, None, + False, None, None, ), From a6c6047fab4e24417ebef98e7425086dcbb2a71f Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Tue, 7 Dec 2021 13:42:16 -0800 Subject: [PATCH 21/23] updated submodule --- tests/environment | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/environment b/tests/environment index 229c6cf2a..95d3aea9c 160000 --- a/tests/environment +++ b/tests/environment @@ -1 +1 @@ -Subproject commit 229c6cf2abc907cf4b1762f797d5a0756c9009fa +Subproject commit 95d3aea9c1f4a18db96f51997ead826d9e2e093c From bcbb318b076ede44f6a0551701e3fddd2149a6a6 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Tue, 7 Dec 2021 14:09:07 -0800 Subject: [PATCH 22/23] updated submodule --- tests/environment | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/environment b/tests/environment index 95d3aea9c..41c32ce34 160000 --- a/tests/environment +++ b/tests/environment @@ -1 +1 @@ -Subproject commit 95d3aea9c1f4a18db96f51997ead826d9e2e093c +Subproject commit 41c32ce3425529680e32701549d3f682f9c82b63 From b3acb1070129760745fd429cf65afeeda5f3b608 Mon Sep 17 00:00:00 2001 From: Daniel Sanche Date: Tue, 7 Dec 2021 14:44:00 -0800 Subject: [PATCH 23/23] changed logic for trace extraction --- google/cloud/logging_v2/handlers/_helpers.py | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/google/cloud/logging_v2/handlers/_helpers.py b/google/cloud/logging_v2/handlers/_helpers.py index 92126de0c..32e70dfdd 100644 --- a/google/cloud/logging_v2/handlers/_helpers.py +++ b/google/cloud/logging_v2/handlers/_helpers.py @@ -80,11 +80,11 @@ def get_request_data_from_flask(): } # find trace id and span id + # first check for w3c traceparent header header = flask.request.headers.get(_FLASK_TRACEPARENT) - if header: - trace_id, span_id, trace_sampled = _parse_trace_parent(header) - else: - # w3 traceparent header not found. Check XCLOUD_TRACE_CONTEXT + trace_id, span_id, trace_sampled = _parse_trace_parent(header) + if trace_id is None: + # traceparent not found. look for xcloud_trace_context header header = flask.request.headers.get(_FLASK_XCLOUD_TRACE_HEADER) trace_id, span_id, trace_sampled = _parse_xcloud_trace(header) @@ -113,11 +113,11 @@ def get_request_data_from_django(): } # find trace id and span id + # first check for w3c traceparent header header = request.META.get(_DJANGO_TRACEPARENT) - if header: - trace_id, span_id, trace_sampled = _parse_trace_parent(header) - else: - # w3 traceparent header not found. Check XCLOUD_TRACE_CONTEXT + trace_id, span_id, trace_sampled = _parse_trace_parent(header) + if trace_id is None: + # traceparent not found. look for xcloud_trace_context header header = request.META.get(_DJANGO_XCLOUD_TRACE_HEADER) trace_id, span_id, trace_sampled = _parse_xcloud_trace(header)