From 21cdc64bfe75572170c61b28ed5a972f36b354ac Mon Sep 17 00:00:00 2001 From: realbigsean Date: Fri, 22 Mar 2024 14:16:13 -0400 Subject: [PATCH] Improve parent lookup logging (#5451) * upgrade parent lookup result processing logs to debug, use display instead of debug for BlockError in case a blob parent unknown error is hit, add block root to BlockIsAlreadyKnown * fix compile * fix compile * fix compile --- beacon_node/beacon_chain/src/beacon_chain.rs | 6 +++--- beacon_node/beacon_chain/src/block_verification.rs | 8 ++++---- beacon_node/beacon_chain/tests/block_verification.rs | 4 ++-- beacon_node/http_api/src/publish_blocks.rs | 4 ++-- .../src/network_beacon_processor/gossip_methods.rs | 2 +- .../src/network_beacon_processor/sync_methods.rs | 4 ++-- beacon_node/network/src/sync/block_lookups/mod.rs | 12 ++++++------ beacon_node/network/src/sync/block_lookups/tests.rs | 12 ++++++++++-- 8 files changed, 30 insertions(+), 22 deletions(-) diff --git a/beacon_node/beacon_chain/src/beacon_chain.rs b/beacon_node/beacon_chain/src/beacon_chain.rs index b94baf0e4a9..534cffae132 100644 --- a/beacon_node/beacon_chain/src/beacon_chain.rs +++ b/beacon_node/beacon_chain/src/beacon_chain.rs @@ -2651,7 +2651,7 @@ impl BeaconChain { // If the block is relevant, add it to the filtered chain segment. Ok(_) => filtered_chain_segment.push((block_root, block)), // If the block is already known, simply ignore this block. - Err(BlockError::BlockIsAlreadyKnown) => continue, + Err(BlockError::BlockIsAlreadyKnown(_)) => continue, // If the block is the genesis block, simply ignore this block. Err(BlockError::GenesisBlock) => continue, // If the block is is for a finalized slot, simply ignore this block. @@ -2879,7 +2879,7 @@ impl BeaconChain { .fork_choice_read_lock() .contains_block(&block_root) { - return Err(BlockError::BlockIsAlreadyKnown); + return Err(BlockError::BlockIsAlreadyKnown(blob.block_root())); } if let Some(event_handler) = self.event_handler.as_ref() { @@ -2911,7 +2911,7 @@ impl BeaconChain { .fork_choice_read_lock() .contains_block(&block_root) { - return Err(BlockError::BlockIsAlreadyKnown); + return Err(BlockError::BlockIsAlreadyKnown(block_root)); } if let Some(event_handler) = self.event_handler.as_ref() { diff --git a/beacon_node/beacon_chain/src/block_verification.rs b/beacon_node/beacon_chain/src/block_verification.rs index ac3d3e3ab80..ecfd04ed00f 100644 --- a/beacon_node/beacon_chain/src/block_verification.rs +++ b/beacon_node/beacon_chain/src/block_verification.rs @@ -190,7 +190,7 @@ pub enum BlockError { /// ## Peer scoring /// /// The block is valid and we have already imported a block with this hash. - BlockIsAlreadyKnown, + BlockIsAlreadyKnown(Hash256), /// The block slot exceeds the MAXIMUM_BLOCK_SLOT_NUMBER. /// /// ## Peer scoring @@ -832,7 +832,7 @@ impl GossipVerifiedBlock { // already know this block. let fork_choice_read_lock = chain.canonical_head.fork_choice_read_lock(); if fork_choice_read_lock.contains_block(&block_root) { - return Err(BlockError::BlockIsAlreadyKnown); + return Err(BlockError::BlockIsAlreadyKnown(block_root)); } // Do not process a block that doesn't descend from the finalized root. @@ -966,7 +966,7 @@ impl GossipVerifiedBlock { SeenBlock::Slashable => { return Err(BlockError::Slashable); } - SeenBlock::Duplicate => return Err(BlockError::BlockIsAlreadyKnown), + SeenBlock::Duplicate => return Err(BlockError::BlockIsAlreadyKnown(block_root)), SeenBlock::UniqueNonSlashable => {} }; @@ -1784,7 +1784,7 @@ pub fn check_block_relevancy( .fork_choice_read_lock() .contains_block(&block_root) { - return Err(BlockError::BlockIsAlreadyKnown); + return Err(BlockError::BlockIsAlreadyKnown(block_root)); } Ok(block_root) diff --git a/beacon_node/beacon_chain/tests/block_verification.rs b/beacon_node/beacon_chain/tests/block_verification.rs index 9b89ee09425..424bf73c0c8 100644 --- a/beacon_node/beacon_chain/tests/block_verification.rs +++ b/beacon_node/beacon_chain/tests/block_verification.rs @@ -1087,7 +1087,7 @@ async fn block_gossip_verification() { assert!( matches!( unwrap_err(harness.chain.verify_block_for_gossip(Arc::new(block.clone())).await), - BlockError::BlockIsAlreadyKnown, + BlockError::BlockIsAlreadyKnown(_), ), "should register any valid signature against the proposer, even if the block failed later verification" ); @@ -1115,7 +1115,7 @@ async fn block_gossip_verification() { .verify_block_for_gossip(block.clone()) .await .expect_err("should error when processing known block"), - BlockError::BlockIsAlreadyKnown + BlockError::BlockIsAlreadyKnown(_) ), "the second proposal by this validator should be rejected" ); diff --git a/beacon_node/http_api/src/publish_blocks.rs b/beacon_node/http_api/src/publish_blocks.rs index 8b85c2ac951..4af2a82a477 100644 --- a/beacon_node/http_api/src/publish_blocks.rs +++ b/beacon_node/http_api/src/publish_blocks.rs @@ -113,7 +113,7 @@ pub async fn publish_block b, - Err(BlockContentsError::BlockError(BlockError::BlockIsAlreadyKnown)) + Err(BlockContentsError::BlockError(BlockError::BlockIsAlreadyKnown(_))) | Err(BlockContentsError::BlobError( beacon_chain::blob_verification::GossipBlobError::RepeatBlob { .. }, )) => { @@ -133,7 +133,7 @@ pub async fn publish_block slot, - "error" => ?e + "error" => %e ); return Err(warp_utils::reject::custom_bad_request(e.to_string())); } diff --git a/beacon_node/network/src/network_beacon_processor/gossip_methods.rs b/beacon_node/network/src/network_beacon_processor/gossip_methods.rs index 07fc06bc370..0fda52244ec 100644 --- a/beacon_node/network/src/network_beacon_processor/gossip_methods.rs +++ b/beacon_node/network/src/network_beacon_processor/gossip_methods.rs @@ -963,7 +963,7 @@ impl NetworkBeaconProcessor { self.propagate_validation_result(message_id, peer_id, MessageAcceptance::Ignore); return None; } - Err(BlockError::BlockIsAlreadyKnown) => { + Err(BlockError::BlockIsAlreadyKnown(_)) => { debug!( self.log, "Gossip block is already known"; diff --git a/beacon_node/network/src/network_beacon_processor/sync_methods.rs b/beacon_node/network/src/network_beacon_processor/sync_methods.rs index 8894d5d9fd9..e7f1491b752 100644 --- a/beacon_node/network/src/network_beacon_processor/sync_methods.rs +++ b/beacon_node/network/src/network_beacon_processor/sync_methods.rs @@ -276,7 +276,7 @@ impl NetworkBeaconProcessor { "slot" => %slot, ); } - Err(BlockError::BlockIsAlreadyKnown) => { + Err(BlockError::BlockIsAlreadyKnown(_)) => { debug!( self.log, "Blobs have already been imported"; @@ -639,7 +639,7 @@ impl NetworkBeaconProcessor { peer_action: Some(PeerAction::LowToleranceError), }) } - BlockError::BlockIsAlreadyKnown => { + BlockError::BlockIsAlreadyKnown(_) => { // This can happen for many reasons. Head sync's can download multiples and parent // lookups can download blocks before range sync Ok(()) diff --git a/beacon_node/network/src/sync/block_lookups/mod.rs b/beacon_node/network/src/sync/block_lookups/mod.rs index 2327abc61b0..794204acee2 100644 --- a/beacon_node/network/src/sync/block_lookups/mod.rs +++ b/beacon_node/network/src/sync/block_lookups/mod.rs @@ -811,7 +811,7 @@ impl BlockLookups { let root = lookup.block_root(); trace!(self.log, "Single block processing failed"; "block" => %root, "error" => %e); match e { - BlockError::BlockIsAlreadyKnown => { + BlockError::BlockIsAlreadyKnown(_) => { // No error here return Ok(None); } @@ -898,17 +898,17 @@ impl BlockLookups { match &result { BlockProcessingResult::Ok(status) => match status { AvailabilityProcessingStatus::Imported(block_root) => { - trace!(self.log, "Parent block processing succeeded"; &parent_lookup, "block_root" => ?block_root) + debug!(self.log, "Parent block processing succeeded"; &parent_lookup, "block_root" => ?block_root) } AvailabilityProcessingStatus::MissingComponents(_, block_root) => { - trace!(self.log, "Parent missing parts, triggering single block lookup "; &parent_lookup,"block_root" => ?block_root) + debug!(self.log, "Parent missing parts, triggering single block lookup "; &parent_lookup,"block_root" => ?block_root) } }, BlockProcessingResult::Err(e) => { - trace!(self.log, "Parent block processing failed"; &parent_lookup, "error" => %e) + debug!(self.log, "Parent block processing failed"; &parent_lookup, "error" => %e) } BlockProcessingResult::Ignored => { - trace!( + debug!( self.log, "Parent block processing job was ignored"; "action" => "re-requesting block", @@ -954,7 +954,7 @@ impl BlockLookups { self.request_parent(parent_lookup, cx); } BlockProcessingResult::Ok(AvailabilityProcessingStatus::Imported(_)) - | BlockProcessingResult::Err(BlockError::BlockIsAlreadyKnown { .. }) => { + | BlockProcessingResult::Err(BlockError::BlockIsAlreadyKnown(_)) => { // Check if the beacon processor is available let Some(beacon_processor) = cx.beacon_processor_if_enabled() else { return trace!( diff --git a/beacon_node/network/src/sync/block_lookups/tests.rs b/beacon_node/network/src/sync/block_lookups/tests.rs index d638ae8a85a..b364d9a05f7 100644 --- a/beacon_node/network/src/sync/block_lookups/tests.rs +++ b/beacon_node/network/src/sync/block_lookups/tests.rs @@ -458,7 +458,11 @@ fn test_parent_lookup_happy_path() { rig.expect_empty_network(); // Processing succeeds, now the rest of the chain should be sent for processing. - bl.parent_block_processed(chain_hash, BlockError::BlockIsAlreadyKnown.into(), &mut cx); + bl.parent_block_processed( + chain_hash, + BlockError::BlockIsAlreadyKnown(block_root).into(), + &mut cx, + ); rig.expect_parent_chain_process(); let process_result = BatchProcessResult::Success { was_non_empty: true, @@ -1117,7 +1121,11 @@ fn test_same_chain_race_condition() { // the processing result if i + 2 == depth { // one block was removed - bl.parent_block_processed(chain_hash, BlockError::BlockIsAlreadyKnown.into(), &mut cx) + bl.parent_block_processed( + chain_hash, + BlockError::BlockIsAlreadyKnown(block.canonical_root()).into(), + &mut cx, + ) } else { bl.parent_block_processed( chain_hash,