Repository navigation
fix(log): do not block the node on a stalled log output - #5679
martinconic wants to merge 3 commits into
Conversation
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.
|
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 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 itself behaves like a normal program here:
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.). |
Checklist
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 pausedcatand filled the pipe. With the pipe full:POST /connectto an unreachable peerkill -9/healthokokThe 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 startandbee deploy, log lines now go into a queue (up to 4096 lines), and a background goroutine writes them out.bee_log_dropped_countmetric. A warning saying how many lines were lost is written exactly where the gap is, or at the end if bee shuts down first.bee db,bee initandbee splitare 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:
kill -9and OOM kills.--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:
pkg/p2p/libp2p/p2pforge.gowrites straight to stdout. It is only active with AutoTLS/WSS enabled, but then it can still block, including during startup.main's finalError:line. The banner only blocks if the pipe is already full when bee starts; theError:line only matters ifbee startfails 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 (
/healthisok) 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