From 334aa2eabd3553d0d966e16e16f13b01e57b25af Mon Sep 17 00:00:00 2001 From: realbigsean Date: Wed, 27 Mar 2024 06:01:27 -0400 Subject: [PATCH] Single lookup improvements (#5488) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * Fix unexpected `UnrequestedBlobId` and `ExtraBlocksReturned` errors due to race conditions. * Continue chain segment processing and skip any blocks that are already known, rather than returning an error. * more de-dup checking * ensure we don't reset `requested_ids` during rpc download * better fix * Merge branch 'unstable' of https://github.com/sigp/lighthouse into more-dup-lookup-fixes * remove chain hash check * Merge branch 'fix-block-lookup-race' of https://github.com/jimmygchen/lighthouse into sean-test-lookups * remove block check * add back tests * Log and CI fixes * undue extra check * Merge branch 'sean-test-lookups' of https://github.com/realbigsean/lighthouse into sean-test-lookups * log improvements * Improve logging --- beacon_node/beacon_chain/src/beacon_chain.rs | 10 ++++-- .../src/block_verification_types.rs | 9 ++++- .../src/data_availability_checker.rs | 2 -- .../network_beacon_processor/sync_methods.rs | 8 ++++- .../network/src/sync/block_lookups/common.rs | 2 +- .../network/src/sync/block_lookups/mod.rs | 36 ++++++++++++++++--- .../src/sync/block_lookups/parent_lookup.rs | 5 +-- .../sync/block_lookups/single_block_lookup.rs | 8 +++-- .../network/src/sync/block_lookups/tests.rs | 1 + 9 files changed, 64 insertions(+), 17 deletions(-) diff --git a/beacon_node/beacon_chain/src/beacon_chain.rs b/beacon_node/beacon_chain/src/beacon_chain.rs index 39089c0b0d3..deeda491dca 100644 --- a/beacon_node/beacon_chain/src/beacon_chain.rs +++ b/beacon_node/beacon_chain/src/beacon_chain.rs @@ -2796,6 +2796,12 @@ impl BeaconChain { } } } + Err(BlockError::BlockIsAlreadyKnown(block_root)) => { + debug!(self.log, + "Ignoring already known blocks while processing chain segment"; + "block_root" => ?block_root); + continue; + } Err(error) => { return ChainSegmentResult::Failed { imported_blocks, @@ -3032,7 +3038,7 @@ impl BeaconChain { match import_block.await { // The block was successfully verified and imported. Yay. Ok(status @ AvailabilityProcessingStatus::Imported(block_root)) => { - trace!( + debug!( self.log, "Beacon block imported"; "block_root" => ?block_root, @@ -3045,7 +3051,7 @@ impl BeaconChain { Ok(status) } Ok(status @ AvailabilityProcessingStatus::MissingComponents(slot, block_root)) => { - trace!( + debug!( self.log, "Beacon block awaiting blobs"; "block_root" => ?block_root, diff --git a/beacon_node/beacon_chain/src/block_verification_types.rs b/beacon_node/beacon_chain/src/block_verification_types.rs index edba7a211cb..d35c402971a 100644 --- a/beacon_node/beacon_chain/src/block_verification_types.rs +++ b/beacon_node/beacon_chain/src/block_verification_types.rs @@ -7,6 +7,7 @@ use crate::{get_block_root, GossipVerifiedBlock, PayloadVerificationOutcome}; use derivative::Derivative; use ssz_types::VariableList; use state_processing::ConsensusContext; +use std::fmt::{Debug, Formatter}; use std::sync::Arc; use types::blob_sidecar::{BlobIdentifier, BlobSidecarError, FixedBlobSidecarList}; use types::{ @@ -27,13 +28,19 @@ use types::{ /// Note: We make a distinction over blocks received over gossip because /// in a post-deneb world, the blobs corresponding to a given block that are received /// over rpc do not contain the proposer signature for dos resistance. -#[derive(Debug, Clone, Derivative)] +#[derive(Clone, Derivative)] #[derivative(Hash(bound = "E: EthSpec"))] pub struct RpcBlock { block_root: Hash256, block: RpcBlockInner, } +impl Debug for RpcBlock { + fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result { + write!(f, "RpcBlock({:?})", self.block_root) + } +} + impl RpcBlock { pub fn block_root(&self) -> Hash256 { self.block_root diff --git a/beacon_node/beacon_chain/src/data_availability_checker.rs b/beacon_node/beacon_chain/src/data_availability_checker.rs index a578c484ed2..7d8af48c782 100644 --- a/beacon_node/beacon_chain/src/data_availability_checker.rs +++ b/beacon_node/beacon_chain/src/data_availability_checker.rs @@ -110,8 +110,6 @@ impl DataAvailabilityChecker { self.processing_cache.read().get(&block_root).cloned() } - /// A `None` indicates blobs are not required. - /// /// If there's no block, all possible ids will be returned that don't exist in the given blobs. /// If there no blobs, all possible ids will be returned. pub fn get_missing_blob_ids>( 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 35b65540e32..887974c6e0b 100644 --- a/beacon_node/network/src/network_beacon_processor/sync_methods.rs +++ b/beacon_node/network/src/network_beacon_processor/sync_methods.rs @@ -117,6 +117,7 @@ impl NetworkBeaconProcessor { "Gossip block is being processed"; "action" => "sending rpc block to reprocessing queue", "block_root" => %block_root, + "process_type" => ?process_type, ); // Send message to work reprocess queue to retry the block @@ -149,6 +150,7 @@ impl NetworkBeaconProcessor { "proposer" => block.message().proposer_index(), "slot" => block.slot(), "commitments" => commitments_formatted, + "process_type" => ?process_type, ); let result = self @@ -418,7 +420,11 @@ impl NetworkBeaconProcessor { } } (imported_blocks, Ok(_)) => { - debug!(self.log, "Parent lookup processed successfully"); + debug!( + self.log, "Parent lookup processed successfully"; + "chain_hash" => %chain_head, + "imported_blocks" => imported_blocks + ); BatchProcessResult::Success { was_non_empty: imported_blocks > 0, } diff --git a/beacon_node/network/src/sync/block_lookups/common.rs b/beacon_node/network/src/sync/block_lookups/common.rs index d989fbb3362..cad187ad7fb 100644 --- a/beacon_node/network/src/sync/block_lookups/common.rs +++ b/beacon_node/network/src/sync/block_lookups/common.rs @@ -380,7 +380,7 @@ impl RequestState for BlobRequestState BlockLookups { if let Some(components) = child_components { lookup.add_child_components(components); } + debug!(self.log, "Already searching for block"; "block_root" => ?block_root); return; } @@ -162,6 +163,7 @@ impl BlockLookups { // If the block was already downloaded, or is being downloaded in this moment, do not // request it. + debug!(self.log, "Already searching for block in a parent lookup request"; "block_root" => ?block_root); return; } @@ -171,6 +173,7 @@ impl BlockLookups { .any(|(hashes, _last_parent_request)| hashes.contains(&block_root)) { // we are already processing this block, ignore it. + debug!(self.log, "Already processing block in a parent request"; "block_root" => ?block_root); return; } @@ -221,15 +224,23 @@ impl BlockLookups { }) { parent_lookup.add_peer(peer_id); // we are already searching for this block, ignore it + debug!(self.log, "Already searching for parent block"; + "block_root" => ?block_root, "parent_root" => ?parent_root); return; } if self .processing_parent_lookups - .values() - .any(|(hashes, _peers)| hashes.contains(&block_root) || hashes.contains(&parent_root)) + .iter() + .any(|(chain_hash, (hashes, _peers))| { + chain_hash == &block_root + || hashes.contains(&block_root) + || hashes.contains(&parent_root) + }) { // we are already processing this block, ignore it. + debug!(self.log, "Already processing parent block"; + "block_root" => ?block_root, "parent_root" => ?parent_root); return; } let parent_lookup = ParentLookup::new( @@ -298,6 +309,12 @@ impl BlockLookups { }; let expected_block_root = lookup.block_root(); + debug!(self.log, + "Peer returned block for single lookup"; + "peer_id" => %peer_id , + "id" => ?id, + "block_root" => ?expected_block_root, + ); match self.single_lookup_response_inner::(peer_id, response, seen_timestamp, cx, lookup) { @@ -478,6 +495,13 @@ impl BlockLookups { return; }; + debug!(self.log, + "Peer returned block for parent lookup"; + "peer_id" => %peer_id , + "id" => ?id, + "block_root" => ?parent_lookup.current_parent_request.block_request_state.requested_block_root, + ); + match self.parent_lookup_response_inner::( peer_id, response, @@ -540,7 +564,7 @@ impl BlockLookups { | ParentVerifyError::NoBlockReturned | ParentVerifyError::NotEnoughBlobsReturned | ParentVerifyError::ExtraBlocksReturned - | ParentVerifyError::UnrequestedBlobId + | ParentVerifyError::UnrequestedBlobId(_) | ParentVerifyError::ExtraBlobsReturned | ParentVerifyError::InvalidIndex(_) => { let e = e.into(); @@ -728,6 +752,8 @@ impl BlockLookups { "Block component processed for lookup"; "response_type" => ?R::response_type(), "block_root" => ?root, + "result" => ?result, + "id" => target_id, ); match result { @@ -901,7 +927,7 @@ impl BlockLookups { debug!(self.log, "Parent block processing succeeded"; &parent_lookup, "block_root" => ?block_root) } AvailabilityProcessingStatus::MissingComponents(_, block_root) => { - debug!(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) => { @@ -1223,7 +1249,7 @@ impl BlockLookups { ) -> Result<(), LookupRequestError> { match cx.beacon_processor_if_enabled() { Some(beacon_processor) => { - trace!(self.log, "Sending block for processing"; "block" => ?block_root, "process" => ?process_type); + debug!(self.log, "Sending block for processing"; "block" => ?block_root, "process" => ?process_type); if let Err(e) = beacon_processor.send_rpc_beacon_block( block_root, block, diff --git a/beacon_node/network/src/sync/block_lookups/parent_lookup.rs b/beacon_node/network/src/sync/block_lookups/parent_lookup.rs index 5c2e90b48c9..1901925cf20 100644 --- a/beacon_node/network/src/sync/block_lookups/parent_lookup.rs +++ b/beacon_node/network/src/sync/block_lookups/parent_lookup.rs @@ -12,6 +12,7 @@ use std::collections::VecDeque; use std::sync::Arc; use store::Hash256; use strum::IntoStaticStr; +use types::blob_sidecar::BlobIdentifier; /// How many attempts we try to find a parent of a block before we give up trying. pub(crate) const PARENT_FAIL_TOLERANCE: u8 = 5; @@ -36,7 +37,7 @@ pub enum ParentVerifyError { NoBlockReturned, NotEnoughBlobsReturned, ExtraBlocksReturned, - UnrequestedBlobId, + UnrequestedBlobId(BlobIdentifier), ExtraBlobsReturned, InvalidIndex(u64), PreviousFailure { parent_root: Hash256 }, @@ -242,7 +243,7 @@ impl From for ParentVerifyError { E::RootMismatch => ParentVerifyError::RootMismatch, E::NoBlockReturned => ParentVerifyError::NoBlockReturned, E::ExtraBlocksReturned => ParentVerifyError::ExtraBlocksReturned, - E::UnrequestedBlobId => ParentVerifyError::UnrequestedBlobId, + E::UnrequestedBlobId(blob_id) => ParentVerifyError::UnrequestedBlobId(blob_id), E::ExtraBlobsReturned => ParentVerifyError::ExtraBlobsReturned, E::InvalidIndex(index) => ParentVerifyError::InvalidIndex(index), E::NotEnoughBlobsReturned => ParentVerifyError::NotEnoughBlobsReturned, diff --git a/beacon_node/network/src/sync/block_lookups/single_block_lookup.rs b/beacon_node/network/src/sync/block_lookups/single_block_lookup.rs index c4d91299345..d393c6a8f76 100644 --- a/beacon_node/network/src/sync/block_lookups/single_block_lookup.rs +++ b/beacon_node/network/src/sync/block_lookups/single_block_lookup.rs @@ -16,7 +16,7 @@ use std::marker::PhantomData; use std::sync::Arc; use store::Hash256; use strum::IntoStaticStr; -use types::blob_sidecar::FixedBlobSidecarList; +use types::blob_sidecar::{BlobIdentifier, FixedBlobSidecarList}; use types::EthSpec; #[derive(Debug, PartialEq, Eq)] @@ -31,7 +31,7 @@ pub enum LookupVerifyError { RootMismatch, NoBlockReturned, ExtraBlocksReturned, - UnrequestedBlobId, + UnrequestedBlobId(BlobIdentifier), ExtraBlobsReturned, NotEnoughBlobsReturned, InvalidIndex(u64), @@ -257,7 +257,9 @@ impl SingleBlockLookup { /// of which blobs still need to be requested. Returns `true` if there are no more blobs to /// request. pub(crate) fn blobs_already_downloaded(&mut self) -> bool { - self.update_blobs_request(); + if matches!(self.blob_request_state.state.state, State::AwaitingDownload) { + self.update_blobs_request(); + } self.blob_request_state.requested_ids.is_empty() } diff --git a/beacon_node/network/src/sync/block_lookups/tests.rs b/beacon_node/network/src/sync/block_lookups/tests.rs index b364d9a05f7..414b4886fd7 100644 --- a/beacon_node/network/src/sync/block_lookups/tests.rs +++ b/beacon_node/network/src/sync/block_lookups/tests.rs @@ -1803,6 +1803,7 @@ mod deneb_only { .expect_blobs_request() .expect_no_block_request(); } + #[test] fn too_few_blobs_response_then_block_response_attestation() { let Some(tester) = DenebTester::new(RequestTrigger::AttestationUnknownBlock) else {