fix(l1): reduce spammy trace-level logs during snap-sync (#5492)

**Motivation**

Running ethrex with trace-level logs results in a lot of spam of "We
didn't get a peer from the table" or similar, due to busy loops we have
when we don't have many peers. This is especially important for the
first few stages, since we start with a small number of peers.

**Description**

This PR reduces the spam by adding a sleep of 10ms, plus a counter to
make the warning be printed only once every 1000 times (effectively once
every 10s). Also does the same in other stages of snap-sync, adding logs
in other busy loops to detect if/when we land in those cases instead of
silently ignoring them.

Author: MegaRedHand

crates/common/trie/trie_sorted.rs

@@ -6,7 +6,6 @@ use crossbeam::channel::{Receiver, Sender, bounded};
 use ethereum_types::H256;
 use ethrex_threadpool::ThreadPool;
 use std::{sync::Arc, thread::scope};
-use tracing::debug;
 
 /// The elements of the stack represent the branch node that is the parent of the current
 /// parent element. When the current parent is no longer valid (is not the parent of
@@ -139,16 +138,6 @@ fn add_current_to_parent_and_write_queue(
     };
     parent_element.element.choices[index as usize] =
         node.compute_hash_no_alloc(&mut nodehash_buffer).into();
-    debug!(
-        "branch {:x?}",
-        parent_element
-            .element
-            .choices
-            .iter()
-            .enumerate()
-            .filter_map(|(index, child)| child.is_valid().then_some(index))
-            .collect::<Vec<_>>()
-    );
     nodes_to_write.push((target_path, node));
     Ok(())
 }

crates/networking/p2p/peer_handler.rs

