console: output goes behind what process.stdout/stderr have buffered, as in Node

DY
11d ago
+207-26

What

console.* writes to fd 1/2 directly. process.stdout / process.stderr buffer whatever a full pipe or socket refuses and write it later from the event loop. The two do not know about each other, so a console.log issued after a process.stdout.write() can land in the middle of it.

In Node the console writes through the stream, so its output queues behind what the stream already holds. This PR does the same: while a stream's sink is backed up, console output for that stream is appended to the sink's buffer. When nothing is buffered, the console writes as it does today.

const K = 256 * 1024;
process.stdout.write(Buffer.alloc(K, "x")); console.log("\nMARK1");
process.stdout.write(Buffer.alloc(K, "y")); console.log("\nMARK2");

Run as ... | (sleep 0.5; cat), runs of a byte collapsed. Linux x64, debug builds, node v26.7.0:

output
main<x*65536> MARK1 <x*65536> MARK2 <x*131072><y*262144>
this PR<x*262144> MARK1 <y*262144> MARK2
node<x*262144> MARK1 <y*262144> MARK2

Same result for process.stderr with console.error, and over a socketpair (Bun.spawn({ stdout: "pipe" })).

How

  • Process keeps the two FileSink wrappers that process.stdout / process.stderr are built on (m_stdioSinks, visited by GC, so no lifetime code). Until a program touches those streams there is no sink.
  • message_with_type_and_level_ asks __bun_stdio_sink_is_backed_up(global, fd) when it picks its writer. If so, the message is formatted into a Vec and, on the way out of the function, __bun_stdio_sink_append adds it to the writer's outgoing buffer. The poll that is already armed for the bytes in that buffer writes it after them.
  • The append makes no syscall, settles nothing and runs no JS, so the sink's state machine, its callbacks and its errors are untouched: the event loop drains and reports exactly as it does on main.
  • Formatting can run user code (inspect.custom), and that code can write until the backlog is gone. Then there is nothing to go behind: the append says so and the message is written directly.
  • A writer whose poll failed to register is closed with bytes left in its buffer; nothing would ever write an appended message, so it does not count as backed up.
  • console.log() with no arguments now prints its newline through the writer the function picked, like every other message, instead of always through the stdout writer.
  • On Windows these sinks are SyncFile (start_sync in Blob::get_writer): every write blocks until it is out, so they are never backed up.

Behaviour

Every row is either what Node does or exactly what main does. Pipe with a reader that starts late, stalls or leaves:

mainthis PRnode
order of write() and console outputinterleavedcall ordercall order
write(big, cb1); console.log(); write("small", cb2)ret2 false, then nextTick, microtask, immediate, timeout, drain, cb1, drain, cb2same as mainas main with one drain
write(big); console.log(); write(big, () => process.exit(0))wrong orderevery byte, in orderevery byte, in order
unref'd timer due while the backlog drainsfiresfiresfires
a signal listener against 'drain' and the callbacksignal, drain, cbsamesame
reader gone, no listener / 'error' listenercb1 EPIPE, (error,) cb2 EPIPEsame as maincb1 EPIPE, cb2 EPIPE, (error)
console.log in 'beforeExit' / 'exit' listeners with a backlogno callback runs inside itsame as mainsame
write(1 MiB); console.log("LAST"); process.exit()truncated, LAST in the middletruncated, LAST losttruncated, LAST lost
console.error() / console.warn() with no argumentsnewline on stdoutnewline on stderrnewline on stderr
  • The last-but-one row is the one place where a program prints less than on main: console output behind a backlog is no longer out when console.log returns, so process.exit() or a crash right after it drops it, as in Node.
  • With a 'SIGPIPE' listener and the reader gone, the listener runs 4 times on main, once here, never in node: the console no longer writes into the broken pipe itself.
  • Also the same output as main: a failing poll registration inside write() (injected epoll_ctl error; the console message is still printed), a one-off injected EPIPE on a sink write, finished(process.stdout), a worker's console.log while the main thread has a backlog, stdout to a file and to a tty.
  • By method, with a backlog on the fd the method prints to: log, info, debug, dir, table, group, trace, warn, error, assert(false, msg) go behind it. count, time* and assert(false) without a message print through other paths and jump ahead, as on main. trace prints on stdout, as on main.
  • Syscall counts for 1000 console.log, with and without process.stdout touched, to a pipe, a file and /dev/null: identical to main.
  • Bun.stdout.writer(), Bun.file(1|2).writer(), Bun.write(Bun.stdout) and console.write have their own sinks, as on main.

Tests

test/js/node/process/process-stdio.test.ts, five tests next to #43868's, using its gated reader (nothing reads the fd until the first write() has returned false, no sleeps). The pipeline tests also assert the writer's own exit status and that it printed nothing else:

  • log / info / debug / log() on a stdout pipe; warn / error / error() on a stderr pipe; stdout on a socketpair. Fail on main with the interleaving above.
  • write(big); console.log(); write(big, () => process.exit(0)) delivers every byte in order. Fails on main.
  • A message whose inspect.custom writes until the backlog is gone is still printed. Passes on main; it covers the direct write when there is nothing left to go behind.

test/js/web/console/console-log.test.ts: console.error() and console.warn() with no arguments print their newline on stderr. Fails on main.