Logs are torn / interleaved on stdout

[Markuu-s]

Add a description

Logs are torn / interleaved on stdout

Summary

Lines in the JSON log stream get split mid-record. Fragments of one log entry appear after another full entry, breaking the one-record-per-line invariant.

The problem reproduces both when stdout (maybe in file too, I did not check it)

Minimal mental model

Two threads writing to one shared stream concurrently - that is already enough:

void f() { std::cout << "Hello"; }

std::thread t1(f);
std::thread t2(f);

Even with this trivial body the output is not guaranteed to be "HelloHello" arriving as two clean writes.

A userver service is exactly this picture, just with more writers and longer records:

• userver's own default and service loggers are two writers into the same @stdout fd;
• request handlers run on multiple coroutines / OS threads;

Evidence

output.log line 65 (collected from the service's stdout):

{"asctime":"2026-04-27 22:33:05,054410","level":"INFO","module":"HandleRequestThrow ( src/service.cpp:123 ) ",..."x-request-id":"e5b846b3-be37-4f56-b9ef-708c42328978","x-session-id":"","x-user-id":""}
{"asctime":"2026-04-27 22:33:05,054590", ... }
{"asctime":"2026-04-27 22:33:05,054662", ... }
28978","x-session-id":"","x-user-id":""}        <-- orphan tail

The orphan tail 28978","x-session-id":"","x-user-id":""} is the suffix of an x-request-id value (...28978) of another concurrent log record whose head was emitted somewhere else (or lost in the interleave). The tearing is structural, not a parsing artefact.

Environment

• Static config:

logging:
  fs-task-processor: fs-task-processor
  loggers:
    default:
      file_path: '@stdout'
      format: 'json'
      level: debug
      overflow_behavior: discard
    service:
      file_path: '@stdout'
      format: json
      level: info
      overflow_behavior: discard

Two named loggers, both writing JSON to the same file descriptor (@stdout).

Root cause

1. write(2) is not atomic past PIPE_BUF (4096 bytes on Linux).
   JSON records carry full request context (x-request-id, trace_id, span_id, link, text, etc.). With stack traces or large text fields, a record routinely exceeds 4 KiB. As soon as that happens, the kernel splits the write, and a write from another thread can land between the halves.

2. stdout is block-buffered when not a TTY.
   In a container or behind a pipe, glibc buffers stdout in 4-64 KiB chunks. Concurrent flushes from multiple writers come out as interleaved blocks rather than line-by-line.

Expected behaviour

Each emitted log record appears on its own line, in full, with no fragments from other records inside it. Required for any structured-log pipeline.

Workarounds

Possible mitigations without waiting for a proper fix - runtime log-level control: https://userver.tech/d1/de2/md_en_2userver_2log__level__running__service.html#autotoc_md740