use std::{
cmp::max,
collections::{HashMap, HashSet},
convert,
future::Future,
pin::Pin,
task::Poll,
time::{Duration, Instant},
};
use color_eyre::eyre::{eyre, Report};
use futures::{
future::OptionFuture,
stream::{FuturesUnordered, StreamExt},
};
use indexmap::IndexSet;
use serde::{Deserialize, Serialize};
use tokio::{
sync::{mpsc, watch},
task::JoinError,
time::{sleep, sleep_until, timeout},
};
use tower::{
builder::ServiceBuilder, hedge::Hedge, limit::ConcurrencyLimit, retry::Retry, timeout::Timeout,
Service, ServiceExt,
};
use zakura_chain::{
block::{self, Height, HeightDiff},
chain_tip::ChainTip,
};
use zakura_network::{self as zn, PeerSocketAddr};
use zakura_state as zs;
use crate::{
components::sync::downloads::BlockDownloadVerifyError, config::ZakuradConfig, BoxError,
};
mod downloads;
pub mod end_of_support;
mod gossip;
mod legacy_trace;
mod progress;
mod recent_sync_lengths;
mod status;
#[cfg(test)]
mod tests;
use downloads::{AlwaysHedge, Downloads, NotFoundKind};
use legacy_trace::LegacySyncTrace;
pub use downloads::VERIFICATION_PIPELINE_SCALING_MULTIPLIER;
pub use gossip::{gossip_best_tip_block_hashes, BlockGossipError};
pub use progress::show_block_chain_progress;
pub use recent_sync_lengths::RecentSyncLengths;
pub use status::SyncStatus;
const FANOUT: usize = 3;
const BLOCK_DOWNLOAD_RETRY_LIMIT: usize = 3;
const MISSING_BLOCK_DOWNLOAD_RETRY_LIMIT: usize = 8;
const MISSING_BLOCK_REGISTRY_RETRY_LIMIT: usize = 60;
const REGISTRY_MISS_RETRY_BACKOFF: Duration = Duration::from_secs(2);
pub const MIN_CHECKPOINT_CONCURRENCY_LIMIT: usize = zakura_consensus::MAX_CHECKPOINT_HEIGHT_GAP;
pub const DEFAULT_CHECKPOINT_CONCURRENCY_LIMIT: usize = MAX_TIPS_RESPONSE_HASH_COUNT * 2;
pub const DEFAULT_ZAKURA_BLOCK_APPLY_CONCURRENCY_LIMIT: usize = 32;
pub const MIN_CONCURRENCY_LIMIT: usize = 1;
pub const MAX_TIPS_RESPONSE_HASH_COUNT: usize = 500;
const MIN_UNREQUESTED_HASHES_BEFORE_EXTEND: usize = MAX_TIPS_RESPONSE_HASH_COUNT;
pub const TIPS_RESPONSE_TIMEOUT: Duration = Duration::from_secs(6);
pub const PEER_GOSSIP_DELAY: Duration = Duration::from_secs(7);
pub(super) const BLOCK_DOWNLOAD_TIMEOUT: Duration = Duration::from_secs(20);
pub(super) const BLOCK_VERIFY_TIMEOUT: Duration = Duration::from_secs(8 * 60);
const FINAL_CHECKPOINT_BLOCK_VERIFY_TIMEOUT: Duration = Duration::from_secs(2 * 60);
const FINAL_CHECKPOINT_BLOCK_VERIFY_TIMEOUT_LIMIT: HeightDiff = 100;
const SYNC_RESTART_DELAY: Duration = Duration::from_secs(45);
const SYNC_RESTART_SLEEP: Duration = Duration::from_secs(10);
const REGTEST_SYNC_RESTART_DELAY: Duration = Duration::from_secs(2);
const TIP_REFRESH_INTERVAL: Duration = Duration::from_secs(10);
const GENESIS_TIMEOUT_RETRY: Duration = Duration::from_secs(10);
const ZAKURA_BODY_SYNC_STALL_TIMEOUT: Duration = Duration::from_secs(10 * 60);
const ZAKURA_BODY_SYNC_STALL_POLL: Duration = Duration::from_secs(10);
const ZAKURA_NEAR_TIP_GAP: HeightDiff = 2;
const ZAKURA_LEGACY_PROBE_STALL_POLLS: u64 = 3;
const ZAKURA_LEGACY_BEHIND_THRESHOLD: HeightDiff = 64;
#[derive(Clone, Copy, Debug)]
struct ZakuraStallTracker {
last_verified_height: Option<Height>,
idle_polls: u64,
}
impl ZakuraStallTracker {
fn new(verified_height: Option<Height>) -> Self {
Self {
last_verified_height: verified_height,
idle_polls: 0,
}
}
}
#[derive(Clone, Copy, Debug)]
struct ZakuraLegacyProbe {
last_verified_height: Option<Height>,
frozen_polls: u64,
}
impl ZakuraLegacyProbe {
fn new(verified_height: Option<Height>) -> Self {
Self {
last_verified_height: verified_height,
frozen_polls: 0,
}
}
fn should_probe(
&mut self,
verified_height: Option<Height>,
looks_caught_up: bool,
min_frozen_polls: u64,
) -> bool {
let advanced = verified_height > self.last_verified_height;
self.last_verified_height = verified_height;
if advanced {
self.frozen_polls = 0;
return false;
}
self.frozen_polls += 1;
looks_caught_up && self.frozen_polls >= min_frozen_polls
}
}
#[derive(Clone, Copy, Debug, Eq, PartialEq)]
enum ZakuraWatchdogAction {
ContinueWaiting,
WarnOnly,
ProbeLegacyPeers,
FallbackToLegacy,
}
fn zakura_watchdog_action(
tracker: &mut ZakuraStallTracker,
legacy_probe: &mut ZakuraLegacyProbe,
verified_height: Option<Height>,
header_tip_height: Option<Height>,
max_idle_polls: u64,
legacy_fallback: bool,
) -> ZakuraWatchdogAction {
if zakura_block_sync_stalled(tracker, verified_height, max_idle_polls) {
if legacy_fallback {
return ZakuraWatchdogAction::FallbackToLegacy;
}
return if tracker.idle_polls.is_multiple_of(max_idle_polls) {
ZakuraWatchdogAction::WarnOnly
} else {
ZakuraWatchdogAction::ContinueWaiting
};
}
if !legacy_fallback {
return ZakuraWatchdogAction::ContinueWaiting;
}
let looks_caught_up = match (header_tip_height, verified_height) {
(Some(header), Some(verified)) => header - verified <= ZAKURA_NEAR_TIP_GAP,
_ => true,
};
if legacy_probe.should_probe(
verified_height,
looks_caught_up,
ZAKURA_LEGACY_PROBE_STALL_POLLS,
) {
ZakuraWatchdogAction::ProbeLegacyPeers
} else {
ZakuraWatchdogAction::ContinueWaiting
}
}
fn legacy_probe_supports_fallback(blocks_ahead: Option<HeightDiff>) -> bool {
matches!(blocks_ahead, Some(blocks_ahead) if blocks_ahead >= ZAKURA_LEGACY_BEHIND_THRESHOLD)
}
fn zakura_sync_status_length(
verified_height: Option<Height>,
header_tip_height: Option<Height>,
) -> Option<usize> {
let (Some(verified_height), Some(header_tip_height)) = (verified_height, header_tip_height)
else {
return None;
};
let gap = header_tip_height - verified_height;
if gap <= 0 {
Some(0)
} else {
Some(usize::try_from(gap).unwrap_or(usize::MAX))
}
}
fn zakura_block_sync_stalled(
tracker: &mut ZakuraStallTracker,
verified_height: Option<Height>,
max_idle_polls: u64,
) -> bool {
let made_progress = verified_height > tracker.last_verified_height;
tracker.last_verified_height = verified_height;
if made_progress {
tracker.idle_polls = 0;
false
} else {
tracker.idle_polls += 1;
tracker.idle_polls >= max_idle_polls
}
}
async fn best_header_tip_height<RS>(read_state: &mut RS) -> Option<Height>
where
RS: Service<zs::ReadRequest, Response = zs::ReadResponse, Error = BoxError>,
{
let ready = read_state.ready().await.ok()?;
match ready.call(zs::ReadRequest::BestHeaderTip).await {
Ok(zs::ReadResponse::BestHeaderTip(tip)) => tip.map(|(height, _hash)| height),
_ => None,
}
}
async fn engage_legacy_fallback_alongside_zakura(
block_sync_handoff: &crate::commands::start::zakura::BlockSyncHandoff,
) {
metrics::counter!("sync.zakura.legacy_fallback.engaged").increment(1);
metrics::gauge!("sync.zakura.legacy_fallback.active").set(1.0);
block_sync_handoff
.yield_to_legacy(std::time::Duration::from_secs(60))
.await;
}
#[derive(Clone, Debug, Eq, PartialEq, Deserialize, Serialize)]
#[serde(deny_unknown_fields, default)]
pub struct Config {
#[serde(alias = "max_concurrent_block_requests")]
pub download_concurrency_limit: usize,
#[serde(alias = "lookahead_limit")]
pub checkpoint_verify_concurrency_limit: usize,
pub full_verify_concurrency_limit: usize,
pub zakura_block_apply_concurrency_limit: usize,
pub parallel_cpu_threads: usize,
#[serde(skip_serializing)]
pub debug_skip_regtest_genesis_self_seed: bool,
#[serde(skip_serializing)]
pub debug_blocksync_throughput_target_height: Option<u32>,
}
impl Default for Config {
fn default() -> Self {
Self {
download_concurrency_limit: 100,
checkpoint_verify_concurrency_limit: DEFAULT_CHECKPOINT_CONCURRENCY_LIMIT,
full_verify_concurrency_limit: 20,
zakura_block_apply_concurrency_limit: DEFAULT_ZAKURA_BLOCK_APPLY_CONCURRENCY_LIMIT,
parallel_cpu_threads: 0,
debug_skip_regtest_genesis_self_seed: false,
debug_blocksync_throughput_target_height: None,
}
}
}
#[derive(Copy, Clone, Debug, Hash, PartialEq, Eq)]
struct CheckedTip {
tip: block::Hash,
expected_next: block::Hash,
}
pub struct ChainSync<ZN, ZS, ZV, ZSTip>
where
ZN: Service<zn::Request, Response = zn::Response, Error = BoxError>
+ Send
+ Sync
+ Clone
+ 'static,
ZN::Future: Send,
ZS: Service<zs::Request, Response = zs::Response, Error = BoxError>
+ Send
+ Sync
+ Clone
+ 'static,
ZS::Future: Send,
ZV: Service<zakura_consensus::Request, Response = block::Hash, Error = BoxError>
+ Send
+ Sync
+ Clone
+ 'static,
ZV::Future: Send,
ZSTip: ChainTip + Clone + Send + 'static,
{
genesis_hash: block::Hash,
max_checkpoint_height: Height,
checkpoint_verify_concurrency_limit: usize,
full_verify_concurrency_limit: usize,
is_regtest: bool,
tip_network: Timeout<ZN>,
downloads: Pin<
Box<
Downloads<
Hedge<ConcurrencyLimit<Retry<zn::RetryLimit, Timeout<ZN>>>, AlwaysHedge>,
Timeout<ZV>,
ZSTip,
>,
>,
>,
state: ZS,
latest_chain_tip: ZSTip,
prospective_tips: HashSet<CheckedTip>,
recent_syncs: RecentSyncLengths,
missing_block_retry_counts: HashMap<block::Hash, usize>,
registry_miss_retry_counts: HashMap<block::Hash, usize>,
registry_miss_retry: HashMap<block::Hash, tokio::time::Instant>,
past_lookahead_limit_receiver: zs::WatchReceiver<bool>,
misbehavior_sender: mpsc::Sender<(PeerSocketAddr, u32)>,
trace: LegacySyncTrace,
}
impl<ZN, ZS, ZV, ZSTip> ChainSync<ZN, ZS, ZV, ZSTip>
where
ZN: Service<zn::Request, Response = zn::Response, Error = BoxError>
+ Send
+ Sync
+ Clone
+ 'static,
ZN::Future: Send,
ZS: Service<zs::Request, Response = zs::Response, Error = BoxError>
+ Send
+ Sync
+ Clone
+ 'static,
ZS::Future: Send,
ZV: Service<zakura_consensus::Request, Response = block::Hash, Error = BoxError>
+ Send
+ Sync
+ Clone
+ 'static,
ZV::Future: Send,
ZSTip: ChainTip + Clone + Send + 'static,
{
pub fn new(
config: &ZakuradConfig,
max_checkpoint_height: Height,
peers: ZN,
verifier: ZV,
state: ZS,
latest_chain_tip: ZSTip,
misbehavior_sender: mpsc::Sender<(PeerSocketAddr, u32)>,
) -> (Self, SyncStatus) {
let mut download_concurrency_limit = config.sync.download_concurrency_limit;
let mut checkpoint_verify_concurrency_limit =
config.sync.checkpoint_verify_concurrency_limit;
let mut full_verify_concurrency_limit = config.sync.full_verify_concurrency_limit;
if download_concurrency_limit < MIN_CONCURRENCY_LIMIT {
warn!(
"configured download concurrency limit {} too low, increasing to {}",
config.sync.download_concurrency_limit, MIN_CONCURRENCY_LIMIT,
);
download_concurrency_limit = MIN_CONCURRENCY_LIMIT;
}
if checkpoint_verify_concurrency_limit < MIN_CHECKPOINT_CONCURRENCY_LIMIT {
warn!(
"configured checkpoint verify concurrency limit {} too low, increasing to {}",
config.sync.checkpoint_verify_concurrency_limit, MIN_CHECKPOINT_CONCURRENCY_LIMIT,
);
checkpoint_verify_concurrency_limit = MIN_CHECKPOINT_CONCURRENCY_LIMIT;
}
if full_verify_concurrency_limit < MIN_CONCURRENCY_LIMIT {
warn!(
"configured full verify concurrency limit {} too low, increasing to {}",
config.sync.full_verify_concurrency_limit, MIN_CONCURRENCY_LIMIT,
);
full_verify_concurrency_limit = MIN_CONCURRENCY_LIMIT;
}
let tip_network = Timeout::new(peers.clone(), TIPS_RESPONSE_TIMEOUT);
let block_network = Hedge::new(
ServiceBuilder::new()
.concurrency_limit(download_concurrency_limit)
.retry(zn::RetryLimit::new(BLOCK_DOWNLOAD_RETRY_LIMIT))
.timeout(BLOCK_DOWNLOAD_TIMEOUT)
.service(peers),
AlwaysHedge,
20,
0.95,
2 * SYNC_RESTART_DELAY,
);
let verifier = Timeout::new(verifier, BLOCK_VERIFY_TIMEOUT);
let (sync_status, recent_syncs) = SyncStatus::new_for_network(&config.network.network);
let (past_lookahead_limit_sender, past_lookahead_limit_receiver) = watch::channel(false);
let past_lookahead_limit_receiver = zs::WatchReceiver::new(past_lookahead_limit_receiver);
let trace = LegacySyncTrace::new(config.network.zakura.trace_dir.clone());
let downloads = Box::pin(Downloads::new(
block_network,
verifier,
latest_chain_tip.clone(),
past_lookahead_limit_sender,
max(
checkpoint_verify_concurrency_limit,
full_verify_concurrency_limit,
),
max_checkpoint_height,
trace.clone(),
));
let new_syncer = Self {
genesis_hash: config.network.network.genesis_hash(),
max_checkpoint_height,
checkpoint_verify_concurrency_limit,
full_verify_concurrency_limit,
is_regtest: config.network.network.is_regtest(),
tip_network,
downloads,
state,
latest_chain_tip,
prospective_tips: HashSet::new(),
recent_syncs,
missing_block_retry_counts: HashMap::new(),
registry_miss_retry_counts: HashMap::new(),
registry_miss_retry: HashMap::new(),
past_lookahead_limit_receiver,
misbehavior_sender,
trace,
};
(new_syncer, sync_status)
}
#[instrument(skip(self))]
pub async fn sync(mut self) -> Result<(), Report> {
self.request_genesis().await?;
loop {
if self.try_to_sync().await.is_err() {
self.downloads.cancel_all();
}
self.update_metrics();
let restart_delay = if self.is_regtest {
REGTEST_SYNC_RESTART_DELAY
} else {
SYNC_RESTART_SLEEP
};
info!(
timeout = ?restart_delay,
state_tip = ?self.latest_chain_tip.best_tip_height(),
"waiting to restart sync"
);
sleep(restart_delay).await;
}
}
#[instrument(skip(self, read_state, block_sync_handoff))]
pub(crate) async fn bootstrap_genesis_then_pause<RS>(
mut self,
mut read_state: RS,
legacy_fallback: bool,
block_sync_handoff: std::sync::Arc<crate::commands::start::zakura::BlockSyncHandoff>,
) -> Result<(), Report>
where
RS: Service<zs::ReadRequest, Response = zs::ReadResponse, Error = BoxError>
+ Send
+ 'static,
RS::Future: Send,
{
self.request_genesis().await?;
info!(
"Zakura block sync replacement completed genesis bootstrap; \
monitoring for Zakura body-sync progress"
);
let max_idle_polls = (ZAKURA_BODY_SYNC_STALL_TIMEOUT.as_secs()
/ ZAKURA_BODY_SYNC_STALL_POLL.as_secs())
.max(1);
let initial_tip = self.latest_chain_tip.best_tip_height();
let mut tracker = ZakuraStallTracker::new(initial_tip);
let mut legacy_probe = ZakuraLegacyProbe::new(initial_tip);
loop {
sleep(ZAKURA_BODY_SYNC_STALL_POLL).await;
let verified_height = self.latest_chain_tip.best_tip_height();
let header_tip_height = best_header_tip_height(&mut read_state).await;
if let Some(sync_length) = zakura_sync_status_length(verified_height, header_tip_height)
{
self.recent_syncs.push_extend_tips_length(sync_length);
}
match zakura_watchdog_action(
&mut tracker,
&mut legacy_probe,
verified_height,
header_tip_height,
max_idle_polls,
legacy_fallback,
) {
ZakuraWatchdogAction::ContinueWaiting => continue,
ZakuraWatchdogAction::WarnOnly => {
warn!(
verified_tip = ?verified_height,
header_tip = ?header_tip_height,
stall = ?ZAKURA_BODY_SYNC_STALL_TIMEOUT,
"Zakura body sync is not closing the gap to the network tip; legacy \
fallback disabled (legacy_p2p is off), continuing to wait for Zakura"
);
continue;
}
ZakuraWatchdogAction::FallbackToLegacy => {
warn!(
verified_tip = ?verified_height,
header_tip = ?header_tip_height,
stall = ?ZAKURA_BODY_SYNC_STALL_TIMEOUT,
"Zakura body sync is not closing the gap to the network tip; resuming \
legacy ChainSync as the body-sync driver while Zakura keeps serving \
peers and following local commits"
);
engage_legacy_fallback_alongside_zakura(&block_sync_handoff).await;
return self.sync().await;
}
ZakuraWatchdogAction::ProbeLegacyPeers => {
let blocks_ahead = self.legacy_peers_blocks_ahead().await;
info!(
verified_tip = ?verified_height,
?blocks_ahead,
"Zakura watchdog probed legacy peers for connected blocks ahead"
);
if legacy_probe_supports_fallback(blocks_ahead) {
warn!(
verified_tip = ?verified_height,
header_tip = ?header_tip_height,
?blocks_ahead,
"Zakura body sync is frozen while legacy peers advertise a much \
higher tip; resuming legacy ChainSync as the body-sync driver \
while Zakura keeps serving peers and following local commits"
);
engage_legacy_fallback_alongside_zakura(&block_sync_handoff).await;
return self.sync().await;
}
}
}
}
}
async fn legacy_peers_blocks_ahead(&mut self) -> Option<HeightDiff> {
let block_locator = self
.state
.ready()
.await
.ok()?
.call(zakura_state::Request::BlockLocator)
.await
.ok()
.and_then(|response| match response {
zakura_state::Response::BlockLocator(block_locator) => Some(block_locator),
_ => None,
})?;
let mut requests = FuturesUnordered::new();
for attempt in 0..FANOUT {
if attempt > 0 {
tokio::task::yield_now().await;
}
let ready_tip_network = self.tip_network.ready().await.ok()?;
requests.push(tokio::spawn(ready_tip_network.call(
zn::Request::FindHeaders {
known_blocks: block_locator.clone(),
stop: None,
},
)));
}
let mut best_ahead: Option<HeightDiff> = None;
while let Some(res) = requests.next().await {
let headers = match res {
Ok(Ok(zn::Response::BlockHeaders(headers))) => headers,
_ => continue,
};
let mut ahead: HeightDiff = 0;
let mut run_parent: Option<block::Hash> = None;
for counted in headers {
let hash = counted.header.hash();
if self.state_contains(hash).await.unwrap_or(true) {
ahead = 0;
run_parent = Some(hash);
continue;
}
let parent = counted.header.previous_block_hash;
let anchored = match run_parent {
Some(run_parent) => parent == run_parent,
None => self.state_contains(parent).await.unwrap_or(false),
};
if !anchored {
ahead = 0;
break;
}
ahead += 1;
run_parent = Some(hash);
if ahead >= ZAKURA_LEGACY_BEHIND_THRESHOLD {
return Some(ahead);
}
}
best_ahead = Some(best_ahead.unwrap_or(0).max(ahead));
}
best_ahead
}
#[instrument(skip(self))]
async fn try_to_sync(&mut self) -> Result<(), Report> {
self.prospective_tips = HashSet::new();
self.missing_block_retry_counts.clear();
self.registry_miss_retry_counts.clear();
self.registry_miss_retry.clear();
let state_tip = self.latest_chain_tip.best_tip_height();
self.trace.round_start(state_tip);
info!(?state_tip, "starting sync, obtaining new tips");
let extra_hashes = timeout(SYNC_RESTART_DELAY, self.obtain_tips())
.await
.map_err(Into::into)
.and_then(convert::identity)
.map_err(|e| {
info!("temporary error obtaining tips: {:#}", e);
e
});
let extra_hashes = match extra_hashes {
Ok(extra_hashes) => extra_hashes,
Err(error) => {
self.trace
.round_finish("obtain_tips_error", state_tip, Some(&error));
return Err(error);
}
};
self.update_metrics();
self.trace
.tips_obtained(extra_hashes.len(), self.prospective_tips.len());
if let Err(error) = self.sync_round(extra_hashes).await {
self.trace_sync_snapshot("round_error_snapshot", 0);
self.trace.round_finish(
"sync_error",
self.latest_chain_tip.best_tip_height(),
Some(&error),
);
return Err(error);
}
info!("exhausted prospective tip set");
self.trace
.round_finish("exhausted", self.latest_chain_tip.best_tip_height(), None);
Ok(())
}
#[instrument(skip(self, reserve))]
async fn sync_round(&mut self, mut reserve: IndexSet<block::Hash>) -> Result<(), Report> {
type ExtendOutput = Result<(IndexSet<block::Hash>, HashSet<CheckedTip>, usize), Report>;
let mut extend: Option<Pin<Box<dyn Future<Output = ExtendOutput> + Send>>> = None;
let mut last_progress = Instant::now();
loop {
while let Poll::Ready(Some(rsp)) = futures::poll!(self.downloads.next()) {
self.handle_block_response_with_missing_retry(rsp).await?;
last_progress = Instant::now();
}
metrics::gauge!("sync.reserve.depth").set(reserve.len() as f64);
self.update_metrics();
if extend.is_none()
&& reserve.len() < MIN_UNREQUESTED_HASHES_BEFORE_EXTEND
&& !self.prospective_tips.is_empty()
{
debug!(
tips.len = self.prospective_tips.len(),
in_flight = self.downloads.in_flight(),
reserve = reserve.len(),
"prefetching more tip hashes",
);
let tip_network = self.tip_network.clone();
let tips = std::mem::take(&mut self.prospective_tips);
extend = Some(Box::pin(Self::build_extend(tip_network, tips)));
}
let lookahead_limit = self.lookahead_limit(reserve.len());
let past_lookahead = self.downloads.in_flight() >= lookahead_limit
|| (self.downloads.in_flight() >= lookahead_limit / 2
&& self.past_lookahead_limit_receiver.cloned_watch_data());
let head_of_line_starved = !self.registry_miss_retry.is_empty();
if !past_lookahead && !head_of_line_starved && !reserve.is_empty() {
debug!(
tips.len = self.prospective_tips.len(),
in_flight = self.downloads.in_flight(),
reserve = reserve.len(),
lookahead_limit,
state_tip = ?self.latest_chain_tip.best_tip_height(),
"requesting more blocks",
);
let response = timeout(
BLOCK_VERIFY_TIMEOUT,
self.request_blocks(std::mem::take(&mut reserve)),
)
.await
.map_err(Report::from)?;
reserve = Self::handle_hash_response(response)?;
last_progress = Instant::now();
continue;
}
if reserve.is_empty()
&& extend.is_none()
&& self.prospective_tips.is_empty()
&& self.registry_miss_retry.is_empty()
&& self.downloads.in_flight() > 0
{
let completed = timeout(TIP_REFRESH_INTERVAL, self.downloads.next()).await;
match completed {
Ok(Some(rsp)) => {
self.handle_block_response_with_missing_retry(rsp).await?;
last_progress = Instant::now();
self.update_metrics();
}
Ok(None) => {}
Err(_) => {
if last_progress.elapsed() >= BLOCK_VERIFY_TIMEOUT {
return Err(eyre!(
"sync round stalled: no block completed or tips extended within timeout"
));
}
info!(
in_flight = self.downloads.in_flight(),
state_tip = ?self.latest_chain_tip.best_tip_height(),
"refreshing tips: in-flight blocks are waiting on undiscovered hashes",
);
metrics::counter!("sync.tip.refresh").increment(1);
let refreshed = timeout(SYNC_RESTART_DELAY, self.obtain_tips())
.await
.map_err(Into::into)
.and_then(convert::identity)?;
reserve.extend(refreshed);
self.update_metrics();
}
}
continue;
}
if self.downloads.in_flight() == 0
&& reserve.is_empty()
&& extend.is_none()
&& self.prospective_tips.is_empty()
&& self.registry_miss_retry.is_empty()
{
break;
}
let has_inflight = self.downloads.in_flight() > 0;
let registry_retry_at = self.registry_miss_retry.values().min().copied();
let step = timeout(BLOCK_VERIFY_TIMEOUT, async {
tokio::select! {
biased;
_ = OptionFuture::from(registry_retry_at.map(sleep_until)),
if registry_retry_at.is_some() =>
{
let now = tokio::time::Instant::now();
let due: Vec<block::Hash> = self
.registry_miss_retry
.iter()
.filter(|(_, deadline)| **deadline <= now)
.map(|(hash, _)| *hash)
.collect();
for hash in due {
self.registry_miss_retry.remove(&hash);
match self.downloads.download_and_verify(hash).await {
Ok(())
| Err(BlockDownloadVerifyError::DuplicateBlockQueuedForDownload {
..
}) => {}
Err(error) => self.handle_block_response(Err(error))?,
}
}
last_progress = Instant::now();
}
rsp = self.downloads.next(), if has_inflight => {
let rsp = rsp.expect("downloads is nonempty");
self.handle_block_response_with_missing_retry(rsp).await?;
last_progress = Instant::now();
self.update_metrics();
}
extended = OptionFuture::from(extend.as_mut()), if extend.is_some() => {
let (download_set, new_tips, discovered) =
extended.expect("only polled while an extension is in flight")?;
self.trace.tips_extended(discovered, new_tips.len());
self.prospective_tips = new_tips;
self.recent_syncs.push_extend_tips_length(discovered);
reserve.extend(download_set);
extend = None;
last_progress = Instant::now();
}
}
Ok::<(), Report>(())
})
.await;
match step {
Ok(result) => result?,
Err(_elapsed) => {
if last_progress.elapsed() >= BLOCK_VERIFY_TIMEOUT {
self.trace_sync_snapshot("round_stalled", reserve.len());
return Err(eyre!(
"sync round stalled: no block completed or tips extended within timeout"
));
}
}
}
}
Ok(())
}
#[instrument(skip(self))]
async fn obtain_tips(&mut self) -> Result<IndexSet<block::Hash>, Report> {
let stage_start = std::time::Instant::now();
let block_locator = self
.state
.ready()
.await
.map_err(|e| eyre!(e))?
.call(zakura_state::Request::BlockLocator)
.await
.map(|response| match response {
zakura_state::Response::BlockLocator(block_locator) => block_locator,
_ => unreachable!(
"GetBlockLocator request can only result in Response::BlockLocator"
),
})
.map_err(|e| eyre!(e))?;
debug!(
tip = ?block_locator.first().expect("we have at least one block locator object"),
?block_locator,
"got block locator and trying to obtain new chain tips"
);
let mut requests = FuturesUnordered::new();
for attempt in 0..FANOUT {
if attempt > 0 {
tokio::task::yield_now().await;
}
let ready_tip_network = self.tip_network.ready().await;
requests.push(tokio::spawn(ready_tip_network.map_err(|e| eyre!(e))?.call(
zn::Request::FindBlocks {
known_blocks: block_locator.clone(),
stop: None,
},
)));
}
let mut download_set = IndexSet::new();
while let Some(res) = requests.next().await {
match res
.unwrap_or_else(|e @ JoinError { .. }| {
if e.is_panic() {
panic!("panic in obtain tips task: {e:?}");
} else {
info!(
"task error during obtain tips task: {e:?},\
is Zebra shutting down?"
);
Err(e.into())
}
})
.map_err::<Report, _>(|e| eyre!(e))
{
Ok(zn::Response::BlockHashes(hashes)) => {
trace!(?hashes);
let hashes = if self.is_regtest {
hashes.as_slice()
} else {
match hashes.as_slice() {
[] => continue,
[rest @ .., _last] => rest,
}
};
if hashes.is_empty() {
continue;
}
let mut first_unknown = None;
for (i, &hash) in hashes.iter().enumerate() {
if !self.state_contains(hash).await? {
first_unknown = Some(i);
break;
}
}
debug!(hashes.len = ?hashes.len(), ?first_unknown);
let unknown_hashes = if let Some(index) = first_unknown {
&hashes[index..]
} else {
continue;
};
trace!(?unknown_hashes);
let new_tip = if let Some(end) = unknown_hashes.rchunks_exact(2).next() {
CheckedTip {
tip: end[0],
expected_next: end[1],
}
} else {
debug!("discarding response that extends only one block");
continue;
};
if !download_set.contains(&new_tip.expected_next) {
debug!(?new_tip,
"adding new prospective tip, and removing existing tips in the new block hash list");
self.prospective_tips
.retain(|t| !unknown_hashes.contains(&t.expected_next));
self.prospective_tips.insert(new_tip);
} else {
debug!(
?new_tip,
"discarding prospective tip: already in download set"
);
}
let prev_download_len = download_set.len();
download_set.extend(unknown_hashes);
let new_download_len = download_set.len();
let new_hashes = new_download_len - prev_download_len;
debug!(new_hashes, "added hashes to download set");
metrics::histogram!("sync.obtain.response.hash.count")
.record(new_hashes as f64);
}
Ok(_) => unreachable!("network returned wrong response"),
Err(e) => debug!(?e),
}
}
debug!(?self.prospective_tips);
for hash in &download_set {
debug!(?hash, "checking if state contains hash");
if self.state_contains(*hash).await? {
return Err(eyre!("queued download of hash behind our chain tip"));
}
}
let new_downloads = download_set.len();
debug!(new_downloads, "queueing new downloads");
metrics::gauge!("sync.obtain.queued.hash.count").set(new_downloads as f64);
self.recent_syncs.push_obtain_tips_length(new_downloads);
let response = self.request_blocks(download_set).await;
metrics::histogram!("sync.stage.duration_seconds", "stage" => "obtain_tips")
.record(stage_start.elapsed().as_secs_f64());
Self::handle_hash_response(response).map_err(Into::into)
}
#[instrument(skip_all)]
async fn build_extend(
mut tip_network: Timeout<ZN>,
tips: HashSet<CheckedTip>,
) -> Result<(IndexSet<block::Hash>, HashSet<CheckedTip>, usize), Report> {
let stage_start = std::time::Instant::now();
let mut prospective_tips: HashSet<CheckedTip> = HashSet::new();
let mut download_set = IndexSet::new();
debug!(tips = ?tips.len(), "trying to extend chain tips");
for tip in tips {
debug!(?tip, "asking peers to extend chain tip");
let mut responses = FuturesUnordered::new();
for attempt in 0..FANOUT {
if attempt > 0 {
tokio::task::yield_now().await;
}
let ready_tip_network = tip_network.ready().await;
responses.push(tokio::spawn(ready_tip_network.map_err(|e| eyre!(e))?.call(
zn::Request::FindBlocks {
known_blocks: vec![tip.tip],
stop: None,
},
)));
}
while let Some(res) = responses.next().await {
match res
.expect("panic in spawned extend tips request")
.map_err::<Report, _>(|e| eyre!(e))
{
Ok(zn::Response::BlockHashes(hashes)) => {
debug!(first = ?hashes.first(), len = ?hashes.len());
trace!(?hashes);
let unknown_hashes = match hashes.as_slice() {
[expected_hash, rest @ ..] if expected_hash == &tip.expected_next => {
rest
}
[first_hash, expected_hash, rest @ ..]
if expected_hash == &tip.expected_next =>
{
debug!(?first_hash,
?tip.expected_next,
?tip.tip,
"unexpected first hash, but the second matches: using the hashes after the match");
rest
}
[] => continue,
[single_hash] => {
debug!(?single_hash,
?tip.expected_next,
?tip.tip,
"discarding response containing a single unexpected hash");
continue;
}
[first_hash, second_hash, rest @ ..] => {
debug!(?first_hash,
?second_hash,
rest_len = ?rest.len(),
?tip.expected_next,
?tip.tip,
"discarding response that starts with two unexpected hashes");
continue;
}
};
let unknown_hashes = match unknown_hashes {
[] => continue,
[rest @ .., _last] => rest,
};
let new_tip = if let Some(end) = unknown_hashes.rchunks_exact(2).next() {
CheckedTip {
tip: end[0],
expected_next: end[1],
}
} else {
debug!("discarding response that extends only one block");
continue;
};
trace!(?unknown_hashes);
if !download_set.contains(&new_tip.expected_next) {
debug!(?new_tip,
"adding new prospective tip, and removing any existing tips in the new block hash list");
prospective_tips.retain(|t| !unknown_hashes.contains(&t.expected_next));
prospective_tips.insert(new_tip);
} else {
debug!(
?new_tip,
"discarding prospective tip: already in download set"
);
}
let prev_download_len = download_set.len();
download_set.extend(unknown_hashes);
let new_download_len = download_set.len();
let new_hashes = new_download_len - prev_download_len;
debug!(new_hashes, "added hashes to download set");
metrics::histogram!("sync.extend.response.hash.count")
.record(new_hashes as f64);
}
Ok(_) => unreachable!("network returned wrong response"),
Err(e) => debug!(?e),
}
}
}
let new_downloads = download_set.len();
debug!(new_downloads, "discovered new hashes to download");
metrics::gauge!("sync.extend.queued.hash.count").set(new_downloads as f64);
metrics::histogram!("sync.stage.duration_seconds", "stage" => "extend_tips")
.record(stage_start.elapsed().as_secs_f64());
Ok((download_set, prospective_tips, new_downloads))
}
async fn request_genesis(&mut self) -> Result<(), Report> {
while !self.state_contains(self.genesis_hash).await? {
info!("starting genesis block download and verify");
let response = timeout(SYNC_RESTART_DELAY, self.request_genesis_once())
.await
.map_err(Into::into);
match response {
Ok(Ok(Ok(response))) => self
.handle_block_response(Ok(response))
.expect("never returns Err for Ok"),
Ok(Err(fatal_error)) => Err(fatal_error)?,
Err(error) | Ok(Ok(Err(error))) => {
if self.is_duplicate_finalized_genesis_error(&error) {
info!(
?error,
"genesis block is already finalized, continuing sync"
);
return Ok(());
}
if Self::should_restart_sync(&error) {
warn!(
?error,
"could not download or verify genesis block, retrying"
);
} else {
info!(
?error,
"temporary error downloading or verifying genesis block, retrying"
);
}
tokio::time::sleep(GENESIS_TIMEOUT_RETRY).await;
}
}
}
Ok(())
}
fn is_duplicate_finalized_genesis_error(&self, error: &BlockDownloadVerifyError) -> bool {
match error {
BlockDownloadVerifyError::Invalid {
error,
height,
hash,
..
} => {
*height == Height(0)
&& *hash == self.genesis_hash
&& Self::is_duplicate_finalized_error(error)
}
_ => false,
}
}
fn is_duplicate_finalized_error(error: &zakura_consensus::RouterError) -> bool {
error.duplicate_location() == Some(&zs::KnownBlock::Finalized)
}
async fn request_genesis_once(
&mut self,
) -> Result<Result<(Height, block::Hash), BlockDownloadVerifyError>, Report> {
let response = self.downloads.download_and_verify(self.genesis_hash).await;
Self::handle_response(response).map_err(|e| eyre!(e))?;
let response = self.downloads.next().await.expect("downloads is nonempty");
Ok(response)
}
async fn request_blocks(
&mut self,
mut hashes: IndexSet<block::Hash>,
) -> Result<IndexSet<block::Hash>, BlockDownloadVerifyError> {
let lookahead_limit = self.lookahead_limit(hashes.len());
debug!(
hashes.len = hashes.len(),
?lookahead_limit,
"requesting blocks",
);
let extra_hashes = if hashes.len() > lookahead_limit {
hashes.split_off(lookahead_limit)
} else {
IndexSet::new()
};
for hash in hashes.into_iter() {
match self.downloads.download_and_verify(hash).await {
Ok(()) => {}
Err(BlockDownloadVerifyError::DuplicateBlockQueuedForDownload { .. }) => {
debug!("block request was already queued, continuing");
}
Err(error) => return Err(error),
}
}
Ok(extra_hashes)
}
fn lookahead_limit(&self, new_hashes: usize) -> usize {
let max_checkpoint_height: usize = self
.max_checkpoint_height
.0
.try_into()
.expect("fits in usize");
let verified_height: usize = self
.latest_chain_tip
.best_tip_height()
.unwrap_or(Height(0))
.0
.try_into()
.expect("fits in usize");
if verified_height >= max_checkpoint_height {
self.full_verify_concurrency_limit
} else if (verified_height + new_hashes) >= max_checkpoint_height {
let checkpoint_hashes = verified_height + new_hashes - max_checkpoint_height;
self.full_verify_concurrency_limit + checkpoint_hashes
} else {
self.checkpoint_verify_concurrency_limit
}
}
#[allow(unknown_lints)]
fn handle_block_response(
&mut self,
response: Result<(Height, block::Hash), BlockDownloadVerifyError>,
) -> Result<(), BlockDownloadVerifyError> {
match response {
Ok((height, hash)) => {
trace!(?height, ?hash, "verified and committed block to state");
return Ok(());
}
Err(BlockDownloadVerifyError::Invalid {
ref error,
advertiser_addr: Some(advertiser_addr),
..
}) if error.misbehavior_score() != 0 => {
let _ = self
.misbehavior_sender
.try_send((advertiser_addr, error.misbehavior_score()));
}
Err(BlockDownloadVerifyError::AboveLookaheadHeightLimit {
advertiser_addr: Some(advertiser_addr),
..
}) => {
let _ = self.misbehavior_sender.try_send((advertiser_addr, 100));
}
Err(BlockDownloadVerifyError::InvalidHeight {
advertiser_addr: Some(advertiser_addr),
..
}) => {
let _ = self.misbehavior_sender.try_send((advertiser_addr, 100));
}
Err(_) => {}
};
Self::handle_response(response)
}
async fn handle_block_response_with_missing_retry(
&mut self,
response: Result<(Height, block::Hash), BlockDownloadVerifyError>,
) -> Result<(), Report> {
if let Ok((_height, hash)) = response.as_ref() {
self.missing_block_retry_counts.remove(hash);
self.registry_miss_retry_counts.remove(hash);
self.registry_miss_retry.remove(hash);
}
if let Some((hash, kind)) = response
.as_ref()
.err()
.and_then(BlockDownloadVerifyError::not_found_download)
{
match kind {
NotFoundKind::Response => {
let retry_count = self.missing_block_retry_counts.entry(hash).or_default();
if *retry_count < MISSING_BLOCK_DOWNLOAD_RETRY_LIMIT {
*retry_count += 1;
info!(
?hash,
retry_attempt = *retry_count,
retry_limit = MISSING_BLOCK_DOWNLOAD_RETRY_LIMIT,
"missing sync block download failed, retrying required block"
);
metrics::counter!("sync.missing.block.requeued.count").increment(1);
match self.downloads.download_and_verify(hash).await {
Ok(()) => return Ok(()),
Err(BlockDownloadVerifyError::DuplicateBlockQueuedForDownload {
..
}) => {
return Ok(());
}
Err(error) => self.handle_block_response(Err(error))?,
}
return Ok(());
}
self.missing_block_retry_counts.remove(&hash);
warn!(
?hash,
retry_limit = MISSING_BLOCK_DOWNLOAD_RETRY_LIMIT,
"missing sync block retry budget exhausted, restarting sync"
);
metrics::counter!("sync.missing.block.retry.limit.count").increment(1);
}
NotFoundKind::Registry => {
metrics::counter!("sync.missing.block.registry.miss.count").increment(1);
let retry_count = self.registry_miss_retry_counts.entry(hash).or_default();
if *retry_count < MISSING_BLOCK_REGISTRY_RETRY_LIMIT {
*retry_count += 1;
debug!(
?hash,
retry_attempt = *retry_count,
retry_limit = MISSING_BLOCK_REGISTRY_RETRY_LIMIT,
"required sync block is missing from all current peers, retrying after backoff"
);
metrics::counter!("sync.missing.block.registry.retry.count").increment(1);
self.registry_miss_retry.insert(
hash,
tokio::time::Instant::now() + REGISTRY_MISS_RETRY_BACKOFF,
);
return Ok(());
}
self.registry_miss_retry_counts.remove(&hash);
self.registry_miss_retry.remove(&hash);
warn!(
?hash,
retry_limit = MISSING_BLOCK_REGISTRY_RETRY_LIMIT,
"required sync block missing from all peers past retry budget, restarting sync"
);
}
}
}
self.handle_block_response(response)?;
Ok(())
}
#[allow(unknown_lints)]
fn handle_hash_response(
response: Result<IndexSet<block::Hash>, BlockDownloadVerifyError>,
) -> Result<IndexSet<block::Hash>, BlockDownloadVerifyError> {
match response {
Ok(extra_hashes) => Ok(extra_hashes),
Err(_) => Self::handle_response(response).map(|()| IndexSet::new()),
}
}
#[allow(unknown_lints)]
fn handle_response<T>(
response: Result<T, BlockDownloadVerifyError>,
) -> Result<(), BlockDownloadVerifyError> {
match response {
Ok(_t) => Ok(()),
Err(error) => {
if Self::should_restart_sync(&error) {
Err(error)
} else {
Ok(())
}
}
}
}
pub(crate) async fn state_contains(&mut self, hash: block::Hash) -> Result<bool, Report> {
match self
.state
.ready()
.await
.map_err(|e| eyre!(e))?
.call(zakura_state::Request::KnownBlock(hash))
.await
.map_err(|e| eyre!(e))?
{
zs::Response::KnownBlock(loc) => Ok(loc.is_some()),
_ => unreachable!("wrong response to known block request"),
}
}
fn update_metrics(&mut self) {
metrics::gauge!("sync.prospective_tips.len",).set(self.prospective_tips.len() as f64);
metrics::gauge!("sync.downloads.in_flight",).set(self.downloads.in_flight() as f64);
let phase_counts = self.downloads.phase_counts();
for (phase, metric) in [
("waiting_network", "sync.downloads.waiting_network"),
("downloading", "sync.downloads.downloading"),
("response_received", "sync.downloads.response_received"),
("waiting_verifier", "sync.downloads.waiting_verifier"),
("verifying", "sync.downloads.verifying"),
] {
let count = u32::try_from(phase_counts.get(phase).copied().unwrap_or_default())
.unwrap_or(u32::MAX);
metrics::gauge!(metric).set(f64::from(count));
}
}
fn trace_sync_snapshot(&self, event: &'static str, reserve: usize) {
self.downloads.as_ref().get_ref().emit_diagnostic_snapshot(
event,
self.latest_chain_tip.best_tip_height(),
reserve,
self.prospective_tips.len(),
self.registry_miss_retry.len(),
);
}
fn should_restart_sync(e: &BlockDownloadVerifyError) -> bool {
match e {
BlockDownloadVerifyError::Invalid { error, .. } if error.is_duplicate_request() => {
debug!(error = ?e, "block was already verified or committed, possibly from a previous sync run, continuing");
false
}
BlockDownloadVerifyError::Invalid { error, .. }
if Self::is_duplicate_finalized_error(error) =>
{
debug!(
error = ?e,
"block was already finalized, possibly from a previous sync run, continuing"
);
false
}
BlockDownloadVerifyError::CancelledDuringDownload { .. }
| BlockDownloadVerifyError::CancelledDuringVerification { .. } => {
debug!(error = ?e, "block verification was cancelled, continuing");
false
}
BlockDownloadVerifyError::BehindTipHeightLimit { .. } => {
debug!(
error = ?e,
"block height is behind the current state tip, \
assuming the syncer will eventually catch up to the state, continuing"
);
false
}
BlockDownloadVerifyError::AboveLookaheadHeightLimit { .. } => {
debug!(
error = ?e,
"block height is above the lookahead limit, \
dropping the block and continuing sync"
);
false
}
BlockDownloadVerifyError::InvalidHeight { .. } => {
debug!(
error = ?e,
"block has no valid height, \
dropping the block and continuing sync"
);
false
}
BlockDownloadVerifyError::DuplicateBlockQueuedForDownload { .. } => {
debug!(
error = ?e,
"queued duplicate block hash for download, \
assuming the syncer will eventually resolve duplicates, continuing"
);
false
}
BlockDownloadVerifyError::DownloadFailed { .. }
if e.not_found_download_hash().is_some() =>
{
warn!(
error = ?e,
"required sync block was not found after retries, restarting sync"
);
true
}
_ => {
let err_str = format!("{e:?}");
if err_str.contains("NotFound") {
error!(?e,
"a BlockDownloadVerifyError that should have been filtered out was detected, \
which possibly indicates a programming error in the downcast inside \
zakurad::components::sync::downloads::Downloads::download_and_verify"
)
}
warn!(?e, "error downloading and verifying block");
true
}
}
}
}