From 1059a07a0ec3f3ce8fc62561b37802009850086c Mon Sep 17 00:00:00 2001 From: giuseppere Date: Thu, 5 Feb 2026 17:46:24 +0100 Subject: [PATCH] improve logging to match upstream anvil --- .../anvil-polkadot/src/api_server/server.rs | 73 +++++++++++++++++-- .../src/substrate_node/mining_engine.rs | 15 +++- 2 files changed, 79 insertions(+), 9 deletions(-) diff --git a/crates/anvil-polkadot/src/api_server/server.rs b/crates/anvil-polkadot/src/api_server/server.rs index e883a8ee7e865..1b7630221e640 100644 --- a/crates/anvil-polkadot/src/api_server/server.rs +++ b/crates/anvil-polkadot/src/api_server/server.rs @@ -67,8 +67,8 @@ use polkadot_sdk::{ ReviveApi, evm::{ self, Block, BlockNumberOrTagOrHash, BlockTag, Bytes, CallTracerConfig, - FeeHistoryResult, FilterResults, Log, ReceiptInfo, TracerType, TransactionInfo, - TransactionSigned, + FeeHistoryResult, FilterResults, HashesOrTransactionInfos, Log, ReceiptInfo, + TracerType, TransactionInfo, TransactionSigned, }, }, parachains_common::{AccountId, Hash, Nonce}, @@ -528,7 +528,7 @@ impl ApiServer { &self, mine: Option>>, ) -> Result> { - node_info!("evm_mineDetailed"); + node_info!("evm_mine_detailed"); // Subscribe to new best blocks. let receiver = self.eth_rpc_client.block_notifier().map(|sender| sender.subscribe()); @@ -656,6 +656,7 @@ impl ApiServer { async fn get_balance(&self, addr: Address, block: Option) -> Result { node_info!("eth_getBalance"); + trace!(target: "backend", "get balance for {:?}", addr); let hash = self.get_block_hash_for_tag(block).await?; let runtime_api = self.eth_rpc_client.runtime_api(hash); @@ -670,6 +671,7 @@ impl ApiServer { block: Option, ) -> Result { node_info!("eth_getStorageAt"); + trace!(target: "backend", "get storage for {:?} at {:?}", addr, slot); let hash = self.get_block_hash_for_tag(block).await?; let runtime_api = self.eth_rpc_client.runtime_api(hash); let bytes: B256 = match runtime_api @@ -687,7 +689,7 @@ impl ApiServer { async fn get_code(&self, address: Address, block: Option) -> Result { node_info!("eth_getCode"); - + trace!(target: "backend", "get code for {:?}", address); let hash = self.get_block_hash_for_tag(block).await?; let code = self .eth_rpc_client @@ -704,6 +706,7 @@ impl ApiServer { hydrated_transactions: bool, ) -> Result> { node_info!("eth_getBlockByHash"); + trace!(target: "backend", "get block by hash {:?}", block_hash); let Some(block) = self .eth_rpc_client .block_by_ethereum_hash(&H256::from_slice(block_hash.as_slice())) @@ -771,6 +774,7 @@ impl ApiServer { block: Option, ) -> Result { node_info!("eth_getTransactionCount"); + trace!(target: "backend", "get nonce for {:?}", address); let hash = self.get_block_hash_for_tag(block).await?; let runtime_api = self.eth_rpc_client.runtime_api(hash); let nonce = runtime_api.nonce(address).await?; @@ -867,7 +871,9 @@ impl ApiServer { } }; - self.send_raw_transaction(Bytes(payload)).await + let hash = self.send_raw_transaction(Bytes(payload)).await?; + trace!(target: "node", "Added transaction: [{:?}] sender={:?}", hash, from); + Ok(hash) } async fn send_transaction_sync( @@ -892,6 +898,7 @@ impl ApiServer { block_number: BlockNumberOrTag, hydrated_transactions: bool, ) -> Result> { + trace!(target: "backend", "get block by number {:?}", block_number); let Some(block) = self .eth_rpc_client .block_by_number_or_tag(&ReviveBlockNumberOrTag::from(block_number).inner()) @@ -905,17 +912,31 @@ impl ApiServer { pub(crate) async fn snapshot(&mut self) -> Result { node_info!("evm_snapshot"); - Ok(self.revert_manager.snapshot()) + let id = self.revert_manager.snapshot(); + // Retrieve the block number from the snapshot we just created + if let Some((block_num, _)) = self.revert_manager.list_snapshots().get(&id) { + trace!(target: "backend", "creating snapshot {} at {}", id, block_num); + } + Ok(id) } pub(crate) async fn revert(&mut self, id: U256) -> Result { node_info!("evm_revert"); + // Get target block number before reverting + let target_block = + self.revert_manager.list_snapshots().get(&id).map(|(block_num, _)| *block_num); let res = self .revert_manager .revert(id) .map_err(|err| Error::Backend(BackendError::Client(err)))?; let Some(res) = res else { return Ok(false) }; + if let Some(block_num) = target_block { + // Note: upstream anvil logs each block reverted in a loop; we revert atomically + // to a snapshot, so we log the target block once + trace!(target: "backend", "reverting to block {}", block_num); + } + self.on_revert_update(res).await?; Ok(true) @@ -929,6 +950,7 @@ impl ApiServer { pub(crate) async fn reset(&mut self, forking: Option) -> Result<()> { self.instance_id = B256::random(); node_info!("anvil_reset"); + trace!(target: "backend", "reset to fresh in-memory state"); // TODO: should be removed once forking feature is implemented and support is added in // revert manager to handle it if forking.is_some() { @@ -1899,6 +1921,45 @@ impl ApiServer { let block_timestamp = self.backend.read_timestamp(block_hash)?; let block_number = self.backend.read_block_number(block_hash)?; let timestamp = utc_from_millis(block_timestamp)?; + + // Get block with transaction hashes + if let Ok(Some(substrate_block)) = self.eth_rpc_client.block_by_hash(&block_hash).await { + if let Some(evm_block) = self.eth_rpc_client.evm_block(substrate_block, false).await { + // Extract transaction hashes + let tx_hashes: Vec = match &evm_block.transactions { + HashesOrTransactionInfos::Hashes(hashes) => hashes.clone(), + // Considering that we called evm_block with hydrated set to false, we will + // never receive TransactionInfos, but we handle it anyways. + HashesOrTransactionInfos::TransactionInfos(infos) => { + infos.iter().map(|i| i.hash).collect() + } + }; + + if !tx_hashes.is_empty() { + node_info!(""); + + // Log each transaction + for tx_hash in tx_hashes { + if let Some(receipt) = self.eth_rpc_client.receipt(&tx_hash).await { + node_info!(" Transaction: {:?}", receipt.transaction_hash); + + if let Some(contract) = &receipt.contract_address { + node_info!(" Contract created: {contract}"); + } + + node_info!(" Gas used: {}", receipt.cumulative_gas_used); + + if receipt.status == Some(evm::U256::zero()) { + node_info!(" Error: reverted"); + } + + node_info!(""); + } + } + } + } + } + node_info!(" Block Number: {}", block_number); node_info!(" Block Hash: {:?}", block_hash); if timestamp.year() > 9999 { diff --git a/crates/anvil-polkadot/src/substrate_node/mining_engine.rs b/crates/anvil-polkadot/src/substrate_node/mining_engine.rs index 1070a1644a1fa..7eeffbdde5f5f 100644 --- a/crates/anvil-polkadot/src/substrate_node/mining_engine.rs +++ b/crates/anvil-polkadot/src/substrate_node/mining_engine.rs @@ -177,11 +177,13 @@ impl MiningEngine { /// # Arguments /// * `interval` - Block production interval in seconds (0 to disable) pub fn set_interval_mining(&self, interval: Duration) { + let old_mode = *self.mining_mode.read(); let new_mode = if interval.as_secs() == 0 { MiningMode::None } else { MiningMode::Interval { tick: interval } }; + trace!(target: "miner", "updated mining mode from {:?} to {:?}", old_mode, new_mode); *self.mining_mode.write() = new_mode; self.wake(); } @@ -221,13 +223,15 @@ impl MiningEngine { /// # Arguments /// * `enabled` - True to enable auto-mining, false to disable pub fn set_auto_mine(&self, enabled: bool) { - let mining_mode = match (self.is_automine(), enabled) { + let old_mode = *self.mining_mode.read(); + let new_mode = match (self.is_automine(), enabled) { (true, false) => Some(MiningMode::None), (false, true) => Some(MiningMode::AutoMining), _ => None, }; - if let Some(mining_mode) = mining_mode { - *self.mining_mode.write() = mining_mode; + if let Some(new_mode) = new_mode { + trace!(target: "miner", "updated mining mode from {:?} to {:?}", old_mode, new_mode); + *self.mining_mode.write() = new_mode; self.wake(); } } @@ -451,8 +455,13 @@ pub async fn run_mining_engine(engine: Arc) { combined_stream = build_streams_for_mode(new_mode, &engine); } Some(_) = combined_stream.next(), if !combined_stream.is_empty() => { + let tx_count = engine.transaction_pool.ready().count(); + trace!(target: "miner", "creating new block"); + trace!(target: "backend", "creating new block with {} transactions", tx_count); match seal_now(&engine.seal_command_sender).await { Ok(block) => { + // Note: upstream anvil logs block_number here, but CreatedBlock only has hash + trace!(target: "miner", "created new block: {:?}", block.hash); debug!(hash=?block.hash, "sealed"); } Err(MiningError::ClosedChannel) => {