diff --git a/evals/README.md b/evals/README.md index 2aacf1b5c..796c91d18 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 2418bbf25..03fdc0102 100644 --- a/evals/test-helper.ts +++ b/evals/test-helper.ts @@ -6,28 +6,102 @@ 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) { + 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: ${details}`, + ); + } + 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: ReturnType | EvalArtifactError; +} + +interface EvalArtifactError { + readonly error: string; +} + +export function formatEvalLog( + capture: RunCapture | null, + toolCalls: ReturnType | EvalArtifactError, +): 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 +123,46 @@ export interface EvalCase { assert: (rig: TestRig, result: string) => Promise; } +async function finalizeEval(rig: TestRig, name: string): Promise { + const capture = rig.getLastRunCapture(); + let toolCalls: ReturnType | EvalArtifactError; + 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', + { cause: artifactError }, + ); + } + 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 d18102781..5f5cbbe48 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 000000000..318cfdecc --- /dev/null +++ b/packages/test-utils/src/process-run.test.ts @@ -0,0 +1,306 @@ +/** + * @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[] = []; +const SPAWN_TIMEOUT_MS = 1500; + +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 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, + SPAWN_TIMEOUT_MS, + (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( + 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, + SPAWN_TIMEOUT_MS, + (value) => { + capture = value; + }, + ); + + await expectRejection(run, /timed out/); + expect(capture).toEqual({ + stdout: 'started shutdown-out', + stderr: 'shutdown-err', + exitCode: null, + timedOut: true, + }); + }); + + 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( + { + 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('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, + SPAWN_TIMEOUT_MS * 4, + () => { + 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; + + 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 f497f76bb..7dad7aeb8 100644 --- a/packages/test-utils/src/process-run.ts +++ b/packages/test-utils/src/process-run.ts @@ -4,10 +4,116 @@ * 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; + +interface CaptureFailure { + readonly error: unknown; +} + +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 { + // 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 { + // The child may have exited between the timeout and the signal. + } + } + + // 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' && + child.pid !== undefined + ) { + const killer = spawn('taskkill', ['/pid', String(child.pid), '/t', '/f'], { + stdio: 'ignore', + windowsHide: true, + }); + killer.once('error', () => { + try { + child.kill(signal); + } catch { + // The main child may already have exited while taskkill was starting. + } + }); + killer.unref(); + return; + } + + try { + child.kill(signal); + } catch { + // The child may have exited between the timeout and the fallback 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, +): 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 { + 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; +} + /** * Stream handler that accumulates stdout/stderr and mirrors them to the * terminal when verbose output is enabled. @@ -56,13 +162,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 +180,43 @@ 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; + reject( + captureErrorOr(captureRun(accumulator, null, false, onCapture), error), + ); + }); + + child.once('close', (code: number | null) => { + if (settled) { + return; + } + settled = true; + const captureFailure = captureRun(accumulator, code, false, onCapture); + if (captureFailure !== null) { + const processError = + code === 0 + ? null + : new Error( + `Process exited with code ${code}:\n${accumulator.stderr}`, + ); + reject( + processError === null + ? captureFailure.error + : captureErrorOr(captureFailure, processError), + ); + return; + } + if (code === 0) { const transformed = transform(accumulator.stdout); resolve( @@ -90,18 +228,76 @@ export function spawnRun( ); } }); + + pipeStdin(child, options); }); } -/** - * Spawn a child process with a timeout for `TestRig.run`. - */ +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, + ); + let processError: Error | null = null; + if (didTimeout) { + processError = context.timeoutError; + } else if (code !== 0) { + processError = new Error( + `Process exited with code ${code}:\n${context.accumulator.stderr}`, + ); + } + if (captureFailure !== null) { + context.reject( + 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 { + for (const timer of timers) { + clearTimeout(timer); + } +} + +/** 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,38 +305,74 @@ 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); - if (code === 0) { - const transformed = transform(accumulator.stdout); - resolve( - maybeAppendStderr(transformed, accumulator.stderr, isJsonOutput), + 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; + reject( + captureErrorOr( + captureRun(accumulator, null, true, onCapture), + timeoutError, + ), ); - } else { + } + }; + 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), + ); + child.once('error', (error) => { + if (!settled) { + settled = true; + if (!didTimeout) { + clearRunTimers(timers); + } + const runError = didTimeout ? timeoutError : error; reject( - new Error(`Process exited with code ${code}:\n${accumulator.stderr}`), + captureErrorOr( + captureRun(accumulator, null, didTimeout, onCapture), + runError, + ), ); } }); - }); - const timeoutPromise = new Promise((_resolve, reject) => { - timeoutHandle = setTimeout(() => { - child.kill('SIGTERM'); - reject(new Error(`TestRig.run() timed out after ${timeoutMs}ms`)); - }, timeoutMs); - }); + const closeContext: CloseRunContext = { + accumulator, + onCapture, + timeoutError, + transform, + isJsonOutput, + resolve, + reject, + }; + child.once('close', (code: number | null) => { + if (!settled) { + settled = true; + clearRunTimers(timers); + settleClosedRun(closeContext, code, didTimeout); + } + }); - return Promise.race([processPromise, timeoutPromise]); + pipeStdin(child, options); + }); } 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 000000000..238f6b21a --- /dev/null +++ b/packages/test-utils/src/stdout-filter.test.ts @@ -0,0 +1,195 @@ +/** + * @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 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 = [ + '{', + " 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 c9ed8d14c..98e656c6d 100644 --- a/packages/test-utils/src/stdout-filter.ts +++ b/packages/test-utils/src/stdout-filter.ts @@ -4,57 +4,243 @@ * 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 METRIC_NAME_FIELD = 'name:'; +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 }; + const output: string[] = []; + let cursor = 0; - for (const line of lines) { - const kept = processLine(line, state); - if (kept !== null) { - filteredLines.push(kept); + 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; + } + } } - if (!state.inTelemetryObject) { - return line; + + return null; +} + +function updateBraceDepth(char: string, depth: number): number { + if (char === '{') { + return depth + 1; + } + 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); +} + +/** Recognize OpenTelemetry JSON LogRecord objects emitted to stdout. */ +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'].trimStart().startsWith(TOOL_CALL_BODY_PREFIX) || + !isRecord(attributes) + ) { + return false; + } + + return ( + typeof attributes[FUNCTION_NAME_ATTRIBUTE] === 'string' || + typeof attributes[FUNCTION_ARGS_ATTRIBUTE] === 'string' + ); +} + +/** 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( + objectText, + INSTRUMENTATION_SCOPE_FIELD, + ); + if (hasServiceIdentity && hasInstrumentationScope) { + return true; + } + + return ( + hasInspectedField(objectText, METRIC_DESCRIPTOR_FIELD) && + hasLlxprtMetricName(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 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, + 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 430b6ad70..d868a433f 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 e06be7a3a..93199d078 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,83 @@ 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 => { + 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) => 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 d5eceb399..20704cc39 100644 --- a/scripts/tests/evals-save-memory-assertion.test.js +++ b/scripts/tests/evals-save-memory-assertion.test.js @@ -9,6 +9,107 @@ 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('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', + 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); + 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', () => { + 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