node:test run(): report child events in byte frames that printed text cannot produce
Problem
run()fromnode:testbelieves a string that a test prints. A logged line forgestest:pass,test:fail, or anendthat lets a script exit 0 over a failing test.handleStdoutLine(src/js/node/test.ts:512, from #34444) searched decoded stdout for\0bun:test:run\0and emitted anytype.
Fix
- Each event is a byte frame:
0xFF,bun:test:run, length, JSON,0xFE. The parent finds it in raw stdout bytes. No UTF-8 text write emits either byte. - The parent accepts only
test:passandtest:fail. - A frame that another writer cut is text, and its file fails. On main that cut read as a pass in 18 of 20 runs.
- Verified:
node-test-run.test.ts(76 tests, 75 fail on 1.4.3) andnode-test-run-output.test.ts(also passes on node v26.3.0). Self-reviewed: 38 concerns raised, 32 addressed, 6 moved to the native follow-up.
Background
run()startsbun test <file>per file, and the child reports on stdout. It reports only whenrun()setBUN_NODE_TEST_RUN_FRAMES, not under everyNODE_TEST_CONTEXT.- Considered a token (still a text search) and fd 3 or IPC (up to 74 of 300 verdicts arrive before their test's line). The first comment asks the maintainers.
Downsides
- A verdict that another writer cuts is lost. Its file fails, also when every test passed.
process.exitCodereads 1 in arun()child after a failure.stream.republish()(bun-only, undocumented) is removed. Frame bytes that a test writes are believed, as on node.- Builtin JS +7,984 bytes, parent decode 3.2 µs against 2.2 µs per event, one more env entry per child. Nothing new outside
run().
Notes
Reach. run() arrived in #34444 and few scripts call it yet. The case for the change is runner integrity before #34515 builds the --test CLI on the same channel. The hole was raised in review on #34444 and left for a follow-up.
Repro. The script from the report: a test logs a string read from a fixture file, the next test fails, a CI script counts test:fail.
- main: forged events in 4 of 4 cases, exit 0 over a failing test in 1 of 2.
- this branch: 0 of 4 and 0 of 2. node v26.3.0: 0 and 0.
Wire. A frame is 0xFF, bun:test:run, the payload length as a big-endian u32, the UTF-8 JSON of { type, data }, 0xFE. The parent takes a frame only when the end byte stands where the length says and no 0xFF is inside. The lead is not node's 0xFF 0x0F, so a node parent does not hand one of these frames to its V8 deserializer. A payload over 64 MiB (the bound of a bun test --parallel frame) is not a frame.
Which writes can start or end a frame. I ran 27 string-write forms on bun 1.4.3 and node v26.3.0. Every write that uses the default encoding emits UTF-8 and never 0xFF or 0xFE: console.*, process.stdout.write(s), fs.writeSync(1, s), fs.writeFileSync(1, s), Bun.write(Bun.stdout, s), a child's text on inherited stdout. A lone surrogate goes out as EF BF BD. The two bytes come out only when the call names a byte encoding (latin1, utf16le, hex, base64) or passes a Buffer. The tests print the frame as a one-byte string, where ÿ and þ are the characters 0xFF and 0xFE.
The child. It builds the frame in JS and writes it with the sink of process.stdout, the queue the text marker also went through. So order against process.stdout output is as on main.
- The writer takes each builtin it calls when
node:testloads in arun()child:JSON.stringify,Error.isError,TextEncoder.prototype.encode,Uint8Array.prototype.set,Array.prototype.slice,Object.setPrototypeOf,fs.writeSync,console.error. A file that removes or replaces them later still reports. So does a file that adds atoJSONto every object. Nothing that the writer throws reaches the test it reports. - An error that the child cannot read (
throw Object.create(null)), that JSON cannot hold (code: 1n), or that is over 64 MiB is replaced by a stand-in error. AnexpectFailurelabel that JSON cannot hold becomestrue. A label that JSON can hold stays when only the error is replaced. The verdict still arrives. Before, thecatch {}aroundJSON.stringifydropped the whole event. - The child sets
process.exitCodeto 1 when it reports a failure that is not a todo or a skip. So a file whose process exits with no code, while the frame is still queued, is a file that failed. - A verdict that cannot be written (the sink throws, the name has no JSON form) is named once on stderr.
- When
process.stdoutis not the stdio stream of fd 1 (the file replaced it, also withprocess.stderr), the frame goes to fd 1 withfs.writeSync. The loop waits and writes again onEAGAIN, so a large frame goes out whole. On main the replacement swallowed every verdict.
A cut frame. A frame larger than one socket chunk (36,544 bytes on this kernel) takes more than one send. A console.log of the same process, or another process or thread on the same stdout, can land between them. On main that text could finish the JSON of the result as a pass. Here a cut frame is text, the decoder counts it, and the file fails with N test result(s) of this file did not arrive: another writer of its stdout printed inside the result, or its process ended while writing it (exit code 0). The stderr of the file is the cause.
The decoder knows a frame from its first five bytes, the lead byte and bun:. A start that no whole frame follows is one lost verdict: other bytes in the tag or in the length, a length over the bound, a stream that ends inside the header. A lead byte with fewer tag bytes stays text, because a test that prints binary data emits lone 0xFF bytes.
Measurements. Release builds of the merge base and of the first push (bdaf3b6c6d), Linux x64. Later pushes changed only builtin JS, and the builtin JS line is from the current commit. strace, perf, valgrind and bloaty are not installed in the container. Syscall counts come from a small ptrace counter. Time is wall clock, interleaved.
- Builtin JS, release bundle of the current commit:
node:test64,409 to 63,044 bytes (-1,365). The new module is 9,225 bytes.internal-for-testing+124. All modules: 2,553,893 to 2,561,877 (+7,984). - Release binary at the first push, when the builtin JS delta was +7,297: 89,318,984 to 89,327,176 bytes (+8,192).
sizetext +7,404, data +0, bss +0. No native code changed, no host function added. require("node:test")outsiderun(): 1,569 and 1,568 Function cells. Pertest(): 19.5 cells to register and 34.5 to run on both.run()child, 1,000 tests: 1 write per event on both, through the sink. 140,953 and 143,690 bytes of stdout, +3 per event.- Parent decode, 10,000 events and 10,000 lines in 64 KiB slices: 3.2 µs against 2.2 µs per event and line (medians of 40 interleaved rounds, run twice, ranges 2.0 to 3.9 and 1.4 to 2.8). 10.1 against 11.0 heap cells.
- Output before verdict, 300 tests that each
console.logone line, 10 runs: 0 of 300 verdicts arrive before their test's line, on both. - A timer in the same process prints
"}},"type":"test:pass"}and 1 MiB of spaces while a 400 KB failing verdict is on its way, 20 runs. main: a pass in 18, the failure in 2. Branch: a pass in 0, the failure in 5, lost in 15. - An inherited child prints that string every millisecond, 20 runs. main: a pass in 3, the failure in 4, lost in 13. Branch: a pass in 0, the failure in 4, lost in 16.
- A 400 KB failing verdict with
console.logoutput around it, 150 runs: the verdict is lost in 141 on main and in 130 on the branch. Each loss fails the file on both. The branch names the cause. after(() => process.exit())and a failing test with a 4 MiB error, 20 runs: main and node report the file as passed in 20. The branch reports it as failed in 20.- A failing test behind 1 MiB of
process.stdoutoutput, thenprocess.exit(), 20 runs. The file is reported as passed in 9 on a release build of main, in 15 on 1.4.3, and in 20 on node. On the current commit (debug build) it is passed in 0: the failure of the test arrives in 7, and the file fails in 13. - A file of 20 passing tests that each write 1 MiB through
process.stdoutand callconsole.log: 0 false failures in 1,400 runs on the branch. main dropped one pass verdict without notice in 1 of 1,000 runs. - A second descriptor: a child prints 300 lines on stdout and writes a verdict to fd 3 after each. The parent sees 0 to 74 verdicts before their line (20 runs).
Deliberate differences from node.
- The parent accepts two event types and checks their shape. node republishes the
typea frame names (runner.js#L321). - A frame that is not one the child writes becomes
test:stdouttext. node throws from its deserializer. - Frames do not pass through
process.stdout.write. A file that replaces it, or that callsprocess.stdout.end(), still reports its tests. On node and on main such a file fails. - A reported failure makes the exit code of the file 1, also when the file calls
process.exit()with no code after it. node reports such a file as passed. - Text that a test left on an open line keeps its trailing spaces when a verdict closes the line. main trimmed them. A byte order mark stays in the text, as on node. main dropped the first one.
Kept as on node. A test file that starts another node:test file on its inherited stdout gets the results of that file counted as its own. I ran it on node v26.3.0: the outer file reports pass nested passes and fail nested fails, and counts 3 tests. bun 1.4.3 does the same with the text marker. If the child removed the env entry, a failing nested file would no longer reach run().
What is left.
- A test that writes a complete frame as bytes is believed, as on node. No tracker exists yet.
- A verdict that is cut is lost, as on node. The file fails and says why. A large verdict is still cut by a
console.logof its own process (130 of 150 above), because the frame waits in theprocess.stdoutqueue whileconsole.*writes fd 1 directly. The native writer below closes that. - A cut inside the first four bytes of a frame is not counted, because a lone
0xFFis also what binary output looks like. Then only the exit code can fail the file. process.exit(0)drops whatprocess.stdouthas queued, as on node. A failing verdict that is still in the queue is lost with it, and the explicit 0 lets the file be reported as passed. #44465 decides the exit code of a file that callsprocess.exit()after a failure.- A healthy file fails when a
console.logof its own lands inside a queued pass verdict. I did not see it in 1,400 runs. main drops such a verdict without notice. - A
run()child still createsprocess.stdoutat its first verdict, as on main. That putsO_NONBLOCKon the stdout it shares with processes it started earlier.
Not in this PR: the native writer. The branch robobun/8b035eac/node-test-run-whole-frames has a host function that writes a frame whole, as console.log writes, after it drains what process.stdout has queued (FileSink::drain_sync, 148 native lines). With it the 400 KB verdict is lost in 0 of 150 runs, and after(() => process.exit()) loses no verdict. It is a separate change for the stdio owners: it blocks on the queue that #43868 keeps asynchronous, and #37128 has a drain_sync of its own. I will open it as a second PR if that direction is wanted.
For #34515. It reads the child's stdout as text and adds child event types. After this PR it has to feed bytes to createRunOutputDecoder and add each new type, with its shape, to decodeRunEvent and to the RunEvent union.
Also fixed. rebuildError called Error(message) with the message the child sent. A test that fails with an error whose message is an object with no string form destroyed the parent's stream (TypeError: No default value). A character that the bytes before a verdict left unfinished is now closed there as U+FFFD and not joined with the bytes after the verdict.
Tests.
node-test-run.test.ts,frames: 61 byte-level tests of the decoder. Each input is fed whole and in reads of 1, 2, 7, 17 and 64 bytes.node-test-run.test.ts,events: 15 runs throughrun()or abun testchild. One reads the child's raw bytes by hand and checks them against the decoder. One replaces the builtins that a reporter could call. That one passes on 1.4.3, and the other 75 tests of the file fail there. Debug and ASAN builds skip the error over 64 MiB.node-test-run-output.test.ts: fournode:testtests of what a script sees when a file prints result-like text. The same file passes on node v26.3.0 (ℹ tests 4 ℹ pass 4 ℹ fail 0) and on this branch (5 pass 0 fail, the fifth runs the file on node). On 1.4.3 the four fail. The file asserts only what both runtimes do. Not asserted, because they differ today: node reportstest:stdoutin the chunks it reads and bun per line, node can report a result after later output, node's tests are at nesting 0 and bun's at 1 (#39284), and node wraps the error inERR_TEST_FAILURE.- The fixtures of that file keep the result on node stable. node v26.3.0 decides if the file itself failed when its process exits (
runner.js#L582). At that time it can have results unread behind text that followed a result (#L356). A parent that reads late then reports a file with a failed test as failed too. So the fixture that prints from a child process has only passing tests, and that child prints in one write. With a parent that is busy 150 of every 160 ms, the earlier fixture failed on node in 25 of 45 runs. The current fixtures fail in 0 of 45. - Each
run()test starts abun testchild. On a debug build one such test takes 3 to 8 s in this container, and a localbun bd testhas a 5 s default. So the tests of both files pass a 60 s timeout on debug and ASAN builds only. Release builds keep the timeout of the runner.node-test.test.tspasses with--timeout 120000(45 of 45). - The codec is a lazily required internal module and not top-level code in
test.ts, so thatnode:testloads nothing new outsiderun()and the tests can feed the decoder chosen read boundaries.
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/node/test_runner/node-test-run.test.ts