Merge pull request #231 from tonlabs/fix-log

Logging was a bit refactored. Added neighbors' stat to telemetry.

CHANGELOG.md

@@ -2,6 +2,10 @@
 
 All notable changes to this project will be documented in this file.
 
+## Version 0.56.7
+
+- Logging was a bit refactored. Added neighbor's stat to telemetry.
+
 ## Version 0.56.6
 
 - Added new parameter to node config `sync_by_archives` which allows to synchronize node by archives 

Cargo.toml

@@ -2,7 +2,7 @@
 build = 'common/build/build.rs'
 edition = '2021'
 name = 'ton_node'
-version = '0.56.6'
+version = '0.56.7'
 
 [workspace]
 members = [ 'storage' ]

src/engine.rs

@@ -1969,7 +1969,7 @@ impl Engine {
             Arc::new(NextBlockDownloader),
             prev_id, 
             limit,
-            10,
+            30,
             "download_next_block_worker", 
             Some((50, 11, 1000))
         ).await?.download().await
@@ -2766,6 +2766,11 @@ fn telemetry_logger(engine: Arc<Engine>) {
                 "Full node client's telemetry:\n{}",
                 engine.network.telemetry().report(Engine::TIMEOUT_TELEMETRY_SEC)
             );
+            log::debug!(
+                target: "telemetry",
+                "Full node neighbours's telemetry:",
+            );
+            engine.network.log_neighbors_stat();
             if engine.remp_client.is_some() {
                 log::debug!(
                     target: "telemetry",

src/internal_db/state_gc_resolver.rs

@@ -56,7 +56,7 @@ impl AllowStateGcSmartResolver {
         );
 
         if new_min_ref_mc_seqno > old_min_ref_mc_seqno {
-            log::info!(
+            log::debug!(
                 "AllowStateGcSmartResolver::advance: updated min_ref_mc_block {} -> {}, mc_block_id: {}",
                 old_min_ref_mc_seqno, new_min_ref_mc_seqno, mc_block_id,
             );
@@ -73,14 +73,14 @@ impl AllowStateGcSmartResolver {
                         |found| if let Some(a) = found {
                             let old_val = a.fetch_max(id.seq_no(), Ordering::Relaxed);
                             if old_val != id.seq_no() {
-                                log::info!(
+                                log::debug!(
                                     "AllowStateGcSmartResolver::advance: updated min actual state for shard {}: {} -> {}",
                                     id.shard(), old_val, id.seq_no()
                                 );
                             }
                             Ok(None)
                         } else {
-                            log::info!(
+                            log::debug!(
                                 "AllowStateGcSmartResolver::advance: added min actual state for shard {}: {}",
                                 id.shard(), id.seq_no()
                             );
@@ -93,7 +93,7 @@ impl AllowStateGcSmartResolver {
                 for kv in self.min_actual_ss.iter() {
                     if !actual_shardes.contains(kv.key()) {
                         self.min_actual_ss.remove(kv.key());
-                        log::info!(
+                        log::debug!(
                             "AllowStateGcSmartResolver::advance: removed shard {}", kv.key()
                         );
                     }

src/network/neighbours.rs

@@ -13,7 +13,7 @@
 
 use crate::network::node_network::NodeNetwork;
 
-use adnl::{common::{Query, TaggedTlObject, Wait}, node::{AdnlNode, AddressCache}};
+use adnl::{common::{Query, TaggedTlObject, Wait}, node::{AddressCache, AdnlNode}};
 use adnl::DhtNode;
 use adnl::{OverlayShortId, OverlayNode};
 use rand::Rng;
@@ -458,18 +458,47 @@ impl Neighbours {
                 log::trace!("add_new_peers: searching IP for peer {}...", peer);
                 match DhtNode::find_address_in_network(&this.dht, peer, None).await {
                     Ok(Some((ip, _))) => {
-                        log::info!("add_new_peers: peer {}, IP {}", peer, ip);
-                        if !this.add_overlay_peer(peer.clone()) {
-                            log::debug!("add_new_peers already present");
-                        }
+                        if this.add_overlay_peer(peer.clone()) {
+                            log::info!("add_new_peers: peer {}, IP {}", peer, ip);
+                        } else {
+                            log::trace!("add_new_peers: peer {}, IP {} is already present", peer, ip);
+                        } 
                     }
-                    Ok(None) => log::warn!("add_new_peers: peer {}, IP not found", peer),
+                    Ok(None) => log::debug!("add_new_peers: peer {}, IP not found", peer),
                     Err(e) => log::warn!("add_new_peers: peer {}, IP search error {}", peer, e)
                 }
             }
         });
     }
 
+    pub fn log_neighbors_stat(&self) {
+        log::debug!(
+            target: "telemetry", 
+            "Neighbours: overlay {} count {}",
+            self.overlay_id, self.peers.count()
+        );
+        let node_stat = self.fail_attempts.load(Ordering::Relaxed) as f64 /
+            self.all_attempts.load(Ordering::Relaxed) as f64;
+        for neighbour in self.peers.get_iter() {
+            let unr = neighbour.effective_unreliability();
+            let roundtrip_rldp = neighbour.roundtrip_rldp.load(Ordering::Relaxed);
+            let roundtrip_adnl = neighbour.roundtrip_adnl.load(Ordering::Relaxed);
+            let peer_stat = neighbour.fail_attempts.load(Ordering::Relaxed) as f64 /
+                neighbour.all_attempts.load(Ordering::Relaxed) as f64;
+            let fines_points = neighbour.fines_points.load(Ordering::Relaxed);
+            log::debug!(
+                target: "telemetry", 
+                "Neighbour {}, unr {:.6}, rt ADNL {:.6}, rt RLDP {:.6} (all stat: {:.4}, peer stat: {:.4}/{}))",
+                neighbour.id(), unr,
+                roundtrip_adnl,
+                roundtrip_rldp,
+                node_stat,
+                peer_stat,
+                fines_points
+            );
+        }
+    }
+
     pub fn choose_neighbour(&self) -> Result<Option<Arc<Neighbour>>> {
         let count = self.peers.count();
         if count == 0 {
@@ -627,7 +656,7 @@ impl Neighbours {
             tokio::spawn(
                 async move {
                     if let Err(e) = self_cloned.update_capabilities(peer, ping_reserve).await {
-                        log::warn!("{}; ping_idx #{}", e, ping_idx)
+                        log::debug!("{}; ping_idx #{}", e, ping_idx)
                     }
                     wait_cloned.respond(Some(()));
                 }
@@ -911,21 +940,21 @@ impl NeighboursCacheCore {
         bad_peer: bool
     ) -> Result<bool> {
         let new_unr = existing_in_reserve.as_ref().map_or(0, |v| v.effective_unreliability());
-        log::info!("started replace (old: {}, new: {}) {}, new_unr: {}",
+        log::debug!("started replace (old: {}, new: {}) {}, new_unr: {}",
             &old, &new, if bad_peer { "as a bad peer" } else { "for rotation" }, new_unr);
         let index = if let Some(index) = self.get_index(old) {
             index
         } else {
             fail!("replaced neighbour not found!")
         };
-        log::info!("replace func use index: {} (old: {}, new: {})", &index, &old, &new);
+        log::debug!("replace func use index: {} (old: {}, new: {})", &index, &old, &new);
         let status_insert = self.insert_ex(new.clone(), true, existing_in_reserve)?;
 
         if status_insert {
             self.indices.insert(index, new);
             self.values.remove(old);
         }
-        log::info!("finish replace (old: {})", &old);
+        log::debug!("finish replace (old: {})", &old);
         Ok(status_insert)
     }
 

src/network/node_network.rs

@@ -271,6 +271,12 @@ impl NodeNetwork {
         }
     }
 
+    pub fn log_neighbors_stat(&self) {
+        for guard in self.overlays.iter() {
+            guard.val().peers().log_neighbors_stat();
+        }
+    }
+
     pub async fn stop_adnl(&self) {
         log::info!("Stopping node network loops...");
         self.cancellation_token.cancel();

src/shard_blocks.rs

@@ -262,7 +262,7 @@ impl ShardBlocksPool {
         }
 
         if last_mc_seq_no != mc_seqno {
-            log::error!("get_shard_blocks: Given last_mc_seq_no {} is not actual", last_mc_seq_no);
+            log::debug!("get_shard_blocks: Given last_mc_seq_no {} is not actual", last_mc_seq_no);
             fail!("Given last_mc_seq_no {} is not actual {}", last_mc_seq_no, mc_seqno);
         } else {
             let mut returned_list = string_builder::Builder::default();

src/shard_blocks_fast_finality.rs

@@ -220,7 +220,7 @@ impl ShardBlocksPool {
             }
 
             if last_mc_seq_no != mc_seqno {
-                log::error!(
+                log::debug!(
                     "get_shard_blocks: Given last_mc_seq_no {} is not actual {}", 
                     last_mc_seq_no, mc_seqno
                 );

validator-session/src/round.rs

@@ -706,9 +706,18 @@ impl RoundState for RoundStateImpl {
                     desc.get_cutoff_weight() as f64 / desc.get_total_weight() as f64;
 
                 if let Some(block) = block {
-                    result = format!("{}      - block {:?}: source={}, hash={:?}, root_hash={:?}, file_hash={:?}, approved={} ({:.2}%/{:.2}%) priority={}\n",
-            result, block.get_id(), block.get_source_index(), block.get_id(), block.get_root_hash(), block.get_file_hash(), approved_weight, normalized_approved_weight * 100.0,
-            normalized_cutoff_weight * 100.0, priority);
+                    result = format!(
+                        "{}      - block {:?}: source={}, hash={:?}, root_hash={:x}, file_hash={:?}, approved={} ({:.2}%/{:.2}%) priority={}\n",
+                        result,
+                        block.get_id(),
+                        block.get_source_index(),
+                        block.get_id(),
+                        block.get_root_hash(),
+                        block.get_file_hash(),
+                        approved_weight, normalized_approved_weight * 100.0,
+                        normalized_cutoff_weight * 100.0,
+                        priority
+                    );
                 } else {
                     result = format!(
                         "{}      - SKIP block: approved={} ({:.2}%/{:.2}%) priority={}\n",