From 470d068087e8649bc788ed16b14957ddb448ff96 Mon Sep 17 00:00:00 2001 From: garrytan Date: Sun, 4 Oct 2026 17:42:45 +0000 Subject: [PATCH] 0.1: session ledger written by the claude -p, Agent SDK, PTY and Codex runners Each armed model session appends one best-effort line to $GSTACK_EVAL_DIR/session-ledger.jsonl: a stable session key, the timeout it armed, monotonic elapsed time, its end reason (completed, session_timeout, observer_timeout, api_error, refusal, aborted, error), one sanitized evidence line and, for stream-JSON runners, a compact liveness summary (longest in-request silence with nothing outstanding, last event kind, tool open at end). Partial messages now stream for every claude -p session and for SDK sessions without a custom query provider (runSharedInteractive opts in); their rows feed only the summary, so transcripts keep their size unless publicStreamDiagnostics is set. Structured refusal and API-error signals win over phrases, and tool results are never read for them. --- test/helpers/agent-sdk-runner.ts | 36 +++- test/helpers/codex-eval.ts | 6 + test/helpers/pty/launch.ts | 23 ++- test/helpers/pty/runners/counting.ts | 2 +- test/helpers/pty/runners/floor.ts | 2 +- test/helpers/pty/runners/observation.ts | 2 +- test/helpers/pty/screen.ts | 7 + test/helpers/pty/session.ts | 18 +- test/helpers/session-ledger.ts | 208 +++++++++++++++++++++++ test/helpers/session-runner.ts | 30 +++- test/helpers/shared-libs-eval-fixture.ts | 13 +- test/session-runner-tools.test.ts | 28 ++- 12 files changed, 354 insertions(+), 21 deletions(-) create mode 100644 test/helpers/session-ledger.ts diff --git a/test/helpers/agent-sdk-runner.ts b/test/helpers/agent-sdk-runner.ts index 7edff1922..870d0652b 100644 --- a/test/helpers/agent-sdk-runner.ts +++ b/test/helpers/agent-sdk-runner.ts @@ -37,6 +37,7 @@ import * as fs from 'fs'; import * as path from 'path'; import { resolveClaudeBinary as resolveClaudeBinaryShared } from '../../lib/claude-bin'; import { resolveEvalModel } from '../../lib/eval-model'; +import { SessionObserver, appendSessionLedger, sessionKey, type SessionEnd } from './session-ledger'; import { hermeticChildEnv } from './hermetic-env'; import type { SkillTestResult } from './session-runner'; @@ -130,6 +131,10 @@ export interface RunAgentSdkOptions { * to auto-allow them. */ canUseTool?: CanUseTool; + /** A custom queryProvider that drops `stream_event` rows from its own evidence opts in to partial messages. */ + streamLiveness?: boolean; + /** The session timeout the caller armed (a getter when armed at admission), for the session ledger. */ + sessionBudgetMs?: number | (() => number | undefined); } /** @@ -336,6 +341,24 @@ export async function runAgentSdkTest( while (attempt <= maxRetries) { await sem.acquire(opts.signal); const startMs = Date.now(); + const startMono = performance.now(); + const startedAt = new Date().toISOString(); + const observer = new SessionObserver(startMono); + let recorded = false; + /** One ledger row per attempt; an abort at the armed budget is a session timeout. */ + const recordSession = (fallback: SessionEnd) => { + if (recorded) return; + recorded = true; + const elapsed = performance.now() - startMono; + const budget = typeof opts.sessionBudgetMs === 'function' ? opts.sessionBudgetMs() : opts.sessionBudgetMs; + const aborted = controller.signal.aborted || opts.signal?.aborted === true; + const structured = observer.verdict(); + const end: SessionEnd = aborted ? (budget !== undefined && elapsed + 1000 >= budget ? 'session_timeout' : 'aborted') : structured?.end ?? fallback; + appendSessionLedger({ key: sessionKey('agent-sdk', opts.testName), ...(opts.testName ? { test_name: opts.testName } : {}), runner: 'agent-sdk', + started_at: startedAt, ...(budget !== undefined ? { budget_ms: budget } : {}), elapsed_ms: elapsed, end, + ...(end === 'session_timeout' ? { evidence: `armed ${budget}ms session timeout fired` } : structured && !aborted ? { evidence: structured.evidence } : {}), + liveness: observer.summary(performance.now()) }); + }; const controller = new AbortController(); let activeQuery: ReturnType | undefined; const abort = () => { @@ -358,7 +381,7 @@ export async function runAgentSdkTest( let terminalResult: SDKResultMessage | null = null; // A generator can emit its terminal result and then throw. Keep its // authoritative usage in both paths, while preserving the caller's outcome. - const finishResult = (exitReason: string): AgentSdkResult => ({ + const finishResult = (exitReason: string): AgentSdkResult => (recordSession(exitReason === 'success' ? 'completed' : 'error'), { events, assistantTurns, toolCalls, @@ -413,7 +436,13 @@ export async function runAgentSdkTest( settingSources: opts.settingSources ?? [], env: hermeticChildEnv(opts.env), pathToClaudeCodeExecutable: opts.pathToClaudeCodeExecutable, - ...(hasCanUseTool ? { canUseTool: opts.canUseTool } : {}), + // Liveness only: stream_event rows are observed, never kept in events. A custom + // queryProvider sees every row first, so it streams them only when it opts in. + includePartialMessages: !opts.queryProvider || opts.streamLiveness === true, + ...(hasCanUseTool ? { canUseTool: async (...args: Parameters) => { + observer.permission(1); + try { return await opts.canUseTool!(...args); } finally { observer.permission(-1); } + } } : {}), }; // Empty bare string means "omit entirely" (SDK runs with no override). // Any object or non-empty string is passed through. @@ -431,7 +460,9 @@ export async function runAgentSdkTest( opts.signal?.throwIfAborted(); for await (const ev of q) { + observer.observe(ev, performance.now()); opts.signal?.throwIfAborted(); + if (ev.type === 'stream_event') continue; const now = Date.now(); if (firstResponseMs === 0) firstResponseMs = now - startMs; const interTurn = now - lastEventMs; @@ -494,6 +525,7 @@ export async function runAgentSdkTest( return finishResult(terminalResult.subtype ?? 'unknown'); } catch (err) { lastErr = err; + if (!isMaxTurnsError(err)) recordSession('error'); opts.signal?.throwIfAborted(); // Some SDK versions throw max-turns after emitting a terminal result; diff --git a/test/helpers/codex-eval.ts b/test/helpers/codex-eval.ts index 6faa04e80..e49f15348 100644 --- a/test/helpers/codex-eval.ts +++ b/test/helpers/codex-eval.ts @@ -4,6 +4,7 @@ import { EvalCollector, getProjectEvalDir, shardSlugOfEvalDir, type EvalTestEntr import * as path from 'node:path'; import * as fs from 'node:fs'; import { classifyOutsideReview } from '../../lib/outside-review-result'; +import { appendSessionLedger, sessionKey } from './session-ledger'; // The process keeps its existing work budget. Its pipes may need the existing // five-second drain grace; Bun must then allow another five seconds to record. @@ -143,6 +144,7 @@ export interface CodexEvalOptions { export async function runRecordedCodexEval(opts: CodexEvalOptions): Promise { const started = Date.now(); + const startMono = performance.now(); const drainGraceMs = opts.drainGraceMs ?? CODEX_DRAIN_GRACE_MS; const timeoutMs = opts.budgetMs + drainGraceMs; const deadlineAt = started + timeoutMs; @@ -196,6 +198,10 @@ export async function runRecordedCodexEval(opts: CodexEvalOptions): Promise; /** Total run timeout (ms). Default 240000 (4 min). */ timeoutMs?: number; + /** Append this session's session-ledger row on close (default). runPtySession writes its own. */ + sessionLedger?: boolean; } export interface ClaudePtySession { @@ -173,7 +176,9 @@ export async function launchClaudePty( const cols = opts.cols ?? 120; const rows = opts.rows ?? 40; const timeoutMs = opts.timeoutMs ?? 240_000; - const wallDeadline = performance.now() + timeoutMs; + const startedMono = performance.now(); + const startedAt = new Date().toISOString(); + const wallDeadline = startedMono + timeoutMs; const screenAbort = new AbortController(); const launch = prepareLaunch(opts); @@ -228,7 +233,19 @@ export async function launchClaudePty( } }, Math.max(0, wallDeadline - performance.now())); const trust = watchTrustDialog(pty); - return sessionHandle(pty, launch, wallTimer, trust); + const handle = sessionHandle(pty, launch, wallTimer, trust); + if (opts.sessionLedger === false) return handle; + const close = handle.close; + let recorded = false; + return Object.assign(handle, { close: () => { + if (!recorded) { + recorded = true; + const elapsed = performance.now() - startedMono; + appendSessionLedger({ key: sessionKey('pty', undefined), runner: 'pty', started_at: startedAt, budget_ms: timeoutMs, + elapsed_ms: elapsed, end: elapsed >= timeoutMs ? 'session_timeout' : 'completed', ...idlePanelEnd(handle.visibleText()) }); + } + return close(); + } }); } /** Arguments, child environment and owned state roots, decided before any spawn. */ diff --git a/test/helpers/pty/runners/counting.ts b/test/helpers/pty/runners/counting.ts index a4ac5961c..8c5c05e54 100644 --- a/test/helpers/pty/runners/counting.ts +++ b/test/helpers/pty/runners/counting.ts @@ -245,7 +245,7 @@ export async function runPlanSkillCounting(opts: PlanSkillCountingOptions): Prom ...(opts.permissionPlanPath ? [opts.permissionPlanPath] : []), ]; return runPtySession({ - driver, + driver, budgetMs: timeoutMs, cleanup: () => fixture.cleanup(), launch: { permissionMode: 'plan', diff --git a/test/helpers/pty/runners/floor.ts b/test/helpers/pty/runners/floor.ts index a8d6d1802..465f01641 100644 --- a/test/helpers/pty/runners/floor.ts +++ b/test/helpers/pty/runners/floor.ts @@ -192,7 +192,7 @@ export async function runPlanSkillFloorCheck(opts: PlanSkillFloorOptions): Promi artifactError: undefined, finished: false, started: false, start: 0, deadlineAt: 0, screenDeadlineAt: 0, } as unknown as FloorRun; return runPtySession({ - driver, + driver, budgetMs: timeoutMs, cleanup: () => fixture.cleanup(), launch: { permissionMode: 'plan', diff --git a/test/helpers/pty/runners/observation.ts b/test/helpers/pty/runners/observation.ts index 032298c30..1c2b75fbb 100644 --- a/test/helpers/pty/runners/observation.ts +++ b/test/helpers/pty/runners/observation.ts @@ -214,7 +214,7 @@ export async function runPlanSkillObservation(opts: PlanSkillObservationOptions) tokensObserved: Object.fromEntries((opts.trackTokens ?? []).map(t => [t, false])), }; return runPtySession({ - driver, + driver, budgetMs, launch: { permissionMode: opts.inPlanMode === false ? null : 'plan', cwd: opts.cwd, diff --git a/test/helpers/pty/screen.ts b/test/helpers/pty/screen.ts index ba86fa311..ee005f36f 100644 --- a/test/helpers/pty/screen.ts +++ b/test/helpers/pty/screen.ts @@ -414,6 +414,13 @@ export function isNumberedOptionListVisible(visible: string): boolean { /** Start of the CLI's public "API Error:" panel. The native AUQ capture reads the same panel. */ export const API_ERROR_PANEL = /(?:^|\n)[\t │┃]*(?:[⎿●⏺]\s*)?API Error:/i; +/** Session-ledger end from the last idle turn's public error panel: a safeguards panel is a refusal, any other an API error. */ +export function idlePanelEnd(visible: string): { end: 'refusal' | 'api_error'; evidence: string } | null { + const panel = idleTurnEnd(visible)?.apiError; + if (!panel) return null; + return { end: /safeguards flagged|can't respond to this message/i.test(panel) ? 'refusal' : 'api_error', evidence: panel }; +} + /** The CLI's end-of-turn line, e.g. "✻ Cooked for 24s · done 12:46 AM" (spaces may collapse in the PTY text). */ const TURN_DONE_RE = /✻[ \t]*\p{L}[\p{L}'’-]*[ \t]*for[ \t]*(?=\d)(?:\d+h[ \t]*)?(?:\d+m[ \t]*)?(?:\d+s)?[ \t]*·[ \t]*done[^\n]*/gu; /** An empty input prompt and its known idle footers, nothing else. */ diff --git a/test/helpers/pty/session.ts b/test/helpers/pty/session.ts index 68f56d907..33e4e8890 100644 --- a/test/helpers/pty/session.ts +++ b/test/helpers/pty/session.ts @@ -8,6 +8,8 @@ * former claude-pty-runner.ts. Tests import through claude-pty-runner.ts. */ import { launchClaudePty, type ClaudePtyOptions, type ClaudePtySession } from './launch'; +import { idlePanelEnd } from './screen'; +import { appendSessionLedger, sessionKey, type SessionEnd } from '../session-ledger'; /** * The runners' launch seam: how a session starts, and the clock the runner @@ -37,6 +39,8 @@ export type PtyStep = { done: R } | 'continue' | 'break'; export interface PtySessionPlan { driver: PtyDriver; launch: ClaudePtyOptions; + /** The observation budget the runner armed (session ledger); defaults to the launch wall. */ + budgetMs?: number; /** Owned fixture cleanup; runs after close, and when launch itself fails. */ cleanup?: () => void; /** Boot and command submission. A returned result ends the run before polling. */ @@ -59,28 +63,36 @@ export interface PtySessionPlan { * owned cleanup runs last. */ export async function runPtySession(plan: PtySessionPlan): Promise { + const started = plan.driver.monotonic(); + const startedAt = new Date(plan.driver.now()).toISOString(); + let end: SessionEnd = 'error'; let session: ClaudePtySession; try { - session = await plan.driver.launch(plan.launch); + session = await plan.driver.launch({ ...plan.launch, sessionLedger: false }); } catch (error) { plan.cleanup?.(); throw error; } let failure: { error: unknown } | undefined; try { + const ended = (result: R) => { end = (result as { outcome?: unknown })?.outcome === 'timeout' ? 'observer_timeout' : 'completed'; return result; }; const early = await plan.start(session); - if (early !== undefined) return early; + if (early !== undefined) return ended(early); while (await plan.poll(session)) { const step = await plan.tick(session); if (step === 'break') break; - if (step !== 'continue') return step.done; + if (step !== 'continue') return ended(step.done); } + end = 'observer_timeout'; return plan.timeout(session); } catch (error) { failure = { error }; plan.onError?.(session, error); throw error; } finally { + appendSessionLedger({ key: sessionKey('pty', undefined), runner: 'pty', started_at: startedAt, + budget_ms: plan.budgetMs ?? plan.launch.timeoutMs ?? 240_000, elapsed_ms: plan.driver.monotonic() - started, + end, ...idlePanelEnd(session.visibleText()) }); try { try { plan.beforeClose?.(session, failure); } catch (error) { if (!failure) { failure = { error }; throw error; } } diff --git a/test/helpers/session-ledger.ts b/test/helpers/session-ledger.ts new file mode 100644 index 000000000..bd091fadc --- /dev/null +++ b/test/helpers/session-ledger.ts @@ -0,0 +1,208 @@ +/** + * Session ledger: one line per armed model session, appended best-effort to + * `$GSTACK_EVAL_DIR/session-ledger.jsonl` (the same sidecar pattern as + * contract-violations.jsonl). Runners record facts here; the record builders + * (classifyTrialShard, junitCensus) attach them to trial records and + * failureCauseOf() in eval-store.ts classifies. A failed append never fails + * a trial: the record then shows its sessions as unknown. + * + * Each row holds a stable session key, the exact timeout the session armed, + * monotonic elapsed time, the end reason, one sanitized evidence line and, + * for stream-JSON runners, a compact liveness summary (never message text). + */ +import * as fs from 'fs'; +import * as path from 'path'; + +export const SESSION_LEDGER_FILE = 'session-ledger.jsonl'; +export const SESSION_EVIDENCE_MAX = 200; +export type SessionRunner = 'claude-p' | 'agent-sdk' | 'pty' | 'codex'; +export type SessionEnd = 'completed' | 'session_timeout' | 'observer_timeout' | 'api_error' | 'refusal' | 'aborted' | 'error'; +export const SESSION_ENDS: readonly SessionEnd[] = ['completed', 'session_timeout', 'observer_timeout', 'api_error', 'refusal', 'aborted', 'error']; + +export interface LivenessSummary { + /** The session streamed partial messages. Without them no stall is ever inferred. */ + partial: boolean; + events: number; + turns: number; + /** Longest gap between events (or before the end) while a model request was in + * flight and no tool call, hook or permission prompt was outstanding. */ + max_request_silence_ms: number; + /** Elapsed ms when that silence began, and the kind of event before it. */ + silence_started_ms?: number; + silence_after?: string; + last_event?: string; + open_tool_at_end?: string; +} + +export interface SessionLedgerRow { + key: string; + case?: string; + test_name?: string; + runner: SessionRunner; + started_at: string; + /** The timeout this session armed; absent when the runner armed none. */ + budget_ms?: number; + elapsed_ms: number; + end: SessionEnd; + evidence?: string; + liveness?: LivenessSummary; +} + +/** One line, control characters stripped, mentions neutralized, capped. */ +export function sessionEvidence(text: string | undefined): string | undefined { + const first = text?.split('\n').map(line => line.trim()).find(Boolean); + if (!first) return undefined; + // eslint-disable-next-line no-control-regex + const clean = first.replace(/[\u0000-\u001f\u007f]/g, ' ').replace(/@(?=[A-Za-z0-9_-])/g, '@\u200b'); + return clean.length > SESSION_EVIDENCE_MAX ? `${clean.slice(0, SESSION_EVIDENCE_MAX - 1)}…` : clean; +} + +const ordinals = new Map(); + +/** Stable within a case: `: