diff --git a/src/tui/runtime-bridge.test.ts b/src/tui/runtime-bridge.test.ts index 8457e7b51..517a3d831 100644 --- a/src/tui/runtime-bridge.test.ts +++ b/src/tui/runtime-bridge.test.ts @@ -1,5 +1,7 @@ import { describe, expect, spyOn, test } from "bun:test"; +import { EventEmitter } from "node:events"; import { mailboxMailWakeLine } from "../subagent/mailbox-mail-drive.js"; +import type { PermissionRequest } from "../permission/types.js"; import { defined } from "../../tests/helpers/defined.js"; import { OPERATOR_ORIGINATED_FLAG } from "../agent/message-provenance.js"; import { buildShellBackgroundMessage } from "../session/runtime-assembly.js"; @@ -13,10 +15,13 @@ import { import { DEFAULT_STALL_MS } from "./agent-progress"; import { appendStreamRow, paintChrome } from "./shell/chrome"; import { createAppShell } from "./shell/index"; -import { getShellBridgeHooks } from "./shell/internals"; +import { getShellBridgeHooks, type AppShell } from "./shell/internals"; import { streamRowCount } from "./shell/transcript"; import { STEER_WAIT_NOTICE_MS } from "./notice-line"; import { withTestRenderer } from "./harness"; +import { wireGates } from "./gate-wire.js"; +import { acceptOverlaySelection } from "./shell/overlay-host.js"; +import { moveOverlaySelection } from "./shell/overlay-list.js"; import { badgeCount } from "./delivery-queue"; import { LIVE_ACTIVITY_WORDS } from "./chrome-state"; @@ -2973,6 +2978,365 @@ describe("in-flight tool row elapsed time", () => { }); }); +describe("CL-7802 gated tool elapsed starts at grant", () => { + function acceptOnce(shell: AppShell): void { + moveOverlaySelection(shell, 1); + acceptOverlaySelection(shell); + } + + function destructiveRequest(subject: string): PermissionRequest { + return { + tool: "run_shell", + action: "Run shell command", + subject, + scopes: [], + }; + } + + test("R1 hidden-gate grant: post-grant stat reads time-since-grant, not time-since-announce", async () => { + await withTestRenderer( + async (h) => { + const shell = createAppShell(h.renderer, { + terminal: { columns: 80, rows: 24 }, + wireKeys: false, + run: "busy", + }); + let nowMs = 0; + let tick: (() => void) | undefined; + const bridge = attachSessionBridge(shell, createRecordingPort(), { + now: () => nowMs, + schedule: (fn) => { + tick = fn; + return () => { + tick = undefined; + }; + }, + }); + try { + bridge.handle({ type: "inference.start", data: {} }); + bridge.handle({ + type: "inference.tool_call.end", + data: { name: "run_shell", callId: "c1", arguments: "sleep 30" }, + }); + const index = streamRowCount(shell) - 1; + const stat = () => defined(shell.streamLog[index], "tool row").stat; + + bridge.gateOpened(); + nowMs = 120_000; + tick?.(); + await h.renderOnce(); + expect(stat()).toBeUndefined(); + + bridge.gateClosed(); + await h.renderOnce(); + expect(stat()).toBe("0:00"); + + nowMs = 125_000; + tick?.(); + await h.renderOnce(); + expect(stat()).toBe("0:05"); + } finally { + bridge.dispose(); + shell.dispose(); + } + }, + { width: 80, height: 24 }, + ); + }); + + test("R2 gated deny: final row carries the answer stat, no m:ss leftover", async () => { + await withTestRenderer( + async (h) => { + const shell = createAppShell(h.renderer, { + terminal: { columns: 80, rows: 24 }, + wireKeys: false, + run: "busy", + }); + let nowMs = 0; + let tick: (() => void) | undefined; + const bridge = attachSessionBridge(shell, createRecordingPort(), { + now: () => nowMs, + schedule: (fn) => { + tick = fn; + return () => { + tick = undefined; + }; + }, + }); + try { + bridge.handle({ type: "inference.start", data: {} }); + bridge.handle({ + type: "inference.tool_call.end", + data: { name: "run_shell", callId: "c1", arguments: "sleep 30" }, + }); + const index = streamRowCount(shell) - 1; + + bridge.gateOpened(); + nowMs = 120_000; + tick?.(); + await h.renderOnce(); + bridge.gateClosed(); + bridge.handle({ + type: "tool.done", + data: { + result: { + callId: "c1", + name: "run_shell", + content: "Denied by operator", + isError: true, + }, + }, + }); + await h.renderOnce(); + expect( + defined(shell.streamLog[index], "tool row").stat ?? "", + ).not.toMatch(/^\d+:\d\d$/); + } finally { + bridge.dispose(); + shell.dispose(); + } + }, + { width: 80, height: 24 }, + ); + }); + + test("R3 shown-gate grant: the wait clock rebases to time-since-grant", async () => { + await withTestRenderer( + async (h) => { + const shell = createAppShell(h.renderer, { + terminal: { columns: 80, rows: 24 }, + wireKeys: false, + run: "busy", + }); + const emitter = new EventEmitter(); + const disposeGates = wireGates(emitter, shell); + let nowMs = 0; + let tick: (() => void) | undefined; + const bridge = attachSessionBridge(shell, createRecordingPort(), { + now: () => nowMs, + schedule: (fn) => { + tick = fn; + return () => { + tick = undefined; + }; + }, + }); + try { + bridge.handle({ type: "inference.start", data: {} }); + bridge.handle({ + type: "inference.tool_call.end", + data: { + name: "run_shell", + callId: "c1", + arguments: "rm -rf /tmp/cl7802", + }, + }); + const index = streamRowCount(shell) - 1; + const stat = () => defined(shell.streamLog[index], "tool row").stat; + + bridge.gateOpened(); + let resolved: unknown; + emitter.emit("permission.gate", { + id: "req-g", + request: destructiveRequest("rm -rf /tmp/cl7802"), + resolve: (outcome: unknown) => { + resolved = outcome; + }, + }); + expect(shell.overlayKind).toBe("permissions"); + + nowMs = 120_000; + tick?.(); + await h.renderOnce(); + expect(stat()).toBe("2:00"); + + acceptOnce(shell); + expect(resolved).toEqual({ allow: true }); + bridge.gateClosed(); + await h.renderOnce(); + expect(stat()).toBe("0:00"); + + nowMs = 125_000; + tick?.(); + await h.renderOnce(); + expect(stat()).toBe("0:05"); + } finally { + bridge.dispose(); + disposeGates(); + shell.dispose(); + } + }, + { width: 80, height: 24 }, + ); + }); + + test("ungated in-flight sibling does not rebase when a later gate settles", async () => { + await withTestRenderer( + async (h) => { + const shell = createAppShell(h.renderer, { + terminal: { columns: 80, rows: 24 }, + wireKeys: false, + run: "busy", + }); + let nowMs = 0; + let tick: (() => void) | undefined; + const bridge = attachSessionBridge(shell, createRecordingPort(), { + now: () => nowMs, + schedule: (fn) => { + tick = fn; + return () => { + tick = undefined; + }; + }, + }); + try { + bridge.handle({ type: "inference.start", data: {} }); + bridge.handle({ + type: "inference.tool_call.end", + data: { name: "grep", callId: "sibling", arguments: "needle" }, + }); + const siblingIndex = streamRowCount(shell) - 1; + const siblingStat = () => + defined(shell.streamLog[siblingIndex], "sibling row").stat; + + nowMs = 60_000; + tick?.(); + await h.renderOnce(); + expect(siblingStat()).toBe("1:00"); + + bridge.handle({ + type: "inference.tool_call.end", + data: { name: "run_shell", callId: "gated", arguments: "sleep 30" }, + }); + const gatedIndex = streamRowCount(shell) - 1; + const gatedStat = () => + defined(shell.streamLog[gatedIndex], "gated row").stat; + + bridge.gateOpened(); + bridge.gateClosed(); + await h.renderOnce(); + expect(siblingStat()).toBe("1:00"); + expect(gatedStat()).toBe("0:00"); + + nowMs = 65_000; + tick?.(); + await h.renderOnce(); + expect(siblingStat()).toBe("1:05"); + expect(gatedStat()).toBe("0:05"); + } finally { + bridge.dispose(); + shell.dispose(); + } + }, + { width: 80, height: 24 }, + ); + }); + + test("diff rows keep their +/- stat through a gate cycle", async () => { + await withTestRenderer( + async (h) => { + const shell = createAppShell(h.renderer, { + terminal: { columns: 80, rows: 24 }, + wireKeys: false, + run: "busy", + }); + let nowMs = 0; + let tick: (() => void) | undefined; + const bridge = attachSessionBridge(shell, createRecordingPort(), { + now: () => nowMs, + schedule: (fn) => { + tick = fn; + return () => { + tick = undefined; + }; + }, + }); + try { + bridge.handle({ type: "inference.start", data: {} }); + bridge.handle({ + type: "inference.tool_call.end", + data: { + name: "write_file", + callId: "c1", + arguments: JSON.stringify({ path: "a.txt", content: "hi\n" }), + }, + }); + const index = streamRowCount(shell) - 1; + const before = defined(shell.streamLog[index], "diff row").stat; + expect(before).toContain("+"); + + bridge.gateOpened(); + nowMs = 120_000; + tick?.(); + await h.renderOnce(); + bridge.gateClosed(); + nowMs = 125_000; + tick?.(); + await h.renderOnce(); + expect(defined(shell.streamLog[index], "diff row").stat).toBe(before); + } finally { + bridge.dispose(); + shell.dispose(); + } + }, + { width: 80, height: 24 }, + ); + }); + + test("spawn_agent rows keep their session clock through a gate cycle", async () => { + await withTestRenderer( + async (h) => { + const shell = createAppShell(h.renderer, { + terminal: { columns: 80, rows: 24 }, + wireKeys: false, + run: "busy", + }); + let nowMs = 0; + const bridge = attachSessionBridge(shell, createRecordingPort(), { + now: () => nowMs, + }); + try { + bridge.handle({ type: "inference.start", data: {} }); + bridge.handle({ + type: "inference.tool_call.end", + data: { + name: "spawn_agent", + callId: "task-1", + arguments: { description: "Review permission gate" }, + }, + }); + const index = streamRowCount(shell) - 1; + nowMs = 120_000; + bridge.syncAgentProgress([ + { + id: "task-1", + status: "running", + currentToolName: "grep", + currentToolPreview: null, + currentToolStartedAt: null, + startedAt: 0, + lastActivityAt: nowMs, + }, + ]); + await h.renderOnce(); + const before = defined(shell.streamLog[index], "progress row").stat; + + bridge.gateOpened(); + bridge.gateClosed(); + await h.renderOnce(); + expect(defined(shell.streamLog[index], "progress row").stat).toBe( + before, + ); + } finally { + bridge.dispose(); + shell.dispose(); + } + }, + { width: 80, height: 24 }, + ); + }); +}); + describe("task checklist calls stay out of the transcript", () => { test("a manage_tasks call and its result paint no rows", async () => { await withTestRenderer( diff --git a/src/tui/runtime-bridge.ts b/src/tui/runtime-bridge.ts index d5e819a74..4fff15cda 100644 --- a/src/tui/runtime-bridge.ts +++ b/src/tui/runtime-bridge.ts @@ -598,6 +598,16 @@ export interface BridgeBag { * length of a slow call — the one case a healthy turn reads as dead. */ toolCallStartedAt: Map; + /** + * In-flight ordinary calls waiting on a decision gate. `gateClosed` re-syncs + * their elapsed clocks to the settle so post-grant stats read + * time-since-grant, not time-since-announcement. Auto-allowed siblings that + * already carry a live elapsed clock are executing, not waiting, and stay + * out of the set. `spawn_agent` ids are never rebased — the session clock + * owns those rows. Results and rollbacks drop their ids so the set cannot + * leak. + */ + gatedToolCalls: Set; /** * Last live shell tail painted per in-flight call, so an unchanged feed * snapshot applies no row update. @@ -1027,6 +1037,9 @@ function applyToolCall( // their own) pick up the live timer. if (row.stat === undefined) { bag.toolCallStartedAt.set(event.callId, bag.now()); + // Announced while a gate stands open: the wait belongs to the gate, so + // the settle re-syncs this clock (see gateClosed). + if (bag.turn.blockedGateCount > 0) bag.gatedToolCalls.add(event.callId); } } if (event.callId !== undefined && event.name === SPAWN_AGENT_TOOL_NAME) { @@ -1064,6 +1077,7 @@ function applyToolResult( if (event.callId !== undefined) { bag.toolRows.delete(event.callId); bag.toolCallStartedAt.delete(event.callId); + bag.gatedToolCalls.delete(event.callId); bag.shellSnapshots.delete(event.callId); // spawn_agent's immediate running JSON is not the end of the worker — // keep the row in taskCallIds / spawnProgressRows until the session @@ -1218,6 +1232,56 @@ function syncToolElapsed(shell: AppShell, bag: BridgeBag, nowMs: number): void { } } +/** + * Re-sync every gate-waited call's elapsed clock to the settle: execution + * starts at the grant, not at the announcement that preceded the approval + * wait. Later ticks read time-since-grant through the same syncToolElapsed + * path an ungated row uses. Fires on every settled gate — allow and deny + * alike, the only settle signal the gate wiring reports (see gate-wire + * `onceClosed`) — so deny needs no special case: the result merge already + * drops the clock-owned stat for the answer's own addendum. Nested gates + * rebase uniformly at each settle rather than per gate/call pair: the bridge + * sees gate lifecycles but not which grant covers which call. `shell` + * keeps its announcement-stamped `inFlightTool.startedAt` on purpose: the + * only reader (`resolveWaitingOn`) uses it as a steer-wait threshold, not an + * execution clock, and a steer queued mid-gate has still been waiting. + */ +function rebaseGatedElapsed( + shell: AppShell, + bag: BridgeBag, + nowMs: number, +): void { + if (bag.gatedToolCalls.size === 0) return; + const grant = clockLabel(0); + for (const callId of bag.gatedToolCalls) { + bag.gatedToolCalls.delete(callId); + // The session clock owns spawn_agent rows; diff rows never enter the + // gated set (they carry no elapsed clock to rebase). + if (bag.taskCallIds.has(callId)) continue; + if (!bag.toolCallStartedAt.has(callId)) continue; + bag.toolCallStartedAt.set(callId, nowMs); + const index = bag.toolRows.get(callId); + if (index === undefined) continue; + const row = bag.pendingRowUpdates.get(index) ?? streamRowAt(shell, index); + if (row === undefined || row.pending !== true) continue; + if (row.stat === grant) continue; + rowUpdates.scheduleRowUpdate(bag, index, { ...row, stat: grant }); + } +} + +/** `clockLabel` trailer already painted on an in-flight ordinary-tool row. */ +function hasPaintedElapsedClock( + shell: AppShell, + bag: BridgeBag, + callId: string, +): boolean { + const index = bag.toolRows.get(callId); + if (index === undefined) return false; + const row = bag.pendingRowUpdates.get(index) ?? streamRowAt(shell, index); + const stat = row?.stat; + return typeof stat === "string" && /^\d+:\d{2}$/.test(stat); +} + /** * User rows the shell paints ahead of the runtime's own inbound copy: a * reinject, which lands before the restarted run reports it, and a row the @@ -1256,6 +1320,7 @@ function rollbackAttempt(shell: AppShell, bag: BridgeBag): void { if (index >= boundary) { bag.toolRows.delete(callId); bag.toolCallStartedAt.delete(callId); + bag.gatedToolCalls.delete(callId); bag.taskCallIds.delete(callId); bag.spawnProgressRows.delete(callId); bag.shellSnapshots.delete(callId); @@ -1533,6 +1598,7 @@ export function attachSessionBridge( now, toolRows: new Map(), toolCallStartedAt: new Map(), + gatedToolCalls: new Set(), shellSnapshots: new Map(), lastToolRow: -1, taskCallIds: new Set(), @@ -2052,12 +2118,22 @@ export function attachSessionBridge( const gateOpened = (): void => { if (bag.disposed) return; bag.turn = turnStateGateOpened(bag.turn); + // Snapshot calls waiting on this gate. An auto-allowed sibling that + // already carries a live elapsed clock is executing, not waiting — leave + // its startedAt at announcement so post-grant stats stay honest. + for (const callId of bag.toolCallStartedAt.keys()) { + if (hasPaintedElapsedClock(shell, bag, callId)) continue; + bag.gatedToolCalls.add(callId); + } paintPhase(); }; const gateClosed = (): void => { if (bag.disposed) return; bag.turn = turnStateGateClosed(bag.turn, now()); + // The grant is execution start: waited clocks re-sync here so post-grant + // stats read time-since-grant (see rebaseGatedElapsed). + rebaseGatedElapsed(shell, bag, now()); paintPhase(); flushOccupancyThenWake(); };