Skip to content

fix(log): do not block the node on a stalled log output - #5679

Closed
martinconic wants to merge 3 commits into
masterfrom
fix/5581-nonblocking-log-sink
Closed

martinconic wants to merge 3 commits into
masterfrom
fix/5581-nonblocking-log-sink

Conversation

@martinconic

@martinconic martinconic commented Oct 26, 2026 •

Copy link
Copy Markdown
Contributor

Checklist

  • I have read the coding guide.
  • My change requires a documentation update, and I have done it.
  • I have added tests to cover my changes.
  • I have added or updated fuzz targets for any code handling untrusted input.
  • I have filled out the description and linked the related issues.

Description

If whatever reads bee's output stops reading it (Swarm Desktop, a paused container, an unread pipe), the pipe fills up and the next log call blocks forever. Logging is synchronous, so the part of the node that was logging just stops.

I reproduced this on current master with a testnet node piped through cat, then paused cat and filled the pipe. With the pipe full:

master this PR
POST /connect to an unreachable peer never answers answers immediately
Node startup stuck in kademlia's bootnode connect, on a log line not affected
Ctrl-C / SIGINT node never stops, needs kill -9 stops in ~6s
/health still reports ok ok

The shutdown hang is not in the issue: the SIGINT handler logs "received interrupt signal" before it cancels anything, so it gets stuck too.

The fix. For bee start and bee deploy, log lines now go into a queue (up to 4096 lines), and a background goroutine writes them out.

  • While the output keeps up, nothing changes: if the queue fills during a burst, the log call waits for space, as it does today, and no lines are lost.
  • Lines are dropped only when the output is stalled, meaning a single write has been stuck for more than 1 second. From then on, log calls drop lines immediately instead of waiting, until the output recovers.
  • Dropped lines (and failed writes) are counted in a new bee_log_dropped_count metric. A warning saying how many lines were lost is written exactly where the gap is, or at the end if bee shuts down first.
  • On exit, queued lines are flushed. bee waits at most 5 seconds, so a stuck output can't stop it from exiting.
  • bee db, bee init and bee split are unchanged. They are short-lived and keep writing logs directly.

I fixed it in the logger rather than at the pricing call from the issue's stack trace, because any log line anywhere in the node could cause the same hang.

What changes for operators:

  • With a stalled log output, log lines are lost, but the metric and the warning make that visible. When the output stalls, log calls can wait up to 1 second once before dropping starts.
  • Lines still in the queue when bee crashes are lost. This includes the last lines before a panic: in a test, one error line logged right before a panic was missing in roughly 7–9% of runs. The panic message and stack trace are unaffected, because Go writes them straight to stderr. The same applies to kill -9 and OOM kills.
  • The dropped-lines warning is printed even with --verbosity error, so lost lines are never silent. Happy to change that if reviewers prefer.

Known gaps: a few things still write to stdout/stderr directly, without going through the bee logger:

  • The AutoTLS (p2p-forge) logger in pkg/p2p/libp2p/p2pforge.go writes straight to stdout. It is only active with AutoTLS/WSS enabled, but then it can still block, including during startup.
  • libp2p's internal logging writes errors to stderr. It is rarely used, but it is synchronous.
  • The welcome banner and main's final Error: line. The banner only blocks if the pipe is already full when bee starts; the Error: line only matters if bee start fails while stderr is stalled.

Routing these through the new writer means passing it into libp2p, so I'd rather do that in a follow-up and keep this change focused on the bee logger.

Not included: a timeout on kademlia's wg.Wait(), which the issue also suggests. With the logger fixed it is no longer needed. It would also leave stuck connect goroutines behind and let new connect rounds overlap them, so I'd rather handle it separately if we want it.

Open API Spec Version Changes (if applicable)

None.

Motivation and Context (Optional)

A node with a stalled log reader looks healthy (/health is ok) while it slowly loses all its peers and can't be restarted cleanly. That is hard to diagnose in the field.

Related Issue (Optional)

Fixes #5581

Screenshots (if appropriate):

AI Disclosure

  • This PR contains code that has been generated by an LLM.
  • I have reviewed the AI generated code thoroughly.
  • I possess the technical expertise to responsibly review the code generated in this PR.

When the process reading bee's output stops reading, the pipe fills
up and every log call blocks forever. Because logging is synchronous,
this stalls whatever was logging: peer connections, API requests,
node startup and even shutdown on SIGINT.

Log lines are now handed to a background writer through a bounded
queue for the start and deploy commands. When the output cannot keep
up, lines are dropped instead of blocking the caller, counted in the
bee_log_dropped_count metric, and reported with a warning once the
output recovers. Queued lines are flushed on exit, waiting at most
five seconds.

Fixes #5581
The dropped lines warning was written in front of lines that had been
queued before the drops, and drops at shutdown were never reported.
The number of dropped lines is now attached to the next queued line,
so the warning lands exactly at the gap, and any drops left at close
are reported after the final flush.

Dropping a line no longer copies it, writes after Close are discarded
instead of piling up in the queue, and no background writer is started
when logging is silent.
Lines were dropped whenever the queue was full, so a healthy output
that was briefly slower than a burst of logging also lost lines. Now a
full queue makes the caller wait for space while the output makes
progress, as before this change. Lines are dropped only once a single
write to the output has been stuck for more than a second, and from
then on immediately, until the output recovers.

Failed writes to the output are now counted as dropped lines. Adds
tests with a slow output, a healthy output under concurrent load, and
a real logger on a stalled pipe.
@martinconic

Copy link
Copy Markdown
Contributor Author

Closing this one. After more digging, the root cause is in Swarm Desktop, not in bee.

Desktop forwards bee's output into its own stdout with subprocess.stdout.pipe(process.stdout). .pipe() applies backpressure, so if Desktop's own stdout stalls or breaks, Node pauses bee's stream. That also stops the listener that writes bee.log. Nobody drains bee's pipe anymore, and bee blocks on its next log line.

I reproduced the full chain with Desktop's exact stdio code and a real bee from master. After Desktop's stdout stalled, bee eventually blocked: API requests hung, bee.log stopped growing, /health still said ok, and SIGINT was ignored.

bee itself behaves like a normal program here:

  • If the process reading its output dies, bee exits with SIGPIPE on its next log line.
  • Blocking on a full stdout is the default for most software (Docker and logback also block by default and make non-blocking an opt-in).

So this change isn't needed in bee. I'm keeping the branch in case the same hang ever shows up outside Desktop (docker, systemd, etc.).

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

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

A stalled log sink deadlocks peer connectivity — node reports healthy with zero peers and never recovers

1 participant