Bun.stdin.stream() loses chunks in async iteration #8695

argosphil · 2024-02-05T17:18:37Z

What version of Bun is running?

1.0.26+c75e768a6

What platform is your computer?

Linux 6.1.31-gentoo-dist x86_64 13th Gen Intel(R) Core(TM) i7-1370P

What steps can reproduce the bug?

In bash, run

seq -f '%4095.4090f' 0 1000 | while read; do sleep .1; echo "$REPLY"; done | tee -a log | strace bun run ./bunbug5.js 2> strace

where bunbug5.js contains this code:

let offset = 0;
for await (let chunk of Bun.stdin.stream()) {
    console.log(offset, [...chunk.slice(0, 8)].map(x => String.fromCharCode(x)).join(""),
		offset / parseFloat([...chunk.slice(0, 8)].map(x => String.fromCharCode(x)).join("")));
    offset += chunk.length;
    Bun.gc(true); // optional, see below
    await new Promise(r => setTimeout(r, 100));
}

What is the expected behavior?

output that looks like this:

0    0.000 NaN
4096    1.000 4096
8192    2.000 4096
12288    3.000 4096
16384    4.000 4096
20480    5.000 4096
24576    6.000 4096
28672    7.000 4096

(that's what I get if I use sleep 1 rather than sleep .1)

What do you see instead?

This output:

0    0.000 NaN
4096    1.000 4096
8192    3.000 2730.6666666666665
12288    4.000 3072
16384    6.000 2730.6666666666665
20480    7.000 2925.714285714286

This indicates that the third 4096-byte line, which starts with " 2.000", has been lost. The same applies to the sixth 4096-byte line, starting with " 5.000". The strace and log outputs indicate that the line has been read by bun:

read(14, "   2.000000000000000000000000000"..., 65536) = 4096
...
ioctl(14, FIONREAD, [0])                = 0
read(14, 0x7fa80a420000, 65536)         = -1 EAGAIN (Resource temporarily unavailable)
...
read(14, "   3.000000000000000000000000000"..., 65536) = 4096
...
write(1, "8192    3.000 2730.6666666666665"..., 33) = 33
...
read(14, "   4.000000000000000000000000000"..., 65536) = 4096

The ioctl-read pair looks odd (we ask whether there's any data to read, there isn't, so we try to read 64KB anyway), and it happens precisely at the points when data is lost.

Additional information

The first part of the pipeline generates lines of precisely 4096 characters; the second part reads those and echoes them back at a rate of one per 100 ms; the third part simply saves the log; the fourth part runs the script and saves its strace.

The script reads a chunk (which happens to be a line), and calculates whether the number of bytes read so far corresponds to 4096 times the number the line begins with. That should always be the case after the first iteration. It then delays for 100 ms, which is how long it will take (approximately) for the next line to arrive.

The call to Bun.gc(true) isn't strictly necessary.

The text was updated successfully, but these errors were encountered:

argosphil · 2024-02-05T17:24:37Z

I'm sorry if it's inconvenient I'm reporting a number of bugs. I'm trying to replace node with bun in a somewhat complex project. What happened was that when I was trying to capture and record a video stream with bun, some data got lost and I ended up with a corrupt stream. My guess was that this was because the output was produced in chunks timed inconveniently for bun, and this bug report seems to provide some evidence for that hypothesis.

Unlike the other bugs, there doesn't seem to be a simple workaround for this one...

The problem is that ready() is sometimes called even when there is no Promise or handler to hand the data to. It's not quite clear to me when that happens. When it does, though, we read data into a buffer and then ignore it. Don't do that.

argosphil · 2024-02-06T19:34:01Z

I've been unable to reproduce this issue after applying this (all code in streams.zig):

argosphil@bf00a60

Once pending.state is used, we should no longer touch the buffer or consume more input. I think that part's uncontroversial. But why does that happen in the first place?

My guess it that it's because readFromJS unconditionally watches the file descriptor, even if it then proceeds to read successfully from it; once more data becomes available, ready is called and will overwrite the data that's already in the buffer.

So I think applying this patch would make the code more robust and avoid the problem for now; however, is readFromJS really supposed to watch an FD in the event of a successful synchronous read?

Under certain circumstances, we would read data from FIFOs without a sensible place to put it, leading to dropped chunks in async iteration over Bun.stdin.stream(). Fixes oven-sh#8695.

This test seems to fail reliably with the current bun release. Uses stderr rather than stdout because bun-debug currently outputs debug information to stdout and I didn't want to filter it. The test simply counts to 20, taking 100 ms for each write, while the reader consumes chunks and takes one second to asynchronously process each one. Due to the timing-sensitive nature of the tested code, it does take 3 seconds to run, which I think is acceptable. Output with current bun release: 490 | let text = ""; 491 | for await (const chunk of producer.stderr) { 492 | text += [...chunk].map(x => String.fromCharCode(x)).join(""); 493 | await new Promise(r => setTimeout(r, 1000)); 494 | } 495 | expect(text).toBe("0\n1\n2\n3\n4\n5\n6\n7\n8\n9\n10\n11\n12\n13\n14\n15\n16\n17\n18\n19\n20\n"); ^ error: expect(received).toBe(expected) Expected: "0\n1\n2\n3\n4\n5\n6\n7\n8\n9\n10\n11\n12\n13\n14\n15\n16\n17\n18\n19\n20\n" Received: "0\n1\n2\n3\n4\n5\n6\n7\n8\n9\n11\n12\n13\n14\n15\n16\n17\n18\n19\n" at .../bun/test/js/bun/io/bun-write.test.js:495:3 (fail) timed output should work [3022.97ms]