Repository: googleapis/python-logging

Issue:
Span ID reported when "X-Cloud-Trace-Context" is used is incorrect
For Googlers: motivating details / context can be found in Buganizer issue # 367762417 

#### Steps to reproduce

  1. Execute in an environment in which tracing context has been supplied via `X-Cloud-Trace-Context`.

#### Observed

  The `LogEntry` that is created contains a `span_id` that is incorrect.
  
  Note that `LogEntry.span_id` should be the hexadecimal encoding of the span ID, whereas `X-Cloud-Trace-Context` (unlike `traceparent`) encodes the `span_id` in decimal format.

#### Expected

 The `LogEntry.span_id` field should be populated with the canonical (hexadecimal) representation of the span ID.

Discussion:

Patch:
diff --git a/google/cloud/logging_v2/handlers/_helpers.py b/google/cloud/logging_v2/handlers/_helpers.py
index 98bf0cd..ff5838e 100644
--- a/google/cloud/logging_v2/handlers/_helpers.py
+++ b/google/cloud/logging_v2/handlers/_helpers.py
@@ -174,13 +174,22 @@ def _parse_xcloud_trace(header):
     Args:
         header (str): the string extracted from the X_CLOUD_TRACE header
     Returns:
-        Tuple[Optional[dict], Optional[str], bool]:
+        Tuple[Optional[str], 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 = span_id = None
     trace_sampled = False
-    # see https://cloud.google.com/trace/docs/setup for X-Cloud-Trace_Context format
+
+    # As per the format described at https://cloud.google.com/trace/docs/trace-context#legacy-http-header
+    #    "X-Cloud-Trace-Context: TRACE_ID[/SPAN_ID][;o=OPTIONS]"
+    # for example:
+    #    "X-Cloud-Trace-Context: 105445aa7843bc8bf206b12000100000/1;o=1"
+    #
+    # We expect:
+    #   * trace_id (optional, 128-bit hex string):  "105445aa7843bc8bf206b12000100000"
+    #   * span_id (optional, 16-bit hex string):   "0000000000000001" (needs to be converted into 16 bit hex string)
+    #   * trace_sampled (optional, bool): 	       true
     if header:
         try:
             regex = r"([\w-]+)?(\/?([\w-]+))?(;?o=(\d))?"
@@ -188,6 +197,17 @@ def _parse_xcloud_trace(header):
             trace_id = match.group(1)
             span_id = match.group(3)
             trace_sampled = match.group(5) == "1"
+
+            # Convert the span ID to 16-bit hexadecimal instead of decimal
+            try:
+                span_id_int = int(span_id)
+                if span_id_int > 0 and span_id_int < 2**64:
+                    span_id = f"{span_id_int:016x}"
+                else:
+                    span_id = None
+            except (ValueError, TypeError):
+                span_id = None
+
         except IndexError:
             pass
     return trace_id, span_id, trace_sampled


Test patch:
diff --git a/tests/unit/handlers/test__helpers.py b/tests/unit/handlers/test__helpers.py
index b8c8fc9..d0577cf 100644
--- a/tests/unit/handlers/test__helpers.py
+++ b/tests/unit/handlers/test__helpers.py
@@ -25,9 +25,13 @@ from tests.unit.handlers import (
 
 _FLASK_TRACE_ID = "flask0id"
 _FLASK_SPAN_ID = "span0flask"
+_FLASK_SPAN_ID_XCTC_DEC = "12345"
+_FLASK_SPAN_ID_XCTC_HEX = "3039".zfill(16)
 _FLASK_HTTP_REQUEST = {"requestUrl": "https://flask.palletsprojects.com/en/1.1.x/"}
 _DJANGO_TRACE_ID = "django0id"
 _DJANGO_SPAN_ID = "span0django"
+_DJANGO_SPAN_ID_XCTC_DEC = "54321"
+_DJANGO_SPAN_ID_XCTC_HEX = "d431".zfill(16)
 _DJANGO_HTTP_REQUEST = {"requestUrl": "https://www.djangoproject.com/"}
 
 
@@ -64,8 +68,9 @@ class Test_get_request_data_from_flask(unittest.TestCase):
     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};o=1"
+        input_span_id = _FLASK_SPAN_ID_XCTC_DEC
+        expected_span_id = _FLASK_SPAN_ID_XCTC_HEX
+        flask_trace_id = f"{expected_trace_id}/{input_span_id};o=1"
 
         app = self.create_app()
         context = app.test_request_context(
@@ -173,9 +178,10 @@ class Test_get_request_data_from_django(unittest.TestCase):
         from google.cloud.logging_v2.handlers.middleware import request
 
         django_trace_header = "HTTP_X_CLOUD_TRACE_CONTEXT"
-        expected_span_id = _DJANGO_SPAN_ID
+        input_span_id = _DJANGO_SPAN_ID_XCTC_DEC
+        expected_span_id = _DJANGO_SPAN_ID_XCTC_HEX
         expected_trace_id = _DJANGO_TRACE_ID
-        django_trace_id = f"{expected_trace_id}/{expected_span_id};o=1"
+        django_trace_id = f"{expected_trace_id}/{input_span_id};o=1"
 
         django_request = RequestFactory().get(
             "/", **{django_trace_header: django_trace_id}
@@ -501,25 +507,40 @@ class Test__parse_xcloud_trace(unittest.TestCase):
         self.assertEqual(sampled, False)
 
     def test_no_trace(self):
-        header = "/12345"
+        input_span = "12345"
+        expected_span = "3039".zfill(16)
+        header = f"/{input_span}"
         trace_id, span_id, sampled = self._call_fut(header)
         self.assertIsNone(trace_id)
-        self.assertEqual(span_id, "12345")
+        self.assertEqual(span_id, expected_span)
         self.assertEqual(sampled, False)
 
     def test_with_span(self):
         expected_trace = "12345"
-        expected_span = "67890"
-        header = f"{expected_trace}/{expected_span}"
+        input_span = "67890"
+        expected_span = "10932".zfill(16)
+        header = f"{expected_trace}/{input_span}"
         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_span_decimal_not_in_bounds(self):
+        input_spans = ["0", "9" * 100]
+
+        for input_span in input_spans:
+            expected_trace = "12345"
+            header = f"{expected_trace}/{input_span}"
+            trace_id, span_id, sampled = self._call_fut(header)
+            self.assertEqual(trace_id, expected_trace)
+            self.assertIsNone(span_id)
+            self.assertEqual(sampled, False)
+
     def test_with_extra_characters(self):
         expected_trace = "12345"
-        expected_span = "67890"
-        header = f"{expected_trace}/{expected_span};abc"
+        input_span = "67890"
+        expected_span = "10932".zfill(16)
+        header = f"{expected_trace}/{input_span};abc"
         trace_id, span_id, sampled = self._call_fut(header)
         self.assertEqual(trace_id, expected_trace)
         self.assertEqual(span_id, expected_span)
@@ -527,8 +548,9 @@ class Test__parse_xcloud_trace(unittest.TestCase):
 
     def test_with_explicit_no_sampled(self):
         expected_trace = "12345"
-        expected_span = "67890"
-        header = f"{expected_trace}/{expected_span};o=0"
+        input_span = "67890"
+        expected_span = "10932".zfill(16)
+        header = f"{expected_trace}/{input_span};o=0"
         trace_id, span_id, sampled = self._call_fut(header)
         self.assertEqual(trace_id, expected_trace)
         self.assertEqual(span_id, expected_span)
@@ -536,8 +558,9 @@ class Test__parse_xcloud_trace(unittest.TestCase):
 
     def test_with__sampled(self):
         expected_trace = "12345"
-        expected_span = "67890"
-        header = f"{expected_trace}/{expected_span};o=1"
+        input_span = "67890"
+        expected_span = "10932".zfill(16)
+        header = f"{expected_trace}/{input_span};o=1"
         trace_id, span_id, sampled = self._call_fut(header)
         self.assertEqual(trace_id, expected_trace)
         self.assertEqual(span_id, expected_span)
diff --git a/tests/unit/handlers/test_handlers.py b/tests/unit/handlers/test_handlers.py
index 535c1f4..14b2e5c 100644
--- a/tests/unit/handlers/test_handlers.py
+++ b/tests/unit/handlers/test_handlers.py
@@ -140,7 +140,7 @@ class TestCloudLoggingFilter(unittest.TestCase):
         self.assertIsNone(record._labels)
         self.assertEqual(record._labels_str, "{}")
 
-    def test_record_with_request(self):
+    def test_record_with_xctc_request(self):
         """
         test filter adds http request data when available
         """
@@ -161,8 +161,9 @@ class TestCloudLoggingFilter(unittest.TestCase):
         expected_path = "http://testserver/123"
         expected_agent = "Mozilla/5.0"
         expected_trace = "123"
-        expected_span = "456"
-        combined_trace = f"{expected_trace}/{expected_span};o=1"
+        input_span = "456"
+        expected_span = "1c8".zfill(16)
+        combined_trace = f"{expected_trace}/{input_span};o=1"
         expected_request = {
             "requestMethod": "GET",
             "requestUrl": expected_path,
diff --git a/tests/unit/handlers/test_structured_log.py b/tests/unit/handlers/test_structured_log.py
index 920ca15..9087587 100644
--- a/tests/unit/handlers/test_structured_log.py
+++ b/tests/unit/handlers/test_structured_log.py
@@ -382,7 +382,7 @@ class TestStructuredLogHandler(unittest.TestCase):
         result = handler.format(record)
         self.assertIn(expected_result, result)
 
-    def test_format_with_request(self):
+    def test_format_with_xctc_request(self):
         import logging
         import json
 
@@ -393,8 +393,9 @@ class TestStructuredLogHandler(unittest.TestCase):
         expected_path = "http://testserver/123"
         expected_agent = "Mozilla/5.0"
         expected_trace = "123"
-        expected_span = "456"
-        trace_header = f"{expected_trace}/{expected_span};o=1"
+        input_span = "456"
+        expected_span = "1c8".zfill(16)
+        trace_header = f"{expected_trace}/{input_span};o=1"
         expected_payload = {
             "logging.googleapis.com/trace": expected_trace,
             "logging.googleapis.com/spanId": expected_span,