From e5f153534908969b3c9281cb83677f7fab1c4e6d Mon Sep 17 00:00:00 2001 From: acoliver Date: Thu, 23 Jul 2026 14:01:36 -0300 Subject: [PATCH 1/6] Fix nightly eval response extraction (Fixes #2651) --- evals/README.md | 2 +- evals/test-helper.ts | 119 ++++++++- integration-tests/json-output.test.ts | 36 +++ packages/test-utils/src/process-run.test.ts | 216 ++++++++++++++++ packages/test-utils/src/process-run.ts | 169 +++++++++++-- packages/test-utils/src/stdout-filter.test.ts | 185 ++++++++++++++ packages/test-utils/src/stdout-filter.ts | 236 +++++++++++++++--- packages/test-utils/src/test-rig.test.ts | 21 ++ packages/test-utils/src/test-rig.ts | 144 +++++++---- .../tests/evals-save-memory-assertion.test.js | 78 ++++++ 10 files changed, 1090 insertions(+), 116 deletions(-) create mode 100644 packages/test-utils/src/process-run.test.ts create mode 100644 packages/test-utils/src/stdout-filter.test.ts diff --git a/evals/README.md b/evals/README.md index 2aacf1b5c3..796c91d184 100644 --- a/evals/README.md +++ b/evals/README.md @@ -72,7 +72,7 @@ describe('my_feature', () => { - `settings`: Override LLxprt settings for this test - `fakeResponsesPath`: Use canned responses instead of live model -Note: Tool call logs are automatically saved to `evals/logs/` for all evals. +Note: Versioned JSON diagnostic logs are automatically saved to `evals/logs/` for all evals. Each log contains the raw process capture and parsed tool calls. ### Available Assertions diff --git a/evals/test-helper.ts b/evals/test-helper.ts index 2418bbf25d..ce38aebd41 100644 --- a/evals/test-helper.ts +++ b/evals/test-helper.ts @@ -6,28 +6,92 @@ import { it } from 'vitest'; import fs from 'node:fs'; +import { z } from 'zod'; import { TestRig, type TestRigSetupOptions, + type RunCapture, } from '@vybestack/llxprt-code-test-utils'; export * from '@vybestack/llxprt-code-test-utils'; export type EvalPolicy = 'ALWAYS_PASSES' | 'USUALLY_PASSES'; +const EvalOutputSchema = z.object({ response: z.string() }); + +export function buildEvalArgs(prompt: string): string[] { + return [`--prompt=${prompt}`, '--output-format', 'json']; +} + +export function extractModelResponse(output: string): string { + let parsed: unknown; + try { + parsed = JSON.parse(output); + } catch { + throw new Error('Expected valid JSON output from LLxprt CLI'); + } + + const result = EvalOutputSchema.safeParse(parsed); + if (!result.success) { + throw new Error( + 'Expected LLxprt CLI JSON output to include a string response', + ); + } + return result.data.response; +} + +/** + * Serialized shape of the eval artifact written to evals/logs. Contains the + * structured process-run capture (separate stdout/stderr/exitCode/timedOut) + * alongside the extracted tool-call records for post-run diagnosis. + */ +export interface EvalArtifact { + readonly schemaVersion: 1; + readonly capture: RunCapture | null; + readonly toolCalls: unknown; +} + +export function formatEvalLog( + capture: RunCapture | null, + toolCalls: unknown, +): string { + const artifact: EvalArtifact = { schemaVersion: 1, capture, toolCalls }; + return JSON.stringify(artifact, null, 2); +} + export function evalTest(policy: EvalPolicy, evalCase: EvalCase): void { const fn = async (): Promise => { const rig = new TestRig(); + let primaryError: unknown; + let failed = false; try { rig.setup(evalCase.name, evalCase.params); - const result = await rig.run({ args: evalCase.prompt }); - await evalCase.assert(rig, result); - } finally { - await logToFile( - evalCase.name, - JSON.stringify(rig.readToolLogs(), null, 2), - ); - await rig.cleanup(); + const cliOutput = await rig.run({ args: buildEvalArgs(evalCase.prompt) }); + await evalCase.assert(rig, extractModelResponse(cliOutput)); + } catch (error) { + failed = true; + primaryError = error; + } + + let finalizationError: unknown; + try { + await finalizeEval(rig, evalCase.name); + } catch (error) { + finalizationError = error; + } + + if (failed) { + if (finalizationError !== undefined) { + throw new AggregateError( + [primaryError, finalizationError], + 'Eval failed and diagnostics finalization also failed', + { cause: primaryError }, + ); + } + throw primaryError; + } + if (finalizationError !== undefined) { + throw finalizationError; } }; @@ -49,6 +113,45 @@ export interface EvalCase { assert: (rig: TestRig, result: string) => Promise; } +async function finalizeEval(rig: TestRig, name: string): Promise { + const capture = rig.getLastRunCapture(); + let toolCalls: unknown; + try { + toolCalls = rig.readToolLogs(); + } catch (error) { + toolCalls = { + error: error instanceof Error ? error.message : String(error), + }; + } + + let artifactError: unknown; + try { + await logToFile(name, formatEvalLog(capture, toolCalls)); + } catch (error) { + artifactError = error; + } + + let cleanupError: unknown; + try { + await rig.cleanup(); + } catch (error) { + cleanupError = error; + } + + if (artifactError !== undefined && cleanupError !== undefined) { + throw new AggregateError( + [artifactError, cleanupError], + 'Writing eval diagnostics and cleaning up both failed', + ); + } + if (artifactError !== undefined) { + throw artifactError; + } + if (cleanupError !== undefined) { + throw cleanupError; + } +} + // Canonical deterministic contract for the save_memory eval: the prompt // instructs the model to answer exactly this value. const CANONICAL_ANSWER = '$blue$'; diff --git a/integration-tests/json-output.test.ts b/integration-tests/json-output.test.ts index d18102781d..5f5cbbe48a 100644 --- a/integration-tests/json-output.test.ts +++ b/integration-tests/json-output.test.ts @@ -39,6 +39,42 @@ describe('JSON output', () => { expect(typeof parsed.stats).toBe('object'); }); + it('should preserve an exact tool-using response and separate diagnostics', async () => { + await rig.setup('json-output-save-memory', { + settings: { tools: { core: ['save_memory'] } }, + fakeResponsesPath: join( + import.meta.dirname, + 'save-memory.responses.jsonl', + ), + }); + + const result = await rig.run({ + args: [ + 'Save that my favorite color is blue, then answer with exactly $blue$.', + '--output-format', + 'json', + ], + }); + + expect(JSON.parse(result).response).toBe('$blue$'); + expect( + rig + .readToolLogs() + .some( + (entry) => + entry.toolRequest.name === 'save_memory' && + entry.toolRequest.success, + ), + ).toBe(true); + + const capture = rig.getLastRunCapture(); + expect(capture?.stdout).toContain('$blue$'); + expect(capture?.exitCode).toBe(0); + expect(capture?.timedOut).toBe(false); + expect(capture?.stderr).toBeDefined(); + expect(result).not.toContain('StdErr:'); + }); + it('should return a valid JSON with a session ID', async () => { await rig.setup('json-output-session-id', { fakeResponsesPath: join( diff --git a/packages/test-utils/src/process-run.test.ts b/packages/test-utils/src/process-run.test.ts new file mode 100644 index 0000000000..c92ba9c8e2 --- /dev/null +++ b/packages/test-utils/src/process-run.test.ts @@ -0,0 +1,216 @@ +/** + * @license + * Copyright 2025 Vybestack LLC + * SPDX-License-Identifier: Apache-2.0 + */ + +import { mkdtempSync, rmSync } from 'node:fs'; +import { tmpdir } from 'node:os'; +import { join } from 'node:path'; +import { afterEach, describe, expect, it } from 'bun:test'; +import { + spawnRun, + spawnRunWithTimeout, + type RunCapture, + type RunContext, +} from './process-run.js'; + +const tempDirs: string[] = []; + +afterEach(() => { + const dirs = tempDirs.slice(); + tempDirs.length = 0; + const errors: unknown[] = []; + for (const dir of dirs) { + try { + rmSync(dir, { recursive: true, force: true }); + } catch (error) { + errors.push(error); + } + } + if (errors.length > 0) { + throw new AggregateError( + errors, + 'Failed to clean process-run test directories', + ); + } +}); + +function makeTempDir(): string { + const dir = mkdtempSync(join(tmpdir(), 'process-run-test-')); + tempDirs.push(dir); + return dir; +} + +function bunContext(code: string, cwd: string): RunContext { + return { + command: 'bun', + commandArgs: ['-e', code], + testDir: cwd, + }; +} + +const identityTransform = (stdout: string): string => stdout; + +async function expectRejection( + promise: Promise, + pattern: RegExp, +): Promise { + try { + await promise; + throw new Error('Expected promise to reject'); + } catch (error) { + if (!(error instanceof Error)) { + throw new Error(`Expected Error, received ${String(error)}`); + } + expect(error.message).toMatch(pattern); + } +} + +describe('process run capture', () => { + it('reports separate stdout and stderr before resolving JSON output', async () => { + let capture: RunCapture | undefined; + const result = await spawnRun( + bunContext( + 'process.stdout.write("hello out"); process.stderr.write("hello err");', + makeTempDir(), + ), + {}, + true, + identityTransform, + (value) => { + capture = value; + }, + ); + + expect(result).toBe('hello out'); + expect(capture).toEqual({ + stdout: 'hello out', + stderr: 'hello err', + exitCode: 0, + timedOut: false, + }); + }); + + it('preserves the existing plain-text stderr append behavior', async () => { + const result = await spawnRun( + bunContext('process.stderr.write("warn line");', makeTempDir()), + {}, + false, + identityTransform, + ); + + expect(result).toContain('warn line'); + expect(result).toMatch(/StdErr:/); + }); + + it('reports partial streams for a nonzero exit', async () => { + let capture: RunCapture | undefined; + const run = spawnRun( + bunContext( + 'process.stdout.write("partial out"); process.stderr.write("partial err"); process.exit(3);', + makeTempDir(), + ), + {}, + false, + identityTransform, + (value) => { + capture = value; + }, + ); + + await expectRejection(run, /code 3/); + expect(capture).toEqual({ + stdout: 'partial out', + stderr: 'partial err', + exitCode: 3, + timedOut: false, + }); + }); + + it('captures shutdown output and force-kills a run that ignores SIGTERM', async () => { + let capture: RunCapture | undefined; + const run = spawnRunWithTimeout( + bunContext( + [ + 'process.on("SIGTERM", () => {', + ' process.stdout.write(" shutdown-out");', + ' process.stderr.write("shutdown-err");', + '});', + 'process.stdout.write("started");', + 'setInterval(() => {}, 1000);', + ].join('\n'), + makeTempDir(), + ), + {}, + false, + identityTransform, + 500, + (value) => { + capture = value; + }, + ); + + await expectRejection(run, /timed out/); + expect(capture).toEqual({ + stdout: 'started shutdown-out', + stderr: 'shutdown-err', + exitCode: null, + timedOut: true, + }); + }); + + it('captures and rejects child-process spawn errors', async () => { + let capture: RunCapture | undefined; + const run = spawnRun( + { + command: join(makeTempDir(), 'missing-command'), + commandArgs: [], + testDir: makeTempDir(), + }, + {}, + false, + identityTransform, + (value) => { + capture = value; + }, + ); + + await expectRejection(run, /ENOENT/); + expect(capture).toEqual({ + stdout: '', + stderr: '', + exitCode: null, + timedOut: false, + }); + }); + + it('keeps concurrent run captures isolated by callback', async () => { + let firstCapture: RunCapture | undefined; + let secondCapture: RunCapture | undefined; + + await Promise.all([ + spawnRun( + bunContext('process.stdout.write("first");', makeTempDir()), + {}, + true, + identityTransform, + (value) => { + firstCapture = value; + }, + ), + spawnRun( + bunContext('process.stdout.write("second");', makeTempDir()), + {}, + true, + identityTransform, + (value) => { + secondCapture = value; + }, + ), + ]); + + expect(firstCapture?.stdout).toBe('first'); + expect(secondCapture?.stdout).toBe('second'); + }); +}); diff --git a/packages/test-utils/src/process-run.ts b/packages/test-utils/src/process-run.ts index f497f76bb7..6155019472 100644 --- a/packages/test-utils/src/process-run.ts +++ b/packages/test-utils/src/process-run.ts @@ -4,10 +4,76 @@ * SPDX-License-Identifier: Apache-2.0 */ -import { spawn } from 'node:child_process'; +import { spawn, type ChildProcess } from 'node:child_process'; import { env } from 'node:process'; import type { Writable } from 'node:stream'; +/** + * Structured capture of the most recent process run, available for diagnosis + * after `spawnRun` / `spawnRunWithTimeout` resolve or reject. Contains the raw + * (untransformed) child stdout and stderr so callers can inspect the original + * process output regardless of the transform applied to the resolved value. + */ +export interface RunCapture { + /** Raw stdout accumulated from the child process (before transform). */ + readonly stdout: string; + /** Raw stderr accumulated from the child process. */ + readonly stderr: string; + /** The process exit code, or null when the process was killed/timed out. */ + readonly exitCode: number | null; + /** Whether the process timed out. */ + readonly timedOut: boolean; +} + +export type RunCaptureHandler = (capture: RunCapture) => void; + +const TERMINATION_GRACE_MS = 500; +const FORCE_KILL_CLOSE_GRACE_MS = 500; + +function signalProcess(child: ChildProcess, signal: NodeJS.Signals): void { + if (process.platform !== 'win32' && child.pid !== undefined) { + try { + process.kill(-child.pid, signal); + return; + } catch { + // The child may have exited between the timeout and the signal. + } + } + + if ( + process.platform === 'win32' && + signal === 'SIGKILL' && + child.pid !== undefined + ) { + const killer = spawn('taskkill', ['/pid', String(child.pid), '/t', '/f'], { + stdio: 'ignore', + windowsHide: true, + }); + killer.once('error', () => {}); + return; + } + + child.kill(signal); +} + +function createTimeoutError(timeoutMs: number): Error { + return new Error(`TestRig.run() timed out after ${timeoutMs}ms`); +} + +function captureRun( + accumulator: StreamAccumulator, + exitCode: number | null, + timedOut: boolean, + onCapture: RunCaptureHandler | undefined, +): void { + onCapture?.({ + stdout: accumulator.stdout, + stderr: accumulator.stderr, + exitCode, + timedOut, + }); +} + /** * Stream handler that accumulates stdout/stderr and mirrors them to the * terminal when verbose output is enabled. @@ -56,13 +122,15 @@ export interface RunContext { /** * Spawn a child process for `TestRig.run` / `runCommand` and resolve with the - * captured stdout. Mirrors output when verbose mode is enabled. + * captured stdout. Mirrors output when verbose mode is enabled and reports the + * structured raw capture before resolving or rejecting. */ export function spawnRun( ctx: RunContext, options: RunOptions, isJsonOutput: boolean, transform: (stdout: string) => string, + onCapture?: RunCaptureHandler, ): Promise { const { onStdout, onStderr, accumulator } = createStreamHandlers(); @@ -72,13 +140,28 @@ export function spawnRun( env: ctx.childEnv, }); - pipeStdin(child, options); - child.stdout.on('data', onStdout); child.stderr.on('data', onStderr); return new Promise((resolve, reject) => { - child.on('close', (code: number) => { + let settled = false; + + child.once('error', (error) => { + if (settled) { + return; + } + settled = true; + captureRun(accumulator, null, false, onCapture); + reject(error); + }); + + child.on('close', (code: number | null) => { + if (settled) { + return; + } + settled = true; + captureRun(accumulator, code, false, onCapture); + if (code === 0) { const transformed = transform(accumulator.stdout); resolve( @@ -90,18 +173,19 @@ export function spawnRun( ); } }); + + pipeStdin(child, options); }); } -/** - * Spawn a child process with a timeout for `TestRig.run`. - */ +/** Spawn a run with bounded SIGTERM/SIGKILL timeout handling. */ export function spawnRunWithTimeout( ctx: RunContext, options: RunOptions, isJsonOutput: boolean, transform: (stdout: string) => string, timeoutMs: number, + onCapture?: RunCaptureHandler, ): Promise { const { onStdout, onStderr, accumulator } = createStreamHandlers(); @@ -109,17 +193,65 @@ export function spawnRunWithTimeout( cwd: ctx.testDir, stdio: 'pipe', env: ctx.childEnv, + detached: process.platform !== 'win32', }); - pipeStdin(child, options); - child.stdout.on('data', onStdout); child.stderr.on('data', onStderr); - let timeoutHandle: NodeJS.Timeout; - const processPromise = new Promise((resolve, reject) => { - child.on('close', (code: number) => { - clearTimeout(timeoutHandle); + return new Promise((resolve, reject) => { + let settled = false; + let didTimeout = false; + const timers: NodeJS.Timeout[] = []; + const timeoutError = createTimeoutError(timeoutMs); + const settleTimedOut = (): void => { + if (!settled) { + settled = true; + captureRun(accumulator, null, true, onCapture); + reject(timeoutError); + } + }; + const forceKill = (): void => { + signalProcess(child, 'SIGKILL'); + timers.push(setTimeout(settleTimedOut, FORCE_KILL_CLOSE_GRACE_MS)); + }; + timers.push( + setTimeout(() => { + didTimeout = true; + signalProcess(child, 'SIGTERM'); + timers.push(setTimeout(forceKill, TERMINATION_GRACE_MS)); + }, timeoutMs), + ); + const clearTimers = (): void => { + for (const timer of timers) { + clearTimeout(timer); + } + }; + + child.once('error', (error) => { + if (!settled) { + settled = true; + if (!didTimeout) { + clearTimers(); + } + captureRun(accumulator, null, didTimeout, onCapture); + reject(didTimeout ? timeoutError : error); + } + }); + + child.on('close', (code: number | null) => { + if (settled) { + return; + } + settled = true; + clearTimers(); + captureRun(accumulator, code, didTimeout, onCapture); + + if (didTimeout) { + reject(timeoutError); + return; + } + if (code === 0) { const transformed = transform(accumulator.stdout); resolve( @@ -131,16 +263,9 @@ export function spawnRunWithTimeout( ); } }); - }); - const timeoutPromise = new Promise((_resolve, reject) => { - timeoutHandle = setTimeout(() => { - child.kill('SIGTERM'); - reject(new Error(`TestRig.run() timed out after ${timeoutMs}ms`)); - }, timeoutMs); + pipeStdin(child, options); }); - - return Promise.race([processPromise, timeoutPromise]); } function maybeAppendStderr( diff --git a/packages/test-utils/src/stdout-filter.test.ts b/packages/test-utils/src/stdout-filter.test.ts new file mode 100644 index 0000000000..ce6bcc8e80 --- /dev/null +++ b/packages/test-utils/src/stdout-filter.test.ts @@ -0,0 +1,185 @@ +/** + * @license + * Copyright 2025 Vybestack LLC + * SPDX-License-Identifier: Apache-2.0 + */ + +import { describe, expect, it } from 'bun:test'; +import { stripTelemetryFromStdout } from './stdout-filter.js'; + +describe('stripTelemetryFromStdout', () => { + it('preserves pretty-printed CLI JSON and its whitespace', () => { + const cliJson = [ + '{', + ' "response": "$blue$",', + ' "session_id": "session-1",', + ' "stats": { "tools": { "totalCalls": 1 } }', + '}', + '', + ].join('\r\n'); + + expect(stripTelemetryFromStdout(cliJson)).toBe(cliJson); + }); + + it('preserves ordinary JSON that happens to contain telemetry-like keys', () => { + const value = JSON.stringify( + { + body: 'user content', + timestamp: 123, + attributes: { theme: 'blue' }, + }, + null, + 2, + ); + + expect(stripTelemetryFromStdout(value)).toBe(value); + }); + + it('preserves ordinary JSON with only an LLxprt event name', () => { + const value = JSON.stringify( + { attributes: { 'event.name': 'llxprt_code.tool_call' } }, + null, + 2, + ); + + expect(stripTelemetryFromStdout(value)).toBe(value); + }); + + it('preserves a CLI response envelope even with telemetry-shaped fields', () => { + const value = JSON.stringify( + { + response: '$blue$', + attributes: { 'event.name': 'llxprt_code.tool_call' }, + }, + null, + 2, + ); + + expect(stripTelemetryFromStdout(value)).toBe(value); + }); + + it('preserves inspected objects without the LLxprt service identity', () => { + const value = [ + '{', + " resource: { attributes: { 'service.name': 'user-content' } },", + " instrumentationScope: { name: 'user-content' }", + '}', + ].join('\n'); + + expect(stripTelemetryFromStdout(value)).toBe(value); + }); + + it('removes JSON telemetry events identified by llxprt event name', () => { + const telemetry = JSON.stringify( + { + timestamp: 123, + body: 'Tool call: save_memory. Success: true. Duration: 5ms', + attributes: { + 'event.name': 'llxprt_code.tool_call', + function_args: '{"fact":"test {value}"}', + }, + }, + null, + 2, + ); + + expect(stripTelemetryFromStdout(`${telemetry}\n$blue$\n`)).toBe('$blue$\n'); + }); + + it('preserves tool-call-shaped JSON without a telemetry timestamp', () => { + const value = JSON.stringify({ + body: 'Tool call: read_file. Success: true. Duration: 2ms', + attributes: { function_args: '{}' }, + }); + + expect(stripTelemetryFromStdout(value)).toBe(value); + }); + + it('removes fallback telemetry records with timestamp, body, and attributes', () => { + const telemetry = JSON.stringify({ + timestamp: 123, + body: 'Tool call: read_file. Success: true. Duration: 2ms', + attributes: { function_args: '{}' }, + }); + + expect(stripTelemetryFromStdout(`${telemetry}\nanswer`)).toBe('answer'); + }); + + it('removes Node-inspected OpenTelemetry log exporter output', () => { + const inspected = [ + '{', + " resource: { attributes: { 'service.name': 'llxprt-code' } },", + " instrumentationScope: { name: 'llxprt-code' },", + ' timestamp: 123,', + " body: 'Tool call: save_memory with { braces }',", + " attributes: { 'event.name': 'llxprt_code.tool_call' }", + '}', + '{', + ' "response": "$blue$"', + '}', + ].join('\n'); + + expect(JSON.parse(stripTelemetryFromStdout(inspected))).toEqual({ + response: '$blue$', + }); + }); + + it('removes differently indented Node-inspected telemetry output', () => { + const inspected = [ + '{', + "\tresource: { attributes: { 'service.name': 'llxprt-code' } },", + "\tinstrumentationScope: { name: 'llxprt-code' },", + "\tbody: 'Tool call: save_memory'", + '}', + 'done', + ].join('\n'); + + expect(stripTelemetryFromStdout(inspected)).toBe('done'); + }); + + it('removes Node-inspected OpenTelemetry metric exporter output', () => { + const inspected = [ + '{', + " descriptor: { name: 'llxprt.requests' },", + ' dataPointType: 3,', + ' dataPoints: []', + '}', + 'done', + ].join('\n'); + + expect(stripTelemetryFromStdout(inspected)).toBe('done'); + }); + + it('preserves blank lines that are not part of a removed object', () => { + const input = 'first\n\nsecond\n'; + + expect(stripTelemetryFromStdout(input)).toBe(input); + }); + + it('preserves malformed and inline JSON-like text', () => { + const input = + 'prefix {"attributes":{"event.name":"llxprt_code.x"}} suffix\n{ broken'; + + expect(stripTelemetryFromStdout(input)).toBe(input); + }); + + it('continues filtering after malformed object-like output', () => { + const input = [ + '{ malformed user output', + '{', + " resource: { attributes: { 'service.name': 'llxprt-code' } },", + " instrumentationScope: { name: 'llxprt-code' },", + " body: 'Tool call: save_memory'", + '}', + '{', + ' "response": "$blue$"', + '}', + ].join('\n'); + + expect(stripTelemetryFromStdout(input)).toBe( + ['{ malformed user output', '{', ' "response": "$blue$"', '}'].join( + '\n', + ), + ); + }); +}); diff --git a/packages/test-utils/src/stdout-filter.ts b/packages/test-utils/src/stdout-filter.ts index c9ed8d14c6..5af33bdde0 100644 --- a/packages/test-utils/src/stdout-filter.ts +++ b/packages/test-utils/src/stdout-filter.ts @@ -4,57 +4,221 @@ * SPDX-License-Identifier: Apache-2.0 */ -import * as os from 'node:os'; - -interface FilterState { - inTelemetryObject: boolean; - braceDepth: number; +interface ObjectRange { + readonly start: number; + readonly end: number; } +const EVENT_NAME_ATTRIBUTE = 'event.name'; +const LLXPRT_EVENT_PREFIX = 'llxprt_code.'; +const TOOL_CALL_BODY_PREFIX = 'Tool call:'; +const FUNCTION_NAME_ATTRIBUTE = 'function_name'; +const FUNCTION_ARGS_ATTRIBUTE = 'function_args'; +const LLXPRT_SERVICE_NAME_PATTERN = + /['"]service\.name['"]:\s*['"]llxprt-code['"]/; +const INSTRUMENTATION_SCOPE_FIELD = 'instrumentationScope:'; +const METRIC_DESCRIPTOR_FIELD = 'descriptor:'; +const LLXPRT_METRIC_NAME_PATTERN = /name:\s*['"]llxprt[._-]/m; +const DATA_POINT_TYPE_FIELD = 'dataPointType:'; +const DATA_POINTS_FIELD = 'dataPoints:'; + /** - * Strip Podman telemetry JSON objects (multi-line `{ ... }` blocks) from - * captured stdout. Podman emits telemetry to stdout even when writing to a - * file, so these must be removed to recover the real CLI output. + * Strip OpenTelemetry console-exporter objects from Podman stdout while + * preserving regular CLI output, including `--output-format json` payloads. */ export function stripTelemetryFromStdout(stdout: string): string { - const lines = stdout.split(os.EOL); - const filteredLines: string[] = []; - const state: FilterState = { inTelemetryObject: false, braceDepth: 0 }; - - for (const line of lines) { - const kept = processLine(line, state); - if (kept !== null) { - filteredLines.push(kept); + const output: string[] = []; + let cursor = 0; + + while (cursor < stdout.length) { + const objectStart = findObjectStart(stdout, cursor); + if (objectStart === null) { + output.push(stdout.slice(cursor)); + cursor = stdout.length; + } else { + const objectEnd = findObjectEnd(stdout, objectStart); + if (objectEnd === null) { + const nextLineStart = findNextLineStart(stdout, objectStart); + output.push(stdout.slice(cursor, nextLineStart)); + cursor = nextLineStart; + } else if (isTelemetryObject(stdout.slice(objectStart, objectEnd + 1))) { + const range = expandStandaloneLine(stdout, objectStart, objectEnd); + output.push(stdout.slice(cursor, range.start)); + cursor = range.end; + } else { + output.push(stdout.slice(cursor, objectEnd + 1)); + cursor = objectEnd + 1; + } } } - return filteredLines.join('\n'); + return output.join(''); } -/** - * Process a single line, mutating filter state. Returns the line to keep, or - * null when the line is part of a telemetry object and should be dropped. - */ -function processLine(line: string, state: FilterState): string | null { - if (!state.inTelemetryObject && line.trim() === '{') { - state.inTelemetryObject = true; - state.braceDepth = 1; - return null; +function findNextLineStart(text: string, fromIndex: number): number { + const newline = text.indexOf('\n', fromIndex); + return newline === -1 ? text.length : newline + 1; +} + +function findObjectStart(text: string, fromIndex: number): number | null { + let lineStart = fromIndex; + + while (lineStart < text.length) { + const lineEnd = text.indexOf('\n', lineStart); + const contentEnd = lineEnd === -1 ? text.length : lineEnd; + let contentStart = lineStart; + while ( + contentStart < contentEnd && + (text[contentStart] === ' ' || + text[contentStart] === '\t' || + text[contentStart] === '\r') + ) { + contentStart++; + } + if (text[contentStart] === '{') { + return contentStart; + } + if (lineEnd === -1) { + return null; + } + lineStart = lineEnd + 1; + } + + return null; +} + +function findObjectEnd(text: string, startIndex: number): number | null { + let depth = 0; + let quote: '"' | "'" | '`' | null = null; + let escaped = false; + + for (let index = startIndex; index < text.length; index++) { + const char = text[index]; + if (escaped) { + escaped = false; + } else if (quote !== null && char === '\\') { + escaped = true; + } else if (char === '"' || char === "'" || char === '`') { + if (quote === null) { + quote = char; + } else if (quote === char) { + quote = null; + } + } else if (quote === null) { + depth = updateBraceDepth(char, depth); + if (depth === 0) { + return index; + } + } + } + + return null; +} + +function updateBraceDepth(char: string, depth: number): number { + if (char === '{') { + return depth + 1; } - if (!state.inTelemetryObject) { - return line; + if (char === '}') { + return depth - 1; } + return depth; +} - for (const char of line) { - if (char === '{') { - state.braceDepth++; - } else if (char === '}') { - state.braceDepth--; +function isTelemetryObject(objectText: string): boolean { + const parsed = parseJsonRecord(objectText); + if (parsed !== null) { + if (typeof parsed['response'] === 'string') { + return false; } + return isJsonTelemetryObject(parsed); } + return isInspectedTelemetryObject(objectText); +} - if (state.braceDepth === 0) { - state.inTelemetryObject = false; +function parseJsonRecord(text: string): Record | null { + try { + const parsed: unknown = JSON.parse(text); + return isRecord(parsed) ? parsed : null; + } catch { + return null; } - return null; +} + +function isRecord(value: unknown): value is Record { + return typeof value === 'object' && value !== null && !Array.isArray(value); +} + +function isJsonTelemetryObject(value: Record): boolean { + const attributes = value['attributes']; + if (isRecord(attributes)) { + const eventName = attributes[EVENT_NAME_ATTRIBUTE]; + if ( + typeof eventName === 'string' && + eventName.startsWith(LLXPRT_EVENT_PREFIX) && + typeof value['timestamp'] === 'number' && + typeof value['body'] === 'string' + ) { + return true; + } + } + + if ( + typeof value['timestamp'] !== 'number' || + typeof value['body'] !== 'string' || + !value['body'].startsWith(TOOL_CALL_BODY_PREFIX) || + !isRecord(attributes) + ) { + return false; + } + + return ( + typeof attributes[FUNCTION_NAME_ATTRIBUTE] === 'string' || + typeof attributes[FUNCTION_ARGS_ATTRIBUTE] === 'string' + ); +} + +function isInspectedTelemetryObject(objectText: string): boolean { + const hasServiceIdentity = LLXPRT_SERVICE_NAME_PATTERN.test(objectText); + const hasInstrumentationScope = hasInspectedField( + objectText, + INSTRUMENTATION_SCOPE_FIELD, + ); + if (hasServiceIdentity && hasInstrumentationScope) { + return true; + } + + return ( + hasInspectedField(objectText, METRIC_DESCRIPTOR_FIELD) && + LLXPRT_METRIC_NAME_PATTERN.test(objectText) && + hasInspectedField(objectText, DATA_POINT_TYPE_FIELD) && + hasInspectedField(objectText, DATA_POINTS_FIELD) + ); +} + +function hasInspectedField(objectText: string, field: string): boolean { + return objectText + .split(/\r?\n/) + .some((line) => line.trimStart().startsWith(field)); +} + +function expandStandaloneLine( + text: string, + objectStart: number, + objectEnd: number, +): ObjectRange { + const lineStart = text.lastIndexOf('\n', objectStart - 1) + 1; + const lineEnd = text.indexOf('\n', objectEnd + 1); + const contentEnd = lineEnd === -1 ? text.length : lineEnd; + const before = text.slice(lineStart, objectStart); + const after = text.slice(objectEnd + 1, contentEnd); + + if (before.trim().length > 0 || after.trim().length > 0) { + return { start: objectStart, end: objectEnd + 1 }; + } + + return { + start: lineStart, + end: lineEnd === -1 ? text.length : lineEnd + 1, + }; } diff --git a/packages/test-utils/src/test-rig.test.ts b/packages/test-utils/src/test-rig.test.ts index 430b6ad704..d868a433fe 100644 --- a/packages/test-utils/src/test-rig.test.ts +++ b/packages/test-utils/src/test-rig.test.ts @@ -68,4 +68,25 @@ describe('TestRig setup and cleanup behavior', () => { expect(testDir).not.toBeNull(); expect(existsSync(testDir as string)).toBe(true); }); + + it('rejects overlapping run operations on one rig', async () => { + createRoot(); + const rig = new TestRig(); + rig.setup('overlapping runs'); + + const firstRun = rig.runCommand(['--version']); + const secondRun = rig.runCommand(['--version']); + + try { + await secondRun; + throw new Error('Expected the overlapping run to reject'); + } catch (error) { + if (!(error instanceof Error)) { + throw new Error(`Expected Error, received ${String(error)}`); + } + expect(error.message).toMatch(/overlapping run operations/); + } + + await firstRun; + }); }); diff --git a/packages/test-utils/src/test-rig.ts b/packages/test-utils/src/test-rig.ts index e06be7a3a5..e8ad7bfde9 100644 --- a/packages/test-utils/src/test-rig.ts +++ b/packages/test-utils/src/test-rig.ts @@ -42,6 +42,7 @@ import { spawnRun, spawnRunWithTimeout, type RunContext, + type RunCapture, } from './process-run.js'; import type { ParsedLog } from './types.js'; @@ -54,6 +55,7 @@ export type { HookLogEntry, TelemetryAttributes, } from './types.js'; +export type { RunCapture } from './process-run.js'; export { CommandRun } from './command-run.js'; export { InteractiveRun } from './interactive-run.js'; export { @@ -103,6 +105,8 @@ export class TestRig { testDir: string | null = null; testName: string | undefined; _lastRunStdout: string | undefined; + private _lastRunCapture: RunCapture | null = null; + private _runInProgress = false; fakeResponsesPath: string | undefined; originalFakeResponsesPath: string | undefined; private _interactiveRuns: InteractiveRun[] = []; @@ -120,6 +124,25 @@ export class TestRig { this._diagnostics.dump(label, content); } + /** + * Return a copy of the structured capture (raw stdout, stderr, exitCode, + * timedOut) from the most recent `run` / `runCommand`, or null when no run + * has completed. The capture reflects the raw child streams before any + * transform or stderr-append logic. + */ + getLastRunCapture(): RunCapture | null { + return this._lastRunCapture === null ? null : { ...this._lastRunCapture }; + } + + private beginRun(): void { + if (this._runInProgress) { + throw new Error('TestRig does not support overlapping run operations'); + } + this._runInProgress = true; + this._lastRunCapture = null; + this._lastRunStdout = undefined; + } + setup(testName: string, options: TestRigSetupOptions = {}) { this.testName = testName; const sanitizedName = sanitizeTestName(testName); @@ -171,64 +194,87 @@ export class TestRig { } async run(options: RunMethodOptions): Promise { - assertProviderConfig(this.fakeResponsesPath); + this.beginRun(); + try { + assertProviderConfig(this.fakeResponsesPath); - const yolo = options.yolo !== false; - const extraArgs = buildExtraArgs(this.fakeResponsesPath, yolo); - const { command, initialArgs } = this._getCommandAndArgs(extraArgs); - const commandArgs = [...initialArgs]; + const yolo = options.yolo !== false; + const extraArgs = buildExtraArgs(this.fakeResponsesPath, yolo); + const { command, initialArgs } = this._getCommandAndArgs(extraArgs); + const commandArgs = [...initialArgs]; - appendUserArgs(commandArgs, options.args); - appendProfileFlag(commandArgs); + appendUserArgs(commandArgs, options.args); + appendProfileFlag(commandArgs); - const childEnv = buildChildEnv( - this.testDir as string, - this.fakeResponsesPath, - ); - const isJsonOutput = - commandArgs.includes('--output-format') && commandArgs.includes('json'); - - const ctx: RunContext = { - command, - commandArgs, - testDir: this.testDir as string, - childEnv, - }; - - const transform = (stdout: string): string => { - this._lastRunStdout = stdout; - if (env['LLXPRT_SANDBOX'] === 'podman') { - return stripTelemetryFromStdout(stdout); - } - return stdout; - }; - - return spawnRunWithTimeout( - ctx, - options, - isJsonOutput, - transform, - getDefaultTimeout() * 4, - ); + const childEnv = buildChildEnv( + this.testDir as string, + this.fakeResponsesPath, + ); + const isJsonOutput = + commandArgs.includes('--output-format') && commandArgs.includes('json'); + + const ctx: RunContext = { + command, + commandArgs, + testDir: this.testDir as string, + childEnv, + }; + + const transform = (stdout: string): string => { + this._lastRunStdout = stdout; + if (env['LLXPRT_SANDBOX'] === 'podman') { + return stripTelemetryFromStdout(stdout); + } + return stdout; + }; + + return await spawnRunWithTimeout( + ctx, + options, + isJsonOutput, + transform, + getDefaultTimeout() * 4, + (capture) => { + this._lastRunCapture = capture; + this._lastRunStdout = capture.stdout; + }, + ); + } finally { + this._runInProgress = false; + } } async runCommand( args: string[], options: { stdin?: string } = {}, ): Promise { - const { command, initialArgs } = this._getCommandAndArgs(); - const commandArgs = [...initialArgs, ...args]; - - const ctx: RunContext = { - command, - commandArgs, - testDir: this.testDir as string, - }; - - return spawnRun(ctx, { stdin: options.stdin }, false, (stdout) => { - this._lastRunStdout = stdout; - return stdout; - }); + this.beginRun(); + try { + const { command, initialArgs } = this._getCommandAndArgs(); + const commandArgs = [...initialArgs, ...args]; + + const ctx: RunContext = { + command, + commandArgs, + testDir: this.testDir as string, + }; + + return await spawnRun( + ctx, + { stdin: options.stdin }, + false, + (stdout) => { + this._lastRunStdout = stdout; + return stdout; + }, + (capture) => { + this._lastRunCapture = capture; + this._lastRunStdout = capture.stdout; + }, + ); + } finally { + this._runInProgress = false; + } } readFile(fileName: string): string { diff --git a/scripts/tests/evals-save-memory-assertion.test.js b/scripts/tests/evals-save-memory-assertion.test.js index d5eceb3998..22e2abfd72 100644 --- a/scripts/tests/evals-save-memory-assertion.test.js +++ b/scripts/tests/evals-save-memory-assertion.test.js @@ -9,6 +9,84 @@ import { pathToFileURL } from 'node:url'; import { join, resolve } from 'node:path'; const ROOT = resolve(import.meta.dirname, '../..'); +describe('eval JSON output contract', () => { + /** @type {(prompt: string) => string[]} */ + let buildEvalArgs; + /** @type {(output: string) => string} */ + let extractModelResponse; + /** @type {(capture: { stdout: string, stderr: string, exitCode: number | null, timedOut: boolean } | null, toolCalls: unknown) => string} */ + let formatEvalLog; + + beforeAll(async () => { + const url = pathToFileURL(join(ROOT, 'evals/test-helper.ts')).href; + const mod = await import(url); + buildEvalArgs = mod.buildEvalArgs; + extractModelResponse = mod.extractModelResponse; + formatEvalLog = mod.formatEvalLog; + }); + + it('requests structured JSON output for eval prompts', () => { + expect(buildEvalArgs('--remember this')).toEqual([ + '--prompt=--remember this', + '--output-format', + 'json', + ]); + }); + + it('extracts only the assistant response from CLI JSON output', () => { + const cliOutput = JSON.stringify({ + session_id: 'session-1', + response: '$blue$', + stats: { tools: { totalCalls: 1 } }, + }); + + expect(extractModelResponse(cliOutput)).toBe('$blue$'); + }); + + it('rejects malformed CLI JSON output', () => { + expect(() => extractModelResponse('not json')).toThrow( + /valid JSON output/i, + ); + }); + + it('rejects CLI JSON output without a response', () => { + expect(() => + extractModelResponse(JSON.stringify({ session_id: 'session-1' })), + ).toThrow(/string response/i); + }); + + it('rejects CLI JSON output with a non-string response', () => { + expect(() => + extractModelResponse( + JSON.stringify({ session_id: 'session-1', response: 42 }), + ), + ).toThrow(/string response/i); + }); + + it('includes structured run capture and tool calls in the eval artifact log', () => { + const capture = { + stdout: '{"response":"$blue$"}', + stderr: 'some diagnostic', + exitCode: 0, + timedOut: false, + }; + const toolCalls = [{ toolRequest: { name: 'save_memory' } }]; + + expect(JSON.parse(formatEvalLog(capture, toolCalls))).toEqual({ + schemaVersion: 1, + capture, + toolCalls, + }); + }); + + it('serializes a null capture when no run has occurred', () => { + expect(JSON.parse(formatEvalLog(null, []))).toEqual({ + schemaVersion: 1, + capture: null, + toolCalls: [], + }); + }); +}); /** * Issue #2605: The save_memory eval contract is deterministic. The prompt tells From 55e43124317bf9407c3317fcf58a1be44e09c96e Mon Sep 17 00:00:00 2001 From: acoliver Date: Thu, 23 Jul 2026 14:15:34 -0300 Subject: [PATCH 2/6] Cover graceful eval process shutdown --- packages/test-utils/src/process-run.test.ts | 33 +++++++++++++++++++++ packages/test-utils/src/stdout-filter.ts | 2 ++ 2 files changed, 35 insertions(+) diff --git a/packages/test-utils/src/process-run.test.ts b/packages/test-utils/src/process-run.test.ts index c92ba9c8e2..983ba70aee 100644 --- a/packages/test-utils/src/process-run.test.ts +++ b/packages/test-utils/src/process-run.test.ts @@ -128,6 +128,39 @@ describe('process run capture', () => { }); }); + it('captures a timed-out run that exits gracefully after SIGTERM', async () => { + let capture: RunCapture | undefined; + const run = spawnRunWithTimeout( + bunContext( + [ + 'process.on("SIGTERM", () => {', + ' process.stdout.write(" graceful-out");', + ' process.stderr.write("graceful-err");', + ' process.exit(0);', + '});', + 'process.stdout.write("started");', + 'setInterval(() => {}, 1000);', + ].join('\n'), + makeTempDir(), + ), + {}, + false, + identityTransform, + 500, + (value) => { + capture = value; + }, + ); + + await expectRejection(run, /timed out/); + expect(capture).toEqual({ + stdout: 'started graceful-out', + stderr: 'graceful-err', + exitCode: 0, + timedOut: true, + }); + }); + it('captures shutdown output and force-kills a run that ignores SIGTERM', async () => { let capture: RunCapture | undefined; const run = spawnRunWithTimeout( diff --git a/packages/test-utils/src/stdout-filter.ts b/packages/test-utils/src/stdout-filter.ts index 5af33bdde0..b4b0c5ee9a 100644 --- a/packages/test-utils/src/stdout-filter.ts +++ b/packages/test-utils/src/stdout-filter.ts @@ -149,6 +149,7 @@ function isRecord(value: unknown): value is Record { return typeof value === 'object' && value !== null && !Array.isArray(value); } +/** Recognize OpenTelemetry JSON LogRecord objects emitted to stdout. */ function isJsonTelemetryObject(value: Record): boolean { const attributes = value['attributes']; if (isRecord(attributes)) { @@ -178,6 +179,7 @@ function isJsonTelemetryObject(value: Record): boolean { ); } +/** Recognize Node util.inspect output from OpenTelemetry console exporters. */ function isInspectedTelemetryObject(objectText: string): boolean { const hasServiceIdentity = LLXPRT_SERVICE_NAME_PATTERN.test(objectText); const hasInstrumentationScope = hasInspectedField( From 5b0533fc5164786ebb099c7df870b35076a7d4fd Mon Sep 17 00:00:00 2001 From: acoliver Date: Thu, 23 Jul 2026 14:19:29 -0300 Subject: [PATCH 3/6] Harden eval review edge cases --- packages/test-utils/src/process-run.test.ts | 4 ++-- packages/test-utils/src/process-run.ts | 7 ++++-- packages/test-utils/src/stdout-filter.ts | 24 +++++++++++++++++-- .../tests/evals-save-memory-assertion.test.js | 23 ++++++++++++++++++ 4 files changed, 52 insertions(+), 6 deletions(-) diff --git a/packages/test-utils/src/process-run.test.ts b/packages/test-utils/src/process-run.test.ts index 983ba70aee..b25b62bbd7 100644 --- a/packages/test-utils/src/process-run.test.ts +++ b/packages/test-utils/src/process-run.test.ts @@ -146,7 +146,7 @@ describe('process run capture', () => { {}, false, identityTransform, - 500, + 1500, (value) => { capture = value; }, @@ -178,7 +178,7 @@ describe('process run capture', () => { {}, false, identityTransform, - 500, + 1500, (value) => { capture = value; }, diff --git a/packages/test-utils/src/process-run.ts b/packages/test-utils/src/process-run.ts index 6155019472..dca9a78fe9 100644 --- a/packages/test-utils/src/process-run.ts +++ b/packages/test-utils/src/process-run.ts @@ -40,6 +40,9 @@ function signalProcess(child: ChildProcess, signal: NodeJS.Signals): void { } } + // Windows has no POSIX-style graceful process-tree signal. The timeout path + // therefore waits through the grace period before taskkill force-terminates + // the tree; child.kill('SIGTERM') only targets the immediate process there. if ( process.platform === 'win32' && signal === 'SIGKILL' && @@ -155,7 +158,7 @@ export function spawnRun( reject(error); }); - child.on('close', (code: number | null) => { + child.once('close', (code: number | null) => { if (settled) { return; } @@ -239,7 +242,7 @@ export function spawnRunWithTimeout( } }); - child.on('close', (code: number | null) => { + child.once('close', (code: number | null) => { if (settled) { return; } diff --git a/packages/test-utils/src/stdout-filter.ts b/packages/test-utils/src/stdout-filter.ts index b4b0c5ee9a..bb1e8ea36c 100644 --- a/packages/test-utils/src/stdout-filter.ts +++ b/packages/test-utils/src/stdout-filter.ts @@ -18,7 +18,7 @@ const LLXPRT_SERVICE_NAME_PATTERN = /['"]service\.name['"]:\s*['"]llxprt-code['"]/; const INSTRUMENTATION_SCOPE_FIELD = 'instrumentationScope:'; const METRIC_DESCRIPTOR_FIELD = 'descriptor:'; -const LLXPRT_METRIC_NAME_PATTERN = /name:\s*['"]llxprt[._-]/m; +const METRIC_NAME_FIELD = 'name:'; const DATA_POINT_TYPE_FIELD = 'dataPointType:'; const DATA_POINTS_FIELD = 'dataPoints:'; @@ -192,7 +192,7 @@ function isInspectedTelemetryObject(objectText: string): boolean { return ( hasInspectedField(objectText, METRIC_DESCRIPTOR_FIELD) && - LLXPRT_METRIC_NAME_PATTERN.test(objectText) && + hasLlxprtMetricName(objectText) && hasInspectedField(objectText, DATA_POINT_TYPE_FIELD) && hasInspectedField(objectText, DATA_POINTS_FIELD) ); @@ -204,6 +204,26 @@ function hasInspectedField(objectText: string, field: string): boolean { .some((line) => line.trimStart().startsWith(field)); } +function hasLlxprtMetricName(objectText: string): boolean { + return objectText.split(/\r?\n/).some((line) => { + const trimmed = line.trimStart(); + if (!trimmed.startsWith(METRIC_DESCRIPTOR_FIELD)) { + return false; + } + const nameIndex = trimmed.indexOf(METRIC_NAME_FIELD); + if (nameIndex === -1) { + return false; + } + const value = trimmed + .slice(nameIndex + METRIC_NAME_FIELD.length) + .trimStart(); + return ( + (value.startsWith("'llxprt") || value.startsWith('"llxprt')) && + ['.', '_', '-'].includes(value[7]) + ); + }); +} + function expandStandaloneLine( text: string, objectStart: number, diff --git a/scripts/tests/evals-save-memory-assertion.test.js b/scripts/tests/evals-save-memory-assertion.test.js index 22e2abfd72..20704cc39f 100644 --- a/scripts/tests/evals-save-memory-assertion.test.js +++ b/scripts/tests/evals-save-memory-assertion.test.js @@ -33,6 +33,16 @@ describe('eval JSON output contract', () => { ]); }); + it('preserves special characters and empty prompts as a single argument', () => { + const prompt = 'line one\n"quoted" \\path --flag'; + expect(buildEvalArgs(prompt)).toEqual([ + `--prompt=${prompt}`, + '--output-format', + 'json', + ]); + expect(buildEvalArgs('')[0]).toBe('--prompt='); + }); + it('extracts only the assistant response from CLI JSON output', () => { const cliOutput = JSON.stringify({ session_id: 'session-1', @@ -61,6 +71,19 @@ describe('eval JSON output contract', () => { JSON.stringify({ session_id: 'session-1', response: 42 }), ), ).toThrow(/string response/i); + expect(() => + extractModelResponse( + JSON.stringify({ session_id: 'session-1', response: null }), + ), + ).toThrow(/string response/i); + }); + + it('preserves an empty string response for the eval assertion to validate', () => { + expect( + extractModelResponse( + JSON.stringify({ session_id: 'session-1', response: '' }), + ), + ).toBe(''); }); it('includes structured run capture and tool calls in the eval artifact log', () => { From 27076b0825b41633dbce7537736c50b0c62bf5df Mon Sep 17 00:00:00 2001 From: acoliver Date: Thu, 23 Jul 2026 15:05:57 -0300 Subject: [PATCH 4/6] Harden eval failure diagnostics --- evals/test-helper.ts | 19 +++++++++++++++---- packages/test-utils/src/process-run.ts | 17 +++++++++++++++-- 2 files changed, 30 insertions(+), 6 deletions(-) diff --git a/evals/test-helper.ts b/evals/test-helper.ts index ce38aebd41..03fdc01024 100644 --- a/evals/test-helper.ts +++ b/evals/test-helper.ts @@ -33,8 +33,14 @@ export function extractModelResponse(output: string): string { const result = EvalOutputSchema.safeParse(parsed); if (!result.success) { + const details = result.error.issues + .map((issue) => { + const path = issue.path.join('.'); + return `${path === '' ? '' : path}: ${issue.message}`; + }) + .join('; '); throw new Error( - 'Expected LLxprt CLI JSON output to include a string response', + `Expected LLxprt CLI JSON output to include a string response: ${details}`, ); } return result.data.response; @@ -48,12 +54,16 @@ export function extractModelResponse(output: string): string { export interface EvalArtifact { readonly schemaVersion: 1; readonly capture: RunCapture | null; - readonly toolCalls: unknown; + readonly toolCalls: ReturnType | EvalArtifactError; +} + +interface EvalArtifactError { + readonly error: string; } export function formatEvalLog( capture: RunCapture | null, - toolCalls: unknown, + toolCalls: ReturnType | EvalArtifactError, ): string { const artifact: EvalArtifact = { schemaVersion: 1, capture, toolCalls }; return JSON.stringify(artifact, null, 2); @@ -115,7 +125,7 @@ export interface EvalCase { async function finalizeEval(rig: TestRig, name: string): Promise { const capture = rig.getLastRunCapture(); - let toolCalls: unknown; + let toolCalls: ReturnType | EvalArtifactError; try { toolCalls = rig.readToolLogs(); } catch (error) { @@ -142,6 +152,7 @@ async function finalizeEval(rig: TestRig, name: string): Promise { throw new AggregateError( [artifactError, cleanupError], 'Writing eval diagnostics and cleaning up both failed', + { cause: artifactError }, ); } if (artifactError !== undefined) { diff --git a/packages/test-utils/src/process-run.ts b/packages/test-utils/src/process-run.ts index dca9a78fe9..400db0e85e 100644 --- a/packages/test-utils/src/process-run.ts +++ b/packages/test-utils/src/process-run.ts @@ -33,6 +33,8 @@ const FORCE_KILL_CLOSE_GRACE_MS = 500; function signalProcess(child: ChildProcess, signal: NodeJS.Signals): void { if (process.platform !== 'win32' && child.pid !== undefined) { try { + // Timeout-managed children are spawned detached below, which makes the + // child PID the process-group ID on POSIX systems. process.kill(-child.pid, signal); return; } catch { @@ -52,11 +54,22 @@ function signalProcess(child: ChildProcess, signal: NodeJS.Signals): void { stdio: 'ignore', windowsHide: true, }); - killer.once('error', () => {}); + killer.once('error', () => { + try { + child.kill(signal); + } catch { + // The main child may already have exited while taskkill was starting. + } + }); + killer.unref(); return; } - child.kill(signal); + try { + child.kill(signal); + } catch { + // The child may have exited between the timeout and the fallback signal. + } } function createTimeoutError(timeoutMs: number): Error { From a789dc255f8c1e2fd3cec8e8b9a4a5967c238f47 Mon Sep 17 00:00:00 2001 From: acoliver Date: Thu, 23 Jul 2026 15:23:55 -0300 Subject: [PATCH 5/6] Isolate process capture callback failures --- packages/test-utils/src/process-run.test.ts | 29 ++++ packages/test-utils/src/process-run.ts | 151 ++++++++++++++------ 2 files changed, 138 insertions(+), 42 deletions(-) diff --git a/packages/test-utils/src/process-run.test.ts b/packages/test-utils/src/process-run.test.ts index b25b62bbd7..53cf803294 100644 --- a/packages/test-utils/src/process-run.test.ts +++ b/packages/test-utils/src/process-run.test.ts @@ -218,6 +218,35 @@ describe('process run capture', () => { }); }); + it('rejects instead of throwing when a capture handler fails', async () => { + const run = spawnRun( + bunContext('process.stdout.write("captured");', makeTempDir()), + {}, + true, + identityTransform, + () => { + throw new Error('capture handler failed'); + }, + ); + + await expectRejection(run, /capture handler failed/); + }); + + it('isolates capture handler failures in timeout-managed runs', async () => { + const run = spawnRunWithTimeout( + bunContext('process.stdout.write("captured");', makeTempDir()), + {}, + true, + identityTransform, + 1500, + () => { + throw new Error('timeout capture handler failed'); + }, + ); + + await expectRejection(run, /timeout capture handler failed/); + }); + it('keeps concurrent run captures isolated by callback', async () => { let firstCapture: RunCapture | undefined; let secondCapture: RunCapture | undefined; diff --git a/packages/test-utils/src/process-run.ts b/packages/test-utils/src/process-run.ts index 400db0e85e..b1bffe4f98 100644 --- a/packages/test-utils/src/process-run.ts +++ b/packages/test-utils/src/process-run.ts @@ -27,6 +27,10 @@ export interface RunCapture { export type RunCaptureHandler = (capture: RunCapture) => void; +interface CaptureFailure { + readonly error: unknown; +} + const TERMINATION_GRACE_MS = 500; const FORCE_KILL_CLOSE_GRACE_MS = 500; @@ -81,13 +85,25 @@ function captureRun( exitCode: number | null, timedOut: boolean, onCapture: RunCaptureHandler | undefined, -): void { - onCapture?.({ - stdout: accumulator.stdout, - stderr: accumulator.stderr, - exitCode, - timedOut, - }); +): CaptureFailure | null { + try { + onCapture?.({ + stdout: accumulator.stdout, + stderr: accumulator.stderr, + exitCode, + timedOut, + }); + return null; + } catch (error) { + return { error }; + } +} + +function captureErrorOr( + failure: CaptureFailure | null, + fallback: unknown, +): unknown { + return failure === null ? fallback : failure.error; } /** @@ -167,8 +183,9 @@ export function spawnRun( return; } settled = true; - captureRun(accumulator, null, false, onCapture); - reject(error); + reject( + captureErrorOr(captureRun(accumulator, null, false, onCapture), error), + ); }); child.once('close', (code: number | null) => { @@ -176,7 +193,11 @@ export function spawnRun( return; } settled = true; - captureRun(accumulator, code, false, onCapture); + const captureFailure = captureRun(accumulator, code, false, onCapture); + if (captureFailure !== null) { + reject(captureFailure.error); + return; + } if (code === 0) { const transformed = transform(accumulator.stdout); @@ -194,6 +215,57 @@ export function spawnRun( }); } +interface CloseRunContext { + readonly accumulator: StreamAccumulator; + readonly onCapture: RunCaptureHandler | undefined; + readonly timeoutError: Error; + readonly transform: (stdout: string) => string; + readonly isJsonOutput: boolean; + readonly resolve: (value: string) => void; + readonly reject: (reason?: unknown) => void; +} + +function settleClosedRun( + context: CloseRunContext, + code: number | null, + didTimeout: boolean, +): void { + const captureFailure = captureRun( + context.accumulator, + code, + didTimeout, + context.onCapture, + ); + if (captureFailure !== null) { + context.reject(captureFailure.error); + return; + } + if (didTimeout) { + context.reject(context.timeoutError); + } else if (code === 0) { + const transformed = context.transform(context.accumulator.stdout); + context.resolve( + maybeAppendStderr( + transformed, + context.accumulator.stderr, + context.isJsonOutput, + ), + ); + } else { + context.reject( + new Error( + `Process exited with code ${code}:\n${context.accumulator.stderr}`, + ), + ); + } +} + +function clearRunTimers(timers: NodeJS.Timeout[]): void { + for (const timer of timers) { + clearTimeout(timer); + } +} + /** Spawn a run with bounded SIGTERM/SIGKILL timeout handling. */ export function spawnRunWithTimeout( ctx: RunContext, @@ -223,8 +295,12 @@ export function spawnRunWithTimeout( const settleTimedOut = (): void => { if (!settled) { settled = true; - captureRun(accumulator, null, true, onCapture); - reject(timeoutError); + reject( + captureErrorOr( + captureRun(accumulator, null, true, onCapture), + timeoutError, + ), + ); } }; const forceKill = (): void => { @@ -238,45 +314,36 @@ export function spawnRunWithTimeout( timers.push(setTimeout(forceKill, TERMINATION_GRACE_MS)); }, timeoutMs), ); - const clearTimers = (): void => { - for (const timer of timers) { - clearTimeout(timer); - } - }; - child.once('error', (error) => { if (!settled) { settled = true; if (!didTimeout) { - clearTimers(); + clearRunTimers(timers); } - captureRun(accumulator, null, didTimeout, onCapture); - reject(didTimeout ? timeoutError : error); + const runError = didTimeout ? timeoutError : error; + reject( + captureErrorOr( + captureRun(accumulator, null, didTimeout, onCapture), + runError, + ), + ); } }); + const closeContext: CloseRunContext = { + accumulator, + onCapture, + timeoutError, + transform, + isJsonOutput, + resolve, + reject, + }; child.once('close', (code: number | null) => { - if (settled) { - return; - } - settled = true; - clearTimers(); - captureRun(accumulator, code, didTimeout, onCapture); - - if (didTimeout) { - reject(timeoutError); - return; - } - - if (code === 0) { - const transformed = transform(accumulator.stdout); - resolve( - maybeAppendStderr(transformed, accumulator.stderr, isJsonOutput), - ); - } else { - reject( - new Error(`Process exited with code ${code}:\n${accumulator.stderr}`), - ); + if (!settled) { + settled = true; + clearRunTimers(timers); + settleClosedRun(closeContext, code, didTimeout); } }); From 42d07b461a61e431acd618653fe5a6d117868bf9 Mon Sep 17 00:00:00 2001 From: acoliver Date: Thu, 23 Jul 2026 15:41:30 -0300 Subject: [PATCH 6/6] Preserve eval process failure context --- packages/test-utils/src/process-run.test.ts | 34 +++++++++- packages/test-utils/src/process-run.ts | 62 +++++++++++++------ packages/test-utils/src/stdout-filter.test.ts | 10 +++ packages/test-utils/src/stdout-filter.ts | 2 +- packages/test-utils/src/test-rig.ts | 6 +- 5 files changed, 86 insertions(+), 28 deletions(-) diff --git a/packages/test-utils/src/process-run.test.ts b/packages/test-utils/src/process-run.test.ts index 53cf803294..318cfdecc2 100644 --- a/packages/test-utils/src/process-run.test.ts +++ b/packages/test-utils/src/process-run.test.ts @@ -16,6 +16,7 @@ import { } from './process-run.js'; const tempDirs: string[] = []; +const SPAWN_TIMEOUT_MS = 1500; afterEach(() => { const dirs = tempDirs.slice(); @@ -146,7 +147,7 @@ describe('process run capture', () => { {}, false, identityTransform, - 1500, + SPAWN_TIMEOUT_MS, (value) => { capture = value; }, @@ -178,7 +179,7 @@ describe('process run capture', () => { {}, false, identityTransform, - 1500, + SPAWN_TIMEOUT_MS, (value) => { capture = value; }, @@ -193,6 +194,33 @@ describe('process run capture', () => { }); }); + it('preserves process and capture failures together', async () => { + const processErrorPattern = /code 3/; + const captureError = new Error('capture handler failed'); + const run = spawnRun( + bunContext('process.exit(3);', makeTempDir()), + {}, + false, + identityTransform, + () => { + throw captureError; + }, + ); + + try { + await run; + throw new Error('Expected promise to reject'); + } catch (error) { + expect(error).toBeInstanceOf(AggregateError); + const aggregate = error as AggregateError; + expect(aggregate.errors).toHaveLength(2); + expect((aggregate.errors[0] as Error).message).toMatch( + processErrorPattern, + ); + expect(aggregate.errors[1]).toBe(captureError); + } + }); + it('captures and rejects child-process spawn errors', async () => { let capture: RunCapture | undefined; const run = spawnRun( @@ -238,7 +266,7 @@ describe('process run capture', () => { {}, true, identityTransform, - 1500, + SPAWN_TIMEOUT_MS * 4, () => { throw new Error('timeout capture handler failed'); }, diff --git a/packages/test-utils/src/process-run.ts b/packages/test-utils/src/process-run.ts index b1bffe4f98..7dad7aeb87 100644 --- a/packages/test-utils/src/process-run.ts +++ b/packages/test-utils/src/process-run.ts @@ -103,7 +103,15 @@ function captureErrorOr( failure: CaptureFailure | null, fallback: unknown, ): unknown { - return failure === null ? fallback : failure.error; + if (failure === null) { + return fallback; + } + const aggregate = new AggregateError( + [fallback, failure.error], + 'Process run and capture handler both failed', + ); + Object.defineProperty(aggregate, 'cause', { value: fallback }); + return aggregate; } /** @@ -195,7 +203,17 @@ export function spawnRun( settled = true; const captureFailure = captureRun(accumulator, code, false, onCapture); if (captureFailure !== null) { - reject(captureFailure.error); + const processError = + code === 0 + ? null + : new Error( + `Process exited with code ${code}:\n${accumulator.stderr}`, + ); + reject( + processError === null + ? captureFailure.error + : captureErrorOr(captureFailure, processError), + ); return; } @@ -236,28 +254,34 @@ function settleClosedRun( didTimeout, context.onCapture, ); - if (captureFailure !== null) { - context.reject(captureFailure.error); - return; - } + let processError: Error | null = null; if (didTimeout) { - context.reject(context.timeoutError); - } else if (code === 0) { - const transformed = context.transform(context.accumulator.stdout); - context.resolve( - maybeAppendStderr( - transformed, - context.accumulator.stderr, - context.isJsonOutput, - ), + processError = context.timeoutError; + } else if (code !== 0) { + processError = new Error( + `Process exited with code ${code}:\n${context.accumulator.stderr}`, ); - } else { + } + if (captureFailure !== null) { context.reject( - new Error( - `Process exited with code ${code}:\n${context.accumulator.stderr}`, - ), + processError === null + ? captureFailure.error + : captureErrorOr(captureFailure, processError), ); + return; } + if (processError !== null) { + context.reject(processError); + return; + } + const transformed = context.transform(context.accumulator.stdout); + context.resolve( + maybeAppendStderr( + transformed, + context.accumulator.stderr, + context.isJsonOutput, + ), + ); } function clearRunTimers(timers: NodeJS.Timeout[]): void { diff --git a/packages/test-utils/src/stdout-filter.test.ts b/packages/test-utils/src/stdout-filter.test.ts index ce6bcc8e80..238f6b21ad 100644 --- a/packages/test-utils/src/stdout-filter.test.ts +++ b/packages/test-utils/src/stdout-filter.test.ts @@ -105,6 +105,16 @@ describe('stripTelemetryFromStdout', () => { expect(stripTelemetryFromStdout(`${telemetry}\nanswer`)).toBe('answer'); }); + it('removes fallback tool telemetry with leading body whitespace', () => { + const telemetry = JSON.stringify({ + timestamp: 123, + body: ' Tool call: read_file. Success: true. Duration: 2ms', + attributes: { function_args: '{}' }, + }); + + expect(stripTelemetryFromStdout(`${telemetry}\nanswer`)).toBe('answer'); + }); + it('removes Node-inspected OpenTelemetry log exporter output', () => { const inspected = [ '{', diff --git a/packages/test-utils/src/stdout-filter.ts b/packages/test-utils/src/stdout-filter.ts index bb1e8ea36c..98e656c6dd 100644 --- a/packages/test-utils/src/stdout-filter.ts +++ b/packages/test-utils/src/stdout-filter.ts @@ -167,7 +167,7 @@ function isJsonTelemetryObject(value: Record): boolean { if ( typeof value['timestamp'] !== 'number' || typeof value['body'] !== 'string' || - !value['body'].startsWith(TOOL_CALL_BODY_PREFIX) || + !value['body'].trimStart().startsWith(TOOL_CALL_BODY_PREFIX) || !isRecord(attributes) ) { return false; diff --git a/packages/test-utils/src/test-rig.ts b/packages/test-utils/src/test-rig.ts index e8ad7bfde9..93199d0784 100644 --- a/packages/test-utils/src/test-rig.ts +++ b/packages/test-utils/src/test-rig.ts @@ -221,7 +221,6 @@ export class TestRig { }; const transform = (stdout: string): string => { - this._lastRunStdout = stdout; if (env['LLXPRT_SANDBOX'] === 'podman') { return stripTelemetryFromStdout(stdout); } @@ -263,10 +262,7 @@ export class TestRig { ctx, { stdin: options.stdin }, false, - (stdout) => { - this._lastRunStdout = stdout; - return stdout; - }, + (stdout) => stdout, (capture) => { this._lastRunCapture = capture; this._lastRunStdout = capture.stdout;