diff --git a/core/test/code_executors/unsafe_local_code_executor_test.ts b/core/test/code_executors/unsafe_local_code_executor_test.ts index 93d960007..82a0d2d01 100644 --- a/core/test/code_executors/unsafe_local_code_executor_test.ts +++ b/core/test/code_executors/unsafe_local_code_executor_test.ts @@ -45,19 +45,6 @@ const EXPECTED_POWERSHELL_ARGS = [ expect.stringMatching(/script\.ps1$/), ]; -/** - * `it()` budget (ms) for the cases that spawn a real interpreter rather than - * the mocked `spawn` used by the `spawn arguments` suite below. The `unit:core` - * project sets no `testTimeout`, so these inherit Vitest's 5000 ms default, - * which is not a process-start budget: on Windows the default shell is Windows - * PowerShell, whose cold start under V8 coverage instrumentation on a loaded CI - * runner does not reliably fit. The value is above `UnsafeLocalCodeExecutor`'s - * own 30 s default execution timeout on purpose, so a genuinely stuck - * interpreter fails with the executor's timeout message instead of an opaque - * Vitest timeout. - */ -const REAL_INTERPRETER_TIMEOUT_MS = 40000; - function createMockInvocationContext(): InvocationContext { const agent = new LlmAgent({ name: 'test_agent', @@ -171,25 +158,21 @@ describe('UnsafeLocalCodeExecutor', () => { expect(result.stderr).toBe(''); }); - it( - 'should execute shell code and return stdout', - async () => { - const params: ExecuteCodeParams = { - invocationContext, - codeExecutionInput: { - code: 'echo "Hello, Shell!"', - language: CodeExecutionLanguage.SHELL, - inputFiles: [], - }, - }; + it('should execute shell code and return stdout', async () => { + const params: ExecuteCodeParams = { + invocationContext, + codeExecutionInput: { + code: 'echo "Hello, Shell!"', + language: CodeExecutionLanguage.SHELL, + inputFiles: [], + }, + }; - const result = await executor.executeCode(params); + const result = await executor.executeCode(params); - expect(result.stdout).toContain('Hello, Shell!'); - expect(result.stderr).toBe(''); - }, - REAL_INTERPRETER_TIMEOUT_MS, - ); + expect(result.stdout).toContain('Hello, Shell!'); + expect(result.stderr).toBe(''); + }); it('should return error for unsupported language', async () => { const params: ExecuteCodeParams = { diff --git a/tests/integration/test_case_utils.ts b/tests/integration/test_case_utils.ts index 580ed05df..a489a6df7 100644 --- a/tests/integration/test_case_utils.ts +++ b/tests/integration/test_case_utils.ts @@ -265,6 +265,9 @@ const OUTPUT_EXCERPT_CHARS = 4000; /** How long `stop()` waits for a clean exit before escalating to SIGKILL. */ const PROCESS_EXIT_TIMEOUT_MS = 5000; +/** How long a premature `'exit'` waits for the stdio pipes to reach EOF. */ +const STDIO_FLUSH_GRACE_MS = 250; + /** * Returns a TCP port on `host` that the OS has just confirmed is free, by * binding port 0, reading the assignment back and releasing it. @@ -295,16 +298,26 @@ export async function reserveFreePort(host: string): Promise { } /** - * Keeps only the last {@link OUTPUT_EXCERPT_CHARS} characters of a captured - * stream: a child that dies noisily writes far more than is useful, and the - * bytes it wrote last are the ones explaining why. + * Appends `chunk` to `buffer`, retaining only the last + * {@link OUTPUT_EXCERPT_CHARS} characters. + * + * Capping on the way in rather than on the way out bounds what a child can make + * the harness hold: a server stuck in a log loop writes for the whole readiness + * window, and only its last words explain why it never started. */ -function excerpt(output: string): string { - return output.slice(-OUTPUT_EXCERPT_CHARS) || '(no output captured)'; +export function appendCapped( + buffer: string, + chunk: string, + maxChars = OUTPUT_EXCERPT_CHARS, +): string { + return (buffer + chunk).slice(-maxChars); } +/** Stands in for a stream the child never wrote to. */ +const NO_OUTPUT = '(no output captured)'; + function formatCapturedOutput(stdout: string, stderr: string): string { - return `\nstdout:\n${excerpt(stdout)}\nstderr:\n${excerpt(stderr)}`; + return `\nstdout:\n${stdout || NO_OUTPUT}\nstderr:\n${stderr || NO_OUTPUT}`; } /** @@ -364,11 +377,14 @@ export abstract class BaseTestServer { // of the child so its pipes keep draining; a chatty server that filled // the 64 KB pipe buffer would otherwise block. let capturing = true; + let flushGrace: ReturnType | undefined; const settle = (error?: Error) => { clearTimeout(timer); + clearTimeout(flushGrace); capturing = false; child.off('error', onError); + child.off('exit', onExit); child.off('close', onClose); if (error) { reject(error); @@ -379,7 +395,7 @@ export abstract class BaseTestServer { const onStdout = (data: Buffer) => { if (!capturing) return; - stdout += data.toString(); + stdout = appendCapped(stdout, data.toString()); // Matched against the accumulated output, not this chunk: a banner // split across two writes must still complete the handshake. @@ -389,8 +405,13 @@ export abstract class BaseTestServer { }; const onStderr = (data: Buffer) => { + const message = data.toString(); + // Echoed unconditionally: retention stops once the handshake settles, + // but a server that starts cleanly and fails later still has to reach + // the CI log. + console.error(`${serverName} Stderr: ${message}`); if (!capturing) return; - stderr += data.toString(); + stderr = appendCapped(stderr, message); }; const onError = (error: Error) => { @@ -418,6 +439,21 @@ export abstract class BaseTestServer { ); }; + // A child that leaves a grandchild holding the inherited stdio pipes -- + // `go run` does exactly that -- emits 'exit' but never 'close', so the + // wait for a drained pipe is bounded and then reported anyway. Reporting + // the exit code beats stalling until the readiness timeout claims the + // server merely started slowly. + const onExit = ( + code: number | null, + signal: ChildProcessWithoutNullStreams['signalCode'], + ) => { + flushGrace = setTimeout( + () => onClose(code, signal), + STDIO_FLUSH_GRACE_MS, + ); + }; + const timer = setTimeout(() => { settle( new Error( @@ -430,6 +466,7 @@ export abstract class BaseTestServer { child.stdout.on('data', onStdout); child.stderr.on('data', onStderr); child.on('error', onError); + child.on('exit', onExit); child.on('close', onClose); }); diff --git a/tests/integration/test_case_utils_test.ts b/tests/integration/test_case_utils_test.ts index c908cd67f..d996cbf37 100644 --- a/tests/integration/test_case_utils_test.ts +++ b/tests/integration/test_case_utils_test.ts @@ -10,8 +10,12 @@ import {mkdtempSync, readFileSync} from 'node:fs'; import {createServer, type Server} from 'node:net'; import {platform, tmpdir} from 'node:os'; import * as path from 'node:path'; -import {afterEach, describe, expect, it} from 'vitest'; -import {BaseTestServer, reserveFreePort} from './test_case_utils.js'; +import {afterEach, describe, expect, it, vi} from 'vitest'; +import { + appendCapped, + BaseTestServer, + reserveFreePort, +} from './test_case_utils.js'; const HOST = 'localhost'; const START_MESSAGE = 'SCRIPTED SERVER STARTED'; @@ -21,6 +25,15 @@ const START_TIMEOUT_MS = 15000; const STAY_ALIVE = 'setInterval(() => {}, 1000);'; /** Mirrors `PROCESS_EXIT_TIMEOUT_MS` in the harness under test. */ const PROCESS_EXIT_TIMEOUT_MS = 5000; +/** Mirrors `OUTPUT_EXCERPT_CHARS` in the harness under test. */ +const OUTPUT_EXCERPT_CHARS = 4000; +/** + * Readiness budget for the grandchild case: long enough that reaching it means + * the exit was never reported, short enough to fail fast when that regresses. + */ +const GRANDCHILD_START_TIMEOUT_MS = 10000; +/** Children write on their own schedule, so observations are polled. */ +const WAIT_FOR_OPTIONS = {timeout: 5000, interval: 10}; const IS_WINDOWS = platform() === 'win32'; const spawned: ChildProcessWithoutNullStreams[] = []; @@ -75,16 +88,14 @@ function hasExited(child: ChildProcessWithoutNullStreams): boolean { * Waits for the harness to reach its spawn closure. `startProcess` awaits the * port reservation first, so the child handle is not available synchronously. */ -async function waitForChild( +function waitForChild( server: ScriptedTestServer, ): Promise { - for (let i = 0; i < 500 && !server.child; i++) { - await new Promise((resolve) => setTimeout(resolve, 10)); - } - if (!server.child) { - expect.fail('the server never reached its spawn closure'); - } - return server.child; + return vi.waitFor(() => { + const child = server.child; + if (!child) expect.fail('the server never reached its spawn closure'); + return child; + }, WAIT_FOR_OPTIONS); } /** True for the Node error raised when a pid no longer exists. */ @@ -154,6 +165,40 @@ describe('reserveFreePort', () => { }); }); +describe('appendCapped', () => { + it('appends without truncating below the cap', () => { + expect(appendCapped('abc', 'de', 8)).toBe('abcde'); + }); + + it('appends without truncating exactly at the cap', () => { + expect(appendCapped('abc', 'de', 5)).toBe('abcde'); + }); + + it('drops the head and keeps the tail once over the cap', () => { + expect(appendCapped('abc', 'de', 4)).toBe('bcde'); + }); + + it('keeps only the tail of a chunk that alone exceeds the cap', () => { + expect(appendCapped('abc', 'defgh', 3)).toBe('fgh'); + }); + + it('stays capped across repeated appends', () => { + let buffer = ''; + for (let i = 0; i < 100; i++) { + buffer = appendCapped(buffer, '0123456789', 15); + } + + expect(buffer).toHaveLength(15); + expect(buffer.endsWith('0123456789')).toBe(true); + }); + + it('defaults to the harness excerpt size', () => { + const overCap = 'x'.repeat(OUTPUT_EXCERPT_CHARS + 1000); + + expect(appendCapped('', overCap)).toHaveLength(OUTPUT_EXCERPT_CHARS); + }); +}); + describe('BaseTestServer.startProcess', () => { it('reserves the port before the child is spawned', async () => { const server = new ScriptedTestServer( @@ -212,6 +257,38 @@ describe('BaseTestServer.startProcess', () => { await expect(attempt).rejects.toThrow('STDOUT-REASON'); }); + it('reports the exit code when a grandchild holds the pipes open', async () => { + // `go run` behaves this way: the built binary inherits the stdio pipes, so + // the wrapper can die without them ever reaching EOF and 'close' never + // arrives. Waiting for it would report a start-up *timeout* minutes later + // instead of the exit code the child already handed us. + const pidFile = path.join( + mkdtempSync(path.join(tmpdir(), 'adk-harness-')), + 'grandchild.pid', + ); + grandchildPidFiles.push(pidFile); + const server = new ScriptedTestServer( + nodeScript( + "const gc = require('node:child_process').spawn(process.execPath, " + + "['-e', 'setTimeout(() => {}, 60000)'], {stdio: 'inherit'});" + + `require('node:fs').writeFileSync(${JSON.stringify(pidFile)}, ` + + 'String(gc.pid));' + + "process.stderr.write('HELD-STDERR\\n', () => " + + "process.stdout.write('HELD-STDOUT\\n', () => process.exit(3)));", + ), + ); + + // Far longer than the flush grace, so a rejection this side of it can only + // have come from the exit path rather than from the readiness timeout. + const attempt = server.start(GRANDCHILD_START_TIMEOUT_MS); + + await expect(attempt).rejects.toThrow( + 'Scripted exited prematurely with code 3', + ); + await expect(attempt).rejects.toThrow('HELD-STDOUT'); + await expect(attempt).rejects.toThrow('HELD-STDERR'); + }); + it('reports both streams as empty when the child exits silently', async () => { const server = new ScriptedTestServer(nodeScript('process.exit(1);')); @@ -305,6 +382,34 @@ describe('BaseTestServer.startProcess', () => { await new Promise((resolve) => child!.once('close', () => resolve())); expect(child!.exitCode).toBe(0); }); + + it('echoes stderr written after the handshake has settled', async () => { + // Retention stops at settle, but the echo is what surfaces a server that + // starts cleanly and then fails mid-test, so it has to outlive the + // handshake. + const server = new ScriptedTestServer( + nodeScript( + `process.stdout.write('${START_MESSAGE}\\n');` + + "setTimeout(() => process.stderr.write('MID-TEST-FAILURE\\n'), 50);" + + STAY_ALIVE, + ), + ); + const echoed = vi.spyOn(console, 'error'); + + try { + await server.start(); + + await vi.waitFor( + () => + expect(echoed).toHaveBeenCalledWith( + expect.stringContaining('Scripted Stderr: MID-TEST-FAILURE'), + ), + WAIT_FOR_OPTIONS, + ); + } finally { + echoed.mockRestore(); + } + }); }); describe('BaseTestServer.stop', () => {