From 2aa5d5c25e22e2f48177ee95bb90a84241e73ba4 Mon Sep 17 00:00:00 2001 From: Lion - dapplion <35266934+dapplion@users.noreply.github.com> Date: Thu, 1 May 2025 16:53:29 -0300 Subject: [PATCH] Make sure to log SyncingChain ID (#7359) Debugging an sync issue from @pawanjay176 I'm missing some key info where instead of logging the ID of the SyncingChain we just log "Finalized" (the sync type). This looks like some typo or something was lost in translation when refactoring things. ``` Apr 17 12:12:00.707 DEBUG Syncing new finalized chain chain: Finalized, component: "range_sync" ``` This log should include more info about the new chain but just logs "Finalized" ``` Apr 17 12:12:00.810 DEBUG New chain added to sync peer_id: "16Uiu2HAmHP8QLYQJwZ4cjMUEyRgxzpkJF87qPgNecLTpUdruYbdA", sync_type: Finalized, new_chain: Finalized, component: "range_sync" ``` - Remove the Display impl and log the ID explicitly for all logs. - Log more details when creating a new SyncingChain --- .../network/src/sync/range_sync/chain.rs | 13 +--------- .../src/sync/range_sync/chain_collection.rs | 24 ++++++++++++------- .../network/src/sync/range_sync/range.rs | 6 ++--- 3 files changed, 20 insertions(+), 23 deletions(-) diff --git a/beacon_node/network/src/sync/range_sync/chain.rs b/beacon_node/network/src/sync/range_sync/chain.rs index 24045e901b..813eb7a0c7 100644 --- a/beacon_node/network/src/sync/range_sync/chain.rs +++ b/beacon_node/network/src/sync/range_sync/chain.rs @@ -13,7 +13,6 @@ use logging::crit; use rand::seq::SliceRandom; use rand::Rng; use std::collections::{btree_map::Entry, BTreeMap, HashSet}; -use std::fmt; use strum::IntoStaticStr; use tracing::{debug, instrument, warn}; use types::{Epoch, EthSpec, Hash256, Slot}; @@ -116,16 +115,6 @@ pub struct SyncingChain { current_processing_batch: Option, } -impl fmt::Display for SyncingChain { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - match self.chain_type { - SyncingChainType::Head => write!(f, "Head"), - SyncingChainType::Finalized => write!(f, "Finalized"), - SyncingChainType::Backfill => write!(f, "Backfill"), - } - } -} - #[derive(PartialEq, Debug)] pub enum ChainSyncingState { /// The chain is not being synced. @@ -177,7 +166,7 @@ impl SyncingChain { /// Get the chain's id. #[instrument(parent = None,level = "info", fields(chain = self.id , service = "range_sync"), skip_all)] - pub fn get_id(&self) -> ChainId { + pub fn id(&self) -> ChainId { self.id } diff --git a/beacon_node/network/src/sync/range_sync/chain_collection.rs b/beacon_node/network/src/sync/range_sync/chain_collection.rs index c6be3de576..9f500c61e0 100644 --- a/beacon_node/network/src/sync/range_sync/chain_collection.rs +++ b/beacon_node/network/src/sync/range_sync/chain_collection.rs @@ -293,8 +293,8 @@ impl ChainCollection { .expect("Chain exists"); match old_id { - Some(Some(old_id)) => debug!(old_id, %chain, "Switching finalized chains"), - None => debug!(%chain, "Syncing new finalized chain"), + Some(Some(old_id)) => debug!(old_id, id = chain.id(), "Switching finalized chains"), + None => debug!(id = chain.id(), "Syncing new finalized chain"), Some(None) => { // this is the same chain. We try to advance it. } @@ -359,7 +359,7 @@ impl ChainCollection { if syncing_chains.len() < PARALLEL_HEAD_CHAINS { // start this chain if it's not already syncing if !chain.is_syncing() { - debug!(%chain, "New head chain started syncing"); + debug!(id = chain.id(), "New head chain started syncing"); } if let Err(remove_reason) = chain.start_syncing(network, local_epoch, local_head_epoch) @@ -421,7 +421,7 @@ impl ChainCollection { if is_outdated(&chain.target_head_slot, &chain.target_head_root) || chain.available_peers() == 0 { - debug!(%chain, "Purging out of finalized chain"); + debug!(id, "Purging out of finalized chain"); Some((*id, chain.is_syncing(), RangeSyncType::Finalized)) } else { None @@ -432,7 +432,7 @@ impl ChainCollection { if is_outdated(&chain.target_head_slot, &chain.target_head_root) || chain.available_peers() == 0 { - debug!(%chain, "Purging out of date head chain"); + debug!(id, "Purging out of date head chain"); Some((*id, chain.is_syncing(), RangeSyncType::Head)) } else { None @@ -478,9 +478,9 @@ impl ChainCollection { debug_assert_eq!(chain.target_head_slot, target_head_slot); if let Err(remove_reason) = chain.add_peer(network, peer) { if remove_reason.is_critical() { - crit!(chain = %id, reason = ?remove_reason, "Chain removed after adding peer"); + crit!(id, reason = ?remove_reason, "Chain removed after adding peer"); } else { - error!(chain = %id, reason = ?remove_reason, "Chain removed after adding peer"); + error!(id, reason = ?remove_reason, "Chain removed after adding peer"); } let is_syncing = chain.is_syncing(); collection.remove(&id); @@ -499,7 +499,15 @@ impl ChainCollection { sync_type.into(), ); - debug!(peer_id = peer_rpr, ?sync_type, %new_chain, "New chain added to sync"); + debug!( + peer_id = peer_rpr, + ?sync_type, + id, + %start_epoch, + %target_head_slot, + ?target_head_root, + "New chain added to sync" + ); collection.insert(id, new_chain); metrics::inc_counter_vec(&metrics::SYNCING_CHAINS_ADDED, &[sync_type.as_str()]); self.update_metrics(); diff --git a/beacon_node/network/src/sync/range_sync/range.rs b/beacon_node/network/src/sync/range_sync/range.rs index ab9a88e4ac..c87418b87b 100644 --- a/beacon_node/network/src/sync/range_sync/range.rs +++ b/beacon_node/network/src/sync/range_sync/range.rs @@ -386,15 +386,15 @@ where op: &'static str, ) { if remove_reason.is_critical() { - crit!(?sync_type, %chain, reason = ?remove_reason,op, "Chain removed"); + crit!(id = chain.id(), ?sync_type, reason = ?remove_reason, op, "Chain removed"); } else { - debug!(?sync_type, %chain, reason = ?remove_reason,op, "Chain removed"); + debug!(id = chain.id(), ?sync_type, reason = ?remove_reason, op, "Chain removed"); } if let RemoveChain::ChainFailed { blacklist, .. } = remove_reason { if RangeSyncType::Finalized == sync_type && blacklist { warn!( - %chain, + id = chain.id(), "Chain failed! Syncing to its head won't be retried for at least the next {} seconds", FAILED_CHAINS_EXPIRY_SECONDS );