Skip to content

Commit e9c085d

Browse files
Merge pull request #567 from corbitsdev/cl-5666-approval-ask-settle-event-log
Log every approval ask and how it settles (CL-5666)
2 parents c80fbe5 + 6fad4cc commit e9c085d

10 files changed

Lines changed: 662 additions & 7 deletions

File tree

CHANGELOG.md

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

4848
## [0.2.105] - 2026-08-23
4949

50+
### Permissions
51+
52+
- **Every approval ask and how it settles is now logged.** `approvals.jsonl`
53+
in the session dir records each consequential decision — auto-mode
54+
allow/deny, or an operator prompt's allow-once / allow-with-scope / deny /
55+
timeout / abort — with the classifier rule that triggered it, queued /
56+
displayed / settled timestamps, and shell chain segment count. No command
57+
text, path, or credential is ever recorded; writes are fire-and-forget and
58+
never fail a run. `scripts/approval-forensics.ts` aggregates across local
59+
sessions.
60+
5061
### Agent
5162

5263
- **Context estimate syncs incrementally on append.** `syncFromTurns` keys

docs/ARCHITECTURE.md

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -376,6 +376,8 @@ tool call
376376
- **queue** — Headless settle registry (`src/permission/queue.ts`). Surfaces enqueue outstanding requests; `wirePermissionGrantReconciliation` listens for `permission.grant` and drains every queued request the new grant covers, without a second prompt. Teardown calls `drain()` so no awaited resolve is left hanging.
377377
- **types**`Approval`, `ApprovalScope`, `PermissionRequest`, `ApprovalOutcome`.
378378

379+
**Approval log** (`src/permission/approval-log.ts`, CL-5666): every consequential decision the gate makes — auto-mode allow/deny or an interactive prompt's allow-once/allow-with-scope/deny/timeout/abort — is appended as one JSONL record to `approvals.jsonl` in the session dir, carrying the classifier/auto-shell rule name that fired (the existing `auto-shell-policy.ts`/`classify.ts` rule names, plus a small closed set of additional fixed literals the log itself defines for decisions those modules don't otherwise name — `auto-allowed-tool`, `non-interactive`, `mega-chain` — never model- or user-authored text), whether the decision was `auto` or `interactive`, a shell chain's segment count, and queued/displayed/settled timestamps. `displayedAt` is set by `PermissionRequest.markDisplayed`, called from `gate-wire.ts`'s `open()` the moment a request actually reaches the overlay host — distinct from when it was raised, so the gap it exposes is the CL-5664 signal (a queued gate arming its timeout before the operator could see it). No command text, file content, path, credential, or other free text is ever recorded — only tool name, rule, mode, segment count, and timing; a sub-agent's free-text dispatch label is deliberately left out, even though it would enable a per-agent breakdown, because nothing constrains what a model puts in it. A hard size cap on the serialized line is defense in depth against a future field reintroducing free text. Writes are fire-and-forget and swallow their own errors; the log defaults to a no-op so nothing depends on it being wired. `scripts/approval-forensics.ts` aggregates across local sessions the same way `intervention-forensics.ts` does for stop/nudge events: per-tool counts by outcome and mode, duration/display-delay percentiles, mega-chain counts, and a duplicate-rate proxy (sessions that hit the same rule more than once).
380+
379381
**Tool wall-clock budget vs. permission prompts.** Each tool `run()` is wrapped by an outer execution watchdog (`src/tui/tool-execution-watchdog.ts`). The watchdog arms only when Settings set `tools.timeoutMs` / `tools.maxTimeoutMs`, or when `run_shell` passes a positive timeout (requested plus slack, so this layer cannot beat shell-guard). The `task` tool is always exempt, regardless of Settings — a sub-agent run is bounded by its own limits (maxTurns, no-progress, thrash, opt-in deadlineMs), so the generic per-tool budget never aborts a healthy long-running worker; parent cancel, maxTurns, and eval `--agent-timeout-ms` still bound the run. By default (`tools.waitForApproval`, Settings → Tools, **On**), an armed budget freezes while the operator is deciding on a permission prompt, so a late approve still runs the tool and the agent waits for the decision instead of timing out under the modal. When **Off**, the budget keeps ticking during the prompt; if it expires first the tool is skipped and the permission modal is dismissed via the budget AbortSignal (auto-deny with a timeout message). The TUI permission queue (`src/tui/gate-wire.ts`, backed by `src/permission/queue.ts`) attaches that signal so ghost prompts cannot outlive an already-aborted tool.
380382

