From d4013bd596fe0e6748a42de0273470d921467570 Mon Sep 17 00:00:00 2001 From: Michael Sproul Date: Mon, 7 Jul 2025 13:25:11 +1000 Subject: [PATCH 1/6] Refine delayed head block logging --- .../beacon_chain/src/canonical_head.rs | 62 +++++++++---------- 1 file changed, 31 insertions(+), 31 deletions(-) diff --git a/beacon_node/beacon_chain/src/canonical_head.rs b/beacon_node/beacon_chain/src/canonical_head.rs index f96b59aec4b..f80a2d4089a 100644 --- a/beacon_node/beacon_chain/src/canonical_head.rs +++ b/beacon_node/beacon_chain/src/canonical_head.rs @@ -38,7 +38,7 @@ use crate::{ block_times_cache::BlockTimesCache, events::ServerSentEventHandler, metrics, - validator_monitor::{get_slot_delay_ms, timestamp_now}, + validator_monitor::get_slot_delay_ms, BeaconChain, BeaconChainError as Error, BeaconChainTypes, BeaconSnapshot, }; use eth2::types::{EventKind, SseChainReorg, SseFinalizedCheckpoint, SseHead, SseLateHead}; @@ -1287,7 +1287,10 @@ fn observe_head_block_delays( slot_clock: &S, event_handler: Option<&ServerSentEventHandler>, ) { - let block_time_set_as_head = timestamp_now(); + let Some(block_time_set_as_head) = slot_clock.now_duration() else { + // Practically unreachable: the slot clock's time should not be before the UNIX epoch. + return; + }; let head_block_root = head_block.root; let head_block_slot = head_block.slot; let head_block_is_optimistic = head_block.execution_status.is_optimistic_or_invalid(); @@ -1308,10 +1311,6 @@ fn observe_head_block_delays( // If a block comes in from over 4 slots ago, it is most likely a block from sync. let block_from_sync = block_delay_total > slot_clock.slot_duration() * 4; - // Determine whether the block has been set as head too late for proper attestation - // production. - let late_head = block_delay_total >= slot_clock.unagg_attestation_production_delay(); - // Do not store metrics if the block was > 4 slots old, this helps prevent noise during // sync. if !block_from_sync { @@ -1410,6 +1409,14 @@ fn observe_head_block_delays( .as_millis() as i64, ); + // Consider the block late if the time it became attestable is after the attestation + // deadline. If the block was not made attestable, use the set-as-head time. + let attestable_delay = block_delays.attestable.unwrap_or(block_delay_total); + + // Determine whether the block has been set as head too late for proper attestation + // production. + let late_head = attestable_delay >= slot_clock.unagg_attestation_production_delay(); + // If the block was enshrined as head too late for attestations to be created for it, // log a debug warning and increment a metric. let format_delay = |delay: &Option| { @@ -1432,6 +1439,24 @@ fn observe_head_block_delays( set_as_head_time_ms = format_delay(&block_delays.set_as_head), "Delayed head block" ); + if let Some(event_handler) = event_handler { + if event_handler.has_late_head_subscribers() { + let peer_info = block_times_cache.get_peer_info(head_block_root); + event_handler.register(EventKind::LateHead(SseLateHead { + slot: head_block_slot, + block: head_block_root, + peer_id: peer_info.id, + peer_client: peer_info.client, + proposer_index: head_block_proposer_index, + proposer_graffiti: head_block_graffiti, + block_delay: block_delay_total, + observed_delay: block_delays.observed, + imported_delay: block_delays.imported, + set_as_head_delay: block_delays.set_as_head, + execution_optimistic: head_block_is_optimistic, + })); + } + } } else { debug!( block_root = ?head_block_root, @@ -1450,29 +1475,4 @@ fn observe_head_block_delays( ); } } - - if let Some(event_handler) = event_handler { - if !block_from_sync && late_head && event_handler.has_late_head_subscribers() { - let peer_info = block_times_cache.get_peer_info(head_block_root); - let block_delays = block_times_cache.get_block_delays( - head_block_root, - slot_clock - .start_of(head_block_slot) - .unwrap_or_else(|| Duration::from_secs(0)), - ); - event_handler.register(EventKind::LateHead(SseLateHead { - slot: head_block_slot, - block: head_block_root, - peer_id: peer_info.id, - peer_client: peer_info.client, - proposer_index: head_block_proposer_index, - proposer_graffiti: head_block_graffiti, - block_delay: block_delay_total, - observed_delay: block_delays.observed, - imported_delay: block_delays.imported, - set_as_head_delay: block_delays.set_as_head, - execution_optimistic: head_block_is_optimistic, - })); - } - } } From b6027904a39dded6bb76f12180ae73cdc21daf4c Mon Sep 17 00:00:00 2001 From: Tan Chee Keong Date: Wed, 9 Jul 2025 21:36:25 +0800 Subject: [PATCH 2/6] Use ssz as default --- .../validator_services/src/block_service.rs | 47 +++++++++++++++---- 1 file changed, 37 insertions(+), 10 deletions(-) diff --git a/validator_client/validator_services/src/block_service.rs b/validator_client/validator_services/src/block_service.rs index 01f786e160b..bbc7c6013f8 100644 --- a/validator_client/validator_services/src/block_service.rs +++ b/validator_client/validator_services/src/block_service.rs @@ -524,22 +524,50 @@ impl BlockService { proposer_index: Option, builder_boost_factor: Option, ) -> Result, BlockError> { - let (block_response, _) = beacon_node - .get_validator_blocks_v3::( + let block_response = match beacon_node + .get_validator_blocks_v3_ssz::( slot, randao_reveal_ref, graffiti.as_ref(), builder_boost_factor, ) .await - .map_err(|e| { - BlockError::Recoverable(format!( - "Error from beacon node when producing block: {:?}", - e - )) - })?; + { + Ok((ssz_block_response, _)) => { + info!(slot = slot.as_u64(), "Received unsigned block in SSZ"); + + ssz_block_response + } + Err(e) => { + warn!( + slot = slot.as_u64(), + error = %e, + "Beacon node does not support SSZ in block production, falling back to JSON" + ); + + let (json_block_response, _) = beacon_node + .get_validator_blocks_v3::( + slot, + randao_reveal_ref, + graffiti.as_ref(), + builder_boost_factor, + ) + .await + .map_err(|e| { + BlockError::Recoverable(format!( + "Error from beacon node when producing block: {:?}", + e + )) + })?; + + info!(slot = slot.as_u64(), "Received unsigned block in JSON"); + + // Extract ProduceBlockV3Response (data field of the struct ForkVersionedResponse) + json_block_response.data + } + }; - let (block_proposer, unsigned_block) = match block_response.data { + let (block_proposer, unsigned_block) = match block_response { eth2::types::ProduceBlockV3Response::Full(block) => { (block.block().proposer_index(), UnsignedBlock::Full(block)) } @@ -548,7 +576,6 @@ impl BlockService { } }; - info!(slot = slot.as_u64(), "Received unsigned block"); if proposer_index != Some(block_proposer) { return Err(BlockError::Recoverable( "Proposer index does not match block proposer. Beacon chain re-orged".to_string(), From 429884be6164155d0d52d423acee04f996bb0abc Mon Sep 17 00:00:00 2001 From: Tan Chee Keong Date: Mon, 14 Jul 2025 09:15:10 +0800 Subject: [PATCH 3/6] simplify --- beacon_node/lighthouse_network/tests/common.rs | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/beacon_node/lighthouse_network/tests/common.rs b/beacon_node/lighthouse_network/tests/common.rs index 0dac126909c..c6d21871d66 100644 --- a/beacon_node/lighthouse_network/tests/common.rs +++ b/beacon_node/lighthouse_network/tests/common.rs @@ -5,6 +5,7 @@ use lighthouse_network::EnrExt; use lighthouse_network::Multiaddr; use lighthouse_network::{NetworkConfig, NetworkEvent}; use std::sync::Arc; +use std::sync::Once; use std::sync::Weak; use tokio::runtime::Runtime; use tracing::{debug, error, info_span, Instrument}; @@ -14,6 +15,8 @@ use types::{ MinimalEthSpec, Slot, }; +static INIT: Once = Once::new(); + type E = MinimalEthSpec; use lighthouse_network::rpc::config::InboundRateLimiterConfig; @@ -71,10 +74,11 @@ impl std::ops::DerefMut for Libp2pInstance { #[allow(unused)] pub fn build_tracing_subscriber(level: &str, enabled: bool) { if enabled { - tracing_subscriber::fmt() - .with_env_filter(EnvFilter::try_new(level).unwrap()) - .try_init() - .unwrap(); + INIT.call_once(|| { + tracing_subscriber::fmt() + .with_env_filter(EnvFilter::try_new(level).unwrap()) + .init(); + }); } } From 9a26794b67c3758a45a3add5234daf63c31af55e Mon Sep 17 00:00:00 2001 From: Tan Chee Keong Date: Mon, 14 Jul 2025 09:16:28 +0800 Subject: [PATCH 4/6] revert last commit --- beacon_node/lighthouse_network/tests/common.rs | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/beacon_node/lighthouse_network/tests/common.rs b/beacon_node/lighthouse_network/tests/common.rs index 0dac126909c..c6d21871d66 100644 --- a/beacon_node/lighthouse_network/tests/common.rs +++ b/beacon_node/lighthouse_network/tests/common.rs @@ -5,6 +5,7 @@ use lighthouse_network::EnrExt; use lighthouse_network::Multiaddr; use lighthouse_network::{NetworkConfig, NetworkEvent}; use std::sync::Arc; +use std::sync::Once; use std::sync::Weak; use tokio::runtime::Runtime; use tracing::{debug, error, info_span, Instrument}; @@ -14,6 +15,8 @@ use types::{ MinimalEthSpec, Slot, }; +static INIT: Once = Once::new(); + type E = MinimalEthSpec; use lighthouse_network::rpc::config::InboundRateLimiterConfig; @@ -71,10 +74,11 @@ impl std::ops::DerefMut for Libp2pInstance { #[allow(unused)] pub fn build_tracing_subscriber(level: &str, enabled: bool) { if enabled { - tracing_subscriber::fmt() - .with_env_filter(EnvFilter::try_new(level).unwrap()) - .try_init() - .unwrap(); + INIT.call_once(|| { + tracing_subscriber::fmt() + .with_env_filter(EnvFilter::try_new(level).unwrap()) + .init(); + }); } } From 3e4381e98ab58d0cdf7272907133bdd515e673e4 Mon Sep 17 00:00:00 2001 From: Tan Chee Keong Date: Mon, 14 Jul 2025 09:20:05 +0800 Subject: [PATCH 5/6] revert --- beacon_node/lighthouse_network/tests/common.rs | 12 ++++-------- 1 file changed, 4 insertions(+), 8 deletions(-) diff --git a/beacon_node/lighthouse_network/tests/common.rs b/beacon_node/lighthouse_network/tests/common.rs index c6d21871d66..0dac126909c 100644 --- a/beacon_node/lighthouse_network/tests/common.rs +++ b/beacon_node/lighthouse_network/tests/common.rs @@ -5,7 +5,6 @@ use lighthouse_network::EnrExt; use lighthouse_network::Multiaddr; use lighthouse_network::{NetworkConfig, NetworkEvent}; use std::sync::Arc; -use std::sync::Once; use std::sync::Weak; use tokio::runtime::Runtime; use tracing::{debug, error, info_span, Instrument}; @@ -15,8 +14,6 @@ use types::{ MinimalEthSpec, Slot, }; -static INIT: Once = Once::new(); - type E = MinimalEthSpec; use lighthouse_network::rpc::config::InboundRateLimiterConfig; @@ -74,11 +71,10 @@ impl std::ops::DerefMut for Libp2pInstance { #[allow(unused)] pub fn build_tracing_subscriber(level: &str, enabled: bool) { if enabled { - INIT.call_once(|| { - tracing_subscriber::fmt() - .with_env_filter(EnvFilter::try_new(level).unwrap()) - .init(); - }); + tracing_subscriber::fmt() + .with_env_filter(EnvFilter::try_new(level).unwrap()) + .try_init() + .unwrap(); } } From 4a3c2686116cb975fdc9ff8b0c8e507a422129ef Mon Sep 17 00:00:00 2001 From: Tan Chee Keong Date: Mon, 14 Jul 2025 09:20:26 +0800 Subject: [PATCH 6/6] simplify --- validator_client/validator_services/src/block_service.rs | 9 ++------- 1 file changed, 2 insertions(+), 7 deletions(-) diff --git a/validator_client/validator_services/src/block_service.rs b/validator_client/validator_services/src/block_service.rs index bbc7c6013f8..4ff8b15bed2 100644 --- a/validator_client/validator_services/src/block_service.rs +++ b/validator_client/validator_services/src/block_service.rs @@ -533,11 +533,7 @@ impl BlockService { ) .await { - Ok((ssz_block_response, _)) => { - info!(slot = slot.as_u64(), "Received unsigned block in SSZ"); - - ssz_block_response - } + Ok((ssz_block_response, _)) => ssz_block_response, Err(e) => { warn!( slot = slot.as_u64(), @@ -560,8 +556,6 @@ impl BlockService { )) })?; - info!(slot = slot.as_u64(), "Received unsigned block in JSON"); - // Extract ProduceBlockV3Response (data field of the struct ForkVersionedResponse) json_block_response.data } @@ -576,6 +570,7 @@ impl BlockService { } }; + info!(slot = slot.as_u64(), "Received unsigned block"); if proposer_index != Some(block_proposer) { return Err(BlockError::Recoverable( "Proposer index does not match block proposer. Beacon chain re-orged".to_string(),