@@ -281,6 +281,8 @@ impl PeerHandler {
 
         *METRICS.headers_download_start_time.lock().await = Some(SystemTime::now());
 
+        let mut logged_no_free_peers_count = 0;
+
         loop {
             if let Ok((headers, peer_id, _connection, startblock, previous_chunk_limit)) =
                 task_receiver.try_recv()
@@ -337,7 +339,14 @@ impl PeerHandler {
                 .get_best_peer(&SUPPORTED_ETH_CAPABILITIES)
                 .await?
             else {
-                trace!("We didn't get a peer from the table");
+                // Log ~ once every 10 seconds
+                if logged_no_free_peers_count == 0 {
+                    trace!("We are missing peers in request_block_headers");
+                    logged_no_free_peers_count = 1000;
+                }
+                logged_no_free_peers_count -= 1;
+                // Sleep a bit to avoid busy polling
+                tokio::time::sleep(Duration::from_millis(10)).await;
                 continue;
             };
 
@@ -656,6 +665,8 @@ impl PeerHandler {
         let mut last_update: SystemTime = SystemTime::now();
         let mut write_set = tokio::task::JoinSet::new();
 
+        let mut logged_no_free_peers_count = 0;
+
         loop {
             if all_accounts_state.len() * size_of::<AccountState>() >= RANGE_FILE_CHUNK_SIZE {
                 let current_account_hashes = std::mem::take(&mut all_account_hashes);
@@ -736,7 +747,14 @@ impl PeerHandler {
                 .inspect_err(|err| error!(err= ?err, "Error requesting a peer for account range"))
                 .unwrap_or(None)
             else {
-                trace!("We are missing peers in request_account_range_request");
+                // Log ~ once every 10 seconds
+                if logged_no_free_peers_count == 0 {
+                    trace!("We are missing peers in request_account_range");
+                    logged_no_free_peers_count = 1000;
+                }
+                logged_no_free_peers_count -= 1;
+                // Sleep a bit to avoid busy polling
+                tokio::time::sleep(Duration::from_millis(10)).await;
                 continue;
             };
 
@@ -974,6 +992,8 @@ impl PeerHandler {
 
         let mut completed_tasks = 0;
 
+        let mut logged_no_free_peers_count = 0;
+
         loop {
             if let Ok(result) = task_receiver.try_recv() {
                 let TaskResult {
@@ -1012,6 +1032,14 @@ impl PeerHandler {
                 .get_best_peer(&SUPPORTED_ETH_CAPABILITIES)
                 .await?
             else {
+                // Log ~ once every 10 seconds
+                if logged_no_free_peers_count == 0 {
+                    trace!("We are missing peers in request_bytecodes");
+                    logged_no_free_peers_count = 1000;
+                }
+                logged_no_free_peers_count -= 1;
+                // Sleep a bit to avoid busy polling
+                tokio::time::sleep(Duration::from_millis(10)).await;
                 continue;
             };
 
@@ -1181,6 +1209,8 @@ impl PeerHandler {
         // vector of hashed storage keys and storage values.
         let mut current_account_storages: BTreeMap<H256, AccountsWithStorage> = BTreeMap::new();
 
+        let mut logged_no_free_peers_count = 0;
+
         debug!("Starting request_storage_ranges loop");
         loop {
             if current_account_storages
@@ -1526,6 +1556,14 @@ impl PeerHandler {
                 .get_best_peer(&SUPPORTED_ETH_CAPABILITIES)
                 .await?
             else {
+                // Log ~ once every 10 seconds
+                if logged_no_free_peers_count == 0 {
+                    trace!("We are missing peers in request_storage_ranges");
+                    logged_no_free_peers_count = 1000;
+                }
+                logged_no_free_peers_count -= 1;
+                // Sleep a bit to avoid busy polling
+                tokio::time::sleep(Duration::from_millis(10)).await;
                 continue;
             };
 

crates/networking/p2p/rlpx/connection/server.rs

@@ -325,7 +325,7 @@ impl GenServer for PeerConnectionServer {
                     trace!(
                         peer=%established_state.node,
                         %message,
-                        "Received incomming message",
+                        "Received incoming message",
                     );
                     handle_incoming_message(established_state, message).await
                 }

crates/networking/p2p/sync/state_healing.rs

@@ -19,7 +19,7 @@ use ethrex_common::{H256, constants::EMPTY_KECCACK_HASH, types::AccountState};
 use ethrex_rlp::{decode::RLPDecode, encode::RLPEncode};
 use ethrex_storage::Store;
 use ethrex_trie::{EMPTY_TRIE_HASH, Nibbles, Node, TrieDB, TrieError};
-use tracing::debug;
+use tracing::{debug, trace};
 
 use crate::{
     metrics::{CurrentStepValue, METRICS},
@@ -119,6 +119,9 @@ async fn heal_state_trie(
     )>(1000);
     // Contains both nodes and their corresponding paths to heal
     let mut nodes_to_heal = Vec::new();
+
+    let mut logged_no_free_peers_count = 0;
+
     loop {
         if last_update.elapsed() >= SHOW_PROGRESS_INTERVAL_DURATION {
             let num_peers = peers
@@ -232,6 +235,16 @@ async fn heal_state_trie(
                 else {
                     // If there are no peers available, re-add the batch to the paths vector, and continue
                     paths.extend(batch);
+
+                    // Log ~ once every 10 seconds
+                    if logged_no_free_peers_count == 0 {
+                        trace!("We are missing peers in heal_state_trie");
+                        logged_no_free_peers_count = 1000;
+                    }
+                    logged_no_free_peers_count -= 1;
+
+                    // Sleep a bit to avoid busy polling
+                    tokio::time::sleep(Duration::from_millis(10)).await;
                     continue;
                 };
 

crates/networking/p2p/sync/storage_healing.rs

@@ -164,6 +164,8 @@ pub async fn heal_storage_trie(
     let (task_sender, mut task_receiver) =
         tokio::sync::mpsc::channel::<Result<TrieNodes, RequestStorageTrieNodes>>(1000);
 
+    let mut logged_no_free_peers_count = 0;
+
     loop {
         yield_now().await;
         if state.last_update.elapsed() >= SHOW_PROGRESS_INTERVAL_DURATION {
@@ -247,6 +249,7 @@ pub async fn heal_storage_trie(
             peers,
             state.state_root,
             &task_sender,
+            &mut logged_no_free_peers_count,
         )
         .await;
 
@@ -317,20 +320,24 @@ async fn ask_peers_for_nodes(
     peers: &mut PeerHandler,
     state_root: H256,
     task_sender: &Sender<Result<TrieNodes, RequestStorageTrieNodes>>,
+    logged_no_free_peers_count: &mut u32,
 ) {
     if (requests.len() as u32) < MAX_IN_FLIGHT_REQUESTS && !download_queue.is_empty() {
         let Some((peer_id, connection)) = peers
             .peer_table
             .get_best_peer(&SUPPORTED_SNAP_CAPABILITIES)
             .await
-            .inspect_err(
-                |err| debug!(err= ?err, "Error requesting a peer to perform storage healing"),
-            )
+            .inspect_err(|err| debug!(?err, "Error requesting a peer to perform storage healing"))
             .unwrap_or(None)
         else {
-            // warn!("We have no free peers for storage healing!"); way too spammy, moving to trace
-            // If we have no peers we shrug our shoulders and wait until next free peer
-            trace!("We have no free peers for storage healing!");
+            // Log ~ once every 10 seconds
+            if *logged_no_free_peers_count == 0 {
+                trace!("We are missing peers in heal_storage_trie");
+                *logged_no_free_peers_count = 1000;
+            }
+            *logged_no_free_peers_count -= 1;
+            // Sleep for a bit to avoid busy polling
+            tokio::time::sleep(tokio::time::Duration::from_millis(10)).await;
             return;
         };
         let at = download_queue.len().saturating_sub(STORAGE_BATCH_SIZE);