diff --git a/litellm/integrations/otel/README.md b/litellm/integrations/otel/README.md index 023caf06d12..d8dfabe23d6 100644 --- a/litellm/integrations/otel/README.md +++ b/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`. diff --git a/litellm/integrations/otel/logger.py b/litellm/integrations/otel/logger.py index bab0d7ec092..0466e00a959 100644 --- a/litellm/integrations/otel/logger.py +++ b/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, ) # ====================================================================== # diff --git a/litellm/integrations/otel/plumbing/context.py b/litellm/integrations/otel/plumbing/context.py index 19243d64c64..9de5c1ac1cb 100644 --- a/litellm/integrations/otel/plumbing/context.py +++ b/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). diff --git a/tests/test_litellm/integrations/otel/test_otel_v2_logger.py b/tests/test_litellm/integrations/otel/test_otel_v2_logger.py index 287f15a7183..00c1343f72e 100644 --- a/tests/test_litellm/integrations/otel/test_otel_v2_logger.py +++ b/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 # --------------------------------------------------------------------------- #