381383
`mcp__*` tool calls are the exception to "arms only when Settings set it": they arm unconditionally with a 5-minute default (`DEFAULT_MCP_TOOL_TIMEOUT_MS`), overridable via `mcp.timeoutMs` and still capped by `tools.maxTimeoutMs` (CL-6895). Nothing else bounds an MCP call — the stall watchdog treats an in-flight tool as activity by design, so a wedged MCP server previously hung a tool call, and the turn, forever. On expiry the call returns a normal tool-error result ("MCP tool `<name>` timed out after `<n>`s — the server may be wedged; retry or continue without it"); the turn is never aborted. The MCP client itself (`src/mcp/client.ts`, wrapping `@modelcontextprotocol/sdk`) multiplexes concurrent requests over one connection by JSON-RPC message id with no serial queue or mutex in our code or in the vendored SDK's `Protocol.request()` — so concurrent calls to the same server are not expected to deadlock each other. Live forensics for CL-6895 showed multi-minute MCP calls that eventually completed successfully, consistent with a slow server response rather than a client-side deadlock.

scripts/approval-forensics.ts

Lines changed: 170 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,170 @@
1+
// Aggregate scan over the approval logs written by src/permission/approval-log.ts
2+
// (~/.corbits/projects/**/approvals.jsonl) — the data CL-5666 needed to exist
3+
// before approval volume could be measured at all.
4+
//
5+
// Reports: total asks, split by mode (auto vs interactive) and outcome, a
6+
// per-rule breakdown, settle-duration and display-delay percentiles (the
7+
// display delay is the CL-5664 signal — a queued gate arming its timeout
8+
// before the operator could see it), and a mega-chain count (segments >=
9+
// MEGA_CHAIN_SEGMENT_THRESHOLD).
10+
//
11+
// Prints only aggregate counts and timings, never a tool subject or command
12+
// text — the log itself never records either, so there is nothing to leak
13+
// here even by accident.
14+
//
15+
// Run: bun run scripts/approval-forensics.ts
16+
17+
import { readdirSync, lstatSync, readFileSync } from "node:fs";
18+
import { join } from "node:path";
19+
import { homedir } from "node:os";
20+
21+
import { APPROVAL_LOG_FILE, type ApprovalRecord } from "../src/permission/approval-log.js";
22+
import { MEGA_CHAIN_SEGMENT_THRESHOLD } from "../src/permission/classify.js";
23+
24+
// lstat, and skip symlinks: session dirs carry a `latest` symlink to a real
25+
// session, and following it double-counts every record in that session.
26+
function findAll(dir: string, name: string, out: string[]): void {
27+
let entries: string[];
28+
try {
29+
entries = readdirSync(dir);
30+
} catch {
31+
return;
32+
}
33+
for (const entry of entries) {
34+
const path = join(dir, entry);
35+
let info: ReturnType<typeof lstatSync>;
36+
try {
37+
info = lstatSync(path);
38+
} catch {
39+
continue;
40+
}
41+
if (info.isSymbolicLink()) continue;
42+
if (info.isDirectory()) findAll(path, name, out);
43+
else if (entry === name) out.push(path);
44+
}
45+
}
46+
47+
function percentile(sorted: readonly number[], p: number): number {
48+
if (sorted.length === 0) return 0;
49+
const index = Math.min(sorted.length - 1, Math.floor((p / 100) * sorted.length));
50+
return sorted[index]!;
51+
}
52+
53+
interface Bucket {
54+
count: number;
55+
byOutcome: Map<string, number>;
56+
byMode: Map<string, number>;
57+
durations: number[];
58+
displayDelays: number[];
59+
megaChains: number;
60+
}
61+
62+
function emptyBucket(): Bucket {
63+
return {
64+
count: 0,
65+
byOutcome: new Map(),
66+
byMode: new Map(),
67+
durations: [],
68+
displayDelays: [],
69+
megaChains: 0,
70+
};
71+
}
72+
73+
const root = join(homedir(), ".corbits", "projects");
74+
const files: string[] = [];
75+
findAll(root, APPROVAL_LOG_FILE, files);
76+
77+
const buckets = new Map<string, Bucket>();
78+
const sessionsByRule = new Map<string, Set<string>>();
79+
let records = 0;
80+
let malformed = 0;
81+
82+
for (const file of files) {
83+
let lines: string[];
84+
try {
85+
lines = readFileSync(file, "utf8").split("\n");
86+
} catch {
87+
continue;
88+
}
89+
for (const line of lines) {
90+
if (line.trim().length === 0) continue;
91+
let record: ApprovalRecord;
92+
try {
93+
record = JSON.parse(line) as ApprovalRecord;
94+
} catch {
95+
malformed++;
96+
continue;
97+
}
98+
if (typeof record.tool !== "string" || typeof record.outcome !== "string") {
99+
malformed++;
100+
continue;
101+
}
102+
records++;
103+
const key = record.tool;
104+
let bucket = buckets.get(key);
105+
if (bucket === undefined) {
106+
bucket = emptyBucket();
107+
buckets.set(key, bucket);
108+
}
109+
bucket.count++;
110+
bucket.byOutcome.set(record.outcome, (bucket.byOutcome.get(record.outcome) ?? 0) + 1);
111+
bucket.byMode.set(record.mode, (bucket.byMode.get(record.mode) ?? 0) + 1);
112+
if (typeof record.durationMs === "number") bucket.durations.push(record.durationMs);
113+
if (typeof record.displayDelayMs === "number") bucket.displayDelays.push(record.displayDelayMs);
114+
if ((record.segments ?? 0) >= MEGA_CHAIN_SEGMENT_THRESHOLD) bucket.megaChains++;
115+
116+
// Duplicate-rate proxy: how often the same rule fires more than once per
117+
// session file (a session repeatedly asking for something it was already
118+
// told no/yes to under a different subject).
119+
if (record.rule !== undefined) {
120+
const sessions = sessionsByRule.get(record.rule) ?? new Set<string>();
121+
sessions.add(file);
122+
sessionsByRule.set(record.rule, sessions);
123+
}
124+
}
125+
}
126+
127+
console.log(`approval logs: ${files.length}`);
128+
console.log(`records: ${records}${malformed > 0 ? ` (${malformed} malformed, skipped)` : ""}`);
129+
if (records === 0) {
130+
console.log("\nNo approvals logged yet. Run some sessions first.");
131+
process.exit(0);
132+
}
133+
134+
const rows = [...buckets.entries()].sort((a, b) => b[1].count - a[1].count);
135+
console.log(
136+
"\ntool n auto/interactive duration p50/p90/max displayDelay p50/p90/max megaChains",
137+
);
138+
for (const [key, bucket] of rows) {
139+
const durations = [...bucket.durations].sort((a, b) => a - b);
140+
const delays = [...bucket.displayDelays].sort((a, b) => a - b);
141+
const durDist =
142+
durations.length === 0
143+
? "-"
144+
: `${percentile(durations, 50)}/${percentile(durations, 90)}/${durations[durations.length - 1]!}`;
145+
const delayDist =
146+
delays.length === 0
147+
? "-"
148+
: `${percentile(delays, 50)}/${percentile(delays, 90)}/${delays[delays.length - 1]!}`;
149+
const autoCount = bucket.byMode.get("auto") ?? 0;
150+
const interactiveCount = bucket.byMode.get("interactive") ?? 0;
151+
console.log(
152+
`${key.padEnd(26)} ${String(bucket.count).padStart(3)} ${String(autoCount).padStart(4)}/${String(interactiveCount).padEnd(11)} ${durDist.padEnd(24)} ${delayDist.padEnd(24)} ${bucket.megaChains}`,
153+
);
154+
}
155+
156+
console.log("\nby outcome");
157+
for (const [key, bucket] of rows) {
158+
const outcomes = [...bucket.byOutcome.entries()]
159+
.sort((a, b) => b[1] - a[1])
160+
.map(([outcome, count]) => `${outcome}=${count}`)
161+
.join(" ");
162+
console.log(`${key.padEnd(26)} ${outcomes}`);
163+
}
164+
165+
console.log("\nrule -> sessions that hit it at least once (duplicate-rate proxy)");
166+
for (const [rule, sessions] of [...sessionsByRule.entries()].sort(
167+
(a, b) => b[1].size - a[1].size,
168+
)) {
169+
console.log(`${rule.padEnd(26)} ${sessions.size}`);
170+
}

src/exec/runner.ts

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -51,6 +51,7 @@ import { OPERATOR_ORIGINATED_FLAG } from "../agent/message-provenance.js";
5151
import { createChatDirector } from "../agent/director.js";
5252
import { loadAgentProfiles } from "../agent/profiles.js";
5353
import { createPermissionGate } from "../permission/gate.js";
54+
import { createApprovalLog } from "../permission/approval-log.js";
5455
import { createWorktreeRootsProvider } from "../permission/worktree-roots.js";
5556
import type { ApprovalOutcome, PermissionRequest } from "../permission/types.js";
5657
import { createAgentToolset, type AgentToolset, type OperatorResult } from "../agent/tools.js";
@@ -366,6 +367,7 @@ export async function runExec(config: Config): Promise<ExecResult> {
366367
requestApproval: (request: PermissionRequest): Promise<ApprovalOutcome> =>
367368
promptPermission(request, interactive),
368369
persist: createApprovalPersist(config.cwd, activeProviderModel),
370+
approvalLog: createApprovalLog(sessionDir(config.cwd, sessionId)),
369371
interactive,
370372
skipPermissions: config.dangerouslySkipPermissions,
371373
auto: config.auto,

0 commit comments

Comments
 (0)