Skip to content

fix(acp): cap how long a pending tool call defers the idle watchdog - #1066

Merged
bingran-you merged 8 commits into
benchflow-ai:mainfrom
Benjamin-eecs:fix-idle-watchdog-pending-grace
Sep 2, 2026
Merged

fix(acp): cap how long a pending tool call defers the idle watchdog#1066
bingran-you merged 8 commits into
benchflow-ai:mainfrom
Benjamin-eecs:fix-idle-watchdog-pending-grace

Conversation

@Benjamin-eecs

@Benjamin-eecs Benjamin-eecs commented Aug 29, 2026

Copy link
Copy Markdown
Contributor

Description

Cap the silent deferral of each pending ACP tool call independently. A call gets PENDING_GRACE_MULTIPLIER (3) x idle_timeout since its own creation or last nonterminal update; streaming progress for that call restarts its grace, while duplicate terminal updates or progress from another call cannot conceal a lost completion.

The grace policy and diagnostics now live in a focused acp/watchdog.py state machine. The async runtime loop is 44 lines and runtime.py is back to 858 lines instead of crossing 1,000.

Motivation and Context

The #1061 stall chain leaves a tool record pending forever when its terminal update is lost, while stderr traffic prevents the transport timeout. Main previously treated any pending call as progress until the multi-hour wall budget. This PR bounds that deferral without killing demonstrably streaming tools.

Expiry raises the existing retryable IdleTimeoutError with additive diagnostics naming all pending calls, the specifically expired calls, the grace, relevant update counts, and update ages.

Behavior change: a call that stays pending and fully silent beyond 3x the idle budget now fails instead of deferring to the wall clock. With the default 600-second idle timeout this is approximately a 30-minute silent cap (plus at most one watchdog poll); legitimate longer silent tools should raise --agent-idle-timeout.

Closes #1061.

Types of changes

  • Bug fix
  • Breaking change: bounded silent pending-call behavior
  • New feature
  • Documentation

Implemented Tasks

  • Track nonterminal progress versions per pending tool call
  • Enforce grace expiry per call, not per session-global update count
  • Ignore repeated terminal noise and updates from other calls
  • Preserve long-running calls that stream in-progress updates
  • Emit truthful, additive timeout diagnostics
  • Extract the watchdog state machine from the ACP runtime loop
  • Add PR-named regression coverage for lost, streaming, unrelated-noise, and diagnostic paths

Validation

  • tests/test_acp.py: 100 passed
  • tests/: 5936 passed, 48 skipped, 7 deselected
  • Ruff format/lint and ty check src/
  • Direct adversarial ACP probe: repeated terminal updates and a different continuously streaming call do not hide the lost pending call
  • Real gemini-3.1-pro-preview Docker and Daytona E2E at the final working tree: reward 1.0 on both backends
  • Artifact validator: Docker 1/1 healthy and Daytona 1/1 healthy, with complete ACP + provider trajectories and training-ready rows

Copilot AI lite review requested due to automatic review settings August 29, 2026 12:25

Copilot AI left a comment

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copilot was unable to review this pull request because the user who requested the review has reached their quota limit.

@devin-ai-integration devin-ai-integration Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Devin Review found 1 potential issue.

Devin Review

Comment thread src/benchflow/acp/runtime.py Outdated
Comment on lines +887 to +890
snapshot = tuple(sorted(session.pending_tool_call_ids()))
if snapshot != pending_snapshot:
pending_snapshot = snapshot
pending_since = now

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🟡 Delayed pending-call grace window

When a tool call appears between polls, cur_count > last_count postpones snapshot tracking until the next poll. The watchdog grants up to two extra poll intervals.

Prompt for agents
In src/benchflow/acp/runtime.py, _prompt_with_idle_watchdog only observes the pending-ID snapshot in the elif branch after activity-count processing. A newly appended tool call increases _activity_count, so the first poll that observes it skips snapshot tracking; pending_since is reset on the following poll instead. Track pending-set transitions on every poll, independently of whether other activity was also detected, while preserving the rule that a pending call only refreshes last_progress during its grace window. Add a regression test where the prompt coroutine creates the pending call after the watchdog starts, rather than pre-populating the session.
Devin Review

Was this helpful? React with 👍 or 👎 to provide feedback.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good catch, fixed: the pending set is now observed every poll, so the grace clock starts on the same poll the call appears.

@JeremyJC67

Copy link
Copy Markdown

