Skip to content

Commit 7d718aa

Browse files
fix(subagent): treat in-flight tools as stall activity (#1089)
* fix(subagent): treat in-flight tools as stall activity A long tool with no assistant text was measured as silence and got stall-nudge mid-call. Outstanding execute_tools now resets the clock. * fix(subagent): drop in-flight tool ids on resume.tool_result Parked-approval deny answers with resume.tool_result, not tool.done. Leaving the id outstanding would reset stall silence forever.
1 parent 52972c4 commit 7d718aa

3 files changed

Lines changed: 91 additions & 12 deletions

File tree

‎docs/ARCHITECTURE.md‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -161,7 +161,7 @@ The ChatDirector counts consecutive assistant turns that contain tool calls and
161161

162162
#### Sub-agent stall management
163163

164-
`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.
164+
`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.
165165

166166
**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).
167167

‎src/subagent/nudge-director.test.ts‎

Lines changed: 65 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -123,6 +123,13 @@ function toolDone(callId: string, isError = false): ReactorInboundEvent {
123123
} as unknown as ReactorInboundEvent;
124124
}
125125

126+
function resumeToolResult(callId: string): ReactorInboundEvent {
127+
return {
128+
type: "resume.tool_result",
129+
result: { callId, content: "denied by approver", isError: true },
130+
} as unknown as ReactorInboundEvent;
131+
}
132+
126133
function messageReceived(content: string): ReactorInboundEvent {
127134
return {
128135
type: "message.received",
@@ -1184,6 +1191,63 @@ describe("SubAgentDirector post-complete terminalization (CL-7068)", () => {
11841191
});
11851192

11861193
describe("SubAgentDirector stall nudge grace", () => {
1194+
test("long in-flight tool with no assistant text does not stall-nudge", async () => {
1195+
let now = 4_000_000;
1196+
const director = new SubAgentDirector(
1197+
"system",
1198+
[],
1199+
undefined,
1200+
1_000,
1201+
() => now,
1202+
);
1203+
const caps = capabilities();
1204+
1205+
await director.decide(inferenceDone(["slow-1"]), state, caps);
1206+
1207+
now += 60_000;
1208+
const midTool = actions(
1209+
await director.decide(messageReceived(""), state, caps),
1210+
);
1211+
expect(midTool).toEqual([{ type: "wait" }]);
1212+
1213+
await director.decide(toolDone("slow-1"), state, caps);
1214+
now += 1_000;
1215+
const afterTool = actions(
1216+
await director.decide(messageReceived(""), state, caps),
1217+
);
1218+
expect(afterTool).toContainEqual({
1219+
type: "checkpoint",
1220+
message: "subagent-stall-nudge",
1221+
});
1222+
});
1223+
1224+
test("resume.tool_result clears in-flight ids so later silence can stall-nudge", async () => {
1225+
let now = 5_000_000;
1226+
const director = new SubAgentDirector(
1227+
"system",
1228+
[],
1229+
undefined,
1230+
1_000,
1231+
() => now,
1232+
);
1233+
const caps = capabilities();
1234+
1235+
await director.decide(inferenceDone(["parked-1"]), state, caps);
1236+
now += 60_000;
1237+
expect(
1238+
actions(await director.decide(messageReceived(""), state, caps)),
1239+
).toEqual([{ type: "wait" }]);
1240+
1241+
await director.decide(resumeToolResult("parked-1"), state, caps);
1242+
now += 1_000;
1243+
expect(
1244+
actions(await director.decide(messageReceived(""), state, caps)),
1245+
).toContainEqual({
1246+
type: "checkpoint",
1247+
message: "subagent-stall-nudge",
1248+
});
1249+
});
1250+
11871251
test("two queued empty pings in the same tick nudge then wait, not stop", async () => {
11881252
let now = 3_000_000;
11891253
const director = new SubAgentDirector(
@@ -1269,7 +1333,7 @@ describe("SubAgentDirector stall nudge grace", () => {
12691333
);
12701334
const caps = capabilities();
12711335

1272-
await director.decide(inferenceDone(["read-1"]), state, caps);
1336+
await director.decide(inferenceDoneText("working"), state, caps);
12731337
now += 1_000;
12741338
const first = actions(
12751339
await director.decide(messageReceived(""), state, caps),

‎src/subagent/nudge-director.ts‎

Lines changed: 25 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -177,14 +177,19 @@ export class SubAgentDirector extends DefaultDirector {
177177
// (directors are pure decide(event, ...) functions — see requestContinuation
178178
// above), so the run loop periodically pings this same continuation channel
179179
// and the director only acts on a ping if genuinely nothing happened since
180-
// the last one. Precedence: this check sits below the turn-boundary stop
181-
// checks above (evaluateSubAgentStop) — those fire from real inference.done
182-
// turns and always take priority; stall pings only ever fire on a
183-
// continuation message that inference.done/tool.done handling did not
180+
// the last one. In-flight tool calls are activity, not silence: a ping can
181+
// arrive while execute_tools is still running, so pending call ids are
182+
// tracked explicitly. Precedence: this check sits below the turn-boundary
183+
// stop checks above (evaluateSubAgentStop) — those fire from real
184+
// inference.done turns and always take priority; stall pings only ever fire
185+
// on a continuation message that inference.done/tool.done handling did not
184186
// already consume this cycle.
185187
private readonly stallTimeoutMs: number | undefined;
186188
private readonly now: () => number;
187189
private lastActivityAt: number;
190+
// Call ids from the last inference.done that have not yet seen tool.done.
191+
// A stall ping mid-execute is not silence.
192+
private readonly inFlightToolCallIds = new Set<string>();
188193
// Wall clock when the first stall nudge was issued. Later empty pings inside
189194
// stallTimeoutMs of this instant wait without stopping or restarting grace;
190195
// stop only after the grace elapses with no activity. Cleared on real
@@ -331,6 +336,7 @@ export class SubAgentDirector extends DefaultDirector {
331336
this.turnsCompleted++;
332337
const content = event.turn.content as readonly {
333338
type: string;
339+
id?: string;
334340
name?: string;
335341
arguments?: unknown;
336342
text?: string;
@@ -341,6 +347,11 @@ export class SubAgentDirector extends DefaultDirector {
341347
this.toolLessNarrationCycles = 0;
342348
this.verbatimToolCallNudgeFired = false;
343349
this.thrashState = nextThrashState(this.thrashState, content);
350+
for (const block of content) {
351+
if (block.type === "tool_call" && typeof block.id === "string") {
352+
this.inFlightToolCallIds.add(block.id);
353+
}
354+
}
344355
}
345356

346357
const stop = evaluateSubAgentStop({
@@ -451,9 +462,10 @@ export class SubAgentDirector extends DefaultDirector {
451462
return terminal;
452463
}
453464
}
454-
if (event.type === "tool.done") {
465+
if (event.type === "tool.done" || event.type === "resume.tool_result") {
455466
this.lastActivityAt = this.now();
456467
this.stallNudgeAt = undefined;
468+
this.inFlightToolCallIds.delete(event.result.callId);
457469
if (event.result.isError === true) {
458470
// Failed-tool recovery guidance. Arm once; coalesce consecutive failure
459471
// audits until applyPendingNudge flushes a single counted record.
@@ -475,11 +487,9 @@ export class SubAgentDirector extends DefaultDirector {
475487
/**
476488
* Reacts to the periodic stall-check ping (an empty-content continuation,
477489
* same channel compaction uses to re-enter an idle reactor) started by the
478-
* run loop when stallTimeoutMs is configured. Only ever sees this event
479-
* when the reactor is genuinely between cycles — a ping delivered while a
480-
* tool call is still executing simply queues until that cycle finishes, so
481-
* "no pending harness-tracked work" falls out of when this method can run
482-
* at all rather than needing separate bookkeeping.
490+
* run loop when stallTimeoutMs is configured. A ping can arrive while a
491+
* tool call is still executing; those in-flight calls reset the silence
492+
* clock and wait instead of nudging.
483493
*
484494
* First silence past the timeout: one continuation nudge, and record
485495
* stallNudgeAt. Queued pings that arrive inside the stallTimeoutMs grace
@@ -496,6 +506,11 @@ export class SubAgentDirector extends DefaultDirector {
496506
if (event.type !== "message.received") return null;
497507
const content = event.message.content;
498508
if (typeof content !== "string" || content.length > 0) return null;
509+
if (this.inFlightToolCallIds.size > 0) {
510+
this.lastActivityAt = this.now();
511+
this.stallNudgeAt = undefined;
512+
return [capabilities.wait()];
513+
}
499514
const elapsed = this.now() - this.lastActivityAt;
500515
if (elapsed < this.stallTimeoutMs) return null;
501516

0 commit comments

Comments
 (0)