test: trace beacon e2e convergence stalls

Author: perfogic

bin/ream/src/main.rs

@@ -1490,30 +1490,53 @@ mod tests {
         peer_count_value(peer_count, "connected")
     }
 
-    fn peer_count_total(peer_count: &serde_json::Value) -> u64 {
-        peer_count_value(peer_count, "connected")
-            + peer_count_value(peer_count, "connecting")
-            + peer_count_value(peer_count, "disconnected")
-            + peer_count_value(peer_count, "disconnecting")
+    fn peer_count_debug_row(
+        http_port: u16,
+        peer_count: &serde_json::Value,
+    ) -> (u16, u64, u64, u64, u64) {
+        (
+            http_port,
+            peer_count_connected(peer_count),
+            peer_count_value(peer_count, "connecting"),
+            peer_count_value(peer_count, "disconnected"),
+            peer_count_value(peer_count, "disconnecting"),
+        )
     }
 
     async fn wait_for_connected_beacon_peer(
         http_ports: &[u16],
     ) -> Result<Vec<serde_json::Value>, Vec<serde_json::Value>> {
         let start = Instant::now();
         let timeout_duration = Duration::from_secs(60);
+        let required_ready_polls = 3;
+        let mut ready_polls = 0;
         loop {
             let mut peer_counts = Vec::new();
             for http_port in http_ports {
                 peer_counts.push(wait_for_beacon_json(*http_port, "/eth/v1/node/peer_count").await);
             }
 
-            let every_node_knows_a_peer =
-                peer_counts.iter().all(|count| peer_count_total(count) > 0);
-            let any_node_connected = peer_counts
+            let every_node_connected = peer_counts
+                .iter()
+                .all(|count| peer_count_connected(count) > 0);
+            let peer_count_summary = http_ports
                 .iter()
-                .any(|count| peer_count_connected(count) > 0);
-            if every_node_knows_a_peer && any_node_connected {
+                .copied()
+                .zip(peer_counts.iter())
+                .map(|(http_port, count)| peer_count_debug_row(http_port, count))
+                .collect::<Vec<_>>();
+            info!(
+                ready_polls,
+                required_ready_polls,
+                ?peer_count_summary,
+                "beacon e2e peer readiness poll"
+            );
+            if every_node_connected {
+                ready_polls += 1;
+            } else {
+                ready_polls = 0;
+            }
+            if ready_polls >= required_ready_polls {
                 return Ok(peer_counts);
             }
 
@@ -2318,7 +2341,7 @@ mod tests {
         assert!(
             peer_counts
                 .iter()
-                .any(|count| peer_count_connected(count) > 0),
+                .all(|count| peer_count_connected(count) > 0),
             "beacon nodes did not report a connected peer: {peer_counts:?}"
         );
     }
@@ -2565,7 +2588,7 @@ mod tests {
         assert!(
             peer_counts
                 .iter()
-                .any(|count| peer_count_connected(count) > 0),
+                .all(|count| peer_count_connected(count) > 0),
             "beacon nodes did not report a connected peer: {peer_counts:?}"
         );
         info!(

crates/networking/manager/src/gossipsub/validate/beacon_block.rs

@@ -160,10 +160,19 @@ pub async fn validate_beacon_block(
             }
         }
         None => {
+            let local_highest_slot = store
+                .db
+                .slot_index_provider()
+                .get_highest_slot()?
+                .unwrap_or_default();
             // [IGNORE] The block's parent (defined by block.parent_root) has been seen.
-            return Ok(ValidationResult::Ignore(
-                "Parent block not found".to_string(),
-            ));
+            return Ok(ValidationResult::Ignore(format!(
+                "Parent block not found: slot={}, root={}, parent_root={}, local_highest_slot={}",
+                block.message.slot,
+                block.message.block_root(),
+                block.message.parent_root,
+                local_highest_slot
+            )));
         }
     }
 

crates/networking/syncer/src/block_range/block_cache.rs

@@ -145,6 +145,14 @@ impl BlockCache {
         MAX_BLOCKS_PER_REQUEST
     }
 
+    pub fn initial_slot(&self) -> u64 {
+        self.initial_slot
+    }
+
+    pub fn next_start_slot(&self) -> u64 {
+        self.next_start_slot
+    }
+
     pub fn push_retry_range(&mut self, range: Range) {
         self.block_ranges_to_retry.push(range);
     }

crates/networking/syncer/src/block_range/mod.rs

@@ -120,10 +120,14 @@ impl BlockRangeSyncer {
 
                 let data_to_fetch = block_cache.data_to_fetch(finalized_slot);
                 info!(
-                    "Forward sync status: Downloaded Blocks {}, Downloaded Blobs {}/{}, Stage {data_to_fetch}",
+                    "Forward sync status: Downloaded Blocks {}, Downloaded Blobs {}/{}, Finalized Slot {}, Initial Slot {}, Next Start Slot {}, Stage {data_to_fetch}, {}",
                     block_cache.block_count(),
                     block_cache.downloaded_blob_count(),
                     block_cache.blob_count(),
+                    finalized_slot,
+                    block_cache.initial_slot(),
+                    block_cache.next_start_slot(),
+                    self.peer_manager.peer_counts(),
                 );
 
                 match data_to_fetch {

crates/networking/syncer/src/block_range/peer_manager.rs

@@ -95,10 +95,20 @@ impl PeerManager {
             .filter(|peer_info| matches!(peer_info.peer_status, PeerStatus::Idle))
             .count();
         let downloading_peers = total_peers - idle_peers;
+        let mut finalized_epochs = HashMap::new();
+        for peer in self.peers.values() {
+            let finalized_epoch = peer
+                .peer
+                .status
+                .as_ref()
+                .map(|status| status.finalized_epoch);
+            *finalized_epochs.entry(finalized_epoch).or_insert(0) += 1;
+        }
 
         format!(
-            "Total Peers: {total_peers}, Idle: {idle_peers}, Downloading: {downloading_peers}, Banned: {}",
-            self.banned_peers.len()
+            "Total Peers: {total_peers}, Idle: {idle_peers}, Downloading: {downloading_peers}, Banned: {}, Finalized Epochs: {:?}",
+            self.banned_peers.len(),
+            finalized_epochs
         )
     }