Skip to content

Commit 6c3de9e

Browse files
committed
fix(telemetry): correct streaming validation span nesting and cross-task detach
The backend `chat` span opened by stream_with_chunking attaches in the caller task but finishes in the orchestration task that drains the MOT. Detaching its OTel context token from that second task failed (logged by OTel as "Failed to detach context"), and the failed detach left the generation span ambient, so a subsequent validation `chat` span nested under generation instead of being its sibling under stream_with_chunking. Add STREAMING_ORCHESTRATION_START/END hooks fired on the orchestration task. The tracing plugin uses them to re-attach the stream_with_chunking span as that task's ambient context for the drain/validate loop, so mid-stream spans parent correctly. _safe_detach skips a detach that would cross asyncio tasks: within a reattach scope the skip is expected and logged at debug; otherwise the detach runs so OTel surfaces its own error, preceded by a warning naming the mismatch. Add unit coverage for the reattach helpers, the task-identity classification, and both log paths; an integration test asserting both chat spans are siblings under stream_with_chunking and carry no streaming events; and an e2e streaming test. Document the stream_with_chunking span and its hierarchy. Assisted-by: Claude Code Signed-off-by: Alex Bozarth <ajbozart@us.ibm.com>
1 parent 36b20be commit 6c3de9e

10 files changed

Lines changed: 542 additions & 45 deletions

File tree

docs/docs/observability/tracing.md

Lines changed: 33 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -137,6 +137,23 @@ The `action` span:
137137
| `mellea.response` | Model response truncated to 500 characters; recorded only when `MELLEA_TRACES_CONTENT=true` |
138138
| `mellea.response_length` | Length of the model response (always recorded) |
139139

140+
The `stream_with_chunking` span covers one streaming-generation run. It wraps
141+
the backend generation and any per-chunk validation:
142+
143+
| Attribute | Description |
144+
| --------- | ----------- |
145+
| `mellea.has_requirements` | Whether requirements were supplied |
146+
| `mellea.requirement_count` | Number of requirements supplied |
147+
| `mellea.chunking_strategy` | `ChunkingStrategy` class name (e.g., `SentenceChunker`) |
148+
| `mellea.full_text_length` | Length of the accumulated text at completion |
149+
| `gen_ai.request.model` | Model ID, when known |
150+
| `gen_ai.provider.name` | Provider name, when known |
151+
152+
It also records span events through the run: `quick_check` and `chunk` per
153+
validated chunk, `streaming_done` once the stream drains, `full_validation`
154+
after the final `validate()` calls, `error` on an unhandled exception, and
155+
`completed` when the run exits.
156+
140157
### Backend spans (`mellea.backend`)
141158