The root-cause analysis here is excellent — the four-link chain in the description (lost terminal update, permanent PENDING, unconditional deferral, event-driven heartbeat) matches the code, and bounding the deferral is the right link to attack rather than trusting the transport. I verified the regression test is red on main (the miniature stall: the outer wait_for trips a plain TimeoutError at 20s) and green here (~5s), 97/97 test_acp.py passes, and the expiry path is genuinely clean: bounded 0.25s cancel-drain, then the existing retryable IdleTimeoutError — not the same stall moved later. I did probe the grace semantics adversarially and found one real false-fire mode plus a diagnostics gap that I think should be fixed before this lands; both keep your approach intact.

  1. Live, streaming tool calls are killed at grace expiry. The grace resets only when the pending set changes (runtime.py:887-890), but in-progress tool_call_update events are invisible to both the set and _activity_count(): they mutate record.status/content in place (session.py:403-422) and touch none of tool_calls/message_chunks/thought_chunks. I ran a probe against this branch — a pending call receiving fresh in-progress content every 0.5s (idle_timeout=1, grace=3s) is killed at grace+idle with "Agent idle for 1s with no new tool call, message, or thought", despite two updates per second arriving. That is a demonstrably-live tool — healthy transport, output flowing — exactly what the deferral exists to protect. Suggested fix: increment a session-level monotonic counter in handle_update for recognized update types and reset pending_since when it moves. This preserves your [BUG] Daytona eval runs stall silently when a tool call's completion update is lost #1061 fix exactly — a half-open PTY delivers no updates at all, so the counter stays flat and the grace still fires — while removing the false fire for any agent that streams tool output. Happy to share the probe script.

  2. At expiry, the diagnostics misattribute the failure. Because the deferral kept refreshing last_progress until the cap, the grace-expiry path reports idle_duration_sec of about idle_timeout and "no new tool call..." (my probe's diagnostic: idle_duration_sec=1, wall 4s, no mention of the pending call). IdleTimeoutDiagnostic carries no pending_tool_call_ids, though AgentPromptTimeoutDiagnostic does. At the scale you are running, triaging lost-completion vs model hang vs long-legit-tool-killed from artifacts is the whole game — suggest adding pending_tool_call_ids and pending_for_sec (or a grace_expired flag) to IdleTimeoutDiagnostic and branching the message when pending calls exist. Diagnostic._init_fields() filters unknown keys, so previously stored artifacts stay loadable.

  3. The ~30-minute silent cap is a behavior change worth stating explicitly. With the default idle timeout of 600s (both DEFAULT_AGENT_IDLE_TIMEOUT_SEC and EvaluationConfig.agent_idle_timeout), a silent tool call now dies at roughly 30-40 minutes where main deferred to the wall clock — the old comment explicitly promised that backstop. A deterministic >30-min silent solve or build now fails every attempt, and retry_on_idle_timeout defaults to True, so retries burn budget on a doomed config; there is no per-task idle knob, and the escape hatches are global (--agent-idle-timeout raises the hang-detection floor everywhere; 0 disables the watchdog and restores the [BUG] Daytona eval runs stall silently when a tool call's completion update is lost #1061 exposure). Fix 1 covers streaming agents; for non-streaming agents this residual trade may well be right, but it deserves a line in the description/docs (and arguably the "breaking change" checkbox), ideally with the 3x multiplier as a named constant so a run profile can tune it.

Minor, fold into 1 if you take it: since the pending branch is an elif, a poll where the activity count grows skips the snapshot update, so the grace start can lag by one poll interval — benign (it only extends the grace).

Ordering vs #1046 (feat/ablate-cli): I trial-merged the branches — clean auto-merge, no textual conflict (our runtime.py changes end at _configure_acp_session; yours start at _prompt_with_idle_watchdog), and the merged tree passes 97/97 test_acp.py. Semantically independent as well: our ACPRequestGlobalError classification covers session-configuration RPCs that run before execute_prompts, and your IdleTimeoutError keeps flowing through the existing IDLE_TIMEOUT retry category. Happy to rebase whichever lands second.

If it helps, I'm happy to send a small patch PR against your branch implementing the grace-reset-on-progress + truthful expiry diagnostics — your call; the review stands either way.

@JeremyJC67

Copy link
Copy Markdown

As offered above — the patch for both review items is ready to merge into this PR's branch: Benjamin-eecs#1 (keeps the bounded-grace design and the 3x constant; grace resets on in-progress tool_call_updates; truthful expiry diagnostics via additive fields; red→green on both defects, your tests untouched and green). Merge it, cherry-pick it, or close it and roll your own — whatever suits your queue.

JeremyJC67 and others added 3 commits August 30, 2026 11:38
…ruthful expiry diagnostics

A single long tool call that streamed in-progress tool_call_update
notifications past the grace boundary was killed as idle: those updates
mutate ToolCallRecord in place, invisible to both the pending-set snapshot
and _activity_count. The watchdog now observes a monotonic
ACPSession.tool_call_update_count each poll, and any change restarts the
pending grace clock alongside pending-set changes — a call that keeps
talking defers as long as it talks, while one silent for the full grace
still trips. On grace expiry, the raised message and IdleTimeoutDiagnostic
now report the truth via additive fields: which pending calls exceeded the
grace, when the pending set last changed, when the last update was
observed, and how many updates were seen.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01DZggU3vNYzr3hfDZJUE7jX
@Benjamin-eecs

Benjamin-eecs commented Aug 30, 2026

Copy link
Copy Markdown
Contributor Author

Thanks @JeremyJC67, both findings were real. Merged your patch into this branch as-is. The update-count reset is the right signal: a streaming call proves the transport is alive, a half-open one stays flat. Named the multiplier (PENDING_GRACE_MULTIPLIER) and the description now states the silent-cap behavior change with the breaking-change box ticked. 99/99 test_acp locally after the merge.

@bingran-you bingran-you left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Validated at exact head 054f91f. Pending grace is now tracked per tool call, so duplicate terminal traffic and another streaming call cannot hide a lost completion, while relevant streaming progress survives. The watchdog policy is extracted from the ACP runtime (runtime: 858 lines; prompt loop: 44 lines). Exact-head ACP tests pass 100/100; the full local suite passes 5936 tests with 48 skipped and 7 deselected; Ruff and ty pass. Real Gemini 3.1 Pro Docker and Daytona runs both earned reward 1, and both artifacts validate healthy and training-ready. All GitHub checks are green after rerunning one transient, unrelated heartbeat timing failure. Ready to squash merge.

@bingran-you
bingran-you merged commit f309f4f into benchflow-ai:main Sep 2, 2026
12 of 13 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

[BUG] Daytona eval runs stall silently when a tool call's completion update is lost

4 participants