fix(logging): quiet the default log and stop colouring syslog - #108
Merged
Merged
Conversation
A field server reached 74 GB of /var/log/syslog in about a month and hit ENOSPC. Two causes, both in how the daemon writes rather than what it does. ANSI colour into a non-TTY. `tracing_subscriber` enables ANSI unconditionally — it does not check for a terminal. Under systemd that stdout is captured by journald/rsyslog, so every line landed as: ubuntu myownmesh[793]: #33[2m2026-…#33[0m #33[32m INFO#033[0m signaling: … That is ~40-60 wasted bytes per line forever, and grep stops matching what you can read. Colour is now gated on `stdout().is_terminal()`. Per-connection tracing at INFO. The signaling relay logged a line on every client connect and disconnect, and the WebRTC negotiation path logged ~12 stage lines per peer per attempt (create_offer / create_answer / set_remote_description / ensure_peer_session). Those were INFO on the premise that they "fire once per connect attempt — negligible in a healthy log". That premise is the bug: a mesh that is renegotiating is exactly the one that floods, so the daemon logged hardest precisely when it was sickest — and the disk that fills takes the diagnosis with it. On a relay holding 20+ clients this was the dominant term. They are DEBUG now. The default log is boring on purpose: startup, control socket commands, network state changes, errors. The debugging workflow is unchanged in substance — `MYOWNMESH_LOG_EXTRA=myownmesh_core=debug, myownmesh_signaling=debug` (what `just serve-trace` already sets) restores every one of those lines verbatim. Documented in DEBUGGING-CONNECTIONS.md so nobody has to rediscover where they went. Nothing that reports a real state change was touched: connection tracing (already gated on a subscriber), interface/IP transitions, relay recovery, and every warn/error path are as they were. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01FMPNLjvNYQCeR3xGfdDUCg
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Why
A field server reached 74 GB of
/var/log/syslogin about a month and hit ENOSPC:Two causes, both in how the daemon writes rather than what it does.
1. ANSI colour written into a non-TTY
tracing_subscriberenables ANSI unconditionally — it does not check for a terminal. Under systemd that stdout is captured by journald/rsyslog, so every line reached syslog wrapped in escape sequences (visible above). That is ~40–60 wasted bytes on every line of a daemon that logs continuously, and it breaksgrepagainst what you can actually read.Colour is now gated on
std::io::stdout().is_terminal()— a terminal still gets colour, a service gets plain text.2. Per-connection tracing at INFO
create_offer/create_answer/set_remote_description/ensure_peer_session).Those were INFO on an explicit, documented premise — that they "fire once per connect attempt — negligible in a healthy log". That premise is the bug. A mesh that is renegotiating is exactly the one that floods, so the daemon logs hardest precisely when it is sickest, and the disk that fills takes the diagnosis with it. On a relay holding 20+ peers this was the dominant term.
They are DEBUG now. The default log is boring on purpose: startup, control-socket commands, network state changes, warnings and errors.
The debugging workflow is unchanged in substance.
MYOWNMESH_LOG_EXTRA=myownmesh_core=debug,myownmesh_signaling=debug— whichjust serve-tracealready sets — restores every one of those lines verbatim.docs/DEBUGGING-CONNECTIONS.mdnow says so explicitly, so nobody has to rediscover where they went.What was deliberately left alone
Nothing that reports a real state change was touched:
conn_trace) — already correctly gated on actl tracesubscriber orMYOWNMESH_CONN_TRACE, and it already diffs only discrete fields so RTT churn doesn't trigger it. It was not a contributor.primary signaling recovered, mesh/identity startup, control-socket commands.warn!/error!path.Testing
cargo test --workspacegreen,cargo clippy --workspace --all-targetsclean,cargo fmt --all --checkclean.One flake seen along the way:
myownmesh --libfailed 1/20 on a first run and then passed 20/20 on five consecutive reruns. It's incontrol/ipc/services— code this PR doesn't touch (the only change in that crate is tomain.rs, a binary, not the lib) — so it's pre-existing and unrelated. Flagging it rather than burying it.Not addressed here
The underlying reason that box logs so much is that a signaling client disconnects and reconnects every ~32 seconds, forever (
activeoscillating 21↔22). That churn is what multiplies every other line. Per direction on the issue, this PR only quiets the logs and does not chase the flap.Generated by Claude Code