Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
9 changes: 6 additions & 3 deletions crates/myownmesh-core/src/engine/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -1357,7 +1357,10 @@ async fn ensure_peer_session(state: &Arc<NetworkState>, 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
Expand Down Expand Up @@ -1406,7 +1409,7 @@ async fn ensure_peer_session(state: &Arc<NetworkState>, 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),
Expand Down
35 changes: 23 additions & 12 deletions crates/myownmesh-core/src/transport/webrtc.rs
Original file line number Diff line number Diff line change
Expand Up @@ -1050,27 +1050,38 @@ 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<RTCSessionDescription> {
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)"
);
self.pc
.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)
}

Expand All @@ -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"
Expand Down Expand Up @@ -1133,21 +1144,21 @@ 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<RTCSessionDescription> {
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)"
);
self.pc
.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)
}

Expand Down
10 changes: 7 additions & 3 deletions crates/myownmesh-signaling/src/server.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -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)
}

Expand All @@ -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).
Expand Down
11 changes: 11 additions & 0 deletions crates/myownmesh/src/main.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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();
}

Expand Down
13 changes: 13 additions & 0 deletions docs/DEBUGGING-CONNECTIONS.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
Loading