Skip to content

Commit 7390f7e

Browse files
committed
Log every stop/nudge intervention (CL-6938)
Fourteen stop reasons and ~20 injected-text interventions decide when a run is stuck, and there was no way to tell how often any of them was wrong. Four threshold judgments in this tree were later reverted, one on a justification the file itself retracts. interventions.jsonl in the firing worker's trace dir now records each intervention with its measured value beside the threshold it crossed, the provider/model/family, and the run state at that moment — turns used vs budget, tool calls, read and edit counts. A refused parent re-dispatch is recorded on the parent side, where no leaf run exists to record it. Writes are fire-and-forget and swallow their own errors: a diagnostic must not be able to fail a run. The sink defaults to a no-op, so nothing depends on logging being wired. scripts/intervention-forensics.ts aggregates across local sessions: per intervention counts by family, measured-value distribution against threshold, and two false-positive proxies — stops that fired on runs which had already edited files, and stops that fired before half the turn budget was spent. It lstats and skips symlinks so the `latest` session link cannot double-count. Stacked on cl-6937.
1 parent 5c8466a commit 7390f7e

9 files changed

Lines changed: 569 additions & 4 deletions

File tree

‎CHANGELOG.md‎

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,15 @@ parallel copies under `docs/` or `scripts/notes/`. At cut time: rename
1515

1616
### Agent
1717

18+
- **Every stop and nudge is now logged.** `interventions.jsonl` in the worker's
19+
trace dir records each intervention with its measured value beside the
20+
threshold it crossed, the model family it fired on, and the run state at that
21+
moment — plus refused parent re-dispatches. `bun run
22+
scripts/intervention-forensics.ts` aggregates them: counts by family, value
23+
distribution against threshold, and two false-positive proxies (stops on runs
24+
that had already edited files, stops before half the turn budget). Threshold
25+
changes can now cite data instead of judgment.
26+
1827
- **Shell file work counts as evidence.** A worker that edited with `sed -i`, a
1928
heredoc, or `>` redirection had `editedPaths` empty and salvaged as
2029
`never-edited` — a sticky hard block that then refused the parent an identical

‎docs/ARCHITECTURE.md‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -152,6 +152,8 @@ Because the operator explicitly wants long autonomous runs to keep going, reachi
152152

