diff --git a/src/identity/node_addr.rs b/src/identity/node_addr.rs index e5f8f48..2551e30 100644 --- a/src/identity/node_addr.rs +++ b/src/identity/node_addr.rs @@ -51,6 +51,11 @@ impl NodeAddr { pub fn as_slice(&self) -> &[u8] { &self.0 } + + /// Return a short hex representation: first 4 bytes + "...". + pub fn short_hex(&self) -> String { + format!("{}...", hex_encode(&self.0[..4])) + } } impl fmt::Debug for NodeAddr { diff --git a/src/identity/peer.rs b/src/identity/peer.rs index ed8c82f..471fab6 100644 --- a/src/identity/peer.rs +++ b/src/identity/peer.rs @@ -78,6 +78,13 @@ impl PeerIdentity { encode_npub(&self.pubkey) } + /// Return a shortened npub for log display (e.g., `npub1abcd...wxyz`). + pub fn short_npub(&self) -> String { + let full = self.npub(); + let data = &full[5..]; // strip "npub1" + format!("npub1{}...{}", &data[..4], &data[data.len() - 4..]) + } + /// Return the node ID. pub fn node_addr(&self) -> &NodeAddr { &self.node_addr diff --git a/src/node/bloom.rs b/src/node/bloom.rs index 8fb8bec..75518e6 100644 --- a/src/node/bloom.rs +++ b/src/node/bloom.rs @@ -77,7 +77,7 @@ impl Node { peer.clear_filter_update_needed(); } - trace!(peer = %peer_addr, seq = announce.sequence, "Sent FilterAnnounce"); + trace!(peer = %self.peer_display_name(peer_addr), seq = announce.sequence, "Sent FilterAnnounce"); Ok(()) } @@ -98,7 +98,7 @@ impl Node { for peer_addr in ready { if let Err(e) = self.send_filter_announce_to_peer(&peer_addr).await { debug!( - peer = %peer_addr, + peer = %self.peer_display_name(&peer_addr), error = %e, "Failed to send pending FilterAnnounce" ); @@ -116,18 +116,18 @@ impl Node { let announce = match FilterAnnounce::decode(payload) { Ok(a) => a, Err(e) => { - debug!(from = %from, error = %e, "Malformed FilterAnnounce"); + debug!(from = %self.peer_display_name(from), error = %e, "Malformed FilterAnnounce"); return; } }; // Validate if !announce.is_valid() { - debug!(from = %from, "FilterAnnounce filter/size_class mismatch"); + debug!(from = %self.peer_display_name(from), "FilterAnnounce filter/size_class mismatch"); return; } if !announce.is_v1_compliant() { - debug!(from = %from, size_class = announce.size_class, "Non-v1 FilterAnnounce rejected"); + debug!(from = %self.peer_display_name(from), size_class = announce.size_class, "Non-v1 FilterAnnounce rejected"); return; } @@ -135,7 +135,7 @@ impl Node { let current_seq = match self.peers.get(from) { Some(peer) => peer.filter_sequence(), None => { - debug!(from = %from, "FilterAnnounce from unknown peer"); + debug!(from = %self.peer_display_name(from), "FilterAnnounce from unknown peer"); return; } }; @@ -143,7 +143,7 @@ impl Node { // Reject stale/replay if announce.sequence <= current_seq { debug!( - from = %from, + from = %self.peer_display_name(from), received_seq = announce.sequence, current_seq = current_seq, "Stale FilterAnnounce rejected" @@ -162,7 +162,7 @@ impl Node { } debug!( - from = %from, + from = %self.peer_display_name(from), seq = announce.sequence, "Received FilterAnnounce" ); diff --git a/src/node/handlers/discovery.rs b/src/node/handlers/discovery.rs index 5e1ec78..b08f9a8 100644 --- a/src/node/handlers/discovery.rs +++ b/src/node/handlers/discovery.rs @@ -28,7 +28,7 @@ impl Node { let request = match LookupRequest::decode(payload) { Ok(req) => req, Err(e) => { - debug!(from = %from, error = %e, "Malformed LookupRequest"); + debug!(from = %self.peer_display_name(from), error = %e, "Malformed LookupRequest"); return; } }; @@ -39,7 +39,7 @@ impl Node { if self.recent_requests.contains_key(&request.request_id) { trace!( request_id = request.request_id, - from = %from, + from = %self.peer_display_name(from), "Duplicate LookupRequest, dropping" ); return; @@ -58,7 +58,7 @@ impl Node { if request.was_visited(self.node_addr()) { trace!( request_id = request.request_id, - target = %request.target, + target = %self.peer_display_name(&request.target), "Already visited, dropping LookupRequest" ); return; @@ -68,7 +68,7 @@ impl Node { if request.target == *self.node_addr() { debug!( request_id = request.request_id, - origin = %request.origin, + origin = %self.peer_display_name(&request.origin), "We are the lookup target, generating response" ); self.send_lookup_response(&request).await; @@ -81,7 +81,7 @@ impl Node { } else { trace!( request_id = request.request_id, - target = %request.target, + target = %self.peer_display_name(&request.target), "LookupRequest TTL exhausted, not forwarding" ); } @@ -102,7 +102,7 @@ impl Node { let response = match LookupResponse::decode(payload) { Ok(resp) => resp, Err(e) => { - debug!(from = %from, error = %e, "Malformed LookupResponse"); + debug!(from = %self.peer_display_name(from), error = %e, "Malformed LookupResponse"); return; } }; @@ -116,15 +116,15 @@ impl Node { debug!( request_id = response.request_id, - target = %response.target, - next_hop = %from_peer, + target = %self.peer_display_name(&response.target), + next_hop = %self.peer_display_name(&from_peer), "Reverse-path forwarding LookupResponse" ); let encoded = response.encode(); if let Err(e) = self.send_encrypted_link_message(&from_peer, &encoded).await { debug!( - next_hop = %from_peer, + next_hop = %self.peer_display_name(&from_peer), error = %e, "Failed to forward LookupResponse" ); @@ -133,7 +133,7 @@ impl Node { // We originated this request — cache the discovered coordinates debug!( request_id = response.request_id, - target = %response.target, + target = %self.peer_display_name(&response.target), depth = response.target_coords.depth(), "Received LookupResponse, caching route" ); @@ -158,7 +158,7 @@ impl Node { let n = self.config.node.session.coords_warmup_packets; entry.set_coords_warmup_remaining(n); debug!( - dest = %target, + dest = %self.peer_display_name(&target), warmup_packets = n, "Reset coords warmup after discovery for existing session" ); @@ -202,7 +202,7 @@ impl Node { recent.from_peer } else { debug!( - origin = %request.origin, + origin = %self.peer_display_name(&request.origin), "Cannot route LookupResponse: no path to origin" ); return; @@ -212,15 +212,15 @@ impl Node { debug!( request_id = request.request_id, - origin = %request.origin, - next_hop = %next_hop_addr, + origin = %self.peer_display_name(&request.origin), + next_hop = %self.peer_display_name(&next_hop_addr), "Sending LookupResponse" ); let encoded = response.encode(); if let Err(e) = self.send_encrypted_link_message(&next_hop_addr, &encoded).await { debug!( - next_hop = %next_hop_addr, + next_hop = %self.peer_display_name(&next_hop_addr), error = %e, "Failed to send LookupResponse" ); @@ -253,7 +253,7 @@ impl Node { debug!( request_id = request.request_id, - target = %request.target, + target = %self.peer_display_name(&request.target), ttl = request.ttl, peer_count = forward_to.len(), "Forwarding LookupRequest" @@ -264,7 +264,7 @@ impl Node { for peer_addr in forward_to { if let Err(e) = self.send_encrypted_link_message(&peer_addr, &encoded).await { debug!( - peer = %peer_addr, + peer = %self.peer_display_name(&peer_addr), error = %e, "Failed to forward LookupRequest to peer" ); @@ -289,7 +289,7 @@ impl Node { debug!( request_id = request.request_id, - target = %target, + target = %self.peer_display_name(target), ttl = ttl, "Initiating LookupRequest" ); @@ -301,7 +301,7 @@ impl Node { for peer_addr in peer_addrs { if let Err(e) = self.send_encrypted_link_message(&peer_addr, &encoded).await { debug!( - peer = %peer_addr, + peer = %self.peer_display_name(&peer_addr), error = %e, "Failed to send LookupRequest to peer" ); diff --git a/src/node/handlers/dispatch.rs b/src/node/handlers/dispatch.rs index 5303d78..47b80ca 100644 --- a/src/node/handlers/dispatch.rs +++ b/src/node/handlers/dispatch.rs @@ -63,13 +63,13 @@ impl Node { let disconnect = match crate::protocol::Disconnect::decode(payload) { Ok(msg) => msg, Err(e) => { - debug!(from = %from, error = %e, "Malformed disconnect message"); + debug!(from = %self.peer_display_name(from), error = %e, "Malformed disconnect message"); return; } }; info!( - node_addr = %from, + peer = %self.peer_display_name(from), reason = %disconnect.reason, "Peer sent disconnect notification" ); @@ -89,14 +89,17 @@ impl Node { let peer = match self.peers.remove(node_addr) { Some(p) => p, None => { - debug!(node_addr = %node_addr, "Peer already removed"); + debug!(peer = %self.peer_display_name(node_addr), "Peer already removed"); return; } }; // MMP teardown log (before we drop the peer) if let Some(mmp) = peer.mmp() { - Self::log_mmp_teardown(node_addr, mmp); + let name = self.peer_aliases.get(node_addr) + .cloned() + .unwrap_or_else(|| peer.identity().short_npub()); + Self::log_mmp_teardown(&name, mmp); } let link_id = peer.link_id(); @@ -126,7 +129,7 @@ impl Node { self.bloom_state.mark_all_updates_needed(remaining_peers); info!( - node_addr = %node_addr, + peer = %self.peer_display_name(node_addr), link_id = %link_id, tree_changed = tree_changed, "Peer removed and state cleaned up" diff --git a/src/node/handlers/encrypted.rs b/src/node/handlers/encrypted.rs index ec762ac..53c429e 100644 --- a/src/node/handlers/encrypted.rs +++ b/src/node/handlers/encrypted.rs @@ -47,7 +47,7 @@ impl Node { Some(s) => s, None => { warn!( - node_addr = %node_addr, + peer = %self.peer_display_name(&node_addr), "Peer in index map has no session" ); return; @@ -64,7 +64,7 @@ impl Node { Ok(p) => p, Err(e) => { debug!( - node_addr = %node_addr, + peer = %self.peer_display_name(&node_addr), counter = header.counter, error = %e, "Decryption failed" @@ -80,7 +80,7 @@ impl Node { Some(parts) => parts, None => { debug!( - node_addr = %node_addr, + peer = %self.peer_display_name(&node_addr), len = plaintext.len(), "Decrypted payload too short for inner header" ); diff --git a/src/node/handlers/handshake.rs b/src/node/handlers/handshake.rs index be8e1e9..04bb8c6 100644 --- a/src/node/handlers/handshake.rs +++ b/src/node/handlers/handshake.rs @@ -165,14 +165,14 @@ impl Node { match result { PromotionResult::Promoted(node_addr) => { info!( - node_addr = %node_addr, + peer = %self.peer_display_name(&node_addr), link_id = %link_id, our_index = %our_index, "Inbound peer promoted to active" ); // Send initial tree announce to new peer if let Err(e) = self.send_tree_announce_to_peer(&node_addr).await { - debug!(peer = %node_addr, error = %e, "Failed to send initial TreeAnnounce"); + debug!(peer = %self.peer_display_name(&node_addr), error = %e, "Failed to send initial TreeAnnounce"); } // Schedule filter announce (sent on next tick via debounce) self.bloom_state.mark_update_needed(node_addr); @@ -181,13 +181,13 @@ impl Node { // Clean up the losing connection's link self.remove_link(&loser_link_id); info!( - node_addr = %node_addr, + peer = %self.peer_display_name(&node_addr), loser_link_id = %loser_link_id, "Inbound cross-connection won, loser link cleaned up" ); // Send initial tree announce to peer (new or reconnected) if let Err(e) = self.send_tree_announce_to_peer(&node_addr).await { - debug!(peer = %node_addr, error = %e, "Failed to send initial TreeAnnounce"); + debug!(peer = %self.peer_display_name(&node_addr), error = %e, "Failed to send initial TreeAnnounce"); } // Schedule filter announce (sent on next tick via debounce) self.bloom_state.mark_update_needed(node_addr); @@ -285,7 +285,7 @@ impl Node { let peer_node_addr = *peer_identity.node_addr(); info!( - node_addr = %peer_node_addr, + peer = %self.peer_display_name(&peer_node_addr), link_id = %link_id, their_index = %header.sender_idx, "Outbound handshake completed" @@ -327,7 +327,7 @@ impl Node { match (outbound_session, outbound_our_index) { (Some(s), Some(idx)) => (s, idx), _ => { - warn!(node_addr = %peer_node_addr, "Incomplete outbound connection"); + warn!(peer = %self.peer_display_name(&peer_node_addr), "Incomplete outbound connection"); self.pending_outbound.remove(&key); return; } @@ -352,7 +352,7 @@ impl Node { ); info!( - node_addr = %peer_node_addr, + peer = %self.peer_display_name(&peer_node_addr), new_our_index = %outbound_our_index, new_their_index = %header.sender_idx, "Cross-connection: swapped to outbound session (our outbound wins)" @@ -372,7 +372,7 @@ impl Node { if let Some(peer) = self.peers.get(&peer_node_addr) { info!( - node_addr = %peer_node_addr, + peer = %self.peer_display_name(&peer_node_addr), kept_their_index = ?peer.their_index(), "Cross-connection: keeping inbound session and original their_index (peer outbound wins)" ); @@ -390,7 +390,7 @@ impl Node { // Send TreeAnnounce now that sessions are aligned if let Err(e) = self.send_tree_announce_to_peer(&peer_node_addr).await { - debug!(peer = %peer_node_addr, error = %e, "Failed to send TreeAnnounce after cross-connection resolution"); + debug!(peer = %self.peer_display_name(&peer_node_addr), error = %e, "Failed to send TreeAnnounce after cross-connection resolution"); } // Schedule filter announce (sent on next tick via debounce) self.bloom_state.mark_update_needed(peer_node_addr); @@ -406,12 +406,12 @@ impl Node { match result { PromotionResult::Promoted(node_addr) => { info!( - node_addr = %node_addr, + peer = %self.peer_display_name(&node_addr), "Peer promoted to active" ); // Send initial tree announce to new peer if let Err(e) = self.send_tree_announce_to_peer(&node_addr).await { - debug!(peer = %node_addr, error = %e, "Failed to send initial TreeAnnounce"); + debug!(peer = %self.peer_display_name(&node_addr), error = %e, "Failed to send initial TreeAnnounce"); } // Schedule filter announce (sent on next tick via debounce) self.bloom_state.mark_update_needed(node_addr); @@ -425,13 +425,13 @@ impl Node { link_id, ); info!( - node_addr = %node_addr, + peer = %self.peer_display_name(&node_addr), loser_link_id = %loser_link_id, "Outbound cross-connection won, loser link cleaned up" ); // Send initial tree announce to peer (new or reconnected) if let Err(e) = self.send_tree_announce_to_peer(&node_addr).await { - debug!(peer = %node_addr, error = %e, "Failed to send initial TreeAnnounce"); + debug!(peer = %self.peer_display_name(&node_addr), error = %e, "Failed to send initial TreeAnnounce"); } // Schedule filter announce (sent on next tick via debounce) self.bloom_state.mark_update_needed(node_addr); @@ -561,7 +561,7 @@ impl Node { self.register_identity(peer_node_addr, verified_identity.pubkey_full()); info!( - node_addr = %peer_node_addr, + peer = %self.peer_display_name(&peer_node_addr), winner_link = %link_id, loser_link = %loser_link_id, "Cross-connection resolved: this connection won" @@ -577,7 +577,7 @@ impl Node { let _ = self.index_allocator.free(our_index); info!( - node_addr = %peer_node_addr, + peer = %self.peer_display_name(&peer_node_addr), winner_link = %existing_link_id, loser_link = %link_id, "Cross-connection resolved: this connection lost" @@ -608,7 +608,7 @@ impl Node { for pending_link_id in &pending_to_same_peer { debug!( - node_addr = %peer_node_addr, + peer = %self.peer_display_name(&peer_node_addr), pending_link_id = %pending_link_id, promoted_link_id = %link_id, "Deferring cleanup of pending outbound (awaiting msg2 for index update)" @@ -643,7 +643,7 @@ impl Node { self.register_identity(peer_node_addr, verified_identity.pubkey_full()); info!( - node_addr = %peer_node_addr, + peer = %self.peer_display_name(&peer_node_addr), link_id = %link_id, our_index = %our_index, their_index = %their_index, diff --git a/src/node/handlers/mmp.rs b/src/node/handlers/mmp.rs index 76279ea..7a0adeb 100644 --- a/src/node/handlers/mmp.rs +++ b/src/node/handlers/mmp.rs @@ -38,7 +38,7 @@ impl Node { let sr = match SenderReport::decode(payload) { Ok(sr) => sr, Err(e) => { - debug!(from = %from, error = %e, "Malformed SenderReport"); + debug!(from = %self.peer_display_name(from), error = %e, "Malformed SenderReport"); return; } }; @@ -46,7 +46,7 @@ impl Node { let peer = match self.peers.get_mut(from) { Some(p) => p, None => { - debug!(from = %from, "SenderReport from unknown peer"); + debug!(from = %self.peer_display_name(from), "SenderReport from unknown peer"); return; } }; @@ -56,7 +56,7 @@ impl Node { } trace!( - from = %from, + from = %self.peer_display_name(from), cum_pkts = sr.cumulative_packets_sent, interval_bytes = sr.interval_bytes_sent, "Received SenderReport" @@ -75,15 +75,17 @@ impl Node { let rr = match ReceiverReport::decode(payload) { Ok(rr) => rr, Err(e) => { - debug!(from = %from, error = %e, "Malformed ReceiverReport"); + debug!(from = %self.peer_display_name(from), error = %e, "Malformed ReceiverReport"); return; } }; + let peer_name = self.peer_display_name(from); + let peer = match self.peers.get_mut(from) { Some(p) => p, None => { - debug!(from = %from, "ReceiverReport from unknown peer"); + debug!(from = %peer_name, "ReceiverReport from unknown peer"); return; } }; @@ -117,7 +119,7 @@ impl Node { } trace!( - from = %from, + from = %peer_name, rtt_ms = ?mmp.metrics.srtt_ms(), loss = format_args!("{:.1}%", mmp.metrics.loss_rate() * 100.0), etx = format_args!("{:.2}", mmp.metrics.etx), @@ -136,6 +138,11 @@ impl Node { let mut receiver_reports: Vec<(NodeAddr, Vec)> = Vec::new(); for (node_addr, peer) in self.peers.iter_mut() { + // Compute display name before taking mutable MMP borrow + let peer_name = self.peer_aliases.get(node_addr) + .cloned() + .unwrap_or_else(|| peer.identity().short_npub()); + let Some(mmp) = peer.mmp_mut() else { continue; }; @@ -160,7 +167,7 @@ impl Node { // Periodic operator logging if mmp.should_log(now) { - Self::log_mmp_metrics(node_addr, mmp); + Self::log_mmp_metrics(&peer_name, mmp); mmp.mark_logged(now); } } @@ -168,19 +175,19 @@ 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 { - debug!(peer = %node_addr, error = %e, "Failed to send SenderReport"); + debug!(peer = %self.peer_display_name(&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 { - debug!(peer = %node_addr, error = %e, "Failed to send ReceiverReport"); + debug!(peer = %self.peer_display_name(&node_addr), error = %e, "Failed to send ReceiverReport"); } } } /// Emit periodic MMP metrics for a peer at info and debug levels. - fn log_mmp_metrics(node_addr: &NodeAddr, mmp: &crate::mmp::MmpPeerState) { + fn log_mmp_metrics(peer_name: &str, mmp: &crate::mmp::MmpPeerState) { let m = &mmp.metrics; let rtt_str = match m.srtt_ms() { @@ -196,7 +203,7 @@ impl Node { // Info-level: concise summary info!( - peer = %node_addr, + peer = %peer_name, rtt = %rtt_str, loss = format_args!("{:.1}%", loss_pct), goodput = %goodput_str, @@ -207,7 +214,7 @@ impl Node { // Debug-level: extended details debug!( - peer = %node_addr, + peer = %peer_name, jitter_us = mmp.receiver.jitter_us(), reorder = mmp.receiver.cumulative_packets_recv(), rtt_trend = format_args!("{}", if m.rtt_trend.initialized() { @@ -228,7 +235,7 @@ impl Node { } /// Emit a teardown log summarizing lifetime MMP metrics for a removed peer. - pub(in crate::node) fn log_mmp_teardown(node_addr: &NodeAddr, mmp: &crate::mmp::MmpPeerState) { + pub(in crate::node) fn log_mmp_teardown(peer_name: &str, mmp: &crate::mmp::MmpPeerState) { let m = &mmp.metrics; let rtt_str = match m.srtt_ms() { @@ -237,7 +244,7 @@ impl Node { }; info!( - peer = %node_addr, + peer = %peer_name, rtt = %rtt_str, loss = format_args!("{:.1}%", m.loss_rate() * 100.0), etx = format_args!("{:.2}", m.etx), @@ -263,6 +270,14 @@ impl Node { let mut reports: Vec<(NodeAddr, u8, Vec)> = Vec::new(); for (dest_addr, entry) in self.sessions.iter_mut() { + // Compute display name before taking mutable MMP borrow + let session_name = self.peer_aliases.get(dest_addr) + .cloned() + .unwrap_or_else(|| { + let (xonly, _) = entry.remote_pubkey().x_only_public_key(); + crate::PeerIdentity::from_pubkey(xonly).short_npub() + }); + let Some(mmp) = entry.mmp_mut() else { continue; }; @@ -309,7 +324,7 @@ impl Node { // Periodic operator logging if mmp.should_log(now) { - Self::log_session_mmp_metrics(dest_addr, mmp); + Self::log_session_mmp_metrics(&session_name, mmp); mmp.mark_logged(now); } } @@ -318,7 +333,7 @@ impl Node { for (dest_addr, msg_type, body) in reports { if let Err(e) = self.send_session_msg(&dest_addr, msg_type, &body).await { debug!( - dest = %dest_addr, + dest = %self.peer_display_name(&dest_addr), msg_type, error = %e, "Failed to send session MMP report" @@ -328,7 +343,7 @@ impl Node { } /// Emit periodic session MMP metrics at info and debug levels. - fn log_session_mmp_metrics(dest_addr: &NodeAddr, mmp: &MmpSessionState) { + fn log_session_mmp_metrics(session_name: &str, mmp: &MmpSessionState) { let m = &mmp.metrics; let rtt_str = match m.srtt_ms() { @@ -343,7 +358,7 @@ impl Node { let observed_mtu = mmp.path_mtu.last_observed_mtu(); info!( - session = %dest_addr, + session = %session_name, rtt = %rtt_str, loss = format_args!("{:.1}%", loss_pct), goodput = %goodput_str, @@ -355,7 +370,7 @@ impl Node { ); debug!( - session = %dest_addr, + session = %session_name, jitter_us = mmp.receiver.jitter_us(), rtt_trend = format_args!("{}", if m.rtt_trend.initialized() { format!("short={:.1} long={:.1}", m.rtt_trend.short(), m.rtt_trend.long()) @@ -375,7 +390,7 @@ impl Node { } /// Emit a teardown log summarizing lifetime session MMP metrics. - pub(in crate::node) fn log_session_mmp_teardown(dest_addr: &NodeAddr, mmp: &MmpSessionState) { + pub(in crate::node) fn log_session_mmp_teardown(session_name: &str, mmp: &MmpSessionState) { let m = &mmp.metrics; let rtt_str = match m.srtt_ms() { @@ -384,7 +399,7 @@ impl Node { }; info!( - session = %dest_addr, + session = %session_name, rtt = %rtt_str, loss = format_args!("{:.1}%", m.loss_rate() * 100.0), etx = format_args!("{:.2}", m.etx), diff --git a/src/node/handlers/session.rs b/src/node/handlers/session.rs index 33d58f7..141d557 100644 --- a/src/node/handlers/session.rs +++ b/src/node/handlers/session.rs @@ -135,7 +135,7 @@ impl Node { let mut entry = match self.sessions.remove(src_addr) { Some(e) => e, None => { - debug!(src = %src_addr, "Encrypted session message for unknown session"); + debug!(src = %self.peer_display_name(src_addr), "Encrypted session message for unknown session"); return; } }; @@ -145,7 +145,7 @@ impl Node { let handshake = match old_state { Some(EndToEndState::Responding(hs)) => hs, _ => { - debug!(src = %src_addr, "Unexpected state during Responding transition"); + debug!(src = %self.peer_display_name(src_addr), "Unexpected state during Responding transition"); return; } }; @@ -160,14 +160,14 @@ 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); - info!(src = %src_addr, "Session established (responder, on first encrypted message)"); + info!(src = %self.peer_display_name(src_addr), "Session established (responder, on first encrypted message)"); } // Decrypt with AAD = the 12-byte header let session = match entry.state_mut() { EndToEndState::Established(s) => s, _ => { - debug!(src = %src_addr, "Encrypted message but session not established"); + debug!(src = %self.peer_display_name(src_addr), "Encrypted message but session not established"); self.sessions.insert(*src_addr, entry); return; } @@ -181,7 +181,7 @@ impl Node { Ok(pt) => pt, Err(e) => { debug!( - error = %e, src = %src_addr, counter = header.counter, + error = %e, src = %self.peer_display_name(src_addr), counter = header.counter, "Session AEAD decryption failed" ); self.sessions.insert(*src_addr, entry); @@ -195,7 +195,7 @@ impl Node { let (timestamp, msg_type, inner_flags_byte, rest) = match fsp_strip_inner_header(&plaintext) { Some(parts) => parts, None => { - debug!(src = %src_addr, "Decrypted payload too short for FSP inner header"); + debug!(src = %self.peer_display_name(src_addr), "Decrypted payload too short for FSP inner header"); return; } }; @@ -236,7 +236,7 @@ impl Node { } } else { trace!( - src = %src_addr, + src = %self.peer_display_name(src_addr), "DataPacket decrypted (no TUN interface, plaintext dropped)" ); } @@ -251,7 +251,7 @@ impl Node { self.handle_session_path_mtu_notification(src_addr, rest); } _ => { - debug!(src = %src_addr, msg_type, "Unknown session message type, dropping"); + debug!(src = %self.peer_display_name(src_addr), msg_type, "Unknown session message type, dropping"); } } @@ -298,25 +298,25 @@ impl Node { if self.identity.node_addr() < src_addr { // We win — drop their setup, they'll process ours debug!( - src = %src_addr, + src = %self.peer_display_name(src_addr), "Simultaneous session initiation: we win (smaller addr), dropping their setup" ); return; } // We lose — discard our pending handshake, become responder below debug!( - src = %src_addr, + src = %self.peer_display_name(src_addr), "Simultaneous session initiation: we lose, becoming responder" ); } EndToEndState::Responding(_) => { // Duplicate setup while we already responded — drop - debug!(src = %src_addr, "Duplicate SessionSetup, already responding"); + debug!(src = %self.peer_display_name(src_addr), "Duplicate SessionSetup, already responding"); return; } EndToEndState::Established(_) => { // Re-establishment: replace existing session below - debug!(src = %src_addr, "Session re-establishment from peer"); + debug!(src = %self.peer_display_name(src_addr), "Session re-establishment from peer"); } } } @@ -360,7 +360,7 @@ impl Node { // Route the ack back to the initiator if let Err(e) = self.send_session_datagram(&mut datagram).await { - debug!(error = %e, dest = %src_addr, "Failed to send SessionAck"); + debug!(error = %e, dest = %self.peer_display_name(src_addr), "Failed to send SessionAck"); return; } @@ -369,7 +369,7 @@ impl Node { let entry = SessionEntry::new(*src_addr, remote_pubkey, EndToEndState::Responding(handshake), now_ms, false); self.sessions.insert(*src_addr, entry); - debug!(src = %src_addr, "SessionSetup processed, SessionAck sent"); + debug!(src = %self.peer_display_name(src_addr), "SessionSetup processed, SessionAck sent"); } /// Handle an incoming SessionAck (Noise IK msg2). @@ -397,7 +397,7 @@ impl Node { let mut entry = match self.sessions.remove(src_addr) { Some(e) => e, None => { - debug!(src = %src_addr, "SessionAck for unknown session"); + debug!(src = %self.peer_display_name(src_addr), "SessionAck for unknown session"); return; } }; @@ -406,7 +406,7 @@ impl Node { let handshake = match entry.take_state() { Some(EndToEndState::Initiating(hs)) => hs, _ => { - debug!(src = %src_addr, "SessionAck but session not in Initiating state"); + debug!(src = %self.peer_display_name(src_addr), "SessionAck but session not in Initiating state"); // Put it back self.sessions.insert(*src_addr, entry); return; @@ -434,7 +434,7 @@ impl Node { // Flush any queued outbound packets for this destination self.flush_pending_packets(src_addr).await; - info!(src = %src_addr, "Session established (initiator)"); + info!(src = %self.peer_display_name(src_addr), "Session established (initiator)"); } // === Session-layer MMP report handlers === @@ -447,13 +447,13 @@ impl Node { let sr = match SessionSenderReport::decode(body) { Ok(sr) => sr, Err(e) => { - debug!(src = %src_addr, error = %e, "Malformed SessionSenderReport"); + debug!(src = %self.peer_display_name(src_addr), error = %e, "Malformed SessionSenderReport"); return; } }; trace!( - src = %src_addr, + src = %self.peer_display_name(src_addr), cum_pkts = sr.cumulative_packets_sent, interval_bytes = sr.interval_bytes_sent, "Received SessionSenderReport" @@ -468,7 +468,7 @@ impl Node { let session_rr = match SessionReceiverReport::decode(body) { Ok(rr) => rr, Err(e) => { - debug!(src = %src_addr, error = %e, "Malformed SessionReceiverReport"); + debug!(src = %self.peer_display_name(src_addr), error = %e, "Malformed SessionReceiverReport"); return; } }; @@ -477,10 +477,11 @@ impl Node { let rr: ReceiverReport = ReceiverReport::from(&session_rr); let now_ms = Self::now_ms(); + let peer_name = self.peer_display_name(src_addr); let entry = match self.sessions.get_mut(src_addr) { Some(e) => e, None => { - debug!(src = %src_addr, "SessionReceiverReport for unknown session"); + debug!(src = %peer_name, "SessionReceiverReport for unknown session"); return; } }; @@ -520,7 +521,7 @@ impl Node { } trace!( - src = %src_addr, + src = %peer_name, rtt_ms = ?mmp.metrics.srtt_ms(), loss = format_args!("{:.1}%", mmp.metrics.loss_rate() * 100.0), "Processed SessionReceiverReport" @@ -535,15 +536,16 @@ impl Node { let notif = match PathMtuNotification::decode(body) { Ok(n) => n, Err(e) => { - debug!(src = %src_addr, error = %e, "Malformed PathMtuNotification"); + debug!(src = %self.peer_display_name(src_addr), error = %e, "Malformed PathMtuNotification"); return; } }; + let peer_name = self.peer_display_name(src_addr); let entry = match self.sessions.get_mut(src_addr) { Some(e) => e, None => { - debug!(src = %src_addr, "PathMtuNotification for unknown session"); + debug!(src = %peer_name, "PathMtuNotification for unknown session"); return; } }; @@ -559,7 +561,7 @@ impl Node { if new_mtu != old_mtu { debug!( - src = %src_addr, + src = %peer_name, old_mtu, new_mtu, "Path MTU changed via notification" @@ -703,7 +705,7 @@ impl Node { let entry = SessionEntry::new(dest_addr, dest_pubkey, EndToEndState::Initiating(handshake), now_ms, true); self.sessions.insert(dest_addr, entry); - info!(dest = %dest_addr, "Session initiation started"); + info!(dest = %self.peer_display_name(&dest_addr), "Session initiation started"); Ok(()) } @@ -977,7 +979,7 @@ impl Node { if let Some(entry) = self.sessions.get(&dest_addr) { if entry.is_established() { if let Err(e) = self.send_session_data(&dest_addr, &ipv6_packet).await { - debug!(dest = %dest_addr, error = %e, "Failed to send TUN packet via session"); + debug!(dest = %self.peer_display_name(&dest_addr), error = %e, "Failed to send TUN packet via session"); } return; } @@ -990,7 +992,7 @@ impl Node { // If session initiation fails (no route), trigger discovery and // queue the packet for retry when discovery completes. if let Err(e) = self.initiate_session(dest_addr, dest_pubkey).await { - debug!(dest = %dest_addr, error = %e, "Failed to initiate session, trying discovery"); + debug!(dest = %self.peer_display_name(&dest_addr), error = %e, "Failed to initiate session, trying discovery"); self.maybe_initiate_lookup(&dest_addr).await; self.queue_pending_packet(dest_addr, ipv6_packet); return; @@ -1086,7 +1088,7 @@ impl Node { }; for packet in packets { if let Err(e) = self.send_session_data(dest_addr, &packet).await { - debug!(dest = %dest_addr, error = %e, "Failed to send queued TUN packet"); + debug!(dest = %self.peer_display_name(dest_addr), error = %e, "Failed to send queued TUN packet"); break; } } @@ -1104,7 +1106,7 @@ impl Node { let dest_pubkey = match self.lookup_by_fips_prefix(&prefix) { Some((_, pk)) => pk, None => { - debug!(dest = %dest_addr, "Discovery complete but no identity for session retry"); + debug!(dest = %self.peer_display_name(&dest_addr), "Discovery complete but no identity for session retry"); return; } }; @@ -1118,10 +1120,10 @@ impl Node { match self.initiate_session(dest_addr, dest_pubkey).await { Ok(()) => { - debug!(dest = %dest_addr, "Session initiated after discovery"); + debug!(dest = %self.peer_display_name(&dest_addr), "Session initiated after discovery"); } Err(e) => { - debug!(dest = %dest_addr, error = %e, "Session retry after discovery failed"); + debug!(dest = %self.peer_display_name(&dest_addr), error = %e, "Session retry after discovery failed"); } } } diff --git a/src/node/handlers/timeout.rs b/src/node/handlers/timeout.rs index 1e348f0..ea7ca5f 100644 --- a/src/node/handlers/timeout.rs +++ b/src/node/handlers/timeout.rs @@ -98,16 +98,19 @@ impl Node { .collect(); for addr in idle { + // Compute display name before removing the session + let name = self.peer_display_name(&addr); + // Log MMP teardown metrics before removing the session if let Some(entry) = self.sessions.get(&addr) && let Some(mmp) = entry.mmp() { - Self::log_session_mmp_teardown(&addr, mmp); + Self::log_session_mmp_teardown(&name, mmp); } self.sessions.remove(&addr); self.pending_tun_packets.remove(&addr); debug!( - dest = %addr, + dest = %name, idle_secs = timeout_ms / 1000, "Idle session removed (no application data)" ); diff --git a/src/node/lifecycle.rs b/src/node/lifecycle.rs index fa7c445..6bc67a0 100644 --- a/src/node/lifecycle.rs +++ b/src/node/lifecycle.rs @@ -17,6 +17,17 @@ impl Node { /// For each peer configured with AutoConnect policy, creates a link and /// peer entry, then starts the Noise handshake by sending the first message. pub(super) async fn initiate_peer_connections(&mut self) { + // Build display name map from all configured peers (alias or short npub) + for peer_config in self.config.peers() { + if let Ok(identity) = PeerIdentity::from_npub(&peer_config.npub) { + let name = peer_config + .alias + .clone() + .unwrap_or_else(|| identity.short_npub()); + self.peer_aliases.insert(*identity.node_addr(), name); + } + } + // Collect peer configs to avoid borrow conflicts let peer_configs: Vec<_> = self.config.auto_connect_peers().cloned().collect(); @@ -160,19 +171,14 @@ impl Node { // Build wire format msg1: [0x01][sender_idx:4 LE][noise_msg1:82] let wire_msg1 = build_msg1(our_index, &noise_msg1); - let alias_display = peer_config - .alias - .as_deref() - .map(|a| format!(" ({})", a)) - .unwrap_or_default(); - - 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); + debug!( + peer = %self.peer_display_name(&peer_node_addr), + transport = %addr.transport, + addr = %addr.addr, + link_id = %link_id, + our_index = %our_index, + "Peer connection initiated" + ); // Track in pending_outbound for msg2 dispatch self.pending_outbound.insert((transport_id, our_index.as_u32()), link_id); @@ -447,7 +453,7 @@ impl Node { Ok(()) => sent += 1, Err(e) => { debug!( - node_addr = %node_addr, + peer = %self.peer_display_name(node_addr), error = %e, "Failed to send disconnect (transport may be down)" ); diff --git a/src/node/mod.rs b/src/node/mod.rs index 0b194ab..5dd90f9 100644 --- a/src/node/mod.rs +++ b/src/node/mod.rs @@ -32,7 +32,7 @@ use crate::tree::TreeState; use crate::upper::icmp_rate_limit::IcmpRateLimiter; use crate::upper::tun::{TunError, TunOutboundRx, TunState, TunTx}; use self::wire::{build_encrypted, build_established_header, prepend_inner_header, FLAG_SP}; -use crate::{Config, ConfigError, Identity, IdentityError, NodeAddr}; +use crate::{Config, ConfigError, Identity, IdentityError, NodeAddr, PeerIdentity}; use std::collections::{HashMap, VecDeque}; use std::fmt; use std::thread::JoinHandle; @@ -326,6 +326,11 @@ pub struct Node { /// or fails, and removed on successful promotion or when max retries /// are exhausted. retry_pending: HashMap, + + // === Display Names === + /// Human-readable names for configured peers (alias or short npub). + /// Populated at startup from peer config. + peer_aliases: HashMap, } impl Node { @@ -409,6 +414,7 @@ impl Node { icmp_rate_limiter: IcmpRateLimiter::new(), routing_error_rate_limiter: RoutingErrorRateLimiter::new(), retry_pending: HashMap::new(), + peer_aliases: HashMap::new(), }) } @@ -485,6 +491,7 @@ impl Node { icmp_rate_limiter: IcmpRateLimiter::new(), routing_error_rate_limiter: RoutingErrorRateLimiter::new(), retry_pending: HashMap::new(), + peer_aliases: HashMap::new(), } } @@ -551,6 +558,27 @@ impl Node { self.identity.npub() } + /// Return a human-readable display name for a NodeAddr. + /// + /// Lookup order: + /// 1. Configured peer alias or short npub (from startup map) + /// 2. Active peer's short npub (e.g., inbound peer not in config) + /// 3. Session endpoint's short npub (end-to-end, may not be direct peer) + /// 4. Truncated NodeAddr hex (unknown address) + pub(crate) fn peer_display_name(&self, addr: &NodeAddr) -> String { + if let Some(name) = self.peer_aliases.get(addr) { + return name.clone(); + } + if let Some(peer) = self.peers.get(addr) { + return peer.identity().short_npub(); + } + if let Some(entry) = self.sessions.get(addr) { + let (xonly, _) = entry.remote_pubkey().x_only_public_key(); + return PeerIdentity::from_pubkey(xonly).short_npub(); + } + addr.short_hex() + } + // === Configuration === /// Get the configuration. diff --git a/src/node/retry.rs b/src/node/retry.rs index bc1af66..0414d4c 100644 --- a/src/node/retry.rs +++ b/src/node/retry.rs @@ -64,13 +64,14 @@ impl Node { let base_interval_ms = retry_cfg.base_interval_secs * 1000; let max_backoff_ms = retry_cfg.max_backoff_secs * 1000; + let peer_name = self.peer_display_name(&node_addr); if let Some(state) = self.retry_pending.get_mut(&node_addr) { // Already tracking — increment state.retry_count += 1; if state.retry_count > max_retries { info!( - node_addr = %node_addr, + peer = %peer_name, attempts = state.retry_count, "Max retries exhausted, giving up on peer" ); @@ -80,7 +81,7 @@ impl Node { let delay = state.backoff_ms(base_interval_ms, max_backoff_ms); state.retry_after_ms = now_ms + delay; debug!( - node_addr = %node_addr, + peer = %peer_name, retry = state.retry_count, delay_secs = delay / 1000, "Scheduling connection retry" @@ -103,7 +104,7 @@ impl Node { let delay = state.backoff_ms(base_interval_ms, max_backoff_ms); state.retry_after_ms = now_ms + delay; debug!( - node_addr = %node_addr, + peer = %self.peer_display_name(&node_addr), delay_secs = delay / 1000, "First connection attempt failed, scheduling retry" ); @@ -145,7 +146,7 @@ impl Node { }; debug!( - node_addr = %node_addr, + peer = %self.peer_display_name(&node_addr), retry = state.retry_count, "Attempting connection retry" ); @@ -155,7 +156,7 @@ impl Node { match self.initiate_peer_connection(&peer_config).await { Ok(()) => { debug!( - node_addr = %node_addr, + peer = %self.peer_display_name(&node_addr), "Retry connection initiated" ); // Don't remove from retry_pending — wait for promotion @@ -163,7 +164,7 @@ impl Node { } Err(e) => { warn!( - node_addr = %node_addr, + peer = %self.peer_display_name(&node_addr), error = %e, "Retry connection initiation failed" ); diff --git a/src/node/session.rs b/src/node/session.rs index a7db99e..6bc91fd 100644 --- a/src/node/session.rs +++ b/src/node/session.rs @@ -47,7 +47,6 @@ pub(crate) struct SessionEntry { #[allow(dead_code)] remote_addr: NodeAddr, /// Remote node's static public key (for Noise IK). - #[allow(dead_code)] remote_pubkey: PublicKey, /// Current session state. `None` only during state transitions. state: Option, @@ -95,6 +94,11 @@ impl SessionEntry { } } + /// Get the remote node's public key. + pub(crate) fn remote_pubkey(&self) -> &PublicKey { + &self.remote_pubkey + } + /// Get the current session state. pub(crate) fn state(&self) -> &EndToEndState { self.state.as_ref().expect("session state taken but not restored") diff --git a/src/node/tree.rs b/src/node/tree.rs index 52916d6..5a2b630 100644 --- a/src/node/tree.rs +++ b/src/node/tree.rs @@ -47,7 +47,7 @@ impl Node { if !peer.can_send_tree_announce(now_ms) { peer.mark_tree_announce_pending(); debug!( - peer = %peer_addr, + peer = %self.peer_display_name(peer_addr), "TreeAnnounce rate-limited, marking pending" ); return Ok(()); @@ -68,7 +68,7 @@ impl Node { peer.record_tree_announce_sent(now_ms); } - trace!(peer = %peer_addr, "Sent TreeAnnounce"); + trace!(peer = %self.peer_display_name(peer_addr), "Sent TreeAnnounce"); Ok(()) } @@ -79,7 +79,7 @@ impl Node { for peer_addr in peer_addrs { if let Err(e) = self.send_tree_announce_to_peer(&peer_addr).await { debug!( - peer = %peer_addr, + peer = %self.peer_display_name(&peer_addr), error = %e, "Failed to send TreeAnnounce" ); @@ -104,7 +104,7 @@ impl Node { for peer_addr in ready { if let Err(e) = self.send_tree_announce_to_peer(&peer_addr).await { debug!( - peer = %peer_addr, + peer = %self.peer_display_name(&peer_addr), error = %e, "Failed to send pending TreeAnnounce" ); @@ -123,7 +123,7 @@ impl Node { let announce = match TreeAnnounce::decode(payload) { Ok(a) => a, Err(e) => { - debug!(from = %from, error = %e, "Malformed TreeAnnounce"); + debug!(from = %self.peer_display_name(from), error = %e, "Malformed TreeAnnounce"); return; } }; @@ -132,7 +132,7 @@ impl Node { let pubkey = match self.peers.get(from) { Some(peer) => peer.pubkey(), None => { - debug!(from = %from, "TreeAnnounce from unknown peer"); + debug!(from = %self.peer_display_name(from), "TreeAnnounce from unknown peer"); return; } }; @@ -140,7 +140,7 @@ impl Node { // The declaring node_addr in the announce should match the sender if announce.declaration.node_addr() != from { debug!( - from = %from, + from = %self.peer_display_name(from), declared = %announce.declaration.node_addr(), "TreeAnnounce node_addr mismatch" ); @@ -149,7 +149,7 @@ impl Node { if let Err(e) = announce.declaration.verify(&pubkey) { warn!( - from = %from, + from = %self.peer_display_name(from), error = %e, "TreeAnnounce signature verification failed" ); @@ -177,12 +177,12 @@ impl Node { ); if !updated { - debug!(from = %from, "TreeAnnounce not fresher than existing, ignored"); + debug!(from = %self.peer_display_name(from), "TreeAnnounce not fresher than existing, ignored"); return; } info!( - from = %from, + from = %self.peer_display_name(from), seq = announce.declaration.sequence(), depth = announce.ancestry.depth(), root = %announce.ancestry.root_id(), @@ -206,7 +206,7 @@ impl Node { self.coord_cache.clear(); info!( - new_parent = %new_parent, + new_parent = %self.peer_display_name(&new_parent), new_seq = new_seq, new_root = %self.tree_state.root(), depth = self.tree_state.my_coords().depth(), @@ -242,7 +242,7 @@ impl Node { if new_root != old_root || new_depth != old_depth { info!( - parent = %from, + parent = %self.peer_display_name(from), old_root = %old_root, new_root = %new_root, new_depth = new_depth,