fix: start each request from its own OTEL trace and log context - #450

Applicable issues

Workaround for the bug in asyncio: python/cpython#141158

It isn't needed when either of the following holds:

1. Python>=3.15: that's where the original asyncio is fixed
2. uvicorn 0.39.0 – 0.44: resetting of context vars was fixed there: explicitly start ASGI run with empty context Kludex/uvicorn#2742
3. uvicorn >= 0.45: now the resetting requires explicit --reset-contextvars CLI option: Add --reset-contextvars flag to isolate ASGI request context Kludex/uvicorn#2912

Supersedes the PR: #448

Description of changes

The symptom

Requests handled by an SDK app can be recorded under another request's trace, while the real
caller's trace ends up with no server span at all. Seen in production as a Core trace with a
client span to an adapter and nothing beneath it, and an earlier Core trace accumulating adapter
requests it never made, for other deployments, seconds or minutes later.

The same inherited state also mislabels logs: a line emitted before routing can name the previous
request's deployment.

What is actually happening

A request's task can start with the contextvars of an earlier request on the same connection.
Under uvicorn on the asyncio event loop this is deterministic once a request body exceeds
uvicorn's HIGH_WATER_LIMIT of 65536 bytes:

1. the oversized body makes handle_events call flow.pause_reading(), dropping the socket reader;
2. the request's own task reads the body, so RequestResponseCycle.receive calls
   flow.resume_reading() → transport.resume_reading() → loop._add_reader(fd, _read_ready);
3. _add_reader builds events.Handle(callback, args, loop, context=None), and None means
   contextvars.copy_context() at that moment — so the connection's read callback is now bound
   to a snapshot of that request's context, for the rest of the connection's life;
4. every later _read_ready → handle_events → loop.create_task(cycle.run_asgi(app)) therefore
   runs in that context, and each new request task copies it.

Nothing is shared or overwritten between requests — only the value a task starts with is wrong.
uvloop is unaffected, since its transports never go through loop._add_reader.

Two consequences follow, one per consumer of the inherited context.

Trace context. opentelemetry.instrumentation.asgi extracts traceparent only when no span is
current (_start_internal_or_server_span):

if trace.get_current_span() is trace.INVALID_SPAN:
    ctx = extract(context_carrier, getter=context_getter)   # not reached
    span_kind = trace.SpanKind.SERVER
else:
    ctx = context.get_current()      # traceparent dropped silently
    span_kind = trace.SpanKind.INTERNAL

With a span inherited from step 4, the header is discarded without a log line and the request is
adopted by the leftover span as INTERNAL. Because the request's span is then itself in the
foreign trace, the next request inherits that, and the whole connection collapses into one trace.
Log records follow along — LoggingInstrumentor fills otelTraceID from get_current_span() at
emit time.

Log deployment id. deployment_id feeds the […] log prefix and is resolved from the
headers/path by _v1_dispatcher / _parse_request before from_request reads the body — i.e.
before step 2 — so it is part of the captured snapshot. Anything a request logs before its handler
runs reads the previous request's deployment: DisconnectMiddleware._log_client_disconnect on an
early disconnect, and validation errors raised before parsing.

The first request on each connection is always correct, which is why it looked intermittent: it
tracks connection reuse and body size, not load.

The fix

Reset both at DIALApp.__call__. That is the ASGI callable uvicorn invokes, so it sits outside the
entire middleware stack — including OpenTelemetryMiddleware, which FastAPIInstrumentor installs
outermost by replacing build_middleware_stack. app.add_middleware(...) would land inside it
and be too late.

• aidial_sdk/telemetry/_context.py (new) — reset_trace_context(), a context manager that
  attaches an empty Context for the duration of the call.
• aidial_sdk/utils/logging.py — reset_log_context(), clearing the inherited deployment id.
• aidial_sdk/application.py — DIALApp.__call__ calls both. _reset_otel_context is
  nullcontext by default and configure_telemetry swaps in reset_trace_context, so the trace
  reset costs nothing when telemetry is off. The log reset is unconditional, since the log prefix
  exists either way.

Neither reset is restored on the way out, deliberately: this task's context is the one the next
request may snapshot, so restoring would put the stale value straight back where it leaks from.

Compared with #448 this drops the build_middleware_stack monkeypatch (and its # type: ignore
and ordering constraint), leaves aidial_sdk/telemetry/init.py untouched, and additionally covers
the log deployment id.

Note on behaviour

An app run in-process inside an existing span — mounted under another instrumented app, or
TestClient called inside a span — now starts a fresh trace from its headers instead of becoming
an in-process child. That is the correct server-boundary semantics, but it is a change.

Alternative considered

uvicorn --reset-contextvars fixes the whole class at the source and would make
reset_log_context() redundant. It is not used here because it needs uvicorn >= 0.45 while
pyproject.toml allows >=0.19, it is opt-in and off by default, and adapters own their own
uvicorn command line — so it cannot be a library guarantee. It is worth adopting as a deployment
standard in addition to this change; note it also severs the PyContext ancestry that
OpenTelemetry's eBPF instrumentation follows, which the reset here does not.

Tests

tests/test_request_context.py:

• test_each_request_is_traced_under_its_own_traceparent — drives a real DIALApp through a real
  uvicorn over one keep-alive connection with two >64 KiB requests carrying distinct
  traceparents, and asserts one SERVER span per request in its own caller's trace. Without the
  reset it fails with request feat: something #2 having no SERVER span at all. This covers the wiring as well as
  the logic — a structural assertion about middleware order would not.
• test_telemetry_installs_the_trace_context_reset — locks the configure_telemetry wiring.
• test_deployment_id_is_not_inherited_from_another_request — a request must not see an earlier
  request's deployment id on entry.

Full suite: 1580 passed, 8 skipped. ruff and pyright clean.

Checklist

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.

🤖 Generated with Claude Code