google / google/adk-python

"Failed to detach context" (Token created in a different Context) logged as ERROR when caller stops runner.run_async() early

Đang mở
#6,559 4 bình luận 0 reaction 2 người được giao Được @rohityan nhận Xem trên GitHub
needs review tracing
Ngôn ngữ chính
Python
Star
21.5k
Fork
4k
Merge trung bình
1 ngày 14 giờ
Pull request đã merge (30 ngày)
37

Mô tả

## 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.

Hướng dẫn đóng góp

Mở hướng dẫn đóng góp

Đánh giá

Issue này chưa được đánh giá.

Nhận issue mới trong hộp thư của bạn

Bản tóm tắt ngắn những issue GitHub phù hợp với người mới.