diff --git a/scripts/runner.node.mjs b/scripts/runner.node.mjs index 06db73b2ff09..56e46a2b093c 100755 --- a/scripts/runner.node.mjs +++ b/scripts/runner.node.mjs @@ -30,7 +30,6 @@ import { import { readFile } from "node:fs/promises"; import { availableParallelism, userInfo } from "node:os"; import { basename, dirname, extname, join, relative, sep } from "node:path"; -import { createInterface } from "node:readline"; import { setTimeout as setTimeoutPromise } from "node:timers/promises"; import { parseArgs } from "node:util"; import { prestartMap as dockerPrestartMap } from "../test/docker/prestart-map.mjs"; @@ -65,6 +64,7 @@ import { markBuildkiteStepReported, printEnvironment, reportAnnotationToBuildKite, + spawnBackgroundServer, startGroup, tmpdir, unzip, @@ -86,6 +86,12 @@ const spawnTimeout = 5_000; const spawnBunTimeout = 20_000; // when running with ASAN/LSAN bun can take a bit longer to exit, not a bug. const testTimeout = 3 * 60_000; const integrationTimeout = 5 * 60_000; +// How long the first test waits for the crash report remap server. It counts from +// the moment the server is needed, not from its start: the server is started +// before the root and test/ installs and is normally listening once they are done. +// A fresh CI agent takes 3.5s to well over 5s to start it (a 5s budget counted +// from its start lost the server on 3 of 4 shards), so keep this far above that. +const ciRemapServerTimeout = 30_000; const resolutionGatingFlags = new Set([ "--expose-internals", @@ -546,6 +552,11 @@ async function runTests() { const tests = getRelevantTests(testsPath, modifiers, expectations); !isQuiet && console.log("Running tests:", tests.length); + // The crash report remap server installs and starts in the background while + // the rest of the setup below runs. Its port is awaited right before the first + // test, the first thing that needs it. + const ciRemapServer = isCI && !isWindows ? startCiRemapServer(execPath) : undefined; + // Start the docker-service coordinator (test/docker/coordinator.ts). It // owns every `docker compose` invocation for this shard — `compose up` is // not concurrency-safe, so exactly one process runs it — and prestarts the @@ -793,44 +804,7 @@ async function runTests() { }; if (!failedResults.length) { - // TODO: remove windows exclusion here - if (isCI && !isWindows && (await installCiRemapServer(execPath))) { - const { promise: portPromise, resolve: portResolve } = Promise.withResolvers(); - const { promise: errorPromise, resolve: errorResolve } = Promise.withResolvers(); - let exiting = false; - - const server = spawn(execPath, ["run", "--silent", "ci-remap-server", execPath, cwd, getCommit()], { - stdio: ["ignore", "pipe", "inherit"], - cwd: ciRemapServerPath, - env: { ...process.env, BUN_DEBUG_QUIET_LOGS: "1", NO_COLOR: "1" }, - }); - server.unref(); - server.on("error", errorResolve); - server.on("exit", (code, signal) => { - if (!exiting && (code !== 0 || signal !== null)) errorResolve(signal ? signal : "code " + code); - }); - function onBeforeExit() { - exiting = true; - server.off("error"); - server.off("exit"); - server.kill?.(); - } - process.once("beforeExit", onBeforeExit); - const lines = createInterface(server.stdout); - lines.on("line", line => { - portResolve({ port: parseInt(line) }); - }); - - const result = await Promise.race([portPromise, errorPromise.catch(e => e), setTimeoutPromise(5000, "timeout")]); - if (typeof result?.port != "number") { - process.off("beforeExit", onBeforeExit); - server.kill?.(); - console.warn("ci-remap server did not start:", result); - } else { - console.log("crash reports parsed on port", result.port); - remapPort = result.port; - } - } + if (ciRemapServer) remapPort = await ciRemapServer.port(); const runOneTest = async (testPath, concurrent) => { await awaitNapiPrebuild(testPath); @@ -2248,20 +2222,66 @@ async function spawnBunInstall(execPath, options) { } /** - * Installs `ci-remap-server`, the bin of bun-tracestrings (github:oven-sh/bun.report). - * It is pinned in scripts/ci-remap-server/package.json rather than the root - * package.json because this runner is its only user, and as a github: dependency - * it would otherwise put GitHub on the critical path of the root `bun install` - * every GitHub Actions workflow and every build runs. Best-effort, like starting - * the server itself: without it crash reports are not remapped, the tests still run. + * Installs and starts `ci-remap-server`, the bin of bun-tracestrings + * (github:oven-sh/bun.report), which remaps the crash reports of the tests + * (spawnBun points them at it with BUN_CRASH_REPORT_URL). It is pinned in + * scripts/ci-remap-server/package.json rather than the root package.json because + * this runner is its only user, and as a github: dependency it would otherwise put + * GitHub on the critical path of the root `bun install` every GitHub Actions + * workflow and every build runs. + * + * Nothing is awaited here. The install and the server's startup (it loads octokit + * and opens a sqlite database) take seconds each on a fresh CI agent, so they run + * while the runner does the rest of its setup, and `port()` is called right before + * the first test. `port()` prints the install output and the outcome as one group. + * Best-effort throughout: without the server crash reports are not remapped, the + * tests still run. * @param {string} execPath - * @returns {Promise} + * @returns {{ port: () => Promise }} */ -async function installCiRemapServer(execPath) { +function startCiRemapServer(execPath) { const title = relative(cwd, join(ciRemapServerPath, "package.json")).replaceAll(sep, "/"); - const { ok, error } = await startGroup(title, () => spawnBunInstall(execPath, { cwd: ciRemapServerPath })); - if (!ok) console.warn(`ci-remap server not installed (${title}: ${error}), crash reports will not be remapped`); - return ok; + const startedAt = Date.now(); + let installOutput = ""; + /** @type {Promise} */ + const server = (async () => { + const { ok, error } = await spawnBunInstall(execPath, { + cwd: ciRemapServerPath, + stdout: chunk => (installOutput += chunk), + stderr: chunk => (installOutput += chunk), + }); + if (!ok) return { error: `not installed (${error})` }; + return spawnBackgroundServer([execPath, "run", "--silent", "ci-remap-server", execPath, cwd, getCommit()], { + cwd: ciRemapServerPath, + env: { + ...process.env, + BUN_DEBUG_QUIET_LOGS: "1", + NO_COLOR: "1", + // The server is killed when this process exits. This also takes it down + // when this process is killed instead, which runs no exit handlers. + BUN_FEATURE_FLAG_NO_ORPHANS: "1", + }, + }); + })().catch(error => ({ error: String(error) })); + + return { + async port() { + const neededAt = Date.now(); + const seconds = since => `${((Date.now() - since) / 1000).toFixed(1)}s`; + const started = await server; + startGroup(title); + process.stdout.write(installOutput); + const result = "port" in started ? await started.port(ciRemapServerTimeout) : started; + if ("error" in result) { + console.warn( + `ci-remap server did not start: ${result.error}, crash reports will not be remapped (${seconds(startedAt)} after it was started)`, + ); + return; + } + console.log(`crash reports parsed on port ${result.port} (waited ${seconds(neededAt)} for it)`); + return result.port; + }, + }; } /** diff --git a/scripts/utils.mjs b/scripts/utils.mjs index 713e8ecb6d9e..c983f9fae8d3 100755 --- a/scripts/utils.mjs +++ b/scripts/utils.mjs @@ -18,6 +18,7 @@ import { connect } from "node:net"; import { hostname, homedir as nodeHomedir, tmpdir as nodeTmpdir, release, userInfo } from "node:os"; import { basename, dirname, join, relative, resolve } from "node:path"; import { normalize as normalizeWindows } from "node:path/win32"; +import { createInterface } from "node:readline"; export const isWindows = process.platform === "win32"; export const isMacOS = process.platform === "darwin"; @@ -439,6 +440,78 @@ export function spawnSyncSafe(command, options = {}) { return spawnSync(command, { throwOnError: true, ...options }); } +/** + * @typedef {object} BackgroundServer + * @property {import("node:child_process").ChildProcess} subprocess + * @property {(timeout: number) => Promise<{ port: number } | { error: string }>} port + */ + +/** + * Starts a server without waiting for it. The server prints the port it listens + * on as its first line of stdout (the ci-remap server does), then keeps running + * until this process exits, which kills it. Start it as early as possible and call + * `port()` right before the server is needed, so that its startup overlaps with + * the work in between. + * + * `port(timeout)` resolves with the port, also when it was printed before the + * call. It resolves with an error as soon as the server fails to spawn or ends + * without printing a line, whatever its exit code, when its first line is not a + * port, or when `timeout` ms pass after the call. In the last two cases the server + * is killed as well. It never rejects. The server does not keep this process + * alive, and it inherits this process's stderr. + * @param {string[]} command + * @param {{ cwd?: string, env?: Record }} [options] + * @returns {BackgroundServer} + */ +export function spawnBackgroundServer(command, options = {}) { + const [cmd, ...args] = command; + debugLog("$", cmd, ...args); + + const { promise: firstLine, resolve: settle } = Promise.withResolvers(); + const subprocess = nodeSpawn(cmd, args, { + cwd: options["cwd"], + env: options["env"], + stdio: ["ignore", "pipe", "inherit"], + }); + // kill() sends SIGTERM, on purpose. `bun run ` stays alive as the parent of + // the script it runs and forwards SIGTERM to it. SIGKILL would end the wrapper + // alone and leave the script running, holding this process's stderr open. + const kill = () => subprocess.kill(); + process.once("exit", kill); + subprocess.on("error", error => settle({ error: error.message })); + // "close" and not "exit": a server that prints its line and exits at once can + // emit "exit" before its stdout was read. "close" comes after the end of stdout, + // and readline emits the line before that. + subprocess.on("close", (exitCode, signalCode) => settle({ error: signalCode ?? `code ${exitCode}` })); + createInterface(subprocess.stdout).once("line", line => settle({ line })); + subprocess.unref(); + subprocess.stdout.unref?.(); + + return { + subprocess, + async port(timeout) { + const timer = setTimeout(() => { + settle({ error: "timeout" }); + kill(); + }, timeout); + let result; + try { + result = await firstLine; + } finally { + clearTimeout(timer); + } + if ("error" in result) { + return result; + } + if (!/^\d+$/.test(result.line)) { + kill(); + return { error: `printed ${JSON.stringify(result.line)} instead of a port` }; + } + return { port: parseInt(result.line) }; + }, + }; +} + /** * @param {number} exitCode * @returns {string | undefined} diff --git a/test/internal/spawn-background-server.test.ts b/test/internal/spawn-background-server.test.ts new file mode 100644 index 000000000000..31175c3613ec --- /dev/null +++ b/test/internal/spawn-background-server.test.ts @@ -0,0 +1,219 @@ +/** + * spawnBackgroundServer() (scripts/utils.mjs) is how scripts/runner.node.mjs starts + * the crash report remap server on CI shards. The server takes seconds to start on + * a fresh agent, so the runner starts it before its own installs and only calls + * port() right before the first test. That works only if a port printed before the + * call is still delivered, if a server that ends without printing one fails the + * call at once and not after the timeout, if a server that prints something else + * or runs into the timeout is killed, and if the server dies with the process that + * started it, on every way out of that process. + * + * Each case runs in a fixture process, under node (the runner's runtime) and + * under bun. The servers are `-e` scripts of the same runtime. The fixture reports + * one JSON line on stdout; spawnBackgroundServer reads the servers' stdout, so + * they cannot write there. The servers inherit the fixture's stderr, so the + * fixture's stderr reaches EOF only once every server is gone: runFixture() reads + * it to EOF, which is how the "killed on exit" cases are proven, and the control + * case shows that a server nothing kills does keep it open. + */ +import { describe, expect, test } from "bun:test"; +import { bunEnv, bunExe, isWindows, nodeExe, tempDir } from "harness"; +import { join } from "node:path"; +import { pathToFileURL } from "node:url"; + +const utils = pathToFileURL(join(import.meta.dir, "../../scripts/utils.mjs")).href; + +const fixture = tempDir("spawn-background-server", { + "spawn-background-server-fixture.mjs": ` + import { spawn } from "node:child_process"; + import { spawnBackgroundServer } from ${JSON.stringify(utils)}; + + const [mode] = process.argv.slice(2); + const server = code => spawnBackgroundServer([process.execPath, "-e", code]); + const forever = "setInterval(() => {}, 1000)"; + const listening = "console.log(12345); " + forever; + // The servers are unref'd: hold the event loop open while waiting for one to end. + async function ended(subprocess) { + const keepAlive = setInterval(() => {}, 1000); + if (subprocess.exitCode === null && subprocess.signalCode === null) { + await new Promise(resolve => subprocess.once("close", resolve)); + } + clearInterval(keepAlive); + return subprocess.signalCode ?? subprocess.exitCode; + } + function isAlive(pid) { + try { + process.kill(pid, 0); + return true; + } catch { + return false; + } + } + // A listening server, plus whether it was still up when the fixture left. + async function up() { + const { subprocess, port } = server(listening); + return { ...(await port(30_000)), alive: isAlive(subprocess.pid) }; + } + + const report = value => console.log(JSON.stringify(value)); + + // Like the runner, this process leaves through process.exit() (below), an + // uncaught exception out of main(), or a signal handler that calls + // process.exit(). The server has to die on each of them. + async function main() { + switch (mode) { + case "ready": + return up(); + case "uncaught-exception": + report(await up()); + throw new Error("runner bug"); + case "signal-handler": + process.on("SIGTERM", () => process.exit(3)); + report(await up()); + process.kill(process.pid, "SIGTERM"); + // The handler ends the process; keep the event loop alive until it runs. + setInterval(() => {}, 1000); + return new Promise(() => {}); + case "printed-before-the-call": { + const { subprocess, port } = server("console.log(12345)"); + const exit = await ended(subprocess); + return { ...(await port(30_000)), exit }; + } + case "exits-3-without-a-line": + return server("process.exit(3)").port(30_000); + case "exits-0-without-a-line": + return server("0").port(30_000); + case "does-not-exist": + return spawnBackgroundServer(["/does/not/exist/ci-remap-server"]).port(30_000); + case "prints-something-else": { + const { subprocess, port } = server("console.log('listening on 12345'); " + forever); + return { ...(await port(30_000)), exit: await ended(subprocess) }; + } + case "timeout": { + const { subprocess, port } = server(forever); + return { ...(await port(250)), exit: await ended(subprocess) }; + } + case "control": { + // Not started through spawnBackgroundServer: nothing kills it when this process exits. + const { pid } = spawn(process.execPath, ["-e", forever], { stdio: ["ignore", "ignore", "inherit"] }); + return { pid }; + } + } + } + + report(await main()); + process.exit(0); + `, +}); + +const env = { ...bunEnv }; +// Under this flag a bun server dies with its parent on its own, which would hide a +// missing "exit" hook. +delete env.BUN_FEATURE_FLAG_NO_ORPHANS; + +function startFixture(exe: string, mode: string) { + return Bun.spawn({ + cmd: [exe, join(String(fixture), "spawn-background-server-fixture.mjs"), mode], + env, + stdout: "pipe", + stderr: "pipe", + }); +} + +/** The JSON line the fixture prints last, or undefined when it did not get that far. */ +function parseReport(stdout: string) { + try { + return JSON.parse(stdout.trim().split("\n").at(-1)!); + } catch { + return undefined; + } +} + +/** Resolves once the fixture has exited and every server it started is gone. */ +async function runFixture(exe: string, mode: string, expected: object = { stderr: "", exitCode: 0 }) { + await using proc = startFixture(exe, mode); + const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]); + expect({ stdout, stderr, exitCode }).toMatchObject(expected); + return parseReport(stdout); +} + +function isAlive(pid: number) { + try { + process.kill(pid, 0); + return true; + } catch { + return false; + } +} + +const listening = { port: 12345, alive: true }; + +for (const [runtime, exe] of [ + ["node", nodeExe()], + ["bun", bunExe()], +] as const) { + // The runner starts the remap server on non-Windows platforms only. + describe.skipIf(isWindows || !exe)(`under ${runtime}`, () => { + test.concurrent("resolves with the port of a server that stays up, and kills it on process.exit()", async () => { + expect(await runFixture(exe!, "ready")).toEqual(listening); + }); + + test.concurrent("kills the server when the process dies of an uncaught exception", async () => { + const expected = { exitCode: 1, stderr: expect.stringContaining("runner bug") }; + expect(await runFixture(exe!, "uncaught-exception", expected)).toEqual(listening); + }); + + test.concurrent("kills the server when a signal handler calls process.exit()", async () => { + expect(await runFixture(exe!, "signal-handler", { stderr: "", exitCode: 3 })).toEqual(listening); + }); + + test.concurrent("delivers a port printed before the call, also once the server is gone", async () => { + expect(await runFixture(exe!, "printed-before-the-call")).toEqual({ port: 12345, exit: 0 }); + }); + + test.concurrent.each([ + ["exits-3-without-a-line", "code 3"], + ["exits-0-without-a-line", "code 0"], + ])("a server that ends without a line (%s) fails the call at once, not after the timeout", async (mode, error) => { + expect(await runFixture(exe!, mode)).toEqual({ error }); + }); + + test.concurrent("a command that cannot be spawned fails the call", async () => { + expect(await runFixture(exe!, "does-not-exist")).toEqual({ error: expect.stringContaining("ENOENT") }); + }); + + test.concurrent("a server whose first line is not a port fails the call and is killed", async () => { + expect(await runFixture(exe!, "prints-something-else")).toEqual({ + error: 'printed "listening on 12345" instead of a port', + exit: "SIGTERM", + }); + }); + + test.concurrent("the timeout counts from the call and kills the server", async () => { + expect(await runFixture(exe!, "timeout")).toEqual({ error: "timeout", exit: "SIGTERM" }); + }); + + test.concurrent("control: a server nothing kills outlives the fixture and holds its stderr open", async () => { + await using proc = startFixture(exe!, "control"); + // stderr is left pending on purpose: the server holds it open until the test kills the server. + const stderr = proc.stderr.text(); + const [stdout, exitCode] = await Promise.all([proc.stdout.text(), proc.exited]); + const pid: number | undefined = parseReport(stdout)?.pid; + try { + expect({ stdout, exitCode }).toMatchObject({ exitCode: 0 }); + expect(pid).toBeNumber(); + expect(isAlive(pid!)).toBe(true); + expect( + await Promise.race([stderr.then(() => "eof"), new Promise(resolve => setImmediate(() => resolve("open")))]), + ).toBe("open"); + } finally { + if (pid !== undefined) { + try { + process.kill(pid, "SIGKILL"); + } catch {} + } + } + expect(await stderr).toBe(""); + }); + }); +}