From 22ed8f5f91be6007378453bacb7b17dea338d145 Mon Sep 17 00:00:00 2001
From: Bo QIU <35757521+boqiu@users.noreply.github.com>
Date: Fri, 16 Aug 2024 10:34:28 +0800
Subject: [PATCH] opt router debug logs (#160)

---
 node/router/src/libp2p_event_handler.rs | 24 +++++++++++++-----------
 node/sync/src/service.rs                |  9 ++++++---
 run/log_config_debug                    |  2 +-
 3 files changed, 20 insertions(+), 15 deletions(-)

diff --git a/node/router/src/libp2p_event_handler.rs b/node/router/src/libp2p_event_handler.rs
index 52527f1..4ef4b81 100644
--- a/node/router/src/libp2p_event_handler.rs
+++ b/node/router/src/libp2p_event_handler.rs
@@ -26,10 +26,10 @@ use crate::peer_manager::PeerManager;
 use crate::Config;
 
 lazy_static::lazy_static! {
-    pub static ref FIND_FILE_TIMEOUT: chrono::Duration = chrono::Duration::minutes(2);
-    pub static ref ANNOUNCE_FILE_TIMEOUT: chrono::Duration = chrono::Duration::minutes(2);
-    pub static ref ANNOUNCE_SHARD_CONFIG_TIMEOUT: chrono::Duration = chrono::Duration::minutes(2);
-    pub static ref TOLERABLE_DRIFT: chrono::Duration = chrono::Duration::seconds(5);
+    pub static ref FIND_FILE_TIMEOUT: chrono::Duration = chrono::Duration::minutes(5);
+    pub static ref ANNOUNCE_FILE_TIMEOUT: chrono::Duration = chrono::Duration::minutes(5);
+    pub static ref ANNOUNCE_SHARD_CONFIG_TIMEOUT: chrono::Duration = chrono::Duration::minutes(5);
+    pub static ref TOLERABLE_DRIFT: chrono::Duration = chrono::Duration::seconds(10);
 }
 
 #[allow(deprecated)]
@@ -403,7 +403,7 @@ impl Libp2pEventHandler {
         // verify timestamp
         let d = duration_since(timestamp);
         if d < TOLERABLE_DRIFT.neg() || d > *FIND_FILE_TIMEOUT {
-            debug!(%timestamp, "Invalid timestamp, ignoring FindFile message");
+            debug!(%timestamp, ?d, "Invalid timestamp, ignoring FindFile message");
             return MessageAcceptance::Ignore;
         }
 
@@ -481,7 +481,7 @@ impl Libp2pEventHandler {
         // verify timestamp
         let d = duration_since(msg.timestamp);
         if d < TOLERABLE_DRIFT.neg() || d > *FIND_FILE_TIMEOUT {
-            debug!(%msg.timestamp, "Invalid timestamp, ignoring FindFile message");
+            debug!(%msg.timestamp, ?d, "Invalid timestamp, ignoring FindFile message");
             return MessageAcceptance::Ignore;
         }
 
@@ -550,7 +550,8 @@ impl Libp2pEventHandler {
         let seen_ips: Vec<IpAddr> = match self.network_globals.peers.read().peer_info(peer_id) {
             Some(v) => v.seen_ip_addresses().collect(),
             None => {
-                debug!(%announced_ip, "Failed to verify announced IP address, no peer info found");
+                // ignore file announcement from un-seen peers
+                trace!(%announced_ip, "Failed to verify announced IP address, no peer info found");
                 return false;
             }
         };
@@ -558,7 +559,8 @@ impl Libp2pEventHandler {
         if seen_ips.iter().any(|x| *x == announced_ip) {
             true
         } else {
-            debug!(%announced_ip, ?seen_ips, "Failed to verify announced IP address, mismatch with seen ips");
+            // ignore file announcement if announced IP and seen IP mismatch
+            trace!(%announced_ip, ?seen_ips, "Failed to verify announced IP address, mismatch with seen ips");
             false
         }
     }
@@ -587,7 +589,7 @@ impl Libp2pEventHandler {
         // propagate gossip to peers
         let d = duration_since(msg.resend_timestamp);
         if d < TOLERABLE_DRIFT.neg() || d > *ANNOUNCE_FILE_TIMEOUT {
-            debug!(%msg.resend_timestamp, "Invalid resend timestamp, ignoring AnnounceFile message");
+            debug!(%msg.resend_timestamp, ?d, "Invalid resend timestamp, ignoring AnnounceFile message");
             return MessageAcceptance::Ignore;
         }
 
@@ -628,7 +630,7 @@ impl Libp2pEventHandler {
         // propagate gossip to peers
         let d = duration_since(msg.resend_timestamp);
         if d < TOLERABLE_DRIFT.neg() || d > *ANNOUNCE_SHARD_CONFIG_TIMEOUT {
-            debug!(%msg.resend_timestamp, "Invalid resend timestamp, ignoring AnnounceShardConfig message");
+            debug!(%msg.resend_timestamp, ?d, "Invalid resend timestamp, ignoring AnnounceShardConfig message");
             return MessageAcceptance::Ignore;
         }
 
@@ -674,7 +676,7 @@ impl Libp2pEventHandler {
         // propagate gossip to peers
         let d = duration_since(msg.resend_timestamp);
         if d < TOLERABLE_DRIFT.neg() || d > *ANNOUNCE_FILE_TIMEOUT {
-            debug!(%msg.resend_timestamp, "Invalid resend timestamp, ignoring AnnounceChunks message");
+            debug!(%msg.resend_timestamp, ?d, "Invalid resend timestamp, ignoring AnnounceChunks message");
             return MessageAcceptance::Ignore;
         }
 
diff --git a/node/sync/src/service.rs b/node/sync/src/service.rs
index 06dbc9d..3a3e1d9 100644
--- a/node/sync/src/service.rs
+++ b/node/sync/src/service.rs
@@ -749,7 +749,7 @@ impl SyncService {
                     to_terminate.push(*tx_seq);
                 }
             }
-        } else {
+        } else if self.controllers.contains_key(&min_tx_seq) {
             to_terminate.push(min_tx_seq);
         }
 
@@ -757,9 +757,12 @@ impl SyncService {
             self.controllers.remove(tx_seq);
         }
 
-        debug!(?to_terminate, "File sync terminated");
+        let num_terminated = to_terminate.len();
+        if num_terminated > 0 {
+            debug!(?to_terminate, "File sync terminated");
+        }
 
-        to_terminate.len()
+        num_terminated
     }
 
     fn on_heartbeat(&mut self) {
diff --git a/run/log_config_debug b/run/log_config_debug
index 44ccd62..76be8df 100644
--- a/run/log_config_debug
+++ b/run/log_config_debug
@@ -1 +1 @@
-debug,hyper=info,h2=info,rpc=info,discv5=info,router=info,jsonrpsee_http_server=info
\ No newline at end of file
+debug,hyper=info,h2=info,rpc=info,discv5=info,jsonrpsee_http_server=info
\ No newline at end of file