From 81ceae76afdddb7dde7167b09280b171e9a78b64 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Pablo=20Marti=CC=81nez=20Bernardo?= Date: Mon, 6 Apr 2026 11:41:46 +0200 Subject: [PATCH 1/2] Fix negative duration on aws.apigateway.authorizer span --- datadog_lambda/tracing.py | 16 +++------- .../authorizer-request-api-gateway-v1.json | 2 +- tests/test_tracing.py | 32 +++++++++++++++++++ 3 files changed, 37 insertions(+), 13 deletions(-) diff --git a/datadog_lambda/tracing.py b/datadog_lambda/tracing.py index da4c9dd33..2f098ed3f 100644 --- a/datadog_lambda/tracing.py +++ b/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 ) diff --git a/tests/event_samples/authorizer-request-api-gateway-v1.json b/tests/event_samples/authorizer-request-api-gateway-v1.json index d14b7aa01..7496c5ed2 100644 --- a/tests/event_samples/authorizer-request-api-gateway-v1.json +++ b/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 diff --git a/tests/test_tracing.py b/tests/test_tracing.py index ec78265a6..3a3d9e895 100644 --- a/tests/test_tracing.py +++ b/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( From 297ab7800c91a18a25c59b280108dbb7fa2e01d3 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Pablo=20Marti=CC=81nez=20Bernardo?= Date: Mon, 6 Apr 2026 11:46:14 +0200 Subject: [PATCH 2/2] Linter --- datadog_lambda/tracing.py | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/datadog_lambda/tracing.py b/datadog_lambda/tracing.py index 2f098ed3f..3c7d9f115 100644 --- a/datadog_lambda/tracing.py +++ b/datadog_lambda/tracing.py @@ -974,11 +974,15 @@ 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 = max(start_time_ns, (request_time_epoch_ms + integration_latency) * 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 )