skip to content

A Ruby worker's puts lines reach the container log late and out of order with its warn lines, though the terminal looked fine; why, and how do you fix it?

level: seniorimportance: should knowfreq 38%

answer

  1. terminal vs pipe
  2. STDOUT buffered, STDERR sync
  3. $stdout.sync = true
  4. flush vs fsync
  5. exit! skips the flush

basics

~20 s

When standard output is a pipe or file, Ruby buffers STDOUT internally, while STDERR is always synchronous, so warn lines overtake puts lines. Set $stdout.sync = true at boot, or call $stdout.flush where output must appear.

solid answer

~40 s

CRuby opens `STDERR` in **sync mode** and `STDOUT` without it. When descriptor 1 is a terminal, every write is still pushed straight to the operating system, so everything looks immediate. In a container the output goes to a **pipe**, and Ruby keeps `puts` output in an internal write buffer until it fills (the minimum is 8 KiB), an explicit `flush`, or a normal exit, while `warn` output on `STDERR` goes out at once. The log collector therefore receives warnings before the lines that preceded them, and a quiet worker's lines may sit in the buffer for minutes. The fix is `$stdout.sync = true` early in boot, which costs a system call per write, or `$stdout.flush` at points that matter. A process killed with SIGKILL, or one that calls `exit!`, loses whatever is still buffered.

code

ruby · 10 lines
ruby
# bin/worker, first lines of the entry point
$stdout.sync = true   # STDERR is already sync; make STDOUT match

loop do
  job = queue.pop
  puts "processing #{job.id}"
  job.run
rescue => e
  warn "retrying #{job.id}: #{e.message}"
end

go deeper

for a junior

Recall that $stdout.sync = true and $stdout.flush make output appear immediately, and that STDERR is not buffered.

for a middle

Explain why a terminal hides the problem: writes to a terminal are pushed at once, writes to a pipe wait in Ruby's buffer.

for a senior

Diagnose reordered or missing container logs to STDOUT buffering, fix it at boot, and know when exit! or SIGKILL loses buffered lines.

for a principal

Standardise how services emit logs, one stream with sync on or a structured logger, so ordering and loss are not left to each entry point.

## Two layers of buffering Bytes written by Ruby pass through two buffers before anything reads them: 1. **Ruby's own write buffer** inside the `IO` object. `puts` appends to it, and Ruby makes a `write` system call when it decides to flush. 2. **The operating system**: after the system call the data sits in the kernel's pipe buffer or page cache, where a reader on the other end of a pipe can already see it. Log ordering problems come from the first layer. The second only matters for durability on disk, which is what `fsync` addresses. ## How CRuby configures the three streams | Stream | Sync mode at start-up | When fd is a terminal | When fd is a pipe or file | |---|---|---|---| | `STDOUT` | off | each write is flushed at once | buffered until full, flushed or closed | | `STDERR` | **on** | written at once | written at once | | `STDIN` | not applicable | | | In `io.c`, `STDERR` is prepared with the sync flag, and a write is pushed to the operating system immediately whenever the stream is in sync mode **or** is attached to a terminal. `STDOUT` gets neither when it is redirected, so its writes accumulate in a buffer that starts at 8 KiB. That is why a developer running the worker in a terminal sees correct, immediate output, and the same code under a container runtime, a process supervisor or `ruby worker.rb | tee log` does not. ## The symptoms - **Out of order**: `puts "processing job 7"` goes into the buffer, `warn "retrying job 7"` goes out immediately, and the collector records the warning first. - **Late**: a worker that prints a line a minute takes a long time to fill 8 KiB, so the log looks frozen although the process is healthy. - **Lost**: buffered bytes are written by a normal exit, including `exit` and an unhandled exception, but not by `exit!`, which ends the process immediately, and not when the process is killed with SIGKILL, for example by an out-of-memory killer or a forced stop. - **Prompts that never show**: `print "Continue? "` without a newline sits in the buffer when stdout is a pipe, so a program driving the script never sees the prompt. ## Fixes - **`$stdout.sync = true`** once, early in boot. Every later write on that stream becomes a system call, so ordering and timeliness match the terminal. The cost is one `write` per `puts`, which is negligible for log-rate output and measurable for tight loops that print megabytes. - **`$stdout.flush`** at meaningful points, such as after a prompt or at the end of each job, when you want buffering for throughput but visibility at checkpoints. - **One stream for logs**: sending both informational and warning lines to the same stream (a logger writing to `$stdout`, with sync on) removes the cross-stream ordering problem entirely. Put the setting at the top of the entry point, before any library has a chance to print, so the whole run behaves the same way. ## `flush` versus `fsync` | Method | What it does | |---|---| | `IO#flush` | moves Ruby's internal buffer into the operating system with a `write` call | | `IO#sync = true` | makes every later write do that automatically | | `IO#fsync` | flushes, then asks the operating system to commit the file's data to the storage device | For a pipe to a log collector, `flush` or `sync` is all you need: once the bytes are in the kernel, the reader can see them. `fsync` is for files whose contents must survive a power loss, and it is much slower. ## Related details - `Process.fork` and `Kernel#fork` flush the current `$stdout` and `$stderr` before forking, so a child does not inherit and later re-emit the parent's pending output. - The write end of `IO.pipe` starts in sync mode. - A `StringIO` reports `sync` as always `true`, because it has no buffer between the object and its string.

  • Why does a prompt printed with print not appear when the script's output is piped?
    `print "Continue? "` writes into STDOUT's internal buffer, and with a pipe as descriptor 1 Ruby does not flush on each write. Nothing reaches the reader until the buffer fills or the process exits. Calling `$stdout.flush` right after the prompt, or setting `$stdout.sync = true`, makes it visible.
  • What does sync = true cost, and when would you avoid it?
    Every write becomes a `write` system call instead of an append to an in-process buffer. For log lines that is negligible; for a batch job that prints millions of short lines to a file it can slow output noticeably. There you keep buffering and flush at checkpoints.
  • Why does fork flush the standard streams first?
    A forked child gets a copy of the parent's memory, including any unwritten buffer. If Ruby did not flush `STDOUT` and `STDERR` before forking, both processes would later write the same pending bytes, and the log would show those lines twice.

Buffered stdout is a waiter who collects orders on a pad and walks to the kitchen when the pad is full; stderr is a waiter who runs each order over as it comes, so the kitchen sees the later orders first.

saying these in an interview costs you the question

  • STDOUT and STDERR buffer output the same way
  • Output is buffered only when writing to a file on disk
  • Calling fsync is needed so a log collector sees the lines
  • Ruby flushes STDOUT after every newline even when it is a pipe
  • Buffered output is always written out, even on exit!