Test/uv 16309 span flush race + fix - #1901
TeodorEscuUiPath wants to merge 9 commits into
Conversation
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]>
_get_and_clear_execution_data() read ExecutionSpanExporter.get_spans() without first flushing the batch span processor. The flush triggered by the root execution span ending only exports spans whose on_end() already fired by that moment, so a tool-call span finishing a beat later (e.g. a detached background task) could still be queued, unexported, and missing from AgentRunHistory when the evaluator reads the trace (UV-16309). Force a flush immediately before the read so every span that has ended by then is guaranteed to be exported first. See UV-16309 and the repro test in test/uv-16309-span-flush-race (test_execution_span_race.py). Co-Authored-By: Claude Sonnet 5 <[email protected]>
There was a problem hiding this comment.
🟡 Changes recommended
The production path lacks direct coverage, late spans may still be missed, and the race test is not deterministic.
Get a fresh assessment by requesting another Copilot review.
Pull request overview
This PR addresses intermittent missing tool-call spans in AgentRunHistory by flushing OpenTelemetry spans before collecting execution data.
Changes:
- Adds OpenTelemetry race reproduction tests.
- Flushes spans before reading and clearing execution data.
File summaries
| File | Description |
|---|---|
packages/uipath/tests/cli/eval/test_execution_span_race.py |
Adds race and regression tests for span export behavior. |
packages/uipath/src/uipath/eval/runtime/runtime.py |
Flushes spans before evaluation data collection. |
Review details
Suppressed comments (3)
packages/uipath/src/uipath/eval/runtime/runtime.py:979
- This flush is only a snapshot barrier:
BatchSpanProcessor.force_flush()drains spans already queued when it runs. If the detached task described above ends after this call, itson_end()queues the span after the flush, and the followingclear()can discard the execution's data without another flush. Please synchronize with or await execution-owned background tasks (or otherwise wait for their spans) before reading and clearing; this line alone does not close that race.
self.trace_manager.flush_spans()
packages/uipath/tests/cli/eval/test_execution_span_race.py:97
- These tests call
processor.force_flush()directly and never exercise_get_and_clear_execution_data(), so they would still pass if the newself.trace_manager.flush_spans()line were removed. Add a test throughUiPathEvalRuntime(or a focused test of this method) that verifies the production read/clear path flushes the processor beforeget_spans().
processor.force_flush()
spans_at_read_time = exporter.get_spans(EXECUTION_ID)
assert {s.name for s in spans_at_read_time} == {"root", "tool_call"}
packages/uipath/tests/cli/eval/test_execution_span_race.py:123
input.valueis an OpenTelemetry span attribute, and dict values are not valid attribute values; the SDK drops this field and logs an invalid-attribute warning. That makes the real-OTel reproduction noisy and loses the tool arguments from the history. Encode the value as a string, as the other evaluator span tests do.
"input.value": {"query": "uipath"},
- Files reviewed: 2/2 changed files
- Comments generated: 2
- Review effort level: Lite
💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.
| # (e.g. a detached background task) would otherwise still be sitting | ||
| # in the batch processor's queue and be silently missing from | ||
| # AgentRunHistory (UV-16309). | ||
| self.trace_manager.flush_spans() |
There was a problem hiding this comment.
Agreed — added test_get_and_clear_execution_data_flushes_before_reading in 7552722. It builds the same trace_manager/span_exporter/span_collector/logs_exporter wiring UiPathEvalRuntime.__init__ sets up, then calls the real _get_and_clear_execution_data (unbound, via the class, against a duck-typed self). I verified it directly: temporarily removed the flush_spans() line locally, confirmed this new test fails ({'root'} == {'root', 'tool_call'}), then restored the line and confirmed it passes again.
… called trace_to_str() only ever renders spans carrying tool.name, so a run where the agent answered in plain text and made zero tool calls produced an empty AgentRunHistory - not because nothing happened, but because trace_to_str had nothing tool-shaped to render. This hid the agent's real final answer from both trajectory evaluators, matching UV-16309's "AgentRunHistory omits the agent's own text responses, causing false 0s (empty) or unearned high scores (non-empty)" description. Both LegacyTrajectoryEvaluator and LLMJudgeTrajectoryEvaluator (via BaseLLMTrajectoryEvaluator) now append WorkloadExecution.workload_output - the agent's actual final answer, independent of the trace - whenever it's non-empty, so the judge always sees what the agent answered. Co-Authored-By: Claude Sonnet 5 <[email protected]>
Covers the deterministic corner case behind the async span-export race fixed in 611fe7d/1bdff0c3: a run with zero tool-call spans left AgentRunHistory silently empty for both trajectory evaluators, hiding the agent's actual final answer. Verifies both LegacyTrajectoryEvaluator and LLMJudgeTrajectoryEvaluator now fall back to workload_output in that case. Co-Authored-By: Claude Sonnet 5 <[email protected]>
Addresses three points from the Copilot review on this PR: - Encode input.value as a JSON string in the repro test, matching real span attribute constraints (a raw dict is not a valid OTel attribute value and would be silently dropped). - Add test_get_and_clear_execution_data_flushes_before_reading, which exercises the real production method through a fake self carrying the same trace_manager/span_exporter/span_collector/logs_exporter wiring UiPathEvalRuntime.__init__ sets up - unlike the earlier tests, this one fails if flush_spans() were removed from _get_and_clear_execution_data. - Document, in both the test module docstring and the fix's own comment, that the flush is a snapshot barrier: it closes the race for a span that has already ended by read time, but not for one belonging to a task that is still running at that point - there is no handle to await such a task, and closing that fully is a separate, larger change. Co-Authored-By: Claude Sonnet 5 <[email protected]>
…kiness Copilot review comment: ExecutionSpanProcessor is a real BatchSpanProcessor with its own background worker thread, which auto-flushes every 5s by default (or when its queue fills). Tests asserting "not yet exported at this exact moment" could in principle flake if that worker thread woke up and exported on its own between a span ending and the assertion running. Push the processor's schedule delay to 1 hour right after construction so only the explicit force_flush() calls in these tests ever export anything, removing the wall-clock dependency entirely rather than relying on the worker thread simply not winning the race in practice. Co-Authored-By: Claude Sonnet 5 <[email protected]>
🚨 Heads up:
|
There was a problem hiding this comment.
🟡 Changes recommended
Moderate unresolved issues remain in both evaluators and the span-race test.
Get a fresh assessment by requesting another Copilot review.
Review details
Suppressed comments (4)
packages/uipath/src/uipath/eval/evaluators/legacy_trajectory_evaluator.py:152
WorkloadExecution.workload_outputexplicitly allows dictionaries, so{}is a valid falsey final output. This truthiness check omits it from the legacy prompt, leaving a tool-free run without the final response section. Check againstNoneinstead of truthiness to preserve valid falsey outputs.
if workload_output:
packages/uipath/src/uipath/eval/evaluators/legacy_trajectory_evaluator.py:156
- As in the LLM-judge evaluator, this appends
workload_outputwhenever it is truthy, including when the rendered history already contains tool calls. The stated fix is a no-tool fallback, so this silently changes existing legacy trajectory prompts and may duplicate or inflate them for normal tool runs. Please either restrict the append to empty rendered history or clarify and cover the intentional broader contract.
if workload_output:
final_output_section = f"Agent Final Response:\n{workload_output}"
agent_run_history = (
f"{agent_run_history}\n\n{final_output_section}"
if agent_run_history
packages/uipath/src/uipath/eval/evaluators/llm_judge_trajectory_evaluator.py:93
WorkloadExecution.workload_outputexplicitly allows dictionaries, so{}is a valid falsey final output. In the no-tool case this branch skips it and_get_actual_output()still returns an empty string, leaving that valid output absent from the judge prompt. Useis not Noneso the optional parameter'sNonesentinel is distinguished from a falsey result.
if final_output:
packages/uipath/src/uipath/eval/evaluators/llm_judge_trajectory_evaluator.py:97
- The PR description scopes this change as a fallback for runs with no tool-call spans, but this condition appends
workload_outputeven whenhistoryalready contains tool calls. That changes every mixed/tool trajectory prompt (and can duplicate or substantially expand the input) rather than only fixing the empty-history case. Please either gate this on an empty rendered history or explicitly document and test the broader behavior; the correct choice is ambiguous from the stated scope.
if final_output:
final_output_section = f"Agent Final Response:\n{final_output}"
history = (
f"{history}\n\n{final_output_section}"
if history
- Files reviewed: 5/5 changed files
- Comments generated: 1
- Review effort level: Lite
Copilot review comment: test_get_and_clear_execution_data_flushes_before_reading builds its own ExecutionSpanProcessor directly (not via _make_processor()), so it had the same unpinned 5s default background-worker schedule and could in principle auto-export tool_call on its own, passing even with the flush_spans() fix removed. Factor the schedule-pinning into a shared _pin_batch_schedule() helper and apply it in both places. Co-Authored-By: Claude Sonnet 5 <[email protected]>
There was a problem hiding this comment.
🔵 Needs a closer look
The span-race test must shut down its trace manager to prevent leaked processors and worker threads.
Review details
Suppressed comments (1)
packages/uipath/tests/cli/eval/test_execution_span_race.py:200
- This test creates a
UiPathTraceManager, which registers a defaultBatchSpanProcessorand retains both processors in the global delegating processor, but it never shuts them down. The default worker thread therefore remains alive and the old processors stay attached to subsequent tests/jobs, potentially receiving and queuing unrelated spans. Wrap the test body intry/finallyand calltrace_manager.shutdown()so the processors are unregistered and their workers are stopped.
trace_manager = UiPathTraceManager()
span_exporter = ExecutionSpanExporter()
span_collector = ExecutionSpanCollector()
span_processor = ExecutionSpanProcessor(span_exporter, span_collector)
_pin_batch_schedule(span_processor)
trace_manager.add_span_processor(span_processor)
- Files reviewed: 5/5 changed files
- Comments generated: 0 new
- Review effort level: Lite
Copilot review comment (2026-09-17): UiPathTraceManager() registers a default batch span processor on the process-global delegating processor and never unregisters it on its own. The test never called shutdown(), so that processor and its background worker thread leaked into whatever ran next in the same process. Wrap the test body in try/finally and call trace_manager.shutdown(). Co-Authored-By: Claude Sonnet 5 <[email protected]>
🚨 Heads up:
|
There was a problem hiding this comment.
🟡 Changes recommended
Extract legacy evaluator output through the base helper to preserve target_output_key and attachment handling.
Get a fresh assessment by requesting another Copilot review.
Review details
- Files reviewed: 5/5 changed files
- Comments generated: 1
- Review effort level: Lite
| evaluation_prompt = self._create_evaluation_prompt( | ||
| expected_agent_behavior=workload_execution.expected_agent_behavior, | ||
| agent_run_history=workload_execution.workload_trace, | ||
| workload_output=workload_execution.workload_output, |
There was a problem hiding this comment.
Good catch. Fixed in 8dde043 — evaluate() now calls self._get_actual_output(workload_execution) instead of passing workload_execution.workload_output directly, so target_output_key extraction and job-attachment URI resolution both apply before the value reaches AgentRunHistory. Added a test (target_output_key="result", a multi-key output dict) that fails without this fix — it previously leaked the whole output object (including an unrelated key) into the prompt.
…utput() Copilot review comment: evaluate() was passing workload_execution.workload_output straight through, bypassing BaseLegacyEvaluator._get_actual_output() - the existing path that applies target_output_key extraction and resolves job-attachment URIs. A trajectory evaluator configured with a specific target_output_key (e.g. "result") would therefore get the whole output object, or an unresolved attachment URI, spliced into AgentRunHistory instead of the agent's actual selected answer. Added test_legacy_trajectory_evaluate_resolves_target_output_key_for_fallback, verified it fails when evaluate() is reverted to use the raw field directly. Co-Authored-By: Claude Sonnet 5 <[email protected]>
|



Proposed fix for two related intermittent/empty
AgentRunHistorycases.1. Genuine tool calls, empty history (intermittent — the async export race)
ExecutionSpanProcessor.on_end()queues spans, whileExecutionSpanExporter.get_spans()only sees spans flushed throughexport(). The root-span flush can therefore run before a slightly-late tool-call span is queued—for example, when a detached/background task outlivesdelegate.execute()—leaving the completed span missing when_get_and_clear_execution_data()reads the trace. This timing race would explain the intermittent behavior.On
test/uv-16309-span-flush-race:This closes the race for a span that has already ended by read time (the common case). It does not close it for a span belonging to a task that's still running when the flush happens — there's no handle for the runtime to await in that case, and doing so would be a separate, larger change. Documented in the fix's own comment.
2. Zero tool calls, empty history (deterministic — the "no-tool" corner case)
trace_to_str()only ever renders spans carryingtool.name, so a run where the agent answered in plain text and made no tool calls at all produced an emptyAgentRunHistory— not because nothing happened, but because there was nothing tool-shaped to render. This matches the ticket's "AgentRunHistory omits the agent's own text responses, causing false 0s (empty) or unearned high scores (non-empty)" description.LegacyTrajectoryEvaluatorandLLMJudgeTrajectoryEvaluatorfall back toWorkloadExecution.workload_output(the agent's actual final answer, independent of the trace) whenever there were no tool-call spans to render.Review follow-ups
_get_and_clear_execution_data()method directly (verified it fails if the fix line is removed).BatchSpanProcessorworker thread can't introduce flakiness.The local eval suite passes with both fixes. Please verify or challenge the mechanism before relying on it — not yet peer-reviewed, no PR merge intended until then.