153153
`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 leaf (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 gets one continuation nudge (asking the leaf to check on the background work or report status); a second **consecutive** stall (no activity since that nudge) escalates to the existing salvage path, returning a `stalled` `forcedStopReport` with the same structured shape (summary/findings/blockers) as `no-progress` / `turn-budget` / `thrash` / `never-acted` / `never-edited`. Any real activity between pings resets the streak, so a leaf that is genuinely working through a slow single turn is never penalized.
154154

155+
**Intervention log**: every stop and nudge is appended as one JSONL record to `interventions.jsonl` in the firing leaf'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 leaf run exists to record it. 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, and two false-positive proxies (stops that fired on runs which had already edited files; stops that fired before half the turn budget was spent). 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).
156+
155157
**Precedence**: stall detection sits **below** no-progress and turn-budget — those are evaluated from real `inference.done` turns inside `evaluateSubAgentStop` and always take priority; the stall check only ever fires on a continuation ping that inference/tool-result handling did not already consume that cycle. Report-forced (near-budget wrap-up) is an independent one-shot, turn-count-driven signal, not a competing stop reason in the sense no-progress/turn-budget are. Stall nudging is wall-clock driven and likewise independent of both.
156158

157159
The reactor only persists a response turn to `turns.jsonl` on `inference.done`, so a cycle that is cancelled, aborted, errors, or is otherwise interrupted mid-stream would leave nothing behind. A cycle-text recorder (`src/session/stream-journal.ts`) closes that gap by buffering the in-flight cycle's streamed text in memory — no writes on the happy path — and appending one JSON record (`{reason, chars, text}`) to `partial.jsonl`, alongside `turns.jsonl` in the session context dir, on abnormal cycle end. It is wired into the sub-agent run loop, the exec runner (flushed on failed sends), and the TUI runner (flushed on interrupt and on session rotation, before the context dir is repointed).

‎scripts/intervention-forensics.ts‎

Lines changed: 165 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,165 @@
1+
// Aggregate scan over the intervention logs written by src/subagent/intervention-log.ts
2+
// (~/.corbits/projects/**/interventions.jsonl) — the data that has to exist
3+
// before any stop/nudge threshold is changed again (CL-6938).
4+
//
5+
// Reports, per intervention id: how often it fired, split by model family, with
6+
// the measured value distribution beside the threshold it crossed, and two
7+
// false-positive proxies:
8+
//
9+
// editedWork — stops that fired on a run which had already edited files.
10+
// A stop claiming nothing shipped, on a run that shipped.
11+
// earlyBudget — stops that fired before half the turn budget was spent.
12+
// A run declared stuck while most of its budget was unused.
13+
//
14+
// Neither proxy is proof on its own; both are cheap and directional, which is
15+
// what the tuning history has been missing.
16+
//
17+
// Run: bun run scripts/intervention-forensics.ts
18+
//
19+
// Prints only aggregate counts and the `detail` field's first token, never turn
20+
// content, so it is safe to run without pulling trace data into a context window.
21+
22+
import { readdirSync, lstatSync, readFileSync } from "node:fs";
23+
import { join } from "node:path";
24+
import { homedir } from "node:os";
25+
26+
import { INTERVENTION_FILE, type InterventionRecord } from "../src/subagent/intervention-log.js";
27+
28+
// lstat, and skip symlinks: session dirs carry a `latest` symlink to a real
29+
// session, and following it double-counts every record in that session.
30+
function findAll(dir: string, name: string, out: string[]): void {
31+
let entries: string[];
32+
try {
33+
entries = readdirSync(dir);
34+
} catch {
35+
return;
36+
}
37+
for (const entry of entries) {
38+
const path = join(dir, entry);
39+
let info: ReturnType<typeof lstatSync>;
40+
try {
41+
info = lstatSync(path);
42+
} catch {
43+
continue;
44+
}
45+
if (info.isSymbolicLink()) continue;
46+
if (info.isDirectory()) findAll(path, name, out);
47+
else if (entry === name) out.push(path);
48+
}
49+
}
50+
51+
function percentile(sorted: readonly number[], p: number): number {
52+
if (sorted.length === 0) return 0;
53+
const index = Math.min(sorted.length - 1, Math.floor((p / 100) * sorted.length));
54+
return sorted[index]!;
55+
}
56+
57+
interface Bucket {
58+
count: number;
59+
byFamily: Map<string, number>;
60+
values: number[];
61+
thresholds: Set<number>;
62+
editedWork: number;
63+
earlyBudget: number;
64+
}
65+
66+
function emptyBucket(): Bucket {
67+
return {
68+
count: 0,
69+
byFamily: new Map(),
70+
values: [],
71+
thresholds: new Set(),
72+
editedWork: 0,
73+
earlyBudget: 0,
74+
};
75+
}
76+
77+
const root = join(homedir(), ".corbits", "projects");
78+
const files: string[] = [];
79+
findAll(root, INTERVENTION_FILE, files);
80+
81+
const buckets = new Map<string, Bucket>();
82+
let records = 0;
83+
let malformed = 0;
84+
85+
for (const file of files) {
86+
let lines: string[];
87+
try {
88+
lines = readFileSync(file, "utf8").split("\n");
89+
} catch {
90+
continue;
91+
}
92+
for (const line of lines) {
93+
if (line.trim().length === 0) continue;
94+
let record: InterventionRecord;
95+
try {
96+
record = JSON.parse(line) as InterventionRecord;
97+
} catch {
98+
malformed++;
99+
continue;
100+
}
101+
if (typeof record.id !== "string") {
102+
malformed++;
103+
continue;
104+
}
105+
records++;
106+
const key = `${record.class ?? "?"}/${record.id}`;
107+
let bucket = buckets.get(key);
108+
if (bucket === undefined) {
109+
bucket = emptyBucket();
110+
buckets.set(key, bucket);
111+
}
112+
bucket.count++;
113+
const family = record.family ?? record.model ?? "unknown";
114+
bucket.byFamily.set(family, (bucket.byFamily.get(family) ?? 0) + 1);
115+
if (record.measurement !== undefined) {
116+
bucket.values.push(record.measurement.value);
117+
if (record.measurement.threshold !== undefined) {
118+
bucket.thresholds.add(record.measurement.threshold);
119+
}
120+
}
121+
const state = record.state;
122+
if (record.class === "stop" && state !== undefined) {
123+
if ((state.editedPaths ?? 0) > 0) bucket.editedWork++;
124+
const turns = state.turnsCompleted ?? 0;
125+
const max = state.maxTurns ?? 0;
126+
if (max > 0 && turns < max / 2) bucket.earlyBudget++;
127+
}
128+
}
129+
}
130+
131+
console.log(`intervention logs: ${files.length}`);
132+
console.log(`records: ${records}${malformed > 0 ? ` (${malformed} malformed, skipped)` : ""}`);
133+
if (records === 0) {
134+
console.log("\nNo interventions logged yet. Run some sessions first.");
135+
process.exit(0);
136+
}
137+
138+
const rows = [...buckets.entries()].sort((a, b) => b[1].count - a[1].count);
139+
console.log(
140+
"\nintervention n value p50/p90/max threshold edited early",
141+
);
142+
for (const [key, bucket] of rows) {
143+
const sorted = [...bucket.values].sort((a, b) => a - b);
144+
const dist =
145+
sorted.length === 0
146+
? "-"
147+
: `${percentile(sorted, 50)}/${percentile(sorted, 90)}/${sorted[sorted.length - 1]!}`;
148+
const thresholds = bucket.thresholds.size === 0 ? "-" : [...bucket.thresholds].join(",");
149+
console.log(
150+
`${key.padEnd(33)} ${String(bucket.count).padStart(3)} ${dist.padEnd(16)} ${thresholds.padEnd(10)} ${String(bucket.editedWork).padStart(5)} ${String(bucket.earlyBudget).padStart(5)}`,
151+
);
152+
}
153+
154+
console.log("\nby family");
155+
for (const [key, bucket] of rows) {
156+
const families = [...bucket.byFamily.entries()]
157+
.sort((a, b) => b[1] - a[1])
158+
.map(([family, count]) => `${family}=${count}`)
159+
.join(" ");
160+
console.log(`${key.padEnd(33)} ${families}`);
161+
}
162+
163+
console.log(
164+
"\nedited = stops on runs that had already edited files; early = stops before half the turn budget.",
165+
);

‎src/subagent/index.test.ts‎

Lines changed: 36 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1121,6 +1121,42 @@ describe("SubAgentDirector report-forced wiring", () => {
11211121
return Array.isArray(result) ? result : [result];
11221122
}
11231123

1124+
test("stops and nudges are recorded with their measured value and threshold (CL-6938)", async () => {
1125+
const director = new SubAgentDirector("system", [], undefined, 3);
1126+
const capabilities = makeCapabilities();
1127+
const recorded: { id: string; class: string; value?: number; threshold?: number }[] = [];
1128+
director.observeInterventions((event) => {
1129+
recorded.push({
1130+
id: event.id,
1131+
class: event.class,
1132+
...(event.measurement !== undefined
1133+
? {
1134+
value: event.measurement.value,
1135+
...(event.measurement.threshold !== undefined
1136+
? { threshold: event.measurement.threshold }
1137+
: {}),
1138+
}
1139+
: {}),
1140+
});
1141+
});
1142+
1143+
// Turn 1 of 3 fires report-forced (a nudge); repeating one identical call
1144+
// to the repeat limit then fires no-progress (a stop).
1145+
for (let i = 0; i < 6; i++) {
1146+
await director.decide(
1147+
makeInferenceDoneEvent([{ id: "r1", name: "read_file", args: { path: "a.ts" } }]),
1148+
mockState,
1149+
capabilities,
1150+
);
1151+
}
1152+
1153+
const nudge = recorded.find((r) => r.id === "report-forced");
1154+
expect(nudge?.class).toBe("nudge");
1155+
const stop = recorded.find((r) => r.id === "no-progress");
1156+
expect(stop?.class).toBe("stop");
1157+
expect(stop?.value).toBeGreaterThanOrEqual(stop?.threshold ?? 0);
1158+
});
1159+
11241160
// maxTurns=3, forceReportWithin (default 2) → report-forced fires exactly
11251161
// at turnsCompleted===1, leaving turns 2 and 3 for turn-budget to remain
11261162
// reachable (regression for the report-forced turn-budget blocker).
Lines changed: 94 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,94 @@
1+
import { describe, expect, test } from "bun:test";
2+
import { mkdtemp, readFile } from "node:fs/promises";
3+
import { tmpdir } from "node:os";
4+
import { join } from "node:path";
5+
6+
import {
7+
createInterventionLog,
8+
INTERVENTION_FILE,
9+
NOOP_INTERVENTION_SINK,
10+
type InterventionRecord,
11+
} from "./intervention-log.js";
12+
13+
async function readRecords(dir: string): Promise<InterventionRecord[]> {
14+
const raw = await readFile(join(dir, INTERVENTION_FILE), "utf8");
15+
return raw
16+
.split("\n")
17+
.filter((line) => line.trim().length > 0)
18+
.map((line) => JSON.parse(line) as InterventionRecord);
19+
}
20+
21+
async function flush(): Promise<void> {
22+
// Appends are fire-and-forget; yield until the chained writes settle.
23+
for (let i = 0; i < 20; i++) await Promise.resolve();
24+
await new Promise((resolve) => setTimeout(resolve, 10));
25+
}
26+
27+
describe("intervention log (CL-6938)", () => {
28+
test("records carry the shared context, the measurement, and the run state", async () => {
29+
const dir = await mkdtemp(join(tmpdir(), "intervention-log-"));
30+
const sink = createInterventionLog(
31+
dir,
32+
{
33+
role: "leaf",
34+
provider: "xai",
35+
model: "grok-4.6",
36+
family: "grok",
37+
intent: "implement",
38+
},
39+
() => new Date("2026-08-23T12:00:00.000Z"),
40+
);
41+
42+
sink({
43+
id: "no-progress",
44+
class: "stop",
45+
measurement: { metric: "consecutiveIdentical", value: 5, threshold: 5 },
46+
state: { turnsCompleted: 7, maxTurns: 30, editedPaths: 2 },
47+
detail: "identical tool call × 5",
48+
});
49+
await flush();
50+
51+
const [record] = await readRecords(dir);
52+
expect(record).toBeDefined();
53+
expect(record?.ts).toBe("2026-08-23T12:00:00.000Z");
54+
expect(record?.id).toBe("no-progress");
55+
expect(record?.class).toBe("stop");
56+
expect(record?.family).toBe("grok");
57+
expect(record?.intent).toBe("implement");
58+
expect(record?.measurement).toEqual({
59+
metric: "consecutiveIdentical",
60+
value: 5,
61+
threshold: 5,
62+
});
63+
// The false-positive proxy the forensics script reads: a stop that fired on
64+
// a run which had already edited files.
65+
expect(record?.state?.editedPaths).toBe(2);
66+
});
67+
68+
test("appends in order, one JSON object per line", async () => {
69+
const dir = await mkdtemp(join(tmpdir(), "intervention-log-"));
70+
const sink = createInterventionLog(dir, { role: "leaf" });
71+
sink({ id: "report-forced", class: "nudge" });
72+
sink({ id: "turn-budget", class: "stop" });
73+
await flush();
74+
75+
const records = await readRecords(dir);
76+
expect(records.map((r) => r.id)).toEqual(["report-forced", "turn-budget"]);
77+
});
78+
79+
test("a write failure never throws into the caller", async () => {
80+
const sink = createInterventionLog(join(tmpdir(), "intervention-log-missing-dir-xyz"), {
81+
role: "leaf",
82+
});
83+
expect(() => {
84+
sink({ id: "stalled", class: "stop" });
85+
}).not.toThrow();
86+
await flush();
87+
});
88+
89+
test("the no-op sink accepts events and writes nothing", () => {
90+
expect(() => {
91+
NOOP_INTERVENTION_SINK({ id: "no-progress", class: "stop" });
92+
}).not.toThrow();
93+
});
94+
});

0 commit comments

Comments
 (0)