bun test: report a test that completes after its timeout as timed out

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);

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,24 +1953,27 @@ 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
             // SAFETY: pointer-identity comparison only — no deref, no provenance laundering.
             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

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 <version> (<revision>)",
+      }
+    `);
+  });
+
+  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 <version> (<revision>)",
+      }
+    `);
+  });
+
+  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 <version> (<revision>)",
+      }
+    `);
+  });
+
+  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 <version> (<revision>)",
+      }
+    `);
+  });
+
+  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 <version> (<revision>)",
+      }
+    `);
+  });
+});
+
 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);