From ab7a4bac29a64addb565496063ecdf2c1c7b90b6 Mon Sep 17 00:00:00 2001 From: Johnathan Corgan Date: Thu, 19 Feb 2026 04:15:08 +0000 Subject: [PATCH] Logging level overhaul: reduce verbosity at info and debug levels Per-packet happy-path events (UDP send/receive, TUN I/O, MMP report processing, TreeAnnounce/FilterAnnounce sent, RTT samples) moved from debug to trace. Periodic maintenance and retry scheduling moved from info to debug. Session state changes (established, initiated, torn down) and transport stop promoted from debug to info. MMP report send failures demoted from warn to debug (normal under churn). --- src/mmp/metrics.rs | 4 ++-- src/node/bloom.rs | 6 +++--- src/node/handlers/mmp.rs | 10 +++++----- src/node/handlers/session.rs | 14 +++++++------- src/node/lifecycle.rs | 14 +++++++------- src/node/retry.rs | 6 +++--- src/node/tree.rs | 4 ++-- src/transport/udp.rs | 8 ++++---- src/upper/tun.rs | 22 +++++++++++----------- 9 files changed, 44 insertions(+), 44 deletions(-) diff --git a/src/mmp/metrics.rs b/src/mmp/metrics.rs index d6f41d7..7631b2a 100644 --- a/src/mmp/metrics.rs +++ b/src/mmp/metrics.rs @@ -8,7 +8,7 @@ use crate::mmp::algorithms::{DualEwma, SrttEstimator, compute_etx}; use crate::mmp::report::ReceiverReport; use std::time::Instant; -use tracing::debug; +use tracing::trace; /// Derived MMP metrics, updated from incoming ReceiverReports. /// @@ -81,7 +81,7 @@ impl MmpMetrics { if our_timestamp_ms > echo_ms + dwell_ms { let rtt_ms = our_timestamp_ms - echo_ms - dwell_ms; let rtt_us = (rtt_ms as i64) * 1000; - debug!( + trace!( our_ts = our_timestamp_ms, echo = echo_ms, dwell = dwell_ms, diff --git a/src/node/bloom.rs b/src/node/bloom.rs index 3c6e154..8fb8bec 100644 --- a/src/node/bloom.rs +++ b/src/node/bloom.rs @@ -9,7 +9,7 @@ use crate::NodeAddr; use super::{Node, NodeError}; use std::collections::HashMap; -use tracing::{debug, info}; +use tracing::{debug, trace}; impl Node { /// Collect inbound filters from all peers for outgoing filter computation. @@ -77,7 +77,7 @@ impl Node { peer.clear_filter_update_needed(); } - debug!(peer = %peer_addr, seq = announce.sequence, "Sent FilterAnnounce"); + trace!(peer = %peer_addr, seq = announce.sequence, "Sent FilterAnnounce"); Ok(()) } @@ -161,7 +161,7 @@ impl Node { peer.update_filter(announce.filter, announce.sequence, now_ms); } - info!( + debug!( from = %from, seq = announce.sequence, "Received FilterAnnounce" diff --git a/src/node/handlers/mmp.rs b/src/node/handlers/mmp.rs index 72a8e91..76279ea 100644 --- a/src/node/handlers/mmp.rs +++ b/src/node/handlers/mmp.rs @@ -13,7 +13,7 @@ use crate::protocol::{ }; use crate::NodeAddr; use std::time::Instant; -use tracing::{debug, info, warn}; +use tracing::{debug, info, trace}; /// Format bytes/sec as human-readable throughput. fn format_throughput(bps: f64) -> String { @@ -55,7 +55,7 @@ impl Node { return; } - debug!( + trace!( from = %from, cum_pkts = sr.cumulative_packets_sent, interval_bytes = sr.interval_bytes_sent, @@ -116,7 +116,7 @@ impl Node { mmp.metrics.set_delivery_ratio_reverse(reverse_ratio); } - debug!( + trace!( from = %from, rtt_ms = ?mmp.metrics.srtt_ms(), loss = format_args!("{:.1}%", mmp.metrics.loss_rate() * 100.0), @@ -168,13 +168,13 @@ impl Node { // Send collected reports for (node_addr, encoded) in sender_reports { if let Err(e) = self.send_encrypted_link_message(&node_addr, &encoded).await { - warn!(peer = %node_addr, error = %e, "Failed to send SenderReport"); + debug!(peer = %node_addr, error = %e, "Failed to send SenderReport"); } } for (node_addr, encoded) in receiver_reports { if let Err(e) = self.send_encrypted_link_message(&node_addr, &encoded).await { - warn!(peer = %node_addr, error = %e, "Failed to send ReceiverReport"); + debug!(peer = %node_addr, error = %e, "Failed to send ReceiverReport"); } } } diff --git a/src/node/handlers/session.rs b/src/node/handlers/session.rs index 95ae64e..33d58f7 100644 --- a/src/node/handlers/session.rs +++ b/src/node/handlers/session.rs @@ -22,7 +22,7 @@ use crate::protocol::{ }; use crate::NodeAddr; use secp256k1::PublicKey; -use tracing::debug; +use tracing::{debug, info, trace}; impl Node { /// Handle a locally-delivered session datagram payload. @@ -160,7 +160,7 @@ impl Node { entry.set_coords_warmup_remaining(self.config.node.session.coords_warmup_packets); entry.mark_established(Self::now_ms()); entry.init_mmp(&self.config.node.session_mmp); - debug!(src = %src_addr, "Session established (responder, on first encrypted message)"); + info!(src = %src_addr, "Session established (responder, on first encrypted message)"); } // Decrypt with AAD = the 12-byte header @@ -235,7 +235,7 @@ impl Node { debug!(error = %e, "Failed to deliver decrypted packet to TUN"); } } else { - debug!( + trace!( src = %src_addr, "DataPacket decrypted (no TUN interface, plaintext dropped)" ); @@ -434,7 +434,7 @@ impl Node { // Flush any queued outbound packets for this destination self.flush_pending_packets(src_addr).await; - debug!(src = %src_addr, "Session established (initiator)"); + info!(src = %src_addr, "Session established (initiator)"); } // === Session-layer MMP report handlers === @@ -452,7 +452,7 @@ impl Node { } }; - debug!( + trace!( src = %src_addr, cum_pkts = sr.cumulative_packets_sent, interval_bytes = sr.interval_bytes_sent, @@ -519,7 +519,7 @@ impl Node { mmp.metrics.set_delivery_ratio_reverse(reverse_ratio); } - debug!( + trace!( src = %src_addr, rtt_ms = ?mmp.metrics.srtt_ms(), loss = format_args!("{:.1}%", mmp.metrics.loss_rate() * 100.0), @@ -703,7 +703,7 @@ impl Node { let entry = SessionEntry::new(dest_addr, dest_pubkey, EndToEndState::Initiating(handshake), now_ms, true); self.sessions.insert(dest_addr, entry); - debug!(dest = %dest_addr, "Session initiation started"); + info!(dest = %dest_addr, "Session initiation started"); Ok(()) } diff --git a/src/node/lifecycle.rs b/src/node/lifecycle.rs index 44f46f7..fa7c445 100644 --- a/src/node/lifecycle.rs +++ b/src/node/lifecycle.rs @@ -166,13 +166,13 @@ impl Node { .map(|a| format!(" ({})", a)) .unwrap_or_default(); - info!("Peer connection initiated{}", alias_display); - info!(" npub: {}", peer_config.npub); - info!(" node_addr: {}", peer_node_addr); - info!(" transport: {}", addr.transport); - info!(" addr: {}", addr.addr); - info!(" link_id: {}", link_id); - info!(" our_index: {}", our_index); + debug!("Peer connection initiated{}", alias_display); + debug!(" npub: {}", peer_config.npub); + debug!(" node_addr: {}", peer_node_addr); + debug!(" transport: {}", addr.transport); + debug!(" addr: {}", addr.addr); + debug!(" link_id: {}", link_id); + debug!(" our_index: {}", our_index); // Track in pending_outbound for msg2 dispatch self.pending_outbound.insert((transport_id, our_index.as_u32()), link_id); diff --git a/src/node/retry.rs b/src/node/retry.rs index afa8e58..bc1af66 100644 --- a/src/node/retry.rs +++ b/src/node/retry.rs @@ -79,7 +79,7 @@ impl Node { } let delay = state.backoff_ms(base_interval_ms, max_backoff_ms); state.retry_after_ms = now_ms + delay; - info!( + debug!( node_addr = %node_addr, retry = state.retry_count, delay_secs = delay / 1000, @@ -102,7 +102,7 @@ impl Node { state.retry_count = 1; let delay = state.backoff_ms(base_interval_ms, max_backoff_ms); state.retry_after_ms = now_ms + delay; - info!( + debug!( node_addr = %node_addr, delay_secs = delay / 1000, "First connection attempt failed, scheduling retry" @@ -144,7 +144,7 @@ impl Node { None => continue, }; - info!( + debug!( node_addr = %node_addr, retry = state.retry_count, "Attempting connection retry" diff --git a/src/node/tree.rs b/src/node/tree.rs index f93985d..52916d6 100644 --- a/src/node/tree.rs +++ b/src/node/tree.rs @@ -7,7 +7,7 @@ use crate::protocol::TreeAnnounce; use crate::NodeAddr; use super::{Node, NodeError}; -use tracing::{debug, info, warn}; +use tracing::{debug, info, trace, warn}; impl Node { /// Build a TreeAnnounce from our current tree state. @@ -68,7 +68,7 @@ impl Node { peer.record_tree_announce_sent(now_ms); } - debug!(peer = %peer_addr, "Sent TreeAnnounce"); + trace!(peer = %peer_addr, "Sent TreeAnnounce"); Ok(()) } diff --git a/src/transport/udp.rs b/src/transport/udp.rs index 4f0db94..2668122 100644 --- a/src/transport/udp.rs +++ b/src/transport/udp.rs @@ -11,7 +11,7 @@ use std::net::SocketAddr; use std::sync::Arc; use tokio::net::UdpSocket; use tokio::task::JoinHandle; -use tracing::{debug, info, warn}; +use tracing::{debug, info, trace, warn}; /// UDP transport for FIPS. /// @@ -149,7 +149,7 @@ impl UdpTransport { self.state = TransportState::Down; - debug!( + info!( transport_id = %self.transport_id, "UDP transport stopped" ); @@ -182,7 +182,7 @@ impl UdpTransport { .await .map_err(|e| TransportError::SendFailed(format!("{}", e)))?; - debug!( + trace!( transport_id = %self.transport_id, remote_addr = %socket_addr, bytes = bytes_sent, @@ -265,7 +265,7 @@ async fn udp_receive_loop( let addr = TransportAddr::from_string(&remote_addr.to_string()); let packet = ReceivedPacket::new(transport_id, addr, data); - debug!( + trace!( transport_id = %transport_id, remote_addr = %remote_addr, bytes = len, diff --git a/src/upper/tun.rs b/src/upper/tun.rs index d7a31d6..e973601 100644 --- a/src/upper/tun.rs +++ b/src/upper/tun.rs @@ -13,7 +13,7 @@ use std::net::Ipv6Addr; use std::os::unix::io::{AsRawFd, FromRawFd}; use std::sync::mpsc; use thiserror::Error; -use tracing::{debug, error, info}; +use tracing::{debug, error, info, trace}; use tun::Layer; /// Channel sender for packets to be written to TUN. @@ -222,7 +222,7 @@ impl TunWriter { for mut packet in self.rx { // Clamp TCP MSS on inbound SYN-ACK packets if clamp_tcp_mss(&mut packet, self.max_mss) { - debug!( + trace!( name = %self.name, max_mss = self.max_mss, "Clamped TCP MSS in inbound SYN-ACK packet" @@ -237,7 +237,7 @@ impl TunWriter { } error!(name = %self.name, error = %e, "TUN write error"); } else { - debug!(name = %self.name, len = packet.len(), "TUN packet written"); + trace!(name = %self.name, len = packet.len(), "TUN packet written"); } } } @@ -301,7 +301,7 @@ pub fn run_tun_reader( if packet[24] == crate::identity::FIPS_ADDRESS_PREFIX { // Clamp TCP MSS if this is a SYN packet if clamp_tcp_mss(packet, max_mss) { - debug!( + trace!( name = %name, max_mss = max_mss, "Clamped TCP MSS in SYN packet" @@ -321,7 +321,7 @@ pub fn run_tun_reader( our_addr.to_ipv6(), ) { - debug!( + trace!( name = %name, len = response.len(), "Sending ICMPv6 Destination Unreachable (non-FIPS destination)" @@ -347,7 +347,7 @@ pub fn run_tun_reader( } } -/// Log basic information about an IPv6 packet at DEBUG level. +/// Log basic information about an IPv6 packet at TRACE level. pub fn log_ipv6_packet(packet: &[u8]) { if packet.len() < 40 { debug!(len = packet.len(), "Received undersized packet"); @@ -374,11 +374,11 @@ pub fn log_ipv6_packet(packet: &[u8]) { _ => "other", }; - debug!("TUN packet received:"); - debug!(" src: {}", src); - debug!(" dst: {}", dst); - debug!(" protocol: {} ({})", protocol, next_header); - debug!(" payload: {} bytes, hop_limit: {}", payload_len, hop_limit); + trace!("TUN packet received:"); + trace!(" src: {}", src); + trace!(" dst: {}", dst); + trace!(" protocol: {} ({})", protocol, next_header); + trace!(" payload: {} bytes, hop_limit: {}", payload_len, hop_limit); } /// Shutdown and delete a TUN interface by name.