Skip to content

fix(daemon): unbounded stderr rotated the tray diagnostics out of the log - #22

Merged
HackPoint merged 1 commit into
mainfrom
fix/daemon-reconnect-log-noise
Aug 1, 2026
Merged

fix(daemon): unbounded stderr rotated the tray diagnostics out of the log#22
HackPoint merged 1 commit into
mainfrom
fix/daemon-reconnect-log-noise

Conversation

@HackPoint

Copy link
Copy Markdown
Owner

Closes #7.

Release logging exists so a tray failure leaves evidence. The GUI forwards the daemon's stderr into
its own log, which is capped at 256 KB with KeepOne — so enough daemon output rotates the file and
takes the startup and tray lines with it, at exactly the moment someone finally reports a problem.

There were two unbounded sources. The issue named one; measuring the fix found the other, which
is 100× larger.

1. The reconnect loop — 434 KB/hour

Retried every 2s and logged two lines per cycle for as long as the failure lasted. Against a held
port that rotated the log every ~35 minutes.

  • Backs off 2s → 4 → 8 → 16 → 30s and stays there. A held port does not free up faster for being
    asked more often, and the 30s cap bounds recovery (the GUI retries its own connection every 2s).
  • An unchanged failure logs the first three attempts, then one in ten, reporting how many were
    suppressed when it next speaks. A changed error always logs — a new error is new information.
  • ws_server no longer logs the bind failure itself. It printed ws bind failed while the loop
    printed ws_server exited for the same event: two lines per cycle, and the throttle state could
    only live in the loop. The loop owns the message now; the error carries the address.

2. The startup backfill — 876 KB in 60 seconds

Not in the issue, and much worse. The initial import logged one line per ingested turn: on this
machine 16,252 lines and 876 KB in a minute — over three times the entire log cap, on the first
launch
, which is the launch a new user is most likely to need a log for.

Scoped to live turns using the broadcast_live flag that already distinguishes them. Seeing live
turns arrive is the point of the tool and they are a few per minute; the backfill now reports one
total line instead.

I included this rather than filing it separately because without it the PR would claim to fix #7
while its own acceptance criterion — diagnostics survive an hour — still failed on every fresh
install. Happy to split it if you'd rather review them apart.

Measured

before after
held port, sustained 434 KB/hour 25 KB/hour
fresh install backfill 16,252 lines / 876 KB 301 lines / 56 KB

The remaining 56 KB is one line per transcript file (not per turn), so it scales with file count
and is a one-time cost well under the 256 KB cap. I left those: they are what tells you which file
was slow or failed. Worth noting they contain transcript paths under $HOME — the fault reporter
redacts paths, the log does not. Say the word if you want that changed too.

Verifying it yourself

cargo test -p lumen-daemon                    # 8 new tests, 27 total in the bin

The end-to-end measurement, which is what actually convinced me:

# hold the port so the daemon cannot bind
python3 -c "import socket,time; s=socket.socket(); \
  s.setsockopt(socket.SOL_SOCKET,socket.SO_REUSEADDR,1); \
  s.bind(('127.0.0.1',9977)); s.listen(1); time.sleep(120)" &

cargo build --release -p lumen-daemon
rm -f /tmp/probe.db
LUMEN_WS_ADDR=127.0.0.1:9977 LUMEN_DB=/tmp/probe.db \
  ./target/release/lumen-daemon >/dev/null 2>/tmp/probe.txt &
sleep 60; kill %2 %1

wc -l -c /tmp/probe.txt        # expect ~300 lines / ~56 KB, not ~16k / ~876 KB
grep ws_server /tmp/probe.txt  # expect 3 lines (attempts 1,2,3), not ~60

LUMEN_LOG=debug restores every line — the same variable the GUI already takes its level from,
rather than a second one to learn.

What I deliberately did not do

  • No new dependency and no logging framework in the daemon. It writes to stderr through
    logline! by design, because the GUI owns that pipe; adding a level filter would be a larger
    change than the defect warrants.
  • Did not reuse faults::record_throttled. The issue suggested it. It keys on
    (kind, variant) with a wall-clock interval and is right for the fault spool, but the decision
    here is attempt-count-based and needs to reset on a changed error — a different shape, and forcing
    one to serve both would make each worse. note_fault already throttles the spool at 60s
    independently, and that path is unchanged.
  • Left the per-file backfill lines. See above.

Local gate

Green before pushing: cargo fmt --all --check, both clippy invocations with -D warnings,
cargo test --workspace, and the frontend suite and build under Node 26.

… log

Release logging was added so a tray failure leaves evidence. Two unbounded stderr sources
defeated it: the GUI forwards this process's output into a log capped at 256 KB with KeepOne,
so enough volume rotates the file and takes the startup and tray lines with it — exactly when
a user finally reports the problem.

The reconnect loop retried every 2s and logged two lines per cycle for as long as the failure
lasted: 434 KB/hour against a held port, rotating the file every ~35 minutes. It now backs off
2s→30s and collapses an unchanged failure to the first three then one in ten, reporting the
suppressed count when it next speaks. A changed error is always logged, because a new error is
new information. Measured against a held port: 25 KB/hour, a 94% reduction.

`ws_server` no longer logs the bind failure itself. It logged "ws bind failed" while the loop
logged "ws_server exited" for the same event — two lines per cycle, and the throttle state
could only live in the loop. The loop now owns the message and the error carries the address.

The larger source was worse and only shows on a fresh install: the startup backfill logged one
line per ingested turn, which on this machine was 16,252 lines and 876 KB in 60 seconds — three
times over the cap, on the first launch, which is the launch a new user is most likely to need
a log for. Per-turn lines are now scoped to live turns via the existing `broadcast_live` flag;
seeing live turns arrive is the point of the tool and they are a few per minute. The backfill
reports one total instead. Fresh-install output: 301 lines, 56 KB.

`LUMEN_LOG=debug|trace` restores everything, using the same variable the GUI already takes its
level from rather than inventing a second one.

Eight tests cover the two decisions as pure functions, including that the delay cannot overflow
or reach zero for any attempt count, and that an hour of one unchanged failure stays between 3
and 20 lines — bounded, but never silent.

Closes #7
@HackPoint
HackPoint merged commit 3b608e6 into main Aug 1, 2026
12 checks passed
@HackPoint
HackPoint deleted the fix/daemon-reconnect-log-noise branch August 1, 2026 19:29
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.

Daemon reconnect noise rotates the tray diagnostics out of the log

1 participant