Improve block lookup logging (#5535)

* Improve block lookup logging

beacon_node/network/src/sync/block_lookups/mod.rs

@@ -249,6 +249,9 @@ impl<T: BeaconChainTypes> BlockLookups<T> {
             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<T: BeaconChainTypes> BlockLookups<T> {
             | 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<T: BeaconChainTypes> BlockLookups<T> {
             .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<T: BeaconChainTypes> BlockLookups<T> {
         cx: &mut SyncNetworkContext<T>,
     ) {
         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,

beacon_node/network/src/sync/block_lookups/parent_lookup.rs

@@ -127,14 +127,14 @@ impl<T: BeaconChainTypes> ParentLookup<T> {
             .update_requested_parent_block(next_parent)
     }
 
-    pub fn block_processing_peer(&self) -> Result<PeerId, ()> {
+    pub fn block_processing_peer(&self) -> Result<PeerId, String> {
         self.current_parent_request
             .block_request_state
             .state
             .processing_peer()
     }
 
-    pub fn blob_processing_peer(&self) -> Result<PeerId, ()> {
+    pub fn blob_processing_peer(&self) -> Result<PeerId, String> {
         self.current_parent_request
             .blob_request_state
             .state

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<PeerId, ()> {
-        if let State::Processing { peer_id } = &self.state {
-            Ok(*peer_id)
-        } else {
-            Err(())
+    pub fn processing_peer(&self) -> Result<PeerId, String> {
+        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::*;

beacon_node/network/src/sync/manager.rs

@@ -619,6 +619,7 @@ impl<T: BeaconChainTypes> SyncManager<T> {
             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<T: BeaconChainTypes> SyncManager<T> {
                 }
                 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<T: BeaconChainTypes> SyncManager<T> {
         slot: Slot,
         child_components: ChildComponents<T::EthSpec>,
     ) {
-        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<T: BeaconChainTypes> SyncManager<T> {
                 || (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 {