From 169223d7def782fe33a7dfe46afb6e59bc29d7d3 Mon Sep 17 00:00:00 2001 From: Francisco Xavier Gauna Date: Fri, 31 Oct 2025 12:37:50 -0300 Subject: [PATCH 1/6] Update tx_broadcaster.rs --- crates/networking/p2p/tx_broadcaster.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/crates/networking/p2p/tx_broadcaster.rs b/crates/networking/p2p/tx_broadcaster.rs index bafbb9626d..9da493ed04 100644 --- a/crates/networking/p2p/tx_broadcaster.rs +++ b/crates/networking/p2p/tx_broadcaster.rs @@ -229,7 +229,7 @@ impl TxBroadcaster { transactions: txs_to_send, }); connection.outgoing_message(txs_message).await.unwrap_or_else(|err| { - error!(peer_id = %format!("{:#x}", peer_id), err = ?err, "Failed to send transactions"); + debug!(peer_id = %format!("{:#x}", peer_id), err = ?err, "Failed to send transactions"); }); self.send_tx_hashes(blob_txs.clone(), capabilities, &mut connection, peer_id) .await?; @@ -301,7 +301,7 @@ pub async fn send_tx_hashes( NewPooledTransactionHashes::new(txs_to_send, blockchain)?, ); connection.outgoing_message(hashes_message.clone()).await.unwrap_or_else(|err| { - error!(peer_id = %format!("{:#x}", peer_id), err = ?err, "Failed to send transactions hashes"); + debug!(peer_id = %format!("{:#x}", peer_id), err = ?err, "Failed to send transactions hashes"); }); } } From 55294161665f7ddbfff20914e10427429ddc7198 Mon Sep 17 00:00:00 2001 From: Francisco Xavier Gauna Date: Fri, 31 Oct 2025 12:38:54 -0300 Subject: [PATCH 2/6] Update tx_broadcaster.rs --- crates/networking/p2p/tx_broadcaster.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/crates/networking/p2p/tx_broadcaster.rs b/crates/networking/p2p/tx_broadcaster.rs index 9da493ed04..95d80fc113 100644 --- a/crates/networking/p2p/tx_broadcaster.rs +++ b/crates/networking/p2p/tx_broadcaster.rs @@ -324,7 +324,7 @@ impl GenServer for TxBroadcaster { debug!(received = "BroadcastTxs"); let _ = self.broadcast_txs().await.inspect_err(|_| { - error!("Failed to broadcast transactions"); + debug!("Failed to broadcast transactions"); }); CastResponse::NoReply From 63a79aaed3952a10d2ba8cc42b3a772805ea24c6 Mon Sep 17 00:00:00 2001 From: Francisco Xavier Gauna Date: Fri, 31 Oct 2025 15:26:19 -0300 Subject: [PATCH 3/6] global allocator --- cmd/ethrex/ethrex.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/cmd/ethrex/ethrex.rs b/cmd/ethrex/ethrex.rs index aeeb16a20e..c532f3f805 100644 --- a/cmd/ethrex/ethrex.rs +++ b/cmd/ethrex/ethrex.rs @@ -16,9 +16,9 @@ static ALLOC: tikv_jemallocator::Jemalloc = tikv_jemallocator::Jemalloc; fn log_global_allocator() { if cfg!(all(feature = "jemalloc", not(target_env = "msvc"))) { - tracing::info!("Global allocator: jemalloc (tikv-jemallocator)"); + tracing::debug!("Global allocator: jemalloc (tikv-jemallocator)"); } else { - tracing::info!("Global allocator: system (std::alloc::System)"); + tracing::debug!("Global allocator: system (std::alloc::System)"); } } From d1680a1dc5dd0c71a11ff683f0ab371b40ed1979 Mon Sep 17 00:00:00 2001 From: Francisco Xavier Gauna Date: Fri, 31 Oct 2025 17:54:48 -0300 Subject: [PATCH 4/6] Fixed gas estimator tip --- crates/networking/rpc/eth/gas_tip_estimator.rs | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-) diff --git a/crates/networking/rpc/eth/gas_tip_estimator.rs b/crates/networking/rpc/eth/gas_tip_estimator.rs index b973d18ce8..ee166a01dd 100644 --- a/crates/networking/rpc/eth/gas_tip_estimator.rs +++ b/crates/networking/rpc/eth/gas_tip_estimator.rs @@ -1,6 +1,6 @@ use ethrex_common::{H256, types::MIN_GAS_TIP}; use ethrex_storage::Store; -use tracing::error; +use tracing::debug; use crate::utils::RpcErr; @@ -63,10 +63,9 @@ impl GasTipEstimator { // These are the blocks we'll use to estimate the price. let block_range = block_range_lower_bound..=latest_block_number; if block_range.is_empty() { - error!( - "Calculated block range from block {} \ - up to block {} for gas price estimation is empty", - block_range_lower_bound, latest_block_number + debug!( + block_range_lower_bound, + latest_block_number, "Calculated block range for gas price estimation is empty", ); return Err(RpcErr::Internal("Error calculating gas price".to_string())); } @@ -77,8 +76,11 @@ impl GasTipEstimator { // that returns a block range to not query them one-by-one. for block_num in block_range { let Some(block_body) = storage.get_block_body(block_num).await? else { - error!( - "Block body for block number {block_num} is missing but is below the latest known block!" + // TODO: check what to do when we have little info, for example when we just finished snap syncing + // There it's expected we miss the number + debug!( + block_num, + "Block body is missing but is below the latest known block!" ); return Err(RpcErr::Internal( "Error calculating gas price: missing data".to_string(), From 562340b93891d416f19c15397feafe672ad8240d Mon Sep 17 00:00:00 2001 From: Francisco Xavier Gauna Date: Fri, 31 Oct 2025 18:23:34 -0300 Subject: [PATCH 5/6] Improved Peer Handler Logs --- crates/networking/p2p/peer_handler.rs | 173 +++++++++++++++----------- 1 file changed, 100 insertions(+), 73 deletions(-) diff --git a/crates/networking/p2p/peer_handler.rs b/crates/networking/p2p/peer_handler.rs index 20799d21e0..56530be859 100644 --- a/crates/networking/p2p/peer_handler.rs +++ b/crates/networking/p2p/peer_handler.rs @@ -101,7 +101,10 @@ async fn ask_peer_head_number( retries: i32, ) -> Result { // TODO: Better error handling - trace!("Sync Log 11: Requesting sync head block number from peer {peer_id}"); + trace!( + ?peer_id, + "ask_peer_head_number: Requesting sync head block number from peer" + ); let request_id = rand::random(); let request = RLPxMessage::GetBlockHeaders(GetBlockHeaders { id: request_id, @@ -111,7 +114,7 @@ async fn ask_peer_head_number( reverse: false, }); - debug!("(Retry {retries}) Requesting sync head {sync_head:?} to peer {peer_id}"); + debug!(retry=retries, ?sync_head, %peer_id, "Requesting sync head from peer"); match PeerHandler::make_request(peer_table, peer_id, connection, request, PEER_REPLY_TIMEOUT) .await @@ -126,7 +129,9 @@ async fn ask_peer_head_number( .ok_or(PeerHandlerError::BlockHeaders)? .number; trace!( - "Sync Log 12: Received sync head block headers from peer {peer_id}, sync head number {sync_head_number}" + %peer_id, + sync_head_number, + "ask_peer_head_number: Received sync head block headers from peer" ); Ok(sync_head_number) } else { @@ -198,7 +203,7 @@ impl PeerHandler { let sync_head_number_retrieval_start = SystemTime::now(); - info!("Retrieving sync head block number from peers"); + debug!("Retrieving sync head block number from peers"); let mut retries = 1; @@ -230,7 +235,9 @@ impl PeerHandler { } Err(err) => { debug!( - "Sync Log 13: Failed to retrieve sync head block number from peer {peer_id}: {err}" + error=?err, + %peer_id, + "request_block_headers: Failed to retrieve sync head block number from peer" ); } } @@ -244,7 +251,7 @@ impl PeerHandler { .elapsed() .unwrap_or_default(); - info!("Sync head block number retrieved"); + debug!("Sync head block number retrieved"); *METRICS.time_to_retrieve_sync_head_block.lock().await = Some(sync_head_number_retrieval_elapsed); @@ -284,7 +291,7 @@ impl PeerHandler { let mut current_show = 0; // 3) create tasks that will request a chunk of headers from a peer - + // Useful info for the user info!("Starting to download block headers from peers"); *METRICS.headers_download_start_time.lock().await = Some(SystemTime::now()); @@ -297,7 +304,7 @@ impl PeerHandler { if headers.is_empty() { self.peer_table.record_failure(&peer_id).await?; - debug!("Failed to download chunk from peer. Downloader {peer_id} freed"); + debug!(%peer_id, "Failed to download chunk from peer. Downloader freed"); // reinsert the task to the queue tasks_queue_not_started.push_back((startblock, previous_chunk_limit)); @@ -314,10 +321,11 @@ impl PeerHandler { let batch_show = downloaded_count / 10_000; if current_show < batch_show { - debug!( - "Downloaded {} headers from peer {} (current count: {downloaded_count})", - headers.len(), - peer_id + trace!( + header_count=headers.len(), + current_count=downloaded_count, + peer_id=%peer_id, + "Downloaded headers from peer", ); current_show += 1; } @@ -332,15 +340,16 @@ impl PeerHandler { let new_chunk_limit = previous_chunk_limit - headers.len() as u64; - debug!( - "Task for ({startblock}, {new_chunk_limit}) was not completed, re-adding to the queue, {new_chunk_limit} remaining headers" + trace!( + startblock, + new_chunk_limit, "Task was not completed, re-adding to the queue" ); tasks_queue_not_started.push_back((new_start, new_chunk_limit)); } self.peer_table.record_success(&peer_id).await?; - debug!("Downloader {peer_id} freed"); + trace!(%peer_id, "Downloader freed"); } let Some((peer_id, mut connection)) = self .peer_table @@ -353,6 +362,7 @@ impl PeerHandler { let Some((startblock, chunk_limit)) = tasks_queue_not_started.pop_front() else { if downloaded_count >= block_count { + // Useful info for the user info!("All headers downloaded successfully"); break; } @@ -366,13 +376,15 @@ impl PeerHandler { continue; }; let tx = task_sender.clone(); - debug!("Downloader {peer_id} is now busy"); + trace!(%peer_id, "Downloader is now busy"); let mut peer_table = self.peer_table.clone(); // run download_chunk_from_peer in a different Tokio task tokio::spawn(async move { trace!( - "Sync Log 5: Requesting block headers from peer {peer_id}, chunk_limit: {chunk_limit}" + %peer_id, + %chunk_limit, + "request_block_headers: Requesting block headers" ); let headers = Self::download_chunk_from_peer( peer_id, @@ -382,14 +394,14 @@ impl PeerHandler { chunk_limit, ) .await - .inspect_err(|err| trace!("Sync Log 6: {peer_id} failed to download chunk: {err}")) + .inspect_err(|err| trace!(%peer_id, error=?err, "download_chunk_from_peer: failed to download chunk")) .unwrap_or_default(); tx.send((headers, peer_id, connection, startblock, chunk_limit)) .await - .inspect_err(|err| { - error!("Failed to send headers result through channel. Error: {err}") - }) + .inspect_err( + |err| debug!(error=?err, "Failed to send headers result through channel"), + ) }); } @@ -400,35 +412,31 @@ impl PeerHandler { let elapsed = start_time.elapsed().unwrap_or_default(); - debug!( - "Downloaded {} headers in {} seconds", - ret.len(), - format_duration(elapsed) - ); - { let downloaded_headers = ret.len(); let unique_headers = ret.iter().map(|h| h.hash()).collect::>(); debug!( - "Downloaded {} headers, unique: {}, duplicates: {}", downloaded_headers, - unique_headers.len(), - downloaded_headers - unique_headers.len() + unique = unique_headers.len(), + duplicates = downloaded_headers - unique_headers.len(), + time_elapsed_s = format_duration(elapsed), + "Downloaded headers" ); match downloaded_headers.cmp(&unique_headers.len()) { std::cmp::Ordering::Equal => { - info!("All downloaded headers are unique"); + trace!("All downloaded headers are unique"); } std::cmp::Ordering::Greater => { - warn!( + debug!( "Downloaded headers contain duplicates, {} duplicates found", downloaded_headers - unique_headers.len() ); } std::cmp::Ordering::Less => { - warn!("Downloaded headers are less than unique headers, something went wrong"); + // This means something is very wrong, we don't expect it + error!("Downloaded headers are less than unique headers, something went wrong"); } } } @@ -474,14 +482,16 @@ impl PeerHandler { { return Ok(Some(block_headers)); } else { - warn!( - "[SYNCING] Received empty/invalid headers from peer, penalizing peer {peer_id}" + debug!( + %peer_id, + "[SYNCING] Received empty/invalid headers from peer, penalizing peer" ); } } // Timeouted - warn!( - "[SYNCING] Didn't receive block headers from peer, penalizing peer {peer_id}..." + debug!( + %peer_id, + "[SYNCING] Didn't receive block headers from peer, penalizing peer" ); } } @@ -499,7 +509,7 @@ impl PeerHandler { startblock: u64, chunk_limit: u64, ) -> Result, PeerHandlerError> { - debug!("Requesting block headers from peer {peer_id}"); + debug!(%peer_id, "Requesting block headers from peer"); let request_id = rand::random(); let request = RLPxMessage::GetBlockHeaders(GetBlockHeaders { id: request_id, @@ -518,7 +528,7 @@ impl PeerHandler { if are_block_headers_chained(&block_headers, &BlockRequestOrder::OldToNew) { Ok(block_headers) } else { - warn!("[SYNCING] Received invalid headers from peer: {peer_id}"); + debug!(%peer_id, "[SYNCING] Received invalid headers from peer"); Err(PeerHandlerError::InvalidHeaders) } } else { @@ -561,8 +571,9 @@ impl PeerHandler { return Ok(Some((block_bodies, peer_id))); } } - warn!( - "[SYNCING] Didn't receive block bodies from peer, penalizing peer {peer_id}..." + debug!( + %peer_id, + "[SYNCING] Didn't receive block bodies from peer, penalizing peer" ); self.peer_table.record_failure(&peer_id).await?; Ok(None) @@ -607,8 +618,10 @@ impl PeerHandler { let mut validation_success = true; for (header, body) in block_headers[..block_bodies.len()].iter().zip(block_bodies) { if let Err(e) = validate_block_body(header, &body) { - warn!( - "Invalid block body error {e}, discarding peer {peer_id} and retrying..." + debug!( + %peer_id, + error=?e, + "Invalid block body, discarding peer and retrying" ); validation_success = false; self.peer_table.record_critical_failure(&peer_id).await?; @@ -874,8 +887,8 @@ impl PeerHandler { dump_accounts_to_file(&path, account_state_chunk) .inspect_err(|err| { error!( - "We had an error dumping the last accounts to disk {}", - err.error + error=%err.error, + "We had an error dumping the last accounts to disk", ) }) .map_err(|_| PeerHandlerError::WriteStateSnapshotsDir(chunk_file))?; @@ -900,7 +913,10 @@ impl PeerHandler { tx: tokio::sync::mpsc::Sender<(Vec, H256, Option<(H256, H256)>)>, ) -> Result<(), PeerHandlerError> { debug!( - "Requesting account range from peer {peer_id}, chunk: {chunk_start:?} - {chunk_end:?}" + %peer_id, + ?chunk_start, + ?chunk_end, + "Requesting account range from peer" ); let request_id = rand::random(); let request = RLPxMessage::GetAccountRange(GetAccountRange { @@ -951,7 +967,7 @@ impl PeerHandler { tx.send((Vec::new(), peer_id, Some((chunk_start, chunk_end)))) .await .ok(); - tracing::error!("Received invalid account range"); + debug!("Received invalid account range"); return Ok(()); }; @@ -984,7 +1000,7 @@ impl PeerHandler { .await .ok(); } else { - tracing::debug!("Failed to get account range"); + debug!("Failed to get account range"); tx.send((Vec::new(), peer_id, Some((chunk_start, chunk_end)))) .await .ok(); @@ -1056,8 +1072,10 @@ impl PeerHandler { } = result; debug!( - "Downloaded {} bytecodes from peer {peer_id} (current count: {downloaded_count})", - bytecodes.len(), + bytecodes_count=bytecodes.len(), + %peer_id, + current_count=downloaded_count, + "Downloaded bytecodes from peer", ); if remaining_start < remaining_end { @@ -1114,7 +1132,10 @@ impl PeerHandler { remaining_end: chunk_end, }; debug!( - "Requesting bytecode from peer {peer_id}, chunk: {chunk_start:?} - {chunk_end:?}" + %peer_id, + ?chunk_start, + ?chunk_end, + "Requesting bytecode from peer" ); let request_id = rand::random(); let request = RLPxMessage::GetByteCodes(GetByteCodes { @@ -1154,7 +1175,7 @@ impl PeerHandler { }; tx.send(result).await.ok(); } else { - tracing::debug!("Failed to get bytecode"); + debug!("Failed to get bytecode"); tx.send(empty_task_result).await.ok(); } }); @@ -1164,8 +1185,8 @@ impl PeerHandler { .downloaded_bytecodes .fetch_add(downloaded_count, Ordering::Relaxed); info!( - "Finished downloading bytecodes, total bytecodes: {}", - all_bytecode_hashes.len() + total_bytecodes = all_bytecode_hashes.len(), + "Finished downloading bytecodes", ); Ok(Some(all_bytecodes)) @@ -1279,7 +1300,7 @@ impl PeerHandler { .expect("Shouldn't be empty") .expect("Shouldn't have a join error") .inspect_err(|err| { - error!("We found this error while dumping to file {err:?}") + error!(error=?err.error, "We found this error while dumping to file") }) .map_err(PeerHandlerError::DumpError)?; } @@ -1321,7 +1342,7 @@ impl PeerHandler { } if remaining_start < remaining_end { - debug!("Failed to download entire chunk from peer {peer_id}"); + debug!(%peer_id, "Failed to download entire chunk from peer"); if hash_start.is_zero() { // Task is common storage range request let task = StorageTask { @@ -1482,7 +1503,7 @@ impl PeerHandler { tasks_queue_not_started.push_back(task); task_count += 1; } - debug!("Split big storage account into {chunk_count} chunks."); + debug!(chunk_count, "Split big storage account into chunks."); } } else { account_storage_roots.accounts_with_storage_root.insert( @@ -1518,7 +1539,7 @@ impl PeerHandler { tasks_queue_not_started.push_back(task); task_count += 1; } - debug!("Split big storage account into {chunk_count} chunks."); + debug!(chunk_count, "Split big storage account into chunks."); } } } @@ -1555,10 +1576,14 @@ impl PeerHandler { .storage_leaves_downloaded .inc_by(effective_slots as u64); - debug!("Downloaded {n_storages} storages ({n_slots} slots) from peer {peer_id}"); debug!( - "Total tasks: {task_count}, completed tasks: {completed_tasks}, queued tasks: {}", - tasks_queue_not_started.len() + downloaded_storages=n_storages, + downloaded_slots=n_slots, + %peer_id, + task_count, + completed_tasks, + queued_tasks=tasks_queue_not_started.len(), + "Downloaded Storage Ranges" ); // THEN: update insert to read with the correct structure and reuse // tries, only changing the prefix for insertion. @@ -1588,7 +1613,7 @@ impl PeerHandler { } if block_is_stale(pivot_header) { - info!("request_storage_ranges became stale, breaking"); + debug!("request_storage_ranges became stale, breaking"); break; } @@ -1618,9 +1643,10 @@ impl PeerHandler { if task_count - completed_tasks < 30 { debug!( - "Assigning task: {task:?}, account_hash: {}, storage_root: {}", - chunk_account_hashes.first().unwrap_or(&H256::zero()), - chunk_storage_roots.first().unwrap_or(&H256::zero()), + ?task, + account_hash=?chunk_account_hashes.first().unwrap_or(&H256::zero()), + storage_root=?chunk_storage_roots.first().unwrap_or(&H256::zero()), + "Assigning task" ); } let peer_table = self.peer_table.clone(); @@ -1656,8 +1682,9 @@ impl PeerHandler { .await .into_iter() .map(|result| { - result - .inspect_err(|err| error!("We found this error while dumping to file {err:?}")) + result.inspect_err( + |err| error!(error=?err.error, "We found this error while dumping to file"), + ) }) .collect::, DumpError>>() .map_err(PeerHandlerError::DumpError)?; @@ -1721,13 +1748,13 @@ impl PeerHandler { ) .await else { - tracing::debug!("Failed to get storage range"); + debug!("Failed to get storage range"); tx.send(empty_task_result).await.ok(); return Ok(()); }; if slots.is_empty() && proof.is_empty() { tx.send(empty_task_result).await.ok(); - tracing::debug!("Received empty storage range"); + debug!("Received empty storage range"); return Ok(()); } // Check we got some data and no more than the requested amount @@ -1760,7 +1787,7 @@ impl PeerHandler { Some(root) => root, None => { tx.send(empty_task_result.clone()).await.ok(); - error!("No storage root for account {i}"); + error!(index = i, "No storage root for account"); return Err(PeerHandlerError::NoStorageRoots); } }; @@ -1888,8 +1915,8 @@ impl PeerHandler { for (index, node) in nodes.iter().enumerate() { if node.compute_hash().finalize() != paths[index].hash { error!( - "A peer is sending wrong data for the state trie node {:?}", - paths[index].path + path=?paths[index].path, + "A peer is sending wrong data for the state trie node", ); return Err(RequestStateTrieNodesError::InvalidHash); } @@ -1961,7 +1988,7 @@ impl PeerHandler { skip: 0, reverse: false, }); - info!("get_block_header: requesting header with number {block_number}"); + debug!(block_number, "get_block_header: requesting header"); match PeerHandler::make_request( &mut self.peer_table, peer_id, From ee042b69687b4c2e07170b433ae4e0a7a8fdcfed Mon Sep 17 00:00:00 2001 From: Francisco Xavier Gauna Date: Fri, 31 Oct 2025 18:31:21 -0300 Subject: [PATCH 6/6] Update rocksdb.rs --- crates/storage/store_db/rocksdb.rs | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/crates/storage/store_db/rocksdb.rs b/crates/storage/store_db/rocksdb.rs index f3e000cbdc..47af8c5e84 100644 --- a/crates/storage/store_db/rocksdb.rs +++ b/crates/storage/store_db/rocksdb.rs @@ -205,7 +205,8 @@ impl Store { // Get existing column families to know which ones to drop later let existing_cfs = match DBWithThreadMode::::list_cf(&db_options, path) { Ok(cfs) => { - info!("Found existing column families: {:?}", cfs); + info!("Database already exists, loading column families"); + debug!(column_families=?cfs, "Found existing database"); cfs } Err(_) => {