Repository navigation
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]>
|
mjnovice
left a comment
There was a problem hiding this comment.
Thanks for the thorough write-up and the repro tests. Summary of where I landed after tracing the call order and running the branch locally:
Part 2 (no-tool-call / agent text missing from AgentRunHistory) is the right fix. trace_to_str only renders tool.name spans and neither trajectory prompt has an output placeholder, so the agent's own words never reach the judge. Appending the final output in every case matches the amended root cause on the ticket. Two changes I'd like before merge: render conversational output as text instead of str(dict), and use the same renderer in both evaluators. Details and a proposed helper inline.
Part 1 (span flush "race") is redundant in production. UiPathExecutionRuntime.execute() already flushes in its finally after the delegate returns, and the eval runtime reads synchronously right after that await. The new flush has nothing left to catch, and the ticket's 34-case dataset contains no "tool calls happened but history empty" case. I'd remove that block and its tests, or at least reword the comment so it does not claim to fix UV-16309.
Verified locally on 8dde0433: the 7 new tests pass, tests/evaluators + tests/cli/eval pass (452 tests), and removing the flush line does fail test_get_and_clear_execution_data_flushes_before_reading, but only because that test omits the execute() finally-flush (comment inline).
Minor: branch is 10 commits behind main; #1896 touched runtime.py in an unrelated region, so a rebase should be clean.
| # Force a flush right before reading: the flush triggered by the root | ||
| # execution span ending only exports spans whose on_end() had already | ||
| # fired by that moment. A tool-call span that finishes a beat later | ||
| # (e.g. a short-lived background task) would otherwise still be | ||
| # sitting in the batch processor's queue and be silently missing from | ||
| # AgentRunHistory (UV-16309). This is a snapshot barrier, not a full | ||
| # closure: a span belonging to a task that is still running (hasn't | ||
| # called on_end() yet) when this flush runs is still missed - closing | ||
| # that would require the runtime to track and await such tasks before | ||
| # this point, which is out of scope for this fix. | ||
| self.trace_manager.flush_spans() |
There was a problem hiding this comment.
This flush cannot catch anything the read would otherwise miss, because production already flushes twice between the last span ending and this read:
UiPathTraceManager.start_execution_spanflushes in itsfinallywhen the root span closes.UiPathExecutionRuntime.execute()(uipath-runtime 0.13.5,uipath/runtime/base.py:186) flushes again in its ownfinallybefore returning.
The eval runtime then calls _get_and_clear_execution_data right after await execution_runtime.execute(...) returns (line ~1063 → ~1084) with no await in between, so no coroutine can end a span in that window. A span that has already ended is exported by flush (2); a span that has not ended is missed with or without this line. The only remaining gap is a span ending on another OS thread in the microseconds between those two statements, and this flush does not close that either.
The Jira data points the same way: none of the 34 cases in UV-16309 is "tool calls happened, history empty". The two tool-call cases had 7.4k-char histories that were missing the agent's text, which is the trace_to_str issue Part 2 fixes.
I'd drop this block and test_execution_span_race.py, and let the PR stand on Part 2. If you prefer to keep it as belt-and-braces, please reword the comment so it does not claim to fix UV-16309 or an observed race.
| # Force a flush right before reading: the flush triggered by the root | |
| # execution span ending only exports spans whose on_end() had already | |
| # fired by that moment. A tool-call span that finishes a beat later | |
| # (e.g. a short-lived background task) would otherwise still be | |
| # sitting in the batch processor's queue and be silently missing from | |
| # AgentRunHistory (UV-16309). This is a snapshot barrier, not a full | |
| # closure: a span belonging to a task that is still running (hasn't | |
| # called on_end() yet) when this flush runs is still missed - closing | |
| # that would require the runtime to track and await such tasks before | |
| # this point, which is out of scope for this fix. | |
| self.trace_manager.flush_spans() |
| history = trace_to_str(workload_execution.workload_trace) | ||
| final_output = workload_execution.workload_output | ||
| if final_output: | ||
| final_output_section = f"Agent Final Response:\n{final_output}" |
There was a problem hiding this comment.
For conversational agents workload_output is {"uipath__agent_response_messages": [...]}, so f"...{final_output}" hands the judge a Python repr of nested dicts with the actual answer buried under contentParts[].data.inline, next to ids, timestamps and mime types. That is the exact case UV-16309 is about (the low-code conversational agent), so it is worth rendering the text properly. For non-conversational agents str(dict) is single-quoted repr rather than JSON, which is also harder for the model to read.
Suggest a small renderer in _helpers/evaluators_helpers.py and using it here and in the legacy evaluator (so both trajectory evaluators produce the same section):
# packages/uipath/src/uipath/eval/_helpers/evaluators_helpers.py
AGENT_RESPONSE_MESSAGES_KEY = "uipath__agent_response_messages"
def render_agent_output(output: dict[str, Any] | str) -> str:
"""Render the workload output for an LLM-judge prompt.
Conversational agents return ``{"uipath__agent_response_messages": [...]}``
where the text sits under ``contentParts[].data.inline``. Surface that text
(and any tool calls) instead of the raw dict repr; anything else is emitted
as indented JSON.
"""
if isinstance(output, str):
return output
messages = output.get(AGENT_RESPONSE_MESSAGES_KEY)
if not isinstance(messages, list):
return json.dumps(output, indent=2, default=str)
lines: list[str] = []
for message in messages:
if not isinstance(message, dict):
continue
role = message.get("role", "assistant")
parts = message.get("contentParts") or message.get("content_parts") or []
for part in parts:
data = part.get("data") if isinstance(part, dict) else None
text = data.get("inline") if isinstance(data, dict) else None
if text:
lines.append(f"[{role}] {text}")
calls = message.get("toolCalls") or message.get("tool_calls") or []
for call in calls:
if isinstance(call, dict):
args = json.dumps(call.get("input"), default=str)
lines.append(f"[{role}] Tool call {call.get('name')}: {args}")
rest = {k: v for k, v in output.items() if k != AGENT_RESPONSE_MESSAGES_KEY}
if rest:
lines.append(json.dumps(rest, indent=2, default=str))
return "\n".join(lines) or json.dumps(output, indent=2, default=str)Then at this call site:
| final_output_section = f"Agent Final Response:\n{final_output}" | |
| final_output_section = ( | |
| f"Agent Final Response:\n{render_agent_output(final_output)}" | |
| ) |
(plus from .._helpers.evaluators_helpers import render_agent_output, trace_to_str at the top). Handles both camelCase aliases and snake_case field names since the runtime does model_dump() without by_alias for pydantic outputs but passes dicts through untouched. A test with a realistic uipath__agent_response_messages payload asserting the assistant text appears verbatim would pin this down.
| # agent genuinely answered. Append the actual final output so the | ||
| # judge always sees what the agent answered (UV-16309). | ||
| if workload_output: | ||
| final_output_section = f"Agent Final Response:\n{workload_output}" |
There was a problem hiding this comment.
Same rendering issue as in llm_judge_trajectory_evaluator.py (see that comment for the proposed render_agent_output helper). Using the same helper here keeps the two trajectory evaluators consistent, which they currently are not: this one resolves target_output_key and job-attachment URIs via _get_actual_output, the non-legacy one appends the raw field.
| final_output_section = f"Agent Final Response:\n{workload_output}" | |
| final_output_section = ( | |
| f"Agent Final Response:\n{render_agent_output(workload_output)}" | |
| ) |
| schedule delay far beyond any test's runtime so only an explicit | ||
| `force_flush()`/`flush_spans()` call ever exports anything. | ||
| """ | ||
| batch_processor = processor._batch_processor |
There was a problem hiding this comment.
_batch_processor, _schedule_delay_millis and _schedule_delay are private attributes of the OpenTelemetry SDK's BatchSpanProcessor (the _batch_processor delegate only exists in newer SDK versions). An SDK bump will silently turn this into an AttributeError or, worse, a no-op that lets the worker thread export and makes the "not yet exported" assertions flaky again. If this file stays, prefer constructing the processor with schedule_delay_millis=3_600_000 via the public constructor argument (UiPathExecutionBatchTraceProcessor forwards to BatchSpanProcessor.__init__) instead of patching internals after the fact.
| pass | ||
| # Root span's own flush (mirrors start_execution_span's finally block) | ||
| # happens before the late tool call below - only the tool call is at risk. | ||
| trace_manager.flush_spans() |
There was a problem hiding this comment.
This test reproduces the missing span only because it omits the flush that production performs after the tool span. In UiPathExecutionRuntime.execute() the finally: self.trace_manager.flush_spans() runs after delegate.execute() returns, i.e. after any span that ended inside the awaited call, and only then does the eval runtime read. To model the real order, add a second trace_manager.flush_spans() after the tool_call span block below and before calling _get_and_clear_execution_data. With that, the test passes with or without the new flush line, which is the point I'm making on runtime.py: the line is not what closes the gap.



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.