Repository navigation
relay: error paths log to line-buffered stdout, the same blocking shape as the removed println! #946
Description
What
The relay's error paths write to line-buffered, globally locked stdout. That is the same blocking shape as the println! removed from subscribe.rs in the job-008 rework — where an undrained stdout pipe turned a 4,000-event REQ into 1 frame in 44.6 s, and closing the pipe mid-read panicked the read task while the socket stayed open.
Found while reviewing that removal (round 4 of the job-008 factory run), not caused by it: nostreamd/src/telemetry.rs is unchanged from the rewrite base 471d439.
Evidence
nostreamd/src/telemetry.rs:40 installs the subscriber:
tracing_subscriber::fmt().with_env_filter(..).with_target(false).try_init()No .with_writer() anywhere in crates/*/src, so the fmt layer's default writer applies — io::stdout() (tracing-subscriber 0.3.23, fmt/fmt_layer.rs:749). std::io::Stdout is line-buffered, so every enabled event is a write syscall taken under stdout's global lock.
telemetry is a public module of the daemon library (nostreamd/src/lib.rs:32), so the daemon has two library-position stdout writers, not one. nostreamd/src/settings_gate.rs:8-9 claiming to be "the workspace's one library-position writer" is false; telemetry.rs:1 says "a tracing subscriber to stdout" in its own header.
Where it lands on a hot path
At the default info filter, warn!/error! are enabled, and these fire per unit of work:
| Site | Frequency |
|---|---|
nostream-relay/src/relay.rs:415 (message limiter unavailable) |
per message while the limiter store errors |
nostream-relay/src/relay.rs:344 (lagged broadcast batch) |
per lagged batch |
nostream-relay/src/handlers/event.rs (store failures) |
per event |
The success path emits nothing, so there is no cost in normal operation — this is a failure-mode hazard, not a steady-state one.
Why it is worth fixing anyway
The failure mode compounds. A store fault (the very thing these lines report) is exactly when the message rate rises, so the relay logs hardest when it is least healthy, and a slow or absent stdout consumer back-pressures every connection through one global lock. A relay is expected to keep serving while its dependencies misbehave.
What is measured and what is not
- Measured: the
println!path, on this branch — 4,000/4,000 frames in 0.14 s with stdout drained; 1/4,000 in 44.6 s with stdout unread; a panic on broken pipe. - Not measured: the same experiment through the tracing path. The mechanism is identical (line-buffered
Stdoutunder a global lock), but nobody has produced the number forwarn!, and this issue does not claim one.
Suggested direction
A non-blocking writer (tracing_appender::non_blocking) or an explicitly buffered writer, so a stalled stdout consumer cannot back-pressure the relay. Any fix wants the same experiment as the println!: an unread pipe, a flood, and a frame count with a deadline.
Also
nostreamd/src/settings_gate.rs:8-14 should stop claiming to be the only library-position stdout writer. The rule that survives is narrower and true: output belongs to a process's entry point; this module's three lines are the operator report of one settings check, and the daemon's stdout writer is telemetry::init's subscriber.
Activity