mirror of
https://github.com/garrytan/gstack.git
synced 2026-10-31 22:14:25 +01:00
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.
This commit is contained in:
1 parent
e54923176f
commit
470d068087
12 files changed
+354
-21
No files matched your search
@@ -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<QueryProvider> | 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<CanUseTool>) => {
|
||||
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;
|
||||
|
||||
@@ -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<CodexResult> {
|
||||
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<Code
|
||||
: 'validation_failed';
|
||||
const message = failure instanceof Error ? failure.message : String(failure);
|
||||
const diagnostic = result?.stderr && !message.includes(result.stderr) ? `${message}\n${result.stderr}` : message;
|
||||
appendSessionLedger({ key: sessionKey('codex', opts.name), test_name: opts.name, runner: 'codex', started_at: new Date(started).toISOString(),
|
||||
budget_ms: opts.budgetMs, elapsed_ms: performance.now() - startMono,
|
||||
end: exitReason === 'timeout' ? 'session_timeout' : passed || exitReason === 'validation_failed' ? 'completed' : 'error',
|
||||
...(exitReason === 'timeout' ? { evidence: `armed ${opts.budgetMs}ms Codex budget expired` } : {}) });
|
||||
|
||||
// addTest appends retry attempts. Never pre-record a failure and then
|
||||
// overwrite it: that would manufacture two attempts from one execution.
|
||||
|
||||
@@ -13,7 +13,8 @@ import { createFilePermissionRecorder } from '../plan-count-file-permission';
|
||||
import { createAutoplanArtifactRecorder } from '../autoplan-artifact-recorder';
|
||||
import { trustDialogInput } from '../pty-trust-dialog';
|
||||
import { resolveClaudeBinary } from './binary';
|
||||
import { createPtyScreen, stripAnsi } from './screen';
|
||||
import { createPtyScreen, idlePanelEnd, stripAnsi } from './screen';
|
||||
import { appendSessionLedger, sessionKey } from '../session-ledger';
|
||||
|
||||
export interface ClaudePtyOptions {
|
||||
/** Register the repo's shipped skills in the child's user scope via
|
||||
@@ -66,6 +67,8 @@ export interface ClaudePtyOptions {
|
||||
env?: Record<string, string>;
|
||||
/** 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. */
|
||||
|
||||
@@ -245,7 +245,7 @@ export async function runPlanSkillCounting(opts: PlanSkillCountingOptions): Prom
|
||||
...(opts.permissionPlanPath ? [opts.permissionPlanPath] : []),
|
||||
];
|
||||
return runPtySession<PlanSkillCountObservation>({
|
||||
driver,
|
||||
driver, budgetMs: timeoutMs,
|
||||
cleanup: () => fixture.cleanup(),
|
||||
launch: {
|
||||
permissionMode: 'plan',
|
||||
|
||||
@@ -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<PlanSkillFloorObservation>({
|
||||
driver,
|
||||
driver, budgetMs: timeoutMs,
|
||||
cleanup: () => fixture.cleanup(),
|
||||
launch: {
|
||||
permissionMode: 'plan',
|
||||
|
||||
@@ -214,7 +214,7 @@ export async function runPlanSkillObservation(opts: PlanSkillObservationOptions)
|
||||
tokensObserved: Object.fromEntries((opts.trackTokens ?? []).map(t => [t, false])),
|
||||
};
|
||||
return runPtySession<PlanSkillObservation>({
|
||||
driver,
|
||||
driver, budgetMs,
|
||||
launch: {
|
||||
permissionMode: opts.inPlanMode === false ? null : 'plan',
|
||||
cwd: opts.cwd,
|
||||
|
||||
@@ -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. */
|
||||
|
||||
@@ -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<R> = { done: R } | 'continue' | 'break';
|
||||
export interface PtySessionPlan<R> {
|
||||
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<R> {
|
||||
* owned cleanup runs last.
|
||||
*/
|
||||
export async function runPtySession<R>(plan: PtySessionPlan<R>): Promise<R> {
|
||||
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; } }
|
||||
|
||||
@@ -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<string, number>();
|
||||
|
||||
/** Stable within a case: `<runner>:<label>#<n>`, n counting this label's sessions in this process. */
|
||||
export function sessionKey(runner: SessionRunner, label: string | undefined, env: NodeJS.ProcessEnv = process.env): string {
|
||||
const base = `${runner}:${label || env.GSTACK_EVAL_CASE_ID || 'session'}`;
|
||||
const n = (ordinals.get(base) ?? 0) + 1;
|
||||
ordinals.set(base, n);
|
||||
return `${base}#${n}`;
|
||||
}
|
||||
|
||||
/** Best-effort append; a missing GSTACK_EVAL_DIR or a write error records nothing. */
|
||||
export function appendSessionLedger(row: Omit<SessionLedgerRow, 'case'> & { case?: string }, env: NodeJS.ProcessEnv = process.env): void {
|
||||
const dir = env.GSTACK_EVAL_DIR;
|
||||
if (!dir) return;
|
||||
const caseId = env.GSTACK_EVAL_CASE_ID || row.case;
|
||||
const out: SessionLedgerRow = { ...row, ...(caseId ? { case: caseId } : {}), elapsed_ms: Math.max(0, Math.round(row.elapsed_ms)),
|
||||
...(row.evidence ? { evidence: sessionEvidence(row.evidence) } : {}) };
|
||||
try {
|
||||
fs.mkdirSync(dir, { recursive: true });
|
||||
fs.appendFileSync(path.join(dir, SESSION_LEDGER_FILE), JSON.stringify(out) + '\n');
|
||||
} catch { /* diagnostics never fail a trial */ }
|
||||
}
|
||||
|
||||
/** Rows of one eval dir; malformed lines are skipped. */
|
||||
export function readSessionLedger(evalDir: string | undefined): SessionLedgerRow[] {
|
||||
if (!evalDir) return [];
|
||||
let text = '';
|
||||
try { text = fs.readFileSync(path.join(evalDir, SESSION_LEDGER_FILE), 'utf8'); } catch { return []; }
|
||||
return text.split('\n').flatMap(line => {
|
||||
try {
|
||||
const row = JSON.parse(line);
|
||||
return row && typeof row.key === 'string' && SESSION_ENDS.includes(row.end) && Number.isFinite(row.elapsed_ms) ? [row as SessionLedgerRow] : [];
|
||||
} catch { return []; }
|
||||
});
|
||||
}
|
||||
|
||||
const REFUSAL_PHRASE = /safeguards flagged this message|can't respond to this message/i;
|
||||
|
||||
/**
|
||||
* Facts from a stream-JSON session (claude -p NDJSON or Agent SDK messages),
|
||||
* fed one event at a time with its arrival time. Structured refusal and API
|
||||
* error signals win; a refusal phrase is read only from the final result or a
|
||||
* synthetic CLI message, never from tool results. Liveness counts every event,
|
||||
* thinking deltas included.
|
||||
*/
|
||||
export class SessionObserver {
|
||||
private partial = false;
|
||||
private events = 0;
|
||||
private turnIds = new Set<string>();
|
||||
private requesting = true;
|
||||
private openTools = new Map<string, string>();
|
||||
private hooks = 0;
|
||||
private permissions = 0;
|
||||
private lastAt: number;
|
||||
private lastKind = 'start';
|
||||
private maxSilence = 0;
|
||||
private silenceStart?: number;
|
||||
private silenceAfter?: string;
|
||||
private refusal?: string;
|
||||
private apiError?: string;
|
||||
private phraseRefusal?: string;
|
||||
|
||||
constructor(private readonly startedAt: number) { this.lastAt = startedAt; }
|
||||
|
||||
/** A permission prompt opened (+1) or settled (-1); SDK canUseTool callbacks. */
|
||||
permission(delta: 1 | -1): void { this.permissions = Math.max(0, this.permissions + delta); }
|
||||
|
||||
private gap(at: number): void {
|
||||
const silence = at - this.lastAt;
|
||||
if (this.requesting && this.openTools.size === 0 && this.hooks === 0 && this.permissions === 0 && silence > this.maxSilence) {
|
||||
this.maxSilence = silence;
|
||||
this.silenceStart = this.lastAt - this.startedAt;
|
||||
this.silenceAfter = this.lastKind;
|
||||
}
|
||||
}
|
||||
|
||||
observe(event: any, at: number): void {
|
||||
if (!event || typeof event !== 'object') return;
|
||||
this.gap(at);
|
||||
this.events++;
|
||||
let kind = String(event.type ?? 'unknown');
|
||||
if (event.type === 'stream_event') {
|
||||
this.partial = true;
|
||||
const inner = event.event ?? {};
|
||||
kind = inner.type === 'content_block_delta' && inner.delta?.type ? String(inner.delta.type) : String(inner.type ?? 'stream_event');
|
||||
if (inner.type === 'message_start') this.requesting = true;
|
||||
if (inner.type === 'message_stop') this.requesting = false;
|
||||
} else if (event.type === 'assistant') {
|
||||
const message = event.message ?? {};
|
||||
if (!event.parent_tool_use_id && typeof message.id === 'string') this.turnIds.add(message.id);
|
||||
for (const block of Array.isArray(message.content) ? message.content : []) {
|
||||
if (block?.type === 'tool_use' && typeof block.id === 'string') this.openTools.set(block.id, String(block.name ?? 'tool'));
|
||||
}
|
||||
if (!this.partial && this.openTools.size > 0) this.requesting = false;
|
||||
if (message.stop_reason === 'refusal') this.refusal ??= this.refusalLine('stop_reason refusal', message.stop_details?.category);
|
||||
const text = (Array.isArray(message.content) ? message.content : []).filter((b: any) => b?.type === 'text').map((b: any) => String(b.text ?? '')).join('\n');
|
||||
if (message.model === '<synthetic>') this.noteResultText(text);
|
||||
} else if (event.type === 'user') {
|
||||
for (const block of Array.isArray(event.message?.content) ? event.message.content : []) {
|
||||
if (block?.type === 'tool_result') this.openTools.delete(block.tool_use_id);
|
||||
}
|
||||
if (this.openTools.size === 0) this.requesting = true;
|
||||
} else if (event.type === 'system') {
|
||||
const subtype = String(event.subtype ?? '');
|
||||
kind = `system:${subtype}`;
|
||||
if (subtype === 'hook_started') this.hooks++;
|
||||
if (subtype === 'hook_response') this.hooks = Math.max(0, this.hooks - 1);
|
||||
if (subtype === 'model_refusal_no_fallback') this.refusal ??= this.refusalLine(subtype, event.api_refusal_category);
|
||||
} else if (event.type === 'result') {
|
||||
this.requesting = false;
|
||||
if (event.stop_reason === 'refusal') this.refusal ??= this.refusalLine('result stop_reason refusal', undefined);
|
||||
if (event.is_error === true && typeof event.result === 'string') this.noteResultText(event.result);
|
||||
}
|
||||
this.lastAt = at;
|
||||
this.lastKind = kind;
|
||||
}
|
||||
|
||||
private refusalLine(source: string, category: unknown): string {
|
||||
return `refusal at turn ${Math.max(1, this.turnIds.size)} (${source})${typeof category === 'string' && category ? ` — ${category}` : ''}`;
|
||||
}
|
||||
|
||||
private noteResultText(text: string): void {
|
||||
const line = text.split('\n').map(l => l.trim()).find(l => /^API Error:/i.test(l));
|
||||
if (!line) return;
|
||||
if (REFUSAL_PHRASE.test(text)) this.phraseRefusal ??= `refusal at turn ${Math.max(1, this.turnIds.size)} (phrase) — ${line}`;
|
||||
else this.apiError ??= line;
|
||||
}
|
||||
|
||||
/** Structured end evidence seen so far: refusal first, then API error, then a refusal phrase. */
|
||||
verdict(): { end: 'refusal' | 'api_error'; evidence: string } | null {
|
||||
if (this.refusal) return { end: 'refusal', evidence: this.refusal };
|
||||
if (this.apiError) return { end: 'api_error', evidence: this.apiError };
|
||||
if (this.phraseRefusal) return { end: 'refusal', evidence: this.phraseRefusal };
|
||||
return null;
|
||||
}
|
||||
|
||||
/** Close the observation at `at` (the final silence counts) and summarize. */
|
||||
summary(at: number): LivenessSummary {
|
||||
this.gap(at);
|
||||
const open = [...this.openTools.values()].at(-1);
|
||||
return {
|
||||
partial: this.partial, events: this.events, turns: this.turnIds.size,
|
||||
max_request_silence_ms: this.partial ? Math.round(this.maxSilence) : 0,
|
||||
...(this.partial && this.silenceStart !== undefined ? { silence_started_ms: Math.round(this.silenceStart), silence_after: this.silenceAfter } : {}),
|
||||
last_event: this.lastKind,
|
||||
...(open ? { open_tool_at_end: open } : {}),
|
||||
};
|
||||
}
|
||||
}
|
||||
@@ -16,6 +16,7 @@ import { getProjectEvalDir } from './eval-store';
|
||||
import { hermeticChildEnv, isHermeticEnabled } from './hermetic-env';
|
||||
import { killProcessGroup } from '../../scripts/test-strict-output';
|
||||
import { resolveEvalModel } from '../../lib/eval-model';
|
||||
import { SessionObserver, appendSessionLedger, sessionKey, type SessionEnd } from './session-ledger';
|
||||
|
||||
const GSTACK_DEV_DIR = path.join(os.homedir(), '.gstack-dev');
|
||||
const HEARTBEAT_PATH = path.join(GSTACK_DEV_DIR, 'e2e-live.json'); // heartbeat stays global
|
||||
@@ -226,7 +227,9 @@ export async function runSkillTest(options: {
|
||||
allowedTools?: string[];
|
||||
/** Optional built-in tool availability. Omit to preserve the CLI defaults. */
|
||||
tools?: string[];
|
||||
/** Opt-in public block timing/input-size diagnostics; never completion evidence. */
|
||||
/** Keep public block timing/input-size diagnostics in the transcript; never completion evidence.
|
||||
* Partial messages always stream for the session ledger's liveness summary; without
|
||||
* this flag their rows are observed and dropped, so transcripts keep their size. */
|
||||
publicStreamDiagnostics?: boolean;
|
||||
timeout?: number;
|
||||
testName?: string;
|
||||
@@ -253,6 +256,8 @@ export async function runSkillTest(options: {
|
||||
};
|
||||
}): Promise<SkillTestResult> {
|
||||
const startTime = Date.now();
|
||||
const startMono = performance.now();
|
||||
const observer = new SessionObserver(startMono);
|
||||
options.signal?.throwIfAborted();
|
||||
const {
|
||||
prompt,
|
||||
@@ -322,7 +327,7 @@ Before source Reads, use Bash to run exactly \`date -u +%Y-%m-%dT%H:%M:%SZ\`. Af
|
||||
// only --tools removes unrelated built-ins such as Agent, Bash, and Skill.
|
||||
// Keep this opt-in: existing workflow evals intentionally use CLI defaults.
|
||||
if (options.tools !== undefined) args.push('--tools', options.tools.join(','));
|
||||
if (options.publicStreamDiagnostics) args.push('--include-partial-messages');
|
||||
args.push('--include-partial-messages');
|
||||
// Hermetic children get zero MCP servers (no --mcp-config is passed).
|
||||
// Gated on the same call-time check as the env scrub so EVALS_HERMETIC=0
|
||||
// restores operator MCP along with the operator env.
|
||||
@@ -499,8 +504,9 @@ Before source Reads, use Bash to run exactly \`date -u +%Y-%m-%dT%H:%M:%SZ\`. Af
|
||||
buf = lines.pop() || '';
|
||||
for (const rawLine of lines) {
|
||||
if (!rawLine.trim()) continue;
|
||||
const line = projectLine(rawLine);
|
||||
collectedLines.push(line);
|
||||
let raw: any;
|
||||
try { raw = JSON.parse(rawLine); } catch { /* projected below */ }
|
||||
observer.observe(raw, performance.now());
|
||||
|
||||
// Track time to first NDJSON line (measures latency from spawn to first Claude response)
|
||||
if (!workPhaseArmed) {
|
||||
@@ -513,6 +519,9 @@ Before source Reads, use Bash to run exactly \`date -u +%Y-%m-%dT%H:%M:%SZ\`. Af
|
||||
// REMAINING budget (total wall stays <= timeout).
|
||||
armWorkPhase(firstResponseMs);
|
||||
}
|
||||
if (!options.publicStreamDiagnostics && raw?.type === 'stream_event') continue;
|
||||
const line = projectLine(rawLine);
|
||||
collectedLines.push(line);
|
||||
|
||||
// Real-time progress to stderr + persistent logs
|
||||
try {
|
||||
@@ -572,7 +581,10 @@ Before source Reads, use Bash to run exactly \`date -u +%Y-%m-%dT%H:%M:%SZ\`. Af
|
||||
stdoutDone = true;
|
||||
|
||||
// Flush remaining buffer
|
||||
if (buf.trim()) {
|
||||
let tail: any;
|
||||
try { tail = buf.trim() ? JSON.parse(buf) : undefined; } catch { /* projected below */ }
|
||||
observer.observe(tail, performance.now());
|
||||
if (buf.trim() && (options.publicStreamDiagnostics || tail?.type !== 'stream_event')) {
|
||||
const line = projectLine(buf);
|
||||
collectedLines.push(line);
|
||||
if (options.publicStreamDiagnostics && runDir && safeName) {
|
||||
@@ -635,6 +647,14 @@ Before source Reads, use Bash to run exactly \`date -u +%Y-%m-%dT%H:%M:%SZ\`. Af
|
||||
}
|
||||
|
||||
const duration = Date.now() - startTime;
|
||||
const structured = observer.verdict();
|
||||
const end: SessionEnd = timedOut ? (signal?.aborted ? 'aborted' : 'session_timeout')
|
||||
: structured?.end ?? (exitReason === 'success' ? 'completed' : 'error');
|
||||
appendSessionLedger({ key: sessionKey('claude-p', testName), ...(testName ? { test_name: testName } : {}), runner: 'claude-p',
|
||||
started_at: startedAt, budget_ms: timeout, elapsed_ms: performance.now() - startMono, end,
|
||||
...(timedOut ? { evidence: timedOutInStartup ? `no output within the ${startupGraceMs}ms startup grace` : `armed ${timeout}ms session timeout fired` }
|
||||
: structured ? { evidence: structured.evidence } : {}),
|
||||
liveness: observer.summary(performance.now()) });
|
||||
|
||||
// Parse all collected NDJSON lines
|
||||
const parsed = parseNDJSON(collectedLines);
|
||||
|
||||
@@ -1228,6 +1228,7 @@ export async function runSharedInteractive(f: SharedLibsFixture, testName: strin
|
||||
let timer: ReturnType<typeof setTimeout> | undefined;
|
||||
let actorFailure: Error | undefined;
|
||||
let captureStartedAt = 0;
|
||||
let armedMs: number | undefined;
|
||||
const streamed: any[] = [];
|
||||
const diagnosticDirectory = path.join(SHARED_LIBS_ROOT, '.context/shared-libs-captures');
|
||||
const diagnostic = path.join(diagnosticDirectory, `${Date.now()}-${testName}-${path.basename(f.root)}.jsonl`);
|
||||
@@ -1240,7 +1241,7 @@ export async function runSharedInteractive(f: SharedLibsFixture, testName: strin
|
||||
userPrompt: prompt, workingDirectory: f.repo, testName, env: f.env,
|
||||
pathToClaudeCodeExecutable: claudeBinary,
|
||||
settingSources: [], maxTurns: SHARED_INTERACTIVE_MAX_TURNS, maxRetries: 0,
|
||||
signal: fixtureOptions.attempt.signal,
|
||||
signal: fixtureOptions.attempt.signal, sessionBudgetMs: () => armedMs, streamLiveness: true,
|
||||
allowedTools: ['Read', 'Bash', 'Write', 'Edit', 'Glob', 'Grep', 'AskUserQuestion'],
|
||||
queryProvider: args => {
|
||||
fixtureOptions.attempt.signal.throwIfAborted();
|
||||
@@ -1248,7 +1249,8 @@ export async function runSharedInteractive(f: SharedLibsFixture, testName: strin
|
||||
if (remaining <= 0) throw new Error('Shared capture attempt expired before admission');
|
||||
abortController = args.options?.abortController;
|
||||
if (!abortController) throw new Error('SDK capture lacks its owned abort controller');
|
||||
timer = setTimeout(() => abortController!.abort(), Math.min(CAPTURE_MS, remaining));
|
||||
armedMs = Math.min(CAPTURE_MS, remaining);
|
||||
timer = setTimeout(() => abortController!.abort(), armedMs);
|
||||
captureStartedAt = Date.now();
|
||||
fs.mkdirSync(diagnosticDirectory, { recursive: true });
|
||||
const source = query({ ...args, options: { ...args.options,
|
||||
@@ -1257,8 +1259,11 @@ export async function runSharedInteractive(f: SharedLibsFixture, testName: strin
|
||||
get(target, key) {
|
||||
if (key === Symbol.asyncIterator) return async function* () {
|
||||
for await (const event of target) {
|
||||
streamed.push(event);
|
||||
fs.appendFileSync(diagnostic, JSON.stringify(event) + '\n');
|
||||
// Partial-message rows feed the runner's liveness summary only.
|
||||
if (event.type !== 'stream_event') {
|
||||
streamed.push(event);
|
||||
fs.appendFileSync(diagnostic, JSON.stringify(event) + '\n');
|
||||
}
|
||||
yield event;
|
||||
}
|
||||
};
|
||||
|
||||
@@ -305,11 +305,37 @@ describe.skipIf(process.platform === 'win32')('session-runner explicit tool avai
|
||||
await withFakeClaude(async (dir, observed) => {
|
||||
await runSkillTest({ prompt: 'Default tools', workingDirectory: dir, allowedTools: ['Read'], timeout: 5_000 });
|
||||
expect(observed().args).not.toContain('--tools');
|
||||
expect(observed().args).not.toContain('--include-partial-messages');
|
||||
// Partial messages always stream for the session ledger's liveness summary (plan 0.2).
|
||||
expect(observed().args).toContain('--include-partial-messages');
|
||||
expect(flagValue(observed().args, '--allowed-tools')).toBe('Read');
|
||||
});
|
||||
});
|
||||
|
||||
test('without public diagnostics, partial messages feed only the session ledger; the transcript keeps its shape', async () => {
|
||||
await withFakeClaude(async (dir) => {
|
||||
fs.writeFileSync(path.join(dir, 'diagnostic-case'), 'complete');
|
||||
const evalDir = path.join(dir, 'eval');
|
||||
const saved = process.env.GSTACK_EVAL_DIR;
|
||||
process.env.GSTACK_EVAL_DIR = evalDir;
|
||||
let result: Awaited<ReturnType<typeof runSkillTest>>;
|
||||
try {
|
||||
result = await runSkillTest({ prompt: 'diagnose', workingDirectory: dir, tools: ['Read', 'Write'], timeout: 5_000, testName: 'ledger-case' });
|
||||
} finally {
|
||||
if (saved === undefined) delete process.env.GSTACK_EVAL_DIR; else process.env.GSTACK_EVAL_DIR = saved;
|
||||
}
|
||||
expect(result.exitReason).toBe('success');
|
||||
expect(result.transcript.map(e => e.type)).toEqual(['system', 'assistant', 'assistant', 'result']);
|
||||
expect(JSON.stringify(result.transcript)).not.toContain('stream_event');
|
||||
const rows = fs.readFileSync(path.join(evalDir, 'session-ledger.jsonl'), 'utf8').trim().split('\n').map(line => JSON.parse(line));
|
||||
expect(rows).toHaveLength(1);
|
||||
expect(rows[0]).toMatchObject({ key: 'claude-p:ledger-case#1', test_name: 'ledger-case', runner: 'claude-p', budget_ms: 5_000, end: 'completed',
|
||||
liveness: { partial: true, turns: 0, last_event: 'result', open_tool_at_end: 'Write' } });
|
||||
expect(rows[0].elapsed_ms).toBeGreaterThan(0);
|
||||
expect(rows[0].liveness.max_request_silence_ms).toBeLessThan(5_000);
|
||||
expect(JSON.stringify(rows[0])).not.toContain('PRIVATE');
|
||||
});
|
||||
});
|
||||
|
||||
test('public stream diagnostics retain timing and input sizes without counting partial tools', async () => {
|
||||
await withFakeClaude(async (dir, observed) => {
|
||||
fs.writeFileSync(path.join(dir, 'diagnostic-case'), 'complete');
|
||||
|
||||
Reference in new issue
Block a user