Fix negative duration on aws.apigateway.authorizer span

Author: pablomartinezbernardo

datadog_lambda/tracing.py

@@ -974,19 +974,11 @@ def process_injected_data(event, request_time_epoch_ms, args, tags):
     injected_authorizer_data = get_injected_authorizer_data(event, False)
     if injected_authorizer_data:
         try:
-            start_time_ns = int(
-                injected_authorizer_data.get(Headers.Parent_Span_Finish_Time)
+            start_time_ns = int(injected_authorizer_data.get(Headers.Parent_Span_Finish_Time))
+            integration_latency = int(
+                event["requestContext"]["authorizer"].get("integrationLatency", 0)
             )
-            finish_time_ns = (
-                request_time_epoch_ms
-                + (
-                    int(
-                        event["requestContext"]["authorizer"].get(
-                            "integrationLatency", 0
-                        )
-                    )
-                )
-            ) * 1e6
+            finish_time_ns = max(start_time_ns, (request_time_epoch_ms + integration_latency) * 1e6)
             upstream_authorizer_span = insert_upstream_authorizer_span(
                 args, tags, start_time_ns, finish_time_ns
             )

tests/event_samples/authorizer-request-api-gateway-v1.json

@@ -55,7 +55,7 @@
   "requestContext": {
     "resourceId": "0et54l",
     "authorizer": {
-      "_datadog": "eyJ4LWRhdGFkb2ctdHJhY2UtaWQiOiAiMTM0Nzg3MDU5OTU3OTcyMjEyMDkiLCAieC1kYXRhZG9nLXBhcmVudC1pZCI6ICI4NDcxMjg4MjYzMzg0MjE2ODk2IiwgIngtZGF0YWRvZy1zYW1wbGluZy1wcmlvcml0eSI6ICIxIiwgIngtZGF0YWRvZy1wYXJlbnQtc3Bhbi1maW5pc2gtdGltZSI6IDE2NjMyOTUwMjE4MjcuNTIxLCAieC1kYXRhZG9nLWF1dGhvcml6aW5nLXJlcXVlc3RpZCI6ICJhYmMxMjMifQ==",
+      "_datadog": "eyJ4LWRhdGFkb2ctdHJhY2UtaWQiOiAiMTM0Nzg3MDU5OTU3OTcyMjEyMDkiLCAieC1kYXRhZG9nLXBhcmVudC1pZCI6ICI4NDcxMjg4MjYzMzg0MjE2ODk2IiwgIngtZGF0YWRvZy1zYW1wbGluZy1wcmlvcml0eSI6ICIxIiwgIngtZGF0YWRvZy1wYXJlbnQtc3Bhbi1maW5pc2gtdGltZSI6IDE2NjMyOTUwMjE4Mjc1MjEwMDAsICJ4LWRhdGFkb2ctYXV0aG9yaXppbmctcmVxdWVzdGlkIjogImFiYzEyMyJ9",
       "scope": "this is just a string",
       "principalId": "foo",
       "integrationLatency": 1897

tests/test_tracing.py

@@ -2408,6 +2408,38 @@ def test_create_inferred_span(mock_span_finish, source, expect):
         assert mock_span_finish.call_count == 0
 
 
+@patch("ddtrace.trace.Span.finish", autospec=True)
+def test_authorizer_span_no_negative_duration_when_clock_skew(mock_span_finish):
+    """
+    Simulate the case where requestTimeEpoch + integrationLatency < parentSpanFinishTime
+    (i.e., API Gateway's reported end is before the authorizer lambda's self-reported finish).
+    This 1ms discrepancy would produce a negative duration.
+    """
+    with open(f"{event_samples}authorizer-request-api-gateway-v1.json") as f:
+        event = json.load(f)
+
+    authorizer_ctx = json.loads(
+        base64.b64decode(event["requestContext"]["authorizer"]["_datadog"])
+    )
+    parent_finish_time_ns = authorizer_ctx["x-datadog-parent-span-finish-time"]
+    request_time_epoch_ms = event["requestContext"]["requestTimeEpoch"]
+    # Set integrationLatency 1ms below the parent span's finish time to simulate clock skew.
+    event["requestContext"]["authorizer"]["integrationLatency"] = (
+        parent_finish_time_ns // 1_000_000 - request_time_epoch_ms - 1
+    )
+
+    ctx = get_mock_context(aws_request_id="123")
+    create_inferred_span(event, ctx)
+
+    args = mock_span_finish.call_args_list[0].args
+    authorizer_span, finish_time = args[0], args[1]
+
+    assert finish_time >= authorizer_span.start, (
+        f"Authorizer span has negative duration: "
+        f"finish_time={finish_time} < start={authorizer_span.start}"
+    )
+
+
 class TestInferredSpans(unittest.TestCase):
     @patch("datadog_lambda.tracing.submit_errors_metric")
     def test_mark_trace_as_error_for_5xx_responses_getting_400_response_code(