Skip to content

Commit 611fe7d

Browse files
TeodorEscuUiPathclaude
TeodorEscuUiPath
and
claude
committed
test(eval): reproduce UV-16309 span-export race for AgentRunHistory
ExecutionSpanProcessor is a real OTel BatchSpanProcessor: on_end() only queues a span, export() (which feeds ExecutionSpanExporter.get_spans(), read by trace_to_str() to build AgentRunHistory) only sees spans already flushed. Production flushes when the root execution span ends, but a tool-call span that genuinely finishes a beat later (e.g. a detached background task) is queued but not yet exported at that point - so a read taken before the next flush sees a real, completed tool call as if it never happened. Reproduces the exporter-level race, ties it to trace_to_str() producing an empty AgentRunHistory for a real tool call, and shows a flush immediately before the read closes the race. Co-Authored-By: Claude Sonnet 5 <[email protected]>
1 parent 30f6bec commit 611fe7d

1 file changed

Lines changed: 143 additions & 0 deletions

File tree

‎packages/uipath/tests/cli/eval/test_execution_span_race.py‎

Lines changed: 143 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,143 @@
1+
"""Reproduces the UV-16309 intermittent-empty-AgentRunHistory race.
2+
3+
`ExecutionSpanProcessor` (eval/runtime/_exporters.py) is a real OTel
4+
`BatchSpanProcessor`: `on_end()` only queues a span, it does not export it.
5+
`ExecutionSpanExporter.get_spans()` (read by `trace_to_str()` to build
6+
`AgentRunHistory`) only sees spans that have already reached `export()`.
7+
8+
Production flushes the queue via `UiPathTraceManager.flush_spans()` (called
9+
from `uipath-runtime`'s `UiPathExecutionRuntime.execute()` finally block, and
10+
from `start_execution_span`'s finally block) right as the root execution span
11+
ends. That flush only catches spans whose `on_end()` already fired by that
12+
moment. A tool-call span that legitimately ends *after* the root span (e.g. a
13+
background/detached task finishing a beat late) is queued but not yet
14+
exported, so a read of `get_spans()` taken between "root span ended" and
15+
"next flush" sees a real, completed tool call as if it never happened -
16+
exactly the "history genuinely exists but AgentRunHistory is empty,
17+
intermittently" symptom.
18+
"""
19+
20+
from opentelemetry import trace
21+
from opentelemetry.sdk.trace import TracerProvider
22+
23+
from uipath.eval._execution_context import ExecutionSpanCollector
24+
from uipath.eval._helpers.evaluators_helpers import trace_to_str
25+
from uipath.eval.runtime._exporters import ExecutionSpanExporter, ExecutionSpanProcessor
26+
27+
EXECUTION_ID = "exec-race-1"
28+
29+
30+
def _make_processor() -> tuple[ExecutionSpanProcessor, ExecutionSpanExporter, trace.Tracer]:
31+
exporter = ExecutionSpanExporter()
32+
collector = ExecutionSpanCollector()
33+
processor = ExecutionSpanProcessor(exporter, collector)
34+
35+
provider = TracerProvider()
36+
provider.add_span_processor(processor)
37+
tracer = provider.get_tracer("test")
38+
39+
return processor, exporter, tracer
40+
41+
42+
def test_flush_only_exports_spans_ended_before_it_runs() -> None:
43+
"""A late-ending tool span is invisible to get_spans() until the *next* flush."""
44+
processor, exporter, tracer = _make_processor()
45+
46+
# Root execution span starts and ends (mirrors start_execution_span's `with` block).
47+
with tracer.start_as_current_span(
48+
"root", attributes={"execution.id": EXECUTION_ID}
49+
):
50+
pass
51+
52+
# Mirrors flush_spans() firing right as the root span's context manager exits.
53+
processor.force_flush()
54+
55+
assert [s.name for s in exporter.get_spans(EXECUTION_ID)] == ["root"]
56+
57+
# A tool-call span that genuinely happened, but whose on_end() only fires
58+
# *after* the flush above - e.g. a detached/background task that outlives
59+
# the awaited delegate.execute() call.
60+
with tracer.start_as_current_span(
61+
"tool_call", attributes={"execution.id": EXECUTION_ID, "tool.name": "search"}
62+
):
63+
pass
64+
65+
# This is the moment _get_and_clear_execution_data() reads spans in
66+
# eval/runtime/runtime.py: no flush has happened since the tool span ended.
67+
spans_at_read_time = exporter.get_spans(EXECUTION_ID)
68+
69+
assert [s.name for s in spans_at_read_time] == ["root"], (
70+
"the tool-call span genuinely ended but is not yet exported - "
71+
"trace_to_str() would build an AgentRunHistory missing this real tool call"
72+
)
73+
74+
# A subsequent flush (e.g. one added right before the read) makes it visible.
75+
processor.force_flush()
76+
assert {s.name for s in exporter.get_spans(EXECUTION_ID)} == {"root", "tool_call"}
77+
78+
79+
def test_flush_immediately_before_read_closes_the_race() -> None:
80+
"""Proposed fix: force_flush() right before get_spans() sees every ended span."""
81+
processor, exporter, tracer = _make_processor()
82+
83+
with tracer.start_as_current_span(
84+
"root", attributes={"execution.id": EXECUTION_ID}
85+
):
86+
with tracer.start_as_current_span(
87+
"tool_call",
88+
attributes={"execution.id": EXECUTION_ID, "tool.name": "search"},
89+
):
90+
pass
91+
92+
# A flush right before the read (unlike production today) picks up
93+
# everything that has ended by then, including the tool call.
94+
processor.force_flush()
95+
96+
spans_at_read_time = exporter.get_spans(EXECUTION_ID)
97+
assert {s.name for s in spans_at_read_time} == {"root", "tool_call"}
98+
99+
100+
def test_race_produces_empty_agent_run_history_for_a_real_tool_call() -> None:
101+
"""Ties the exporter-level race to the actual UV-16309 symptom.
102+
103+
trace_to_str() (used to build AgentRunHistory for the trajectory/LLM-judge
104+
evaluators) is handed exactly what get_spans() returns. If the read happens
105+
in the window between the root-span flush and the late tool span's own
106+
flush, the genuinely-completed tool call is silently dropped from the
107+
evaluator prompt - not because it didn't happen, but because it wasn't
108+
exported yet.
109+
"""
110+
processor, exporter, tracer = _make_processor()
111+
112+
with tracer.start_as_current_span(
113+
"root", attributes={"execution.id": EXECUTION_ID}
114+
):
115+
pass
116+
processor.force_flush()
117+
118+
with tracer.start_as_current_span(
119+
"tool_call",
120+
attributes={
121+
"execution.id": EXECUTION_ID,
122+
"tool.name": "search",
123+
"input.value": {"query": "uipath"},
124+
"output.value": "42 results",
125+
},
126+
):
127+
pass
128+
129+
# No flush here - mirrors _get_and_clear_execution_data() reading
130+
# immediately after the delegate returns, with nothing forcing the
131+
# late-ending tool span's export first.
132+
agent_run_history = trace_to_str(exporter.get_spans(EXECUTION_ID))
133+
assert agent_run_history == "", (
134+
"expected the unflushed tool call to be missing from AgentRunHistory, "
135+
"reproducing UV-16309's 'history genuinely exists but comes back empty' case"
136+
)
137+
138+
# With the extra flush (the proposed fix) in place, the same real tool
139+
# call is captured correctly.
140+
processor.force_flush()
141+
agent_run_history_after_flush = trace_to_str(exporter.get_spans(EXECUTION_ID))
142+
assert "Tool: search" in agent_run_history_after_flush
143+
assert "42 results" in agent_run_history_after_flush

0 commit comments

Comments
 (0)