From b7d7b68d5f71e643df32d7ea63f49ca3b9246b1b Mon Sep 17 00:00:00 2001 From: William Wang Date: Tue, 1 Sep 2026 11:25:30 +0800 Subject: [PATCH] fix: key stall termination on read watermark, not prompt lock (0.14.3) --- AGENTS.md | 13 +++ CHANGELOG.md | 19 ++++ docs/ARCHITECTURE.md | 29 ++++-- package.json | 2 +- src/backend/types.ts | 4 + src/handlers/session.ts | 107 ++++++++++++--------- tests/stale-running-recovery.test.ts | 135 +++++++++++++++++---------- 7 files changed, 205 insertions(+), 104 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 3c8674e..1393cf2 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -160,6 +160,19 @@ ZCode protocol types into ACP notifications directly — always translate. its push — the next turn would run deaf) and re-baseline the projection differ (the abandoned turn committed messages while waiting — a stale baseline replays that residue as the next reply). +- **Prompt lock ≠ turn liveness** (raw-backend verified, Aug-28 app-server): + `session/goal show` succeeds mid-turn (never reports the 1308 lock), and a + probe `session/send` is ACCEPTED while the turn runs — it is queued as + steer input. The 1308 lock only exists during turn finalisation, so "lock + released" proves nothing about whether a turn is alive. Killing a silently + running turn on a lock probe murdered live sub-agent turns behind quiet + event streams (PR #85 did exactly this for a day). The honest liveness + signal is the `session/read` projection watermark + (contextUsed/totalTokenCount/turnCount/currentTurnId): a sub-agent turn + advances it for minutes with zero stream events. `runEventTurn` therefore + defers the terminal decision while the watermark moves and only ends a + turn after the watermark has been frozen for STALE_FREEZE_MS (10 min) — + reply-fetch first, bounded stop as the last resort. - **The backend rejects JSON-RPC frames carrying a `jsonrpc` field** (strict zod: "Unrecognized key: jsonrpc", code -32600). The bridge's backend client never sends one — keep it that way when hand-probing diff --git a/CHANGELOG.md b/CHANGELOG.md index fdc2676..f3fdbf5 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,25 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +## [0.14.3] - 2026-09-01 + +### Fixed + +- Turns running silently behind a sub-agent (or any long quiet operation) are + no longer killed after 120 seconds of stream silence. 0.14.2's deadline + check probed the prompt lock via `session/goal show` and killed the turn on + a released or indeterminate lock — but raw-backend probes against the + Aug-28 app-server proved the prompt lock is not a liveness signal: + `session/goal show` succeeds mid-turn, and a probe `session/send` is + accepted (queued as steer input) while the turn runs, because the lock is + only held during turn finalisation. The deadline now keys on the + `session/read` projection watermark (contextUsed / totalTokenCount / + turnCount / currentTurnId), refreshed by the 15-second stall reconcile: an + advancing watermark proves the backend is still making progress and defers + the terminal decision indefinitely, and only a watermark frozen for ten + minutes (STALE_FREEZE_MS) ends the turn — reply fetch first, bounded stop + as the last resort. + ## [0.14.2] - 2026-08-31 ### Fixed diff --git a/docs/ARCHITECTURE.md b/docs/ARCHITECTURE.md index 7c59f2d..aaafdc8 100644 --- a/docs/ARCHITECTURE.md +++ b/docs/ARCHITECTURE.md @@ -263,21 +263,30 @@ editor still has it open). | turn.completed | -> end_turn | turn.failed | -> error | turn.cancelled | -> cancelled - | no protocol | - | progress (120s) | -> probe prompt lock - | lock released | -> max_turn_requests - | lock held | -> defer decision - | manual cancel | -> cancelled + | no protocol | + | progress (120s) | -> check read watermark + | watermark moved | -> defer decision (alive) + | frozen < 10 min | -> defer decision + | frozen >= 10 min | -> fetch reply -> end_turn + | | no reply, no output -> max_turn_requests + | manual cancel | -> cancelled +---------------------+ ``` Projection polling is a recovery signal, not protocol progress. In particular, `projection.status=running` may be stale and therefore never -refreshes the 120-second deadline. At that deadline the bridge probes the -backend prompt lock (`session/goal show`): an explicitly held lock proves a -model or tool turn is still active and defers the terminal decision, while a -released or indeterminate lock preserves the bounded `max_turn_requests` -outcome. Already-queued events win the deadline race and are consumed first. +refreshes the 120-second deadline. Neither is the prompt lock a liveness +signal — verified against the Aug-28 app-server, `session/goal show` succeeds +mid-turn, and a probe `session/send` is accepted (queued as steer input) while +the turn runs; the lock is only held during finalisation. Instead the 15s +stall-reconcile reads feed a liveness watermark +(`contextUsed`/`totalTokenCount`/`turnCount`/`currentTurnId` from +`session/read`): an advancing watermark proves a silently-working turn +(typically a sub-agent) and defers the terminal decision indefinitely, while +a watermark frozen for 10 minutes (STALE_FREEZE_MS) marks the projection as +truly stale — the turn then ends gently (reply fetch first, bounded stop only +when nothing was ever delivered). Already-queued events win the deadline race +and are consumed first. ### Tool lifecycle diff --git a/package.json b/package.json index 5a1a82f..9c797c8 100644 --- a/package.json +++ b/package.json @@ -1,6 +1,6 @@ { "name": "zcode-acp-server", - "version": "0.14.2", + "version": "0.14.3", "description": "Agent Client Protocol (ACP) server bridging headless ZCode to editors like Zed and JetBrains.", "type": "module", "license": "Apache-2.0", diff --git a/src/backend/types.ts b/src/backend/types.ts index d8b8f88..a140f85 100644 --- a/src/backend/types.ts +++ b/src/backend/types.ts @@ -102,6 +102,10 @@ export interface ZcodeProjection { contextUsed?: number; contextWindow?: number; totalTokenCount?: number; + /** Turns completed in this session (observed in app-server projections). */ + turnCount?: number; + /** Id of the turn the projection considers current, if any. */ + currentTurnId?: string; } // ---------- messages / history ---------- diff --git a/src/handlers/session.ts b/src/handlers/session.ts index 74e082c..3a298cb 100644 --- a/src/handlers/session.ts +++ b/src/handlers/session.ts @@ -17,7 +17,12 @@ import type * as acp from "@agentclientprotocol/sdk"; import { RequestError } from "@agentclientprotocol/sdk"; import { EventStreamListener, TurnMonitor } from "../backend/listener.js"; -import type { ZcodeCreateResult, ZcodeListResult, ZcodeSnapshot } from "../backend/types.js"; +import type { + ZcodeCreateResult, + ZcodeListResult, + ZcodeProjection, + ZcodeSnapshot, +} from "../backend/types.js"; import { buildModes, buildConfigOptions, @@ -1630,8 +1635,33 @@ export async function runEventTurn( const translator = new EventTranslator(); differ.resetTurn(); const NO_PROGRESS_MS = 120_000; + // Stall termination policy. Two candidate liveness signals were verified + // against the Aug-28 app-server and both are unusable for kill decisions: + // - `session/goal show` succeeds mid-turn (never reports the 1308 lock), + // - a probe `session/send` is ACCEPTED while the turn runs (queued as + // steer input) — the prompt lock is only held during finalisation. + // So "lock released" proves nothing about turn liveness, and killing on it + // murdered live sub-agent turns after 120s of stream silence. The honest + // signal is the read-projection watermark: contextUsed / totalTokenCount / + // turnCount / currentTurnId advance while the backend makes progress + // (verified: a sub-agent turn advanced the watermark for 5+ minutes with + // zero stream events). A live turn may still freeze the watermark for a + // while (long CoT, quiet tools — observed 60s+ pauses), so a freeze alone + // never kills: only a freeze sustained past STALE_FREEZE_MS ends the turn, + // reply-fetch first, stop as the last resort. + const STALE_FREEZE_MS = 600_000; let lastProtocolProgressAt = Date.now(); let nextNoProgressDecisionAt = lastProtocolProgressAt + NO_PROGRESS_MS; + let lastWatermarkAdvanceAt = Date.now(); + let watermark = ""; + const noteWatermark = (proj: ZcodeProjection | null): void => { + if (!proj) return; + const next = `${proj.contextUsed ?? 0}/${proj.totalTokenCount ?? 0}/${proj.turnCount ?? 0}/${proj.currentTurnId ?? ""}`; + if (next !== watermark) { + watermark = next; + lastWatermarkAdvanceAt = Date.now(); + } + }; let lastStallCheck = Date.now(); let emittedText = false; let emittedOutput = false; @@ -1663,22 +1693,42 @@ export async function runEventTurn( stopBackendTurn(server, turn.zcodeSid, turn.foregroundExecutionId); return { stopReason: "max_turn_requests" }; } else { - const lockState = await probePromptLock(server, turn.zcodeSid); - if (lockState === "held") { - // A prompt-lock failure is direct evidence that the backend still owns - // an active turn. It is liveness, not protocol progress: leave - // lastProtocolProgressAt untouched and schedule a later decision. - // This protects legitimately long model/tool operations without - // allowing a stale `projection.status=running` to refresh the clock. + const frozenMs = Date.now() - lastWatermarkAdvanceAt; + if (frozenMs < STALE_FREEZE_MS) { + // The read watermark moved recently — direct evidence the backend is + // still making progress (typically a sub-agent or slow tool working + // behind a silent stream). Keep waiting; the 15s stall-reconcile + // below keeps refreshing the watermark via session/read. const activeTools = [...translator.seenToolIds].filter( (toolId) => !translator.finalToolIds.has(toolId), ).length; log( - ` [stall] prompt lock still held after ${Math.round((Date.now() - lastProtocolProgressAt) / 1000)}s silence (activeTools=${activeTools}); deferring terminal decision`, + ` [stall] watermark advanced within the last ${Math.round(frozenMs / 1000)}s (activeTools=${activeTools}); deferring terminal decision`, ); nextNoProgressDecisionAt = Date.now() + NO_PROGRESS_MS; + } else if (emittedText || emittedOutput) { + // Watermark frozen past the budget and something was already + // delivered — treat as a completed-but-terminal-event-lost turn + // (never compress its context; the completion is inferred). + turn.stallRecovered = true; + log( + ` [stall] watermark frozen ${Math.round(frozenMs / 1000)}s; ending turn after delivered output`, + ); + return { stopReason: "end_turn" }; } else { - log(` [stall] no-progress deadline reached; prompt lock=${lockState}`); + const reply = await fetchLastReply(server, turn.zcodeSid, differ); + if (reply) { + registerFetchedReply(translator, reply); + await sendTextChunk(cx, acpSid, reply.text, chunkMsgId); + turn.stallRecovered = true; + log( + ` [stall] watermark frozen ${Math.round(frozenMs / 1000)}s; recovered reply via session/messages`, + ); + return { stopReason: "end_turn" }; + } + log( + ` [stall] watermark frozen ${Math.round(frozenMs / 1000)}s with no output; stopping backend turn`, + ); stopBackendTurn(server, turn.zcodeSid, turn.foregroundExecutionId); return { stopReason: "max_turn_requests" }; } @@ -1754,6 +1804,7 @@ export async function runEventTurn( ) { lastStallCheck = Date.now(); const proj = await monitor.pollOnce(); + noteWatermark(proj); if (proj?.status === "idle") { // A single idle probe can also fire mid-work: the backend is silent // during the model's thinking/connection phase and may report idle @@ -1767,6 +1818,7 @@ export async function runEventTurn( continue; // alive — events will be consumed by the next poll } const proj2 = await monitor.pollOnce(); + noteWatermark(proj2); if (proj2?.status === "idle" && !listener.hasQueuedEvents()) { // Turn completed but the event was lost (double-confirmed). if (!emittedText) { @@ -1979,41 +2031,6 @@ export async function runEventTurn( } } -type PromptLockState = "held" | "released" | "unknown"; - -/** - * Probe the backend's authoritative prompt lock without waiting for it to - * change. `session/read` projection status is intentionally not considered: - * that projection can remain stale at `running`, which is the condition this - * probe is used to disambiguate. - */ -async function probePromptLock(server: ZcodeAcpServer, zcodeSid: string): Promise { - const backend = server.ensureBackend(); - if (backend.isDead) return "unknown"; - try { - const resp = await backend.request( - server.nextId(), - "session/goal", - { sessionId: zcodeSid, action: "show" }, - 10_000, - ); - if (!resp.error) return "released"; - // Lock-busy must match by error CODE, not message text: backend message - // wording drifts between releases (repo Gotcha), and a missed match kills - // a live turn. 1308 is the prompt-lock-busy code (same one the send-retry - // loop keys on); message matching kept as a legacy fallback. - if (resp.error.code === 1308) return "held"; - const message = (resp.error.message ?? "").toLowerCase(); - if (message.includes("prompt is running") || message.includes("already running")) { - return "held"; - } - return "unknown"; - } catch (e) { - log(` [stall] prompt-lock probe failed: ${e instanceof Error ? e.message : String(e)}`); - return "unknown"; - } -} - /** * Turn-attribution gate decision (pure, exported for tests): whether an event * observed before this turn's own `turn.started` should be dropped as leftover diff --git a/tests/stale-running-recovery.test.ts b/tests/stale-running-recovery.test.ts index a7b10f5..76e9861 100644 --- a/tests/stale-running-recovery.test.ts +++ b/tests/stale-running-recovery.test.ts @@ -1,7 +1,15 @@ /** - * Regression coverage for a stale `projection.status === "running"` keeping - * the event turn alive forever. The public `prompt()` boundary is used so the - * test covers the real listener, monitor, and timeout wiring together. + * Regression coverage for stall termination in `runEventTurn`. + * + * History: PR #85 killed a turn after 120s of stream silence whenever a + * `session/goal show` probe answered without the 1308 lock error. Raw-backend + * probes (Aug-28 app-server) proved that probe worthless — goal show succeeds + * mid-turn, and even a probe `session/send` is accepted as steer input while + * the turn runs — so live sub-agent turns behind a silent stream were being + * murdered after 2 minutes. The replacement policy keys on the read-projection + * watermark (contextUsed/totalTokenCount/turnCount/currentTurnId): advancing + * watermark = alive (wait), watermark frozen past STALE_FREEZE_MS (10 min) = + * stale (end gently, stop as last resort). */ import type * as acp from "@agentclientprotocol/sdk"; @@ -22,18 +30,18 @@ interface StaleBackendControl { backend: ZcodeBackend; emit: (event: ZcodeEvent) => void; goalProbes: ReturnType; - setPromptLockHeld: (held: boolean) => void; sendRequests: ReturnType; + /** "advance": every session/read bumps contextUsed (live sub-agent). "frozen": never changes. */ + setWatermarkMode: (mode: "advance" | "frozen") => void; } function staleRunningBackend(): StaleBackendControl { const listeners = new Set<{ handleEvent: (event: ZcodeEvent) => void }>(); - let promptLockHeld = false; - const goalProbes = vi.fn(async () => - promptLockHeld - ? { error: { message: "session goal: prompt is running" } } - : { result: { goal: null } }, - ); + let watermarkMode: "advance" | "frozen" = "frozen"; + let contextUsed = 0; + // Kept only to assert the goal channel is NEVER consulted again — it cannot + // see turn liveness (verified against the real backend). + const goalProbes = vi.fn(async () => ({ result: { goal: null } })); const sendRequests = vi.fn(); const backend = { isDead: false, @@ -46,13 +54,15 @@ function staleRunningBackend(): StaleBackendControl { return { result: { eventSeq: 1 } }; case "session/messages": return { result: { messages: [] } }; - case "session/read": + case "session/read": { + if (watermarkMode === "advance") contextUsed += 1000; return { result: { - projection: { status: "running", contextUsed: 0 }, + projection: { status: "running", contextUsed, contextWindow: 1000000 }, settings: {}, }, }; + } case "session/goal": return goalProbes(); case "session/send": @@ -78,10 +88,10 @@ function staleRunningBackend(): StaleBackendControl { for (const listener of listeners) listener.handleEvent(event); }, goalProbes, - setPromptLockHeld: (held) => { - promptLockHeld = held; - }, sendRequests, + setWatermarkMode: (mode) => { + watermarkMode = mode; + }, }; } @@ -103,7 +113,15 @@ const cx = { request: vi.fn().mockResolvedValue({}), } as unknown as acp.AgentContext; -describe("stale running projection recovery", () => { +/** Pump the micro-task queue until prompt() has fired its session/send. */ +async function waitForSend(sendRequests: ReturnType) { + for (let i = 0; i < 80 && sendRequests.mock.calls.length === 0; i++) { + await Promise.resolve(); + } + expect(sendRequests).toHaveBeenCalledOnce(); +} + +describe("stall termination policy (watermark-based)", () => { beforeEach(() => { vi.useFakeTimers(); }); @@ -113,62 +131,83 @@ describe("stale running projection recovery", () => { vi.clearAllMocks(); }); - it("bounds a silent turn when running is stale and the prompt lock is released", async () => { - const { backend, goalProbes, sendRequests } = staleRunningBackend(); - const turn = prompt(setup(backend), params, cx, 1); + it("keeps a silently-running sub-agent turn alive while the read watermark advances", async () => { + // The user-visible bug: a sub-agent works behind a silent event stream for + // minutes. The read watermark keeps moving (contextUsed grows on every + // 15s stall-reconcile probe), so the turn must NOT be killed at the 120s + // no-progress deadline — nor ever, while the watermark keeps advancing. + const control = staleRunningBackend(); + control.setWatermarkMode("advance"); + const turn = prompt(setup(control.backend), params, cx, 1); + let settled: acp.PromptResponse | undefined; + void turn.then((value) => { + settled = value; + }); + await waitForSend(control.sendRequests); + + await vi.advanceTimersByTimeAsync(121_000); + expect(settled).toBeUndefined(); // old goal-probe code killed the turn here + + // Still alive long past any single deadline window. + await vi.advanceTimersByTimeAsync(700_000); + expect(settled).toBeUndefined(); + + control.emit({ type: "turn.completed", payload: { resultType: "success" } }); + await vi.advanceTimersByTimeAsync(5_000); + + await expect(turn).resolves.toEqual({ stopReason: "end_turn" }); + expect(control.goalProbes).not.toHaveBeenCalled(); + expect(control.backend.send).not.toHaveBeenCalled(); + }); + + it("ends a watermark-frozen turn after the stale-freeze budget (no output → stop)", async () => { + // PR #85's original goal stays: a projection stuck at `running` whose + // watermark never advances must eventually converge instead of hanging + // forever. Nothing was emitted, no reply can be fetched → bounded stop. + const control = staleRunningBackend(); + control.setWatermarkMode("frozen"); + const server = setup(control.backend); + const turn = prompt(server, params, cx, 2); let result: acp.PromptResponse | undefined; void turn.then((value) => { result = value; }); + await waitForSend(control.sendRequests); - // Let prompt() finish its immediate setup/subscribe/send chain before the - // large time jump; otherwise fake time can advance before runEventTurn has - // captured its initial deadline. - for (let i = 0; i < 80 && sendRequests.mock.calls.length === 0; i++) { - await Promise.resolve(); - } - expect(sendRequests).toHaveBeenCalledOnce(); await vi.advanceTimersByTimeAsync(121_000); + expect(result).toBeUndefined(); // 120s freeze alone must not kill yet + + // 10-minute stale-freeze budget from the first watermark read (~15s in). + await vi.advanceTimersByTimeAsync(700_000); expect(result).toEqual({ stopReason: "max_turn_requests" }); - expect(goalProbes).toHaveBeenCalled(); + expect(control.backend.send).toHaveBeenCalled(); // stopBackendTurn fired + expect(control.goalProbes).not.toHaveBeenCalled(); }); - it("does not cancel an active tool while the prompt lock is still held", async () => { + it("ends a watermark-frozen turn gently when output was already delivered", async () => { + // Same freeze, but a tool card was already streamed: the turn is treated + // as completed-but-terminal-event-lost — end_turn, no backend stop. const control = staleRunningBackend(); - control.setPromptLockHeld(true); - const turn = prompt(setup(control.backend), params, cx, 2); + control.setWatermarkMode("frozen"); + const turn = prompt(setup(control.backend), params, cx, 3); let settled = false; void turn.then(() => { settled = true; }); + await waitForSend(control.sendRequests); - for (let i = 0; i < 80 && control.sendRequests.mock.calls.length === 0; i++) { - await Promise.resolve(); - } - expect(control.sendRequests).toHaveBeenCalledOnce(); - control.emit({ - type: "tool.updated", - payload: { - kind: "scheduled", - toolCallId: "tool-1", - toolName: "Read", - input: { file_path: "/tmp/example" }, - }, - }); control.emit({ type: "tool.updated", payload: { kind: "started", toolCallId: "tool-1", toolName: "Read" }, }); await vi.advanceTimersByTimeAsync(0); - await vi.advanceTimersByTimeAsync(121_000); - expect(control.goalProbes).toHaveBeenCalled(); + await vi.advanceTimersByTimeAsync(121_000); expect(settled).toBe(false); - control.emit({ type: "turn.completed", payload: { resultType: "success" } }); - await vi.advanceTimersByTimeAsync(5_000); - + await vi.advanceTimersByTimeAsync(700_000); await expect(turn).resolves.toEqual({ stopReason: "end_turn" }); + expect(control.backend.send).not.toHaveBeenCalled(); }); });