diff --git a/docs/ARCHITECTURE.md b/docs/ARCHITECTURE.md index 11006cdaf..b0976d771 100644 --- a/docs/ARCHITECTURE.md +++ b/docs/ARCHITECTURE.md @@ -161,7 +161,7 @@ The ChatDirector counts consecutive assistant turns that contain tool calls and #### Sub-agent stall management -`SubAgentDirector` tracks `lastActivityAt`, updated on every real `inference.done` and `tool.done`. Directors are pure `decide(event, ...)` functions with no timer of their own and the reactor has no proactive "idle" event, so a genuinely silent worker (e.g. parked on a long-running background command with nothing else to do) produces no event for the director to react to. `runSubAgent` (`src/subagent/index.ts`) arms an external interval, at `subAgentStallTimeoutMs`, that pings the same content-less continuation channel the compaction governor uses to re-enter an idle reactor (`requestContinuation`). The director only acts on a ping if the elapsed time since `lastActivityAt` has crossed the timeout — a ping delivered while a tool call is still executing simply queues until that cycle finishes, so "no pending harness-tracked work" falls out of when the check can run at all rather than needing separate bookkeeping. The first stall past the timeout records `stallNudgeAt` and issues one continuation nudge (asking the worker to check on the background work or report status). Later empty pings inside `subAgentStallTimeoutMs` of that instant wait without stopping or treating the ping as activity; salvage fires only once a ping arrives after that grace with still no `tool.done` / turn-boundary reset. That grace is what keeps two queued interval ticks from salvaging hundreds of milliseconds after the nudge. Any real activity clears `stallNudgeAt`, so a worker that is genuinely working through a slow single turn is never penalized. After the worker has already replied with a terminal report (complete envelope or salvage), further empty continuations — idle-compact meter sync or stall pings — return `wait` instead of falling through to `DefaultDirector.infer`; only a non-empty parent message (`resume_agent` / `send_input`) re-opens the brief. +`SubAgentDirector` tracks `lastActivityAt`, updated on every real `inference.done` and `tool.done`. Directors are pure `decide(event, ...)` functions with no timer of their own and the reactor has no proactive "idle" event, so a genuinely silent worker (e.g. parked on a long-running background command with nothing else to do) produces no event for the director to react to. `runSubAgent` (`src/subagent/index.ts`) arms an external interval, at `subAgentStallTimeoutMs`, that pings the same content-less continuation channel the compaction governor uses to re-enter an idle reactor (`requestContinuation`). The director only acts on a ping if the elapsed time since `lastActivityAt` has crossed the timeout. A ping can still be delivered while `execute_tools` is in flight; outstanding call ids from the last `inference.done` reset the silence clock and wait rather than recording `stall-nudge` with a huge `silenceMs`. The first stall past the timeout records `stallNudgeAt` and issues one continuation nudge (asking the worker to check on the background work or report status). Later empty pings inside `subAgentStallTimeoutMs` of that instant wait without stopping or treating the ping as activity; salvage fires only once a ping arrives after that grace with still no `tool.done` / turn-boundary reset. That grace is what keeps two queued interval ticks from salvaging hundreds of milliseconds after the nudge. Any real activity clears `stallNudgeAt`, so a worker that is genuinely working through a slow single turn is never penalized. After the worker has already replied with a terminal report (complete envelope or salvage), further empty continuations — idle-compact meter sync or stall pings — return `wait` instead of falling through to `DefaultDirector.infer`; only a non-empty parent message (`resume_agent` / `send_input`) re-opens the brief. **Intervention log**: every stop and nudge is appended as one JSONL record to `interventions.jsonl` in the firing worker's trace dir (`src/subagent/intervention-log.ts`), carrying the trigger's measured value beside the threshold it crossed, the provider/model/family it fired on, and the run state at that moment (turns used vs budget, tool calls, read/edit counts). A refused parent re-dispatch is recorded on the parent side, where no worker run exists to record it. The parent also appends one `outcome` record per completed dispatch — the salvage kind `classifyBriefSalvage` assigned, or a clean-complete marker, plus the dispatch count — so the log carries dispatch outcomes as well as interventions, and a stop record can later be read alongside what the dispatch it touched actually produced. Writes are fire-and-forget and swallow their own errors — a diagnostic must not be able to fail a run. `scripts/intervention-forensics.ts` aggregates these across local sessions: per-intervention counts by model family, the measured-value distribution against the threshold, two context columns (stops that fired on runs which had already edited files; stops that fired before half the turn budget was spent — neither is a measured false-positive rate, since either is equally consistent with a correct stop or a wrong one), and outcome counts by kind. This exists because every threshold in this tree was set by judgment and four of those judgments were later reverted — a threshold change is expected to cite this data (CL-6938). diff --git a/src/subagent/nudge-director.test.ts b/src/subagent/nudge-director.test.ts index 8547e7b5c..e7c445da2 100644 --- a/src/subagent/nudge-director.test.ts +++ b/src/subagent/nudge-director.test.ts @@ -123,6 +123,13 @@ function toolDone(callId: string, isError = false): ReactorInboundEvent { } as unknown as ReactorInboundEvent; } +function resumeToolResult(callId: string): ReactorInboundEvent { + return { + type: "resume.tool_result", + result: { callId, content: "denied by approver", isError: true }, + } as unknown as ReactorInboundEvent; +} + function messageReceived(content: string): ReactorInboundEvent { return { type: "message.received", @@ -1184,6 +1191,63 @@ describe("SubAgentDirector post-complete terminalization (CL-7068)", () => { }); describe("SubAgentDirector stall nudge grace", () => { + test("long in-flight tool with no assistant text does not stall-nudge", async () => { + let now = 4_000_000; + const director = new SubAgentDirector( + "system", + [], + undefined, + 1_000, + () => now, + ); + const caps = capabilities(); + + await director.decide(inferenceDone(["slow-1"]), state, caps); + + now += 60_000; + const midTool = actions( + await director.decide(messageReceived(""), state, caps), + ); + expect(midTool).toEqual([{ type: "wait" }]); + + await director.decide(toolDone("slow-1"), state, caps); + now += 1_000; + const afterTool = actions( + await director.decide(messageReceived(""), state, caps), + ); + expect(afterTool).toContainEqual({ + type: "checkpoint", + message: "subagent-stall-nudge", + }); + }); + + test("resume.tool_result clears in-flight ids so later silence can stall-nudge", async () => { + let now = 5_000_000; + const director = new SubAgentDirector( + "system", + [], + undefined, + 1_000, + () => now, + ); + const caps = capabilities(); + + await director.decide(inferenceDone(["parked-1"]), state, caps); + now += 60_000; + expect( + actions(await director.decide(messageReceived(""), state, caps)), + ).toEqual([{ type: "wait" }]); + + await director.decide(resumeToolResult("parked-1"), state, caps); + now += 1_000; + expect( + actions(await director.decide(messageReceived(""), state, caps)), + ).toContainEqual({ + type: "checkpoint", + message: "subagent-stall-nudge", + }); + }); + test("two queued empty pings in the same tick nudge then wait, not stop", async () => { let now = 3_000_000; const director = new SubAgentDirector( @@ -1269,7 +1333,7 @@ describe("SubAgentDirector stall nudge grace", () => { ); const caps = capabilities(); - await director.decide(inferenceDone(["read-1"]), state, caps); + await director.decide(inferenceDoneText("working"), state, caps); now += 1_000; const first = actions( await director.decide(messageReceived(""), state, caps), diff --git a/src/subagent/nudge-director.ts b/src/subagent/nudge-director.ts index a711d06a7..7f288f128 100644 --- a/src/subagent/nudge-director.ts +++ b/src/subagent/nudge-director.ts @@ -177,14 +177,19 @@ export class SubAgentDirector extends DefaultDirector { // (directors are pure decide(event, ...) functions — see requestContinuation // above), so the run loop periodically pings this same continuation channel // and the director only acts on a ping if genuinely nothing happened since - // the last one. Precedence: this check sits below the turn-boundary stop - // checks above (evaluateSubAgentStop) — those fire from real inference.done - // turns and always take priority; stall pings only ever fire on a - // continuation message that inference.done/tool.done handling did not + // the last one. In-flight tool calls are activity, not silence: a ping can + // arrive while execute_tools is still running, so pending call ids are + // tracked explicitly. Precedence: this check sits below the turn-boundary + // stop checks above (evaluateSubAgentStop) — those fire from real + // inference.done turns and always take priority; stall pings only ever fire + // on a continuation message that inference.done/tool.done handling did not // already consume this cycle. private readonly stallTimeoutMs: number | undefined; private readonly now: () => number; private lastActivityAt: number; + // Call ids from the last inference.done that have not yet seen tool.done. + // A stall ping mid-execute is not silence. + private readonly inFlightToolCallIds = new Set(); // Wall clock when the first stall nudge was issued. Later empty pings inside // stallTimeoutMs of this instant wait without stopping or restarting grace; // stop only after the grace elapses with no activity. Cleared on real @@ -331,6 +336,7 @@ export class SubAgentDirector extends DefaultDirector { this.turnsCompleted++; const content = event.turn.content as readonly { type: string; + id?: string; name?: string; arguments?: unknown; text?: string; @@ -341,6 +347,11 @@ export class SubAgentDirector extends DefaultDirector { this.toolLessNarrationCycles = 0; this.verbatimToolCallNudgeFired = false; this.thrashState = nextThrashState(this.thrashState, content); + for (const block of content) { + if (block.type === "tool_call" && typeof block.id === "string") { + this.inFlightToolCallIds.add(block.id); + } + } } const stop = evaluateSubAgentStop({ @@ -451,9 +462,10 @@ export class SubAgentDirector extends DefaultDirector { return terminal; } } - if (event.type === "tool.done") { + if (event.type === "tool.done" || event.type === "resume.tool_result") { this.lastActivityAt = this.now(); this.stallNudgeAt = undefined; + this.inFlightToolCallIds.delete(event.result.callId); if (event.result.isError === true) { // Failed-tool recovery guidance. Arm once; coalesce consecutive failure // audits until applyPendingNudge flushes a single counted record. @@ -475,11 +487,9 @@ export class SubAgentDirector extends DefaultDirector { /** * Reacts to the periodic stall-check ping (an empty-content continuation, * same channel compaction uses to re-enter an idle reactor) started by the - * run loop when stallTimeoutMs is configured. Only ever sees this event - * when the reactor is genuinely between cycles — a ping delivered while a - * tool call is still executing simply queues until that cycle finishes, so - * "no pending harness-tracked work" falls out of when this method can run - * at all rather than needing separate bookkeeping. + * run loop when stallTimeoutMs is configured. A ping can arrive while a + * tool call is still executing; those in-flight calls reset the silence + * clock and wait instead of nudging. * * First silence past the timeout: one continuation nudge, and record * stallNudgeAt. Queued pings that arrive inside the stallTimeoutMs grace @@ -496,6 +506,11 @@ export class SubAgentDirector extends DefaultDirector { if (event.type !== "message.received") return null; const content = event.message.content; if (typeof content !== "string" || content.length > 0) return null; + if (this.inFlightToolCallIds.size > 0) { + this.lastActivityAt = this.now(); + this.stallNudgeAt = undefined; + return [capabilities.wait()]; + } const elapsed = this.now() - this.lastActivityAt; if (elapsed < this.stallTimeoutMs) return null;