"Failed to detach context" (Token created in a different Context) logged as ERROR when caller stops runner.run_async() early
- 主要言語
- Python
- スター
- 21.5k
- フォーク
- 4k
- 平均マージ
- 1日 14時間
- マージ済み PR(30日)
- 37
説明
## Description
When a caller stops iterating `Runner.run_async()` **early** (a `break`/`return` as soon as the final response arrives — a very common pattern), an `ERROR`-level log is emitted on every invocation:
```
ERROR opentelemetry.context Failed to detach context
Traceback (most recent call last):
File ".../opentelemetry/trace/__init__.py", line 589, in use_span
yield span
File ".../opentelemetry/trace/__init__.py", line 508, in start_as_current_span
yield span
File ".../google/adk/runners.py", line 572, in _run_node_async
yield event
GeneratorExit
During handling of the above exception, another exception occurred:
File ".../opentelemetry/context/__init__.py", line 143, in detach
_RUNTIME_CONTEXT.detach(token)
File ".../opentelemetry/context/contextvars_context.py", line 42, in detach
self._current_context.reset(token)
ValueError: was created in a different Context
```
Functionally the invocation completes correctly (OpenTelemetry swallows the exception inside `detach()` and only logs it), so this is **cosmetic** — but it is logged at `ERROR` level on **every** early-terminated run, which creates significant log noise and false-positive error-rate alerts (e.g. Datadog).
## Environment
- `google-adk`: observed in production on `2.3.0`; the relevant structure is unchanged through `v2.6.1` (verified by source inspection)
- Python 3.13 (also reproduces on 3.9–3.12)
- FastAPI + uvicorn (`--workers 2`), run under `ddtrace-run` (Datadog APM); logs shipped to Datadog
- `OTEL_SDK_DISABLED=true` is set
- `opentelemetry-api` / `-sdk`: current 1.x (its `context.detach()` wraps the failure in `try/except` and calls `logger.exception("Failed to detach context")`)
Note: setting `OTEL_SDK_DISABLED=true` does **not** suppress this — that flag disables the SDK (export/sampling), but `context.attach()/detach()` live in the context **API** and keep running. Running under `ddtrace-run` (which proxies the OTel context) makes the cross-context mismatch surface reliably.
## Root cause
`runners._run_node_async` is an `async` generator whose event-yielding loop is wrapped in an OpenTelemetry current-span context manager:
```python
# runners.py -> telemetry/_instrumentation.record_invocation (schema v1)
with tracer.start_as_current_span("invocation"):
...
async for event in agen:
yield event
```
`start_as_current_span` does `attach()` on entry (creating a contextvars `Token`) and `detach(token)` on exit. In an async generator the `attach()` happens in the execution context where the generator is **resumed to produce a value**. When the caller stops early, the generator is not finalized in that same context — it is closed later by GC / `loop.shutdown_asyncgens()` / a different task, which raises `GeneratorExit` (or `CancelledError`) at the `yield`. The context manager's `__exit__` then calls `detach(token)` in a **different context** than the one where the token was created, which is exactly the situation `contextvars.Token` forbids → `ValueError: was created in a different Context`.
This is the well-known "`start_as_current_span` around an `async` generator" anti-pattern; it only manifests on **early close**, never on full consumption.
## Minimal reproduction (no ADK / API key required)
Reproduces the exact OTel interaction with only `opentelemetry-sdk`:
```python
import asyncio, contextlib, logging
logging.basicConfig(level=logging.ERROR)
from opentelemetry import trace, context as context_api
from opentelemetry.sdk.trace import TracerProvider
trace.set_tracer_provider(TracerProvider())
tracer = trace.get_tracer("adk-repro")
@contextlib.contextmanager
def record_invocation_current(): # current ADK structure
with tracer.start_as_current_span("invocation"):
yield
async def event_queue():
for i in range(10):
await asyncio.sleep(0)
yield i
async def run_node(): # ~ runners._run_node_async
with record_invocation_current():
async for ev in event_queue():
yield ev
async def caller_early_stop():
async for ev in run_node():
if ev == 2:
return # early stop -> generator closed later
# in a different context
asyncio.run(caller_early_stop()) # -> ERROR "Failed to detach context"
```
| Scenario | Current structure | With proposed fix |
|---|---|---|
| Caller stops early (`break`/`return`) | ❌ `Failed to detach context` ERROR | ✅ clean |
| Caller consumes to completion | ✅ clean | ✅ clean (unchanged) |
## Proposed fix (minimal — schema v1 `invocation` span)
Manage the span/context explicitly and **only `detach()` when the generator body completed normally**; skip `detach()` on early close (the token belongs to a different context and the generator's context is discarded anyway). The span is always ended, so trace completeness is preserved.
```diff
--- a/src/google/adk/telemetry/_instrumentation.py
+++ b/src/google/adk/telemetry/_instrumentation.py
@@ def record_invocation(...):
if resolve_schema_version() < SCHEMA_VERSION_SEMCONV_ALIGNED:
- with tracing.tracer.start_as_current_span("invocation"):
- yield
- return
+ # NOTE: this context manager wraps an async generator (runners.
+ # _run_node_async). If the caller stops iterating early, the generator is
+ # finalized (GeneratorExit / CancelledError) in a different execution
+ # context than the one where the span was attached, so an automatic
+ # detach() would raise "Token was created in a different Context" (OTel
+ # swallows it but logs an ERROR). Detach only on normal completion; always
+ # end the span.
+ span = tracing.tracer.start_span("invocation")
+ token = context_api.attach(trace.set_span_in_context(span))
+ completed = False
+ try:
+ yield
+ completed = True
+ finally:
+ if completed:
+ context_api.detach(token)
+ span.end()
+ return
```
(`trace` and `context_api` are already imported in `_instrumentation.py`.)
The same `start_as_current_span`-around-async-generator pattern also exists on the schema v2 path (`node_tracing._use_invoke_workflow_span`) and could get the same treatment, but this issue/PR intentionally scopes to the default (schema v1) `invocation` span that users hit today.
## Workaround (for users, until fixed)
Consume the generator to completion instead of returning early — capture the final response and let the loop end naturally:
```python
final = None
async for event in runner.run_async(...):
if event.is_final_response():
final = event # don't break/return here
# loop ends naturally -> attach/detach occur in the same context, no error
```
## Related (same root cause, different layers)
- #1170 (secondary "Failed to detach context" note during `GeneratorExit`)
- #1028, #949, #860, #501 (context-token detach in Loop/Parallel/AgentTool paths)
Happy to send a PR with the fix + a unit test if this direction looks good.
コントリビューションガイド
評価
この issue はまだ評価されていません。