diff --git a/google/cloud/logging_v2/handlers/_helpers.py b/google/cloud/logging_v2/handlers/_helpers.py index f5dfb7c55..32e70dfdd 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" @@ -62,13 +64,12 @@ def get_request_data_from_flask(): """Get http_request and trace data from flask 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], 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. """ if flask is None or not flask.request: - return None, None, None + return None, None, None, False # build http_request http_request = { @@ -79,25 +80,29 @@ 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) + # first check for w3c traceparent header + header = flask.request.headers.get(_FLASK_TRACEPARENT) + 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) - 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], 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() if request is None: - return None, None, None + return None, None, None, False # build http_request http_request = { @@ -108,34 +113,75 @@ 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) + # first check for w3c traceparent header + header = request.META.get(_DJANGO_TRACEPARENT) + 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) - return http_request, trace_id, span_id + 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 + example: 00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01 + Returns: + Tuple[Optional[dict], Optional[str], bool]: + The trace_id, span_id and trace_sampled extracted from the header + Each field will be None if header can't be parsed in expected format. + """ + trace_id = span_id = None + trace_sampled = False + # 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?$" + match = re.match(regex, header) + trace_id = match.group(2) + span_id = match.group(3) + # 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 + + +def _parse_xcloud_trace(header): """Given an X_CLOUD_TRACE header, extract the trace and span ids. 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], 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 = None + trace_sampled = False + # 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 = r"([\w-]+)?(\/?([\w-]+))?(;?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 +189,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], 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. """ checkers = ( get_request_data_from_django, @@ -154,8 +199,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, False 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 39bcbca79..769146007 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 = 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 +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 = 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 @@ -98,6 +104,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 ) @@ -205,6 +212,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/tests/system/test_system.py b/tests/system/test_system.py index 24050e8b3..90b4059d6 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" @@ -534,6 +536,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 +548,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} diff --git a/tests/unit/handlers/test__helpers.py b/tests/unit/handlers/test__helpers.py index d26e700e8..9946c8eb5 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,17 +47,18 @@ 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): + 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( @@ -64,10 +66,30 @@ 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, 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): @@ -106,7 +128,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,20 +154,21 @@ 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): + 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} @@ -152,10 +176,31 @@ 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, True) + self.assertEqual(http_request["requestMethod"], "GET") + + def test_traceparent_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): @@ -203,7 +248,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 +268,13 @@ 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, False) django_mock, flask_mock, output = self._helper(django_expected, flask_expected) self.assertEqual(output, django_expected) @@ -231,8 +282,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, False) + 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 +292,13 @@ 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 +309,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, False)) 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, False) + 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 +331,136 @@ 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, False) + django_expected = (None, None, None, False) django_mock, flask_mock, output = self._helper(django_expected, flask_expected) - self.assertEqual(output, (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)) + self.assertEqual(output, (None, None, None, False)) -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) + + +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) 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"]) diff --git a/tests/unit/handlers/test_handlers.py b/tests/unit/handlers/test_handlers.py index 71a709b6a..bbfacf59f 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,47 @@ 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 +351,7 @@ def test_emit(self): {"python_logger": logname}, None, None, + False, None, None, ), @@ -322,7 +368,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 +396,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 +423,7 @@ def test_emit_manual_field_override(self): expected_labels, expected_trace, expected_span, + expected_sampled, expected_http, expected_source, ), @@ -410,6 +459,7 @@ def test_emit_with_custom_formatter(self): expected_label, None, None, + False, None, None, ), @@ -442,6 +492,7 @@ def test_emit_dict(self): expected_label, None, None, + False, None, None, ), @@ -476,6 +527,7 @@ def test_emit_w_json_extras(self): expected_label, None, None, + False, None, None, ), @@ -508,6 +560,7 @@ def test_emit_with_encoded_json(self): expected_label, None, None, + False, None, None, ), @@ -533,7 +586,17 @@ 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, + ), ) @@ -809,6 +872,7 @@ def send( labels=None, trace=None, span_id=None, + trace_sampled=None, http_request=None, source_location=None, ): @@ -819,6 +883,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 08e4c2906..5db098c29 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,41 @@ 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 +327,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": {