From 665a577d14b71e201b5194de874c40246fa7e6c2 Mon Sep 17 00:00:00 2001 From: Edgar Luque Date: Wed, 27 May 2026 15:30:32 +0200 Subject: [PATCH 1/4] fix(l1): clearer sync diagnostics during catch-up - eth_syncing: report real highestBlock number instead of the truncated forkchoice head hash (was emitting garbage like 0x3abc579fc0fc31b8) - full sync: log the consensus-provided sync target and how far behind the local head is, and warn (when stale > 30m) that the consensus client may be catching up to chain head - full sync: log when a behind cycle reaches the consensus-provided head so idle-waiting is distinguishable from a hang --- crates/networking/p2p/sync/full.rs | 92 ++++++++++++++++++++++++++++- crates/networking/rpc/eth/client.rs | 19 ++++-- 2 files changed, 104 insertions(+), 7 deletions(-) diff --git a/crates/networking/p2p/sync/full.rs b/crates/networking/p2p/sync/full.rs index 561a09b0808..15250a7fdb1 100644 --- a/crates/networking/p2p/sync/full.rs +++ b/crates/networking/p2p/sync/full.rs @@ -4,8 +4,9 @@ //! are fetched via p2p eth requests and executed to rebuild the state. use std::cmp::min; -use std::sync::Arc; -use std::time::Duration; +use std::io::IsTerminal; +use std::sync::{Arc, LazyLock}; +use std::time::{Duration, SystemTime, UNIX_EPOCH}; use ethrex_blockchain::{ BatchBlockProcessingFailure, Blockchain, @@ -25,6 +26,46 @@ use crate::snap::constants::{MAX_BLOCK_BODIES_TO_REQUEST, MAX_HEADER_FETCH_ATTEM use super::{EXECUTE_BATCH_SIZE, SyncError}; +/// Forkchoice heads older than this (in seconds) trigger a "consensus is behind" +/// warning during sync. A synced consensus client always advertises a head only +/// a few seconds old, so a large age means the consensus client itself is lagging +/// chain head and is the sync bottleneck. +const STALE_FORKCHOICE_HEAD_SECS: u64 = 1800; + +/// Distance (in blocks) below which the node is considered to be following head. +/// Below this we suppress the per-cycle sync-target logging to avoid noise on an +/// already-synced node, which runs a sync cycle on every slot. +const FOLLOW_DISTANCE: u64 = 8; + +/// Whether stdout is a color-capable TTY. Honors the `NO_COLOR` convention and +/// matches the writer used by the tracing fmt layer, so logs piped to a file or +/// to journald stay plain. Note: this does not read the `--log.color` CLI flag. +static STDOUT_COLOR: LazyLock = + LazyLock::new(|| std::env::var_os("NO_COLOR").is_none() && std::io::stdout().is_terminal()); + +/// Wrap `text` in bold-yellow ANSI when stdout supports color, otherwise return it as-is. +fn highlight(text: &str) -> String { + if *STDOUT_COLOR { + format!("\x1b[1;33m{text}\x1b[0m") + } else { + text.to_string() + } +} + +/// Render a duration in seconds as a compact human string, e.g. "13d 4h". +fn humanize_secs(secs: u64) -> String { + let days = secs / 86_400; + let hours = (secs % 86_400) / 3_600; + let mins = (secs % 3_600) / 60; + if days > 0 { + format!("{days}d {hours}h") + } else if hours > 0 { + format!("{hours}h {mins}m") + } else { + format!("{mins}m") + } +} + /// Performs full sync cycle - fetches and executes all blocks between current head and sync head /// /// # Returns @@ -60,6 +101,12 @@ pub async fn sync_cycle_full( let mut attempts = 0; + // Tracks whether this cycle started meaningfully behind the consensus-provided + // head, so we can log progress and a final "caught up" message without spamming + // a synced node. Set on the first batch of headers we fetch. + let mut started_behind = false; + let mut sync_target_logged = false; + // Request and store all block headers from the advertised sync head loop { let Some(mut block_headers) = peers @@ -92,6 +139,38 @@ pub async fn sync_cycle_full( first_header.number, last_header.number, ); + + // On the first batch, report the distance to the consensus-provided head and + // warn if that head is stale (a strong signal the consensus client is behind). + if !sync_target_logged { + sync_target_logged = true; + let target = first_header.number; + let target_ts = first_header.timestamp; + let local_head = store.get_latest_block_number().await?; + let behind = target.saturating_sub(local_head); + if behind > FOLLOW_DISTANCE { + started_behind = true; + info!( + "Sync target from consensus forkchoice: block {target} ({behind} blocks ahead of local head {local_head})" + ); + let now = SystemTime::now() + .duration_since(UNIX_EPOCH) + .unwrap_or_default() + .as_secs(); + let age = now.saturating_sub(target_ts); + if age > STALE_FORKCHOICE_HEAD_SECS { + warn!( + "{}", + highlight(&format!( + "Consensus forkchoice head (block {target}) is {} old. This can happen while the consensus client is still catching up to chain head; \ + if so, execution will only advance as fast as it does. If sync seems slow, it may be worth checking the consensus client's sync status.", + humanize_secs(age) + )) + ); + } + } + } + end_block_number = end_block_number.max(first_header.number); start_block_number = last_header.number; @@ -266,6 +345,15 @@ pub async fn sync_cycle_full( .await?; } + // If this cycle started behind, announce that we've caught up to the head the + // consensus client gave us, so the operator can tell idle-waiting from a hang. + if started_behind { + let local_head = store.get_latest_block_number().await?; + info!( + "Reached consensus-provided head at block {local_head}. Waiting for the next forkchoice update from the consensus client." + ); + } + store.clear_fullsync_headers().await?; Ok(()) } diff --git a/crates/networking/rpc/eth/client.rs b/crates/networking/rpc/eth/client.rs index 6ae2bfeb34f..5c6c71e8f00 100644 --- a/crates/networking/rpc/eth/client.rs +++ b/crates/networking/rpc/eth/client.rs @@ -58,13 +58,22 @@ impl RpcHandler for Syncing { if context.blockchain.is_synced() { Ok(Value::Bool(!context.blockchain.is_synced())) } else { + let current_block = context.storage.get_latest_block_number().await?; + // `get_last_fcu_head` returns the head *hash* from the last forkchoiceUpdated. + // Resolve it to a block number; if the head's header isn't stored yet (e.g. + // mid snap-sync), fall back to the current block instead of reporting garbage. + let head_hash = syncer + .get_last_fcu_head() + .map_err(|error| RpcErr::Internal(error.to_string()))?; + let highest_block = context + .storage + .get_block_number(head_hash) + .await? + .unwrap_or(current_block); let syncing_status = SyncingStatusRpc { starting_block: context.storage.get_earliest_block_number().await?, - current_block: context.storage.get_latest_block_number().await?, - highest_block: syncer - .get_last_fcu_head() - .map_err(|error| RpcErr::Internal(error.to_string()))? - .to_low_u64_be(), + current_block, + highest_block, }; serde_json::to_value(syncing_status) .map_err(|error| RpcErr::Internal(error.to_string())) From fbb285b7fa012c4f0746482313ec25fd9eb1388b Mon Sep 17 00:00:00 2001 From: Edgar Luque Date: Wed, 27 May 2026 15:39:22 +0200 Subject: [PATCH 2/4] fix(l1): drop color handling from stale-head warning --- crates/networking/p2p/sync/full.rs | 27 ++++----------------------- 1 file changed, 4 insertions(+), 23 deletions(-) diff --git a/crates/networking/p2p/sync/full.rs b/crates/networking/p2p/sync/full.rs index 15250a7fdb1..225894ed5cf 100644 --- a/crates/networking/p2p/sync/full.rs +++ b/crates/networking/p2p/sync/full.rs @@ -4,8 +4,7 @@ //! are fetched via p2p eth requests and executed to rebuild the state. use std::cmp::min; -use std::io::IsTerminal; -use std::sync::{Arc, LazyLock}; +use std::sync::Arc; use std::time::{Duration, SystemTime, UNIX_EPOCH}; use ethrex_blockchain::{ @@ -37,21 +36,6 @@ const STALE_FORKCHOICE_HEAD_SECS: u64 = 1800; /// already-synced node, which runs a sync cycle on every slot. const FOLLOW_DISTANCE: u64 = 8; -/// Whether stdout is a color-capable TTY. Honors the `NO_COLOR` convention and -/// matches the writer used by the tracing fmt layer, so logs piped to a file or -/// to journald stay plain. Note: this does not read the `--log.color` CLI flag. -static STDOUT_COLOR: LazyLock = - LazyLock::new(|| std::env::var_os("NO_COLOR").is_none() && std::io::stdout().is_terminal()); - -/// Wrap `text` in bold-yellow ANSI when stdout supports color, otherwise return it as-is. -fn highlight(text: &str) -> String { - if *STDOUT_COLOR { - format!("\x1b[1;33m{text}\x1b[0m") - } else { - text.to_string() - } -} - /// Render a duration in seconds as a compact human string, e.g. "13d 4h". fn humanize_secs(secs: u64) -> String { let days = secs / 86_400; @@ -160,12 +144,9 @@ pub async fn sync_cycle_full( let age = now.saturating_sub(target_ts); if age > STALE_FORKCHOICE_HEAD_SECS { warn!( - "{}", - highlight(&format!( - "Consensus forkchoice head (block {target}) is {} old. This can happen while the consensus client is still catching up to chain head; \ - if so, execution will only advance as fast as it does. If sync seems slow, it may be worth checking the consensus client's sync status.", - humanize_secs(age) - )) + "Consensus forkchoice head (block {target}) is {} old. This can happen while the consensus client is still catching up to chain head; \ + if so, execution will only advance as fast as it does. If sync seems slow, it may be worth checking the consensus client's sync status.", + humanize_secs(age) ); } } From d4d1d86c558454f8cd3f9ffec022d72ca8fae70d Mon Sep 17 00:00:00 2001 From: Edgar Luque Date: Wed, 27 May 2026 16:38:10 +0200 Subject: [PATCH 3/4] fix(l1): resolve pending-block head and pre-rewind FCU target in sync diagnostics --- crates/networking/p2p/sync/full.rs | 11 +++++++++-- crates/networking/rpc/eth/client.rs | 18 +++++++++++------- 2 files changed, 20 insertions(+), 9 deletions(-) diff --git a/crates/networking/p2p/sync/full.rs b/crates/networking/p2p/sync/full.rs index 225894ed5cf..a59761607b6 100644 --- a/crates/networking/p2p/sync/full.rs +++ b/crates/networking/p2p/sync/full.rs @@ -75,6 +75,13 @@ pub async fn sync_cycle_full( pending_blocks.insert(0, block); } + // The consensus-provided forkchoice head, captured before `sync_head` is rewound + // over the pending blocks above. Used for sync-target diagnostics so we report the + // actual head rather than the rewound ancestor we end up requesting headers from. + let fcu_head = pending_blocks + .last() + .map(|block| (block.header.number, block.header.timestamp)); + // Request all block headers between the sync head and our local chain // We will begin from the sync head so that we download the latest state first, ensuring we follow the correct chain // This step is not parallelized @@ -128,8 +135,8 @@ pub async fn sync_cycle_full( // warn if that head is stale (a strong signal the consensus client is behind). if !sync_target_logged { sync_target_logged = true; - let target = first_header.number; - let target_ts = first_header.timestamp; + let (target, target_ts) = + fcu_head.unwrap_or((first_header.number, first_header.timestamp)); let local_head = store.get_latest_block_number().await?; let behind = target.saturating_sub(local_head); if behind > FOLLOW_DISTANCE { diff --git a/crates/networking/rpc/eth/client.rs b/crates/networking/rpc/eth/client.rs index 5c6c71e8f00..f5ea6a7160e 100644 --- a/crates/networking/rpc/eth/client.rs +++ b/crates/networking/rpc/eth/client.rs @@ -60,16 +60,20 @@ impl RpcHandler for Syncing { } else { let current_block = context.storage.get_latest_block_number().await?; // `get_last_fcu_head` returns the head *hash* from the last forkchoiceUpdated. - // Resolve it to a block number; if the head's header isn't stored yet (e.g. - // mid snap-sync), fall back to the current block instead of reporting garbage. + // Resolve it to a block number. If the header isn't canonical yet it may still + // be a pending block whose number we can read; only when neither is available + // (e.g. mid snap-sync, target not downloaded) fall back to the current block + // instead of reporting garbage. let head_hash = syncer .get_last_fcu_head() .map_err(|error| RpcErr::Internal(error.to_string()))?; - let highest_block = context - .storage - .get_block_number(head_hash) - .await? - .unwrap_or(current_block); + let highest_block = match context.storage.get_block_number(head_hash).await? { + Some(number) => number, + None => match context.storage.get_pending_block(head_hash).await? { + Some(block) => block.header.number, + None => current_block, + }, + }; let syncing_status = SyncingStatusRpc { starting_block: context.storage.get_earliest_block_number().await?, current_block, From 52bc365714c23baeeab603be0949d098838e61a4 Mon Sep 17 00:00:00 2001 From: Edgar Luque Date: Thu, 28 May 2026 08:37:30 +0200 Subject: [PATCH 4/4] fix(l1): guard humanize_secs against sub-minute inputs --- crates/networking/p2p/sync/full.rs | 3 +++ 1 file changed, 3 insertions(+) diff --git a/crates/networking/p2p/sync/full.rs b/crates/networking/p2p/sync/full.rs index a59761607b6..2bc5878b973 100644 --- a/crates/networking/p2p/sync/full.rs +++ b/crates/networking/p2p/sync/full.rs @@ -38,6 +38,9 @@ const FOLLOW_DISTANCE: u64 = 8; /// Render a duration in seconds as a compact human string, e.g. "13d 4h". fn humanize_secs(secs: u64) -> String { + if secs < 60 { + return "< 1m".to_string(); + } let days = secs / 86_400; let hours = (secs % 86_400) / 3_600; let mins = (secs % 3_600) / 60;