fix(sync): interrupt cancel race + state-based silence watchdog + E2E observability - #74
Merged
Merged
Conversation
…uess The silence watchdog shipped in #73 disarmed permanently on the first agent event. That covers the production wedge (prompt accepted, zero events ever) but misses the other shape: streamed some output, then stalled before completing — observed in the E2E claude round, where the agent returned a correct answer and then never sent message_completed. The obvious fix — a second, longer idle timeout — would have required hard-coding an assumption about the longest plausible tool call, which is both unknowable and wrong the first time someone runs a 40-minute build. Instead the watchdog now asks the thread whether anything is actually outstanding. has_outstanding_work() reports true while any tool call is Pending / InProgress / WaitingForConfirmation. Busy threads are exempt for exactly as long as the work genuinely takes, with no duration constant anywhere; silence is only judged when nothing is running. Both wedge shapes then fall out of one rule: generating + no events for <budget> + nothing outstanding => wedged That also means the budget no longer has to cover tool calls at all — only model think-time between consecutive events — so a single modest 120s default is defensible. Renamed HELIX_ACP_FIRST_EVENT_TIMEOUT_SECS -> HELIX_ACP_SILENCE_TIMEOUT_SECS to match the changed semantics (shipped hours ago, no deployment references it). Also fixes the E2E agent-version diagnostic, which queried @anthropic-ai/claude-agent-acp — a package that 404s. Zed installs @agentclientprotocol/claude-agent-acp (0.63.0 today, the same version that wedged in prod). The wrong scope silently reported 'unknown', disabling the one signal that distinguishes our regression from an agent-package change. Now queries the right scope, warns loudly if it cannot resolve, and states that the install is unpinned. cargo test -p external_websocket_sync: 56 passed.
|
Bugbot is not enabled for your account, so this pull request was not reviewed. Enable Bugbot in the Cursor dashboard to get automatic reviews on future PRs. |
Author
|
Paired Helix PR (pins |
Root cause of the intermittent E2E Phase 17 failure "interrupt message never delivered", found by running the suite repeatedly. A chat_message with interrupt=true fired TWO independent channels for what is semantically one operation: request_cancel_thread() to the dedicated cancel task, and request_thread_creation() to the creation task. Those tasks are separate spawns with no ordering guarantee, so the send can begin before the cancel is processed -- and the cancel then kills the NEW turn instead of the old one. Observed in a failing run (claude round, thread 5c80128a): 07:18:06 turn_cancelled req=int_...6apt (X) <- correct 07:18:06 message_completed req=int_...6apt usage=null 07:18:06 message_completed req=int_...6ejk (Y) usage=null <- Y just created 07:18:06 "Ignoring stale request_id rebind (mapping previously consumed by completion)" 07:19:06 Phase 17: FAIL -- interrupt message never delivered Y was created and completed in the same second with usage=null: its turn never ran. Every healthy completion on that thread carries real usage. Y's real completion was then rejected as a stale rebind, so the interaction never left the waiting state -- the same off-by-one shape Critical Fix #9 addresses, reached by a different route. The interrupt is now carried on ThreadCreationRequest and the cancel is performed inline by the creation task immediately before the send, so the two steps cannot be reordered. The dedicated cancel task is retained for standalone cancel_current_turn, which is what it exists for: cancelling while the creation loop is blocked awaiting a previous turn. cargo test -p external_websocket_sync: 56 passed.
…r turn Root cause of the intermittent E2E Phase 17 failure "interrupt message never delivered", found by running the suite repeatedly (~50% failure rate). An interrupt dispatches its cancel out-of-band, to a dedicated task, so it can fire while the sequential creation loop is blocked awaiting the very turn being interrupted. That is necessary -- but it also means the cancel races that loop. If the old turn finishes on its own just as the interrupt arrives, the creation loop starts the NEW turn and the in-flight cancel lands on that instead. Observed in a failing run (claude round, thread 5c80128a): 07:18:06 turn_cancelled req=int_...6apt (X) <- intended 07:18:06 message_completed req=int_...6apt usage=null 07:18:06 message_completed req=int_...6ejk (Y) usage=null <- Y just created 07:18:06 "Ignoring stale request_id rebind (mapping previously consumed by completion)" 07:19:06 Phase 17: FAIL -- interrupt message never delivered Y was created and completed in the same second with usage=null: its turn never ran. Every healthy completion on that thread carries real token usage. Y's real completion was then rejected as a stale rebind, so the interaction never left the waiting state -- the same off-by-one shape Critical Fix #9 addresses, reached by a different route. In production this is a user pressing stop and retyping while a turn streams. The cancel now names the turn it intends to kill: request_cancel_thread() takes an expected_request_id, and the cancel task drops the request as stale if the thread has since moved on. An untargeted cancel (explicit user stop) still cancels whatever is running, by passing None. Rejected alternative: performing the cancel inline in the creation loop. That orders cancel-before-send trivially, but the loop awaits each turn to completion, so an interrupt queued behind a running turn could never cancel it -- trading a race for a deadlock. The dedicated cancel task exists precisely to avoid that, so the fix keeps it and makes it precise instead. cargo test -p external_websocket_sync: 56 passed. cargo check -p zed --features external_websocket_sync: clean.
'grep -c' PRINTS the count and EXITS NON-ZERO when the count is zero, so $(grep -c ... || echo "0") produces the two-line string "0\n0". Every subsequent [ "$X" -gt 0 ] then died with: /test/run_e2e.sh: line 58: [: 0 0: integer expression expected visible at the end of every run. Consequence: the ACP_SPAWN / ACP_DEDUP diagnostic block never rendered, so agent-spawn and connection-dedup behaviour — exactly what is needed to diagnose a claude-round failure — was silently withheld. Fallback moved onto the assignment.
A failing round previously reported only "phase N timed out". That is not enough to attribute the failure, and the ordering that produced it is invisible from the Helix side (Helix sees completions, not the sequence inside Zed that caused them). Diagnosing the Phase 17 interrupt race required reading the Helix log by hand and inferring Zed's behaviour, because none of it was surfaced. Adds a TURN LIFECYCLE / CANCEL ORDERING block to cleanup, alongside the existing ACP_SPAWN/ACP_DEDUP one, covering the three shapes seen so far: - cancel landing on the wrong turn -> CANCEL_TASK vs THREAD_SERVICE ordering - a stale cancel correctly dropped -> "Stale cancel ignored" - agent accepted a prompt then died -> helix_silent_prompt_wedge Also applies the grep -c fix to ACP_LINES, which had the same defect already fixed for ZED_ERRORS: grep -c prints the count AND exits non-zero at zero matches, so the `|| echo 0` fallback produced "0\n0" and the guard died with "integer expression expected" -- silently suppressing the ACP diagnostics.
The message_completed handler ignores cross-round completions with two checks: the request id must contain the current agent name, and the thread must belong to the current round. The first is a heuristic that only holds for the synthetic ids the harness mints itself (req-phaseN-<agent>). The production-queue phases (16/17) drive REAL Helix interactions, whose ids are ULIDs (int_01kyry6ejk...) containing no agent name. So live completions for the current round were rejected and logged as: [claude] FILTERED completion (wrong agent): req=int_01kyry6ejk... That is worse than useless during triage — it asserts the opposite of what happened. It cost real time chasing a phantom routing bug while Phase 17 was actually hitting a cancel race. Helix-minted ids are round-safe regardless (each round gets fresh sessions and threads), so they now defer to the precise thread check that follows. go build: clean. (main.go has pre-existing gofmt drift in the phase9/10 struct fields, left alone to keep this diff focused.)
lukemarsden
changed the title
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Follow-ups to the silence watchdog in #73. Started as two small fixes; running the E2E repeatedly then turned up a real product race, so this now carries that fix plus the observability work needed to find it.
Paired Helix PR (pins
ZED_COMMIT): helixml/helix#2898Why: the suite was failing ~50% of the time
Four full runs of
E2E_AGENTS="zed-agent,claude"onmaingave 2 failures, both in the claude round, in two different shapes. Neither was test noise.1. Interrupt cancels could kill the wrong turn (product bug)
An interrupt dispatches its cancel out-of-band, to a dedicated task, so it can fire while the sequential creation loop is blocked awaiting the very turn being interrupted. That is necessary — but it means the cancel races that loop. If the old turn finishes on its own just as the interrupt arrives, the loop starts the NEW turn and the in-flight cancel lands on that instead.
From a failing run (claude round, thread
5c80128a):Y was created and completed in the same second with
usage=null— its turn never ran. Every healthy completion on that thread carries real token usage. Y's real completion was then rejected as a stale rebind, so the interaction never leftwaiting. Same off-by-one shape as Critical Fix #9, reached by a different route. In production this is a user pressing stop and retyping mid-stream.Fix: the cancel now names the turn it intends to kill.
request_cancel_thread()takes anexpected_request_id; the cancel task drops the request as stale if the thread has moved on. Explicit user stop passesNoneand still cancels whatever is running.Rejected alternative (present as a reverted commit in this branch's history,
d006aa4332): performing the cancel inline in the creation loop. It orders cancel-before-send trivially, but the loop awaits each turn to completion, so an interrupt queued behind a running turn could never cancel it — trading a race for a deadlock. The dedicated cancel task exists precisely to avoid that.2. Silence watchdog: judged by state, not a tool-duration guess
The #73 watchdog disarmed permanently on the first agent event, so it caught "prompt accepted, zero events" but missed "streamed output, then stalled before completing" — a shape the E2E claude round actually produced.
Adding a second, longer idle timeout would require hard-coding "the longest plausible tool call" — unknowable, and wrong the first time someone runs a 40-minute build. Instead
has_outstanding_work()asks the thread: true while any tool call isPending/InProgress/WaitingForConfirmation. Busy threads are exempt for as long as the work genuinely takes, no duration constant anywhere, and silence is judged only when nothing is running:The budget then only covers model think-time between events, so a single 120s default is defensible.
HELIX_ACP_FIRST_EVENT_TIMEOUT_SECS→HELIX_ACP_SILENCE_TIMEOUT_SECS;0disables.3. Observability — three things that actively misled diagnosis
grep -ccounters were broken.grep -cprints the count and exits non-zero at zero matches, so$(grep -c … || echo 0)produced"0\n0"and every guard died withinteger expression expected(visible at the end of every run). This silently suppressed the ACP_SPAWN/ACP_DEDUP block.strings.Contains(requestID, agentName)only holds for syntheticreq-phaseN-<agent>ids; the production-queue phases use real ULIDs (int_…), so live completions were rejected and loggedFILTERED completion (wrong agent)— asserting the opposite of what happened, and costing real time chasing a phantom routing bug.@anthropic-ai/claude-agent-acp, which 404s. Zed installs@agentclientprotocol/claude-agent-acp(0.63.0 today — the version that wedged in prod).Validation
cargo check -p zed --features external_websocket_sync— cleancargo test -p external_websocket_sync— 56 passedcargo test -p acp_thread— 127 passed, 1 documented ignoreNote on the unpinned agent
Deliberately keeping
claude-agent-acpunpinned: production auto-installs latest, and tracking the fast-moving Anthropic API is the point of this integration. Pinning CI would test something we don't ship and convert a real signal into silence. The remedy is attribution (fixed above) plus resilience, not determinism.🤖 Generated with Claude Code