diff --git a/scripts/test-paid-shards.ts b/scripts/test-paid-shards.ts index e6d36c165..26ca8263b 100644 --- a/scripts/test-paid-shards.ts +++ b/scripts/test-paid-shards.ts @@ -50,17 +50,16 @@ * bun run scripts/test-paid-shards.ts --timeout 600 --jobs 2 */ -import { spawn } from 'node:child_process'; import * as fs from 'node:fs'; +import * as os from 'node:os'; import * as path from 'node:path'; import { normalizeRelativePath } from './test-free-shards'; import { BunTestOutputClassifier, exactTestFileSelectors, forwardAndClassify, - installChildSignalForwarding, isTerminationRequested, - killProcessGroup, + runShardChild, strictTestExitCode, } from './test-strict-output'; import { PAID_TEST_GLOBS, isPaidTestFile } from '../test/helpers/paid-test-set'; @@ -218,6 +217,26 @@ export function computePaidDiffSelection( return { selectedNames: new Set(selection.selected), reason: selection.reason, totalTests }; } +/** + * Serialize the parent's diff selection for shard children (EVALS_SELECTION_JSON). + * + * Children's e2e-helpers module-load path adopts this instead of re-deriving + * the selection per shard — which, when touchfiles-data.ts is in the diff, + * spawned one bun subprocess PER CHILD to evaluate the old data file (the + * map-diff path in test/helpers/test-selection.ts, 20s timeout each; 46-68 + * redundant children per full run). `selected: null` means run-all, mirroring + * PaidDiffSelection.selectedNames. The child-side parser lives in + * test/helpers/e2e-helpers.ts (parseEvalsSelectionJson); round-trip parity is + * pinned by test/paid-selection-propagation.test.ts. + */ +export function serializePaidDiffSelection(selection: PaidDiffSelection): string { + return JSON.stringify({ + version: 1, + selected: selection.selectedNames === null ? null : [...selection.selectedNames].sort(), + reason: selection.reason, + }); +} + export interface ShardSkipDecision { file: string; kept: boolean; @@ -363,11 +382,43 @@ export interface RunShardsOptions { env?: NodeJS.ProcessEnv; /** When set, each shard child gets GSTACK_EVAL_DIR=/shards//. */ evalDirBase?: string; + /** Directory for the per-shard full-stream log files (default os.tmpdir()). Tests inject. */ + logDir?: string; /** Override the spawned command. Tests inject fake slow/spinning commands. */ commandFor?: (files: string[]) => ShardCommand; log?: (line: string) => void; } +let shardLogSequence = 0; + +/** Per-shard log path: slug + timestamp; pid + sequence defeat same-ms collisions. */ +function nextShardLogPath(files: string[], logDir: string): string { + const stamp = new Date().toISOString().replace(/[:.]/g, '-'); + shardLogSequence += 1; + return path.join(logDir, `gstack-paid-shard-${shardSlug(files)}-${stamp}-${process.pid}-${shardLogSequence}.log`); +} + +/** On-failure console excerpt budget: the last N bytes of the shard's log. */ +export const FAILURE_TAIL_BYTES = 64 * 1024; + +/** Read back only the tail of a shard log (never the whole 30-min stream). */ +function readLogTail(logPath: string, maxBytes = FAILURE_TAIL_BYTES): string { + try { + const size = fs.statSync(logPath).size; + const start = Math.max(0, size - maxBytes); + const fd = fs.openSync(logPath, 'r'); + try { + const buffer = Buffer.alloc(size - start); + fs.readSync(fd, buffer, 0, buffer.length, start); + return buffer.toString('utf8'); + } finally { + fs.closeSync(fd); + } + } catch { + return ''; // a lost tail must never turn a real verdict into an exception + } +} + export async function runPaidShard( files: string[], shardNumber: number, @@ -400,67 +451,85 @@ export async function runPaidShard( const startedAt = Date.now(); log(`${label} START ${files.join(' ')} (timeout ${Math.round(timeoutMs / 1000)}s)`); - const child = spawn(command, args, { - cwd: rootDir, - env, - stdio: ['ignore', 'pipe', 'pipe'], - detached: process.platform !== 'win32', - windowsHide: true, - }); - const groupPid = child.pid ?? null; - // Group-kill on parent SIGINT/SIGTERM too, not just on timeout. - const forwarding = installChildSignalForwarding({ - kill: (signal?: NodeJS.Signals | number) => { - killProcessGroup(child, (signal as NodeJS.Signals) ?? 'SIGTERM'); - return true; - }, + // Full-stream spool: EVERY child byte lands on disk (the free runner's + // model), never in a whole-run Buffer[] — non-live shards used to hold + // their entire 30-min stream-json stdout+stderr in RAM, × concurrent jobs. + // Printed at START so a wedged shard is inspectable live, mid-run. + const logPath = nextShardLogPath(files, options.logDir ?? os.tmpdir()); + const logStream = fs.createWriteStream(logPath); + let logWriteFailed = false; + logStream.on('error', (err) => { + if (logWriteFailed) return; + logWriteFailed = true; + console.error(`${label} could not write the full log at ${logPath}: ${err.message}`); }); + log(`${label} full log: ${logPath}`); const classifier = new BunTestOutputClassifier(); - const buffered: Buffer[] = []; - const sink = (destination: NodeJS.WriteStream): NodeJS.WriteStream => (streamLive - ? destination - : ({ write: (chunk: Buffer | string) => buffered.push(Buffer.from(chunk)) } as unknown as NodeJS.WriteStream)); - - let timedOut = false; - const killTimer = setTimeout(() => { - timedOut = true; - killProcessGroup(child, 'SIGKILL'); - }, timeoutMs); + // Tee: the spool always gets the chunk; live mode (jobs=1) also forwards to + // the console. forwardAndClassify feeds the classifier FIRST, so the strict + // verdict path is unchanged by where the bytes land afterwards. + const sink = (destination: NodeJS.WriteStream): NodeJS.WriteStream => ({ + write: (chunk: Buffer | string): boolean => { + if (!logWriteFailed) logStream.write(chunk); + if (streamLive) destination.write(chunk); + return true; + }, + } as unknown as NodeJS.WriteStream); let exitCode: number | null = null; + let timedOut = false; + let groupPid: number | null = null; try { - const streams: Array> = []; - if (child.stdout) streams.push(forwardAndClassify(child.stdout, sink(process.stdout), classifier, 'stdout')); - if (child.stderr) streams.push(forwardAndClassify(child.stderr, sink(process.stderr), classifier, 'stderr')); - exitCode = await new Promise((resolve, reject) => { - child.once('error', reject); - child.once('close', (code) => resolve(code)); + // Shared spawn/detached/group-kill/wall-timer/reap lifecycle. + const result = await runShardChild({ + command, + args, + cwd: rootDir, + env, + timeoutMs, + hookStreams: (child) => { + const streams: Array> = []; + if (child.stdout) streams.push(forwardAndClassify(child.stdout, sink(process.stdout), classifier, 'stdout')); + if (child.stderr) streams.push(forwardAndClassify(child.stderr, sink(process.stderr), classifier, 'stderr')); + return streams; + }, }); - await Promise.all(streams); + exitCode = result.exitCode; + timedOut = result.timedOut; + groupPid = result.groupPid; } finally { - clearTimeout(killTimer); - forwarding.dispose(); - // Reap survivors of this shard even on the clean path. - killProcessGroup(child, 'SIGKILL'); + // Close the spool even when the spawn itself failed. + await new Promise((resolve) => logStream.end(() => resolve())); } const summary = classifier.end(); - if (!streamLive && buffered.length > 0) process.stdout.write(Buffer.concat(buffered)); // Pass expectedFiles so a shard whose bun child ran fewer files than planned // (or zero, all self-skipped) with exit 0 is NOT recorded 'passed' — the // invisible-non-execution class this runner exists to kill. bun prints // "Ran N tests across M files" with M = selected files even when every test - // self-skips, so terminalFileCounts must include files.length. Only enforced - // on the real bun path: an injected commandFor (tests) isn't bun and emits no - // terminal summary, so there's no file count to check against. - const expectedFiles = options.commandFor ? undefined : files.length; + // self-skips, so terminalFileCounts must include files.length. Enforced for + // injected commandFor (tests) too, matching the free runner — fake passing + // commands must print a synthetic `Ran N tests across M files. [Xms]` line, + // so tests can pin the summary-missing => failure backstop. + const expectedFiles = files.length; const status: ShardStatus = timedOut ? 'timed-out' : strictTestExitCode(exitCode ?? 1, summary, expectedFiles) === 0 ? 'passed' : 'failed'; const elapsedMs = Date.now() - startedAt; - log(`${label} ${status.toUpperCase()} in ${Math.round(elapsedMs / 1000)}s (exit ${exitCode ?? 'signal'})`); + + // Failure debuggability without the RAM cost: read back only the log's + // tail. Live mode already streamed everything, so no re-print there. + if (status !== 'passed' && !streamLive) { + const tail = readLogTail(logPath); + if (tail.length > 0) { + process.stdout.write(`${label} last ${Math.min(tail.length, FAILURE_TAIL_BYTES)} bytes of ${logPath}:\n`); + process.stdout.write(tail.endsWith('\n') ? tail : `${tail}\n`); + } + } + const logSuffix = status === 'passed' ? '' : ` — full log: ${logPath}`; + log(`${label} ${status.toUpperCase()} in ${Math.round(elapsedMs / 1000)}s (exit ${exitCode ?? 'signal'})${logSuffix}`); return { shard: shardNumber, files, status, exitCode, elapsedMs, groupPid }; } @@ -676,7 +745,17 @@ async function main(): Promise { timeoutMs: options.timeoutMs, jobs: options.jobs, withinShardConcurrency: options.withinShardConcurrency, - env: { ...process.env, EVALS: '1', EVALS_TIER: options.tier, EVALS_PREFLIGHT_OK: '1' }, + env: { + ...process.env, + EVALS: '1', + EVALS_TIER: options.tier, + EVALS_PREFLIGHT_OK: '1', + // The parent's selection, computed once above — children's e2e-helpers + // module load adopts it instead of re-deriving per shard (which spawned + // a bun subprocess per child on the touchfiles-data map-diff path). + // Children fall back to local derivation on any parse failure. + EVALS_SELECTION_JSON: serializePaidDiffSelection(diffSelection), + }, evalDirBase: process.env.GSTACK_EVAL_DIR || getProjectEvalDir(), }); const skippedOutcomes: ShardOutcome[] = skipped.map((s, index) => ({ diff --git a/scripts/test-strict-output.ts b/scripts/test-strict-output.ts index 4da71fd19..31e2dccd3 100644 --- a/scripts/test-strict-output.ts +++ b/scripts/test-strict-output.ts @@ -11,7 +11,7 @@ * future strict wrapper around `bun test`. */ -import { type ChildProcess } from 'node:child_process'; +import { spawn, type ChildProcess } from 'node:child_process'; import { StringDecoder } from 'node:string_decoder'; import * as path from 'node:path'; @@ -298,3 +298,88 @@ export function forwardAndClassify( stream.on('error', reject); }); } + +// --- Shared shard-child lifecycle --- + +export interface RunShardChildOptions { + command: string; + args: string[]; + cwd: string; + env: NodeJS.ProcessEnv; + /** External wall-clock deadline; on expiry the child's process GROUP is SIGKILLed. */ + timeoutMs: number; + /** + * Hook the freshly-spawned child's stdout/stderr. Stream POLICY (classifier + * tees, log spooling, console forwarding, reporters) is entirely the + * caller's. Runs synchronously right after spawn; the returned promises are + * awaited AFTER the child closes, so trailing output is fully drained + * before the caller reads its classifier/reporter state. + */ + hookStreams: (child: ChildProcess) => Array>; +} + +export interface ShardChildResult { + exitCode: number | null; + /** True when the wall timer fired and SIGKILLed the group. */ + timedOut: boolean; + /** The child's pid — the process-GROUP id on POSIX (detached spawn). */ + groupPid: number | null; +} + +/** + * The child lifecycle both sharded runners need, extracted from + * scripts/test-paid-shards.ts runPaidShard (scripts/test-free-shards.ts + * runFreeShard duplicates the same ~35 lines verbatim today and is designed + * to migrate here in a later change): + * + * - spawn detached on POSIX so the child owns its process group, + * - forward parent SIGINT/SIGTERM to the whole group (not just the child), + * - arm an EXTERNAL wall-clock timer that SIGKILLs the group — a spinning + * child main thread never fires its own in-process timer, + * - in EVERY exit path: disarm the timer, detach the signal forwarder, and + * reap group survivors with SIGKILL. + * + * Caller-side cleanup that must run even on a spawn failure (log streams, + * reporters, temp dirs) belongs in the caller's own try/finally around this + * call: a spawn 'error' event THROWS from here after the finally block runs, + * preserving the runners' existing could-not-run handling. + */ +export async function runShardChild(options: RunShardChildOptions): Promise { + const child = spawn(options.command, options.args, { + cwd: options.cwd, + env: options.env, + stdio: ['ignore', 'pipe', 'pipe'], + detached: process.platform !== 'win32', + windowsHide: true, + }); + const groupPid = child.pid ?? null; + // Group-kill on parent SIGINT/SIGTERM too, not just on timeout. + const forwarding = installChildSignalForwarding({ + kill: (signal?: NodeJS.Signals | number) => { + killProcessGroup(child, (signal as NodeJS.Signals) ?? 'SIGTERM'); + return true; + }, + }); + + let timedOut = false; + const killTimer = setTimeout(() => { + timedOut = true; + killProcessGroup(child, 'SIGKILL'); + }, options.timeoutMs); + + let exitCode: number | null = null; + try { + const streams = options.hookStreams(child); + exitCode = await new Promise((resolve, reject) => { + child.once('error', reject); + child.once('close', (code) => resolve(code)); + }); + await Promise.all(streams); + } finally { + clearTimeout(killTimer); + forwarding.dispose(); + // Reap survivors of this shard even on the clean path. + killProcessGroup(child, 'SIGKILL'); + } + return { exitCode, timedOut, groupPid }; +} diff --git a/test/paid-shards.test.ts b/test/paid-shards.test.ts index 771d5b0b8..7b6335e58 100644 --- a/test/paid-shards.test.ts +++ b/test/paid-shards.test.ts @@ -11,6 +11,7 @@ import { describe, test, expect } from 'bun:test'; import * as fs from 'fs'; +import * as os from 'os'; import * as path from 'path'; const ROOT = path.resolve(import.meta.dir, '..'); @@ -115,10 +116,17 @@ describe('tier classification', () => { describe('shard execution', () => { const BUSY_LOOP = 'const end = Date.now() + 600000; while (Date.now() < end) {}'; + // PIN UPDATE (deliberate): the strict expectedFiles check is now enforced + // for injected fake commands too (drift fix toward the free runner's + // behavior), so a fake PASSING command must print a synthetic bun terminal + // summary — a summary-less exit 0 is the truncation class and reads FAILED. + const PASS_WITH_SUMMARY = 'console.log("ok"); console.log("Ran 1 tests across 1 files. [1ms]")'; + const commandFor = (files: string[]) => { if (files[0] === 'spin') return { command: process.execPath, args: ['-e', BUSY_LOOP] }; if (files[0] === 'fail') return { command: process.execPath, args: ['-e', 'process.exit(3)'] }; - return { command: process.execPath, args: ['-e', 'console.log("ok")'] }; + if (files[0] === 'silent-pass') return { command: process.execPath, args: ['-e', 'console.log("ok")'] }; + return { command: process.execPath, args: ['-e', PASS_WITH_SUMMARY] }; }; test('a spinning shard times out, is killed, and the run continues', async () => { @@ -153,6 +161,48 @@ describe('shard execution', () => { expect(lines.some((l) => /PASSED in \d+s/.test(l))).toBe(true); }, 30_000); + test('exit 0 WITHOUT the terminal summary is FAILED — enforced for injected commands too', async () => { + // The invisible-non-execution backstop: previously the paid runner + // exempted injected commandFor from the expectedFiles check, so a fake + // that exited 0 without bun's terminal summary recorded 'passed'. Now it + // matches the free runner: enforcement always on. + const summary = await runPaidShards([['silent-pass']], { + timeoutMs: 30_000, jobs: 1, commandFor, log: () => {}, + }); + expect(summary.outcomes[0].status).toBe('failed'); + }, 30_000); + + test('shard output spools to a per-shard log file; failures name the path', async () => { + const logDir = fs.mkdtempSync(path.join(os.tmpdir(), 'paid-shard-logs-')); + const lines: string[] = []; + try { + const summary = await runPaidShards([['fail'], ['pass']], { + timeoutMs: 30_000, jobs: 2, commandFor, logDir, log: (line) => lines.push(line), + }); + const byName = (name: string) => summary.outcomes.find((o) => o.files[0] === name) as ShardOutcome; + expect(byName('fail').status).toBe('failed'); + expect(byName('pass').status).toBe('passed'); + + // One log per shard, named by slug, and it holds the child's full stream + // (nothing buffered in RAM: the file IS the record). + const logs = fs.readdirSync(logDir).sort(); + expect(logs.length).toBe(2); + expect(logs.some((f) => f.includes('fail'))).toBe(true); + const passLog = logs.find((f) => f.includes('pass')) as string; + expect(fs.readFileSync(path.join(logDir, passLog), 'utf8')).toContain('Ran 1 tests across 1 files.'); + + // Every shard announces its log path up front; the FAILED terminal line + // repeats it, the PASSED one stays clean. + expect(lines.filter((l) => l.includes('full log:') && !l.includes('FAILED')).length).toBe(2); + const failLine = lines.find((l) => l.includes('FAILED')) as string; + expect(failLine).toContain(logDir); + const passLine = lines.find((l) => l.includes('PASSED')) as string; + expect(passLine).not.toContain(logDir); + } finally { + fs.rmSync(logDir, { recursive: true, force: true }); + } + }, 30_000); + test('summarize reports shards that never ran', () => { const summary = summarize([ { shard: 1, files: ['a'], status: 'passed', exitCode: 0, elapsedMs: 1, groupPid: 1 }, diff --git a/test/run-shard-child.test.ts b/test/run-shard-child.test.ts new file mode 100644 index 000000000..d8e39790c --- /dev/null +++ b/test/run-shard-child.test.ts @@ -0,0 +1,91 @@ +/** + * Direct pins for runShardChild (scripts/test-strict-output.ts) — the shared + * spawn/detached/group-kill/wall-timer/reap lifecycle extracted from the paid + * runner's runPaidShard, designed for scripts/test-free-shards.ts to migrate + * onto next. test/paid-shards.test.ts pins the paid runner end-to-end; these + * pin the helper's own contract so the free-runner migration has a floor. + */ + +import { describe, test, expect } from 'bun:test'; +import * as os from 'os'; +import * as path from 'path'; +import type { ChildProcess } from 'child_process'; +import { runShardChild } from '../scripts/test-strict-output'; + +/** Collect the child's full stdout+stderr, resolving only when drained. */ +function collectingHook(chunks: string[]) { + return (child: ChildProcess): Array> => { + const consume = (stream: NodeJS.ReadableStream | null): Promise => + stream + ? new Promise((resolve, reject) => { + stream.on('data', (chunk: Buffer | string) => chunks.push(chunk.toString())); + stream.on('end', resolve); + stream.on('error', reject); + }) + : Promise.resolve(); + return [consume(child.stdout), consume(child.stderr)]; + }; +} + +describe('runShardChild', () => { + test('clean exit: exitCode 0, not timed out, output drained before resolve', async () => { + const chunks: string[] = []; + const result = await runShardChild({ + command: process.execPath, + args: ['-e', 'console.log("hello-from-child")'], + cwd: process.cwd(), + env: process.env, + timeoutMs: 30_000, + hookStreams: collectingHook(chunks), + }); + expect(result.exitCode).toBe(0); + expect(result.timedOut).toBe(false); + expect(result.groupPid).toBeGreaterThan(0); + // The hookStreams promises are awaited AFTER close — trailing output is + // fully drained before callers read their classifier/log state. + expect(chunks.join('')).toContain('hello-from-child'); + }, 30_000); + + test('non-zero exit code propagates untouched', async () => { + const result = await runShardChild({ + command: process.execPath, + args: ['-e', 'process.exit(7)'], + cwd: process.cwd(), + env: process.env, + timeoutMs: 30_000, + hookStreams: () => [], + }); + expect(result.exitCode).toBe(7); + expect(result.timedOut).toBe(false); + }, 30_000); + + test('a spinning child is group-SIGKILLed at the wall deadline and reported timedOut', async () => { + const startedAt = Date.now(); + const result = await runShardChild({ + command: process.execPath, + // A real busy loop: an in-process timer could never fire in this child. + args: ['-e', 'const end = Date.now() + 600000; while (Date.now() < end) {}'], + cwd: process.cwd(), + env: process.env, + timeoutMs: 1_200, + hookStreams: () => [], + }); + expect(result.timedOut).toBe(true); + expect(Date.now() - startedAt).toBeLessThan(30_000); + if (process.platform !== 'win32') { + // The whole group is gone, not left to burn a core. + expect(() => process.kill(result.groupPid as number, 0)).toThrow(); + } + }, 30_000); + + test('a spawn failure THROWS so callers keep their could-not-run handling', async () => { + await expect(runShardChild({ + command: path.join(os.tmpdir(), 'definitely-not-a-real-binary-8b1f'), + args: [], + cwd: process.cwd(), + env: process.env, + timeoutMs: 5_000, + hookStreams: () => [], + })).rejects.toThrow(); + }, 30_000); +});