diff --git a/CHANGELOG.md b/CHANGELOG.md index 5c223c40..f9457514 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/Cargo.toml b/Cargo.toml index 0a764a10..26cf087e 100644 --- a/Cargo.toml +++ b/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' ] diff --git a/src/engine.rs b/src/engine.rs index 31b768e8..f186277f 100644 --- a/src/engine.rs +++ b/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) { "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", diff --git a/src/internal_db/state_gc_resolver.rs b/src/internal_db/state_gc_resolver.rs index ec30aa7b..3055c627 100644 --- a/src/internal_db/state_gc_resolver.rs +++ b/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() ); } diff --git a/src/network/neighbours.rs b/src/network/neighbours.rs index 05d31752..7bb54ba4 100644 --- a/src/network/neighbours.rs +++ b/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>> { 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 { 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) } diff --git a/src/network/node_network.rs b/src/network/node_network.rs index 60867e4d..9bd99418 100644 --- a/src/network/node_network.rs +++ b/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(); diff --git a/src/shard_blocks.rs b/src/shard_blocks.rs index ada7a458..f4f48c09 100644 --- a/src/shard_blocks.rs +++ b/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(); diff --git a/src/shard_blocks_fast_finality.rs b/src/shard_blocks_fast_finality.rs index b3cc91d1..d6b5afc0 100644 --- a/src/shard_blocks_fast_finality.rs +++ b/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 ); diff --git a/validator-session/src/round.rs b/validator-session/src/round.rs index ddbfdb01..0c5328c2 100644 --- a/validator-session/src/round.rs +++ b/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",