From 9dd77fa10f6675e63a397e14805dd277cd81a573 Mon Sep 17 00:00:00 2001 From: Floris Bruynooghe Date: Mon, 29 Jan 2024 16:23:11 +0100 Subject: [PATCH] refactor(iroh-net): A bunch of logging improvements (#1982) - Make sure the DerpMap has a nicer Debug impl that shows the map with URLs instead of structs. - Do not log individual packets on debug level, downgrade those to trace. - Log derp URLs and URLs rather than structs in various places. - Log sending of DISCO messages on debug, these are generally interesting and do not transfer bulk data. ## Description ## Notes & open questions ## Change checklist - [x] Self-review. - [x] Documentation updates if relevant. - [x] Tests if relevant. --- iroh-net/src/derp/client.rs | 4 ++-- iroh-net/src/derp/http/client.rs | 2 +- iroh-net/src/derp/map.rs | 12 +++++++++++- iroh-net/src/magicsock.rs | 8 ++++---- iroh-net/src/magicsock/derp_actor.rs | 2 +- iroh-net/src/magicsock/peer_map/endpoint.rs | 4 ++-- 6 files changed, 21 insertions(+), 11 deletions(-) diff --git a/iroh-net/src/derp/client.rs b/iroh-net/src/derp/client.rs index 77dd033d2d..b8af5f8d5f 100644 --- a/iroh-net/src/derp/client.rs +++ b/iroh-net/src/derp/client.rs @@ -10,7 +10,7 @@ use futures::{Sink, SinkExt, StreamExt}; use tokio::io::{AsyncRead, AsyncWrite}; use tokio::sync::mpsc; use tokio_util::codec::{FramedRead, FramedWrite}; -use tracing::{debug, info_span, Instrument}; +use tracing::{debug, info_span, trace, Instrument}; use super::codec::PER_CLIENT_READ_QUEUE_DEPTH; use super::{ @@ -83,7 +83,7 @@ impl Client { /// /// Errors if the packet is larger than [`super::MAX_PACKET_SIZE`] pub async fn send(&self, dstkey: PublicKey, packet: Bytes) -> Result<()> { - debug!(%dstkey, len = packet.len(), "[DERP] send"); + trace!(%dstkey, len = packet.len(), "[DERP] send"); self.inner .writer_channel diff --git a/iroh-net/src/derp/http/client.rs b/iroh-net/src/derp/http/client.rs index 7af9036fec..b6a496bf2a 100644 --- a/iroh-net/src/derp/http/client.rs +++ b/iroh-net/src/derp/http/client.rs @@ -840,7 +840,7 @@ impl Actor { } async fn send(&mut self, dst_key: PublicKey, b: Bytes) -> Result<(), ClientError> { - debug!(dst = %dst_key.fmt_short(), len = b.len(), "send"); + trace!(dst = %dst_key.fmt_short(), len = b.len(), "send"); let (client, _, _) = self.connect().await?; if client.send(dst_key, b).await.is_err() { self.close_for_reconnect().await; diff --git a/iroh-net/src/derp/map.rs b/iroh-net/src/derp/map.rs index 815acfbf03..227e969d54 100644 --- a/iroh-net/src/derp/map.rs +++ b/iroh-net/src/derp/map.rs @@ -20,7 +20,7 @@ pub enum DerpMode { } /// Configuration of all the Derp servers that can be used. -#[derive(Debug, Clone, PartialEq, Eq)] +#[derive(Clone, PartialEq, Eq)] pub struct DerpMap { /// A map of the different derp IDs to the [`DerpNode`] information nodes: Arc>>, @@ -104,6 +104,16 @@ impl DerpMap { } } +impl fmt::Debug for DerpMap { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let mut m = f.debug_map(); + for (url, node) in self.nodes.iter() { + m.entry(&url.as_str(), node); + } + m.finish() + } +} + impl fmt::Display for DerpMap { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { fmt::Debug::fmt(&self, f) diff --git a/iroh-net/src/magicsock.rs b/iroh-net/src/magicsock.rs index 5e7054ce37..7379aef490 100644 --- a/iroh-net/src/magicsock.rs +++ b/iroh-net/src/magicsock.rs @@ -727,14 +727,14 @@ impl Inner { tx_id, node_key: self.public_key(), }); - trace!(dst = ?dst, %tx_id, ?purpose, "send ping"); + trace!(%dst, %tx_id, ?purpose, "send ping"); let sent = match dst { SendAddr::Udp(addr) => self.udp_disco_sender.try_send((addr, dst_key, msg)).is_ok(), SendAddr::Derp(ref url) => self.send_disco_message_derp(url, dst_key, msg), }; if sent { let msg_sender = self.actor_sender.clone(); - debug!(dst = ?dst, tx = %hex::encode(tx_id), ?purpose, "ping sent (queued)"); + debug!(%dst, tx = %hex::encode(tx_id), ?purpose, "ping sent (queued)"); self.node_map .notify_ping_sent(id, dst, tx_id, purpose, msg_sender); } else { @@ -756,7 +756,7 @@ impl Inner { }); ready!(self.poll_send_disco_message(dst.clone(), *dst_key, msg, cx))?; let msg_sender = self.actor_sender.clone(); - debug!(dst = ?dst, tx = %hex::encode(tx_id), ?purpose, "ping sent (polled)"); + debug!(%dst, tx = %hex::encode(tx_id), ?purpose, "ping sent (polled)"); self.node_map .notify_ping_sent(*id, dst.clone(), *tx_id, *purpose, msg_sender); Poll::Ready(Ok(())) @@ -801,7 +801,7 @@ impl Inner { } fn send_disco_message_derp(&self, url: &Url, dst_key: PublicKey, msg: disco::Message) -> bool { - trace!(node = %dst_key.fmt_short(), %url, %msg, "send disco message (derp)"); + debug!(node = %dst_key.fmt_short(), %url, %msg, "send disco message (derp)"); let pkt = self.encode_disco_message(dst_key, &msg); inc!(MagicsockMetrics, send_disco_derp); if self.try_send_derp(url, dst_key, smallvec![pkt]) { diff --git a/iroh-net/src/magicsock/derp_actor.rs b/iroh-net/src/magicsock/derp_actor.rs index a7b73338d3..71d09cc9cc 100644 --- a/iroh-net/src/magicsock/derp_actor.rs +++ b/iroh-net/src/magicsock/derp_actor.rs @@ -366,7 +366,7 @@ impl DerpActor { } async fn send_derp(&mut self, url: &Url, contents: DerpContents, peer: PublicKey) { - debug!(%url, peer = %peer.fmt_short(),len = contents.iter().map(|c| c.len()).sum::(), "sending derp"); + trace!(%url, peer = %peer.fmt_short(),len = contents.iter().map(|c| c.len()).sum::(), "sending derp"); // Derp Send let derp_client = self.connect_derp(url, Some(&peer)).await; for content in &contents { diff --git a/iroh-net/src/magicsock/peer_map/endpoint.rs b/iroh-net/src/magicsock/peer_map/endpoint.rs index 1aec773541..f82ef7c5a5 100644 --- a/iroh-net/src/magicsock/peer_map/endpoint.rs +++ b/iroh-net/src/magicsock/peer_map/endpoint.rs @@ -406,7 +406,7 @@ impl Endpoint { // queue a ping to our derper, if needed. if let Some((url, state)) = self.derp_url.as_ref() { if state.needs_ping(&now) { - debug!(?url, "node's derp needs ping"); + debug!(%url, "node's derp needs ping"); if let Some(msg) = self.start_ping(SendAddr::Derp(url.clone()), DiscoPingPurpose::Discovery) { @@ -463,7 +463,7 @@ impl Endpoint { // message to our node via DERP informing them that we've // sent so our firewall ports are probably open and now // would be a good time for them to connect. - debug!(?url, "queue call-me-maybe"); + debug!(%url, "queue call-me-maybe"); msgs.push(PingAction::SendCallMeMaybe { derp_url: url.clone(), dst_key: self.public_key,