diff --git a/CHANGELOG.md b/CHANGELOG.md index 0bef5578..abba0457 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/docs/ARCHITECTURE.md b/docs/ARCHITECTURE.md index 729091f9..726ddb17 100644 --- a/docs/ARCHITECTURE.md +++ b/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 `` timed out after ``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. diff --git a/scripts/approval-forensics.ts b/scripts/approval-forensics.ts new file mode 100644 index 00000000..d9b3c7e6 --- /dev/null +++ b/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; + 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; + byMode: Map; + 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(); +const sessionsByRule = new Map>(); +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(); + 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}`); +} diff --git a/src/exec/runner.ts b/src/exec/runner.ts index be03c5d6..f2459a02 100644 --- a/src/exec/runner.ts +++ b/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 { requestApproval: (request: PermissionRequest): Promise => promptPermission(request, interactive), persist: createApprovalPersist(config.cwd, activeProviderModel), + approvalLog: createApprovalLog(sessionDir(config.cwd, sessionId)), interactive, skipPermissions: config.dangerouslySkipPermissions, auto: config.auto, diff --git a/src/permission/approval-log.test.ts b/src/permission/approval-log.test.ts new file mode 100644 index 00000000..c41cf7fb --- /dev/null +++ b/src/permission/approval-log.test.ts @@ -0,0 +1,207 @@ +import { describe, test, expect } from "bun:test"; +import { mkdtempSync, readFileSync } from "node:fs"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; + +import { APPROVAL_LOG_FILE, NOOP_APPROVAL_LOG, createApprovalLog } from "./approval-log.js"; +import { createPermissionGate } from "./gate.js"; +import type { ToolCall } from "@intx/types/runtime"; + +function readRecords(dir: string): Record[] { + let raw: string; + try { + raw = readFileSync(join(dir, APPROVAL_LOG_FILE), "utf8"); + } catch { + return []; + } + return raw + .split("\n") + .filter((l) => l.trim().length > 0) + .map((l) => JSON.parse(l) as Record); +} + +describe("createApprovalLog", () => { + test("NOOP never throws and never writes", () => { + const ask = NOOP_APPROVAL_LOG.ask({ tool: "run_shell", mode: "interactive" }); + expect(() => { + ask.markDisplayed(); + ask.settle("allow-once"); + }).not.toThrow(); + }); + + test("records queued/displayed/settled timestamps and duration for one ask", async () => { + const dir = mkdtempSync(join(tmpdir(), "approval-log-")); + let now = new Date("2026-01-01T00:00:00.000Z").getTime(); + const clock = () => new Date(now); + const log = createApprovalLog(dir, clock); + + const ask = log.ask({ tool: "run_shell", mode: "interactive", segments: 3 }); + now += 50; // sat behind another overlay + ask.markDisplayed(); + now += 100; // operator decides + ask.settle("allow-with-scope"); + + // Appends are fire-and-forget; give the microtask queue a turn to flush. + await new Promise((r) => setTimeout(r, 10)); + + const [record] = readRecords(dir); + expect(record).toBeDefined(); + expect(record!.tool).toBe("run_shell"); + expect(record!.mode).toBe("interactive"); + expect(record!.segments).toBe(3); + expect(record!.outcome).toBe("allow-with-scope"); + expect(record!.durationMs).toBe(150); + expect(record!.displayDelayMs).toBe(50); + // No command text, path, or subject of any kind is ever recorded. + expect(Object.keys(record!)).not.toContain("subject"); + expect(Object.keys(record!)).not.toContain("command"); + expect(Object.keys(record!)).not.toContain("arguments"); + }); + + test("settle is idempotent — a second call does not append twice", async () => { + const dir = mkdtempSync(join(tmpdir(), "approval-log-")); + const log = createApprovalLog(dir); + const ask = log.ask({ tool: "write_file", mode: "auto" }); + ask.settle("auto-allow"); + ask.settle("deny"); + await new Promise((r) => setTimeout(r, 10)); + expect(readRecords(dir)).toHaveLength(1); + }); +}); + +const shellCall = (command: string): ToolCall => ({ + id: "c", + name: "run_shell", + arguments: { command }, +}); + +describe("approval-log wiring through the permission gate", () => { + test("logs an auto-deny for a file-mutation shell command in auto mode, with no command text", async () => { + const dir = mkdtempSync(join(tmpdir(), "approval-log-gate-")); + const cwd = mkdtempSync(join(tmpdir(), "gate-cwd-")); + const gate = createPermissionGate({ + approvals: [], + interactive: false, + skipPermissions: false, + auto: true, + cwd, + approvalLog: createApprovalLog(dir), + }); + const verdict = await gate.evaluate(shellCall("echo hunter2 > /tmp/leaked-secret-file.txt")); + expect(verdict.allowed).toBe(false); + + await new Promise((r) => setTimeout(r, 10)); + const [record] = readRecords(dir); + expect(record).toBeDefined(); + expect(record!.mode).toBe("auto"); + expect(record!.outcome).toBe("auto-deny"); + expect(record!.rule).toBe("file-mutation"); + const serialized = JSON.stringify(record); + expect(serialized).not.toContain("hunter2"); + expect(serialized).not.toContain("leaked-secret-file"); + }); + + test("logs an interactive allow-once with no command text in the record", async () => { + const dir = mkdtempSync(join(tmpdir(), "approval-log-gate-")); + const cwd = mkdtempSync(join(tmpdir(), "gate-cwd-")); + const gate = createPermissionGate({ + approvals: [], + interactive: true, + skipPermissions: false, + cwd, + approvalLog: createApprovalLog(dir), + requestApproval: async (request) => { + request.markDisplayed?.(); + return { allow: true }; + }, + }); + const verdict = await gate.evaluate(shellCall("curl https://example.com/super-secret-token")); + expect(verdict.allowed).toBe(true); + + await new Promise((r) => setTimeout(r, 10)); + const [record] = readRecords(dir); + expect(record).toBeDefined(); + expect(record!.mode).toBe("interactive"); + expect(record!.outcome).toBe("allow-once"); + expect(typeof record!.displayDelayMs).toBe("number"); + const serialized = JSON.stringify(record); + expect(serialized).not.toContain("super-secret-token"); + expect(serialized).not.toContain("curl"); + }); + + test("logs deny with non-interactive rule when no operator is attached", async () => { + const dir = mkdtempSync(join(tmpdir(), "approval-log-gate-")); + const cwd = mkdtempSync(join(tmpdir(), "gate-cwd-")); + const gate = createPermissionGate({ + approvals: [], + interactive: false, + skipPermissions: false, + cwd, + approvalLog: createApprovalLog(dir), + }); + const verdict = await gate.evaluate(shellCall("curl https://example.com")); + expect(verdict.allowed).toBe(false); + + await new Promise((r) => setTimeout(r, 10)); + const [record] = readRecords(dir); + expect(record).toBeDefined(); + expect(record!.outcome).toBe("deny"); + expect(record!.rule).toBe("non-interactive"); + }); + + // A sub-agent's `task` dispatch `description` is model-authored free text + // (see task-tool.ts) — it is only ever trimmed, never constrained to a + // closed set. A prior version of this log carried it verbatim as + // `agentLabel`. It must never reach the record: unlike `rule` (a fixed + // taxonomy) and `segments` (a count), nothing stops a model from quoting a + // path, a token, or secret content it just read into its own summary of the + // sub-task. + test("never logs a sub-agent's free-text dispatch description, even with a secret embedded", async () => { + const { runWithSubAgentIdentity } = await import("../subagent/identity-context.js"); + const dir = mkdtempSync(join(tmpdir(), "approval-log-gate-")); + const cwd = mkdtempSync(join(tmpdir(), "gate-cwd-")); + const gate = createPermissionGate({ + approvals: [], + interactive: true, + skipPermissions: false, + cwd, + approvalLog: createApprovalLog(dir), + requestApproval: async (request) => { + request.markDisplayed?.(); + return { allow: true }; + }, + }); + const secret = "sk-live-9f2c7a1e4b6d8f0a"; + const verdict = await runWithSubAgentIdentity( + { description: `fetch the token ${secret} from the vault and cache it`, cwd }, + () => gate.evaluate(shellCall("curl https://example.com")), + ); + expect(verdict.allowed).toBe(true); + + await new Promise((r) => setTimeout(r, 10)); + const [record] = readRecords(dir); + expect(record).toBeDefined(); + expect(Object.keys(record!)).not.toContain("agentLabel"); + const serialized = JSON.stringify(record); + expect(serialized).not.toContain(secret); + expect(serialized).not.toContain("vault"); + }); +}); + +describe("approval-log record size cap", () => { + test("drops a record that would exceed the hard size cap rather than truncate it", async () => { + const dir = mkdtempSync(join(tmpdir(), "approval-log-cap-")); + const log = createApprovalLog(dir); + // `rule` is a real, typed field — simulate a future regression where some + // caller stuffs unbounded text into it instead of the closed taxonomy. + // The cap must catch that even though the type system would not. + const ask = log.ask({ + tool: "run_shell", + mode: "interactive", + rule: "x".repeat(10_000), + }); + ask.settle("allow-once"); + await new Promise((r) => setTimeout(r, 10)); + expect(readRecords(dir)).toHaveLength(0); + }); +}); diff --git a/src/permission/approval-log.ts b/src/permission/approval-log.ts new file mode 100644 index 00000000..4c7c47d0 --- /dev/null +++ b/src/permission/approval-log.ts @@ -0,0 +1,180 @@ +/** + * Approval log: one record every time the permission gate settles a + * consequential action — whether that settlement came from an operator + * prompt or from auto mode deciding without one. + * + * Before this file, the only durable record of an approval was a lifetime + * "Allow Always" grant (see store.ts) — every allow-once and every deny, the + * overwhelming majority of answers, was discarded the moment it was given. + * There was no way to answer how many approvals a session fires, which + * classifier rule triggers them, or whether a prompt was even auto-allowed by + * policy rather than shown to the operator (CL-5666). + * + * No command text, file content, path, credential, or any other + * model-authored or user-authored free text ever appears here — only the tool + * name (a fixed identifier), the classifier/auto-shell rule that fired + * (reusing the rule names already defined in auto-shell-policy.ts and + * classify.ts, plus a small closed set of additional literals this file + * defines for decisions those modules don't otherwise name — never a new + * taxonomy), a shell chain's segment count, and timing. Every field is either + * a fixed enum, a count, or a timestamp; a sub-agent's free-text dispatch + * label was deliberately left out even though it would enable a per-agent + * breakdown, because nothing constrains what a model puts in it. Writes are + * fire-and-forget and never throw: a diagnostic must not be able to fail a + * run. A hard size cap on the serialized line (see MAX_RECORD_BYTES) is + * belt-and-suspenders insurance against a future field reintroducing free + * text. + */ + +import { appendFile } from "node:fs/promises"; +import { join } from "node:path"; +import { randomUUID } from "node:crypto"; + +import { getLogger } from "@intx/log"; + +import { LOG_NAMESPACE_ROOT } from "../branding.js"; + +export const APPROVAL_LOG_FILE = "approvals.jsonl"; + +/** Whether the settlement came from an unattended policy decision or an operator prompt. */ +export type ApprovalMode = "auto" | "interactive"; + +/** + * How the request settled. `allow-once` / `allow-with-scope` / `deny` are + * operator decisions; `auto-allow` / `auto-deny` are auto-mode policy + * decisions made without a prompt; `timeout` / `abort` are the gate settling + * itself because the operator never answered. + */ +export type ApprovalOutcomeKind = + "allow-once" | "allow-with-scope" | "deny" | "auto-allow" | "auto-deny" | "timeout" | "abort"; + +export interface ApprovalRecord { + /** Correlates this settlement with the ask that raised it. */ + id: string; + tool: string; + /** + * The classifier/auto-shell rule name that triggered this decision (e.g. + * "dependency-install", "sensitive-path" from auto-shell-policy.ts), when + * one fired. Undefined for a plain interactive ask with no specific rule. + */ + rule?: string; + mode: ApprovalMode; + /** Real (non-comment) shell chain segment count, for run_shell requests. */ + segments?: number; + outcome: ApprovalOutcomeKind; + /** ISO timestamp the request was raised (queued for an operator or a policy check). */ + queuedAt: string; + /** + * ISO timestamp the request actually reached the operator's screen. Equal + * to queuedAt unless the request sat behind another overlay first — the gap + * between the two is the CL-5664 defect signal (timers arming before the + * operator can see the request). + */ + displayedAt: string; + /** ISO timestamp the request settled (decided, auto-decided, timed out, or aborted). */ + settledAt: string; + /** settledAt - queuedAt, in milliseconds. */ + durationMs: number; + /** displayedAt - queuedAt, in milliseconds. */ + displayDelayMs: number; +} + +export interface AskEvent { + tool: string; + rule?: string; + mode: ApprovalMode; + segments?: number; +} + +// Belt-and-suspenders cap on the serialized record. Every field here is +// either a fixed enum, a count, or a timestamp, so a well-formed line should +// never come close to this — it exists only so a future field that +// reintroduces free text (an agent label, a subject, a message) cannot grow +// this file into a content leak; oversized lines are dropped, not truncated, +// so no partial secret survives half-written. +const MAX_RECORD_BYTES = 512; + +/** Handle for one in-flight ask, returned by ApprovalLog.ask(). */ +export interface ApprovalAsk { + readonly id: string; + /** Mark the moment this request actually reached the operator's screen. Idempotent. */ + markDisplayed: () => void; + /** Settle the ask and append its record. Safe to call at most meaningfully once. */ + settle: (outcome: ApprovalOutcomeKind) => void; +} + +export interface ApprovalLog { + ask: (event: AskEvent) => ApprovalAsk; +} + +/** Log that drops everything — the default, so logging is never required. */ +export const NOOP_APPROVAL_LOG: ApprovalLog = { + ask: () => ({ + id: "", + markDisplayed: () => {}, + settle: () => {}, + }), +}; + +/** + * Append-only sink over `/approvals.jsonl`. + * + * Appends are fire-and-forget: the caller is on the permission-gate decision + * path, and a diagnostic write must not add latency to it or fail the run. + * Ordering within a session is preserved by chaining each append onto the + * previous one. + */ +export function createApprovalLog(dir: string, now: () => Date = () => new Date()): ApprovalLog { + const path = join(dir, APPROVAL_LOG_FILE); + const log = getLogger(`${LOG_NAMESPACE_ROOT}:approval-log`); + let tail: Promise = Promise.resolve(); + + const append = (record: ApprovalRecord): void => { + const line = `${JSON.stringify(record)}\n`; + if (Buffer.byteLength(line, "utf8") > MAX_RECORD_BYTES) { + log.debug?.("approval log record dropped: exceeds max size"); + return; + } + tail = tail.then( + () => + appendFile(path, line, "utf8").catch((err: unknown) => { + log.debug?.(`approval log append failed: ${String(err)}`); + }), + () => undefined, + ); + }; + + return { + ask: (event) => { + const id = randomUUID(); + const queuedAt = now(); + let displayedAt: Date | undefined; + let settled = false; + return { + id, + markDisplayed: () => { + if (displayedAt === undefined) displayedAt = now(); + }, + settle: (outcome) => { + if (settled) return; + settled = true; + const settledAt = now(); + const displayed = displayedAt ?? queuedAt; + append({ + id, + tool: event.tool, + ...(event.rule !== undefined ? { rule: event.rule } : {}), + mode: event.mode, + ...(event.segments !== undefined ? { segments: event.segments } : {}), + outcome, + queuedAt: queuedAt.toISOString(), + displayedAt: displayed.toISOString(), + settledAt: settledAt.toISOString(), + durationMs: settledAt.getTime() - queuedAt.getTime(), + displayDelayMs: displayed.getTime() - queuedAt.getTime(), + }); + }, + }; + }, + }; +} diff --git a/src/permission/gate.ts b/src/permission/gate.ts index c7c3a2fb..f05aaa00 100644 --- a/src/permission/gate.ts +++ b/src/permission/gate.ts @@ -43,10 +43,27 @@ import { end, start } from "../perf/index.js"; import { currentTurnId } from "../perf/reactor-spans.js"; import { classifyPermissionKind } from "../telemetry/classify.js"; import { NOOP_TELEMETRY, type Telemetry } from "../telemetry/index.js"; +import { NOOP_APPROVAL_LOG, type ApprovalLog, type ApprovalOutcomeKind } from "./approval-log.js"; // Closes out an operator prompt: ends the wait span and records the outcome. // buildRequests yields at most one request per tool call, and the two prompt // sites below are mutually exclusive, so this runs once per prompt shown. +// Classifies a settled ApprovalOutcome into the approval-log taxonomy. +// gate-wire.ts's timeout/abort auto-denies carry a fixed message text (see +// autoDeny in gate-wire.ts and the timeout branch in tui/request-approval.ts's +// finish() usage); anything else that denies is a plain operator/unavailable +// decision. +function classifyOutcome(outcome: ApprovalOutcome | undefined): ApprovalOutcomeKind { + if (outcome === undefined) return "deny"; + if (!outcome.allow) { + const message = outcome.message ?? ""; + if (message.includes("timed out")) return "timeout"; + if (message.includes("no longer running")) return "abort"; + return "deny"; + } + return outcome.persist !== undefined ? "allow-with-scope" : "allow-once"; +} + function finishApprovalWait( telemetry: Telemetry, waitSpanId: string, @@ -274,6 +291,10 @@ export interface PermissionGateOptions { // than read from the process-wide handle so a gate built without one is // silent by construction. telemetry?: Telemetry; + // Ask/settle event log (see approval-log.ts): one record per consequential + // decision, auto or interactive. Defaults to a no-op so nothing depends on + // logging being wired. + approvalLog?: ApprovalLog; } export interface PermissionGate { @@ -321,6 +342,7 @@ export interface PermissionGate { export function createPermissionGate(options: PermissionGateOptions): PermissionGate { const { requestApproval, persist, interactive, providerName, model, cwd } = options; const telemetry = options.telemetry ?? NOOP_TELEMETRY; + const approvalLog = options.approvalLog ?? NOOP_APPROVAL_LOG; const mcpTiers = options.mcpTiers ?? createMcpToolPermissionRegistry(); const resolvedCwd = cwd ?? process.cwd(); const rootsProvider = options.rootsProvider ?? createWorktreeRootsProvider(resolvedCwd); @@ -382,6 +404,25 @@ export function createPermissionGate(options: PermissionGateOptions): Permission ); }; + // An auto-mode (or non-interactive-unavailable) decision settles the + // instant it is made — there is no operator to wait on, so queued/displayed/ + // settled all collapse to now. Interactive prompts use approvalLog.ask + // directly (see below) so their real queued/displayed/settled timestamps + // are captured. + const recordAutoDecision = ( + tool: string, + rule: string | undefined, + outcome: ApprovalOutcomeKind, + ): void => { + approvalLog + .ask({ + tool, + mode: "auto", + ...(rule !== undefined ? { rule } : {}), + }) + .settle(outcome); + }; + const evaluate = async (call: ToolCall): Promise => { if (skipPermissions) return { allowed: true }; // Sub-agent tool calls run under ALS identity (identity-context.ts). The @@ -450,9 +491,16 @@ export function createPermissionGate(options: PermissionGateOptions): Permission // reads stay hard-denied by secret-guard; shell that only *mentions* // a secret path is ask so an explicit one-time approval can pass it. const shellRule = autoShellRuleForCall(call, isRestrictedHere, effectiveCwd, rootsProvider); - if (shellRule?.effect === "deny") return { allowed: false, reason: shellRule.reason }; - if (shellRule === undefined) return { allowed: true }; + if (shellRule?.effect === "deny") { + recordAutoDecision(call.name, shellRule.name, "auto-deny"); + return { allowed: false, reason: shellRule.reason }; + } + if (shellRule === undefined) { + recordAutoDecision(call.name, undefined, "auto-allow"); + return { allowed: true }; + } } else if (!restricted && AUTO_ALLOWED_TOOLS.has(call.name)) { + recordAutoDecision(call.name, "auto-allowed-tool", "auto-allow"); return { allowed: true }; } // Any other tool in auto mode (MCP or unknown built-in) is not @@ -552,7 +600,17 @@ export function createPermissionGate(options: PermissionGateOptions): Permission } if (!needsOperator) continue; + // A mega-chain (see MEGA_CHAIN_SEGMENT_THRESHOLD) is accept-once only: + // no scope is offered for it (buildRequests already returns none), and + // this check is the belt to that suspenders — the gate itself refuses + // to mint a grant for one even if a persist scope somehow arrived. + // Computed ahead of the non-interactive branch too, so both settle + // paths tag the same ask with the same rule. + const isMegaChain = segments.length >= MEGA_CHAIN_SEGMENT_THRESHOLD; + const askRule = anySecret ? "sensitive-path" : isMegaChain ? "mega-chain" : undefined; + if (!interactive || requestApproval === undefined) { + recordAutoDecision(request.tool, askRule ?? "non-interactive", "deny"); return { allowed: false, reason: anySecret @@ -563,12 +621,14 @@ export function createPermissionGate(options: PermissionGateOptions): Permission // Secret-path shell must never mint a stored grant — even an exact match // would be misleading because future secret-path shell always re-asks. - // A mega-chain (see MEGA_CHAIN_SEGMENT_THRESHOLD) is accept-once only: - // no scope is offered for it (buildRequests already returns none), and - // this check is the belt to that suspenders — the gate itself refuses - // to mint a grant for one even if a persist scope somehow arrived. - const isMegaChain = segments.length >= MEGA_CHAIN_SEGMENT_THRESHOLD; const requestForOperator = anySecret ? { ...request, scopes: [] } : request; + const ask = approvalLog.ask({ + tool: request.tool, + mode: "interactive", + ...(askRule !== undefined ? { rule: askRule } : {}), + segments: segments.length, + }); + requestForOperator.markDisplayed = ask.markDisplayed; const turnId = currentTurnId(); const waitSpanId = start("permission.wait", { ...(turnId !== null && turnId.length > 0 ? { parentId: turnId } : {}), @@ -579,6 +639,7 @@ export function createPermissionGate(options: PermissionGateOptions): Permission outcome = await requestApproval(requestForOperator); } finally { finishApprovalWait(telemetry, waitSpanId, request.tool, outcome); + ask.settle(classifyOutcome(outcome)); } if (outcome === undefined || !outcome.allow) { const suffix = @@ -611,12 +672,18 @@ export function createPermissionGate(options: PermissionGateOptions): Permission } if (!interactive || requestApproval === undefined) { + recordAutoDecision(request.tool, "non-interactive", "deny"); return { allowed: false, reason: `${request.action} requires operator approval, which is unavailable in a non-interactive run. Re-run with --dangerously-skip-permissions to bypass, or narrow the action.`, }; } + const ask = approvalLog.ask({ + tool: request.tool, + mode: "interactive", + }); + request.markDisplayed = ask.markDisplayed; const turnId = currentTurnId(); const waitSpanId = start("permission.wait", { ...(turnId !== null && turnId.length > 0 ? { parentId: turnId } : {}), @@ -627,6 +694,7 @@ export function createPermissionGate(options: PermissionGateOptions): Permission outcome = await requestApproval(request); } finally { finishApprovalWait(telemetry, waitSpanId, request.tool, outcome); + ask.settle(classifyOutcome(outcome)); } if (outcome === undefined || !outcome.allow) { const suffix = diff --git a/src/permission/types.ts b/src/permission/types.ts index 2d6cc7e0..430fba68 100644 --- a/src/permission/types.ts +++ b/src/permission/types.ts @@ -57,6 +57,14 @@ export interface PermissionRequest { // yet" case (e.g. a mega-chain that only offers accept-once). Plain literal // text, never model-authored. notice?: string; + // Set by the gate right before handing this request to requestApproval, so + // whichever surface actually renders it (see gate-wire.ts's overlay host) + // can report the moment it reached the operator's screen — distinct from + // the moment it was raised, when a busy overlay host queues it first (see + // src/permission/approval-log.ts). Never present on requests built for + // display/matching only (buildRequests), only on the copy passed to + // requestApproval. + markDisplayed?: () => void; } // The operator's answer. `allow` gates the action; `persist`, when present, is diff --git a/src/tui/gate-wire.ts b/src/tui/gate-wire.ts index c2eebffc..09006ebc 100644 --- a/src/tui/gate-wire.ts +++ b/src/tui/gate-wire.ts @@ -330,6 +330,11 @@ export function wireGates( const open = (): void => { openedGeneration = overlayGeneration; + // The gate may have sat behind another overlay in `pending` — this is + // the moment it actually reaches the operator's screen, distinct from + // when it was raised (see PermissionRequest.markDisplayed and + // src/permission/approval-log.ts). + ev.request.markDisplayed?.(); if (ev.timeoutMs !== undefined) { timer = setTimeout(() => { autoDeny(ev.timeoutMessage ?? "approval timed out; request denied"); diff --git a/src/tui/runner.ts b/src/tui/runner.ts index c0d8f633..c4bd226c 100644 --- a/src/tui/runner.ts +++ b/src/tui/runner.ts @@ -155,6 +155,7 @@ import { createChatDirector, hydrateTasksFromTurns } from "../agent/director.js" import { loadAgentProfiles } from "../agent/profiles.js"; import { resolveAgentPluginProfiles } from "../plugins/agent-plugins.js"; import { createPermissionGate } from "../permission/gate.js"; +import { createApprovalLog } from "../permission/approval-log.js"; import { createWorktreeRootsProvider } from "../permission/worktree-roots.js"; import { createPermissionsAdmin, type ScopedApproval } from "../permission/admin.js"; import type { GrantScope } from "../permission/types.js"; @@ -829,6 +830,7 @@ export async function runTUI(initialConfig: Config): Promise { approvalTimeout, }), persist: createApprovalPersist(config.cwd, activeProviderModel), + approvalLog: createApprovalLog(sessionDir(config.cwd, sessionId)), interactive: true, skipPermissions: config.dangerouslySkipPermissions, auto: config.auto,