diff --git a/src/runtime/test_runner/Execution.rs b/src/runtime/test_runner/Execution.rs index a67b00fcc37a..cc7a6cff551a 100644 --- a/src/runtime/test_runner/Execution.rs +++ b/src/runtime/test_runner/Execution.rs @@ -766,6 +766,29 @@ impl Execution { } } + /// Judged here rather than in `step`: other callbacks may block before the queued completion is processed. + pub(crate) fn handle_callback_completed(&mut self, user_data: &RefDataValue) { + let _g = group_begin!(); + + let Some((sequence_ptr, _group_ptr)) = + self.get_current_and_valid_execution_sequence(user_data) + else { + return; + }; + // SAFETY: sequence_ptr points into self.sequences; `self` is not accessed for the + // remainder of this function, so this is the unique live `&mut` to that element. + let sequence = unsafe { &mut *sequence_ptr.as_ptr() }; + let Some(entry) = sequence.active_entry else { + return; + }; + // SAFETY: arena-owned entry, alive for lifetime of BunTest + let _ = unsafe { entry.as_ref() }.evaluate_timeout( + sequence, + &Timespec::now_force_real_time(), + true, + ); + } + pub(crate) fn handle_uncaught_exception( &mut self, user_data: &RefDataValue, @@ -980,7 +1003,7 @@ fn step_sequence_one( }; // SAFETY: arena-owned entry let active_entry = unsafe { &mut *active_entry_ptr.as_ptr() }; - if active_entry.evaluate_timeout(sequence, now) { + if active_entry.evaluate_timeout(sequence, now, false) { Execution::advance_sequence(buntest_ptr, sequence_ptr, group); return Ok(None); // run again } @@ -1044,7 +1067,7 @@ fn step_sequence_one( // SAFETY: re-deref after run_test_callback; sequence_ptr still valid (sequences is a // Box<[ExecutionSequence]>, never reallocated during execution). let sequence = unsafe { &mut *sequence_ptr.as_ptr() }; - let _ = next_item.evaluate_timeout(sequence, now); + let _ = next_item.evaluate_timeout(sequence, now, true); // the result is available immediately; advance the sequence and run again. Execution::advance_sequence(buntest_ptr, sequence_ptr, group); diff --git a/src/runtime/test_runner/bun_test.rs b/src/runtime/test_runner/bun_test.rs index 30023ceab736..ed2ac7bc3ccb 100644 --- a/src/runtime/test_runner/bun_test.rs +++ b/src/runtime/test_runner/bun_test.rs @@ -777,6 +777,7 @@ impl BunTest { return Ok(()); } + this.on_callback_completed(&refdata.phase); this.add_result(refdata.phase); // `this` borrow ends here (NLL); `run_next_tick` re-derives via `.get()`. Self::run_next_tick(&refdata.buntest_weak, global_this, refdata.phase); @@ -852,7 +853,9 @@ impl BunTest { }; // SAFETY: `&mut` derived via `UnsafeCell`; borrow ends before // `run_next_tick` re-derives. - strong.get().add_result(ref_in.phase); + let this = strong.get(); + this.on_callback_completed(&ref_in.phase); + this.add_result(ref_in.phase); Self::run_next_tick(&ref_in.buntest_weak, global_this, ref_in.phase); Ok(JSValue::UNDEFINED) @@ -916,6 +919,13 @@ impl BunTest { vm.enqueue_task(task); } + /// Call before `add_result` with the completion of a test or hook callback. + pub(crate) fn on_callback_completed(&mut self, data: &RefDataValue) { + if self.phase == Phase::Execution { + self.execution.handle_callback_completed(data); + } + } + pub(crate) fn add_result(&mut self, result: RefDataValue) { let _ = self.result_queue.write_item(result); // OOM/capacity: fire-and-forget } @@ -1943,10 +1953,12 @@ impl ExecutionEntry { entry } + /// `callback_completed`: the callback already finished, so the missing-`done()` hint does not apply. pub(crate) fn evaluate_timeout( &self, sequence: &mut Execution::ExecutionSequence, now: &Timespec, + callback_completed: bool, ) -> bool { if !self.timespec.eql(&Timespec::EPOCH) && self.timespec.order(now) == core::cmp::Ordering::Less { // timed out @@ -1954,13 +1966,14 @@ impl ExecutionEntry { let is_test_entry = sequence .test_entry .is_some_and(|p| core::ptr::eq(p.as_ptr().cast_const(), self)); + let waiting_for_done = self.has_done_parameter && !callback_completed; sequence.result = if is_test_entry { - if self.has_done_parameter { + if waiting_for_done { Execution::Result::FailBecauseTimeoutWithDoneCallback } else { Execution::Result::FailBecauseTimeout } - } else if self.has_done_parameter { + } else if waiting_for_done { Execution::Result::FailBecauseHookTimeoutWithDoneCallback } else { Execution::Result::FailBecauseHookTimeout diff --git a/test/js/bun/test/test-test.test.ts b/test/js/bun/test/test-test.test.ts index 1fad55319b9b..6d98ec1086fd 100644 --- a/test/js/bun/test/test-test.test.ts +++ b/test/js/bun/test/test-test.test.ts @@ -3,7 +3,7 @@ import { spawn, spawnSync } from "bun"; import { afterAll, afterEach, beforeAll, beforeEach, describe, expect, it, test } from "bun:test"; import { copyFileSync, mkdirSync, realpathSync, rmSync, writeFileSync } from "fs"; import { rm, writeFile } from "fs/promises"; -import { bunEnv, bunExe, tempDir, tmpdirSync } from "harness"; +import { bunEnv, bunExe, normalizeBunSnapshot, tempDir, tmpdirSync } from "harness"; import { tmpdir } from "os"; import { dirname, join } from "path"; @@ -554,6 +554,199 @@ it("test timeouts when expected", () => { expect(err).not.toContain("unreachable code"); }); +describe("a test that completes after its timeout has passed is reported as timed out", () => { + // Each body blocks synchronously for longer than its timeout, so the timeout timer cannot fire until the + // callback has already completed, and the verdict has to come from the completion itself. + async function runFixture(name: string, code: string) { + using dir = tempDir("late-timeout-" + name, { + "blocks.test.js": code, + "package.json": "{}", + }); + await using proc = spawn({ + cmd: [bunExe(), "test", "blocks.test.js"], + cwd: String(dir), + stdout: "pipe", + stderr: "pipe", + env: bunEnv, + }); + const [stdout, stderr, exitCode] = await Promise.all([proc.stdout.text(), proc.stderr.text(), proc.exited]); + return { stdout: normalizeBunSnapshot(stdout), stderr: normalizeBunSnapshot(stderr), exitCode }; + } + + test.concurrent("sequential test, Bun.sleepSync after an await", async () => { + const result = await runFixture( + "sequential", + /*js*/ ` + import { test } from "bun:test"; + test("sleeps synchronously after an await", async () => { + await Bun.sleep(1); + Bun.sleepSync(300); + }, 100); + test("next test still runs", async () => { + await Bun.sleep(1); + }); + `, + ); + expect(result).toMatchInlineSnapshot(` + { + "exitCode": 1, + "stderr": + "blocks.test.js: + (fail) sleeps synchronously after an await + ^ this test timed out after 100ms. + (pass) next test still runs + + 1 pass + 1 fail + Ran 2 tests across 1 file." + , + "stdout": "bun test ()", + } + `); + }); + + test.concurrent("concurrent test with a sibling still pending, busy loop after an await", async () => { + const result = await runFixture( + "concurrent-busy-loop", + /*js*/ ` + import { test } from "bun:test"; + test.concurrent("busy loops after an await", async () => { + await Bun.sleep(1); + const start = Date.now(); + while (Date.now() - start < 300) {} + }, 100); + test.concurrent("sibling", async () => { + await Bun.sleep(10); + }, 30_000); + `, + ); + expect(result).toMatchInlineSnapshot(` + { + "exitCode": 1, + "stderr": + "blocks.test.js: + (fail) busy loops after an await + ^ this test timed out after 100ms. + (pass) sibling + + 1 pass + 1 fail + Ran 2 tests across 1 file." + , + "stdout": "bun test ()", + } + `); + }); + + test.concurrent("concurrent test with a sibling still pending, Bun.spawnSync after an await", async () => { + // With a sibling running, spawnSync's wait loop cannot tell whose child it is waiting on and uses + // the sibling's later deadline, so this test's own deadline is only checked once the callback + // completes. + const result = await runFixture( + "concurrent-spawnSync", + /*js*/ ` + import { test } from "bun:test"; + test.concurrent("spawnSync outlives the timeout", async () => { + await Bun.sleep(1); + Bun.spawnSync({ cmd: [process.execPath, "-e", "Bun.sleepSync(300)"] }); + }, 100); + test.concurrent("sibling", async () => { + await Bun.sleep(10); + }, 30_000); + `, + ); + expect(result).toMatchInlineSnapshot(` + { + "exitCode": 1, + "stderr": + "blocks.test.js: + (fail) spawnSync outlives the timeout + ^ this test timed out after 100ms. + (pass) sibling + + 1 pass + 1 fail + Ran 2 tests across 1 file." + , + "stdout": "bun test ()", + } + `); + }); + + test.concurrent("done() called after the timeout has passed", async () => { + // done() was called, so the hint about a missing done() call does not apply to either test. + const result = await runFixture( + "done-callback", + /*js*/ ` + import { test } from "bun:test"; + test("done() from a timer callback", done => { + setTimeout(() => { + Bun.sleepSync(300); + done(); + }, 1); + }, 100); + test("done() synchronously", done => { + Bun.sleepSync(300); + done(); + }, 100); + `, + ); + expect(result).toMatchInlineSnapshot(` + { + "exitCode": 1, + "stderr": + "blocks.test.js: + (fail) done() from a timer callback + ^ this test timed out after 100ms. + (fail) done() synchronously + ^ this test timed out after 100ms. + + 0 pass + 2 fail + Ran 2 tests across 1 file." + , + "stdout": "bun test ()", + } + `); + }); + + test.concurrent("a test that finished in time is not blamed for a sibling blocking afterwards", async () => { + // The first test's completion is queued as soon as it returns, but the runner only processes the queue + // once the sibling, resumed by the microtask the first test queues on its way out, has finished + // blocking. The verdict has to be based on when the completion arrived, not on when it was processed. + const result = await runFixture( + "sibling-blocks-after-completion", + /*js*/ ` + import { test } from "bun:test"; + const { promise: firstReturned, resolve: markFirstReturned } = Promise.withResolvers(); + test.concurrent("finishes within its timeout", async () => { + await Bun.sleep(1); + queueMicrotask(markFirstReturned); + }, 100); + test.concurrent("blocks once the first test has returned", async () => { + await firstReturned; + Bun.sleepSync(300); + }, 30_000); + `, + ); + expect(result).toMatchInlineSnapshot(` + { + "exitCode": 0, + "stderr": + "blocks.test.js: + (pass) finishes within its timeout + (pass) blocks once the first test has returned + + 2 pass + 0 fail + Ran 2 tests across 1 file." + , + "stdout": "bun test ()", + } + `); + }); +}); + test("jest.setTimeout will change default timeout", () => { const path = join(tmp, "jest-setTimeout-test.test.js"); copyFileSync(join(import.meta.dir, "setTimeout-test-fixture.js"), path);