142159
Backend spans cover individual LLM API calls. They follow the
@@ -189,6 +206,22 @@ session (mellea.application)
189206
[gen_ai.request.model=gpt-4o]
190207
```
191208

209+
In a `stream_with_chunking` run, the backend generation and each per-chunk
210+
validation call nest under the `stream_with_chunking` span as sibling `chat`
211+
spans:
212+
213+
```text
214+
stream_with_chunking (mellea.application)
215+
│ [mellea.chunking_strategy=SentenceChunker]
216+
├── chat (mellea.backend) ← streaming generation
217+
│ [gen_ai.request.model=granite4.1:3b]
218+
└── chat (mellea.backend) ← per-chunk validation
219+
[gen_ai.request.model=granite4.1:3b]
220+
```
221+
222+
The `stream_with_chunking` span itself parents under whatever span is active
223+
when the run starts, or is a root span when none is.
224+
192225
## Reading traces in a typical agent run
193226

194227
When you open a trace in your backend, look for these patterns:

mellea/plugins/hooks/streaming.py

Lines changed: 23 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -67,3 +67,26 @@ class StreamingEndPayload(MelleaBasePayload):
6767
model: str | None = None
6868
provider: str | None = None
6969
full_text_length: int = 0
70+
71+
72+
class StreamingOrchestrationStartPayload(MelleaBasePayload):
73+
"""Payload for `streaming_orchestration_start` — on the orchestration task, before the stream is drained.
74+
75+
Attributes:
76+
streaming_id: UUID correlating with the matching `streaming_start`.
77+
"""
78+
79+
streaming_id: str = ""
80+
81+
82+
class StreamingOrchestrationEndPayload(MelleaBasePayload):
83+
"""Payload for `streaming_orchestration_end` — on the orchestration task, after the stream is drained.
84+
85+
Fires on the same task as `streaming_orchestration_start`.
86+
87+
Attributes:
88+
streaming_id: UUID correlating with the matching
89+
`streaming_orchestration_start`.
90+
"""
91+
92+
streaming_id: str = ""

mellea/plugins/types.py

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -71,6 +71,8 @@ class HookType(StrEnum):
7171
STREAMING_START = "streaming_start"
7272
STREAMING_EVENT = "streaming_event"
7373
STREAMING_END = "streaming_end"
74+
STREAMING_ORCHESTRATION_START = "streaming_orchestration_start"
75+
STREAMING_ORCHESTRATION_END = "streaming_orchestration_end"
7476

7577

7678
# Lazily populated mapping: hook_type -> (payload_class, result_class).
@@ -111,6 +113,8 @@ def _build_hook_registry() -> dict[str, tuple[type, type]]:
111113
from mellea.plugins.hooks.streaming import (
112114
StreamingEndPayload,
113115
StreamingEventPayload,
116+
StreamingOrchestrationEndPayload,
117+
StreamingOrchestrationStartPayload,
114118
StreamingStartPayload,
115119
)
116120
from mellea.plugins.hooks.tool import ToolPostInvokePayload, ToolPreInvokePayload
@@ -169,6 +173,14 @@ def _build_hook_registry() -> dict[str, tuple[type, type]]:
169173
HookType.STREAMING_START.value: (StreamingStartPayload, PluginResult),
170174
HookType.STREAMING_EVENT.value: (StreamingEventPayload, PluginResult),
171175
HookType.STREAMING_END.value: (StreamingEndPayload, PluginResult),
176+
HookType.STREAMING_ORCHESTRATION_START.value: (
177+
StreamingOrchestrationStartPayload,
178+
PluginResult,
179+
),
180+
HookType.STREAMING_ORCHESTRATION_END.value: (
181+
StreamingOrchestrationEndPayload,
182+
PluginResult,
183+
),
172184
}
173185

174186

mellea/stdlib/streaming.py

Lines changed: 22 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -551,6 +551,15 @@ async def _process_chunk(c: str, ci: int) -> bool:
551551
return False
552552

553553
try:
554+
# Inside the try so a cancellation at this await still runs the finally.
555+
if has_plugins(HookType.STREAMING_ORCHESTRATION_START):
556+
from ..plugins.hooks.streaming import StreamingOrchestrationStartPayload
557+
558+
await invoke_hook(
559+
HookType.STREAMING_ORCHESTRATION_START,
560+
StreamingOrchestrationStartPayload(streaming_id=result._streaming_id),
561+
)
562+
554563
while not mot.is_computed():
555564
try:
556565
delta = await mot.astream()
@@ -680,6 +689,19 @@ async def _process_chunk(c: str, ci: int) -> bool:
680689
except BaseException:
681690
pass
682691

692+
# Shielded so a CancelledError from the hook cannot skip the terminal
693+
# queue bookkeeping and _done.set() below.
694+
if has_plugins(HookType.STREAMING_ORCHESTRATION_END):
695+
from ..plugins.hooks.streaming import StreamingOrchestrationEndPayload
696+
697+
try:
698+
await invoke_hook(
699+
HookType.STREAMING_ORCHESTRATION_END,
700+
StreamingOrchestrationEndPayload(streaming_id=result._streaming_id),
701+
)
702+
except BaseException:
703+
pass
704+
683705
completed_ev = CompletedEvent(
684706
success=result.completed, full_text=result.full_text, attempts_used=1
685707
)

mellea/telemetry/tracing.py

Lines changed: 115 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,7 @@
2424

2525
from __future__ import annotations
2626

27+
import asyncio
2728
import os
2829
import warnings
2930
from importlib.metadata import version
@@ -221,7 +222,75 @@ def get_backend_tracer() -> Any:
221222
return _backend_tracer
222223

223224

224-
_in_flight_spans: dict[str, tuple[Span, Token[Context]]] = {}
225+
_in_flight_spans: dict[str, tuple[Span, Token[Context], asyncio.Task[Any] | None]] = {}
226+
227+
# reattach_span() entries, keyed by correlation key: the OTel context token plus
228+
# the task that attached it. Released by release_reattached_span() on that task.
229+
_reattached_tokens: dict[str, tuple[Token[Context], asyncio.Task[Any] | None]] = {}
230+
231+
232+
def _current_task() -> asyncio.Task[Any] | None:
233+
"""Return the running asyncio task, or None when no loop is running."""
234+
try:
235+
return asyncio.current_task()
236+
except RuntimeError:
237+
return None
238+
239+
240+
def _safe_detach(token: Token[Context], attach_task: asyncio.Task[Any] | None) -> None:
241+
"""Detach `token`, suppressing only the cross-task detach we expect and understand.
242+
243+
OTel context tokens are bound to the `contextvars.Context` of the task that
244+
created them, so detaching from a different task fails — OTel catches the
245+
`ValueError` and logs it at ERROR as "Failed to detach context". Most spans
246+
attach and finish on one task and never hit this.
247+
248+
A cross-task detach is suppressed (skipped, since it would only fail) and
249+
logged at debug only when the detaching task holds an open `reattach_span`
250+
scope — the marker that this task knowingly opened a span elsewhere and
251+
expects the mismatch. Any other cross-task detach is left to run so OTel
252+
surfaces its ERROR with a traceback to the real origin; a warning is added
253+
first to name the task mismatch OTel's message omits.
254+
255+
Example:
256+
Under `stream_with_chunking` the backend `chat` span attaches in the
257+
caller task but finishes in the orchestration task that drains the MOT.
258+
To keep that span's `chat` children nesting correctly, the orchestration
259+
task re-attaches the streaming span for the duration of the drain
260+
(`reattach_span` / `release_reattached_span`). The cross-task `chat`
261+
detach that then happens within that scope is the expected, suppressed
262+
case.
263+
264+
Note:
265+
The reattach scope is an *incomplete* proxy for "expected". It holds for
266+
streaming because that case both needs sibling-nesting protection (so it
267+
reattaches) and has an expected cross-task detach. A future case with the
268+
same open-in-parent / close-in-child shape but no siblings to protect
269+
would not reattach, so its equally-expected cross-task detach falls
270+
through to the warn-and-detach path. That is harmless (the detach only
271+
fails, and the task ends right after, so nothing leaks); the warning is
272+
the signal that the new use needs its own way to mark the detach expected.
273+
274+
Args:
275+
token: The OTel context token returned by the matching `attach`.
276+
attach_task: The task that performed the `attach`, or None if it was
277+
attached outside any running task.
278+
"""
279+
current = _current_task()
280+
if attach_task is not None and current is not attach_task:
281+
from mellea.core.utils import MelleaLogger
282+
283+
if any(task is current for _, task in _reattached_tokens.values()):
284+
MelleaLogger.get_logger().debug(
285+
"Skipped expected cross-task OTel context detach within a "
286+
"reattached-span scope."
287+
)
288+
return
289+
MelleaLogger.get_logger().warning(
290+
"Detaching an OTel context token across asyncio tasks; the span's "
291+
"attach and detach ran on different tasks. OTel will log the failure."
292+
)
293+
otel_context.detach(token)
225294

226295

227296
def start_backend_span(
@@ -286,7 +355,7 @@ def start_backend_span(
286355
set_conversation_id(span)
287356

288357
token = otel_context.attach(trace.set_span_in_context(span))
289-
_in_flight_spans[generation_id] = (span, token)
358+
_in_flight_spans[generation_id] = (span, token, _current_task())
290359
return span
291360

292361

@@ -321,7 +390,7 @@ def finish_backend_span_success(
321390
entry = _in_flight_spans.pop(generation_id, None)
322391
if entry is None:
323392
return
324-
span, token = entry
393+
span, token, attach_task = entry
325394
try:
326395
if gen is not None:
327396
set_request_attrs(span, gen, operation)
@@ -330,7 +399,7 @@ def finish_backend_span_success(
330399
if mot is not None and gen is not None:
331400
set_mellea_attrs(span, mot, gen)
332401
finally:
333-
otel_context.detach(token)
402+
_safe_detach(token, attach_task)
334403
span.end()
335404

336405

@@ -355,15 +424,15 @@ def finish_backend_span_error(
355424
entry = _in_flight_spans.pop(generation_id, None)
356425
if entry is None:
357426
return
358-
span, token = entry
427+
span, token, attach_task = entry
359428
try:
360429
if gen is not None:
361430
set_request_attrs(span, gen, operation)
362431
span.record_exception(exception)
363432
span.set_status(trace.Status(trace.StatusCode.ERROR, str(exception)))
364433
span.set_attribute("error.type", type(exception).__name__)
365434
finally:
366-
otel_context.detach(token)
435+
_safe_detach(token, attach_task)
367436
span.end()
368437

369438

@@ -392,7 +461,7 @@ def _start_application_span(
392461
set_attribute_safe(span, k, v)
393462

394463
token = otel_context.attach(trace.set_span_in_context(span))
395-
_in_flight_spans[key] = (span, token)
464+
_in_flight_spans[key] = (span, token, _current_task())
396465
return span
397466

398467

@@ -414,13 +483,13 @@ def _finish_application_span_success(
414483
entry = _in_flight_spans.pop(key, None)
415484
if entry is None:
416485
return
417-
span, token = entry
486+
span, token, attach_task = entry
418487
try:
419488
if extra_attributes:
420489
for k, v in extra_attributes.items():
421490
set_attribute_safe(span, k, v)
422491
finally:
423-
otel_context.detach(token)
492+
_safe_detach(token, attach_task)
424493
span.end()
425494

426495

@@ -448,7 +517,7 @@ def _finish_application_span_error(
448517
entry = _in_flight_spans.pop(key, None)
449518
if entry is None:
450519
return
451-
span, token = entry
520+
span, token, attach_task = entry
452521
try:
453522
if extra_attributes:
454523
for k, v in extra_attributes.items():
@@ -460,7 +529,7 @@ def _finish_application_span_error(
460529
else:
461530
span.set_status(trace.Status(trace.StatusCode.ERROR, description or ""))
462531
finally:
463-
otel_context.detach(token)
532+
_safe_detach(token, attach_task)
464533
span.end()
465534

466535

@@ -697,11 +766,45 @@ def add_streaming_event(
697766
entry = _in_flight_spans.get(streaming_id)
698767
if entry is None:
699768
return
700-
span, _ = entry
769+
span = entry[0]
701770
filtered = {k: v for k, v in attributes.items() if v is not None}
702771
span.add_event(event_name, filtered)
703772

704773

774+
def reattach_span(key: str) -> None:
775+
"""Make the in-flight span `key` the current task's ambient context.
776+
777+
Spans opened by later work on this task then parent under it. Paired with
778+
`release_reattached_span()`, which must run on the same task. No-op when the
779+
span is not in flight. See `_safe_detach` for how this scope is used to
780+
classify the cross-task detach it enables.
781+
782+
Args:
783+
key: Correlation key of an in-flight span (the key it was stashed under).
784+
"""
785+
entry = _in_flight_spans.get(key)
786+
if entry is None:
787+
return
788+
span = entry[0]
789+
token = otel_context.attach(trace.set_span_in_context(span))
790+
_reattached_tokens[key] = (token, _current_task())
791+
792+
793+
def release_reattached_span(key: str) -> None:
794+
"""Release a reattached span from a matching `reattach_span()` call.
795+
796+
Must run on the same task that called `reattach_span()`. No-op when no token
797+
is stored.
798+
799+
Args:
800+
key: Correlation key from the matching `reattach_span()` call.
801+
"""
802+
entry = _reattached_tokens.pop(key, None)
803+
if entry is not None:
804+
token, _ = entry
805+
otel_context.detach(token)
806+
807+
705808
def finish_streaming_span(
706809
streaming_id: str,
707810
*,

0 commit comments

Comments
 (0)