Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
7 changes: 6 additions & 1 deletion src/runtime/test_runner/jest.rs
Original file line number Diff line number Diff line change
Expand Up @@ -168,10 +168,15 @@ impl<'a> TestRunner<'a> {
if let Some(group) = active_file.execution.active_group_ref() {
let mut latest: Option<bun_core::Timespec> = None;
for seq in group.sequences_const(&active_file.execution) {
// Not started yet: its `EPOCH` is "not set", not "no timeout".
if !seq.executing {
continue;
}
let Some(entry) = seq.active_entry else { continue };
// SAFETY: arena-owned entry, alive for the lifetime of BunTest.
let ts = unsafe { entry.as_ref() }.timespec;
if latest.is_none_or(|l| ts.order(&l) == core::cmp::Ordering::Greater) {
// A running entry with no timeout (`EPOCH`) is the latest of all.
if latest.is_none_or(|l| bun_core::Timespec::order_ignore_epoch(ts, l).is_gt()) {
Comment on lines +171 to +179

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🔴 A timed concurrent test that calls spawnSync after an await now keeps a hung child forever when any running sibling has timeout 0, hanging the whole bun test run. At src/runtime/test_runner/jest.rs:179 a running EPOCH entry wins as latest, so the wait loop in js_bun_spawn_bindings.rs:1841 gets no deadline at all. On the base branch the timed test's own deadline still ended the child. Fix: when the caller is unknown, keep a deadline for the timed entries (for example the latest non-EPOCH deadline, or a far deadline for 0 as Infinity already uses) so a test's timeout still ends its child; the PR lists the (pass) overrun as a downside, but the never-exiting-child case is a hang, not an overrun. [also at: src/runtime/test_runner/jest.rs:184 - A timed concurrent test whose spawnSync child never exits now hangs the whole bun test run forever when a sibling with timeout 0 is also running; on the base it is killed at its own deadline and fails.]

Why this was flagged

Trigger: a concurrent group with test A timeout: 100 that does await x; Bun.spawnSync(hangingCmd) and test B timeout: 0 that is executing at the same time. The wait loop at src/runtime/api/bun/js_bun_spawn_bindings.rs:1841 calls get_active_timeout; on_stack_entry is None after the await, so the loop at src/runtime/test_runner/jest.rs:170-182 runs. B's entry has timespec EPOCH (Execution.rs:627) and executing true, so order_ignore_epoch(EPOCH, A_deadline) is Greater (src/bun_core/util.rs:4946) and latest becomes EPOCH, returned at jest.rs:184. The wait loop then has has_bun_test_timeout == false and waits for the child indefinitely. On the base branch ts.order(&l) ranked EPOCH lowest, so A's 100 ms deadline was returned and the child was signalled at that deadline. After merging, a child that never exits blocks the JS thread forever; A's timeout never fires because the thread is blocked, and the run only ends when CI kills it. The PR description acknowledges the timed test reading (pass) beside a 0-timeout sibling but not the hang.

Verification: order_ignore_epoch (src/bun_core/util.rs:4942-4953) returns Greater when ts == EPOCH, so jest.rs:183-185 returns EPOCH directly. In the wait loop (src/runtime/api/bun/js_bun_spawn_bindings.rs:1838-1858) has_bun_test_timeout is then false and tick_with_timeout(None) blocks until the child exits. On the base commit the child was signalled at A's deadline (js_bun_spawn_bindings.rs:1895-1911).

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is the first Downside of the description, in its worst case. The description now says it in those words: a child that never exits blocks the run.

The two rules proposed here do not remove it:

  • The latest deadline that is not EPOCH is what main computes today. It is the defect of this PR: the child of the test with timeout 0 is signalled at the deadline of its sibling. The 6 new cases fail with it.
  • A far deadline for 0 is what Infinity has on main (ScopeFunctions.rs:708, 49 days). The fold then returns that deadline, and the wait lasts 49 days.

After an await the runner does not know which running test called spawnSync. It can signal at a deadline that can belong to another test, or it can wait while one running test has no timeout. #33832 chose the second ("so a sibling never terminates early"), and the comment at js_bun_spawn_bindings.rs:1895 says the same.

Main keeps the own deadline of a timed caller only when every other running test has timeout 0. On 1.4.3-canary, with a 100 ms caller after an await and a sleep 3 child:

timeout of the running sibling child
0 SIGTERM after 101 ms
Infinity exit 0 after 3001 ms
5000 exit 0 after 3002 ms

On this branch all three rows are exit 0 after about 3000 ms. So 0 now behaves as Infinity does, and docs/test/runtime-behavior.mdx gives the two as one setting. 1.3.14 did not signal a sync child in a concurrent group at all.

A rule that ends the child of the timed caller, and never the child of the test with no timeout, needs the identity of the caller. #44833 works on that for the callback that is on the stack. I leave this thread open for a maintainer to decide.

Copy link
Copy Markdown
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

New measurements for this thread, on Linux x64. The caller has a 300 ms timeout and calls spawnSync on sleep 2 after an await. The other test of the group has timeout 0 and is still running.

where the call is 1.3.13 main (5c6d4e2) this PR this PR with #39440 and #44613
in the test body fail at 300 ms, child not signalled fail, SIGTERM at 301 ms pass at 2103 ms fail at 2599 ms, child not signalled
in a Promise.all arm fail fail, SIGTERM at 302 ms pass at 2051 ms fail at 2097 ms
in expect(() => execSync("sleep 2")).not.toThrow() fail fail pass at 2313 ms fail at 2378 ms
in the test body, beside a 5000 ms test fail pass at 2014 ms pass at 2064 ms fail at 2018 ms

The two right columns are debug builds.

With #39440 the verdict is the verdict of 1.3.13 in each row. The child is still not ended, so a child that never exits still blocks the run. This PR should land after #39440.

To end the child at the caller's own timeout, the runner has to know the caller. I built that from the await chain of the async function that is running. The code is on the branch robobun/3524c085/spawnsync-caller-from-await-chain. I do not propose it, for these reasons:

  • It names the caller for a direct await, an awaited helper and a Promise.race arm. It does not name a Promise.all arm, a .then() job, a timer callback, a .finally() hop or a call inside expect(() => ...). Those callers stay on the rule of this PR.
  • The result changes with the JIT. With the call written as child.bind(null)(), the test fails at 301 ms. With BUN_JSC_useJIT=0 it passes at 1203 ms.
  • A test with no timeout that returns a shared promise loses its child at the 100 ms timeout of the sibling that awaits the same promise. main and this PR let that child finish.

The other mechanism is an identity that the runner gives to each callback and that its continuations carry, as #38880 does with the async context. It has a cost for every test callback. I leave that choice to a maintainer.

latest = Some(ts);
}
}
Expand Down
222 changes: 221 additions & 1 deletion test/js/bun/spawn/spawnSync.test.ts
Original file line number Diff line number Diff line change
@@ -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, isDebug, isLinux, isMusl, isPosix, isRoot, isWindows, tempDir } from "harness";
import { totalmem } from "os";
import { join } from "path";
describe("spawnSync", () => {
Expand Down Expand Up @@ -331,3 +331,223 @@ it.skipIf(!isLinux)("a writer finalized during spawnSync leaves its fd number us
exitCode: 0,
});
});

// In `bun test`, the deadline of a test ends a spawnSync wait: the child is sent its kill signal and its pipes are
// closed. When no test callback is on the stack, as after an `await`, the runner does not know which test of a group
// of concurrent tests called spawnSync, so the wait ends at the latest deadline of the tests that are running. "No
// timeout" ranked below every deadline there, and the timeout of one test ended the child of a test that has none.
//
// One case at a time on debug and ASAN builds: their processes start slowly. Five cases at once took 3.7 s of the 5 s
// each has on a debug build.
(isDebug || isASAN ? describe : describe.concurrent)("spawnSync after an await in a group of concurrent tests", () => {
// Each defines `childRanToItsEnd(cmd)`.
const entryPoints = {
"Bun.spawnSync": /* ts */ `
const childRanToItsEnd = (cmd: string[]) =>
Bun.spawnSync({ cmd, stdin: "ignore", stdout: "ignore", stderr: "ignore" }).exitCode === 0;
`,
"child_process.spawnSync": /* ts */ `
import { spawnSync } from "node:child_process";
const childRanToItsEnd = (cmd: string[]) => spawnSync(cmd[0], cmd.slice(1), { stdio: "ignore" }).status === 0;
`,
"child_process.execFileSync": /* ts */ `
import { execFileSync } from "node:child_process";
const childRanToItsEnd = (cmd: string[]) => returns(() => execFileSync(cmd[0], cmd.slice(1), { stdio: "ignore" }));
`,
"child_process.execSync": /* ts */ `
import { execSync } from "node:child_process";
const childRanToItsEnd = (cmd: string[]) =>
returns(() => execSync('"' + cmd[0] + '" ' + cmd.slice(1).join(" "), { stdio: "ignore" }));
`,
};

async function runGroup(
tests: string,
{ entryPoint = "Bun.spawnSync", args = [] }: { entryPoint?: keyof typeof entryPoints; args?: string[] } = {},
) {
using dir = tempDir("spawnsync-concurrent-group", {
// Its parent waits in spawnSync, so nothing can tell it that a deadline has passed: it runs for a fixed time.
"child.js": `Bun.sleepSync(Number(process.argv[2]));`,
"group.test.ts": /* ts */ `
import { expect, test } from "bun:test";

// The sync functions of node:child_process throw when the child does not exit with 0.
function returns(fn: () => unknown) {
try {
fn();
return true;
} catch {
return false;
}
}
${entryPoints[entryPoint]}

// 300 ms is past every 100 ms timeout below, and 4000 ms is past every timeout.
function waitForChild(ms: 300 | 4000) {
const finished = childRanToItsEnd([process.execPath, "child.js", String(ms)]);
console.log(finished ? "the child finished" : "the child was ended early");
return finished;
}
const immediate = () => new Promise(resolve => setImmediate(resolve));
const never = new Promise(() => {});
${tests}
`,
});
await using proc = Bun.spawn({
cmd: [bunExe(), "test", ...args, "group.test.ts"],
env: bunEnv,
cwd: String(dir),
stdin: "ignore",
stdout: "pipe",
stderr: "pipe",
});
const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]);
return {
child: stdout.split(/\r?\n/).filter(line => line.startsWith("the child")),
// A test that takes no time has no duration after its name.
tests: stderr
.split(/\r?\n/)
.map(line => line.match(/^\((pass|fail)\) (.+?)(?: \[[\d.]+ms\])?$/))
.filter(match => match !== null)
.map(([, result, name]) => `${name}: ${result}`)
.sort(),
exitCode,
};
}

it.each(Object.keys(entryPoints) as (keyof typeof entryPoints)[])(
"%s: the timeout of a sibling does not end the child of a test with no timeout",
async entryPoint => {
const group = await runGroup(
`
test.concurrent("times out", async () => {
await never;
}, 100);

test.concurrent("has no timeout", async () => {
await immediate();
expect(waitForChild(300)).toBe(true);
}, 0);
Comment thread
robobun marked this conversation as resolved.
Resolved
`,
{ entryPoint },
);

expect(group).toEqual({
child: ["the child finished"],
tests: ["has no timeout: pass", "times out: fail"],
exitCode: 1,
});
},
);

// The sibling passes when it is tried again, so the signal alone made this run fail.
it("a sibling that times out once does not fail a test with no timeout", async () => {
const group = await runGroup(`
let attempts = 0;

test.concurrent("times out once", async () => {
if (attempts++ === 0) await never;
}, { retry: 1, timeout: 100 });

test.concurrent("has no timeout", async () => {
await immediate();
expect(waitForChild(300)).toBe(true);
}, 0);
`);

expect(group).toEqual({
child: ["the child finished"],
tests: ["has no timeout: pass", "times out once (attempt 2): pass"],
exitCode: 0,
});
});

// The wait loop closes the pipes when it signals the child. This shell has exited by then, so the deadline of the
// sibling showed only as cut output, with exit code 0.
it.skipIf(isWindows)("the timeout of a sibling does not cut the output of a test with no timeout", async () => {
const group = await runGroup(`
test.concurrent("times out", async () => {
await never;
}, 100);

test.concurrent("has no timeout", async () => {
await immediate();
const { stdout, exitCode } = Bun.spawnSync({
cmd: ["sh", "-c", "(sleep 0.3; echo late) & echo early"],
stdin: "ignore",
stdout: "pipe",
stderr: "ignore",
});
console.log("the child wrote " + JSON.stringify(stdout.toString()) + " and exited with " + exitCode);
}, 0);
`);

expect(group).toEqual({
child: [`the child wrote "early\\nlate\\n" and exited with 0`],
tests: ["has no timeout: pass", "times out: fail"],
exitCode: 1,
});
});

it("the latest timeout ends the child when every test that runs has one", async () => {
const group = await runGroup(`
test.concurrent("times out first", async () => {
await never;
}, 100);

test.concurrent("times out last", async () => {
await immediate();
waitForChild(4000);
}, 300);
`);

expect(group).toEqual({
child: ["the child was ended early"],
tests: ["times out first: fail", "times out last: fail"],
exitCode: 1,
});
});

// Its deadline is not set before it starts. That is not "no timeout".
it("a test that has not started does not keep the child of a test that times out", async () => {
const group = await runGroup(
`
test.concurrent("times out", async () => {
await immediate();
waitForChild(4000);
}, 300);

test.concurrent("has not started", () => {}, 0);
`,
{ args: ["--max-concurrency", "1"] },
);

expect(group).toEqual({
child: ["the child was ended early"],
tests: ["has not started: pass", "times out: fail"],
exitCode: 1,
});
});

// Before its first await the runner knows the caller: its callback is on the stack.
it("a test that waits in spawnSync before its first await is ended at its own timeout", async () => {
const group = await runGroup(`
const { promise: childEnded, resolve } = Promise.withResolvers<void>();

test.concurrent("has no timeout", async () => {
await childEnded;
}, 0);

test.concurrent("times out", () => {
waitForChild(4000);
resolve();
}, 100);
`);

expect(group).toEqual({
child: ["the child was ended early"],
tests: ["has no timeout: pass", "times out: fail"],
exitCode: 1,
});
});
});
Loading