From 2dc40c1c87d37db48970a0c4d6b8500e7c7fe15f Mon Sep 17 00:00:00 2001 From: Dustin Brickwood Date: Wed, 20 Nov 2024 22:25:16 -0600 Subject: [PATCH 01/16] feat: add structured show call logging --- src/config/cli.rs | 37 +++----- src/config/mod.rs | 82 ++++++++++++++++++ src/data/address_map.json | 145 ++++++++++--------------------- src/formatter.rs | 175 +++++++++++++++++++++++++++++++++++--- src/node/in_memory.rs | 28 +++--- 5 files changed, 312 insertions(+), 155 deletions(-) diff --git a/src/config/cli.rs b/src/config/cli.rs index 7a4ffa5c..c763287b 100644 --- a/src/config/cli.rs +++ b/src/config/cli.rs @@ -91,6 +91,10 @@ pub struct Cli { /// Show call output information. pub show_outputs: Option, + #[arg(long, help_heading = "Debugging Options")] + /// Show event logs information. + pub show_event_logs: Option, + #[arg(long, help_heading = "Debugging Options")] /// Show storage log information. pub show_storage_logs: Option, @@ -325,22 +329,7 @@ impl Cli { pub fn into_test_node_config(self) -> eyre::Result { let genesis_balance = U256::from(self.balance as u128 * 10u128.pow(18)); - let vm_log_detail = if let Some(output) = self.show_outputs { - if output { - Some(ShowVMDetails::All) - } else { - Some(ShowVMDetails::None) - } - } else if let Some(logs) = self.show_storage_logs { - match logs { - ShowStorageLogs::None => Some(ShowVMDetails::None), - _ => Some(ShowVMDetails::All), - } - } else { - None - }; - - let config = TestNodeConfig::default() + let mut config = TestNodeConfig::default() .with_port(self.port) .with_l1_gas_price(self.l1_gas_price) .with_l2_gas_price(self.l2_gas_price) @@ -349,7 +338,12 @@ impl Cli { .with_show_event_logs(self.show_event_logs) .with_disable_console_log(self.disable_console_log) .with_show_calls(self.show_calls) - .with_vm_log_detail(vm_log_detail) + .with_vm_log_detail(self.show_vm_details) + .with_show_storage_logs(self.show_storage_logs) + .with_show_gas_details(self.show_gas_details) + .with_show_outputs(self.show_outputs) + .with_show_event_logs(self.show_event_logs) + .with_resolve_hashes(self.resolve_hashes) .with_gas_limit_scale(self.limit_scale_factor) .with_price_scale(self.price_scale_factor) .with_resolve_hashes(self.resolve_hashes) @@ -396,13 +390,10 @@ impl Cli { } if self.debug_mode { - Ok(config - .with_show_calls(Some(ShowCalls::All)) - .with_vm_log_detail(Some(ShowVMDetails::All)) - .with_resolve_hashes(Some(true))) - } else { - Ok(config) + config = config.with_debug_mode(); } + + Ok(config) } fn account_generator(&self) -> AccountGenerator { diff --git a/src/config/mod.rs b/src/config/mod.rs index 021c4d3c..065f2900 100644 --- a/src/config/mod.rs +++ b/src/config/mod.rs @@ -77,6 +77,8 @@ pub struct TestNodeConfig { pub show_vm_details: ShowVMDetails, /// Level of detail for gas usage logs pub show_gas_details: ShowGasDetails, + /// Whether to show event logs + pub show_event_logs: bool, /// Whether to resolve hash references pub resolve_hashes: bool, /// Don’t print anything on startup if true @@ -151,6 +153,7 @@ impl Default for TestNodeConfig { show_storage_logs: Default::default(), show_vm_details: Default::default(), show_gas_details: Default::default(), + show_event_logs: false, resolve_hashes: false, silent: false, system_contracts_options: Default::default(), @@ -600,6 +603,15 @@ impl TestNodeConfig { &self.log_file_path } + /// Applies the defaults for debug mode. + #[must_use] + pub fn with_debug_mode(mut self) -> Self { + self.show_calls = ShowCalls::User; // Set show_calls to User + self.resolve_hashes = true; // Enable resolving hashes + self.show_gas_details = ShowGasDetails::All; // Enable detailed gas logs + self + } + /// Set the visibility of call logs #[must_use] pub fn with_show_calls(mut self, show_calls: Option) -> Self { @@ -672,6 +684,76 @@ impl TestNodeConfig { self.resolve_hashes } + /// Set the visibility of storage logs + #[must_use] + pub fn with_show_storage_logs(mut self, show_storage_logs: Option) -> Self { + if let Some(show_storage_logs) = show_storage_logs { + self.show_storage_logs = show_storage_logs; + } + self + } + + /// Get the visibility of storage logs + pub fn get_show_storage_logs(&self) -> ShowStorageLogs { + self.show_storage_logs + } + + /// Set the detail level of VM execution logs + #[must_use] + pub fn with_vm_log_detail(mut self, detail: Option) -> Self { + if let Some(detail) = detail { + self.show_vm_details = detail; + } + self + } + + /// Get the detail level of VM execution logs + pub fn get_vm_log_detail(&self) -> ShowVMDetails { + self.show_vm_details + } + + /// Set the visibility of gas usage logs + #[must_use] + pub fn with_show_gas_details(mut self, show_gas_details: Option) -> Self { + if let Some(show_gas_details) = show_gas_details { + self.show_gas_details = show_gas_details; + } + self + } + + /// Get the visibility of gas usage logs + pub fn get_show_gas_details(&self) -> ShowGasDetails { + self.show_gas_details + } + + /// Set the visibility of event logs + #[must_use] + pub fn with_show_event_logs(mut self, show_event_logs: Option) -> Self { + if let Some(show_event_logs) = show_event_logs { + self.show_event_logs = show_event_logs; + } + self + } + + /// Get the visibility of event logs + pub fn get_show_event_logs(&self) -> bool { + self.show_event_logs + } + + /// Set show outputs + #[must_use] + pub fn with_show_outputs(mut self, show_outputs: Option) -> Self { + if let Some(show_outputs) = show_outputs { + self.show_outputs = show_outputs; + } + self + } + + /// Get show outputs + pub fn get_show_outputs(&self) -> bool { + self.show_outputs + } + /// Set the gas limit scale factor #[must_use] pub fn with_gas_limit_scale(mut self, scale: Option) -> Self { diff --git a/src/data/address_map.json b/src/data/address_map.json index 065615b6..341f2be1 100644 --- a/src/data/address_map.json +++ b/src/data/address_map.json @@ -1,102 +1,45 @@ [ - [ - "0x0000000000000000000000000000000000008001", - "bootloader", - "System" - ], - [ - "0x0000000000000000000000000000000000008002", - "Account Code Storage", - "System" - ], - [ - "0x0000000000000000000000000000000000008003", - "Nonce Holder", - "System" - ], - [ - "0x0000000000000000000000000000000000008004", - "Known code storage", - "System" - ], - [ - "0x0000000000000000000000000000000000008005", - "ImmutableSimulator", - "System" - ], - [ - "0x0000000000000000000000000000000000008006", - "L2 deployer", - "System" - ], - [ - "0x0000000000000000000000000000000000008007", - "Force L2 deployer", - "System" - ], - [ - "0x0000000000000000000000000000000000008008", - "L1 messenger", - "System" - ], - [ - "0x0000000000000000000000000000000000008009", - "Msg Value System Contract", - "System" - ], - [ - "0x000000000000000000000000000000000000800a", - "EthToken System Contract", - "System" - ], - [ - "0x000000000000000000000000000000000000800b", - "System context", - "System" - ], - [ - "0x000000000000000000000000000000000000800c", - "Bootloader utilities", - "System" - ], - [ - "0x000000000000000000000000000000000000800d", - "Event writer", - "System" - ], - [ - "0x000000000000000000000000000000000000800e", - "Compressor", - "System" - ], - [ - "0x000000000000000000000000000000000000800f", - "ComplexUpgrader", - "System" - ], - [ - "0x0000000000000000000000000000000000008010", - "Keccak", - "Precompile" - ], - [ - "0x0000000000000000000000000000000000008011", - "PubdataChunkPublisher", - "System" - ], - [ - "0x0000000000000000000000000000000000008012", - "CodeOracle", - "System" - ], - [ - "0x000000000000000000636f6e736f6c652e6c6f67", - "Console log", - "Precompile" - ], - [ - "0x0000000000000000000000000000000000010000", - "Create2Factory", - "Popular" - ] -] \ No newline at end of file + ["0x0000000000000000000000000000000000008001", "bootloader", "System"], + [ + "0x0000000000000000000000000000000000008002", + "AccountCodeStorage", + "System" + ], + ["0x0000000000000000000000000000000000008003", "NonceHolder", "System"], + ["0x0000000000000000000000000000000000008004", "KnownCodesStorage", "System"], + [ + "0x0000000000000000000000000000000000008005", + "ImmutableSimulator", + "System" + ], + ["0x0000000000000000000000000000000000008006", "ContractDeployer", "System"], + ["0x0000000000000000000000000000000000008007", "ForceL2Deployer", "System"], + ["0x0000000000000000000000000000000000008008", "L1Messenger", "System"], + ["0x0000000000000000000000000000000000008009", "MsgValueSimulator", "System"], + ["0x000000000000000000000000000000000000800a", "L2BaseToken", "System"], + ["0x000000000000000000000000000000000000800b", "SystemContext", "System"], + [ + "0x000000000000000000000000000000000000800c", + "BootloaderUtilities", + "System" + ], + ["0x000000000000000000000000000000000000800d", "EventWriter", "System"], + ["0x000000000000000000000000000000000000800e", "Compressor", "System"], + ["0x000000000000000000000000000000000000800f", "ComplexUpgrader", "System"], + ["0x0000000000000000000000000000000000008010", "Keccak", "Precompile"], + [ + "0x0000000000000000000000000000000000008011", + "PubdataChunkPublisher", + "System" + ], + ["0x0000000000000000000000000000000000008012", "CodeOracle", "System"], + ["0x000000000000000000636f6e736f6c652e6c6f67", "ConsoleLog", "Precompile"], + ["0x0000000000000000000000000000000000010000", "Create2Factory", "Popular"], + ["0x0000000000000000000000000000000000000002", "SHA256", "Precompile"], + ["0x0000000000000000000000000000000000000001", "ECRecover", "Precompile"], + ["0x0000000000000000000000000000000000000006", "EcAdd", "Precompile"], + ["0x0000000000000000000000000000000000000007", "EcMul", "Precompile"], + ["0x0000000000000000000000000000000000000008", "EcPairing", "Precompile"], + ["0xc706EC7dfA5D4Dc87f29f859094165E8290530f5", "GasBoundCaller", "System"], + ["0x0000000000000000000000000000000000000100", "P256Verify", "System"] +] diff --git a/src/formatter.rs b/src/formatter.rs index 92c515b3..3b07effb 100644 --- a/src/formatter.rs +++ b/src/formatter.rs @@ -10,11 +10,11 @@ use std::str; use crate::fork::block_on; use zksync_types::H160; +use lazy_static::lazy_static; use zksync_multivm::interface::{Call, VmEvent, VmExecutionResultAndLogs}; +use zksync_types::Address; use zksync_types::StorageLogWithPreviousValue; -use lazy_static::lazy_static; - #[derive(Debug, Deserialize, Clone, PartialEq, Eq)] pub enum ContractType { System, @@ -43,15 +43,25 @@ lazy_static! { }; } -fn address_to_human_readable(address: H160) -> Option { - KNOWN_ADDRESSES - .get(&address) - .map(|known_address| match known_address.contract_type { - ContractType::System => known_address.name.to_string(), - ContractType::Precompile => format!("{}", known_address.name.dimmed()), - ContractType::Popular => format!("{}", known_address.name.green()), - ContractType::Unknown => known_address.name.to_string(), +fn address_to_human_readable(address: H160, initiator: H160) -> Option { + let is_initiator = address == initiator; + if is_initiator { + let name = "initiator".bold().green().to_string(); + let formatted_address = format!("{:#x}", address); + Some(format!("{}@{}", name, formatted_address)) + } else { + KNOWN_ADDRESSES.get(&address).map(|known_address| { + let name = match known_address.contract_type { + ContractType::System => known_address.name.bold().bright_blue().to_string(), + ContractType::Precompile => known_address.name.bold().magenta().to_string(), + ContractType::Popular => known_address.name.bold().green().to_string(), + ContractType::Unknown => known_address.name.dimmed().to_string(), + }; + + let formatted_address = format!("{:#x}", address); + format!("{}@{}", name, formatted_address) }) + } } /// Pretty-prints event object @@ -74,10 +84,10 @@ pub fn print_event(event: &VmEvent, resolve_hashes: bool) { tt.push(selector.unwrap_or(format!("{:#x}", topic))); } } - + // TODO: fix tracing::info!( "{}", - address_to_human_readable(event.address) + address_to_human_readable(event.address, event.address) .map(|x| format!("{:42}", x.blue())) .unwrap_or(format!("{:42}", format!("{:?}", event.address).blue())) ); @@ -188,7 +198,7 @@ pub fn print_call( "{}{:?} {} {} {} {} {} {} ({})", " ".repeat(padding), call.r#type, - address_to_human_readable(call.to) + address_to_human_readable(call.to, call.from) .map(|x| format!("{:<52}", x)) .unwrap_or(format!("{:<52}", format!("{:?}", call.to).bold())), function_signature, @@ -262,6 +272,143 @@ impl PubdataBytesInfo { } } +fn format_number(num: u64) -> String { + num.to_string() +} + +fn build_prefix(sibling_stack: &Vec) -> String { + let mut prefix = String::new(); + for &has_more_siblings in sibling_stack { + if has_more_siblings { + prefix.push_str("│ "); + } else { + prefix.push_str(" "); + } + } + prefix +} + +pub fn print_call2( + initiator: Address, + call: &Call, + sibling_stack: &Vec, + is_last_sibling: bool, + show_calls: &ShowCalls, + show_outputs: bool, + resolve_hashes: bool, +) { + let contract_type = KNOWN_ADDRESSES + .get(&call.to) + .cloned() + .map(|known_address| known_address.contract_type) + .unwrap_or(ContractType::Unknown); + + let should_print = match (&contract_type, &show_calls) { + (_, ShowCalls::All) => true, + (_, ShowCalls::None) => false, + (ContractType::Unknown, _) => true, + (ContractType::Popular, _) => true, + (ContractType::Precompile, _) => false, + (ContractType::System, ShowCalls::User) => false, + (ContractType::System, ShowCalls::System) => true, + }; + + if should_print { + let prefix = build_prefix(sibling_stack); + let branch = if is_last_sibling { + "└─ " + } else { + "├─ " + }; + let full_prefix = format!("{}{}", prefix, branch); + + let call_type_display = format!("{:?}", call.r#type).blue(); + let remaining_gas_display = format_number(call.gas).yellow(); + let gas_used_display = format!("({})", format_number(call.gas_used)).bold(); + + // Get contract display + let contract_display = address_to_human_readable(call.to, initiator) + .map(|x| format!("{:}", x)) + .unwrap_or(format!("{:}", format!("{:?}", call.to).bold())); + + // Get function signature + let function_signature = if call.input.len() >= 4 { + let sig = hex::encode(&call.input[0..4]); + if contract_type == ContractType::Precompile || !resolve_hashes { + format!("0x{}", sig) + } else { + block_on(async move { + match resolver::decode_function_selector(&sig).await { + Ok(Some(name)) => name, + Ok(None) | Err(_) => format!("0x{}", sig), + } + }) + } + } else { + "unknown".to_string() + }; + + // TODO: handle outputs + let output = if show_outputs { + call.output + .as_slice() + .iter() + .map(|byte| format!("{:02x}", byte)) + .collect::>() + .join("") + } else { + "".to_string() + }; + + let function_display = function_signature.cyan().bold(); + + // Build the line + let line = format!( + "{}{} [{}] {}::{} {}", + full_prefix, + call_type_display, + remaining_gas_display, + contract_display, + function_display, + gas_used_display + ); + + // Handle errors + if call.revert_reason.is_some() || call.error.is_some() { + tracing::info!("{}", line.red()); + if let Some(ref reason) = call.revert_reason { + let error_line = format!("{} └─ 🔴 Revert reason: {}", prefix, reason); + tracing::info!("{}", error_line.red()); + } + if let Some(ref error) = call.error { + let error_line = format!("{} └─ 🔴 Error: {}", prefix, error); + tracing::info!("{}", error_line.red()); + } + } else { + tracing::info!("{}", line); + } + } + // Process subcalls + let num_subcalls = call.calls.len(); + if num_subcalls > 0 { + let mut new_sibling_stack = sibling_stack.clone(); + new_sibling_stack.push(!is_last_sibling); + for (i, subcall) in call.calls.iter().enumerate() { + let is_last_subcall = i == num_subcalls - 1; + print_call2( + initiator, + subcall, + &new_sibling_stack, + is_last_subcall, + show_calls, + show_outputs, + resolve_hashes, + ); + } + } +} + +// TODO address to human readable issue pub fn print_logs( log_query: &StorageLogWithPreviousValue, pubdata_bytes: Option, @@ -271,7 +418,7 @@ pub fn print_logs( tracing::info!( "{:<15} {}", "Address:", - address_to_human_readable(*log_query.log.key.address()) + address_to_human_readable(*log_query.log.key.address(), *log_query.log.key.address()) .unwrap_or(format!("{}", log_query.log.key.address())) ); tracing::info!("{:<15} {:#066x}", "Key:", log_query.log.key.key()); diff --git a/src/node/in_memory.rs b/src/node/in_memory.rs index fee137a7..d79a876d 100644 --- a/src/node/in_memory.rs +++ b/src/node/in_memory.rs @@ -1566,31 +1566,25 @@ impl InMemoryNode { inner.console_log_handler.handle_call_recursive(call); } } - + println!(""); + println!(""); if inner.config.show_calls != ShowCalls::None { - tracing::info!(""); - let call_traces_count = if !call_traces.is_empty() { - // All calls/sub-calls are stored within the first call trace - call_traces[0].calls.len() - } else { - 0 - }; - tracing::info!( - "==== {}", - format!("{:?} call traces. ", call_traces_count).bold() - ); - - for call in call_traces { - formatter::print_call( + tracing::info!("[Transaction Execution]"); + let num_calls = call_traces.len(); + for (i, call) in call_traces.iter().enumerate() { + let is_last_sibling = i == num_calls - 1; + formatter::print_call2( + tx.initiator_account(), call, - 0, + &vec![], + is_last_sibling, &inner.config.show_calls, inner.config.show_outputs, inner.config.resolve_hashes, ); } } - + println!(""); if inner.config.show_event_logs { tracing::info!(""); tracing::info!( From b34236a1b4fef762027614bb223b826bcbf0140e Mon Sep 17 00:00:00 2001 From: Dustin Brickwood Date: Thu, 21 Nov 2024 14:47:54 -0600 Subject: [PATCH 02/16] feat: tx summary logs structured --- src/data/address_map.json | 2 +- src/formatter.rs | 268 ++++++++++++++++++-------------------- src/node/in_memory.rs | 96 +++++++------- src/utils.rs | 14 ++ 4 files changed, 189 insertions(+), 191 deletions(-) diff --git a/src/data/address_map.json b/src/data/address_map.json index 341f2be1..d3f53704 100644 --- a/src/data/address_map.json +++ b/src/data/address_map.json @@ -34,7 +34,7 @@ ], ["0x0000000000000000000000000000000000008012", "CodeOracle", "System"], ["0x000000000000000000636f6e736f6c652e6c6f67", "ConsoleLog", "Precompile"], - ["0x0000000000000000000000000000000000010000", "Create2Factory", "Popular"], + ["0x0000000000000000000000000000000000010000", "Create2Factory", "System"], ["0x0000000000000000000000000000000000000002", "SHA256", "Precompile"], ["0x0000000000000000000000000000000000000001", "ECRecover", "Precompile"], ["0x0000000000000000000000000000000000000006", "EcAdd", "Precompile"], diff --git a/src/formatter.rs b/src/formatter.rs index 3b07effb..0b7842ce 100644 --- a/src/formatter.rs +++ b/src/formatter.rs @@ -10,10 +10,11 @@ use std::str; use crate::fork::block_on; use zksync_types::H160; +use crate::utils::{calculate_eth_cost, format_gwei, to_human_size}; use lazy_static::lazy_static; use zksync_multivm::interface::{Call, VmEvent, VmExecutionResultAndLogs}; use zksync_types::Address; -use zksync_types::StorageLogWithPreviousValue; +use zksync_types::{StorageLogWithPreviousValue, Transaction}; #[derive(Debug, Deserialize, Clone, PartialEq, Eq)] pub enum ContractType { @@ -43,25 +44,57 @@ lazy_static! { }; } -fn address_to_human_readable(address: H160, initiator: H160) -> Option { +fn address_to_human_readable(address: H160) -> Option { + KNOWN_ADDRESSES + .get(&address) + .map(|known_address| match known_address.contract_type { + ContractType::System => known_address.name.to_string(), + ContractType::Precompile => format!("{}", known_address.name.dimmed()), + ContractType::Popular => format!("{}", known_address.name.green()), + ContractType::Unknown => known_address.name.to_string(), + }) +} + +fn address_to_human_readable2( + address: H160, + initiator: H160, + contract_address: Option, + call_type: &str, +) -> Option { let is_initiator = address == initiator; + let excluded_addresses = [ + H160::from_slice(&hex::decode("0000000000000000000000000000000000008006").unwrap()), + H160::from_slice(&hex::decode("0000000000000000000000000000000000010000").unwrap()), + ]; + + let is_contract = Some(address) == contract_address && !excluded_addresses.contains(&address); + if is_initiator { let name = "initiator".bold().green().to_string(); let formatted_address = format!("{:#x}", address); - Some(format!("{}@{}", name, formatted_address)) - } else { - KNOWN_ADDRESSES.get(&address).map(|known_address| { - let name = match known_address.contract_type { - ContractType::System => known_address.name.bold().bright_blue().to_string(), - ContractType::Precompile => known_address.name.bold().magenta().to_string(), - ContractType::Popular => known_address.name.bold().green().to_string(), - ContractType::Unknown => known_address.name.dimmed().to_string(), - }; - - let formatted_address = format!("{:#x}", address); - format!("{}@{}", name, formatted_address) - }) + return Some(format!("{}{}{}", name, "@".dimmed(), formatted_address)); + } + if call_type == "Create" { + let name = "deployed".bold().bright_green().to_string(); + let formatted_address = format!("{:#x}", address); + return Some(format!("{}{}{}", name, "@".dimmed(), formatted_address)); + } else if is_contract { + let name = "contract".bold().bright_green().to_string(); + let formatted_address = format!("{:#x}", address); + return Some(format!("{}{}{}", name, "@".dimmed(), formatted_address)); } + + KNOWN_ADDRESSES.get(&address).map(|known_address| { + let name = match known_address.contract_type { + ContractType::System => known_address.name.bold().bright_blue().to_string(), + ContractType::Precompile => known_address.name.bold().magenta().to_string(), + ContractType::Popular => known_address.name.bold().bright_green().to_string(), + ContractType::Unknown => known_address.name.dimmed().to_string(), + }; + + let formatted_address = format!("{:#x}", address).dimmed(); + format!("{}{}{}", name, "@".dimmed(), formatted_address) + }) } /// Pretty-prints event object @@ -87,7 +120,7 @@ pub fn print_event(event: &VmEvent, resolve_hashes: bool) { // TODO: fix tracing::info!( "{}", - address_to_human_readable(event.address, event.address) + address_to_human_readable(event.address) .map(|x| format!("{:42}", x.blue())) .unwrap_or(format!("{:42}", format!("{:?}", event.address).blue())) ); @@ -129,109 +162,6 @@ pub fn print_event(event: &VmEvent, resolve_hashes: bool) { }); } -/// Pretty-prints contents of a 'call' - including subcalls. -/// If skip_resolve is false, will try to contact openchain to resolve the ABI names. -pub fn print_call( - call: &Call, - padding: usize, - show_calls: &ShowCalls, - show_outputs: bool, - resolve_hashes: bool, -) { - let contract_type = KNOWN_ADDRESSES - .get(&call.to) - .cloned() - .map(|known_address| known_address.contract_type) - .unwrap_or(ContractType::Unknown); - - let should_print = match (&contract_type, &show_calls) { - (_, ShowCalls::All) => true, - (_, ShowCalls::None) => false, - // now we're left only with 'user' and 'system' - (ContractType::Unknown, _) => true, - (ContractType::Popular, _) => true, - (ContractType::Precompile, _) => false, - // Now we're left with System - (ContractType::System, ShowCalls::User) => false, - (ContractType::System, ShowCalls::System) => true, - }; - if should_print { - let function_signature = if call.input.len() >= 4 { - let sig = call.input.as_slice()[..4] - .iter() - .map(|byte| format!("{:02x}", byte)) - .collect::>() - .join(""); - - if contract_type == ContractType::Precompile || !resolve_hashes { - format!("{:>16}", sig) - } else { - block_on(async move { - let fetch = resolver::decode_function_selector(&sig).await.unwrap(); - fetch.unwrap_or(format!("{:>16}", format!("0x{}", sig).dimmed())) - }) - } - } else { - format!( - "0x{}", - call.input - .as_slice() - .iter() - .map(|byte| format!("{:02x}", byte)) - .collect::>() - .join("") - ) - }; - - let output = if show_outputs { - call.output - .as_slice() - .iter() - .map(|byte| format!("{:02x}", byte)) - .collect::>() - .join("") - } else { - "".to_string() - }; - - let pretty_print = format!( - "{}{:?} {} {} {} {} {} {} ({})", - " ".repeat(padding), - call.r#type, - address_to_human_readable(call.to, call.from) - .map(|x| format!("{:<52}", x)) - .unwrap_or(format!("{:<52}", format!("{:?}", call.to).bold())), - function_signature, - output, - call.revert_reason - .as_ref() - .map(|s| format!("Revert: {}", s)) - .unwrap_or_default(), - call.error - .as_ref() - .map(|s| format!("Error: {}", s)) - .unwrap_or_default(), - call.gas, - call.gas_used - ); - - if call.revert_reason.as_ref().is_some() || call.error.as_ref().is_some() { - tracing::info!("{}", pretty_print.on_red()); - } else { - tracing::info!("{}", pretty_print); - } - } - for subcall in &call.calls { - print_call( - subcall, - padding + 2, - show_calls, - show_outputs, - resolve_hashes, - ); - } -} - /// Amount of pubdata that given write has cost. pub enum PubdataBytesInfo { // This slot is free @@ -272,10 +202,6 @@ impl PubdataBytesInfo { } } -fn format_number(num: u64) -> String { - num.to_string() -} - fn build_prefix(sibling_stack: &Vec) -> String { let mut prefix = String::new(); for &has_more_siblings in sibling_stack { @@ -288,8 +214,9 @@ fn build_prefix(sibling_stack: &Vec) -> String { prefix } -pub fn print_call2( +pub fn print_call( initiator: Address, + contract_address: Option, call: &Call, sibling_stack: &Vec, is_last_sibling: bool, @@ -323,13 +250,18 @@ pub fn print_call2( let full_prefix = format!("{}{}", prefix, branch); let call_type_display = format!("{:?}", call.r#type).blue(); - let remaining_gas_display = format_number(call.gas).yellow(); - let gas_used_display = format!("({})", format_number(call.gas_used)).bold(); + let remaining_gas_display = to_human_size(call.gas.into()).yellow(); + let gas_used_display = format!("({})", to_human_size(call.gas_used.into())).bold(); // Get contract display - let contract_display = address_to_human_readable(call.to, initiator) - .map(|x| format!("{:}", x)) - .unwrap_or(format!("{:}", format!("{:?}", call.to).bold())); + let contract_display = address_to_human_readable2( + call.to, + initiator, + contract_address, + format!("{:?}", call.r#type).as_str(), + ) + .map(|x| format!("{:}", x)) + .unwrap_or(format!("{:}", format!("{:?}", call.to).bold())); // Get function signature let function_signature = if call.input.len() >= 4 { @@ -348,18 +280,6 @@ pub fn print_call2( "unknown".to_string() }; - // TODO: handle outputs - let output = if show_outputs { - call.output - .as_slice() - .iter() - .map(|byte| format!("{:02x}", byte)) - .collect::>() - .join("") - } else { - "".to_string() - }; - let function_display = function_signature.cyan().bold(); // Build the line @@ -387,7 +307,28 @@ pub fn print_call2( } else { tracing::info!("{}", line); } + + // Handle outputs + if show_outputs && !call.output.is_empty() { + let output_display = call + .output + .as_slice() + .iter() + .map(|byte| format!("{:02x}", byte)) + .collect::>() + .join(""); + + let output_branch = if is_last_sibling { + " └── Output: ".dimmed() + } else { + " ├── Output: ".dimmed() + }; + + let output_line = format!("{}{}", full_prefix, output_branch) + &output_display; + tracing::info!("{}", output_line); + } } + // Process subcalls let num_subcalls = call.calls.len(); if num_subcalls > 0 { @@ -395,8 +336,9 @@ pub fn print_call2( new_sibling_stack.push(!is_last_sibling); for (i, subcall) in call.calls.iter().enumerate() { let is_last_subcall = i == num_subcalls - 1; - print_call2( + print_call( initiator, + contract_address, subcall, &new_sibling_stack, is_last_subcall, @@ -408,6 +350,46 @@ pub fn print_call2( } } +pub fn log_transaction_summary( + l2_gas_price: u64, + tx: &Transaction, + tx_result: &VmExecutionResultAndLogs, + status: &str, +) { + // Calculate used and refunded gas + let used_gas = tx.gas_limit() - tx_result.refunds.gas_refunded; + let paid_in_eth = calculate_eth_cost(l2_gas_price, used_gas.as_u64()); + + let refunded_gas = tx_result.refunds.gas_refunded; + + // Calculate refunded gas in ETH + let refunded_in_eth = calculate_eth_cost(l2_gas_price, refunded_gas); + + let emoji = match status { + "SUCCESS" => "✅", + "FAILED" => "❌", + "HALTED" => "⏸️", + _ => "⚠️", + }; + + tracing::info!("{} [{}] Hash: {:?}", emoji, status, tx.hash()); + tracing::info!("Initiator: {:?}", tx.initiator_account()); + tracing::info!("Payer: {:?}", tx.payer()); + tracing::info!( + "Gas Usage: Limit: {} | Used: {} | Refunded: {}", + to_human_size(tx.gas_limit()), + to_human_size(used_gas.into()), + to_human_size(tx_result.refunds.gas_refunded.into()) + ); + tracing::info!( + "Paid: {:.10} ETH ({} gas * {})", + paid_in_eth, + used_gas, + format_gwei(l2_gas_price.into()) + ); + tracing::info!("Refunded: {:.10} ETH", refunded_in_eth); +} + // TODO address to human readable issue pub fn print_logs( log_query: &StorageLogWithPreviousValue, @@ -418,7 +400,7 @@ pub fn print_logs( tracing::info!( "{:<15} {}", "Address:", - address_to_human_readable(*log_query.log.key.address(), *log_query.log.key.address()) + address_to_human_readable(*log_query.log.key.address()) .unwrap_or(format!("{}", log_query.log.key.address())) ); tracing::info!("{:<15} {:#066x}", "Key:", log_query.log.key.key()); diff --git a/src/node/in_memory.rs b/src/node/in_memory.rs index d79a876d..237bb638 100644 --- a/src/node/in_memory.rs +++ b/src/node/in_memory.rs @@ -1200,7 +1200,7 @@ impl InMemoryNode { } let tx: Transaction = l2_tx.into(); - vm.push_transaction(tx); + vm.push_transaction(tx.clone()); let call_tracer_result = Arc::new(OnceCell::default()); @@ -1239,18 +1239,23 @@ impl InMemoryNode { } } - if inner.config.show_calls != ShowCalls::None { - tracing::info!(""); - tracing::info!("=== Call traces:"); - for call in &call_traces { - formatter::print_call( - call, - 0, - &inner.config.show_calls, - inner.config.show_outputs, - inner.config.resolve_hashes, - ); - } + tracing::info!( + "[Transaction Execution] ({} calls)", + call_traces[0].calls.len() + ); + let num_calls = call_traces.len(); + for (i, call) in call_traces.iter().enumerate() { + let is_last_sibling = i == num_calls - 1; + formatter::print_call( + tx.initiator_account(), + tx.execute.contract_address, + call, + &vec![], + is_last_sibling, + &inner.config.show_calls, + inner.config.show_outputs, + inner.config.resolve_hashes, + ); } Ok(tx_result.result) @@ -1515,38 +1520,31 @@ impl InMemoryNode { let spent_on_pubdata = tx_result.statistics.gas_used - tx_result.statistics.computational_gas_used as u64; + let status = match &tx_result.result { + ExecutionResult::Success { .. } => "SUCCESS", + ExecutionResult::Revert { .. } => "FAILED", + ExecutionResult::Halt { .. } => "HALTED", + }; if inner.config.show_tx_summary { - tracing::info!("┌─────────────────────────┐"); - tracing::info!("│ TRANSACTION SUMMARY │"); - tracing::info!("└─────────────────────────┘"); - - match &tx_result.result { - ExecutionResult::Success { .. } => { - tracing::info!("Transaction: {}", "SUCCESS".green()) - } - ExecutionResult::Revert { .. } => tracing::info!("Transaction: {}", "FAILED".red()), - ExecutionResult::Halt { .. } => tracing::info!("Transaction: {}", "HALTED".red()), - } - - tracing::info!("Initiator: {:?}", tx.initiator_account()); - tracing::info!("Payer: {:?}", tx.payer()); - tracing::info!( - "Gas - Limit: {} | Used: {} | Refunded: {}", - to_human_size(tx.gas_limit()), - to_human_size(tx.gas_limit() - tx_result.refunds.gas_refunded), - to_human_size(tx_result.refunds.gas_refunded.into()) + formatter::log_transaction_summary( + inner.config.get_l2_gas_price(), + &tx, + &tx_result, + status, ); } - - if inner.config.show_gas_details != ShowGasDetails::None { - let info = - self.display_detailed_gas_info(bootloader_debug_result.get(), spent_on_pubdata); - if info.is_err() { - tracing::info!( - "{}\nError: {}", - "!!! FAILED TO GET DETAILED GAS INFO !!!".to_owned().red(), - info.unwrap_err() - ); + match inner.config.show_gas_details { + ShowGasDetails::None => {} + ShowGasDetails::All => { + let info = + self.display_detailed_gas_info(bootloader_debug_result.get(), spent_on_pubdata); + if info.is_err() { + tracing::info!( + "{}\nError: {}", + "!!! FAILED TO GET DETAILED GAS INFO !!!".to_owned().red(), + info.unwrap_err() + ); + } } } @@ -1566,15 +1564,19 @@ impl InMemoryNode { inner.console_log_handler.handle_call_recursive(call); } } - println!(""); - println!(""); + tracing::info!(""); + if inner.config.show_calls != ShowCalls::None { - tracing::info!("[Transaction Execution]"); + tracing::info!( + "[Transaction Execution] ({} calls)", + call_traces[0].calls.len() + ); let num_calls = call_traces.len(); for (i, call) in call_traces.iter().enumerate() { let is_last_sibling = i == num_calls - 1; - formatter::print_call2( + formatter::print_call( tx.initiator_account(), + tx.execute.contract_address, call, &vec![], is_last_sibling, @@ -1584,7 +1586,7 @@ impl InMemoryNode { ); } } - println!(""); + tracing::info!(""); if inner.config.show_event_logs { tracing::info!(""); tracing::info!( diff --git a/src/utils.rs b/src/utils.rs index 06725520..419288ab 100644 --- a/src/utils.rs +++ b/src/utils.rs @@ -322,6 +322,20 @@ impl TryFrom for u64 { } } +// Returns the cost of the transaction in ETH +pub fn calculate_eth_cost(gas_price_in_wei_per_gas: u64, gas_used: u64) -> f64 { + // Convert gas price from wei to gwei + let gas_price_in_gwei = gas_price_in_wei_per_gas as f64 / 1e9; + + // Calculate total cost in gwei + let total_cost_in_gwei = gas_price_in_gwei * gas_used as f64; + + // Convert total cost from gwei to ETH + let total_cost_in_eth = total_cost_in_gwei / 1e9; + + total_cost_in_eth +} + #[cfg(test)] mod tests { use zksync_types::U256; From 50f36b7b70418c39353162fcb481d07b44ed4697 Mon Sep 17 00:00:00 2001 From: Dustin Brickwood Date: Thu, 21 Nov 2024 14:53:01 -0600 Subject: [PATCH 03/16] chore: clean up --- src/formatter.rs | 14 ++++++++------ src/node/in_memory.rs | 2 +- src/utils.rs | 6 ++---- 3 files changed, 11 insertions(+), 11 deletions(-) diff --git a/src/formatter.rs b/src/formatter.rs index 0b7842ce..d7bd268d 100644 --- a/src/formatter.rs +++ b/src/formatter.rs @@ -43,7 +43,8 @@ lazy_static! { .collect() }; } - +// TODO: When refactoring other logs (e.g event, storage, vm, gas) update this function. +// Currently a close duplicate of format_address_human_readable fn address_to_human_readable(address: H160) -> Option { KNOWN_ADDRESSES .get(&address) @@ -55,7 +56,7 @@ fn address_to_human_readable(address: H160) -> Option { }) } -fn address_to_human_readable2( +fn format_address_human_readable( address: H160, initiator: H160, contract_address: Option, @@ -214,6 +215,7 @@ fn build_prefix(sibling_stack: &Vec) -> String { prefix } +#[allow(clippy::too_many_arguments)] pub fn print_call( initiator: Address, contract_address: Option, @@ -254,13 +256,13 @@ pub fn print_call( let gas_used_display = format!("({})", to_human_size(call.gas_used.into())).bold(); // Get contract display - let contract_display = address_to_human_readable2( + let contract_display = format_address_human_readable( call.to, initiator, contract_address, format!("{:?}", call.r#type).as_str(), ) - .map(|x| format!("{:}", x)) + .map(|x| x.to_string()) .unwrap_or(format!("{:}", format!("{:?}", call.to).bold())); // Get function signature @@ -350,7 +352,7 @@ pub fn print_call( } } -pub fn log_transaction_summary( +pub fn print_transaction_summary( l2_gas_price: u64, tx: &Transaction, tx_result: &VmExecutionResultAndLogs, @@ -378,7 +380,7 @@ pub fn log_transaction_summary( tracing::info!( "Gas Usage: Limit: {} | Used: {} | Refunded: {}", to_human_size(tx.gas_limit()), - to_human_size(used_gas.into()), + to_human_size(used_gas), to_human_size(tx_result.refunds.gas_refunded.into()) ); tracing::info!( diff --git a/src/node/in_memory.rs b/src/node/in_memory.rs index 237bb638..36b468a6 100644 --- a/src/node/in_memory.rs +++ b/src/node/in_memory.rs @@ -1526,7 +1526,7 @@ impl InMemoryNode { ExecutionResult::Halt { .. } => "HALTED", }; if inner.config.show_tx_summary { - formatter::log_transaction_summary( + formatter::print_transaction_summary( inner.config.get_l2_gas_price(), &tx, &tx_result, diff --git a/src/utils.rs b/src/utils.rs index 419288ab..8ff0032b 100644 --- a/src/utils.rs +++ b/src/utils.rs @@ -322,7 +322,7 @@ impl TryFrom for u64 { } } -// Returns the cost of the transaction in ETH +/// Calculates the cost of a transaction in ETH. pub fn calculate_eth_cost(gas_price_in_wei_per_gas: u64, gas_used: u64) -> f64 { // Convert gas price from wei to gwei let gas_price_in_gwei = gas_price_in_wei_per_gas as f64 / 1e9; @@ -331,9 +331,7 @@ pub fn calculate_eth_cost(gas_price_in_wei_per_gas: u64, gas_used: u64) -> f64 { let total_cost_in_gwei = gas_price_in_gwei * gas_used as f64; // Convert total cost from gwei to ETH - let total_cost_in_eth = total_cost_in_gwei / 1e9; - - total_cost_in_eth + total_cost_in_gwei / 1e9 } #[cfg(test)] From cceca2e576ecb5cd802bafd74c6ac4a7bd0525ed Mon Sep 17 00:00:00 2001 From: Dustin Brickwood Date: Thu, 21 Nov 2024 16:39:59 -0600 Subject: [PATCH 04/16] chore: wip for gas details --- src/formatter.rs | 180 ++++++++++++++++++++++++++------------- src/node/in_memory.rs | 158 ++++++++++++++++++++++++++++++++-- src/node/storage_logs.rs | 54 +++++------- 3 files changed, 291 insertions(+), 101 deletions(-) diff --git a/src/formatter.rs b/src/formatter.rs index d7bd268d..92d47719 100644 --- a/src/formatter.rs +++ b/src/formatter.rs @@ -46,14 +46,17 @@ lazy_static! { // TODO: When refactoring other logs (e.g event, storage, vm, gas) update this function. // Currently a close duplicate of format_address_human_readable fn address_to_human_readable(address: H160) -> Option { - KNOWN_ADDRESSES - .get(&address) - .map(|known_address| match known_address.contract_type { - ContractType::System => known_address.name.to_string(), - ContractType::Precompile => format!("{}", known_address.name.dimmed()), - ContractType::Popular => format!("{}", known_address.name.green()), - ContractType::Unknown => known_address.name.to_string(), - }) + KNOWN_ADDRESSES.get(&address).map(|known_address| { + let name = match known_address.contract_type { + ContractType::System => known_address.name.bold().bright_blue().to_string(), + ContractType::Precompile => known_address.name.bold().magenta().to_string(), + ContractType::Popular => known_address.name.bold().bright_green().to_string(), + ContractType::Unknown => known_address.name.dimmed().to_string(), + }; + + let formatted_address = format!("{:#x}", address).dimmed(); + format!("{}{}{}", name, "@".dimmed(), formatted_address) + }) } fn format_address_human_readable( @@ -98,49 +101,55 @@ fn format_address_human_readable( }) } -/// Pretty-prints event object -/// if skip_resolve is false, will try to contact openchain to resolve the topic hashes. +/// Pretty-prints event object using the new structured log format. +/// If `resolve_hashes` is true, attempts to resolve topic hashes. pub fn print_event(event: &VmEvent, resolve_hashes: bool) { let event = event.clone(); block_on(async move { - let mut tt: Vec = vec![]; - if !resolve_hashes { - tt = event - .indexed_topics - .iter() - .map(|t| format!("{:#x}", t)) - .collect(); - } else { - for topic in event.indexed_topics { - let selector = resolver::decode_event_selector(&format!("{:#x}", topic)) + let mut topics: Vec = vec![]; + + // Resolve or fallback to raw hex topics + for topic in event.indexed_topics.iter() { + let resolved = if resolve_hashes { + resolver::decode_event_selector(&format!("{:#x}", topic)) .await - .unwrap(); - tt.push(selector.unwrap_or(format!("{:#x}", topic))); - } + .unwrap_or(None) + } else { + None + }; + + topics.push(resolved.unwrap_or_else(|| format!("{:#x}", topic))); } - // TODO: fix - tracing::info!( - "{}", - address_to_human_readable(event.address) - .map(|x| format!("{:42}", x.blue())) - .unwrap_or(format!("{:42}", format!("{:?}", event.address).blue())) - ); - tracing::info!("{}", " Topics:".truecolor(128, 128, 128)); - for indexed_topic in &tt { - tracing::info!(" {}", indexed_topic); + // Event address (contract) + let contract_display = address_to_human_readable(event.address) + .map(|x| format!("{:42}", x.blue())) + .unwrap_or(format!("{:42}", format!("{:?}", event.address).blue())); + + tracing::info!(" ├─ Event [{}]", contract_display); + + // Topics + if topics.is_empty() { + tracing::info!(" │ └─ Topics: EMPTY"); + } else { + tracing::info!(" │ ├─ Topics:"); + for (i, topic) in topics.iter().enumerate() { + let prefix = if i + 1 == topics.len() { + "└─" + } else { + "├─" + }; + tracing::info!(" │ │ {} Topic[{}]: {}", prefix, i, topic); + } } + // Data if event.value.is_empty() { - tracing::info!("{}", " Data: EMPTY".truecolor(128, 128, 128)); + tracing::info!(" │ └─ Data: EMPTY"); } else { match str::from_utf8(&event.value) { Ok(v) => { - tracing::info!( - "{} {}", - " Data (String):".truecolor(128, 128, 128), - v.to_string() - ); + tracing::info!(" │ └─ Data (String): {}", v.truecolor(128, 128, 128)); } Err(_) => { let hex_str = hex::encode(&event.value); @@ -151,12 +160,11 @@ pub fn print_event(event: &VmEvent, resolve_hashes: bool) { }; tracing::info!( - "{} 0x{}", - " Data (Hex):".truecolor(128, 128, 128), - display_str + " │ └─ Data (Hex): 0x{}", + display_str.truecolor(128, 128, 128) ); } - }; + } } tracing::info!(""); @@ -169,7 +177,7 @@ pub enum PubdataBytesInfo { FreeSlot, // This slot costs this much. Paid(u32), - // This happens when we already paid a litte for this slot in the past. + // This happens when we already paid a little for this slot in the past. // This slots costs additional X, the total cost is Y. AdditionalPayment(u32, u32), // We already paid for this slot in this transaction. @@ -179,14 +187,17 @@ pub enum PubdataBytesInfo { impl std::fmt::Display for PubdataBytesInfo { fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { match self { - PubdataBytesInfo::FreeSlot => write!(f, "free slot"), - PubdataBytesInfo::Paid(cost) => write!(f, "{:?} bytes", cost), + PubdataBytesInfo::FreeSlot => write!(f, "Free Slot (no cost)"), + PubdataBytesInfo::Paid(cost) => { + write!(f, "Paid: {} bytes", to_human_size((*cost).into())) + } PubdataBytesInfo::AdditionalPayment(additional_cost, total_cost) => write!( f, - "{:?} addditional bytes, {:?} total cost", - additional_cost, total_cost + "Additional Payment: {} bytes (Total: {} bytes)", + to_human_size((*additional_cost).into()), + to_human_size((*total_cost).into()) ), - PubdataBytesInfo::PaidAlready => write!(f, "already paid"), + PubdataBytesInfo::PaidAlready => write!(f, "Already Paid (no additional cost)"), } } } @@ -392,30 +403,77 @@ pub fn print_transaction_summary( tracing::info!("Refunded: {:.10} ETH", refunded_in_eth); } -// TODO address to human readable issue pub fn print_logs( log_query: &StorageLogWithPreviousValue, pubdata_bytes: Option, + log_index: usize, + is_last: bool, ) { - let separator = "─".repeat(82); - tracing::info!("{:<15} {:?}", "Kind:", log_query.log.kind); + let prefix = if is_last { "└─" } else { "├─" }; + tracing::info!(" {} Log #{}", prefix, log_index); + tracing::info!(" │ ├─ Kind: {:?}", log_query.log.kind); tracing::info!( - "{:<15} {}", - "Address:", + " │ ├─ Address: {}", address_to_human_readable(*log_query.log.key.address()) - .unwrap_or(format!("{}", log_query.log.key.address())) + .unwrap_or_else(|| format!("{}", log_query.log.key.address())) + ); + tracing::info!( + " │ ├─ Key: {:#066x}", + log_query.log.key.key() + ); + tracing::info!( + " │ ├─ Read Value: {:#066x}", + log_query.previous_value ); - tracing::info!("{:<15} {:#066x}", "Key:", log_query.log.key.key()); - - tracing::info!("{:<15} {:#066x}", "Read Value:", log_query.previous_value,); if log_query.log.is_write() { - tracing::info!("{:<15} {:#066x}", "Written Value:", log_query.log.value); + tracing::info!(" │ ├─ Written Value: {:#066x}", log_query.log.value); } + if let Some(pubdata_bytes) = pubdata_bytes { - tracing::info!("{:<15} {:}", "Pubdata bytes:", pubdata_bytes); + tracing::info!(" │ └─ Pubdata Bytes: {}", pubdata_bytes); + } else { + tracing::info!(" │ └─ Pubdata Bytes: None"); + } +} + +pub fn print_vm_details2(result: &VmExecutionResultAndLogs) { + tracing::info!(""); + tracing::info!("[VM Execution Results]"); + + // Log the main statistics + tracing::info!( + " ├─ Cycles Used: {}", + to_human_size(result.statistics.cycles_used.into()) + ); + tracing::info!( + " ├─ Computation Gas Used: {}", + to_human_size(result.statistics.computational_gas_used.into()) + ); + tracing::info!( + " ├─ Contracts Used: {}", + to_human_size(result.statistics.contracts_used.into()) + ); + + // Log execution outcome + match &result.result { + zksync_multivm::interface::ExecutionResult::Success { .. } => { + tracing::info!(" └─ Execution Outcome: Success"); + } + zksync_multivm::interface::ExecutionResult::Revert { output } => { + tracing::info!(" ├─ Execution Outcome: Failure"); + tracing::info!( + " │ └─ Revert Reason: {}", + output.to_user_friendly_string().red() + ); + } + zksync_multivm::interface::ExecutionResult::Halt { reason } => { + tracing::info!(" ├─ Execution Outcome: Failure"); + tracing::info!(" │ └─ Halt Reason: {}", reason.to_string().red()); + } } - tracing::info!("{}", separator); + + tracing::info!(""); } pub fn print_vm_details(result: &VmExecutionResultAndLogs) { diff --git a/src/node/in_memory.rs b/src/node/in_memory.rs index 36b468a6..35037893 100644 --- a/src/node/in_memory.rs +++ b/src/node/in_memory.rs @@ -1261,6 +1261,152 @@ impl InMemoryNode { Ok(tx_result.result) } + fn display_detailed_gas_info2( + &self, + bootloader_debug_result: Option<&eyre::Result>, + spent_on_pubdata: u64, + ) -> eyre::Result<(), String> { + if let Some(bootloader_result) = bootloader_debug_result { + let bootloader_debug = bootloader_result.clone()?; + + tracing::info!(""); + tracing::info!("[Gas Details]"); + + // Gas Summary + let total_gas_limit = bootloader_debug + .total_gas_limit_from_user + .saturating_sub(bootloader_debug.reserved_gas); + let intrinsic_gas = total_gas_limit - bootloader_debug.gas_limit_after_intrinsic; + let gas_for_validation = + bootloader_debug.gas_limit_after_intrinsic - bootloader_debug.gas_after_validation; + let gas_spent_on_compute = bootloader_debug.gas_spent_on_execution + - bootloader_debug.gas_spent_on_bytecode_preparation; + let gas_used = intrinsic_gas + + gas_for_validation + + bootloader_debug.gas_spent_on_bytecode_preparation + + gas_spent_on_compute; + + tracing::info!(" ├─ Gas Summary"); + tracing::info!( + " │ ├─ Limit: {}", + to_human_size(total_gas_limit) + ); + tracing::info!(" │ ├─ Used: {}", to_human_size(gas_used)); + tracing::info!( + " │ └─ Refunded: {}", + to_human_size(bootloader_debug.refund_by_operator) + ); + + if bootloader_debug.refund_computed != bootloader_debug.refund_by_operator { + tracing::warn!( + " │ WARNING: Refund by VM: {}, but operator refunded more: {}", + to_human_size(bootloader_debug.refund_computed), + to_human_size(bootloader_debug.refund_by_operator) + ); + } + + if bootloader_debug.total_gas_limit_from_user != total_gas_limit { + tracing::info!( + " │ WARNING: User provided more gas ({}), but system had a lower max limit.", + to_human_size(bootloader_debug.total_gas_limit_from_user) + ); + } + + // Execution Gas Breakdown + tracing::info!(" ├─ Execution Gas Breakdown"); + tracing::info!( + " │ ├─ Transaction Setup: {} gas ({:>2}%)", + to_human_size(intrinsic_gas), + intrinsic_gas * 100 / gas_used + ); + tracing::info!( + " │ ├─ Bytecode Preparation: {} gas ({:>2}%)", + to_human_size(bootloader_debug.gas_spent_on_bytecode_preparation), + bootloader_debug.gas_spent_on_bytecode_preparation * 100 / gas_used + ); + tracing::info!( + " │ ├─ Account Validation: {} gas ({:>2}%)", + to_human_size(gas_for_validation), + gas_for_validation * 100 / gas_used + ); + tracing::info!( + " │ └─ Computations (Opcodes): {} gas ({:>2}%)", + to_human_size(gas_spent_on_compute), + gas_spent_on_compute * 100 / gas_used + ); + + // Transaction Setup Cost Breakdown + tracing::info!(" ├─ Transaction Setup Cost Breakdown"); + tracing::info!( + " │ ├─ Total Setup Cost: {} gas", + to_human_size(intrinsic_gas) + ); + tracing::info!( + " │ ├─ Fixed Cost: {} gas ({:>2}%)", + to_human_size(bootloader_debug.intrinsic_overhead), + bootloader_debug.intrinsic_overhead * 100 / intrinsic_gas + ); + tracing::info!( + " │ └─ Operator Cost: {} gas ({:>2}%)", + to_human_size(bootloader_debug.operator_overhead), + bootloader_debug.operator_overhead * 100 / intrinsic_gas + ); + + if bootloader_debug.required_overhead != U256::zero() { + tracing::info!( + " │ FYI: Operator could have charged up to {}, so you got a {}% discount.", + to_human_size(bootloader_debug.required_overhead), + (bootloader_debug.required_overhead - bootloader_debug.operator_overhead) * 100 + / bootloader_debug.required_overhead + ); + } + + // L1 Publishing Costs + let bytes_published = spent_on_pubdata / bootloader_debug.gas_per_pubdata.as_u64(); + tracing::info!(" ├─ L1 Publishing Costs"); + tracing::info!( + " │ ├─ Published: {} bytes", + to_human_size(bytes_published.into()) + ); + tracing::info!( + " │ ├─ Cost per Byte: {} gas", + to_human_size(bootloader_debug.gas_per_pubdata) + ); + tracing::info!( + " │ └─ Total Gas Cost: {} gas", + to_human_size(spent_on_pubdata.into()) + ); + + // Block Contribution + tracing::info!(" └─ Block Contribution"); + tracing::info!( + " ├─ Length Overhead: {} gas", + to_human_size(bootloader_debug.overhead_for_length) + ); + tracing::info!( + " ├─ Slot Overhead: {} gas", + to_human_size(bootloader_debug.overhead_for_slot) + ); + tracing::info!( + " └─ Full Block Cost: ~{} L2 gas", + to_human_size( + bootloader_debug.gas_per_pubdata + * self + .inner + .read() + .unwrap() + .fee_input_provider + .get_fee_model_config() + .batch_overhead_l1_gas + ) + ); + + Ok(()) + } else { + Err("Bootloader tracer didn't finish.".to_owned()) + } + } + fn display_detailed_gas_info( &self, bootloader_debug_result: Option<&eyre::Result>, @@ -1536,8 +1682,8 @@ impl InMemoryNode { match inner.config.show_gas_details { ShowGasDetails::None => {} ShowGasDetails::All => { - let info = - self.display_detailed_gas_info(bootloader_debug_result.get(), spent_on_pubdata); + let info = self + .display_detailed_gas_info2(bootloader_debug_result.get(), spent_on_pubdata); if info.is_err() { tracing::info!( "{}\nError: {}", @@ -1553,7 +1699,7 @@ impl InMemoryNode { } if inner.config.show_vm_details != ShowVMDetails::None { - formatter::print_vm_details(&tx_result); + formatter::print_vm_details2(&tx_result); } if !inner.config.disable_console_log { @@ -1588,11 +1734,7 @@ impl InMemoryNode { } tracing::info!(""); if inner.config.show_event_logs { - tracing::info!(""); - tracing::info!( - "==== {}", - format!("{} events", tx_result.logs.events.len()).bold() - ); + tracing::info!(" [Events] ({} events)", tx_result.logs.events.len()); for event in &tx_result.logs.events { formatter::print_event(event, inner.config.resolve_hashes); } diff --git a/src/node/storage_logs.rs b/src/node/storage_logs.rs index ddf3aed4..268e73ae 100644 --- a/src/node/storage_logs.rs +++ b/src/node/storage_logs.rs @@ -63,13 +63,14 @@ pub fn print_storage_logs_details( result: &VmExecutionResultAndLogs, ) { tracing::info!(""); - tracing::info!("┌──────────────────┐"); - tracing::info!("│ STORAGE LOGS │"); - tracing::info!("└──────────────────┘"); + tracing::info!( + "[Storage Logs] ({} entries)", + result.logs.storage_logs.len() + ); let mut cost_paid = HashMap::::default(); - for log_query in &result.logs.storage_logs { + for (index, log_query) in result.logs.storage_logs.iter().enumerate() { let pubdata_bytes_info = if matches!( log_query.log.kind, StorageLogKind::RepeatedWrite | StorageLogKind::InitialWrite @@ -79,35 +80,24 @@ pub fn print_storage_logs_details( None }; - match show_storage_logs { - ShowStorageLogs::Write => { - if matches!( - log_query.log.kind, - StorageLogKind::RepeatedWrite | StorageLogKind::InitialWrite - ) { - formatter::print_logs(log_query, pubdata_bytes_info); - } - } - ShowStorageLogs::Paid => { - // Show only the logs that incur any cost. - if pubdata_bytes_info - .as_ref() - .map(|x| x.does_cost()) - .unwrap_or_default() - { - formatter::print_logs(log_query, pubdata_bytes_info); - } - } - ShowStorageLogs::Read => { - if log_query.log.kind == StorageLogKind::Read { - formatter::print_logs(log_query, pubdata_bytes_info); - } - } - ShowStorageLogs::All => { - formatter::print_logs(log_query, pubdata_bytes_info); - } + // Filter logs based on the selected storage log type + let should_print = match show_storage_logs { + ShowStorageLogs::Write => matches!( + log_query.log.kind, + StorageLogKind::RepeatedWrite | StorageLogKind::InitialWrite + ), + ShowStorageLogs::Paid => pubdata_bytes_info + .as_ref() + .map(|x| x.does_cost()) + .unwrap_or_default(), + ShowStorageLogs::Read => log_query.log.kind == StorageLogKind::Read, + ShowStorageLogs::All => true, + _ => false, + }; - _ => {} + if should_print { + let is_last = index == result.logs.storage_logs.len() - 1; + formatter::print_logs(log_query, pubdata_bytes_info, index + 1, is_last); } } } From f329618b77ed4d1c1c96df31e78158d1aff27007 Mon Sep 17 00:00:00 2001 From: Dustin Brickwood Date: Thu, 21 Nov 2024 21:58:51 -0600 Subject: [PATCH 05/16] wip: broken but uses builder --- src/formatter.rs | 452 ++++++++++++++++++++-------------- src/formatter2.rs | 511 +++++++++++++++++++++++++++++++++++++++ src/node/in_memory.rs | 250 ++++++++++++++++++- src/node/storage_logs.rs | 8 +- 4 files changed, 1038 insertions(+), 183 deletions(-) create mode 100644 src/formatter2.rs diff --git a/src/formatter.rs b/src/formatter.rs index 92d47719..11a36bbc 100644 --- a/src/formatter.rs +++ b/src/formatter.rs @@ -8,13 +8,13 @@ use std::collections::HashMap; use std::str; use crate::fork::block_on; -use zksync_types::H160; - use crate::utils::{calculate_eth_cost, format_gwei, to_human_size}; +use futures::future::join_all; use lazy_static::lazy_static; use zksync_multivm::interface::{Call, VmEvent, VmExecutionResultAndLogs}; use zksync_types::Address; use zksync_types::{StorageLogWithPreviousValue, Transaction}; +use zksync_types::{H160, H256}; #[derive(Debug, Deserialize, Clone, PartialEq, Eq)] pub enum ContractType { @@ -43,6 +43,93 @@ lazy_static! { .collect() }; } + +pub struct Formatter { + sibling_stack: Vec, +} + +impl Formatter { + pub fn new() -> Self { + Formatter { + sibling_stack: Vec::new(), + } + } + + pub fn with_initial_stack(sibling_stack: Vec) -> Self { + Formatter { sibling_stack } + } + + pub fn section(&mut self, title: &str, has_more_siblings: bool, f: F) + where + F: FnOnce(&mut Self), + { + self.format_log(false, title); + self.enter_scope(has_more_siblings); + f(self); + self.exit_scope(); + } + + pub fn subsection(&mut self, title: &str, has_more_siblings: bool, f: F) + where + F: FnOnce(&mut Self), + { + self.format_log(false, title); + self.enter_scope(has_more_siblings); + f(self); + self.exit_scope(); + } + + pub fn item(&mut self, is_last_sibling: bool, key: &str, value: &str) { + self.format_log( + is_last_sibling, + &format!("{}: {}", key.bold(), value.dimmed()), + ); + } + + pub fn warning(&mut self, is_last_sibling: bool, message: &str) { + self.format_error(is_last_sibling, &format!("WARNING: {}", message)); + } + + pub fn enter_scope(&mut self, has_more_siblings: bool) { + self.sibling_stack.push(has_more_siblings); + } + + pub fn exit_scope(&mut self) { + self.sibling_stack.pop(); + } + + pub fn format_log(&self, is_last_sibling: bool, message: &str) { + let prefix = build_prefix(&self.sibling_stack, is_last_sibling); + tracing::info!("{}{}", prefix, message); + } + + pub fn format_error(&self, is_last_sibling: bool, message: &str) { + let prefix = build_prefix(&self.sibling_stack, is_last_sibling); + tracing::info!("{}", format!("{}{}", prefix, message).red()); + } +} + +fn build_prefix(sibling_stack: &[bool], is_last_sibling: bool) -> String { + let mut prefix = String::new(); + let depth = sibling_stack.len(); + if depth > 0 { + for &has_more_siblings in &sibling_stack[..depth - 1] { + if has_more_siblings { + prefix.push_str("│ "); + } else { + prefix.push_str(" "); + } + } + let branch = if is_last_sibling { + "└─ " + } else { + "├─ " + }; + prefix.push_str(branch); + } + prefix +} + // TODO: When refactoring other logs (e.g event, storage, vm, gas) update this function. // Currently a close duplicate of format_address_human_readable fn address_to_human_readable(address: H160) -> Option { @@ -101,74 +188,85 @@ fn format_address_human_readable( }) } -/// Pretty-prints event object using the new structured log format. -/// If `resolve_hashes` is true, attempts to resolve topic hashes. -pub fn print_event(event: &VmEvent, resolve_hashes: bool) { - let event = event.clone(); +fn resolve_topics(topics: &[H256], resolve_hashes: bool) -> Vec { + let topics = topics.to_owned(); block_on(async move { - let mut topics: Vec = vec![]; - - // Resolve or fallback to raw hex topics - for topic in event.indexed_topics.iter() { - let resolved = if resolve_hashes { + let futures = topics.into_iter().map(|topic| async move { + if resolve_hashes { resolver::decode_event_selector(&format!("{:#x}", topic)) .await .unwrap_or(None) + .unwrap_or_else(|| format!("{:#x}", topic)) } else { - None - }; + format!("{:#x}", topic) + } + }); - topics.push(resolved.unwrap_or_else(|| format!("{:#x}", topic))); - } + join_all(futures).await + }) +} - // Event address (contract) - let contract_display = address_to_human_readable(event.address) - .map(|x| format!("{:42}", x.blue())) - .unwrap_or(format!("{:42}", format!("{:?}", event.address).blue())); +pub fn print_event(event: &VmEvent, resolve_hashes: bool, is_last_sibling: bool) { + // Clone the event to avoid borrowing issues + let event = event.clone(); + let mut formatter = Formatter::new(); + + // Resolve topics before logging + let topics = resolve_topics(&event.indexed_topics, resolve_hashes); + + // Format the event address (contract) + let contract_display = address_to_human_readable(event.address) + .map(|x| format!("{:42}", x.blue())) + .unwrap_or_else(|| format!("{:42}", format!("{:?}", event.address).blue())); + + // Start the event section + formatter.section( + &format!("Event [{}]", contract_display), + !is_last_sibling, + |event_section| { + // We'll always have two subitems: Topics and Data + let total_subitems = 2; + let mut subitem_idx = 0; + + // Topics Section + subitem_idx += 1; + let is_last_subitem = subitem_idx == total_subitems; + + event_section.section("Topics", !is_last_subitem, |topics_section| { + let num_topics = topics.len(); + if num_topics == 0 { + topics_section.item(true, "Topics", "EMPTY"); + } else { + for (i, topic) in topics.iter().enumerate() { + let is_last_topic = i == num_topics - 1; + topics_section.item(is_last_topic, &format!("Topic[{}]", i), topic); + } + } + }); - tracing::info!(" ├─ Event [{}]", contract_display); + // Data Section + subitem_idx += 1; + let is_last_subitem = subitem_idx == total_subitems; - // Topics - if topics.is_empty() { - tracing::info!(" │ └─ Topics: EMPTY"); - } else { - tracing::info!(" │ ├─ Topics:"); - for (i, topic) in topics.iter().enumerate() { - let prefix = if i + 1 == topics.len() { - "└─" - } else { - "├─" + if event.value.is_empty() { + event_section.item(is_last_subitem, "Data", "EMPTY"); + } else { + let data_str = match str::from_utf8(&event.value) { + Ok(v) => format!("{}", v.truecolor(128, 128, 128)), + Err(_) => { + let hex_str = hex::encode(&event.value); + let display_str = if hex_str.len() > 200 { + format!("{}...", &hex_str[..200]) + } else { + hex_str + }; + format!("0x{}", display_str.truecolor(128, 128, 128)) + } }; - tracing::info!(" │ │ {} Topic[{}]: {}", prefix, i, topic); + event_section.item(is_last_subitem, "Data", &data_str); } - } - - // Data - if event.value.is_empty() { - tracing::info!(" │ └─ Data: EMPTY"); - } else { - match str::from_utf8(&event.value) { - Ok(v) => { - tracing::info!(" │ └─ Data (String): {}", v.truecolor(128, 128, 128)); - } - Err(_) => { - let hex_str = hex::encode(&event.value); - let display_str = if hex_str.len() > 200 { - format!("{}...", &hex_str[..200]) - } else { - hex_str.to_string() - }; - - tracing::info!( - " │ └─ Data (Hex): 0x{}", - display_str.truecolor(128, 128, 128) - ); - } - } - } - - tracing::info!(""); - }); + }, + ); } /// Amount of pubdata that given write has cost. @@ -214,24 +312,11 @@ impl PubdataBytesInfo { } } -fn build_prefix(sibling_stack: &Vec) -> String { - let mut prefix = String::new(); - for &has_more_siblings in sibling_stack { - if has_more_siblings { - prefix.push_str("│ "); - } else { - prefix.push_str(" "); - } - } - prefix -} - -#[allow(clippy::too_many_arguments)] pub fn print_call( initiator: Address, contract_address: Option, call: &Call, - sibling_stack: &Vec, + formatter: &mut Formatter, is_last_sibling: bool, show_calls: &ShowCalls, show_outputs: bool, @@ -254,14 +339,6 @@ pub fn print_call( }; if should_print { - let prefix = build_prefix(sibling_stack); - let branch = if is_last_sibling { - "└─ " - } else { - "├─ " - }; - let full_prefix = format!("{}{}", prefix, branch); - let call_type_display = format!("{:?}", call.r#type).blue(); let remaining_gas_display = to_human_size(call.gas.into()).yellow(); let gas_used_display = format!("({})", to_human_size(call.gas_used.into())).bold(); @@ -273,8 +350,7 @@ pub fn print_call( contract_address, format!("{:?}", call.r#type).as_str(), ) - .map(|x| x.to_string()) - .unwrap_or(format!("{:}", format!("{:?}", call.to).bold())); + .unwrap_or_else(|| format!("{:}", format!("{:?}", call.to).bold())); // Get function signature let function_signature = if call.input.len() >= 4 { @@ -297,8 +373,7 @@ pub fn print_call( // Build the line let line = format!( - "{}{} [{}] {}::{} {}", - full_prefix, + "{} [{}] {}::{} {}", call_type_display, remaining_gas_display, contract_display, @@ -308,17 +383,19 @@ pub fn print_call( // Handle errors if call.revert_reason.is_some() || call.error.is_some() { - tracing::info!("{}", line.red()); + formatter.format_error(is_last_sibling, &line); if let Some(ref reason) = call.revert_reason { - let error_line = format!("{} └─ 🔴 Revert reason: {}", prefix, reason); - tracing::info!("{}", error_line.red()); + formatter.enter_scope(!is_last_sibling); + formatter.format_error(true, &format!("🔴 Revert reason: {}", reason)); + formatter.exit_scope(); } if let Some(ref error) = call.error { - let error_line = format!("{} └─ 🔴 Error: {}", prefix, error); - tracing::info!("{}", error_line.red()); + formatter.enter_scope(!is_last_sibling); + formatter.format_error(true, &format!("🔴 Error: {}", error)); + formatter.exit_scope(); } } else { - tracing::info!("{}", line); + formatter.format_log(is_last_sibling, &line); } // Handle outputs @@ -331,152 +408,173 @@ pub fn print_call( .collect::>() .join(""); - let output_branch = if is_last_sibling { - " └── Output: ".dimmed() - } else { - " ├── Output: ".dimmed() - }; - - let output_line = format!("{}{}", full_prefix, output_branch) + &output_display; - tracing::info!("{}", output_line); + formatter.enter_scope(!is_last_sibling); + formatter.format_log(true, &format!("Output: {}", output_display.dimmed())); + formatter.exit_scope(); } } // Process subcalls - let num_subcalls = call.calls.len(); - if num_subcalls > 0 { - let mut new_sibling_stack = sibling_stack.clone(); - new_sibling_stack.push(!is_last_sibling); + if !call.calls.is_empty() { + formatter.enter_scope(!is_last_sibling); + + let num_subcalls = call.calls.len(); for (i, subcall) in call.calls.iter().enumerate() { let is_last_subcall = i == num_subcalls - 1; print_call( initiator, contract_address, subcall, - &new_sibling_stack, + formatter, is_last_subcall, show_calls, show_outputs, resolve_hashes, ); } - } -} -pub fn print_transaction_summary( - l2_gas_price: u64, - tx: &Transaction, - tx_result: &VmExecutionResultAndLogs, - status: &str, -) { - // Calculate used and refunded gas - let used_gas = tx.gas_limit() - tx_result.refunds.gas_refunded; - let paid_in_eth = calculate_eth_cost(l2_gas_price, used_gas.as_u64()); - - let refunded_gas = tx_result.refunds.gas_refunded; - - // Calculate refunded gas in ETH - let refunded_in_eth = calculate_eth_cost(l2_gas_price, refunded_gas); - - let emoji = match status { - "SUCCESS" => "✅", - "FAILED" => "❌", - "HALTED" => "⏸️", - _ => "⚠️", - }; - - tracing::info!("{} [{}] Hash: {:?}", emoji, status, tx.hash()); - tracing::info!("Initiator: {:?}", tx.initiator_account()); - tracing::info!("Payer: {:?}", tx.payer()); - tracing::info!( - "Gas Usage: Limit: {} | Used: {} | Refunded: {}", - to_human_size(tx.gas_limit()), - to_human_size(used_gas), - to_human_size(tx_result.refunds.gas_refunded.into()) - ); - tracing::info!( - "Paid: {:.10} ETH ({} gas * {})", - paid_in_eth, - used_gas, - format_gwei(l2_gas_price.into()) - ); - tracing::info!("Refunded: {:.10} ETH", refunded_in_eth); + formatter.exit_scope(); + } } pub fn print_logs( log_query: &StorageLogWithPreviousValue, pubdata_bytes: Option, log_index: usize, + formatter: &mut Formatter, is_last: bool, ) { - let prefix = if is_last { "└─" } else { "├─" }; - tracing::info!(" {} Log #{}", prefix, log_index); - tracing::info!(" │ ├─ Kind: {:?}", log_query.log.kind); - tracing::info!( - " │ ├─ Address: {}", - address_to_human_readable(*log_query.log.key.address()) - .unwrap_or_else(|| format!("{}", log_query.log.key.address())) + formatter.format_log(is_last, &format!("Log #{}", log_index)); + + formatter.enter_scope(!is_last); + formatter.format_log(false, &format!("Kind: {:?}", log_query.log.kind)); + formatter.format_log( + false, + &format!( + "Address: {}", + address_to_human_readable(*log_query.log.key.address()) + .unwrap_or_else(|| format!("{}", log_query.log.key.address())) + ), ); - tracing::info!( - " │ ├─ Key: {:#066x}", - log_query.log.key.key() + formatter.format_log( + false, + &format!("Key: {:#066x}", log_query.log.key.key()), ); - tracing::info!( - " │ ├─ Read Value: {:#066x}", - log_query.previous_value + formatter.format_log( + false, + &format!("Read Value: {:#066x}", log_query.previous_value), ); if log_query.log.is_write() { - tracing::info!(" │ ├─ Written Value: {:#066x}", log_query.log.value); + formatter.format_log( + false, + &format!("Written Value: {:#066x}", log_query.log.value), + ); } if let Some(pubdata_bytes) = pubdata_bytes { - tracing::info!(" │ └─ Pubdata Bytes: {}", pubdata_bytes); + formatter.format_log(true, &format!("Pubdata Bytes: {}", pubdata_bytes)); } else { - tracing::info!(" │ └─ Pubdata Bytes: None"); + formatter.format_log(true, "Pubdata Bytes: None"); } + formatter.exit_scope(); } pub fn print_vm_details2(result: &VmExecutionResultAndLogs) { tracing::info!(""); tracing::info!("[VM Execution Results]"); + let mut formatter = Formatter::new(); + // Log the main statistics - tracing::info!( - " ├─ Cycles Used: {}", - to_human_size(result.statistics.cycles_used.into()) + formatter.format_log( + false, + &format!( + "Cycles Used: {}", + to_human_size(result.statistics.cycles_used.into()) + ), ); - tracing::info!( - " ├─ Computation Gas Used: {}", - to_human_size(result.statistics.computational_gas_used.into()) + formatter.format_log( + false, + &format!( + "Computation Gas Used: {}", + to_human_size(result.statistics.computational_gas_used.into()) + ), ); - tracing::info!( - " ├─ Contracts Used: {}", - to_human_size(result.statistics.contracts_used.into()) + formatter.format_log( + false, + &format!( + "Contracts Used: {}", + to_human_size(result.statistics.contracts_used.into()) + ), ); // Log execution outcome match &result.result { zksync_multivm::interface::ExecutionResult::Success { .. } => { - tracing::info!(" └─ Execution Outcome: Success"); + formatter.format_log(true, "Execution Outcome: Success"); } zksync_multivm::interface::ExecutionResult::Revert { output } => { - tracing::info!(" ├─ Execution Outcome: Failure"); - tracing::info!( - " │ └─ Revert Reason: {}", - output.to_user_friendly_string().red() + formatter.format_log(false, "Execution Outcome: Failure"); + formatter.enter_scope(true); + formatter.format_error( + true, + &format!("Revert Reason: {}", output.to_user_friendly_string()), ); + formatter.exit_scope(); } zksync_multivm::interface::ExecutionResult::Halt { reason } => { - tracing::info!(" ├─ Execution Outcome: Failure"); - tracing::info!(" │ └─ Halt Reason: {}", reason.to_string().red()); + formatter.format_log(false, "Execution Outcome: Failure"); + formatter.enter_scope(true); + formatter.format_error(true, &format!("Halt Reason: {}", reason.to_string())); + formatter.exit_scope(); } } tracing::info!(""); } -pub fn print_vm_details(result: &VmExecutionResultAndLogs) { +pub fn print_transaction_summary( + l2_gas_price: u64, + tx: &Transaction, + tx_result: &VmExecutionResultAndLogs, + status: &str, +) { + // Calculate used and refunded gas + let used_gas = tx.gas_limit() - tx_result.refunds.gas_refunded; + let paid_in_eth = calculate_eth_cost(l2_gas_price, used_gas.as_u64()); + + let refunded_gas = tx_result.refunds.gas_refunded; + + // Calculate refunded gas in ETH + let refunded_in_eth = calculate_eth_cost(l2_gas_price, refunded_gas); + + let emoji = match status { + "SUCCESS" => "✅", + "FAILED" => "❌", + "HALTED" => "⏸️", + _ => "⚠️", + }; + + tracing::info!("{} [{}] Hash: {:?}", emoji, status, tx.hash()); + tracing::info!("Initiator: {:?}", tx.initiator_account()); + tracing::info!("Payer: {:?}", tx.payer()); + tracing::info!( + "Gas Usage: Limit: {} | Used: {} | Refunded: {}", + to_human_size(tx.gas_limit()), + to_human_size(used_gas), + to_human_size(tx_result.refunds.gas_refunded.into()) + ); + tracing::info!( + "Paid: {:.10} ETH ({} gas * {})", + paid_in_eth, + used_gas, + format_gwei(l2_gas_price.into()) + ); + tracing::info!("Refunded: {:.10} ETH", refunded_in_eth); +} + +pub fn _print_vm_details(result: &VmExecutionResultAndLogs) { tracing::info!(""); tracing::info!("┌──────────────────────────┐"); tracing::info!("│ VM EXECUTION RESULTS │"); diff --git a/src/formatter2.rs b/src/formatter2.rs new file mode 100644 index 00000000..92d47719 --- /dev/null +++ b/src/formatter2.rs @@ -0,0 +1,511 @@ +//! Helper methods to display transaction data in more human readable way. +use crate::{config::show_details::ShowCalls, resolver}; + +use colored::Colorize; + +use serde::Deserialize; +use std::collections::HashMap; +use std::str; + +use crate::fork::block_on; +use zksync_types::H160; + +use crate::utils::{calculate_eth_cost, format_gwei, to_human_size}; +use lazy_static::lazy_static; +use zksync_multivm::interface::{Call, VmEvent, VmExecutionResultAndLogs}; +use zksync_types::Address; +use zksync_types::{StorageLogWithPreviousValue, Transaction}; + +#[derive(Debug, Deserialize, Clone, PartialEq, Eq)] +pub enum ContractType { + System, + Precompile, + Popular, + Unknown, +} + +#[derive(Debug, Deserialize, Clone)] +pub struct KnownAddress { + address: H160, + name: String, + contract_type: ContractType, +} + +lazy_static! { + /// Loads the known contact addresses from the JSON file. + static ref KNOWN_ADDRESSES: HashMap = { + let json_value = serde_json::from_slice(include_bytes!("data/address_map.json")).unwrap(); + let pairs: Vec = serde_json::from_value(json_value).unwrap(); + + pairs + .into_iter() + .map(|entry| (entry.address, entry)) + .collect() + }; +} +// TODO: When refactoring other logs (e.g event, storage, vm, gas) update this function. +// Currently a close duplicate of format_address_human_readable +fn address_to_human_readable(address: H160) -> Option { + KNOWN_ADDRESSES.get(&address).map(|known_address| { + let name = match known_address.contract_type { + ContractType::System => known_address.name.bold().bright_blue().to_string(), + ContractType::Precompile => known_address.name.bold().magenta().to_string(), + ContractType::Popular => known_address.name.bold().bright_green().to_string(), + ContractType::Unknown => known_address.name.dimmed().to_string(), + }; + + let formatted_address = format!("{:#x}", address).dimmed(); + format!("{}{}{}", name, "@".dimmed(), formatted_address) + }) +} + +fn format_address_human_readable( + address: H160, + initiator: H160, + contract_address: Option, + call_type: &str, +) -> Option { + let is_initiator = address == initiator; + let excluded_addresses = [ + H160::from_slice(&hex::decode("0000000000000000000000000000000000008006").unwrap()), + H160::from_slice(&hex::decode("0000000000000000000000000000000000010000").unwrap()), + ]; + + let is_contract = Some(address) == contract_address && !excluded_addresses.contains(&address); + + if is_initiator { + let name = "initiator".bold().green().to_string(); + let formatted_address = format!("{:#x}", address); + return Some(format!("{}{}{}", name, "@".dimmed(), formatted_address)); + } + if call_type == "Create" { + let name = "deployed".bold().bright_green().to_string(); + let formatted_address = format!("{:#x}", address); + return Some(format!("{}{}{}", name, "@".dimmed(), formatted_address)); + } else if is_contract { + let name = "contract".bold().bright_green().to_string(); + let formatted_address = format!("{:#x}", address); + return Some(format!("{}{}{}", name, "@".dimmed(), formatted_address)); + } + + KNOWN_ADDRESSES.get(&address).map(|known_address| { + let name = match known_address.contract_type { + ContractType::System => known_address.name.bold().bright_blue().to_string(), + ContractType::Precompile => known_address.name.bold().magenta().to_string(), + ContractType::Popular => known_address.name.bold().bright_green().to_string(), + ContractType::Unknown => known_address.name.dimmed().to_string(), + }; + + let formatted_address = format!("{:#x}", address).dimmed(); + format!("{}{}{}", name, "@".dimmed(), formatted_address) + }) +} + +/// Pretty-prints event object using the new structured log format. +/// If `resolve_hashes` is true, attempts to resolve topic hashes. +pub fn print_event(event: &VmEvent, resolve_hashes: bool) { + let event = event.clone(); + block_on(async move { + let mut topics: Vec = vec![]; + + // Resolve or fallback to raw hex topics + for topic in event.indexed_topics.iter() { + let resolved = if resolve_hashes { + resolver::decode_event_selector(&format!("{:#x}", topic)) + .await + .unwrap_or(None) + } else { + None + }; + + topics.push(resolved.unwrap_or_else(|| format!("{:#x}", topic))); + } + + // Event address (contract) + let contract_display = address_to_human_readable(event.address) + .map(|x| format!("{:42}", x.blue())) + .unwrap_or(format!("{:42}", format!("{:?}", event.address).blue())); + + tracing::info!(" ├─ Event [{}]", contract_display); + + // Topics + if topics.is_empty() { + tracing::info!(" │ └─ Topics: EMPTY"); + } else { + tracing::info!(" │ ├─ Topics:"); + for (i, topic) in topics.iter().enumerate() { + let prefix = if i + 1 == topics.len() { + "└─" + } else { + "├─" + }; + tracing::info!(" │ │ {} Topic[{}]: {}", prefix, i, topic); + } + } + + // Data + if event.value.is_empty() { + tracing::info!(" │ └─ Data: EMPTY"); + } else { + match str::from_utf8(&event.value) { + Ok(v) => { + tracing::info!(" │ └─ Data (String): {}", v.truecolor(128, 128, 128)); + } + Err(_) => { + let hex_str = hex::encode(&event.value); + let display_str = if hex_str.len() > 200 { + format!("{}...", &hex_str[..200]) + } else { + hex_str.to_string() + }; + + tracing::info!( + " │ └─ Data (Hex): 0x{}", + display_str.truecolor(128, 128, 128) + ); + } + } + } + + tracing::info!(""); + }); +} + +/// Amount of pubdata that given write has cost. +pub enum PubdataBytesInfo { + // This slot is free + FreeSlot, + // This slot costs this much. + Paid(u32), + // This happens when we already paid a little for this slot in the past. + // This slots costs additional X, the total cost is Y. + AdditionalPayment(u32, u32), + // We already paid for this slot in this transaction. + PaidAlready, +} + +impl std::fmt::Display for PubdataBytesInfo { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + match self { + PubdataBytesInfo::FreeSlot => write!(f, "Free Slot (no cost)"), + PubdataBytesInfo::Paid(cost) => { + write!(f, "Paid: {} bytes", to_human_size((*cost).into())) + } + PubdataBytesInfo::AdditionalPayment(additional_cost, total_cost) => write!( + f, + "Additional Payment: {} bytes (Total: {} bytes)", + to_human_size((*additional_cost).into()), + to_human_size((*total_cost).into()) + ), + PubdataBytesInfo::PaidAlready => write!(f, "Already Paid (no additional cost)"), + } + } +} + +impl PubdataBytesInfo { + // Whether the slot incurs any cost + pub fn does_cost(&self) -> bool { + match self { + PubdataBytesInfo::FreeSlot => false, + PubdataBytesInfo::Paid(_) => true, + PubdataBytesInfo::AdditionalPayment(_, _) => true, + PubdataBytesInfo::PaidAlready => false, + } + } +} + +fn build_prefix(sibling_stack: &Vec) -> String { + let mut prefix = String::new(); + for &has_more_siblings in sibling_stack { + if has_more_siblings { + prefix.push_str("│ "); + } else { + prefix.push_str(" "); + } + } + prefix +} + +#[allow(clippy::too_many_arguments)] +pub fn print_call( + initiator: Address, + contract_address: Option, + call: &Call, + sibling_stack: &Vec, + is_last_sibling: bool, + show_calls: &ShowCalls, + show_outputs: bool, + resolve_hashes: bool, +) { + let contract_type = KNOWN_ADDRESSES + .get(&call.to) + .cloned() + .map(|known_address| known_address.contract_type) + .unwrap_or(ContractType::Unknown); + + let should_print = match (&contract_type, &show_calls) { + (_, ShowCalls::All) => true, + (_, ShowCalls::None) => false, + (ContractType::Unknown, _) => true, + (ContractType::Popular, _) => true, + (ContractType::Precompile, _) => false, + (ContractType::System, ShowCalls::User) => false, + (ContractType::System, ShowCalls::System) => true, + }; + + if should_print { + let prefix = build_prefix(sibling_stack); + let branch = if is_last_sibling { + "└─ " + } else { + "├─ " + }; + let full_prefix = format!("{}{}", prefix, branch); + + let call_type_display = format!("{:?}", call.r#type).blue(); + let remaining_gas_display = to_human_size(call.gas.into()).yellow(); + let gas_used_display = format!("({})", to_human_size(call.gas_used.into())).bold(); + + // Get contract display + let contract_display = format_address_human_readable( + call.to, + initiator, + contract_address, + format!("{:?}", call.r#type).as_str(), + ) + .map(|x| x.to_string()) + .unwrap_or(format!("{:}", format!("{:?}", call.to).bold())); + + // Get function signature + let function_signature = if call.input.len() >= 4 { + let sig = hex::encode(&call.input[0..4]); + if contract_type == ContractType::Precompile || !resolve_hashes { + format!("0x{}", sig) + } else { + block_on(async move { + match resolver::decode_function_selector(&sig).await { + Ok(Some(name)) => name, + Ok(None) | Err(_) => format!("0x{}", sig), + } + }) + } + } else { + "unknown".to_string() + }; + + let function_display = function_signature.cyan().bold(); + + // Build the line + let line = format!( + "{}{} [{}] {}::{} {}", + full_prefix, + call_type_display, + remaining_gas_display, + contract_display, + function_display, + gas_used_display + ); + + // Handle errors + if call.revert_reason.is_some() || call.error.is_some() { + tracing::info!("{}", line.red()); + if let Some(ref reason) = call.revert_reason { + let error_line = format!("{} └─ 🔴 Revert reason: {}", prefix, reason); + tracing::info!("{}", error_line.red()); + } + if let Some(ref error) = call.error { + let error_line = format!("{} └─ 🔴 Error: {}", prefix, error); + tracing::info!("{}", error_line.red()); + } + } else { + tracing::info!("{}", line); + } + + // Handle outputs + if show_outputs && !call.output.is_empty() { + let output_display = call + .output + .as_slice() + .iter() + .map(|byte| format!("{:02x}", byte)) + .collect::>() + .join(""); + + let output_branch = if is_last_sibling { + " └── Output: ".dimmed() + } else { + " ├── Output: ".dimmed() + }; + + let output_line = format!("{}{}", full_prefix, output_branch) + &output_display; + tracing::info!("{}", output_line); + } + } + + // Process subcalls + let num_subcalls = call.calls.len(); + if num_subcalls > 0 { + let mut new_sibling_stack = sibling_stack.clone(); + new_sibling_stack.push(!is_last_sibling); + for (i, subcall) in call.calls.iter().enumerate() { + let is_last_subcall = i == num_subcalls - 1; + print_call( + initiator, + contract_address, + subcall, + &new_sibling_stack, + is_last_subcall, + show_calls, + show_outputs, + resolve_hashes, + ); + } + } +} + +pub fn print_transaction_summary( + l2_gas_price: u64, + tx: &Transaction, + tx_result: &VmExecutionResultAndLogs, + status: &str, +) { + // Calculate used and refunded gas + let used_gas = tx.gas_limit() - tx_result.refunds.gas_refunded; + let paid_in_eth = calculate_eth_cost(l2_gas_price, used_gas.as_u64()); + + let refunded_gas = tx_result.refunds.gas_refunded; + + // Calculate refunded gas in ETH + let refunded_in_eth = calculate_eth_cost(l2_gas_price, refunded_gas); + + let emoji = match status { + "SUCCESS" => "✅", + "FAILED" => "❌", + "HALTED" => "⏸️", + _ => "⚠️", + }; + + tracing::info!("{} [{}] Hash: {:?}", emoji, status, tx.hash()); + tracing::info!("Initiator: {:?}", tx.initiator_account()); + tracing::info!("Payer: {:?}", tx.payer()); + tracing::info!( + "Gas Usage: Limit: {} | Used: {} | Refunded: {}", + to_human_size(tx.gas_limit()), + to_human_size(used_gas), + to_human_size(tx_result.refunds.gas_refunded.into()) + ); + tracing::info!( + "Paid: {:.10} ETH ({} gas * {})", + paid_in_eth, + used_gas, + format_gwei(l2_gas_price.into()) + ); + tracing::info!("Refunded: {:.10} ETH", refunded_in_eth); +} + +pub fn print_logs( + log_query: &StorageLogWithPreviousValue, + pubdata_bytes: Option, + log_index: usize, + is_last: bool, +) { + let prefix = if is_last { "└─" } else { "├─" }; + tracing::info!(" {} Log #{}", prefix, log_index); + tracing::info!(" │ ├─ Kind: {:?}", log_query.log.kind); + tracing::info!( + " │ ├─ Address: {}", + address_to_human_readable(*log_query.log.key.address()) + .unwrap_or_else(|| format!("{}", log_query.log.key.address())) + ); + tracing::info!( + " │ ├─ Key: {:#066x}", + log_query.log.key.key() + ); + tracing::info!( + " │ ├─ Read Value: {:#066x}", + log_query.previous_value + ); + + if log_query.log.is_write() { + tracing::info!(" │ ├─ Written Value: {:#066x}", log_query.log.value); + } + + if let Some(pubdata_bytes) = pubdata_bytes { + tracing::info!(" │ └─ Pubdata Bytes: {}", pubdata_bytes); + } else { + tracing::info!(" │ └─ Pubdata Bytes: None"); + } +} + +pub fn print_vm_details2(result: &VmExecutionResultAndLogs) { + tracing::info!(""); + tracing::info!("[VM Execution Results]"); + + // Log the main statistics + tracing::info!( + " ├─ Cycles Used: {}", + to_human_size(result.statistics.cycles_used.into()) + ); + tracing::info!( + " ├─ Computation Gas Used: {}", + to_human_size(result.statistics.computational_gas_used.into()) + ); + tracing::info!( + " ├─ Contracts Used: {}", + to_human_size(result.statistics.contracts_used.into()) + ); + + // Log execution outcome + match &result.result { + zksync_multivm::interface::ExecutionResult::Success { .. } => { + tracing::info!(" └─ Execution Outcome: Success"); + } + zksync_multivm::interface::ExecutionResult::Revert { output } => { + tracing::info!(" ├─ Execution Outcome: Failure"); + tracing::info!( + " │ └─ Revert Reason: {}", + output.to_user_friendly_string().red() + ); + } + zksync_multivm::interface::ExecutionResult::Halt { reason } => { + tracing::info!(" ├─ Execution Outcome: Failure"); + tracing::info!(" │ └─ Halt Reason: {}", reason.to_string().red()); + } + } + + tracing::info!(""); +} + +pub fn print_vm_details(result: &VmExecutionResultAndLogs) { + tracing::info!(""); + tracing::info!("┌──────────────────────────┐"); + tracing::info!("│ VM EXECUTION RESULTS │"); + tracing::info!("└──────────────────────────┘"); + + tracing::info!("Cycles Used: {}", result.statistics.cycles_used); + tracing::info!( + "Computation Gas Used: {}", + result.statistics.computational_gas_used + ); + tracing::info!("Contracts Used: {}", result.statistics.contracts_used); + match &result.result { + zksync_multivm::interface::ExecutionResult::Success { .. } => {} + zksync_multivm::interface::ExecutionResult::Revert { output } => { + tracing::info!(""); + tracing::info!( + "{}", + format!( + "\n[!] Revert Reason: {}", + output.to_user_friendly_string() + ) + .on_red() + ); + } + zksync_multivm::interface::ExecutionResult::Halt { reason } => { + tracing::info!(""); + tracing::info!("{}", format!("\n[!] Halt Reason: {}", reason).on_red()); + } + } + + tracing::info!("════════════════════════════"); +} diff --git a/src/node/in_memory.rs b/src/node/in_memory.rs index 35037893..dd38a9f9 100644 --- a/src/node/in_memory.rs +++ b/src/node/in_memory.rs @@ -1250,7 +1250,7 @@ impl InMemoryNode { tx.initiator_account(), tx.execute.contract_address, call, - &vec![], + &mut formatter::Formatter::new(), is_last_sibling, &inner.config.show_calls, inner.config.show_outputs, @@ -1269,6 +1269,237 @@ impl InMemoryNode { if let Some(bootloader_result) = bootloader_debug_result { let bootloader_debug = bootloader_result.clone()?; + let total_gas_limit = bootloader_debug + .total_gas_limit_from_user + .saturating_sub(bootloader_debug.reserved_gas); + let intrinsic_gas = total_gas_limit - bootloader_debug.gas_limit_after_intrinsic; + let gas_for_validation = + bootloader_debug.gas_limit_after_intrinsic - bootloader_debug.gas_after_validation; + let gas_spent_on_compute = bootloader_debug.gas_spent_on_execution + - bootloader_debug.gas_spent_on_bytecode_preparation; + let gas_used = intrinsic_gas + + gas_for_validation + + bootloader_debug.gas_spent_on_bytecode_preparation + + gas_spent_on_compute; + + let bytes_published = spent_on_pubdata / bootloader_debug.gas_per_pubdata.as_u64(); + + // Initialize the logger with an empty sibling stack + let mut logger = formatter::Formatter::new(); + logger.format_log(false, "[Gas Details]"); + + // 1. Gas Summary + logger.enter_scope(false); // Enter scope under [Gas Details], more sections follow + logger.format_log(false, "Gas Summary"); + + logger.enter_scope(true); // Items under Gas Summary + logger.format_log( + false, + &format!("Limit: {}", to_human_size(total_gas_limit)), + ); + logger.format_log(false, &format!("Used: {}", to_human_size(gas_used))); + logger.format_log( + true, + &format!( + "Refunded: {}", + to_human_size(bootloader_debug.refund_by_operator) + ), + ); + logger.exit_scope(); // Exit items under Gas Summary + + // Handle warnings + if bootloader_debug.refund_computed != bootloader_debug.refund_by_operator { + logger.format_error( + false, + &format!( + "WARNING: Refund by VM: {}, but operator refunded more: {}", + to_human_size(bootloader_debug.refund_computed), + to_human_size(bootloader_debug.refund_by_operator) + ), + ); + } + + if bootloader_debug.total_gas_limit_from_user != total_gas_limit { + logger.format_error( + false, + &format!( + "WARNING: User provided more gas ({}), but system had a lower max limit.", + to_human_size(bootloader_debug.total_gas_limit_from_user) + ), + ); + } + logger.exit_scope(); // Exit Gas Summary + + // 2. Execution Gas Breakdown + logger.enter_scope(false); // More sections follow + logger.format_log(false, "Execution Gas Breakdown"); + + logger.enter_scope(true); // Items under Execution Gas Breakdown + let gas_breakdown_items = vec![ + ( + "Transaction Setup", + intrinsic_gas, + intrinsic_gas * 100 / gas_used, + ), + ( + "Bytecode Preparation", + bootloader_debug.gas_spent_on_bytecode_preparation, + bootloader_debug.gas_spent_on_bytecode_preparation * 100 / gas_used, + ), + ( + "Account Validation", + gas_for_validation, + gas_for_validation * 100 / gas_used, + ), + ( + "Computations (Opcodes)", + gas_spent_on_compute, + gas_spent_on_compute * 100 / gas_used, + ), + ]; + + for (i, (description, amount, percentage)) in gas_breakdown_items.iter().enumerate() { + let is_last = i == gas_breakdown_items.len() - 1; + logger.format_log( + is_last, + &format!( + "{}: {} gas ({:>2}%)", + description, + to_human_size(*amount), + percentage + ), + ); + } + + logger.exit_scope(); // Exit items under Execution Gas Breakdown + logger.exit_scope(); // Exit Execution Gas Breakdown + + // 3. Transaction Setup Cost Breakdown + logger.enter_scope(false); // More sections follow + logger.format_log(false, "Transaction Setup Cost Breakdown"); + + logger.enter_scope(true); // Items under Transaction Setup Cost Breakdown + logger.format_log( + false, + &format!( + "Total Setup Cost: {} gas", + to_human_size(intrinsic_gas) + ), + ); + logger.format_log( + false, + &format!( + "Fixed Cost: {} gas ({:>2}%)", + to_human_size(bootloader_debug.intrinsic_overhead), + bootloader_debug.intrinsic_overhead * 100 / intrinsic_gas + ), + ); + logger.format_log( + true, + &format!( + "Operator Cost: {} gas ({:>2}%)", + to_human_size(bootloader_debug.operator_overhead), + bootloader_debug.operator_overhead * 100 / intrinsic_gas + ), + ); + logger.exit_scope(); // Exit items under Transaction Setup Cost Breakdown + + if bootloader_debug.required_overhead != U256::zero() { + logger.format_log( + false, + &format!( + "FYI: Operator could have charged up to {}, so you got a {}% discount.", + to_human_size(bootloader_debug.required_overhead), + (bootloader_debug.required_overhead - bootloader_debug.operator_overhead) + * 100 + / bootloader_debug.required_overhead + ), + ); + } + + logger.exit_scope(); // Exit Transaction Setup Cost Breakdown + + // 4. L1 Publishing Costs + logger.enter_scope(false); // More sections follow + logger.format_log(false, "L1 Publishing Costs"); + + logger.enter_scope(true); // Items under L1 Publishing Costs + logger.format_log( + false, + &format!( + "Published: {} bytes", + to_human_size(bytes_published.into()) + ), + ); + logger.format_log( + false, + &format!( + "Cost per Byte: {} gas", + to_human_size(bootloader_debug.gas_per_pubdata) + ), + ); + logger.format_log( + true, + &format!( + "Total Gas Cost: {} gas", + to_human_size(spent_on_pubdata.into()) + ), + ); + logger.exit_scope(); // Exit items under L1 Publishing Costs + logger.exit_scope(); // Exit L1 Publishing Costs + + // 5. Block Contribution + logger.enter_scope(true); // This is the last section + logger.format_log(true, "Block Contribution"); + + logger.enter_scope(true); // Items under Block Contribution + logger.format_log( + false, + &format!( + "Length Overhead: {} gas", + to_human_size(bootloader_debug.overhead_for_length) + ), + ); + logger.format_log( + false, + &format!( + "Slot Overhead: {} gas", + to_human_size(bootloader_debug.overhead_for_slot) + ), + ); + logger.format_log( + true, + &format!( + "Full Block Cost: ~{} L2 gas", + to_human_size( + bootloader_debug.gas_per_pubdata + * self + .inner + .read() + .unwrap() + .fee_input_provider + .get_fee_model_config() + .batch_overhead_l1_gas + ) + ), + ); + logger.exit_scope(); // Exit items under Block Contribution + logger.exit_scope(); // Exit Block Contribution + + Ok(()) + } else { + Err("Bootloader tracer didn't finish.".to_owned()) + } + } + + fn display_detailed_gas_info3( + &self, + bootloader_debug_result: Option<&eyre::Result>, + spent_on_pubdata: u64, + ) -> eyre::Result<(), String> { + if let Some(bootloader_result) = bootloader_debug_result { + let bootloader_debug = bootloader_result.clone()?; + tracing::info!(""); tracing::info!("[Gas Details]"); @@ -1672,13 +1903,16 @@ impl InMemoryNode { ExecutionResult::Halt { .. } => "HALTED", }; if inner.config.show_tx_summary { + tracing::info!(""); formatter::print_transaction_summary( inner.config.get_l2_gas_price(), &tx, &tx_result, status, ); + tracing::info!(""); } + // TODO: improve gas details match inner.config.show_gas_details { ShowGasDetails::None => {} ShowGasDetails::All => { @@ -1694,10 +1928,12 @@ impl InMemoryNode { } } + // TODO: improve storage logs if inner.config.show_storage_logs != ShowStorageLogs::None { print_storage_logs_details(&inner.config.show_storage_logs, &tx_result); } + // TODO: improve vm details if inner.config.show_vm_details != ShowVMDetails::None { formatter::print_vm_details2(&tx_result); } @@ -1712,6 +1948,7 @@ impl InMemoryNode { } tracing::info!(""); + // TODO: improve call traces if inner.config.show_calls != ShowCalls::None { tracing::info!( "[Transaction Execution] ({} calls)", @@ -1724,7 +1961,7 @@ impl InMemoryNode { tx.initiator_account(), tx.execute.contract_address, call, - &vec![], + &mut formatter::Formatter::with_initial_stack(vec![false]), is_last_sibling, &inner.config.show_calls, inner.config.show_outputs, @@ -1734,11 +1971,14 @@ impl InMemoryNode { } tracing::info!(""); if inner.config.show_event_logs { - tracing::info!(" [Events] ({} events)", tx_result.logs.events.len()); - for event in &tx_result.logs.events { - formatter::print_event(event, inner.config.resolve_hashes); + tracing::info!("[Events] ({} events)", tx_result.logs.events.len()); + + for (i, event) in tx_result.logs.events.iter().enumerate() { + let is_last = i == tx_result.logs.events.len() - 1; + formatter::print_event(event, inner.config.resolve_hashes, is_last); } } + tracing::info!(""); let mut bytecodes = HashMap::new(); for b in &*compressed_bytecodes { diff --git a/src/node/storage_logs.rs b/src/node/storage_logs.rs index 268e73ae..20584254 100644 --- a/src/node/storage_logs.rs +++ b/src/node/storage_logs.rs @@ -97,7 +97,13 @@ pub fn print_storage_logs_details( if should_print { let is_last = index == result.logs.storage_logs.len() - 1; - formatter::print_logs(log_query, pubdata_bytes_info, index + 1, is_last); + formatter::print_logs( + log_query, + pubdata_bytes_info, + index + 1, + &mut formatter::Formatter::new(), + is_last, + ); } } } From 46be139facb22881970933d27207fd944339d688 Mon Sep 17 00:00:00 2001 From: Dustin Brickwood Date: Fri, 22 Nov 2024 12:49:41 -0600 Subject: [PATCH 06/16] chore: clean up --- src/config/cli.rs | 9 +- src/formatter.rs | 1027 ++++++++++++++++++++++++-------------- src/node/in_memory.rs | 596 ++-------------------- src/node/storage_logs.rs | 9 +- 4 files changed, 688 insertions(+), 953 deletions(-) diff --git a/src/config/cli.rs b/src/config/cli.rs index c763287b..2f2f551c 100644 --- a/src/config/cli.rs +++ b/src/config/cli.rs @@ -87,11 +87,16 @@ pub struct Cli { /// Show call debug information. pub show_calls: Option, - #[arg(long, default_missing_value = "true", num_args(0..=1), help_heading = "Debugging Options")] + #[arg( + default_missing_value = "true", num_args(0..=1), + long, + requires = "show_calls", + help_heading = "Debugging Options" + )] /// Show call output information. pub show_outputs: Option, - #[arg(long, help_heading = "Debugging Options")] + #[arg(short, long, help_heading = "Debugging Options")] /// Show event logs information. pub show_event_logs: Option, diff --git a/src/formatter.rs b/src/formatter.rs index 11a36bbc..d0a85a95 100644 --- a/src/formatter.rs +++ b/src/formatter.rs @@ -1,47 +1,90 @@ //! Helper methods to display transaction data in more human readable way. +use crate::bootloader_debug::BootloaderDebug; +use crate::fork::block_on; +use crate::utils::{calculate_eth_cost, format_gwei, to_human_size}; use crate::{config::show_details::ShowCalls, resolver}; use colored::Colorize; - -use serde::Deserialize; -use std::collections::HashMap; -use std::str; - -use crate::fork::block_on; -use crate::utils::{calculate_eth_cost, format_gwei, to_human_size}; use futures::future::join_all; use lazy_static::lazy_static; +use serde::Deserialize; +use std::{collections::HashMap, str}; use zksync_multivm::interface::{Call, VmEvent, VmExecutionResultAndLogs}; -use zksync_types::Address; -use zksync_types::{StorageLogWithPreviousValue, Transaction}; -use zksync_types::{H160, H256}; +use zksync_types::{ + fee_model::FeeModelConfigV2, Address, StorageLogWithPreviousValue, Transaction, H160, H256, + U256, +}; +// @dev elected to have GasDetails struct as we can do more with it in the future +// More detailed understanding of gas errors and gas usage #[derive(Debug, Deserialize, Clone, PartialEq, Eq)] -pub enum ContractType { - System, - Precompile, - Popular, - Unknown, -} - -#[derive(Debug, Deserialize, Clone)] -pub struct KnownAddress { - address: H160, - name: String, - contract_type: ContractType, +pub struct GasDetails { + total_gas_limit: U256, + intrinsic_gas: U256, + gas_for_validation: U256, + gas_spent_on_compute: U256, + gas_used: U256, + bytes_published: u64, + spent_on_pubdata: u64, + gas_spent_on_bytecode_preparation: U256, + refund_computed: U256, + refund_by_operator: U256, + required_overhead: U256, + operator_overhead: U256, + intrinsic_overhead: U256, + overhead_for_length: U256, + overhead_for_slot: U256, + gas_per_pubdata: U256, + total_gas_limit_from_user: U256, + gas_spent_on_execution: U256, + gas_limit_after_intrinsic: U256, + gas_after_validation: U256, + reserved_gas: U256, } -lazy_static! { - /// Loads the known contact addresses from the JSON file. - static ref KNOWN_ADDRESSES: HashMap = { - let json_value = serde_json::from_slice(include_bytes!("data/address_map.json")).unwrap(); - let pairs: Vec = serde_json::from_value(json_value).unwrap(); - - pairs - .into_iter() - .map(|entry| (entry.address, entry)) - .collect() - }; +/// Computes the gas details for the transaction to be displayed. +pub fn compute_gas_details( + bootloader_debug: &BootloaderDebug, + spent_on_pubdata: u64, +) -> GasDetails { + let total_gas_limit = bootloader_debug + .total_gas_limit_from_user + .saturating_sub(bootloader_debug.reserved_gas); + let intrinsic_gas = total_gas_limit - bootloader_debug.gas_limit_after_intrinsic; + let gas_for_validation = + bootloader_debug.gas_limit_after_intrinsic - bootloader_debug.gas_after_validation; + let gas_spent_on_compute = bootloader_debug.gas_spent_on_execution + - bootloader_debug.gas_spent_on_bytecode_preparation; + let gas_used = intrinsic_gas + + gas_for_validation + + bootloader_debug.gas_spent_on_bytecode_preparation + + gas_spent_on_compute; + + let bytes_published = spent_on_pubdata / bootloader_debug.gas_per_pubdata.as_u64(); + + GasDetails { + total_gas_limit, + intrinsic_gas, + gas_for_validation, + gas_spent_on_compute, + gas_used, + bytes_published, + spent_on_pubdata, + gas_spent_on_bytecode_preparation: bootloader_debug.gas_spent_on_bytecode_preparation, + refund_computed: bootloader_debug.refund_computed, + refund_by_operator: bootloader_debug.refund_by_operator, + required_overhead: bootloader_debug.required_overhead, + operator_overhead: bootloader_debug.operator_overhead, + intrinsic_overhead: bootloader_debug.intrinsic_overhead, + overhead_for_length: bootloader_debug.overhead_for_length, + overhead_for_slot: bootloader_debug.overhead_for_slot, + gas_per_pubdata: bootloader_debug.gas_per_pubdata, + total_gas_limit_from_user: bootloader_debug.total_gas_limit_from_user, + gas_spent_on_execution: bootloader_debug.gas_spent_on_execution, + gas_limit_after_intrinsic: bootloader_debug.gas_limit_after_intrinsic, + gas_after_validation: bootloader_debug.gas_after_validation, + reserved_gas: bootloader_debug.reserved_gas, + } } pub struct Formatter { @@ -59,22 +102,22 @@ impl Formatter { Formatter { sibling_stack } } - pub fn section(&mut self, title: &str, has_more_siblings: bool, f: F) + pub fn section(&mut self, title: &str, is_last_sibling: bool, f: F) where F: FnOnce(&mut Self), { - self.format_log(false, title); - self.enter_scope(has_more_siblings); + self.format_log(is_last_sibling, title); + self.enter_scope(is_last_sibling); f(self); self.exit_scope(); } - pub fn subsection(&mut self, title: &str, has_more_siblings: bool, f: F) + pub fn subsection(&mut self, title: &str, is_last_sibling: bool, f: F) where F: FnOnce(&mut Self), { - self.format_log(false, title); - self.enter_scope(has_more_siblings); + self.format_log(is_last_sibling, title); + self.enter_scope(is_last_sibling); f(self); self.exit_scope(); } @@ -107,14 +150,493 @@ impl Formatter { let prefix = build_prefix(&self.sibling_stack, is_last_sibling); tracing::info!("{}", format!("{}{}", prefix, message).red()); } -} + /// Prints gas details for the transaction in a structured log. + pub fn print_gas_details( + &mut self, + gas_details: &GasDetails, + fee_model_config: &FeeModelConfigV2, + ) { + let GasDetails { + total_gas_limit, + intrinsic_gas, + gas_for_validation, + gas_spent_on_compute, + gas_used, + bytes_published, + spent_on_pubdata, + gas_spent_on_bytecode_preparation, + refund_computed, + refund_by_operator, + required_overhead: _required_overhead, + operator_overhead, + intrinsic_overhead, + overhead_for_length, + overhead_for_slot, + gas_per_pubdata, + total_gas_limit_from_user, + .. + } = *gas_details; + + self.section("[Gas Details]", true, |gas_details_section| { + let mut total_items = 0; + let mut warnings = Vec::new(); + + // Prepare warnings + if refund_computed != refund_by_operator { + warnings.push(format!( + "WARNING: Refund by VM: {}, but operator refunded: {}", + to_human_size(refund_computed), + to_human_size(refund_by_operator) + )); + } + if total_gas_limit_from_user != total_gas_limit { + warnings.push(format!( + "WARNING: User provided more gas ({}), but system had a lower max limit.", + to_human_size(total_gas_limit_from_user) + )); + } + + // Calculate total items under [Gas Details] + total_items += 1; // Gas Summary + total_items += warnings.len(); // Warnings + total_items += 1; // Execution Gas Breakdown + total_items += 1; // Transaction Setup Cost Breakdown + total_items += 1; // L1 Publishing Costs + total_items += 1; // Block Contribution + + let mut item_index = 0; + + // 1. Gas Summary + let is_last_sibling = item_index == total_items - 1; + gas_details_section.section("Gas Summary", is_last_sibling, |gas_summary_section| { + let items = vec![ + ("Limit", to_human_size(total_gas_limit)), + ("Used", to_human_size(gas_used)), + ("Refunded", to_human_size(refund_by_operator)), + ]; + + let num_items = items.len(); + for (i, (key, value)) in items.into_iter().enumerate() { + let is_last_item = i == num_items - 1; + gas_summary_section.item(is_last_item, key, &value); + } + }); + item_index += 1; + + // warnings + for warning in warnings { + let is_last_sibling = item_index == total_items - 1; + gas_details_section.format_error(is_last_sibling, &warning); + item_index += 1; + } + + // 2. Execution Gas Breakdown + let is_last_sibling = item_index == total_items - 1; + gas_details_section.section( + "Execution Gas Breakdown", + is_last_sibling, + |execution_breakdown_section| { + let gas_breakdown_items = vec![ + ( + "Transaction Setup", + intrinsic_gas, + intrinsic_gas * 100 / gas_used, + ), + ( + "Bytecode Preparation", + gas_spent_on_bytecode_preparation, + gas_spent_on_bytecode_preparation * 100 / gas_used, + ), + ( + "Account Validation", + gas_for_validation, + gas_for_validation * 100 / gas_used, + ), + ( + "Computations (Opcodes)", + gas_spent_on_compute, + gas_spent_on_compute * 100 / gas_used, + ), + ]; + + let num_items = gas_breakdown_items.len(); + for (i, (description, amount, percentage)) in + gas_breakdown_items.iter().enumerate() + { + let is_last_item = i == num_items - 1; + execution_breakdown_section.item( + is_last_item, + description, + &format!("{} gas ({:>2}%)", to_human_size(*amount), percentage), + ); + } + }, + ); + item_index += 1; + + // 3. Transaction Setup Cost Breakdown + let is_last_sibling = item_index == total_items - 1; + gas_details_section.section( + "Transaction Setup Cost Breakdown", + is_last_sibling, + |transaction_setup_section| { + let items = vec![ + ( + "Total Setup Cost", + format!("{} gas", to_human_size(intrinsic_gas)), + ), + ( + "Fixed Cost", + format!( + "{} gas ({:>2}%)", + to_human_size(intrinsic_overhead), + intrinsic_overhead * 100 / intrinsic_gas + ), + ), + ( + "Operator Cost", + format!( + "{} gas ({:>2}%)", + to_human_size(operator_overhead), + operator_overhead * 100 / intrinsic_gas + ), + ), + ]; + + let num_items = items.len(); + for (i, (key, value)) in items.into_iter().enumerate() { + let is_last_item = i == num_items - 1; + transaction_setup_section.item(is_last_item, key, &value); + } + }, + ); + item_index += 1; + + // 4. L1 Publishing Costs + let is_last_sibling = item_index == total_items - 1; + gas_details_section.section( + "L1 Publishing Costs", + is_last_sibling, + |l1_publishing_section| { + let items = vec![ + ( + "Published", + format!("{} bytes", to_human_size(bytes_published.into())), + ), + ( + "Cost per Byte", + format!("{} gas", to_human_size(gas_per_pubdata)), + ), + ( + "Total Gas Cost", + format!("{} gas", to_human_size(spent_on_pubdata.into())), + ), + ]; + + let num_items = items.len(); + for (i, (key, value)) in items.into_iter().enumerate() { + let is_last_item = i == num_items - 1; + l1_publishing_section.item(is_last_item, key, &value); + } + }, + ); + item_index += 1; + + // 5. Block Contribution + let is_last_sibling = item_index == total_items - 1; + gas_details_section.section("Block Contribution", is_last_sibling, |block_section| { + let full_block_cost = gas_per_pubdata * fee_model_config.batch_overhead_l1_gas; + + let items = vec![ + ( + "Length Overhead", + format!("{} gas", to_human_size(overhead_for_length)), + ), + ( + "Slot Overhead", + format!("{} gas", to_human_size(overhead_for_slot)), + ), + ( + "Full Block Cost", + format!("~{} L2 gas", to_human_size(full_block_cost)), + ), + ]; + + let num_items = items.len(); + for (i, (key, value)) in items.into_iter().enumerate() { + let is_last_item = i == num_items - 1; + block_section.item(is_last_item, key, &value); + } + }); + }); + } + /// Prints the events of a contract in a structured log. + pub fn print_event(&mut self, event: &VmEvent, resolve_hashes: bool, is_last_sibling: bool) { + tracing::info!(""); + let event = event.clone(); + + let topics = resolve_topics(&event.indexed_topics, resolve_hashes); + + let contract_display = address_to_human_readable(event.address) + .map(|x| format!("{:42}", x.blue())) + .unwrap_or_else(|| format!("{:42}", format!("{:?}", event.address).blue())); + + self.section( + &format!("Event [{}]", contract_display), + is_last_sibling, + |event_section| { + event_section.subsection("Topics", false, |topics_section| { + let num_topics = topics.len(); + if num_topics == 0 { + topics_section.item(true, "Topics", "EMPTY"); + } else { + for (i, topic) in topics.iter().enumerate() { + let is_last_topic = i == num_topics - 1; + topics_section.item(is_last_topic, &format!("Topic[{}]", i), topic); + } + } + }); + + event_section.item(true, "Data", &format_data(&event.value)); + }, + ); + } + /// Prints the call stack of either the system or user calls in a structured log. + pub fn print_call( + &mut self, + initiator: Address, + contract_address: Option, + call: &Call, + is_last_sibling: bool, + show_calls: &ShowCalls, + show_outputs: bool, + resolve_hashes: bool, + ) { + tracing::info!(""); + let contract_type = KNOWN_ADDRESSES + .get(&call.to) + .cloned() + .map(|known_address| known_address.contract_type) + .unwrap_or(ContractType::Unknown); + + let should_print = match (&contract_type, &show_calls) { + (_, ShowCalls::All) => true, + (_, ShowCalls::None) => false, + (ContractType::Unknown, _) => true, + (ContractType::Popular, _) => true, + (ContractType::Precompile, _) => false, + (ContractType::System, ShowCalls::User) => false, + (ContractType::System, ShowCalls::System) => true, + }; + + // Collect subcalls that should be printed (e.g. handle filtering) + let subcalls_to_print: Vec<&Call> = call + .calls + .iter() + .filter(|subcall| { + let subcall_contract_type = KNOWN_ADDRESSES + .get(&subcall.to) + .cloned() + .map(|known_address| known_address.contract_type) + .unwrap_or(ContractType::Unknown); + + match (&subcall_contract_type, &show_calls) { + (_, ShowCalls::All) => true, + (_, ShowCalls::None) => false, + (ContractType::Unknown, _) => true, + (ContractType::Popular, _) => true, + (ContractType::Precompile, _) => false, + (ContractType::System, ShowCalls::User) => false, + (ContractType::System, ShowCalls::System) => true, + } + }) + .collect(); + + if should_print { + let call_type_display = format!("{:?}", call.r#type).blue(); + let remaining_gas_display = to_human_size(call.gas.into()).yellow(); + let gas_used_display = format!("({})", to_human_size(call.gas_used.into())).bold(); + + let contract_display = format_address_human_readable( + call.to, + initiator, + contract_address, + format!("{:?}", call.r#type).as_str(), + ) + .unwrap_or_else(|| format!("{:}", format!("{:?}", call.to).bold())); + + // Get function signature + let function_signature = if call.input.len() >= 4 { + let sig = hex::encode(&call.input[0..4]); + if contract_type == ContractType::Precompile || !resolve_hashes { + format!("0x{}", sig) + } else { + block_on(async move { + match resolver::decode_function_selector(&sig).await { + Ok(Some(name)) => name, + Ok(None) | Err(_) => format!("0x{}", sig), + } + }) + } + } else { + "unknown".to_string() + }; + + let function_display = function_signature.cyan().bold(); + + let line = format!( + "{} [{}] {}::{} {}", + call_type_display, + remaining_gas_display, + contract_display, + function_display, + gas_used_display + ); + + // Handle errors and outputs within a new indentation scope + self.section(&line, is_last_sibling, |call_section| { + if call.revert_reason.is_some() || call.error.is_some() { + if let Some(ref reason) = call.revert_reason { + call_section.format_error(true, &format!("🔴 Revert reason: {}", reason)); + } + if let Some(ref error) = call.error { + call_section.format_error(true, &format!("🔴 Error: {}", error)); + } + } + + if show_outputs && !call.output.is_empty() { + let output_display = call + .output + .as_slice() + .iter() + .map(|byte| format!("{:02x}", byte)) + .collect::>() + .join(""); + call_section.format_log(true, &format!("Output: {}", output_display.dimmed())); + } + + // Process subcalls that should be printed + let num_subcalls = subcalls_to_print.len(); + for (i, subcall) in subcalls_to_print.iter().enumerate() { + let is_last_subcall = i == num_subcalls - 1; + call_section.print_call( + initiator, + contract_address, + subcall, + is_last_subcall, + show_calls, + show_outputs, + resolve_hashes, + ); + } + }); + } else { + // Call is not printed; process subcalls at the same indentation level + let num_subcalls = subcalls_to_print.len(); + for (i, subcall) in subcalls_to_print.iter().enumerate() { + let is_last_subcall = is_last_sibling && (i == num_subcalls - 1); + self.print_call( + initiator, + contract_address, + subcall, + is_last_subcall, + show_calls, + show_outputs, + resolve_hashes, + ); + } + } + } + + /// Prints the storage logs of the system in a structured log. + pub fn print_storage_logs( + &mut self, + log_query: &StorageLogWithPreviousValue, + pubdata_bytes: Option, + log_index: usize, + is_last: bool, + ) { + self.section(&format!("Log #{}", log_index), is_last, |log_section| { + let mut items = vec![ + ("Kind", format!("{:?}", log_query.log.kind)), + ( + "Address", + address_to_human_readable(*log_query.log.key.address()) + .unwrap_or_else(|| format!("{:?}", log_query.log.key.address())), + ), + ("Key", format!("{:#066x}", log_query.log.key.key())), + ("Read Value", format!("{:#066x}", log_query.previous_value)), + ]; + + if log_query.log.is_write() { + items.push(("Written Value", format!("{:#066x}", log_query.log.value))); + } + + let pubdata_bytes_str = pubdata_bytes + .map(|p| format!("{}", p)) + .unwrap_or_else(|| "None".to_string()); + items.push(("Pubdata Bytes", pubdata_bytes_str)); + + let num_items = items.len(); + for (i, (key, value)) in items.iter().enumerate() { + let is_last_item = i == num_items - 1; + log_section.item(is_last_item, key, value); + } + }); + } + /// Prints the VM execution results in a structured log. + pub fn print_vm_details(&mut self, result: &VmExecutionResultAndLogs) { + tracing::info!(""); + + self.section("[VM Execution Results]", true, |section| { + let stats = vec![ + ( + "Cycles Used", + to_human_size(result.statistics.cycles_used.into()), + ), + ( + "Computation Gas Used", + to_human_size(result.statistics.computational_gas_used.into()), + ), + ( + "Contracts Used", + to_human_size(result.statistics.contracts_used.into()), + ), + ]; + + for (key, value) in stats.iter() { + section.item(false, key, value); + } + + // Handle execution outcome + match &result.result { + zksync_multivm::interface::ExecutionResult::Success { .. } => { + section.item(true, "Execution Outcome", "Success"); + } + zksync_multivm::interface::ExecutionResult::Revert { output } => { + section.item(false, "Execution Outcome", "Failure"); + section.format_error( + true, + &format!("Revert Reason: {}", output.to_user_friendly_string()), + ); + } + zksync_multivm::interface::ExecutionResult::Halt { reason } => { + section.item(false, "Execution Outcome", "Failure"); + section.format_error(true, &format!("Halt Reason: {}", reason.to_string())); + } + } + }); + + tracing::info!(""); + } +} +// Builds the branched prefix for the structured logs. fn build_prefix(sibling_stack: &[bool], is_last_sibling: bool) -> String { let mut prefix = String::new(); - let depth = sibling_stack.len(); - if depth > 0 { - for &has_more_siblings in &sibling_stack[..depth - 1] { - if has_more_siblings { + if !sibling_stack.is_empty() { + for &is_last in sibling_stack { + if !is_last { prefix.push_str("│ "); } else { prefix.push_str(" "); @@ -130,9 +652,35 @@ fn build_prefix(sibling_stack: &[bool], is_last_sibling: bool) -> String { prefix } -// TODO: When refactoring other logs (e.g event, storage, vm, gas) update this function. -// Currently a close duplicate of format_address_human_readable -fn address_to_human_readable(address: H160) -> Option { +#[derive(Debug, Deserialize, Clone, PartialEq, Eq)] +pub enum ContractType { + System, + Precompile, + Popular, + Unknown, +} + +#[derive(Debug, Deserialize, Clone)] +pub struct KnownAddress { + address: H160, + name: String, + contract_type: ContractType, +} + +lazy_static! { + /// Loads the known contact addresses from the JSON file. + static ref KNOWN_ADDRESSES: HashMap = { + let json_value = serde_json::from_slice(include_bytes!("data/address_map.json")).unwrap(); + let pairs: Vec = serde_json::from_value(json_value).unwrap(); + + pairs + .into_iter() + .map(|entry| (entry.address, entry)) + .collect() + }; +} + +fn format_known_address(address: H160) -> Option { KNOWN_ADDRESSES.get(&address).map(|known_address| { let name = match known_address.contract_type { ContractType::System => known_address.name.bold().bright_blue().to_string(), @@ -146,48 +694,67 @@ fn address_to_human_readable(address: H160) -> Option { }) } +fn format_address(name: &str, address: H160, color: impl FnOnce(&str) -> String) -> String { + let name_colored = color(name); + let formatted_address = format!("{:#x}", address).dimmed(); + format!("{}{}{}", name_colored, "@".dimmed(), formatted_address) +} + +fn address_to_human_readable(address: H160) -> Option { + format_known_address(address) +} + fn format_address_human_readable( address: H160, initiator: H160, contract_address: Option, call_type: &str, ) -> Option { - let is_initiator = address == initiator; let excluded_addresses = [ H160::from_slice(&hex::decode("0000000000000000000000000000000000008006").unwrap()), H160::from_slice(&hex::decode("0000000000000000000000000000000000010000").unwrap()), ]; + let is_initiator = address == initiator; let is_contract = Some(address) == contract_address && !excluded_addresses.contains(&address); if is_initiator { - let name = "initiator".bold().green().to_string(); - let formatted_address = format!("{:#x}", address); - return Some(format!("{}{}{}", name, "@".dimmed(), formatted_address)); + return Some(format_address("initiator", address, |s| { + s.bold().green().to_string() + })); } if call_type == "Create" { - let name = "deployed".bold().bright_green().to_string(); - let formatted_address = format!("{:#x}", address); - return Some(format!("{}{}{}", name, "@".dimmed(), formatted_address)); - } else if is_contract { - let name = "contract".bold().bright_green().to_string(); - let formatted_address = format!("{:#x}", address); - return Some(format!("{}{}{}", name, "@".dimmed(), formatted_address)); + return Some(format_address("deployed", address, |s| { + s.bold().bright_green().to_string() + })); + } + if is_contract { + return Some(format_address("contract", address, |s| { + s.bold().bright_green().to_string() + })); } - KNOWN_ADDRESSES.get(&address).map(|known_address| { - let name = match known_address.contract_type { - ContractType::System => known_address.name.bold().bright_blue().to_string(), - ContractType::Precompile => known_address.name.bold().magenta().to_string(), - ContractType::Popular => known_address.name.bold().bright_green().to_string(), - ContractType::Unknown => known_address.name.dimmed().to_string(), - }; - - let formatted_address = format!("{:#x}", address).dimmed(); - format!("{}{}{}", name, "@".dimmed(), formatted_address) - }) + format_known_address(address) } +fn format_data(value: &[u8]) -> String { + if value.is_empty() { + "EMPTY".to_string() + } else { + match std::str::from_utf8(value) { + Ok(v) => format!("{}", v.truecolor(128, 128, 128)), + Err(_) => { + let hex_str = hex::encode(value); + if hex_str.len() > 200 { + format!("0x{}...", &hex_str[..200]) + } else { + format!("0x{}", hex_str) + } + } + } + } +} +// Separated from print_events. Consider the same for print_calls. fn resolve_topics(topics: &[H256], resolve_hashes: bool) -> Vec { let topics = topics.to_owned(); block_on(async move { @@ -206,70 +773,8 @@ fn resolve_topics(topics: &[H256], resolve_hashes: bool) -> Vec { }) } -pub fn print_event(event: &VmEvent, resolve_hashes: bool, is_last_sibling: bool) { - // Clone the event to avoid borrowing issues - let event = event.clone(); - let mut formatter = Formatter::new(); - - // Resolve topics before logging - let topics = resolve_topics(&event.indexed_topics, resolve_hashes); - - // Format the event address (contract) - let contract_display = address_to_human_readable(event.address) - .map(|x| format!("{:42}", x.blue())) - .unwrap_or_else(|| format!("{:42}", format!("{:?}", event.address).blue())); - - // Start the event section - formatter.section( - &format!("Event [{}]", contract_display), - !is_last_sibling, - |event_section| { - // We'll always have two subitems: Topics and Data - let total_subitems = 2; - let mut subitem_idx = 0; - - // Topics Section - subitem_idx += 1; - let is_last_subitem = subitem_idx == total_subitems; - - event_section.section("Topics", !is_last_subitem, |topics_section| { - let num_topics = topics.len(); - if num_topics == 0 { - topics_section.item(true, "Topics", "EMPTY"); - } else { - for (i, topic) in topics.iter().enumerate() { - let is_last_topic = i == num_topics - 1; - topics_section.item(is_last_topic, &format!("Topic[{}]", i), topic); - } - } - }); - - // Data Section - subitem_idx += 1; - let is_last_subitem = subitem_idx == total_subitems; - - if event.value.is_empty() { - event_section.item(is_last_subitem, "Data", "EMPTY"); - } else { - let data_str = match str::from_utf8(&event.value) { - Ok(v) => format!("{}", v.truecolor(128, 128, 128)), - Err(_) => { - let hex_str = hex::encode(&event.value); - let display_str = if hex_str.len() > 200 { - format!("{}...", &hex_str[..200]) - } else { - hex_str - }; - format!("0x{}", display_str.truecolor(128, 128, 128)) - } - }; - event_section.item(is_last_subitem, "Data", &data_str); - } - }, - ); -} - /// Amount of pubdata that given write has cost. +/// Used when displaying Storage Logs. pub enum PubdataBytesInfo { // This slot is free FreeSlot, @@ -312,228 +817,8 @@ impl PubdataBytesInfo { } } -pub fn print_call( - initiator: Address, - contract_address: Option, - call: &Call, - formatter: &mut Formatter, - is_last_sibling: bool, - show_calls: &ShowCalls, - show_outputs: bool, - resolve_hashes: bool, -) { - let contract_type = KNOWN_ADDRESSES - .get(&call.to) - .cloned() - .map(|known_address| known_address.contract_type) - .unwrap_or(ContractType::Unknown); - - let should_print = match (&contract_type, &show_calls) { - (_, ShowCalls::All) => true, - (_, ShowCalls::None) => false, - (ContractType::Unknown, _) => true, - (ContractType::Popular, _) => true, - (ContractType::Precompile, _) => false, - (ContractType::System, ShowCalls::User) => false, - (ContractType::System, ShowCalls::System) => true, - }; - - if should_print { - let call_type_display = format!("{:?}", call.r#type).blue(); - let remaining_gas_display = to_human_size(call.gas.into()).yellow(); - let gas_used_display = format!("({})", to_human_size(call.gas_used.into())).bold(); - - // Get contract display - let contract_display = format_address_human_readable( - call.to, - initiator, - contract_address, - format!("{:?}", call.r#type).as_str(), - ) - .unwrap_or_else(|| format!("{:}", format!("{:?}", call.to).bold())); - - // Get function signature - let function_signature = if call.input.len() >= 4 { - let sig = hex::encode(&call.input[0..4]); - if contract_type == ContractType::Precompile || !resolve_hashes { - format!("0x{}", sig) - } else { - block_on(async move { - match resolver::decode_function_selector(&sig).await { - Ok(Some(name)) => name, - Ok(None) | Err(_) => format!("0x{}", sig), - } - }) - } - } else { - "unknown".to_string() - }; - - let function_display = function_signature.cyan().bold(); - - // Build the line - let line = format!( - "{} [{}] {}::{} {}", - call_type_display, - remaining_gas_display, - contract_display, - function_display, - gas_used_display - ); - - // Handle errors - if call.revert_reason.is_some() || call.error.is_some() { - formatter.format_error(is_last_sibling, &line); - if let Some(ref reason) = call.revert_reason { - formatter.enter_scope(!is_last_sibling); - formatter.format_error(true, &format!("🔴 Revert reason: {}", reason)); - formatter.exit_scope(); - } - if let Some(ref error) = call.error { - formatter.enter_scope(!is_last_sibling); - formatter.format_error(true, &format!("🔴 Error: {}", error)); - formatter.exit_scope(); - } - } else { - formatter.format_log(is_last_sibling, &line); - } - - // Handle outputs - if show_outputs && !call.output.is_empty() { - let output_display = call - .output - .as_slice() - .iter() - .map(|byte| format!("{:02x}", byte)) - .collect::>() - .join(""); - - formatter.enter_scope(!is_last_sibling); - formatter.format_log(true, &format!("Output: {}", output_display.dimmed())); - formatter.exit_scope(); - } - } - - // Process subcalls - if !call.calls.is_empty() { - formatter.enter_scope(!is_last_sibling); - - let num_subcalls = call.calls.len(); - for (i, subcall) in call.calls.iter().enumerate() { - let is_last_subcall = i == num_subcalls - 1; - print_call( - initiator, - contract_address, - subcall, - formatter, - is_last_subcall, - show_calls, - show_outputs, - resolve_hashes, - ); - } - - formatter.exit_scope(); - } -} - -pub fn print_logs( - log_query: &StorageLogWithPreviousValue, - pubdata_bytes: Option, - log_index: usize, - formatter: &mut Formatter, - is_last: bool, -) { - formatter.format_log(is_last, &format!("Log #{}", log_index)); - - formatter.enter_scope(!is_last); - formatter.format_log(false, &format!("Kind: {:?}", log_query.log.kind)); - formatter.format_log( - false, - &format!( - "Address: {}", - address_to_human_readable(*log_query.log.key.address()) - .unwrap_or_else(|| format!("{}", log_query.log.key.address())) - ), - ); - formatter.format_log( - false, - &format!("Key: {:#066x}", log_query.log.key.key()), - ); - formatter.format_log( - false, - &format!("Read Value: {:#066x}", log_query.previous_value), - ); - - if log_query.log.is_write() { - formatter.format_log( - false, - &format!("Written Value: {:#066x}", log_query.log.value), - ); - } - - if let Some(pubdata_bytes) = pubdata_bytes { - formatter.format_log(true, &format!("Pubdata Bytes: {}", pubdata_bytes)); - } else { - formatter.format_log(true, "Pubdata Bytes: None"); - } - formatter.exit_scope(); -} - -pub fn print_vm_details2(result: &VmExecutionResultAndLogs) { - tracing::info!(""); - tracing::info!("[VM Execution Results]"); - - let mut formatter = Formatter::new(); - - // Log the main statistics - formatter.format_log( - false, - &format!( - "Cycles Used: {}", - to_human_size(result.statistics.cycles_used.into()) - ), - ); - formatter.format_log( - false, - &format!( - "Computation Gas Used: {}", - to_human_size(result.statistics.computational_gas_used.into()) - ), - ); - formatter.format_log( - false, - &format!( - "Contracts Used: {}", - to_human_size(result.statistics.contracts_used.into()) - ), - ); - - // Log execution outcome - match &result.result { - zksync_multivm::interface::ExecutionResult::Success { .. } => { - formatter.format_log(true, "Execution Outcome: Success"); - } - zksync_multivm::interface::ExecutionResult::Revert { output } => { - formatter.format_log(false, "Execution Outcome: Failure"); - formatter.enter_scope(true); - formatter.format_error( - true, - &format!("Revert Reason: {}", output.to_user_friendly_string()), - ); - formatter.exit_scope(); - } - zksync_multivm::interface::ExecutionResult::Halt { reason } => { - formatter.format_log(false, "Execution Outcome: Failure"); - formatter.enter_scope(true); - formatter.format_error(true, &format!("Halt Reason: {}", reason.to_string())); - formatter.exit_scope(); - } - } - - tracing::info!(""); -} - +// @dev Separate from Formatter as it does not make use of structured log format. +/// Print the transaction summary. pub fn print_transaction_summary( l2_gas_price: u64, tx: &Transaction, @@ -573,37 +858,3 @@ pub fn print_transaction_summary( ); tracing::info!("Refunded: {:.10} ETH", refunded_in_eth); } - -pub fn _print_vm_details(result: &VmExecutionResultAndLogs) { - tracing::info!(""); - tracing::info!("┌──────────────────────────┐"); - tracing::info!("│ VM EXECUTION RESULTS │"); - tracing::info!("└──────────────────────────┘"); - - tracing::info!("Cycles Used: {}", result.statistics.cycles_used); - tracing::info!( - "Computation Gas Used: {}", - result.statistics.computational_gas_used - ); - tracing::info!("Contracts Used: {}", result.statistics.contracts_used); - match &result.result { - zksync_multivm::interface::ExecutionResult::Success { .. } => {} - zksync_multivm::interface::ExecutionResult::Revert { output } => { - tracing::info!(""); - tracing::info!( - "{}", - format!( - "\n[!] Revert Reason: {}", - output.to_user_friendly_string() - ) - .on_red() - ); - } - zksync_multivm::interface::ExecutionResult::Halt { reason } => { - tracing::info!(""); - tracing::info!("{}", format!("\n[!] Halt Reason: {}", reason).on_red()); - } - } - - tracing::info!("════════════════════════════"); -} diff --git a/src/node/in_memory.rs b/src/node/in_memory.rs index dd38a9f9..3ecc274e 100644 --- a/src/node/in_memory.rs +++ b/src/node/in_memory.rs @@ -68,7 +68,7 @@ use crate::{ }, observability::Observability, system_contracts::{self, SystemContracts}, - utils::{bytecode_to_factory_dep, create_debug_output, into_jsrpc_error, to_human_size}, + utils::{bytecode_to_factory_dep, create_debug_output, into_jsrpc_error}, }; /// Max possible size of an ABI encoded tx (in bytes). @@ -1246,11 +1246,11 @@ impl InMemoryNode { let num_calls = call_traces.len(); for (i, call) in call_traces.iter().enumerate() { let is_last_sibling = i == num_calls - 1; - formatter::print_call( + let mut formatter = formatter::Formatter::new(); + formatter.print_call( tx.initiator_account(), tx.execute.contract_address, call, - &mut formatter::Formatter::new(), is_last_sibling, &inner.config.show_calls, inner.config.show_outputs, @@ -1261,383 +1261,7 @@ impl InMemoryNode { Ok(tx_result.result) } - fn display_detailed_gas_info2( - &self, - bootloader_debug_result: Option<&eyre::Result>, - spent_on_pubdata: u64, - ) -> eyre::Result<(), String> { - if let Some(bootloader_result) = bootloader_debug_result { - let bootloader_debug = bootloader_result.clone()?; - - let total_gas_limit = bootloader_debug - .total_gas_limit_from_user - .saturating_sub(bootloader_debug.reserved_gas); - let intrinsic_gas = total_gas_limit - bootloader_debug.gas_limit_after_intrinsic; - let gas_for_validation = - bootloader_debug.gas_limit_after_intrinsic - bootloader_debug.gas_after_validation; - let gas_spent_on_compute = bootloader_debug.gas_spent_on_execution - - bootloader_debug.gas_spent_on_bytecode_preparation; - let gas_used = intrinsic_gas - + gas_for_validation - + bootloader_debug.gas_spent_on_bytecode_preparation - + gas_spent_on_compute; - - let bytes_published = spent_on_pubdata / bootloader_debug.gas_per_pubdata.as_u64(); - - // Initialize the logger with an empty sibling stack - let mut logger = formatter::Formatter::new(); - logger.format_log(false, "[Gas Details]"); - - // 1. Gas Summary - logger.enter_scope(false); // Enter scope under [Gas Details], more sections follow - logger.format_log(false, "Gas Summary"); - - logger.enter_scope(true); // Items under Gas Summary - logger.format_log( - false, - &format!("Limit: {}", to_human_size(total_gas_limit)), - ); - logger.format_log(false, &format!("Used: {}", to_human_size(gas_used))); - logger.format_log( - true, - &format!( - "Refunded: {}", - to_human_size(bootloader_debug.refund_by_operator) - ), - ); - logger.exit_scope(); // Exit items under Gas Summary - - // Handle warnings - if bootloader_debug.refund_computed != bootloader_debug.refund_by_operator { - logger.format_error( - false, - &format!( - "WARNING: Refund by VM: {}, but operator refunded more: {}", - to_human_size(bootloader_debug.refund_computed), - to_human_size(bootloader_debug.refund_by_operator) - ), - ); - } - - if bootloader_debug.total_gas_limit_from_user != total_gas_limit { - logger.format_error( - false, - &format!( - "WARNING: User provided more gas ({}), but system had a lower max limit.", - to_human_size(bootloader_debug.total_gas_limit_from_user) - ), - ); - } - logger.exit_scope(); // Exit Gas Summary - - // 2. Execution Gas Breakdown - logger.enter_scope(false); // More sections follow - logger.format_log(false, "Execution Gas Breakdown"); - - logger.enter_scope(true); // Items under Execution Gas Breakdown - let gas_breakdown_items = vec![ - ( - "Transaction Setup", - intrinsic_gas, - intrinsic_gas * 100 / gas_used, - ), - ( - "Bytecode Preparation", - bootloader_debug.gas_spent_on_bytecode_preparation, - bootloader_debug.gas_spent_on_bytecode_preparation * 100 / gas_used, - ), - ( - "Account Validation", - gas_for_validation, - gas_for_validation * 100 / gas_used, - ), - ( - "Computations (Opcodes)", - gas_spent_on_compute, - gas_spent_on_compute * 100 / gas_used, - ), - ]; - - for (i, (description, amount, percentage)) in gas_breakdown_items.iter().enumerate() { - let is_last = i == gas_breakdown_items.len() - 1; - logger.format_log( - is_last, - &format!( - "{}: {} gas ({:>2}%)", - description, - to_human_size(*amount), - percentage - ), - ); - } - - logger.exit_scope(); // Exit items under Execution Gas Breakdown - logger.exit_scope(); // Exit Execution Gas Breakdown - - // 3. Transaction Setup Cost Breakdown - logger.enter_scope(false); // More sections follow - logger.format_log(false, "Transaction Setup Cost Breakdown"); - - logger.enter_scope(true); // Items under Transaction Setup Cost Breakdown - logger.format_log( - false, - &format!( - "Total Setup Cost: {} gas", - to_human_size(intrinsic_gas) - ), - ); - logger.format_log( - false, - &format!( - "Fixed Cost: {} gas ({:>2}%)", - to_human_size(bootloader_debug.intrinsic_overhead), - bootloader_debug.intrinsic_overhead * 100 / intrinsic_gas - ), - ); - logger.format_log( - true, - &format!( - "Operator Cost: {} gas ({:>2}%)", - to_human_size(bootloader_debug.operator_overhead), - bootloader_debug.operator_overhead * 100 / intrinsic_gas - ), - ); - logger.exit_scope(); // Exit items under Transaction Setup Cost Breakdown - - if bootloader_debug.required_overhead != U256::zero() { - logger.format_log( - false, - &format!( - "FYI: Operator could have charged up to {}, so you got a {}% discount.", - to_human_size(bootloader_debug.required_overhead), - (bootloader_debug.required_overhead - bootloader_debug.operator_overhead) - * 100 - / bootloader_debug.required_overhead - ), - ); - } - - logger.exit_scope(); // Exit Transaction Setup Cost Breakdown - - // 4. L1 Publishing Costs - logger.enter_scope(false); // More sections follow - logger.format_log(false, "L1 Publishing Costs"); - - logger.enter_scope(true); // Items under L1 Publishing Costs - logger.format_log( - false, - &format!( - "Published: {} bytes", - to_human_size(bytes_published.into()) - ), - ); - logger.format_log( - false, - &format!( - "Cost per Byte: {} gas", - to_human_size(bootloader_debug.gas_per_pubdata) - ), - ); - logger.format_log( - true, - &format!( - "Total Gas Cost: {} gas", - to_human_size(spent_on_pubdata.into()) - ), - ); - logger.exit_scope(); // Exit items under L1 Publishing Costs - logger.exit_scope(); // Exit L1 Publishing Costs - - // 5. Block Contribution - logger.enter_scope(true); // This is the last section - logger.format_log(true, "Block Contribution"); - - logger.enter_scope(true); // Items under Block Contribution - logger.format_log( - false, - &format!( - "Length Overhead: {} gas", - to_human_size(bootloader_debug.overhead_for_length) - ), - ); - logger.format_log( - false, - &format!( - "Slot Overhead: {} gas", - to_human_size(bootloader_debug.overhead_for_slot) - ), - ); - logger.format_log( - true, - &format!( - "Full Block Cost: ~{} L2 gas", - to_human_size( - bootloader_debug.gas_per_pubdata - * self - .inner - .read() - .unwrap() - .fee_input_provider - .get_fee_model_config() - .batch_overhead_l1_gas - ) - ), - ); - logger.exit_scope(); // Exit items under Block Contribution - logger.exit_scope(); // Exit Block Contribution - - Ok(()) - } else { - Err("Bootloader tracer didn't finish.".to_owned()) - } - } - - fn display_detailed_gas_info3( - &self, - bootloader_debug_result: Option<&eyre::Result>, - spent_on_pubdata: u64, - ) -> eyre::Result<(), String> { - if let Some(bootloader_result) = bootloader_debug_result { - let bootloader_debug = bootloader_result.clone()?; - - tracing::info!(""); - tracing::info!("[Gas Details]"); - - // Gas Summary - let total_gas_limit = bootloader_debug - .total_gas_limit_from_user - .saturating_sub(bootloader_debug.reserved_gas); - let intrinsic_gas = total_gas_limit - bootloader_debug.gas_limit_after_intrinsic; - let gas_for_validation = - bootloader_debug.gas_limit_after_intrinsic - bootloader_debug.gas_after_validation; - let gas_spent_on_compute = bootloader_debug.gas_spent_on_execution - - bootloader_debug.gas_spent_on_bytecode_preparation; - let gas_used = intrinsic_gas - + gas_for_validation - + bootloader_debug.gas_spent_on_bytecode_preparation - + gas_spent_on_compute; - - tracing::info!(" ├─ Gas Summary"); - tracing::info!( - " │ ├─ Limit: {}", - to_human_size(total_gas_limit) - ); - tracing::info!(" │ ├─ Used: {}", to_human_size(gas_used)); - tracing::info!( - " │ └─ Refunded: {}", - to_human_size(bootloader_debug.refund_by_operator) - ); - - if bootloader_debug.refund_computed != bootloader_debug.refund_by_operator { - tracing::warn!( - " │ WARNING: Refund by VM: {}, but operator refunded more: {}", - to_human_size(bootloader_debug.refund_computed), - to_human_size(bootloader_debug.refund_by_operator) - ); - } - - if bootloader_debug.total_gas_limit_from_user != total_gas_limit { - tracing::info!( - " │ WARNING: User provided more gas ({}), but system had a lower max limit.", - to_human_size(bootloader_debug.total_gas_limit_from_user) - ); - } - - // Execution Gas Breakdown - tracing::info!(" ├─ Execution Gas Breakdown"); - tracing::info!( - " │ ├─ Transaction Setup: {} gas ({:>2}%)", - to_human_size(intrinsic_gas), - intrinsic_gas * 100 / gas_used - ); - tracing::info!( - " │ ├─ Bytecode Preparation: {} gas ({:>2}%)", - to_human_size(bootloader_debug.gas_spent_on_bytecode_preparation), - bootloader_debug.gas_spent_on_bytecode_preparation * 100 / gas_used - ); - tracing::info!( - " │ ├─ Account Validation: {} gas ({:>2}%)", - to_human_size(gas_for_validation), - gas_for_validation * 100 / gas_used - ); - tracing::info!( - " │ └─ Computations (Opcodes): {} gas ({:>2}%)", - to_human_size(gas_spent_on_compute), - gas_spent_on_compute * 100 / gas_used - ); - - // Transaction Setup Cost Breakdown - tracing::info!(" ├─ Transaction Setup Cost Breakdown"); - tracing::info!( - " │ ├─ Total Setup Cost: {} gas", - to_human_size(intrinsic_gas) - ); - tracing::info!( - " │ ├─ Fixed Cost: {} gas ({:>2}%)", - to_human_size(bootloader_debug.intrinsic_overhead), - bootloader_debug.intrinsic_overhead * 100 / intrinsic_gas - ); - tracing::info!( - " │ └─ Operator Cost: {} gas ({:>2}%)", - to_human_size(bootloader_debug.operator_overhead), - bootloader_debug.operator_overhead * 100 / intrinsic_gas - ); - - if bootloader_debug.required_overhead != U256::zero() { - tracing::info!( - " │ FYI: Operator could have charged up to {}, so you got a {}% discount.", - to_human_size(bootloader_debug.required_overhead), - (bootloader_debug.required_overhead - bootloader_debug.operator_overhead) * 100 - / bootloader_debug.required_overhead - ); - } - - // L1 Publishing Costs - let bytes_published = spent_on_pubdata / bootloader_debug.gas_per_pubdata.as_u64(); - tracing::info!(" ├─ L1 Publishing Costs"); - tracing::info!( - " │ ├─ Published: {} bytes", - to_human_size(bytes_published.into()) - ); - tracing::info!( - " │ ├─ Cost per Byte: {} gas", - to_human_size(bootloader_debug.gas_per_pubdata) - ); - tracing::info!( - " │ └─ Total Gas Cost: {} gas", - to_human_size(spent_on_pubdata.into()) - ); - - // Block Contribution - tracing::info!(" └─ Block Contribution"); - tracing::info!( - " ├─ Length Overhead: {} gas", - to_human_size(bootloader_debug.overhead_for_length) - ); - tracing::info!( - " ├─ Slot Overhead: {} gas", - to_human_size(bootloader_debug.overhead_for_slot) - ); - tracing::info!( - " └─ Full Block Cost: ~{} L2 gas", - to_human_size( - bootloader_debug.gas_per_pubdata - * self - .inner - .read() - .unwrap() - .fee_input_provider - .get_fee_model_config() - .batch_overhead_l1_gas - ) - ); - - Ok(()) - } else { - Err("Bootloader tracer didn't finish.".to_owned()) - } - } - + // Prints the gas details of the transaction for debugging purposes. fn display_detailed_gas_info( &self, bootloader_debug_result: Option<&eyre::Result>, @@ -1646,163 +1270,21 @@ impl InMemoryNode { if let Some(bootloader_result) = bootloader_debug_result { let bootloader_debug = bootloader_result.clone()?; - tracing::info!("┌─────────────────────────┐"); - tracing::info!("│ GAS DETAILS │"); - tracing::info!("└─────────────────────────┘"); - - // Total amount of gas (should match tx.gas_limit). - let total_gas_limit = bootloader_debug - .total_gas_limit_from_user - .saturating_sub(bootloader_debug.reserved_gas); - - let intrinsic_gas = total_gas_limit - bootloader_debug.gas_limit_after_intrinsic; - let gas_for_validation = - bootloader_debug.gas_limit_after_intrinsic - bootloader_debug.gas_after_validation; - - let gas_spent_on_compute = bootloader_debug.gas_spent_on_execution - - bootloader_debug.gas_spent_on_bytecode_preparation; - - let gas_used = intrinsic_gas - + gas_for_validation - + bootloader_debug.gas_spent_on_bytecode_preparation - + gas_spent_on_compute; - - tracing::info!( - "Gas - Limit: {} | Used: {} | Refunded: {}", - to_human_size(total_gas_limit), - to_human_size(gas_used), - to_human_size(bootloader_debug.refund_by_operator) - ); - - if bootloader_debug.total_gas_limit_from_user != total_gas_limit { - tracing::info!( - "{}", - format!( - " WARNING: user actually provided more gas {}, but system had a lower max limit.", - to_human_size(bootloader_debug.total_gas_limit_from_user) - ) - .yellow() - ); - } - if bootloader_debug.refund_computed != bootloader_debug.refund_by_operator { - tracing::info!( - "{}", - format!( - " WARNING: Refund by VM: {}, but operator refunded more: {}", - to_human_size(bootloader_debug.refund_computed), - to_human_size(bootloader_debug.refund_by_operator) - ) - .yellow() - ); - } - - if bootloader_debug.refund_computed + gas_used != total_gas_limit { - tracing::info!( - "{}", - format!( - " WARNING: Gas totals don't match. {} != {} , delta: {}", - to_human_size(bootloader_debug.refund_computed + gas_used), - to_human_size(total_gas_limit), - to_human_size( - total_gas_limit.abs_diff(bootloader_debug.refund_computed + gas_used) - ) - ) - .yellow() - ); - } - - let bytes_published = spent_on_pubdata / bootloader_debug.gas_per_pubdata.as_u64(); - - tracing::info!( - "During execution published {} bytes to L1, @{} each - in total {} gas", - to_human_size(bytes_published.into()), - to_human_size(bootloader_debug.gas_per_pubdata), - to_human_size(spent_on_pubdata.into()) - ); - - tracing::info!("Out of {} gas used, we spent:", to_human_size(gas_used)); - tracing::info!( - " {:>15} gas ({:>2}%) for transaction setup", - to_human_size(intrinsic_gas), - to_human_size(intrinsic_gas * 100 / gas_used) - ); - tracing::info!( - " {:>15} gas ({:>2}%) for bytecode preparation (decompression etc)", - to_human_size(bootloader_debug.gas_spent_on_bytecode_preparation), - to_human_size(bootloader_debug.gas_spent_on_bytecode_preparation * 100 / gas_used) - ); - tracing::info!( - " {:>15} gas ({:>2}%) for account validation", - to_human_size(gas_for_validation), - to_human_size(gas_for_validation * 100 / gas_used) - ); - tracing::info!( - " {:>15} gas ({:>2}%) for computations (opcodes)", - to_human_size(gas_spent_on_compute), - to_human_size(gas_spent_on_compute * 100 / gas_used) - ); - - tracing::info!(""); - tracing::info!(""); - tracing::info!( - "{}", - "=== Transaction setup cost breakdown ===".to_owned().bold(), - ); + let gas_details = formatter::compute_gas_details(&bootloader_debug, spent_on_pubdata); + let mut formatter = formatter::Formatter::new(); - tracing::info!("Total cost: {}", to_human_size(intrinsic_gas).bold()); - tracing::info!( - " {:>15} gas ({:>2}%) fixed cost", - to_human_size(bootloader_debug.intrinsic_overhead), - to_human_size(bootloader_debug.intrinsic_overhead * 100 / intrinsic_gas) - ); - tracing::info!( - " {:>15} gas ({:>2}%) operator cost", - to_human_size(bootloader_debug.operator_overhead), - to_human_size(bootloader_debug.operator_overhead * 100 / intrinsic_gas) - ); + let fee_model_config = self + .inner + .read() + .unwrap() + .fee_input_provider + .get_fee_model_config(); - tracing::info!(""); - tracing::info!( - " FYI: operator could have charged up to: {}, so you got {}% discount", - to_human_size(bootloader_debug.required_overhead), - to_human_size( - (bootloader_debug.required_overhead - bootloader_debug.operator_overhead) * 100 - / bootloader_debug.required_overhead - ) - ); + formatter.print_gas_details(&gas_details, &fee_model_config); - { - let fee_model_config = self - .inner - .read() - .expect("Failed to acquire reading lock") - .fee_input_provider - .get_fee_model_config(); - tracing::info!( - "Publishing full block costs the operator around {} l2 gas", - to_human_size( - bootloader_debug.gas_per_pubdata * fee_model_config.batch_overhead_l1_gas - ), - ); - } - tracing::info!("Your transaction has contributed to filling up the block in the following way (we take the max contribution as the cost):"); - tracing::info!( - " Length overhead: {:>15}", - to_human_size(bootloader_debug.overhead_for_length) - ); - tracing::info!( - " Slot overhead: {:>15}", - to_human_size(bootloader_debug.overhead_for_slot) - ); - tracing::info!("Also, with every spent gas unit you potentially can pay some additional amount of gas for filling up the block by execution limits"); - tracing::info!( - "This overhead is included in the gas price, although now it's set to zero" - ); - tracing::info!("And with every pubdata byte, you potentially can pay an additional amount of gas for filling up the block by pubdata limit"); - tracing::info!("This overhead is included in the `gas_per_pubdata` price"); Ok(()) } else { - Err("Booloader tracer didn't finish.".to_owned()) + Err("Bootloader tracer didn't finish.".to_owned()) } } @@ -1902,6 +1384,8 @@ impl InMemoryNode { ExecutionResult::Revert { .. } => "FAILED", ExecutionResult::Halt { .. } => "HALTED", }; + + // Print transaction summary if inner.config.show_tx_summary { tracing::info!(""); formatter::print_transaction_summary( @@ -1912,30 +1396,21 @@ impl InMemoryNode { ); tracing::info!(""); } - // TODO: improve gas details - match inner.config.show_gas_details { - ShowGasDetails::None => {} - ShowGasDetails::All => { - let info = self - .display_detailed_gas_info2(bootloader_debug_result.get(), spent_on_pubdata); - if info.is_err() { - tracing::info!( - "{}\nError: {}", - "!!! FAILED TO GET DETAILED GAS INFO !!!".to_owned().red(), - info.unwrap_err() - ); - } - } + // Print gas details if enabled + if inner.config.show_gas_details != ShowGasDetails::None { + self.display_detailed_gas_info(bootloader_debug_result.get(), spent_on_pubdata) + .unwrap_or_else(|err| { + tracing::error!("{}", format!("Cannot display gas details: {err}").on_red()); + }); } - - // TODO: improve storage logs + // Print storage logs if enabled if inner.config.show_storage_logs != ShowStorageLogs::None { print_storage_logs_details(&inner.config.show_storage_logs, &tx_result); } - - // TODO: improve vm details + // Print VM details if enabled if inner.config.show_vm_details != ShowVMDetails::None { - formatter::print_vm_details2(&tx_result); + let mut formatter = formatter::Formatter::new(); + formatter.print_vm_details(&tx_result); } if !inner.config.disable_console_log { @@ -1957,11 +1432,11 @@ impl InMemoryNode { let num_calls = call_traces.len(); for (i, call) in call_traces.iter().enumerate() { let is_last_sibling = i == num_calls - 1; - formatter::print_call( + let mut formatter = formatter::Formatter::new(); + formatter.print_call( tx.initiator_account(), tx.execute.contract_address, call, - &mut formatter::Formatter::with_initial_stack(vec![false]), is_last_sibling, &inner.config.show_calls, inner.config.show_outputs, @@ -1969,17 +1444,26 @@ impl InMemoryNode { ); } } - tracing::info!(""); + // Print event logs if enabled if inner.config.show_event_logs { tracing::info!("[Events] ({} events)", tx_result.logs.events.len()); - for (i, event) in tx_result.logs.events.iter().enumerate() { let is_last = i == tx_result.logs.events.len() - 1; - formatter::print_event(event, inner.config.resolve_hashes, is_last); + let mut formatter = formatter::Formatter::new(); + formatter.print_event(event, inner.config.resolve_hashes, is_last); } } tracing::info!(""); + // TODO: Properly handle console logs. Consider adding a flag to enable console logs. + // Maybe related to issue: https://github.com/matter-labs/era-test-node/issues/205 + tracing::info!(""); + tracing::info!("==== Console logs: "); + for call in call_traces { + inner.console_log_handler.handle_call_recursive(call); + } + tracing::info!(""); + let mut bytecodes = HashMap::new(); for b in &*compressed_bytecodes { let (hash, bytecode) = bytecode_to_factory_dep(b.original.clone()).map_err(|err| { diff --git a/src/node/storage_logs.rs b/src/node/storage_logs.rs index 20584254..cda90032 100644 --- a/src/node/storage_logs.rs +++ b/src/node/storage_logs.rs @@ -97,13 +97,8 @@ pub fn print_storage_logs_details( if should_print { let is_last = index == result.logs.storage_logs.len() - 1; - formatter::print_logs( - log_query, - pubdata_bytes_info, - index + 1, - &mut formatter::Formatter::new(), - is_last, - ); + let mut formatter = formatter::Formatter::new(); + formatter.print_storage_logs(log_query, pubdata_bytes_info, index + 1, is_last); } } } From 5257865b0ac40f0d649c42658aa8817b0b9e6132 Mon Sep 17 00:00:00 2001 From: Dustin Brickwood Date: Fri, 22 Nov 2024 12:53:20 -0600 Subject: [PATCH 07/16] fix: fixes log structure --- src/formatter.rs | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/src/formatter.rs b/src/formatter.rs index d0a85a95..20d721b4 100644 --- a/src/formatter.rs +++ b/src/formatter.rs @@ -91,6 +91,12 @@ pub struct Formatter { sibling_stack: Vec, } +impl Default for Formatter { + fn default() -> Self { + Self::new() + } +} + impl Formatter { pub fn new() -> Self { Formatter { @@ -403,6 +409,7 @@ impl Formatter { ); } /// Prints the call stack of either the system or user calls in a structured log. + #[allow(clippy::too_many_arguments)] pub fn print_call( &mut self, initiator: Address, @@ -590,7 +597,7 @@ impl Formatter { tracing::info!(""); self.section("[VM Execution Results]", true, |section| { - let stats = vec![ + let stats = [ ( "Cycles Used", to_human_size(result.statistics.cycles_used.into()), @@ -623,7 +630,7 @@ impl Formatter { } zksync_multivm::interface::ExecutionResult::Halt { reason } => { section.item(false, "Execution Outcome", "Failure"); - section.format_error(true, &format!("Halt Reason: {}", reason.to_string())); + section.format_error(true, &format!("Halt Reason: {}", reason)); } } }); From 2a1d0eb56b3fa5235d366719a76093341d9fc15b Mon Sep 17 00:00:00 2001 From: Dustin Brickwood Date: Fri, 22 Nov 2024 12:58:44 -0600 Subject: [PATCH 08/16] chore: clean up --- src/formatter2.rs | 511 ---------------------------------------------- 1 file changed, 511 deletions(-) delete mode 100644 src/formatter2.rs diff --git a/src/formatter2.rs b/src/formatter2.rs deleted file mode 100644 index 92d47719..00000000 --- a/src/formatter2.rs +++ /dev/null @@ -1,511 +0,0 @@ -//! Helper methods to display transaction data in more human readable way. -use crate::{config::show_details::ShowCalls, resolver}; - -use colored::Colorize; - -use serde::Deserialize; -use std::collections::HashMap; -use std::str; - -use crate::fork::block_on; -use zksync_types::H160; - -use crate::utils::{calculate_eth_cost, format_gwei, to_human_size}; -use lazy_static::lazy_static; -use zksync_multivm::interface::{Call, VmEvent, VmExecutionResultAndLogs}; -use zksync_types::Address; -use zksync_types::{StorageLogWithPreviousValue, Transaction}; - -#[derive(Debug, Deserialize, Clone, PartialEq, Eq)] -pub enum ContractType { - System, - Precompile, - Popular, - Unknown, -} - -#[derive(Debug, Deserialize, Clone)] -pub struct KnownAddress { - address: H160, - name: String, - contract_type: ContractType, -} - -lazy_static! { - /// Loads the known contact addresses from the JSON file. - static ref KNOWN_ADDRESSES: HashMap = { - let json_value = serde_json::from_slice(include_bytes!("data/address_map.json")).unwrap(); - let pairs: Vec = serde_json::from_value(json_value).unwrap(); - - pairs - .into_iter() - .map(|entry| (entry.address, entry)) - .collect() - }; -} -// TODO: When refactoring other logs (e.g event, storage, vm, gas) update this function. -// Currently a close duplicate of format_address_human_readable -fn address_to_human_readable(address: H160) -> Option { - KNOWN_ADDRESSES.get(&address).map(|known_address| { - let name = match known_address.contract_type { - ContractType::System => known_address.name.bold().bright_blue().to_string(), - ContractType::Precompile => known_address.name.bold().magenta().to_string(), - ContractType::Popular => known_address.name.bold().bright_green().to_string(), - ContractType::Unknown => known_address.name.dimmed().to_string(), - }; - - let formatted_address = format!("{:#x}", address).dimmed(); - format!("{}{}{}", name, "@".dimmed(), formatted_address) - }) -} - -fn format_address_human_readable( - address: H160, - initiator: H160, - contract_address: Option, - call_type: &str, -) -> Option { - let is_initiator = address == initiator; - let excluded_addresses = [ - H160::from_slice(&hex::decode("0000000000000000000000000000000000008006").unwrap()), - H160::from_slice(&hex::decode("0000000000000000000000000000000000010000").unwrap()), - ]; - - let is_contract = Some(address) == contract_address && !excluded_addresses.contains(&address); - - if is_initiator { - let name = "initiator".bold().green().to_string(); - let formatted_address = format!("{:#x}", address); - return Some(format!("{}{}{}", name, "@".dimmed(), formatted_address)); - } - if call_type == "Create" { - let name = "deployed".bold().bright_green().to_string(); - let formatted_address = format!("{:#x}", address); - return Some(format!("{}{}{}", name, "@".dimmed(), formatted_address)); - } else if is_contract { - let name = "contract".bold().bright_green().to_string(); - let formatted_address = format!("{:#x}", address); - return Some(format!("{}{}{}", name, "@".dimmed(), formatted_address)); - } - - KNOWN_ADDRESSES.get(&address).map(|known_address| { - let name = match known_address.contract_type { - ContractType::System => known_address.name.bold().bright_blue().to_string(), - ContractType::Precompile => known_address.name.bold().magenta().to_string(), - ContractType::Popular => known_address.name.bold().bright_green().to_string(), - ContractType::Unknown => known_address.name.dimmed().to_string(), - }; - - let formatted_address = format!("{:#x}", address).dimmed(); - format!("{}{}{}", name, "@".dimmed(), formatted_address) - }) -} - -/// Pretty-prints event object using the new structured log format. -/// If `resolve_hashes` is true, attempts to resolve topic hashes. -pub fn print_event(event: &VmEvent, resolve_hashes: bool) { - let event = event.clone(); - block_on(async move { - let mut topics: Vec = vec![]; - - // Resolve or fallback to raw hex topics - for topic in event.indexed_topics.iter() { - let resolved = if resolve_hashes { - resolver::decode_event_selector(&format!("{:#x}", topic)) - .await - .unwrap_or(None) - } else { - None - }; - - topics.push(resolved.unwrap_or_else(|| format!("{:#x}", topic))); - } - - // Event address (contract) - let contract_display = address_to_human_readable(event.address) - .map(|x| format!("{:42}", x.blue())) - .unwrap_or(format!("{:42}", format!("{:?}", event.address).blue())); - - tracing::info!(" ├─ Event [{}]", contract_display); - - // Topics - if topics.is_empty() { - tracing::info!(" │ └─ Topics: EMPTY"); - } else { - tracing::info!(" │ ├─ Topics:"); - for (i, topic) in topics.iter().enumerate() { - let prefix = if i + 1 == topics.len() { - "└─" - } else { - "├─" - }; - tracing::info!(" │ │ {} Topic[{}]: {}", prefix, i, topic); - } - } - - // Data - if event.value.is_empty() { - tracing::info!(" │ └─ Data: EMPTY"); - } else { - match str::from_utf8(&event.value) { - Ok(v) => { - tracing::info!(" │ └─ Data (String): {}", v.truecolor(128, 128, 128)); - } - Err(_) => { - let hex_str = hex::encode(&event.value); - let display_str = if hex_str.len() > 200 { - format!("{}...", &hex_str[..200]) - } else { - hex_str.to_string() - }; - - tracing::info!( - " │ └─ Data (Hex): 0x{}", - display_str.truecolor(128, 128, 128) - ); - } - } - } - - tracing::info!(""); - }); -} - -/// Amount of pubdata that given write has cost. -pub enum PubdataBytesInfo { - // This slot is free - FreeSlot, - // This slot costs this much. - Paid(u32), - // This happens when we already paid a little for this slot in the past. - // This slots costs additional X, the total cost is Y. - AdditionalPayment(u32, u32), - // We already paid for this slot in this transaction. - PaidAlready, -} - -impl std::fmt::Display for PubdataBytesInfo { - fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { - match self { - PubdataBytesInfo::FreeSlot => write!(f, "Free Slot (no cost)"), - PubdataBytesInfo::Paid(cost) => { - write!(f, "Paid: {} bytes", to_human_size((*cost).into())) - } - PubdataBytesInfo::AdditionalPayment(additional_cost, total_cost) => write!( - f, - "Additional Payment: {} bytes (Total: {} bytes)", - to_human_size((*additional_cost).into()), - to_human_size((*total_cost).into()) - ), - PubdataBytesInfo::PaidAlready => write!(f, "Already Paid (no additional cost)"), - } - } -} - -impl PubdataBytesInfo { - // Whether the slot incurs any cost - pub fn does_cost(&self) -> bool { - match self { - PubdataBytesInfo::FreeSlot => false, - PubdataBytesInfo::Paid(_) => true, - PubdataBytesInfo::AdditionalPayment(_, _) => true, - PubdataBytesInfo::PaidAlready => false, - } - } -} - -fn build_prefix(sibling_stack: &Vec) -> String { - let mut prefix = String::new(); - for &has_more_siblings in sibling_stack { - if has_more_siblings { - prefix.push_str("│ "); - } else { - prefix.push_str(" "); - } - } - prefix -} - -#[allow(clippy::too_many_arguments)] -pub fn print_call( - initiator: Address, - contract_address: Option, - call: &Call, - sibling_stack: &Vec, - is_last_sibling: bool, - show_calls: &ShowCalls, - show_outputs: bool, - resolve_hashes: bool, -) { - let contract_type = KNOWN_ADDRESSES - .get(&call.to) - .cloned() - .map(|known_address| known_address.contract_type) - .unwrap_or(ContractType::Unknown); - - let should_print = match (&contract_type, &show_calls) { - (_, ShowCalls::All) => true, - (_, ShowCalls::None) => false, - (ContractType::Unknown, _) => true, - (ContractType::Popular, _) => true, - (ContractType::Precompile, _) => false, - (ContractType::System, ShowCalls::User) => false, - (ContractType::System, ShowCalls::System) => true, - }; - - if should_print { - let prefix = build_prefix(sibling_stack); - let branch = if is_last_sibling { - "└─ " - } else { - "├─ " - }; - let full_prefix = format!("{}{}", prefix, branch); - - let call_type_display = format!("{:?}", call.r#type).blue(); - let remaining_gas_display = to_human_size(call.gas.into()).yellow(); - let gas_used_display = format!("({})", to_human_size(call.gas_used.into())).bold(); - - // Get contract display - let contract_display = format_address_human_readable( - call.to, - initiator, - contract_address, - format!("{:?}", call.r#type).as_str(), - ) - .map(|x| x.to_string()) - .unwrap_or(format!("{:}", format!("{:?}", call.to).bold())); - - // Get function signature - let function_signature = if call.input.len() >= 4 { - let sig = hex::encode(&call.input[0..4]); - if contract_type == ContractType::Precompile || !resolve_hashes { - format!("0x{}", sig) - } else { - block_on(async move { - match resolver::decode_function_selector(&sig).await { - Ok(Some(name)) => name, - Ok(None) | Err(_) => format!("0x{}", sig), - } - }) - } - } else { - "unknown".to_string() - }; - - let function_display = function_signature.cyan().bold(); - - // Build the line - let line = format!( - "{}{} [{}] {}::{} {}", - full_prefix, - call_type_display, - remaining_gas_display, - contract_display, - function_display, - gas_used_display - ); - - // Handle errors - if call.revert_reason.is_some() || call.error.is_some() { - tracing::info!("{}", line.red()); - if let Some(ref reason) = call.revert_reason { - let error_line = format!("{} └─ 🔴 Revert reason: {}", prefix, reason); - tracing::info!("{}", error_line.red()); - } - if let Some(ref error) = call.error { - let error_line = format!("{} └─ 🔴 Error: {}", prefix, error); - tracing::info!("{}", error_line.red()); - } - } else { - tracing::info!("{}", line); - } - - // Handle outputs - if show_outputs && !call.output.is_empty() { - let output_display = call - .output - .as_slice() - .iter() - .map(|byte| format!("{:02x}", byte)) - .collect::>() - .join(""); - - let output_branch = if is_last_sibling { - " └── Output: ".dimmed() - } else { - " ├── Output: ".dimmed() - }; - - let output_line = format!("{}{}", full_prefix, output_branch) + &output_display; - tracing::info!("{}", output_line); - } - } - - // Process subcalls - let num_subcalls = call.calls.len(); - if num_subcalls > 0 { - let mut new_sibling_stack = sibling_stack.clone(); - new_sibling_stack.push(!is_last_sibling); - for (i, subcall) in call.calls.iter().enumerate() { - let is_last_subcall = i == num_subcalls - 1; - print_call( - initiator, - contract_address, - subcall, - &new_sibling_stack, - is_last_subcall, - show_calls, - show_outputs, - resolve_hashes, - ); - } - } -} - -pub fn print_transaction_summary( - l2_gas_price: u64, - tx: &Transaction, - tx_result: &VmExecutionResultAndLogs, - status: &str, -) { - // Calculate used and refunded gas - let used_gas = tx.gas_limit() - tx_result.refunds.gas_refunded; - let paid_in_eth = calculate_eth_cost(l2_gas_price, used_gas.as_u64()); - - let refunded_gas = tx_result.refunds.gas_refunded; - - // Calculate refunded gas in ETH - let refunded_in_eth = calculate_eth_cost(l2_gas_price, refunded_gas); - - let emoji = match status { - "SUCCESS" => "✅", - "FAILED" => "❌", - "HALTED" => "⏸️", - _ => "⚠️", - }; - - tracing::info!("{} [{}] Hash: {:?}", emoji, status, tx.hash()); - tracing::info!("Initiator: {:?}", tx.initiator_account()); - tracing::info!("Payer: {:?}", tx.payer()); - tracing::info!( - "Gas Usage: Limit: {} | Used: {} | Refunded: {}", - to_human_size(tx.gas_limit()), - to_human_size(used_gas), - to_human_size(tx_result.refunds.gas_refunded.into()) - ); - tracing::info!( - "Paid: {:.10} ETH ({} gas * {})", - paid_in_eth, - used_gas, - format_gwei(l2_gas_price.into()) - ); - tracing::info!("Refunded: {:.10} ETH", refunded_in_eth); -} - -pub fn print_logs( - log_query: &StorageLogWithPreviousValue, - pubdata_bytes: Option, - log_index: usize, - is_last: bool, -) { - let prefix = if is_last { "└─" } else { "├─" }; - tracing::info!(" {} Log #{}", prefix, log_index); - tracing::info!(" │ ├─ Kind: {:?}", log_query.log.kind); - tracing::info!( - " │ ├─ Address: {}", - address_to_human_readable(*log_query.log.key.address()) - .unwrap_or_else(|| format!("{}", log_query.log.key.address())) - ); - tracing::info!( - " │ ├─ Key: {:#066x}", - log_query.log.key.key() - ); - tracing::info!( - " │ ├─ Read Value: {:#066x}", - log_query.previous_value - ); - - if log_query.log.is_write() { - tracing::info!(" │ ├─ Written Value: {:#066x}", log_query.log.value); - } - - if let Some(pubdata_bytes) = pubdata_bytes { - tracing::info!(" │ └─ Pubdata Bytes: {}", pubdata_bytes); - } else { - tracing::info!(" │ └─ Pubdata Bytes: None"); - } -} - -pub fn print_vm_details2(result: &VmExecutionResultAndLogs) { - tracing::info!(""); - tracing::info!("[VM Execution Results]"); - - // Log the main statistics - tracing::info!( - " ├─ Cycles Used: {}", - to_human_size(result.statistics.cycles_used.into()) - ); - tracing::info!( - " ├─ Computation Gas Used: {}", - to_human_size(result.statistics.computational_gas_used.into()) - ); - tracing::info!( - " ├─ Contracts Used: {}", - to_human_size(result.statistics.contracts_used.into()) - ); - - // Log execution outcome - match &result.result { - zksync_multivm::interface::ExecutionResult::Success { .. } => { - tracing::info!(" └─ Execution Outcome: Success"); - } - zksync_multivm::interface::ExecutionResult::Revert { output } => { - tracing::info!(" ├─ Execution Outcome: Failure"); - tracing::info!( - " │ └─ Revert Reason: {}", - output.to_user_friendly_string().red() - ); - } - zksync_multivm::interface::ExecutionResult::Halt { reason } => { - tracing::info!(" ├─ Execution Outcome: Failure"); - tracing::info!(" │ └─ Halt Reason: {}", reason.to_string().red()); - } - } - - tracing::info!(""); -} - -pub fn print_vm_details(result: &VmExecutionResultAndLogs) { - tracing::info!(""); - tracing::info!("┌──────────────────────────┐"); - tracing::info!("│ VM EXECUTION RESULTS │"); - tracing::info!("└──────────────────────────┘"); - - tracing::info!("Cycles Used: {}", result.statistics.cycles_used); - tracing::info!( - "Computation Gas Used: {}", - result.statistics.computational_gas_used - ); - tracing::info!("Contracts Used: {}", result.statistics.contracts_used); - match &result.result { - zksync_multivm::interface::ExecutionResult::Success { .. } => {} - zksync_multivm::interface::ExecutionResult::Revert { output } => { - tracing::info!(""); - tracing::info!( - "{}", - format!( - "\n[!] Revert Reason: {}", - output.to_user_friendly_string() - ) - .on_red() - ); - } - zksync_multivm::interface::ExecutionResult::Halt { reason } => { - tracing::info!(""); - tracing::info!("{}", format!("\n[!] Halt Reason: {}", reason).on_red()); - } - } - - tracing::info!("════════════════════════════"); -} From f79fade70b1e083941c8932fde1c7c8d014e353a Mon Sep 17 00:00:00 2001 From: Dustin Brickwood Date: Fri, 22 Nov 2024 13:35:43 -0600 Subject: [PATCH 09/16] fix: address issue with event topics, being filtered, clean up and udpate comments --- src/config/mod.rs | 6 ++-- src/formatter.rs | 73 ++++++++++++++++++++----------------------- src/node/in_memory.rs | 1 + 3 files changed, 38 insertions(+), 42 deletions(-) diff --git a/src/config/mod.rs b/src/config/mod.rs index 065f2900..f141458c 100644 --- a/src/config/mod.rs +++ b/src/config/mod.rs @@ -606,9 +606,9 @@ impl TestNodeConfig { /// Applies the defaults for debug mode. #[must_use] pub fn with_debug_mode(mut self) -> Self { - self.show_calls = ShowCalls::User; // Set show_calls to User - self.resolve_hashes = true; // Enable resolving hashes - self.show_gas_details = ShowGasDetails::All; // Enable detailed gas logs + self.show_calls = ShowCalls::User; + self.resolve_hashes = true; + self.show_gas_details = ShowGasDetails::All; self } diff --git a/src/formatter.rs b/src/formatter.rs index 20d721b4..f76a5a67 100644 --- a/src/formatter.rs +++ b/src/formatter.rs @@ -16,7 +16,7 @@ use zksync_types::{ }; // @dev elected to have GasDetails struct as we can do more with it in the future -// More detailed understanding of gas errors and gas usage +// We can provide more detailed understanding of gas errors and gas usage #[derive(Debug, Deserialize, Clone, PartialEq, Eq)] pub struct GasDetails { total_gas_limit: U256, @@ -87,6 +87,7 @@ pub fn compute_gas_details( } } +/// Responsible for formatting the data in a structured log. pub struct Formatter { sibling_stack: Vec, } @@ -98,16 +99,13 @@ impl Default for Formatter { } impl Formatter { + /// Creates a new formatter with an empty sibling stack. pub fn new() -> Self { Formatter { sibling_stack: Vec::new(), } } - - pub fn with_initial_stack(sibling_stack: Vec) -> Self { - Formatter { sibling_stack } - } - + /// Logs a section with a title, applies a scoped function, and manages sibling hierarchy. pub fn section(&mut self, title: &str, is_last_sibling: bool, f: F) where F: FnOnce(&mut Self), @@ -117,41 +115,27 @@ impl Formatter { f(self); self.exit_scope(); } - - pub fn subsection(&mut self, title: &str, is_last_sibling: bool, f: F) - where - F: FnOnce(&mut Self), - { - self.format_log(is_last_sibling, title); - self.enter_scope(is_last_sibling); - f(self); - self.exit_scope(); - } - + /// Logs a key-value item as part of the formatted output. pub fn item(&mut self, is_last_sibling: bool, key: &str, value: &str) { self.format_log( is_last_sibling, &format!("{}: {}", key.bold(), value.dimmed()), ); } - - pub fn warning(&mut self, is_last_sibling: bool, message: &str) { - self.format_error(is_last_sibling, &format!("WARNING: {}", message)); - } - + /// Enters a new scope for nested logging, tracking sibling relationships. pub fn enter_scope(&mut self, has_more_siblings: bool) { self.sibling_stack.push(has_more_siblings); } - + /// Exits the current logging scope, removing the last sibling marker. pub fn exit_scope(&mut self) { self.sibling_stack.pop(); } - + /// Logs a formatted message with a hierarchical prefix. pub fn format_log(&self, is_last_sibling: bool, message: &str) { let prefix = build_prefix(&self.sibling_stack, is_last_sibling); tracing::info!("{}{}", prefix, message); } - + /// Logs a formatted error message with a hierarchical prefix. pub fn format_error(&self, is_last_sibling: bool, message: &str) { let prefix = build_prefix(&self.sibling_stack, is_last_sibling); tracing::info!("{}", format!("{}{}", prefix, message).red()); @@ -213,7 +197,7 @@ impl Formatter { let mut item_index = 0; - // 1. Gas Summary + // Gas Summary let is_last_sibling = item_index == total_items - 1; gas_details_section.section("Gas Summary", is_last_sibling, |gas_summary_section| { let items = vec![ @@ -237,7 +221,7 @@ impl Formatter { item_index += 1; } - // 2. Execution Gas Breakdown + // Execution Gas Breakdown let is_last_sibling = item_index == total_items - 1; gas_details_section.section( "Execution Gas Breakdown", @@ -281,7 +265,7 @@ impl Formatter { ); item_index += 1; - // 3. Transaction Setup Cost Breakdown + // Transaction Setup Cost Breakdown let is_last_sibling = item_index == total_items - 1; gas_details_section.section( "Transaction Setup Cost Breakdown", @@ -319,7 +303,7 @@ impl Formatter { ); item_index += 1; - // 4. L1 Publishing Costs + // L1 Publishing Costs let is_last_sibling = item_index == total_items - 1; gas_details_section.section( "L1 Publishing Costs", @@ -349,7 +333,7 @@ impl Formatter { ); item_index += 1; - // 5. Block Contribution + // Block Contribution let is_last_sibling = item_index == total_items - 1; gas_details_section.section("Block Contribution", is_last_sibling, |block_section| { let full_block_cost = gas_per_pubdata * fee_model_config.batch_overhead_l1_gas; @@ -379,10 +363,21 @@ impl Formatter { } /// Prints the events of a contract in a structured log. pub fn print_event(&mut self, event: &VmEvent, resolve_hashes: bool, is_last_sibling: bool) { - tracing::info!(""); let event = event.clone(); - let topics = resolve_topics(&event.indexed_topics, resolve_hashes); + let resolved_topics = resolve_topics(&event.indexed_topics, resolve_hashes); + let topics: Vec = event + .indexed_topics + .iter() + .zip(resolved_topics.iter()) + .map(|(original, resolved)| { + if resolved.is_empty() { + format!("{:#x}", original) + } else { + resolved.clone() + } + }) + .collect(); let contract_display = address_to_human_readable(event.address) .map(|x| format!("{:42}", x.blue())) @@ -392,7 +387,7 @@ impl Formatter { &format!("Event [{}]", contract_display), is_last_sibling, |event_section| { - event_section.subsection("Topics", false, |topics_section| { + event_section.section("Topics", false, |topics_section| { let num_topics = topics.len(); if num_topics == 0 { topics_section.item(true, "Topics", "EMPTY"); @@ -420,7 +415,6 @@ impl Formatter { show_outputs: bool, resolve_hashes: bool, ) { - tracing::info!(""); let contract_type = KNOWN_ADDRESSES .get(&call.to) .cloned() @@ -502,6 +496,7 @@ impl Formatter { ); // Handle errors and outputs within a new indentation scope + // TODO: can make this more informative by adding "Suggested action" for errors self.section(&line, is_last_sibling, |call_section| { if call.revert_reason.is_some() || call.error.is_some() { if let Some(ref reason) = call.revert_reason { @@ -555,7 +550,6 @@ impl Formatter { } } } - /// Prints the storage logs of the system in a structured log. pub fn print_storage_logs( &mut self, @@ -717,6 +711,7 @@ fn format_address_human_readable( contract_address: Option, call_type: &str, ) -> Option { + // Exclude ContractDeployer and Create2Factory addresses let excluded_addresses = [ H160::from_slice(&hex::decode("0000000000000000000000000000000000008006").unwrap()), H160::from_slice(&hex::decode("0000000000000000000000000000000000010000").unwrap()), @@ -767,10 +762,10 @@ fn resolve_topics(topics: &[H256], resolve_hashes: bool) -> Vec { block_on(async move { let futures = topics.into_iter().map(|topic| async move { if resolve_hashes { - resolver::decode_event_selector(&format!("{:#x}", topic)) - .await - .unwrap_or(None) - .unwrap_or_else(|| format!("{:#x}", topic)) + match resolver::decode_event_selector(&format!("{:#x}", topic)).await { + Ok(Some(resolved)) => resolved, + Ok(None) | Err(_) => format!("{:#x}", topic), + } } else { format!("{:#x}", topic) } diff --git a/src/node/in_memory.rs b/src/node/in_memory.rs index 3ecc274e..79bdf4cf 100644 --- a/src/node/in_memory.rs +++ b/src/node/in_memory.rs @@ -1238,6 +1238,7 @@ impl InMemoryNode { inner.console_log_handler.handle_call_recursive(call); } } + tracing::info!(""); tracing::info!( "[Transaction Execution] ({} calls)", From a31863a6229a5fbef6001e5b9eb3cb6e83c95ae2 Mon Sep 17 00:00:00 2001 From: Dustin Brickwood Date: Sat, 23 Nov 2024 18:11:09 -0600 Subject: [PATCH 10/16] chore: add paid field --- src/formatter.rs | 1 + 1 file changed, 1 insertion(+) diff --git a/src/formatter.rs b/src/formatter.rs index f76a5a67..1f01b3fc 100644 --- a/src/formatter.rs +++ b/src/formatter.rs @@ -204,6 +204,7 @@ impl Formatter { ("Limit", to_human_size(total_gas_limit)), ("Used", to_human_size(gas_used)), ("Refunded", to_human_size(refund_by_operator)), + ("Paid:", to_human_size(total_gas_limit - refund_by_operator)), ]; let num_items = items.len(); From 848581f955c63a08ff3e64049a8aa8b1b0898e09 Mon Sep 17 00:00:00 2001 From: Dustin Brickwood Date: Mon, 25 Nov 2024 07:49:19 -0600 Subject: [PATCH 11/16] fix: address broken test --- src/config/cli.rs | 4 ---- 1 file changed, 4 deletions(-) diff --git a/src/config/cli.rs b/src/config/cli.rs index 2f2f551c..9f0e1e29 100644 --- a/src/config/cli.rs +++ b/src/config/cli.rs @@ -96,10 +96,6 @@ pub struct Cli { /// Show call output information. pub show_outputs: Option, - #[arg(short, long, help_heading = "Debugging Options")] - /// Show event logs information. - pub show_event_logs: Option, - #[arg(long, help_heading = "Debugging Options")] /// Show storage log information. pub show_storage_logs: Option, From ddd02395932ccc51709a0cd830b232e21022bfcf Mon Sep 17 00:00:00 2001 From: Dustin Brickwood Date: Fri, 29 Nov 2024 11:02:02 -0600 Subject: [PATCH 12/16] chore: minor fixes --- src/config/mod.rs | 36 +++++------------------------------- src/node/in_memory.rs | 11 ++--------- 2 files changed, 7 insertions(+), 40 deletions(-) diff --git a/src/config/mod.rs b/src/config/mod.rs index f141458c..58bc84ad 100644 --- a/src/config/mod.rs +++ b/src/config/mod.rs @@ -77,8 +77,6 @@ pub struct TestNodeConfig { pub show_vm_details: ShowVMDetails, /// Level of detail for gas usage logs pub show_gas_details: ShowGasDetails, - /// Whether to show event logs - pub show_event_logs: bool, /// Whether to resolve hash references pub resolve_hashes: bool, /// Don’t print anything on startup if true @@ -153,7 +151,6 @@ impl Default for TestNodeConfig { show_storage_logs: Default::default(), show_vm_details: Default::default(), show_gas_details: Default::default(), - show_event_logs: false, resolve_hashes: false, silent: false, system_contracts_options: Default::default(), @@ -670,6 +667,11 @@ impl TestNodeConfig { self } + /// Get the visibility of event logs + pub fn get_show_event_logs(&self) -> bool { + self.show_event_logs + } + // Enable or disable printing of `console.log` invocations to stdout #[must_use] pub fn with_disable_console_log(mut self, disable_console_log: Option) -> Self { @@ -726,20 +728,6 @@ impl TestNodeConfig { self.show_gas_details } - /// Set the visibility of event logs - #[must_use] - pub fn with_show_event_logs(mut self, show_event_logs: Option) -> Self { - if let Some(show_event_logs) = show_event_logs { - self.show_event_logs = show_event_logs; - } - self - } - - /// Get the visibility of event logs - pub fn get_show_event_logs(&self) -> bool { - self.show_event_logs - } - /// Set show outputs #[must_use] pub fn with_show_outputs(mut self, show_outputs: Option) -> Self { @@ -796,20 +784,6 @@ impl TestNodeConfig { self } - /// Set the detail level of VM execution logs - #[must_use] - pub fn with_vm_log_detail(mut self, detail: Option) -> Self { - if let Some(detail) = detail { - self.show_vm_details = detail; - } - self - } - - /// Get the detail level of VM execution logs - pub fn get_vm_log_detail(&self) -> ShowVMDetails { - self.show_vm_details - } - /// Sets the balance of the genesis accounts in the genesis block #[must_use] pub fn with_genesis_balance>(mut self, balance: U) -> Self { diff --git a/src/node/in_memory.rs b/src/node/in_memory.rs index 79bdf4cf..40fb53f6 100644 --- a/src/node/in_memory.rs +++ b/src/node/in_memory.rs @@ -1426,6 +1426,7 @@ impl InMemoryNode { // TODO: improve call traces if inner.config.show_calls != ShowCalls::None { + tracing::info!(""); tracing::info!( "[Transaction Execution] ({} calls)", call_traces[0].calls.len() @@ -1447,6 +1448,7 @@ impl InMemoryNode { } // Print event logs if enabled if inner.config.show_event_logs { + tracing::info!(""); tracing::info!("[Events] ({} events)", tx_result.logs.events.len()); for (i, event) in tx_result.logs.events.iter().enumerate() { let is_last = i == tx_result.logs.events.len() - 1; @@ -1456,15 +1458,6 @@ impl InMemoryNode { } tracing::info!(""); - // TODO: Properly handle console logs. Consider adding a flag to enable console logs. - // Maybe related to issue: https://github.com/matter-labs/era-test-node/issues/205 - tracing::info!(""); - tracing::info!("==== Console logs: "); - for call in call_traces { - inner.console_log_handler.handle_call_recursive(call); - } - tracing::info!(""); - let mut bytecodes = HashMap::new(); for b in &*compressed_bytecodes { let (hash, bytecode) = bytecode_to_factory_dep(b.original.clone()).map_err(|err| { From 5836b76207d038dc551f2117307a8b5fc944de2e Mon Sep 17 00:00:00 2001 From: Dustin Brickwood Date: Fri, 29 Nov 2024 15:49:43 -0600 Subject: [PATCH 13/16] chore: fix lint --- src/console_log.rs | 6 +++++- src/node/in_memory.rs | 44 +++++++++++++++++++------------------------ 2 files changed, 24 insertions(+), 26 deletions(-) diff --git a/src/console_log.rs b/src/console_log.rs index f3514a4c..3e516c27 100644 --- a/src/console_log.rs +++ b/src/console_log.rs @@ -59,7 +59,11 @@ impl ConsoleLogHandler { tokens.iter().map(|t| format!("{}", t)).join(" ") }) }); - tracing::info!("{}", message.cyan()); + if !message.is_empty() { + tracing::info!(""); + tracing::info!("==== Console logs: "); + tracing::info!("{}", message.cyan()); + } } } diff --git a/src/node/in_memory.rs b/src/node/in_memory.rs index 40fb53f6..bb78c21a 100644 --- a/src/node/in_memory.rs +++ b/src/node/in_memory.rs @@ -1232,31 +1232,30 @@ impl InMemoryNode { } if !inner.config.disable_console_log { - tracing::info!(""); - tracing::info!("=== Console Logs: "); for call in &call_traces { inner.console_log_handler.handle_call_recursive(call); } } - tracing::info!(""); - tracing::info!( - "[Transaction Execution] ({} calls)", - call_traces[0].calls.len() - ); - let num_calls = call_traces.len(); - for (i, call) in call_traces.iter().enumerate() { - let is_last_sibling = i == num_calls - 1; - let mut formatter = formatter::Formatter::new(); - formatter.print_call( - tx.initiator_account(), - tx.execute.contract_address, - call, - is_last_sibling, - &inner.config.show_calls, - inner.config.show_outputs, - inner.config.resolve_hashes, + if inner.config.show_calls != ShowCalls::None { + tracing::info!( + "[Transaction Execution] ({} calls)", + call_traces[0].calls.len() ); + let num_calls = call_traces.len(); + for (i, call) in call_traces.iter().enumerate() { + let is_last_sibling = i == num_calls - 1; + let mut formatter = formatter::Formatter::new(); + formatter.print_call( + tx.initiator_account(), + tx.execute.contract_address, + call, + is_last_sibling, + &inner.config.show_calls, + inner.config.show_outputs, + inner.config.resolve_hashes, + ); + } } Ok(tx_result.result) @@ -1415,16 +1414,11 @@ impl InMemoryNode { } if !inner.config.disable_console_log { - tracing::info!(""); - tracing::info!("==== Console logs: "); - for call in call_traces { inner.console_log_handler.handle_call_recursive(call); } } - tracing::info!(""); - // TODO: improve call traces if inner.config.show_calls != ShowCalls::None { tracing::info!(""); tracing::info!( @@ -1455,8 +1449,8 @@ impl InMemoryNode { let mut formatter = formatter::Formatter::new(); formatter.print_event(event, inner.config.resolve_hashes, is_last); } + tracing::info!(""); } - tracing::info!(""); let mut bytecodes = HashMap::new(); for b in &*compressed_bytecodes { From 938a8bccb360c85c8c9900eb095005f8b9f978c1 Mon Sep 17 00:00:00 2001 From: Dustin Brickwood Date: Fri, 29 Nov 2024 15:59:57 -0600 Subject: [PATCH 14/16] chore:small fix --- src/formatter.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/formatter.rs b/src/formatter.rs index 1f01b3fc..b445d3b7 100644 --- a/src/formatter.rs +++ b/src/formatter.rs @@ -848,7 +848,7 @@ pub fn print_transaction_summary( tracing::info!("Initiator: {:?}", tx.initiator_account()); tracing::info!("Payer: {:?}", tx.payer()); tracing::info!( - "Gas Usage: Limit: {} | Used: {} | Refunded: {}", + "Gas Limit: {} | Used: {} | Refunded: {}", to_human_size(tx.gas_limit()), to_human_size(used_gas), to_human_size(tx_result.refunds.gas_refunded.into()) From d63b180ac2a4e549732423d5159a34c5c0172ce4 Mon Sep 17 00:00:00 2001 From: romsters Date: Tue, 3 Dec 2024 12:56:17 +0200 Subject: [PATCH 15/16] fix: print console logs once per call, fix spacing --- src/console_log.rs | 14 +++++++++----- src/formatter.rs | 2 -- src/node/in_memory.rs | 10 ++++------ 3 files changed, 13 insertions(+), 13 deletions(-) diff --git a/src/console_log.rs b/src/console_log.rs index 3e516c27..d0aac4e5 100644 --- a/src/console_log.rs +++ b/src/console_log.rs @@ -35,6 +35,14 @@ impl Default for ConsoleLogHandler { } impl ConsoleLogHandler { + pub fn handle_calls_recursive(&self, calls: &Vec) { + tracing::info!(""); + tracing::info!("==== Console logs: "); + + for call in calls { + self.handle_call_recursive(call); + } + } pub fn handle_call_recursive(&self, current_call: &Call) { self.handle_call(current_call); for call in ¤t_call.calls { @@ -59,11 +67,7 @@ impl ConsoleLogHandler { tokens.iter().map(|t| format!("{}", t)).join(" ") }) }); - if !message.is_empty() { - tracing::info!(""); - tracing::info!("==== Console logs: "); - tracing::info!("{}", message.cyan()); - } + tracing::info!("{}", message.cyan()); } } diff --git a/src/formatter.rs b/src/formatter.rs index b445d3b7..b76bdb65 100644 --- a/src/formatter.rs +++ b/src/formatter.rs @@ -629,8 +629,6 @@ impl Formatter { } } }); - - tracing::info!(""); } } // Builds the branched prefix for the structured logs. diff --git a/src/node/in_memory.rs b/src/node/in_memory.rs index 0d17bd95..f78a67d2 100644 --- a/src/node/in_memory.rs +++ b/src/node/in_memory.rs @@ -1227,6 +1227,7 @@ impl InMemoryNode { .unwrap_or_default(); if inner.config.show_tx_summary { + tracing::info!(""); match &tx_result.result { ExecutionResult::Success { output } => { tracing::info!("Call: {}", "SUCCESS".green()); @@ -1243,12 +1244,11 @@ impl InMemoryNode { } if !inner.config.disable_console_log { - for call in &call_traces { - inner.console_log_handler.handle_call_recursive(call); - } + inner.console_log_handler.handle_calls_recursive(&call_traces); } if inner.config.show_calls != ShowCalls::None { + tracing::info!(""); tracing::info!( "[Transaction Execution] ({} calls)", call_traces[0].calls.len() @@ -1425,9 +1425,7 @@ impl InMemoryNode { } if !inner.config.disable_console_log { - for call in call_traces { - inner.console_log_handler.handle_call_recursive(call); - } + inner.console_log_handler.handle_calls_recursive(&call_traces); } if inner.config.show_calls != ShowCalls::None { From 35addb8c213f2bc5b00fa7c434a4436c415b2789 Mon Sep 17 00:00:00 2001 From: romsters Date: Tue, 3 Dec 2024 12:58:47 +0200 Subject: [PATCH 16/16] fix: lint --- src/node/in_memory.rs | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/src/node/in_memory.rs b/src/node/in_memory.rs index f78a67d2..73e1240b 100644 --- a/src/node/in_memory.rs +++ b/src/node/in_memory.rs @@ -1244,7 +1244,9 @@ impl InMemoryNode { } if !inner.config.disable_console_log { - inner.console_log_handler.handle_calls_recursive(&call_traces); + inner + .console_log_handler + .handle_calls_recursive(&call_traces); } if inner.config.show_calls != ShowCalls::None { @@ -1425,7 +1427,9 @@ impl InMemoryNode { } if !inner.config.disable_console_log { - inner.console_log_handler.handle_calls_recursive(&call_traces); + inner + .console_log_handler + .handle_calls_recursive(call_traces); } if inner.config.show_calls != ShowCalls::None {