Repository navigation
Conversation
A test or hook callback that blocked past its timeout and then threw was reported as timed out when it ended without a yield to the event loop. `test.failing` failed, and JUnit lost the thrown error. `BunTest::run_test_callback` now returns how the callback ended: `Running`, `Returned` or `Failed`. `Failed` is a throw, a rejection, or a test that failed through `done(error)`. `step_sequence_one` checks the deadline only after a callback that returned. A callback that failed still gets the deadline check in two cases: - bun killed a process, or ended a `Bun.spawnSync` wait, because the timeout passed, at or after the deadline of the callback. `Execution.killed_on_timeout_at` records that where `kill_dangling_processes_on_timeout` and `Bun.spawnSync` act. - it is a hook whose error cannot fail the test: the body of a `test.failing` or `test.todo` already failed as expected, or a `node:test` body called `t.skip()`. The timeout is then the only failure.
|
No actionable comments were generated in the recent review. WalkthroughThe test runner now tracks whether callbacks are running, returned, or failed. It uses callback outcomes and timeout-related process-kill timing when evaluating deadlines. Regression tests cover late callbacks and hooks in Bun, Vitest-flavor, and node:test. ChangesTest timeout handling
Possibly related issues
Suggested reviewers: Merge Risk:
|
|
Status Reproduced with this fixture, on a build of main (3bf1a06) and on this branch: import { test } from "bun:test";
test("throws after its timeout", () => {
Bun.sleepSync(200);
throw new Error("own error");
}, 100);
test.failing("test.failing throws after its timeout", () => {
Bun.sleepSync(200);
throw new Error("the expected failure");
}, 100);
CI, build 137324 on d927955 (finished):
PR: #47867 |
…late `done(error)` ends a callback as `Failed` only when the call comes after the deadline of the test. A test that passes an error to `done` in time and then returns after its timeout is a late return: the runner reports the timeout, as it does on main. `DoneCallback.failed_late` replaces `failed_test`. `ExecutionEntry::is_past_deadline` holds the deadline comparison that `evaluate_timeout` had inline.
Problem
test.failingfails, and JUnit loses the thrown error (report, ruling).step_sequence_one(src/runtime/test_runner/Execution.rs) callsevaluate_timeoutafter every callback that ended insiderun_test_callback.Fix
run_test_callbackreturns how the callback ended:Running,ReturnedorFailed. The runner checks the deadline only forReturned.Execution.killed_on_timeout_at). Or a hook fails after atest.failingbody failed as expected.test/js/bun/test/test-test.test.ts,vitest-flavor.test.ts(13 rows equal to Vitest 5.0.5),node-test.test.ts. Also 17 other runner suites.Background
sequence.resultormaybe_skip. Both also drop the timeout of a late return after a stray rejection.Downsides
test.failingwhose body threw (also on main). So a late throw of the body, then a hook error, now passes.Bun.build()past its timeout, then throws, losestimed outif bun killed nothing.BunTestgrows from 440 to 456 bytes per file. Release.textdoes not change.Notes
Rows that change, main (3bf1a06) to this PR. Each callback passes its timeout inside one call and does not yield first.
timed outasynctest rejects afterawait 0, or returns a rejected promisetimed outthengetter throwstimed outdone(error)after the timeout, also from a microtask or anasynccallbacktimed out ... before its done callback was calledasync)done()timed outtest.failingthrowstest.failingwithretrythrowstest.todothrows,--todobeforeAll,beforeEach,afterEach,afterAll,onTestFinished)hook timed outskip()of the test context (vitest)afterEachthrows afterskip()(vitest)aroundEachthrows in set-up or teardownAroundHook...ErrortimeoutaroundEachset-up returns withoutrunTest()test.extendfixture returns withoutuse()hook timed outsignal.abortedafter a throw (vitest)truefalsefalsenode:testbody throwstimed outnode:testexpectFailurebody returnstimed outBun.build()for an async plugin past its timeout, then throws, and bun killed nothingtimed outtest.failingortest.todobody throws, then a hook throws in time or anaroundEachteardown times outtimed outtest.failingwithafterEach)JUnit for the first row:
<failure type="TimeoutError" message="test timed out" />on main,<failure type="Error" message="thrown by the test">with this PR.What follows from a changed result also changes:
retryandrepeatsruns,--bail,onTestFailed, andtask.result.state. Each of these rows prints what the same callback prints when it fails in time.Rows that do not change.
done()timed outexpect.soft()failed, after a stray rejection, or after a matcher that it did not await failedtimed outexpect.soft()afterEachreturns late after a test that threw in timehook timed outdone(error)in time, then a late return, alsotest.failingtimed outtest.failingpassesdone(error)hook timed outafterEachoronTestFinishedthrows after the body of atest.failingortest.todofailed as expected in timehook timed outbun:testhook throws after anode:testbody calledt.skip()hook timed outBun.spawnSyncoutlived the timeout, alsotest.failingandtest.concurrenttimed outBun.spawnSyncitself throws after bun killed its childtimed outBun.build()timed outnode:testbody returnstimed outnode:testexpectFailurebody throwstimed outnode:testt.skip()timed outThe end kind is that of the function the runner calls. For an around set-up, a
test.extendfixture and anode:testtest, that function is a wrapper of bun. When the wrapper throws for a user function that returned (norunTest(), nouse(),expectFailurethat passed, a plan mismatch, at.after()that throws), the end isFailed. When the wrapper accepts a throw and callsdone()(expectFailure), the end isReturned.done(error). It ends the callback asFailedonly when the call comes after the deadline of the test (DoneCallback.failed_late). A test that callsdone(error)in time and returns late is a late return, so the runner reports the timeout, as on main. The first push kept only the error there. Review pointed out that this is a late return, and the second commit restores the timeout.The mark for a killed process.
killed_on_timeout_atis a time. The runner compares it with the deadline of the entry, so a kill for an earlier entry does not count. Two places write it, because two places act:kill_dangling_processes_on_timeout(only in a group with one sequence, when it killed a process) and the wait loop ofBun.spawnSync(it ends its own wait, also in a concurrent group). A mark each time the timer ran was tried first. With it onetest.failingpassed in 11 of 40 runs, by its position in the file.The clause for hooks.
handle_uncaught_exceptionwrites the failure of a hook only overPending. After the body of atest.failingstoredPass, atest.todobody storedTodo, ort.skip()ofnode:teststoredSkip, the error of a hook is printed and the test does not fail. On main the timeout was the only thing that failed such a test when the hook was late.result_survives_hook_errorkeeps that. Delete it when the hook arm is fixed.skip()of a test context hides later errors on purpose, so that case follows the thrown error, as Vitest does.Left alone on purpose.
handle_uncaught_exception. Its fix also changes the row where body and hook both throw in time (pass to fail, Jest fails it).node:test: a latet.skip()ort.todo(), and anexpectFailurebody that throws late, stay timed out. The shim ends those tests withdone().done(error)in a hook is not attributed to the hook on main. It stays "Unhandled error between tests" plus the hook timeout. Abefore()orafter()ofnode:teston a suite or a file is such a hook (bun test: fail the test or hook whose done() received an error #39112).skip()that the test catches, then a late return: timed out, as on main. Vitest 5.0.5 reports skipped.AroundHook...Error. Vitest 5.0.5 passes it.Bun.build()and then throws keeps its error and its child. The same holds for aBun.$child, a process in a concurrent group, and aBun.spawnSyncwhose owntimeoutoption ended the wait first.awaitin a concurrent group,Bun.spawnSyncwatches the latest deadline of the group (get_active_timeout). Bun then kills nothing at the deadline of this test, so a throw after the wait keeps its error. Without theawait, bun kills the child at the deadline of the test and the timeout stands.kill_dangling_processes_on_timeouttreats an entry without a timeout as past its deadline (fix(test): preserve unlimited test children after stale deadlines #44613 fixes that line). The mark that this PR writes there has no effect for such an entry, becauseevaluate_timeoutignores it.Execution::step) has no deadline check on main. That is the second part of bun test: setDefaultTimeout() in a preload applies only to the first file, and a sync block after a timer escapes the timeout #45192, and bun test: time out a test or hook whose callback completes after its deadline #39440 adds the check. A returned thenable that is not a promise ends on that path.Related open PRs. This diff conflicts in source with two open PRs that merge onto main. For each, the PR that lands second has to keep both changes.
src/runtime/api/bun/js_bun_spawn_bindings.rs. Both PRs change one branch of the wait loop inspawn_maybe_sync. That branch runs when aBun.spawnSyncchild outlives the timeout of the test. This PR writeskilled_on_timeout_atthere, and bun test: SIGKILL a spawnSync child that is still running 500 ms after the test's timeout #45792 rewrites those lines.src/runtime/test_runner/Execution.rs. Both PRs rewrite the call ofrun_test_callbackinstep_sequence_one.A local merge of this PR with each open PR that shares a file with it found these two. The heads: main 675ee5b, this PR d927955, #45792 027d3b8, #47731 da299de.
#47730, #47760 and #47800 edit the call in
run_test_callbackwhose result this PR classifies. They merge with this diff without a conflict. #39112 edits lines near this diff and does not merge onto main now. #47760 callsthen()of a returned thenable before the microtask drain, so a thenable that settles at once then reaches this check. This PR has rows for thenables that reject or throw. #38153 (atest.todobody that times out) and #41865 (test.failingand unhandled errors) change how those modes store a result.Measurements (linux-x64, main 3bf1a06 against this change on the same base).
Execution72 to 88, andBunTest, which contains it, 440 to 456.DoneCallback56 to 56, the newCell<bool>is in former padding.ExecutionSequence208 andExecutionEntry144 do not change.CallbackEndis 1 byte and replaces a 40-byteOption<RefDataValue>return.LD_PRELOADclock_gettimecounter, debug builds): one more read for eachdone(error)that fails the running test. The other counts are equal on main and this PR. 250 and 1250 tests that pass: 1080 and 5084 (4.004 per test). 250 and 1250 tests that throw in time: 1081 and 5087 (4.006 per test). 10 and 20 tests whoseBun.spawnSyncchild outlives a 100 ms timeout: 183 and 292 (10.9 per test).llvm-objdump, release,step_sequence): 28 to 31 from the return ofrun_test_callbackto the call ofadvance_sequence, for a callback that returned in time. Function totals:run_test_callback568 to 560,step_sequence1885 to 1908..text(llvm-size -A): 110,642,729 to 110,642,729 bytes. Seven symbols change size, net +95 bytes:Bun__Bindgen__BunTest__bunTestDoneCallback1058 to 1164,BunTest::run12402 to 12310,execution::step_sequence8413 to 8499,TestCommand::run15692 to 15642,Execution::kill_dangling_processes_on_timeout409 to 441,spawn_maybe_sync24184 to 24200,BunTest::run_test_callback2426 to 2423.timed outper fixture, main to this PR: late throws 21 to 0, late returns 16 to 16, killed process 6 to 6, vitest rows 13 to 3,node:test5 to 3. Result lines that change: thetest.failing,test.todoandskip()rows of the first table. No other result line changes.Tests.
test-test.test.ts, three fixtures. "keeps its own result when it threw" (27 tests) fails on main. "is timed out when it returned, or when its error could not fail the test" (16 tests) and "is timed out when bun killed a process for its timeout before it threw" (6 tests) pass on main and with this PR. They fail with a guard onsequence.resultormaybe_skip, without the clause for hooks, without the deadline test fordone(error), or without either write ofkilled_on_timeout_at.vitest-flavor.test.ts: 13 rows withimport from "vitest". The fixture gives the same results on Vitest 5.0.5.node-test.test.ts: five rows fornode:test. The last one fails without theSkiparm of the clause for hooks.t.skip()row, which the clause for hooks now covers, and the around-hook form of the hook bug in Downsides.Suites run on the debug build:
test/js/bun/test/{test-test,vitest-flavor,vitest-apis,expect-deferred,bun_test,done-async,concurrent,concurrent_immediate,test-retry-repeats-basic,test-on-test-finished,failure-skip,jest-hooks,describe,test-failing,test-error-code-done-callback}.test.ts,test/js/node/test_runner/node-test.test.ts,test/cli/test/{bun-test,test-timeout-behavior}.test.ts,test/js/bun/spawn/spawnSync.test.ts,test/regression/issue/23865.test.ts.History. The check after a synchronous completion came with #22928 in 1.2.23: b537fee added it, de90183 removed it, c4d565b restored it. 1.2.22 reports the thrown error. A callback that returns late is timed out on purpose, and stays so.
no test proof · iteration 1 · platform-specific test(s) that do not run on this machine, deferring to CI, which covers all platforms: test/js/bun/test/test-test.test.ts