diff --git a/crates/myownmesh-core/src/engine/mod.rs b/crates/myownmesh-core/src/engine/mod.rs index 75673ec..a1ed610 100644 --- a/crates/myownmesh-core/src/engine/mod.rs +++ b/crates/myownmesh-core/src/engine/mod.rs @@ -62,7 +62,7 @@ use std::time::{Duration, Instant}; use bytes::Bytes; use tokio::sync::mpsc; -use tracing::{debug, info, trace, warn}; +use tracing::{debug, trace, warn}; use webrtc::ice_transport::ice_connection_state::RTCIceConnectionState; use webrtc::peer_connection::peer_connection_state::RTCPeerConnectionState; use webrtc::peer_connection::sdp::sdp_type::RTCSdpType; @@ -1357,7 +1357,10 @@ async fn ensure_peer_session(state: &Arc, device_id: String, role: { return; } - info!(peer = %short_peer(&device_id), ?role, "ensure_peer_session: opening transport session"); + // Per-peer negotiation stage, same reasoning as the webrtc.rs stage logs: + // one line per peer per attempt is fine when connects are rare and a flood + // when they aren't. Restored by `MYOWNMESH_LOG_EXTRA=myownmesh_core=debug`. + debug!(peer = %short_peer(&device_id), ?role, "ensure_peer_session: opening transport session"); let cfg = state.config.read().clone(); let (session, mut rx) = match state .transport @@ -1406,7 +1409,7 @@ async fn ensure_peer_session(state: &Arc, device_id: String, role: // the daemon sat with one worker spinning and the driver parked here // forever while the control socket timed out op after op. A stuck offer // now costs this one attempt (the watchdog rebuilds it), not the engine. - info!(peer = %short_peer(&device_id), "ensure_peer_session: building offer"); + debug!(peer = %short_peer(&device_id), "ensure_peer_session: building offer"); if role == Role::Offerer { let built = tokio::time::timeout( Duration::from_millis(scheduler::OFFER_BUILD_TIMEOUT_MS), diff --git a/crates/myownmesh-core/src/transport/webrtc.rs b/crates/myownmesh-core/src/transport/webrtc.rs index 3d48d71..5dc91e5 100644 --- a/crates/myownmesh-core/src/transport/webrtc.rs +++ b/crates/myownmesh-core/src/transport/webrtc.rs @@ -1050,19 +1050,30 @@ impl PeerSession { } /// Build an offer SDP. Offerer-only (answerer never calls this). - /// The stage logs are plain INFO on purpose: this pair is the engine's - /// inline-on-the-driver excursion into webrtc-rs, it wedges on the - /// NanoKVM with nothing inside logging, and a stage line that only shows - /// under a special log filter has already cost deploy cycles. They fire - /// once per connect attempt — negligible in a healthy log. + /// + /// The stage logs exist because this pair is the engine's + /// inline-on-the-driver excursion into webrtc-rs: it wedges on the NanoKVM + /// with nothing inside logging, so knowing *which* stage stopped is what + /// turns an invisible freeze into a diagnosis. + /// + /// They were INFO on the premise that they "fire once per connect attempt — + /// negligible in a healthy log". That premise is what broke: an unhealthy + /// mesh renegotiates constantly, and at ~12 lines per peer per attempt + /// across 20+ peers this became the single largest contributor to a + /// multi-gigabyte syslog. Precisely when the daemon is sickest, its logs + /// grow fastest — and the disk that fills takes the diagnosis with it. + /// + /// So they are DEBUG now, and the field workflow is unchanged in substance: + /// `MYOWNMESH_LOG_EXTRA=myownmesh_core=debug` (what `just serve-trace` + /// already sets) brings every one of them back verbatim. pub async fn create_offer(&self) -> Result { - info!("create_offer: building SDP (pc.create_offer)"); + debug!("create_offer: building SDP (pc.create_offer)"); let offer = self .pc .create_offer(None) .await .map_err(|e| Error::Transport(format!("create_offer: {e}")))?; - info!( + debug!( sdp_bytes = offer.sdp.len(), "create_offer: applying local description (starts ICE gathering)" ); @@ -1070,7 +1081,7 @@ impl PeerSession { .set_local_description(offer.clone()) .await .map_err(|e| Error::Transport(format!("set_local_description (offer): {e}")))?; - info!("create_offer: local description applied"); + debug!("create_offer: local description applied"); Ok(offer) } @@ -1081,7 +1092,7 @@ impl PeerSession { /// REMOTE side's media sections regardless of our own lane count), so it /// is equally capable of freezing the engine invisibly. pub async fn set_remote_description(&self, desc: RTCSessionDescription) -> Result<()> { - info!( + debug!( sdp_type = %desc.sdp_type, sdp_bytes = desc.sdp.len(), "set_remote_description: applying remote SDP" @@ -1133,13 +1144,13 @@ impl PeerSession { /// [`Self::set_remote_description`]. Stage-logged like create_offer — /// same inline-on-the-driver machinery, same invisible-freeze potential. pub async fn create_answer(&self) -> Result { - info!("create_answer: building SDP (pc.create_answer)"); + debug!("create_answer: building SDP (pc.create_answer)"); let answer = self .pc .create_answer(None) .await .map_err(|e| Error::Transport(format!("create_answer: {e}")))?; - info!( + debug!( sdp_bytes = answer.sdp.len(), "create_answer: applying local description (starts ICE gathering)" ); @@ -1147,7 +1158,7 @@ impl PeerSession { .set_local_description(answer.clone()) .await .map_err(|e| Error::Transport(format!("set_local_description (answer): {e}")))?; - info!("create_answer: local description applied"); + debug!("create_answer: local description applied"); Ok(answer) } diff --git a/crates/myownmesh-signaling/src/server.rs b/crates/myownmesh-signaling/src/server.rs index c8ea30e..d783b1c 100644 --- a/crates/myownmesh-signaling/src/server.rs +++ b/crates/myownmesh-signaling/src/server.rs @@ -47,7 +47,7 @@ use tokio::net::{TcpListener, TcpStream}; use tokio::sync::mpsc; use tokio::task::JoinHandle; use tokio_tungstenite::tungstenite::Message as WsMessage; -use tracing::{info, trace, warn}; +use tracing::{debug, info, trace, warn}; use crate::nostr::event::{ make_event, now_secs, NostrEvent, NostrIdentity, SIGNALING_EPHEMERAL_KIND, SIGNALING_EVENT_KIND, @@ -404,7 +404,11 @@ impl HubInner { }, ); self.connections_total += 1; - info!(%ip, active = self.conns.len(), "signaling: client connected"); + // Per-connection churn, not a daemon event: on a relay holding 20+ + // clients this fires constantly, and every reconnect writes a pair of + // lines forever. The running total is what a healthy log wants, and + // that's on the periodic summary — this stays available at debug. + debug!(%ip, active = self.conns.len(), "signaling: client connected"); Some(id) } @@ -418,7 +422,7 @@ impl HubInner { self.ip_counts.remove(&entry.ip); } } - info!(ip = %entry.ip, active = self.conns.len(), "signaling: client disconnected"); + debug!(ip = %entry.ip, active = self.conns.len(), "signaling: client disconnected"); // Emit a departure for each device this connection was the live // owner of (skip any that a newer connection has since taken // over — presence holds only the latest owner per device). diff --git a/crates/myownmesh/src/main.rs b/crates/myownmesh/src/main.rs index fdc9662..e6184a7 100644 --- a/crates/myownmesh/src/main.rs +++ b/crates/myownmesh/src/main.rs @@ -8,6 +8,7 @@ //! `ctl …`-style and addresses the running daemon via the control //! socket. +use std::io::IsTerminal; use std::process::ExitCode; use anyhow::Result; @@ -156,16 +157,26 @@ fn main() -> ExitCode { let json_logs = std::env::var("MYOWNMESH_LOG_FORMAT") .map(|v| v.eq_ignore_ascii_case("json")) .unwrap_or(false); + // Colour only when a human is actually looking at a terminal. + // `tracing_subscriber` turns ANSI on unconditionally, which is fine in a + // shell and actively harmful under systemd: journald/rsyslog capture the + // escape sequences verbatim, so every line reaches /var/log/syslog as + // `#033[2m2026-…#033[0m #033[32m INFO#033[0m …`. That is ~40-60 wasted + // bytes per line, and it breaks grep on a daemon log — the two things you + // least want on a box that logs continuously. + let ansi = std::io::stdout().is_terminal(); if json_logs { tracing_subscriber::fmt() .json() .with_env_filter(tracing_subscriber::EnvFilter::new(log_level)) .with_target(false) + .with_ansi(ansi) .init(); } else { tracing_subscriber::fmt() .with_env_filter(tracing_subscriber::EnvFilter::new(log_level)) .with_target(false) + .with_ansi(ansi) .init(); } diff --git a/docs/DEBUGGING-CONNECTIONS.md b/docs/DEBUGGING-CONNECTIONS.md index d4e8db5..535904e 100644 --- a/docs/DEBUGGING-CONNECTIONS.md +++ b/docs/DEBUGGING-CONNECTIONS.md @@ -113,6 +113,19 @@ Tag the file with the hostname so the merge tool can label rows. > `MYOWNMESH_LOG` only when you deliberately want raw webrtc detail, e.g. > `MYOWNMESH_LOG="info,webrtc_ice=debug"`.) +> **Where the negotiation stage lines went.** `create_offer` / +> `create_answer` / `set_remote_description` / `ensure_peer_session`, and the +> signaling relay's per-client `connected` / `disconnected` pair, are **debug** +> level. They used to be INFO on the reasoning that they fire once per connect +> attempt — fine when connects are rare, but a mesh that is renegotiating is +> exactly the one that floods, so the daemon logged hardest precisely when it +> was sickest (a field box reached a multi-gigabyte syslog this way, and a full +> disk takes the diagnosis with it). The default log is now boring on purpose. +> +> The debugging workflow is unchanged — the `MYOWNMESH_LOG_EXTRA` line below, +> and `just serve-trace`, already set `myownmesh_core=debug` and +> `myownmesh_signaling=debug`, which restore every one of those lines verbatim. + **macOS / Linux** ```sh