diff --git a/docs/test/writing-tests.mdx b/docs/test/writing-tests.mdx index 002aec0bd566..37c7c4b878bf 100644 --- a/docs/test/writing-tests.mdx +++ b/docs/test/writing-tests.mdx @@ -117,7 +117,7 @@ test( ### 🧟 Zombie Process Killer -When a test times out, Bun kills any still-running processes that the test spawned with `Bun.spawn`, `Bun.spawnSync`, or `node:child_process`, and logs a message to the console. This prevents zombie processes from lingering after timed-out tests. +When a test times out, Bun kills any still-running processes that the test spawned with `Bun.spawn`, `Bun.spawnSync`, or `node:child_process`, and logs a message to the console. This prevents zombie processes from lingering after timed-out tests. A test that waits in `Bun.spawnSync` or in a synchronous `node:child_process` call cannot end before that child does: on Linux and macOS, Bun sends `SIGKILL` to that child if it is still running 500 milliseconds after the timeout. Tests that run concurrently do not get this. ## Test Modifiers diff --git a/src/runtime/api/bun/js_bun_spawn_bindings.rs b/src/runtime/api/bun/js_bun_spawn_bindings.rs index 86db753802c7..2c4c34ef0d59 100644 --- a/src/runtime/api/bun/js_bun_spawn_bindings.rs +++ b/src/runtime/api/bun/js_bun_spawn_bindings.rs @@ -1832,16 +1832,23 @@ fn spawn_maybe_sync( let has_user_timespec = !user_timespec.eql(&Timespec::EPOCH); let mut bun_test_fired = false; + // Once the bun:test deadline has fired: when the child is sent SIGKILL. `EPOCH`: never. + let mut force_kill_at = Timespec::EPOCH; while subprocess.compute_has_pending_activity() { // Re-evaluate this at each iteration of the loop since it may change between iterations. let bun_test_timeout: Timespec = if bun_test_fired { - Timespec::EPOCH + force_kill_at } else if jsc_vm.is_main_thread && let Some(runner) = crate::test_runner::jest::Jest::runner() { // The test runner and its deadlines belong to the main thread. - runner.get_active_timeout() + // After this call's own timeout, the deadline of a test ends the wait only when it is the caller's. + if did_timeout && !runner.active_timeout_is_callers() { + Timespec::EPOCH + } else { + runner.get_active_timeout() + } } else { Timespec::EPOCH }; @@ -1874,7 +1881,7 @@ fn spawn_maybe_sync( // Tick the isolated event loop without passing timeout to avoid blocking // The timeout check is done at the top of the loop - match sync_loop.tick_with_timeout(if has_timespec && !did_timeout { + match sync_loop.tick_with_timeout(if has_timespec { Some(&absolute_timespec) } else { None @@ -1882,12 +1889,15 @@ fn spawn_maybe_sync( TickState::Completed => {} TickState::Timeout => { now = Timespec::now(TimespecMockMode::ForceRealTime); - let did_user_timeout = has_user_timespec + let did_user_timeout = !did_timeout + && has_user_timespec && (absolute_timespec.eql(&user_timespec) || user_timespec.order(&now) == core::cmp::Ordering::Less); if did_user_timeout { did_timeout = true; + // It fired: only a bun:test deadline is left to wake this loop. + user_timespec = Timespec::EPOCH; let _ = subprocess.try_kill(subprocess.kill_signal); } @@ -1898,20 +1908,27 @@ fn spawn_maybe_sync( if has_bun_test_timeout && bun_test_timeout.order(&now) == core::cmp::Ordering::Less { - bun_test_fired = true; - *bun_test_deadline = Some(absolute_timespec); - if let Some(active_file) = crate::test_runner::jest::Jest::runner() - .unwrap() - .bun_test_root - .active_file - .clone() - { - active_file - .get() - .execution - .kill_dangling_processes_on_timeout(cx.global()); + if bun_test_fired { + force_kill_at = Timespec::EPOCH; + // Not `kill_signal`, which the child may ignore: nothing else bounds the wait. + let _ = subprocess.try_kill(SignalCode::SIGKILL); + } else { + bun_test_fired = true; + *bun_test_deadline = Some(absolute_timespec); + let runner = crate::test_runner::jest::Jest::runner().unwrap(); + if runner.active_timeout_is_callers() { + force_kill_at = now.add_ms( + crate::test_runner::jest::TestRunner::SPAWN_SYNC_KILL_GRACE_MS, + ); + } + if let Some(active_file) = runner.bun_test_root.active_file.clone() { + active_file + .get() + .execution + .kill_dangling_processes_on_timeout(cx.global()); + } + let _ = subprocess.try_kill(subprocess.kill_signal); } - let _ = subprocess.try_kill(subprocess.kill_signal); } } } diff --git a/src/runtime/test_runner/jest.rs b/src/runtime/test_runner/jest.rs index 703b9186eb7d..7ee5ae469e27 100644 --- a/src/runtime/test_runner/jest.rs +++ b/src/runtime/test_runner/jest.rs @@ -192,6 +192,33 @@ impl<'a> TestRunner<'a> { bun_core::Timespec { sec: active_file.timer.next.sec, nsec: active_file.timer.next.nsec } } + /// How long a `spawnSync` child has to exit after its test timed out, before it is sent SIGKILL. + pub(crate) const SPAWN_SYNC_KILL_GRACE_MS: i64 = 500; + + /// Whether [`Self::get_active_timeout`] is certainly the deadline of the caller of `spawnSync`: one test runs, and its callback is not done. + pub(crate) fn active_timeout_is_callers(&self) -> bool { + // The default kill signal ends the child on Windows. + if cfg!(windows) { + return false; + } + let Some(active_file) = self.bun_test_root.active_file.clone() else { + return false; + }; + let buntest = active_file.get(); + let execution = &mut buntest.execution; + let one_test_runs = execution.active_group_ref().is_some_and(|group| { + matches!(group.sequences_const(execution), [only] if only.active_entry.is_some()) + }); + // A result for it is queued: its callback is done, and `run` has yet to step past it. + let queue = &buntest.result_queue; + one_test_runs + && !(0..queue.readable_length()).any(|offset| { + execution + .get_current_and_valid_execution_sequence(&queue.peek_item(offset)) + .is_some() + }) + } + pub(crate) fn remove_active_timeout(&mut self, vm: &mut VirtualMachine) { let Some(active_file) = self.bun_test_root.active_file.as_ref() else { return; diff --git a/test/js/bun/spawn/spawnSync.test.ts b/test/js/bun/spawn/spawnSync.test.ts index 9ccf716fae0c..e9908a139b22 100644 --- a/test/js/bun/spawn/spawnSync.test.ts +++ b/test/js/bun/spawn/spawnSync.test.ts @@ -1,5 +1,5 @@ import { describe, expect, it } from "bun:test"; -import { bunEnv, bunExe, bunRun, isLinux, isMusl, isPosix, isRoot, isWindows, tempDir } from "harness"; +import { bunEnv, bunExe, bunRun, isASAN, isLinux, isMusl, isPosix, isRoot, isWindows, tempDir } from "harness"; import { totalmem } from "os"; import { join } from "path"; describe("spawnSync", () => { @@ -225,6 +225,169 @@ it("a test timeout doesn't kill the child of a spawnSync running in a Worker", a expect(exitCode).toBe(1); }); +// A test times out while it waits in spawnSync. The runner then sends the child its kill signal, and SIGTERM with the +// other processes of that test. A child that ignores both used to keep the test waiting for as long as it ran. +// Windows ends a process on the first signal. Every case starts a `bun test`: an ASAN build starts too slowly to run +// them all at once inside the timeout of a case. +(isASAN ? describe : describe.concurrent).skipIf(isWindows)("the timeout of a test that waits in spawnSync", () => { + const prelude = /* ts */ ` + import { test } from "bun:test"; + import { spawnSync } from "node:child_process"; + import { readFileSync } from "node:fs"; + + const ignore = { stdin: "ignore", stdout: "ignore", stderr: "ignore" } as const; + + function report({ exitCode, signalCode }: { exitCode: number | null; signalCode?: unknown }) { + console.log(\`the child ended: exitCode \${exitCode}, signalCode \${signalCode ?? null}\`); + } + `; + + async function runTestFile(source: string, { noOrphans = false } = {}) { + for (let attempt = 1; ; attempt++) { + using dir = tempDir("spawnsync-test-timeout", { "timeout.test.ts": prelude + source }); + await using proc = Bun.spawn({ + cmd: [bunExe(), "test", "timeout.test.ts"], + // The mode is the runner's choice for some CI lanes, so every case names it. + env: { ...bunEnv, BUN_FEATURE_FLAG_NO_ORPHANS: noOrphans ? "1" : undefined }, + cwd: String(dir), + stdin: "ignore", + stdout: "pipe", + stderr: "pipe", + }); + const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]); + const combined = stdout + stderr; + // No child of these cases ends on SIGTERM or misses its first SIGURG once it is set up: this one was signalled + // sooner than that, on a machine too slow for the case. That run says nothing about the runner: do it again. + if (attempt === 3 || !/signalCode SIGTERM|got SIGURG 0 times/.test(combined)) return { combined, exitCode }; + } + } + + // One process: `sleep` keeps the SIGTERM that `sh` ignores. Nothing tells a caller that waits in spawnSync when + // `sh` has done that, so no case sends SIGTERM sooner than 300 ms after the spawn. + const ignoresSigterm = (seconds: number) => JSON.stringify(["sh", "-c", `trap '' TERM; exec sleep ${seconds}`]); + // SIGURG does nothing to a process that does not handle it. + const ownTimeout = `timeout: 100, killSignal: "SIGURG"`; + + const sigkill = "the child ended: exitCode null, signalCode SIGKILL"; + + it.each([ + ["Bun.spawnSync", `test("times out", () => { report(Bun.spawnSync({ cmd, ...ignore })); }, 300);`], + [ + "child_process.spawnSync", + `test("times out", () => { + const { status, signal } = spawnSync(cmd[0], cmd.slice(1), { stdio: "ignore" }); + report({ exitCode: status, signalCode: signal }); + }, 300);`, + ], + [ + "Bun.spawnSync after an await", + `test("times out", async () => { + await new Promise(resolve => setImmediate(resolve)); + report(Bun.spawnSync({ cmd, ...ignore })); + }, 300);`, + ], + [ + "Bun.spawnSync after its own timeout", + `test("times out", () => { report(Bun.spawnSync({ cmd, ${ownTimeout}, ...ignore })); }, 300);`, + ], + ])("%s: the child is sent SIGKILL", async (_, timesOut) => { + const { combined, exitCode } = await runTestFile(`const cmd = ${ignoresSigterm(3)}; ${timesOut}`); + + expect(combined).toContain(sigkill); + expect(combined).toContain("(fail) times out"); + expect(exitCode).toBe(1); + }); + + it("in no-orphans mode too", async () => { + const { combined, exitCode } = await runTestFile( + `test("times out", () => { report(Bun.spawnSync({ cmd: ${ignoresSigterm(3)}, ...ignore })); }, 300);`, + { noOrphans: true }, + ); + + expect(combined).toContain(sigkill); + expect(exitCode).toBe(1); + }); + + it("a test that is done before spawnSync returns keeps the child", async () => { + const { combined, exitCode } = await runTestFile(` + test("is done in time", done => { + setImmediate(() => { + done(); + report(Bun.spawnSync({ cmd: ${ignoresSigterm(1.2)}, ...ignore })); + }); + }, 300); + `); + + expect(combined).toContain("the child ended: exitCode 0, signalCode null"); + expect(combined).toContain("(pass) is done in time"); + expect(exitCode).toBe(0); + }); + + it("in a group of concurrent tests, the timeout of one test does not send SIGKILL to the child of another", async () => { + const { combined, exitCode } = await runTestFile(` + test.concurrent("times out", async () => { + await new Promise(() => {}); + }, 100); + + test.concurrent("has no timeout", async () => { + await new Promise(resolve => setImmediate(resolve)); + report(Bun.spawnSync({ cmd: ["sleep", "1"], killSignal: "SIGURG", ...ignore })); + }, 0); + `); + + expect(combined).toContain("the child ended: exitCode 0, signalCode null"); + expect(combined).toContain("(pass) has no timeout"); + expect(exitCode).toBe(1); + }); + + it("in a group of concurrent tests, a deadline after the timeout of spawnSync does not signal the child again", async () => { + const countsSigurg = [ + "sh", + "-c", + "n=0; trap 'n=$((n+1))' URG; i=0; while [ $i -lt 120 ]; do sleep 0.01; i=$((i+1)); done; echo $n > signals", + ]; + const { combined } = await runTestFile(` + test.concurrent("runs in the same group", () => {}); + + test.concurrent("calls spawnSync", async () => { + await new Promise(resolve => setImmediate(resolve)); + const start = performance.now(); + Bun.spawnSync({ cmd: ${JSON.stringify(countsSigurg)}, timeout: 300, killSignal: "SIGURG", ...ignore }); + console.log("the deadline of the test passed during the call: " + (performance.now() - start > 600)); + console.log("the child got SIGURG " + readFileSync("signals", "utf8").trim() + " times"); + }, 600); + `); + + expect(combined).toContain("the deadline of the test passed during the call: true"); + expect(combined).toContain("the child got SIGURG 1 times"); + }); + + it("the timeout of spawnSync alone does not send SIGKILL", async () => { + const { combined, exitCode } = await runTestFile(` + test("does not time out", () => { + report(Bun.spawnSync({ cmd: ["sleep", "1"], ${ownTimeout}, ...ignore })); + }); + `); + + expect(combined).toContain("the child ended: exitCode 0, signalCode null"); + expect(exitCode).toBe(0); + }); + + it("a child that exits on SIGTERM keeps its exit code", async () => { + const exitsOnSigterm = [ + "sh", + "-c", + "trap 'exit 7' TERM; i=0; while [ $i -lt 300 ]; do sleep 0.01; i=$((i+1)); done", + ]; + const { combined, exitCode } = await runTestFile( + `test("times out", () => { report(Bun.spawnSync({ cmd: ${JSON.stringify(exitsOnSigterm)}, ...ignore })); }, 300);`, + ); + + expect(combined).toContain("the child ended: exitCode 7, signalCode null"); + expect(exitCode).toBe(1); + }); +}); + describe("uid/gid", () => { it("rejects a non-integer uid", () => { expect(() => Bun.spawnSync({ cmd: [bunExe()], env: bunEnv, uid: 1.5 })).toThrow();