add debug tracing for libp2p open/close

1 files changed, 63 insertions, 11 deletions

diff --git a/src/transport/p2p.rs b/src/transport/p2p.rs
index c03a0c4..fcf961e 100644
--- a/src/transport/p2p.rs
+++ b/src/transport/p2p.rs
@@ -55,7 +55,7 @@ use anyhow::{Context, Result, anyhow, bail};
 use async_trait::async_trait;
 use futures::{AsyncReadExt, AsyncWriteExt, StreamExt};
 use tokio::sync::{Semaphore, mpsc, oneshot, watch};
-use tracing::{debug, info, warn};
+use tracing::{debug, info, trace, warn};
 
 use crate::locks::MutexExt;
 use crate::transport::stats::{
@@ -379,6 +379,20 @@ fn published(all: &[Multiaddr]) -> Vec<Multiaddr> {
 }
 
 impl Book {
+    /// Whether all of `addresses` are known of `peer` (`remember`).
+    fn knows(&self, peer: PeerId, addresses: &[Multiaddr]) -> bool {
+        let Some(known) = self.addresses.get(&peer) else {
+            return false;
+        };
+        addresses.iter().all(|address| {
+            let mut address = address.clone();
+            if let Some(Protocol::P2p(_)) = address.iter().last() {
+                address.pop();
+            }
+            known.contains(&address)
+        })
+    }
+
     /// `peer` is at `address` (without its `/p2p` part): kept first.
     fn remember(&mut self, peer: PeerId, mut address: Multiaddr) {
         if let Some(Protocol::P2p(_)) = address.iter().last() {
@@ -952,6 +966,14 @@ async fn run(
                         book.touch(peer_id);
                         let relayed = endpoint.is_relayed();
                         book.connections.insert(connection_id, (peer_id, relayed));
+                        debug!(
+                            peer = %peer_id,
+                            connection = %connection_id,
+                            dialled = endpoint.is_dialer(),
+                            address = %endpoint.get_remote_address(),
+                            relayed,
+                            "libp2p connection opened"
+                        );
                     }
                     for done in connecting.remove(&peer_id).into_iter().flatten() {
                         let _ = done.send(Ok(()));
@@ -961,8 +983,14 @@ async fn run(
                         let _ = done.send(Ok(peer_id));
                     }
                 }
-                SwarmEvent::ConnectionClosed { connection_id, .. } => {
+                SwarmEvent::ConnectionClosed { peer_id, connection_id, cause, .. } => {
                     lock(&book).connections.remove(&connection_id);
+                    debug!(
+                        peer = %peer_id,
+                        connection = %connection_id,
+                        cause = ?cause,
+                        "libp2p connection closed"
+                    );
                 }
                 SwarmEvent::OutgoingConnectionError { connection_id, peer_id, error } => {
                     count_dial_failure(&mut lock(&book).counts.dial_failures, &error);
@@ -1088,18 +1116,25 @@ async fn run(
                     }
                 },
                 SwarmEvent::Behaviour(BehaviourEvent::Identify(
-                    ::libp2p::identify::Event::Received { peer_id, info, .. },
+                    ::libp2p::identify::Event::Received { connection_id, peer_id, info },
                 )) => {
-                    debug!(
-                        peer = %peer_id,
-                        listen = ?info.listen_addrs,
-                        observed = %info.observed_addr,
-                        agent = %info.agent_version,
-                        "libp2p peer identified"
-                    );
                     let mut book = lock(&book);
+                    let listen = published(&info.listen_addrs);
+                    // Every new connection identifies again: logged when it says something new.
+                    if book.knows(peer_id, &listen) {
+                        trace!(peer = %peer_id, connection = %connection_id, "libp2p peer identified again");
+                    } else {
+                        debug!(
+                            peer = %peer_id,
+                            connection = %connection_id,
+                            listen = ?info.listen_addrs,
+                            observed = %info.observed_addr,
+                            agent = %info.agent_version,
+                            "libp2p peer identified"
+                        );
+                    }
                     // Last first: `remember` puts each in front.
-                    for address in published(&info.listen_addrs).into_iter().rev() {
+                    for address in listen.into_iter().rev() {
                         book.remember(peer_id, address);
                     }
                     if relaying.public
@@ -1707,6 +1742,23 @@ mod tests {
         assert_eq!(book.discovered, [address.with_p2p(lan).unwrap()]);
     }
 
+    #[test]
+    fn known_addresses() {
+        let mut book = Book::default();
+        let (relay, us) = (peer(), peer());
+        let direct: Multiaddr = "/ip6/fd00::1/tcp/9661".parse().unwrap();
+        let relayed: Multiaddr = format!("/ip6/fd00::2/tcp/9661/p2p/{relay}/p2p-circuit/p2p/{us}")
+            .parse()
+            .unwrap();
+        assert!(!book.knows(us, &[direct.clone()]));
+        book.remember(us, relayed.clone());
+        book.remember(us, direct.clone());
+        // In any order, with or without the peer ID.
+        assert!(book.knows(us, &[relayed.clone(), direct.clone()]));
+        assert!(book.knows(us, &[direct.clone().with_p2p(us).unwrap()]));
+        assert!(!book.knows(us, &["/ip6/fd00::3/tcp/9661".parse().unwrap()]));
+    }
+
     /// Peers nobody mentions any more are forgotten, but connected ones.
     #[test]
     fn stale_peers_are_forgotten() {