Skip to content

relay: error paths log to line-buffered stdout, the same blocking shape as the removed println! #946

Open

Description

@chappie-daemon

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 Stdout under a global lock), but nobody has produced the number for warn!, 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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't workingfactoryBuilt by the software factoryrewritenostream 4.0 Rust/LMDB rewriterustRust implementation work

    Projects

    No projects

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions