Log every approval ask and how it settles (CL-5666)

CHANGELOG.md

@@ -13,6 +13,17 @@ parallel copies under `docs/` or `scripts/notes/`. At cut time: rename
 
 ## [0.2.105] - 2026-08-23
 
+### Permissions
+
+- **Every approval ask and how it settles is now logged.** `approvals.jsonl`
+  in the session dir records each consequential decision — auto-mode
+  allow/deny, or an operator prompt's allow-once / allow-with-scope / deny /
+  timeout / abort — with the classifier rule that triggered it, queued /
+  displayed / settled timestamps, and shell chain segment count. No command
+  text, path, or credential is ever recorded; writes are fire-and-forget and
+  never fail a run. `scripts/approval-forensics.ts` aggregates across local
+  sessions.
+
 ### Agent
 
 - **Context estimate syncs incrementally on append.** `syncFromTurns` keys

docs/ARCHITECTURE.md

@@ -374,6 +374,8 @@ tool call
 - **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.
 - **types** — `Approval`, `ApprovalScope`, `PermissionRequest`, `ApprovalOutcome`.
 
+**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).
+
 **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.
 
 `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

@@ -0,0 +1,170 @@
+// Aggregate scan over the approval logs written by src/permission/approval-log.ts
+// (~/.corbits/projects/**/approvals.jsonl) — the data CL-5666 needed to exist
+// before approval volume could be measured at all.
+//
+// Reports: total asks, split by mode (auto vs interactive) and outcome, a
+// per-rule breakdown, settle-duration and display-delay percentiles (the
+// display delay is the CL-5664 signal — a queued gate arming its timeout
+// before the operator could see it), and a mega-chain count (segments >=
+// MEGA_CHAIN_SEGMENT_THRESHOLD).
+//
+// Prints only aggregate counts and timings, never a tool subject or command
+// text — the log itself never records either, so there is nothing to leak
+// here even by accident.
+//
+// Run: bun run scripts/approval-forensics.ts
+
+import { readdirSync, lstatSync, readFileSync } from "node:fs";
+import { join } from "node:path";
+import { homedir } from "node:os";
+
+import { APPROVAL_LOG_FILE, type ApprovalRecord } from "../src/permission/approval-log.js";
+import { MEGA_CHAIN_SEGMENT_THRESHOLD } from "../src/permission/classify.js";
+
+// lstat, and skip symlinks: session dirs carry a `latest` symlink to a real
+// session, and following it double-counts every record in that session.
+function findAll(dir: string, name: string, out: string[]): void {
+  let entries: string[];
+  try {
+    entries = readdirSync(dir);
+  } catch {
+    return;
+  }
+  for (const entry of entries) {
+    const path = join(dir, entry);
+    let info: ReturnType<typeof lstatSync>;
+    try {
+      info = lstatSync(path);
+    } catch {
+      continue;
+    }
+    if (info.isSymbolicLink()) continue;
+    if (info.isDirectory()) findAll(path, name, out);
+    else if (entry === name) out.push(path);
+  }
+}
+
+function percentile(sorted: readonly number[], p: number): number {
+  if (sorted.length === 0) return 0;
+  const index = Math.min(sorted.length - 1, Math.floor((p / 100) * sorted.length));
+  return sorted[index]!;
+}
+
+interface Bucket {
+  count: number;
+  byOutcome: Map<string, number>;
+  byMode: Map<string, number>;
+  durations: number[];
+  displayDelays: number[];
+  megaChains: number;
+}
+
+function emptyBucket(): Bucket {
+  return {
+    count: 0,
+    byOutcome: new Map(),
+    byMode: new Map(),
+    durations: [],
+    displayDelays: [],
+    megaChains: 0,
+  };
+}
+
+const root = join(homedir(), ".corbits", "projects");
+const files: string[] = [];
+findAll(root, APPROVAL_LOG_FILE, files);
+
+const buckets = new Map<string, Bucket>();
+const sessionsByRule = new Map<string, Set<string>>();
+let records = 0;
+let malformed = 0;
+
+for (const file of files) {
+  let lines: string[];
+  try {
+    lines = readFileSync(file, "utf8").split("\n");
+  } catch {
+    continue;
+  }
+  for (const line of lines) {
+    if (line.trim().length === 0) continue;
+    let record: ApprovalRecord;
+    try {
+      record = JSON.parse(line) as ApprovalRecord;
+    } catch {
+      malformed++;
+      continue;
+    }
+    if (typeof record.tool !== "string" || typeof record.outcome !== "string") {
+      malformed++;
+      continue;
+    }
+    records++;
+    const key = record.tool;
+    let bucket = buckets.get(key);
+    if (bucket === undefined) {
+      bucket = emptyBucket();
+      buckets.set(key, bucket);
+    }
+    bucket.count++;
+    bucket.byOutcome.set(record.outcome, (bucket.byOutcome.get(record.outcome) ?? 0) + 1);
+    bucket.byMode.set(record.mode, (bucket.byMode.get(record.mode) ?? 0) + 1);
+    if (typeof record.durationMs === "number") bucket.durations.push(record.durationMs);
+    if (typeof record.displayDelayMs === "number") bucket.displayDelays.push(record.displayDelayMs);
+    if ((record.segments ?? 0) >= MEGA_CHAIN_SEGMENT_THRESHOLD) bucket.megaChains++;
+
+    // Duplicate-rate proxy: how often the same rule fires more than once per
+    // session file (a session repeatedly asking for something it was already
+    // told no/yes to under a different subject).
+    if (record.rule !== undefined) {
+      const sessions = sessionsByRule.get(record.rule) ?? new Set<string>();
+      sessions.add(file);
+      sessionsByRule.set(record.rule, sessions);
+    }
+  }
+}
+
+console.log(`approval logs: ${files.length}`);
+console.log(`records: ${records}${malformed > 0 ? ` (${malformed} malformed, skipped)` : ""}`);
+if (records === 0) {
+  console.log("\nNo approvals logged yet. Run some sessions first.");
+  process.exit(0);
+}
+
+const rows = [...buckets.entries()].sort((a, b) => b[1].count - a[1].count);
+console.log(
+  "\ntool                        n  auto/interactive  duration p50/p90/max  displayDelay p50/p90/max  megaChains",
+);
+for (const [key, bucket] of rows) {
+  const durations = [...bucket.durations].sort((a, b) => a - b);
+  const delays = [...bucket.displayDelays].sort((a, b) => a - b);
+  const durDist =
+    durations.length === 0
+      ? "-"
+      : `${percentile(durations, 50)}/${percentile(durations, 90)}/${durations[durations.length - 1]!}`;
+  const delayDist =
+    delays.length === 0
+      ? "-"
+      : `${percentile(delays, 50)}/${percentile(delays, 90)}/${delays[delays.length - 1]!}`;
+  const autoCount = bucket.byMode.get("auto") ?? 0;
+  const interactiveCount = bucket.byMode.get("interactive") ?? 0;
+  console.log(
+    `${key.padEnd(26)} ${String(bucket.count).padStart(3)}  ${String(autoCount).padStart(4)}/${String(interactiveCount).padEnd(11)} ${durDist.padEnd(24)} ${delayDist.padEnd(24)} ${bucket.megaChains}`,
+  );
+}
+
+console.log("\nby outcome");
+for (const [key, bucket] of rows) {
+  const outcomes = [...bucket.byOutcome.entries()]
+    .sort((a, b) => b[1] - a[1])
+    .map(([outcome, count]) => `${outcome}=${count}`)
+    .join(" ");
+  console.log(`${key.padEnd(26)} ${outcomes}`);
+}
+
+console.log("\nrule -> sessions that hit it at least once (duplicate-rate proxy)");
+for (const [rule, sessions] of [...sessionsByRule.entries()].sort(
+  (a, b) => b[1].size - a[1].size,
+)) {
+  console.log(`${rule.padEnd(26)} ${sessions.size}`);
+}

src/exec/runner.ts

@@ -51,6 +51,7 @@ import { OPERATOR_ORIGINATED_FLAG } from "../agent/message-provenance.js";
 import { createChatDirector } from "../agent/director.js";
 import { loadAgentProfiles } from "../agent/profiles.js";
 import { createPermissionGate } from "../permission/gate.js";
+import { createApprovalLog } from "../permission/approval-log.js";
 import { createWorktreeRootsProvider } from "../permission/worktree-roots.js";
 import type { ApprovalOutcome, PermissionRequest } from "../permission/types.js";
 import { createAgentToolset, type AgentToolset, type OperatorResult } from "../agent/tools.js";
@@ -366,6 +367,7 @@ export async function runExec(config: Config): Promise<ExecResult> {
       requestApproval: (request: PermissionRequest): Promise<ApprovalOutcome> =>
         promptPermission(request, interactive),
       persist: createApprovalPersist(config.cwd, activeProviderModel),
+      approvalLog: createApprovalLog(sessionDir(config.cwd, sessionId)),
       interactive,
       skipPermissions: config.dangerouslySkipPermissions,
       auto: config.auto,