fix(otel): root post-response service spans in their own trace linked to the request (#42826)

* fix(otel): root post-response service spans in their own trace linked to the request

Co-Authored-By: Devin AI <158243242+devin-ai-integration[bot]@users.noreply.github.com>

* refactor(otel): trim service span context docstring

Co-Authored-By: Devin AI <158243242+devin-ai-integration[bot]@users.noreply.github.com>

---------

Co-authored-by: yassin <yassin@berri.ai>
Co-authored-by: Devin AI <158243242+devin-ai-integration[bot]@users.noreply.github.com>

litellm/integrations/otel/README.md

@@ -63,7 +63,24 @@ Spans are named `"{service} {call_type}"` (e.g. `"redis set"`) so repeated calls
 to one service stay distinguishable. Like every other span they parent to the
 **ambient** context, falling back to the threaded `litellm_parent_otel_span` only
 when ambient has no live span; a background job with neither starts its own root
-trace. Caller-supplied `event_metadata` is **sanitized** before it reaches a span
+trace.
+
+**Post-response work is its own trace.** Spend tracking, the response cache write
+and the spend-counter increment all run after the response is on the wire, so they
+add nothing to the request's latency. Parenting them under the (already ended)
+server span stretched the request trace past the request itself, which is what a
+viewer shows as trace duration. `context.resolve_service_span_context` compares
+the call's end time with the resolved parent's end time: a call that finished
+after its parent ended starts a **new root trace** carrying a **span link** back
+to the request span (the `FollowsFrom` relationship of OpenTracing; the default
+`:link` propagation style of the OTel Ruby ActiveJob and Sidekiq
+instrumentations). Identity Baggage still rides along, so the detached span keeps
+its team / key / user attributes. Only an SDK span that has really ended detaches:
+a sampled-out or remote `NonRecordingSpan` is never recording but is still the
+right parent. A call that ended before the server span did stays a child even when
+its `asyncio.create_task`-dispatched hook runs after the response.
+
+Caller-supplied `event_metadata` is **sanitized** before it reaches a span
 (primitives only, no live objects, no secrets/headers, bounded) — see
 `payloads.sanitize_event_metadata`.
 

litellm/integrations/otel/logger.py

@@ -56,8 +56,8 @@ from litellm.integrations.otel.plumbing.context import (
     request_root_http_route,
     request_root_span,
     resolve_mcp_span_context,
-    resolve_parent_context,
     resolve_request_span_context,
+    resolve_service_span_context,
     set_request_baggage,
     set_request_root_span,
 )
@@ -671,14 +671,17 @@ class OpenTelemetryV2(CustomLogger):
         # rides along and the call nests under whatever request phase is active —
         # e.g. a DB lookup under the live ``auth`` span), falling back to the
         # server span the proxy threaded as ``parent_otel_span``. A background
-        # service call has neither, so it starts its own root trace.
-        parent_context: Final = resolve_parent_context(threaded=parent_otel_span)
+        # service call has neither, so it starts its own root trace, as does one
+        # that finished after the request span ended (linked back to it).
+        end_time_ns: Final = to_ns(end_time)
+        parent_context, links = resolve_service_span_context(threaded=parent_otel_span, end_time_ns=end_time_ns)
         return self._emitter.emit(
             role,
             data,
             parent_context=parent_context,
             start_time_ns=to_ns(start_time),
-            end_time_ns=to_ns(end_time),
+            end_time_ns=end_time_ns,
+            links=links,
         )
 
     # ====================================================================== #

litellm/integrations/otel/plumbing/context.py

@@ -9,6 +9,7 @@ from opentelemetry import baggage
 from opentelemetry.context import Context, get_current
 from opentelemetry.sdk.trace import ReadableSpan
 from opentelemetry.trace import (
+    INVALID_SPAN,
     Link,
     NonRecordingSpan,
     Span,
@@ -225,6 +226,28 @@ def resolve_parent_context(threaded: Span | None = None) -> Context:
     return ctx
 
 
+def resolve_service_span_context(
+    threaded: Span | None = None, end_time_ns: int | None = None
+) -> tuple[Context, tuple[Link, ...]]:
+    """Parent context + links for a service/DB span that ended at ``end_time_ns``.
+
+    A call that finished after its parent ended (post-response spend tracking)
+    starts its own root trace with a span link back to the parent instead of
+    stretching the parent's trace. Baggage stays on the returned context.
+    """
+    ctx: Final = resolve_parent_context(threaded)
+    parent: Final = get_current_span(ctx)
+    if not _ended_before(parent, end_time_ns):
+        return ctx, ()
+    return set_span_in_context(INVALID_SPAN, ctx), (Link(parent.get_span_context()),)
+
+
+def _ended_before(span: Span, end_time_ns: int | None) -> bool:
+    if not isinstance(span, ReadableSpan) or span.end_time is None:
+        return False
+    return end_time_ns is None or end_time_ns > span.end_time
+
+
 def resolve_request_span_context() -> Context:
     """The parent context for a request-level span (the LLM call, a guardrail).
 

tests/test_litellm/integrations/otel/test_otel_v2_logger.py

@@ -2001,6 +2001,91 @@ def test_service_span_prefers_ambient_context_over_threaded_parent():
     assert by_name["redis get"].parent.span_id == ambient.get_span_context().span_id
 
 
+_REQUEST_END = 1_000.0
+
+
+def _ended_request_span(logger):
+    """A PROXY_REQUEST span whose response already went out at ``_REQUEST_END``."""
+    server = logger._emitter.start_span(SpanRole.PROXY_REQUEST, LITELLM_PROXY_REQUEST_SPAN_NAME)
+    server.end(end_time=to_ns(_REQUEST_END))
+    return server
+
+
+@pytest.mark.parametrize("parent_source", ["ambient", "threaded"])
+def test_service_call_that_outlives_the_request_roots_its_own_trace_linked_to_the_request(parent_source):
+    """Post-response work (spend tracking, the cache write, the spend-counter
+    increment) finishes after the server span ended, so it did not add to the
+    request's latency. Nesting it under the request would stretch the request
+    trace past the response, so it starts its own trace and keeps the request
+    reachable through a span link, whether the request span is the ambient
+    context or the threaded ``parent_otel_span``."""
+    logger, exporter = _logger()
+    server = _ended_request_span(logger)
+    hook = logger.async_service_success_hook(
+        payload=_ServicePayload("batch_write_to_db", "_PROXY_track_cost_callback"),
+        parent_otel_span=server if parent_source == "threaded" else None,
+        start_time=_REQUEST_END + 0.1,
+        end_time=_REQUEST_END + 0.5,
+    )
+    if parent_source == "ambient":
+        with trace.use_span(server, end_on_exit=False):
+            asyncio.run(hook)
+    else:
+        asyncio.run(hook)
+    by_name = {s.name: s for s in exporter.get_finished_spans()}
+    span = by_name["batch_write_to_db _PROXY_track_cost_callback"]
+    request_ctx = server.get_span_context()
+    assert span.parent is None
+    assert span.context.trace_id != request_ctx.trace_id
+    assert [(link.context.trace_id, link.context.span_id) for link in span.links] == [
+        (request_ctx.trace_id, request_ctx.span_id)
+    ]
+
+
+def test_service_call_that_finished_before_the_response_stays_in_the_request_trace():
+    """The hook is dispatched with ``asyncio.create_task`` and can run after the
+    response went out even though the call itself completed during the request.
+    Its own end time decides: a call that ended before the request span did is
+    request latency and stays a child of the request."""
+    logger, exporter = _logger()
+    server = _ended_request_span(logger)
+    asyncio.run(
+        logger.async_service_success_hook(
+            payload=_ServicePayload("postgres", "get_data"),
+            parent_otel_span=server,
+            start_time=_REQUEST_END - 0.5,
+            end_time=_REQUEST_END - 0.1,
+        )
+    )
+    span = {s.name: s for s in exporter.get_finished_spans()}["postgres get_data"]
+    assert span.parent.span_id == server.get_span_context().span_id
+    assert span.context.trace_id == server.get_span_context().trace_id
+    assert list(span.links) == []
+
+
+def test_service_call_under_a_remote_parent_is_never_detached():
+    """A propagated parent is a ``NonRecordingSpan`` with no end time of its own.
+    Not recording is not the same as ended, so the call stays its child."""
+    from opentelemetry.trace import NonRecordingSpan, SpanContext, TraceFlags
+
+    logger, exporter = _logger()
+    remote = NonRecordingSpan(
+        SpanContext(trace_id=0xABC, span_id=0x123, is_remote=True, trace_flags=TraceFlags(TraceFlags.SAMPLED))
+    )
+    asyncio.run(
+        logger.async_service_success_hook(
+            payload=_ServicePayload("redis", "get"),
+            parent_otel_span=remote,
+            start_time=_REQUEST_END + 0.1,
+            end_time=_REQUEST_END + 0.5,
+        )
+    )
+    span = {s.name: s for s in exporter.get_finished_spans()}["redis get"]
+    assert span.parent.span_id == 0x123
+    assert span.context.trace_id == 0xABC
+    assert list(span.links) == []
+
+
 # --------------------------------------------------------------------------- #
 #  Proxy SERVER span lifecycle
 # --------------------------------------------------------------------------- #