PipeReader: do not read again after a failed read
Problem
spawn-stdio-syscall-error.test.tsfails with"lost": -78925in 95 of the last 400 CI builds, all on Alpine.- After a
recv()on a child's stdout fails, bun callsrecv()again. The later bytes come out as'data'before'error'. - Cause:
read_loop(src/io/PipeReader.rs) delivers the bytes it holds before it reports a failed read. The consumer pulls again during that delivery.
Fix
read_oncesets a new flag,READ_FAILED.begin_readtests it withIS_PAUSED, soread,read_intoandon_polldo nothing until the parent callsstart(). The frame that saw the failure still reports the error once.- Verified:
spawn-stdio-syscall-error.test.ts, four new tests countrecv()calls after the failure. Three fail on main, all pass here. Other suites: Notes. - Self-reviewed: 13 concerns raised, 10 addressed. Kept: the
KEEP_ALIVErenumbering (one aarch64 immediate), no test for thestart()reset, the tests' timing precondition (Notes).
Background
PosixBufferedReaderreads pipes and sockets for 14 parents (streams, subprocess stdio, the shell). A streaming parent runs JS insideon_read_chunk, and that JS can pull again.- Considered closing the reader before the delivery, as for EOF: the nested pull reports a clean EOF. Considered a guard in
native-readable.ts:Bun.spawnstreams keep the bug.
Downsides
- One more instruction per read entry on aarch64, and one per loop pass on x64.
.textgrows 512 bytes. - After a read error,
bun run --filterno longer drains that pipe at exit. No other parent reads after an error (Notes).
Notes
CI data. Buildkite annotations of the 400 finished builds #119336 to #120061: the test "node:child_process: stdout delivers every byte read before the error" is in a flaky-new annotation on 95 builds (Alpine 3.23 x64 98 entries, aarch64 42), and on 23 of the last 50. It started with the build of #43739, which added the test. Every lost value is a negative multiple of 1025. busybox head -c writes 1025-byte chunks, so several small recv() calls fill one pass of the loop and the injected 6th call lands inside it. GNU head fills the pass with one recv(), so the glibc lanes do not see it.
Repro without Alpine. A writer that writes 1025-byte chunks (8 MB) with the test's shim and SPAWN_FAULT_RECV_AT=6. A shim that logs each call shows the two cases:
good: recv#2..#5 return bytes, recv#6 len=65536 (a JS pull, read_into) -> EIO, fd closed, no later recv
bad: recv#2..#5 len=262144, 247794, 219094, 189369 (one pass), recv#6 len=153494 -> EIO
recv#7 len=65536 -> 65536 bytes, recv#8 ... (reads go on)
The existing lost: 0 assertion with that writer, 50 runs each on debug builds: main fails 22 (up to 91 recv() calls after the failed one), this PR fails 0 and makes 0 calls after the failure.
New tests. The shim gets SPAWN_FAULT_RECV_MID_FILL=1 (the recv() that directly follows a recv() that returned bytes fails) and SPAWN_FAULT_READS_AFTER=path (how many recv() calls came after the failure). The writer is sh -c 'read go; printf hello; read done'. The parent sends go from setImmediate, when its first read is parked, so the bytes arrive through the poll and the failure is in the same pass.
| test | main | this PR |
|---|---|---|
node:child_process: 'data', then 'error' | fails, 1 recv() after the failure | passes |
node:child_process: destroy() in that 'data' listener leaves only 'close' | passes | passes |
| Bun.spawn: the chunk, then the read rejects | fails, 1 | passes |
Bun.spawn: cancel() after that chunk resolves | fails, 1 | passes |
The destroy() and cancel() cases close the reader inside the delivery. They run the branch that skips the error report for a reader that is already done. That branch tests is_done(), so a parent that tears the reader down with deinit() inside the delivery gets no report either. No parent does that today, so no test covers it. 20 runs of each fixture outside the test runner: 1 call after the failure on main, 0 here, every run. The existing flaky test and its fixture are unchanged.
Failure path, BUN_DEBUG_FileReader=1. Same lines on main and on this PR: onReadChunk() = 5 (progress), onPull(65531) = 0, onPull(65531) = pending, then the rejection. On main the = 0 pull is a real recv() that returns EAGAIN. Here it stops at the gate.
Costs, measured. Release builds (bun run build:release) of main 73df7bb270 and of this PR, linux-x64. The aarch64 rows are from cargo rustc -p bun_io --release --target aarch64-unknown-linux-gnu -- --emit=asm, which is the crate alone and not the linked binary.
| what | main | PR |
|---|---|---|
.text (llvm-size -A, bun and bun-profile) | 58,154,396 | 58,154,908 (+512) |
file size of the stripped bun | 80,844,320 | 80,844,320 |
reader symbols (llvm-nm -S) | +178 bytes: read_loop +158, start +16, two callers with start inlined +6 each, read -3, read_once -5. 0 new symbols | |
x64 gate in read, read_into | testl $0x200 | testl $0x600, +0 instructions |
x64 read_loop check after a delivery | testb $0x31, 0x58(%rsi) | movzwl 0x58(%r10), %ecx and testl $0x431, %ecx, +1 per pass |
x64 start | 57 instructions | 59 |
aarch64 gate in read, read_into, on_poll | tbnz w8, #9 | tst w8, #0x600 and a branch, +1 |
aarch64 read_loop check after a delivery | mov w9, #49 and tst w8, w9 | mov w9, #1073 and tst w8, w9, +0 |
size_of::<PosixBufferedReader>() (-Zprint-type-sizes) | 96 | 96 |
lock-step stream, 1000 chunks of 4096 bytes, recv() calls (LD_PRELOAD counter, 3 runs each) | child_process 3000, Bun.spawn 3003 | 3000, 3003 |
same, libc epoll_ctl calls | 2 | 2 |
2 GiB through child.stdout 'data', 8 interleaved rounds | mean 1195 MiB/s (962 to 1440) | mean 1209 MiB/s (986 to 1417) |
strace, perf, valgrind and bloaty are not installed in the container that ran this. The syscall counts come from an LD_PRELOAD counter that interposes recv and epoll_ctl. There are no perf stat instruction counts.
Audit of the parents. All 14 on_reader_error implementations and every external read(), read_into(), watch(), start() call were read. After an error FileReader, SubprocessPipeReader, Terminal and FileResponseStream close the reader. The install, cron, multi_run and test-worker parents only count the fd as finished. multi_run.rs drains at exit only when ended is not set, and its on_reader_error sets it, so it never read after an error. The lifecycle script and git runners replace the reader before the next spawn. The shell IOReader is the one parent that can start the same reader again, through start(), which clears the flag. It calls start() only when the poll is not registered. After a failure in a poll-driven read the fired poll still counts as registered, so a later reader of the shell's stdin waits. main has the same hang, because nothing arms the poll again after an error. I did not reproduce it, and this PR does not fix it. A fix that restarts the reader must go through start(). filter_run.rs (drain_and_close_pipes) reads again on process exit after an error. On main that read can report the same fd twice and can pick up bytes that arrived after the failure. With the flag it is a no-op, and deinit() follows. The flag is set only in read_once, so a failed poll registration, which FileResponseStream answers with a second read(), is unchanged.
Self-review, the 3 concerns that did not change the diff.
KEEP_ALIVEmoves from bit 10 to bit 11. Nothing depends on its value. It keepsIS_PAUSED | READ_FAILEDone contiguous mask, which aarch64 encodes in thetstitself. With bits 9 and 11 the gate needs one moremov.- No test restarts a failed reader through
start(). Only the shell's shared stdin reader can do that, and a test needs a failed read on the shell's own stdin. - The new tests need the first bytes to arrive through the poll, not through a pull. If that ever changes, the tests pass on a broken build too: they can miss the bug, they cannot fail without it.
The concerns that changed the diff: an unreachable READ_FAILED test in try_register_poll (removed), no check in from() for a failed reader (a debug_assert! now), the gate's contract was not written down (doc on begin_read), no coverage for a consumer that stops inside the delivery (two tests), a mask constant named like the done() method (removed), a duplicated mask (one use now), a 300-character doc line (one short line now), the --filter drain (in Downsides), test titles that claimed an order the fixture did not record (the events now hold 'data' and the chunk), and a constant name in the test.
After review. The error report is now skipped for every done state (is_done()), not only IS_DONE: a reader torn down with deinit() sets CLOSED_WITHOUT_REPORTING only. The comments on the flag are cut to one line.
Suites run on the debug build with the fix. spawn-stdio-syscall-error.test.ts (17 pass, 8 runs in a row), spawn-streaming-stdout.test.ts, spawn-maxbuf.test.ts (16), spawn-stdin-readable-stream.test.ts (37), spawn.test.ts -t stdout (25), child-process-stdio.test.js (9), process-stdin.test.ts (22), body-clone.test.ts (85), node-stream.test.js (112), bunshell.test.ts (436), filter-workspace.test.ts (89). cargo check -p bun_io for aarch64-apple-darwin, x86_64-pc-windows-msvc, x86_64-unknown-freebsd and aarch64-unknown-linux-musl. On an earlier revision of this diff child_process.test.ts gave 81 pass and 2 fail ("should allow us to spawn in the default shell", "extra stdio pipes are not double-closed on GC"). The same 2 fail on a debug build of main in the same container.
Load. With the default 5 s test timeout and three copies of the file running at once on the debug build, tests of this file time out, the existing node:child_process ones too. No run showed a wrong value. CI runs the file in the parallel batch with a 90 s test timeout (270 s on the ASAN lane, scripts/runner.node.ts).
Not covered. macOS and FreeBSD use the same reader, but the tests need LD_PRELOAD and run on Linux only. The Windows reader is completion based and has no pass that holds bytes when a read fails.
no test proof · iteration 0 · platform-specific test(s) that do not run on this machine, deferring to CI, which covers all platforms: test/js/bun/spawn/spawn-stdio-syscall-error.test.ts