From b74da14261d19558e690afda0e0db5b3c19579dc Mon Sep 17 00:00:00 2001 From: Lion - dapplion <35266934+dapplion@users.noreply.github.com> Date: Tue, 9 Apr 2024 23:25:18 +0900 Subject: [PATCH] Improve block lookup logging (#5535) * Improve block lookup logging --- .../network/src/sync/block_lookups/mod.rs | 16 ++++-- .../src/sync/block_lookups/parent_lookup.rs | 4 +- .../sync/block_lookups/single_block_lookup.rs | 19 +++++-- beacon_node/network/src/sync/manager.rs | 52 ++++++++++++------- 4 files changed, 62 insertions(+), 29 deletions(-) diff --git a/beacon_node/network/src/sync/block_lookups/mod.rs b/beacon_node/network/src/sync/block_lookups/mod.rs index f12491edf71..76efc728fd5 100644 --- a/beacon_node/network/src/sync/block_lookups/mod.rs +++ b/beacon_node/network/src/sync/block_lookups/mod.rs @@ -249,6 +249,9 @@ impl BlockLookups { self.da_checker.clone(), cx, ); + + debug!(self.log, "Created new parent lookup"; "block_root" => ?block_root, "parent_root" => ?parent_root); + self.request_parent(parent_lookup, cx); } @@ -575,7 +578,7 @@ impl BlockLookups { | ParentVerifyError::ExtraBlobsReturned | ParentVerifyError::InvalidIndex(_) => { let e = e.into(); - warn!(self.log, "Peer sent invalid response to parent request."; + warn!(self.log, "Peer sent invalid response to parent request"; "peer_id" => %peer_id, "reason" => %e); // We do not tolerate these kinds of errors. We will accept a few but these are signs @@ -661,7 +664,7 @@ impl BlockLookups { .position(|req| req.check_peer_disconnected(peer_id).is_err()) { let parent_lookup = self.parent_lookups.remove(pos); - trace!(self.log, "Parent lookup's peer disconnected"; &parent_lookup); + debug!(self.log, "Dropping parent lookup after peer disconnected"; &parent_lookup); self.request_parent(parent_lookup, cx); } } @@ -745,14 +748,19 @@ impl BlockLookups { cx: &mut SyncNetworkContext, ) { let Some(mut lookup) = self.single_block_lookups.remove(&target_id) else { + debug!(self.log, "Unknown single block lookup"; "target_id" => target_id); return; }; let root = lookup.block_root(); let request_state = R::request_state_mut(&mut lookup); - let Ok(peer_id) = request_state.get_state().processing_peer() else { - return; + let peer_id = match request_state.get_state().processing_peer() { + Ok(peer_id) => peer_id, + Err(e) => { + debug!(self.log, "Attempting to process single block lookup in bad state"; "id" => target_id, "response_type" => ?R::response_type(), "error" => e); + return; + } }; debug!( self.log, 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 c180e685165..a3cdfd7b00b 100644 --- a/beacon_node/network/src/sync/block_lookups/parent_lookup.rs +++ b/beacon_node/network/src/sync/block_lookups/parent_lookup.rs @@ -127,14 +127,14 @@ impl ParentLookup { .update_requested_parent_block(next_parent) } - pub fn block_processing_peer(&self) -> Result { + pub fn block_processing_peer(&self) -> Result { self.current_parent_request .block_request_state .state .processing_peer() } - pub fn blob_processing_peer(&self) -> Result { + pub fn blob_processing_peer(&self) -> Result { self.current_parent_request .blob_request_state .state 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 f94978a3a78..7f3849c161b 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 @@ -465,11 +465,10 @@ impl SingleLookupRequestState { /// Returns the id peer we downloaded from if we have downloaded a verified block, otherwise /// returns an error. - pub fn processing_peer(&self) -> Result { - if let State::Processing { peer_id } = &self.state { - Ok(*peer_id) - } else { - Err(()) + pub fn processing_peer(&self) -> Result { + match &self.state { + State::Processing { peer_id } => Ok(*peer_id), + other => Err(format!("not in processing state: {}", other).to_string()), } } } @@ -525,6 +524,16 @@ impl slog::Value for SingleLookupRequestState { } } +impl std::fmt::Display for State { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + match self { + State::AwaitingDownload => write!(f, "AwaitingDownload"), + State::Downloading { .. } => write!(f, "Downloading"), + State::Processing { .. } => write!(f, "Processing"), + } + } +} + #[cfg(test)] mod tests { use super::*; diff --git a/beacon_node/network/src/sync/manager.rs b/beacon_node/network/src/sync/manager.rs index dc523d7572e..e95649806bc 100644 --- a/beacon_node/network/src/sync/manager.rs +++ b/beacon_node/network/src/sync/manager.rs @@ -619,6 +619,7 @@ impl SyncManager { SyncMessage::UnknownParentBlock(peer_id, block, block_root) => { let block_slot = block.slot(); let parent_root = block.parent_root(); + debug!(self.log, "Received unknown parent block message"; "block_root" => %block_root, "parent_root" => %parent_root); self.handle_unknown_parent( peer_id, block_root, @@ -638,6 +639,7 @@ impl SyncManager { } let mut blobs = FixedBlobSidecarList::default(); *blobs.index_mut(blob_index as usize) = Some(blob); + debug!(self.log, "Received unknown parent blob message"; "block_root" => %block_root, "parent_root" => %parent_root); self.handle_unknown_parent( peer_id, block_root, @@ -723,24 +725,33 @@ impl SyncManager { slot: Slot, child_components: ChildComponents, ) { - if self.should_search_for_block(slot, &peer_id) { - self.block_lookups.search_parent( - slot, - block_root, - parent_root, - peer_id, - &mut self.network, - ); - self.block_lookups.search_child_block( - block_root, - child_components, - &[peer_id], - &mut self.network, - ); + match self.should_search_for_block(slot, &peer_id) { + Ok(_) => { + self.block_lookups.search_parent( + slot, + block_root, + parent_root, + peer_id, + &mut self.network, + ); + self.block_lookups.search_child_block( + block_root, + child_components, + &[peer_id], + &mut self.network, + ); + } + Err(reason) => { + debug!(self.log, "Ignoring unknown parent request"; "block_root" => %block_root, "parent_root" => %parent_root, "reason" => reason); + } } } - fn should_search_for_block(&mut self, block_slot: Slot, peer_id: &PeerId) -> bool { + fn should_search_for_block( + &mut self, + block_slot: Slot, + peer_id: &PeerId, + ) -> Result<(), &'static str> { if !self.network_globals().sync_state.read().is_synced() { let head_slot = self.chain.canonical_head.cached_head().head_slot(); @@ -751,12 +762,17 @@ impl SyncManager { || (head_slot < block_slot && block_slot.sub(head_slot).as_usize() > SLOT_IMPORT_TOLERANCE) { - return false; + return Err("not synced"); } } - self.network_globals().peers.read().is_connected(peer_id) - && self.network.is_execution_engine_online() + if !self.network_globals().peers.read().is_connected(peer_id) { + return Err("peer not connected"); + } + if !self.network.is_execution_engine_online() { + return Err("execution engine offline"); + } + Ok(()) } fn synced(&mut self) -> bool {