diff --git a/src/chain_sync/chain_follower.rs b/src/chain_sync/chain_follower.rs index 5a9ad238cb4..5cc764f09cc 100644 --- a/src/chain_sync/chain_follower.rs +++ b/src/chain_sync/chain_follower.rs @@ -39,7 +39,10 @@ use chrono::Utc; use hashbrown::{HashMap, HashSet}; use libp2p::PeerId; use parking_lot::Mutex; -use std::time::{Duration, Instant}; +use std::{ + borrow::Cow, + time::{Duration, Instant}, +}; use tokio::{sync::Notify, task::JoinSet}; use tokio_util::sync::CancellationToken; @@ -376,52 +379,71 @@ async fn chain_follower( } }); - // Periodically report progress if there are any tipsets left to be fetched. - // Once we're in steady-state (i.e. caught up to HEAD) and there are no - // active forks, this will not report anything. + // Periodically report progress while catching up to HEAD. Once we're in + // steady-state (i.e. caught up to HEAD), and there are + // no active forks, this will not report anything. set.spawn({ let state_manager = state_manager.shallow_clone(); - let state_machine = state_machine.clone(); + let sync_status = sync_status.shallow_clone(); async move { loop { tokio::time::sleep(tokio::time::Duration::from_secs(10)).await; - let (tasks_set, _) = state_machine.lock().tasks(); let heaviest_tipset = state_manager.chain_store().heaviest_tipset(); let heaviest_epoch = heaviest_tipset.epoch(); - - let to_download = tasks_set - .iter() - .filter_map(|task| match task { - SyncTask::FetchTipset(_, epoch) => Some(epoch - heaviest_epoch), - _ => None, - }) - .max() - .unwrap_or(0); - let expected_head = calculate_expected_epoch( Utc::now().timestamp() as u64, state_manager.chain_store().genesis_block_header().timestamp, state_manager.chain_config().block_delay_secs, ); + let diff = expected_head - heaviest_epoch; // Only print 'Catching up to HEAD' if we're more than 10 epochs // behind. Otherwise it can be too spammy. - match (expected_head - heaviest_epoch > 10, to_download > 0) { - (true, true) => info!( - "Catching up to HEAD: {heaviest_epoch}{} -> {expected_head} (diff: {}), downloading {to_download} tipsets" - , heaviest_tipset.key(), - expected_head - heaviest_epoch - ), - (true, false) => info!( - "Catching up to HEAD: {heaviest_epoch}{} -> {expected_head} (diff: {})" - ,heaviest_tipset.key(), - expected_head - heaviest_epoch - ), - (false, true) => { - info!("Downloading {to_download} tipsets") - } - (false, false) => {} + if diff <= 10 { + continue; } + + // The event loop refreshes this report on every state change, + // so it is never staler than the state machine itself. + let report = sync_status.load(); + let forks = &report.active_forks; + // Once the nearest fork is validating, the remaining fetch + // gaps belong to freshly gossiped forks near the clock head + // and their min would mislead. + let status: Cow<'static, str> = if forks + .iter() + .any(|fork| fork.stage == ForkSyncStage::ValidatingTipsets) + { + ", validating tipsets".into() + } else if forks + .iter() + .any(|fork| fork.stage == ForkSyncStage::FetchingHeaders) + { + // The fork closest to the validated head connects first, so + // its gap approximates the header fetches left before + // validation can start. + let remaining = forks + .iter() + .filter(|fork| fork.stage == ForkSyncStage::FetchingHeaders) + .map(|fork| fork.target_sync_epoch_start - fork.validated_chain_head_epoch) + .filter(|gap| *gap > 0) + .min(); + match remaining { + Some(remaining) => format!(", fetching headers (~{remaining})").into(), + // All fetches are at or below the validated head: + // fork-point searches, fetching a competing branch's + // ancestry down to where it forked off our chain. + None => ", fetching headers".into(), + } + } else { + // waiting for peers to (re)seed tipsets (startup, no usable peers, or the buffer + // was just cleared after a failed validation). + ", waiting for tipsets".into() + }; + info!( + "Catching up to HEAD: {heaviest_epoch}{} -> {expected_head} (diff: {diff}){status}", + heaviest_tipset.key() + ); } } });