Merge pull request #1800 from subspace/improve-logging

Improve logging for DSN protocols.

crates/subspace-networking/src/connected_peers.rs

@@ -79,13 +79,27 @@ enum ConnectionState {
     NotInterested,
 }
 
+impl ConnectionState {
+    /// Converts [`ConnectionState`] to a string with information loss.
+    fn stringify(&self) -> String {
+        match self {
+            ConnectionState::Connecting { .. } => "Connecting".to_string(),
+            ConnectionState::Deciding => "Deciding".to_string(),
+            ConnectionState::Permanent => "Permanent".to_string(),
+            ConnectionState::NotInterested => "NotInterested".to_string(),
+        }
+    }
+}
+
 /// Connected peers protocol configuration.
 #[derive(Debug, Clone)]
 pub struct Config {
     /// Defines a target for logging.
     pub log_target: &'static str,
     /// Interval between new dialing attempts.
     pub dialing_interval: Duration,
+    /// Interval between logging of the internal state.
+    pub logging_interval: Duration,
     /// Number of connected peers that protocol will maintain.
     pub target_connected_peers: u32,
     /// We dial peers using this batch size.
@@ -101,6 +115,7 @@ impl Default for Config {
         Self {
             log_target: DEFAULT_CONNECTED_PEERS_LOG_TARGET,
             dialing_interval: Duration::from_secs(3),
+            logging_interval: Duration::from_secs(5),
             target_connected_peers: 30,
             dialing_peer_batch_size: 5,
             decision_timeout: Duration::from_secs(10),
@@ -122,6 +137,13 @@ struct PeerConnectionDecisionUpdate {
     keep_alive: KeepAlive,
 }
 
+#[derive(Debug, Default)]
+#[allow(dead_code)] // actually, we use the fields implicitly using the `Debug` on logging.
+struct ConnectedPeerStats {
+    status_count: HashMap<String, usize>,
+    peer_status: HashMap<String, Vec<PeerId>>,
+}
+
 /// `Behaviour` for `connected peers` protocol.
 #[derive(Debug)]
 pub struct Behaviour<Instance> {
@@ -145,12 +167,16 @@ pub struct Behaviour<Instance> {
 
     /// Instance type marker.
     phantom_data: PhantomData<Instance>,
+
+    /// Delay between logging of the internal state.
+    logging_delay: Delay,
 }
 
 impl<Instance> Behaviour<Instance> {
     /// Creates a new `Behaviour`.
     pub fn new(config: Config) -> Self {
         let dialing_delay = Delay::new(config.dialing_interval);
+        let logging_delay = Delay::new(config.logging_interval);
         Self {
             config,
             known_peers: HashMap::new(),
@@ -159,6 +185,7 @@ impl<Instance> Behaviour<Instance> {
             peer_cache: Vec::new(),
             waker: None,
             phantom_data: PhantomData,
+            logging_delay,
         }
     }
 
@@ -251,6 +278,35 @@ impl<Instance> Behaviour<Instance> {
             waker.wake_by_ref()
         }
     }
+
+    fn gather_stats(&self) -> ConnectedPeerStats {
+        let status_count =
+            self.known_peers
+                .iter()
+                .fold(HashMap::new(), |mut result, (_, state)| {
+                    result
+                        .entry(state.connection_state.stringify())
+                        .and_modify(|count| *count += 1)
+                        .or_insert(1);
+                    result
+                });
+
+        let peer_status = self.known_peers.iter().fold(
+            HashMap::<String, Vec<PeerId>>::new(),
+            |mut result, (peer_id, state)| {
+                result
+                    .entry(state.connection_state.stringify())
+                    .and_modify(|peers| peers.push(*peer_id))
+                    .or_insert(vec![*peer_id]);
+                result
+            },
+        );
+
+        ConnectedPeerStats {
+            status_count,
+            peer_status,
+        }
+    }
 }
 
 impl<Instance: 'static + Send> NetworkBehaviour for Behaviour<Instance> {
@@ -372,12 +428,6 @@ impl<Instance: 'static + Send> NetworkBehaviour for Behaviour<Instance> {
 
         // Check decision statuses.
         for (peer_id, state) in self.known_peers.iter_mut() {
-            trace!(
-                %peer_id,
-                ?state,
-                target=%self.config.log_target,
-                "Peer decisions for connected peers protocol."
-            );
             match state.connection_state.clone() {
                 ConnectionState::Connecting {
                     peer_address: address,
@@ -435,6 +485,18 @@ impl<Instance: 'static + Send> NetworkBehaviour for Behaviour<Instance> {
             }
         }
 
+        // Log the internal state.
+        match self.logging_delay.poll_unpin(cx) {
+            Poll::Pending => {}
+            Poll::Ready(()) => {
+                self.logging_delay.reset(self.config.logging_interval);
+
+                let stats = self.gather_stats();
+
+                debug!(instance=%self.config.log_target, ?stats, "Connected peers protocol statistics.");
+            }
+        }
+
         self.waker.replace(cx.waker().clone());
         Poll::Pending
     }

crates/subspace-networking/src/node_runner.rs

@@ -591,8 +591,10 @@ where
                                 }
                                 _ => true,
                             };
+
                             if should_temporary_ban {
                                 self.temporary_bans.lock().create_or_extend(peer_id);
+                                debug!(%peer_id, ?error, "Peer was temporarily banned.");
                             }
                         }
                     };