From 2ca627d3c3926653f21d67c9e9e9dbd1c3f1b937 Mon Sep 17 00:00:00 2001 From: Dustin Brickwood Date: Tue, 3 Dec 2024 12:10:41 -0600 Subject: [PATCH 1/6] feat: add structured error formatting --- src/formatter.rs | 330 +++++++++++++++++++++++++++++++++- src/node/call_error_tracer.rs | 42 +---- src/node/eth.rs | 4 - src/node/in_memory.rs | 147 +++++++++------ src/resolver.rs | 4 +- 5 files changed, 434 insertions(+), 93 deletions(-) diff --git a/src/formatter.rs b/src/formatter.rs index b76bdb65..19d4dd0c 100644 --- a/src/formatter.rs +++ b/src/formatter.rs @@ -9,12 +9,23 @@ 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_multivm::interface::{ + Call, ExecutionResult, Halt, VmEvent, VmExecutionResultAndLogs, VmExecutionStatistics, + VmRevertReason, +}; +use zksync_multivm::zk_evm_latest::vm_state::ErrorFlags; +use zksync_types::ExecuteTransactionCommon; use zksync_types::{ fee_model::FeeModelConfigV2, Address, StorageLogWithPreviousValue, Transaction, H160, H256, U256, }; +#[derive(Debug, Clone, PartialEq)] +pub enum ExecutionOutput { + RevertReason(VmRevertReason), + HaltReason(Halt), +} + // @dev elected to have GasDetails struct as we can do more with it in the future // We can provide more detailed understanding of gas errors and gas usage #[derive(Debug, Deserialize, Clone, PartialEq, Eq)] @@ -475,7 +486,7 @@ impl Formatter { format!("0x{}", sig) } else { block_on(async move { - match resolver::decode_function_selector(&sig).await { + match resolver::decode_function_selector(sig.clone()).await { Ok(Some(name)) => name, Ok(None) | Err(_) => format!("0x{}", sig), } @@ -630,7 +641,141 @@ impl Formatter { } }); } + + /// Prints structured error message with insights. + #[allow(clippy::too_many_arguments)] + pub fn print_structured_error( + &mut self, + initiator: Address, + contract_address: Option, + call: &Call, + is_last_sibling: bool, + error_flag: &ErrorFlags, + _tx_result: &VmExecutionStatistics, + output: &ExecutionOutput, + tx: &Transaction, + ) { + // Filter to only the last error call + if let Some(last_error_call) = find_last_error_call(call) { + let contract_type = KNOWN_ADDRESSES + .get(&last_error_call.to) + .cloned() + .map(|known_address| known_address.contract_type) + .unwrap_or(ContractType::Unknown); + + let call_type_display = format!("{:?}", last_error_call.r#type).blue(); + let remaining_gas_display = to_human_size(last_error_call.gas.into()).yellow(); + let gas_used_display = + format!("({})", to_human_size(last_error_call.gas_used.into())).bold(); + + let contract_display = format_address_human_readable( + last_error_call.to, + initiator, + contract_address, + format!("{:?}", last_error_call.r#type).as_str(), + ) + .unwrap_or_else(|| format!("{:}", format!("{:?}", last_error_call.to).bold())); + + let function_signature = if last_error_call.input.len() >= 4 { + let sig = hex::encode(&last_error_call.input[0..4]); + if contract_type == ContractType::Precompile { + format!("0x{}", sig) + } else { + block_on(async move { + match resolver::decode_function_selector(sig.clone()).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 + ); + + self.section(&line, is_last_sibling, |call_section| { + if last_error_call.revert_reason.is_some() || last_error_call.error.is_some() { + if let Some(ref reason) = last_error_call.revert_reason { + if reason.contains("Error function_selector = 0x") { + // Extract the function selector from the reason string + if let Some(func_selector_hex) = + extract_function_selector_from_reason(reason) + { + let error_function_name = get_error_function_name( + func_selector_hex.clone(), + contract_type, + ); + call_section.format_error( + true, + &format!( + "🔴 Revert reason: Error in function `{}` (selector 0x{}).", + error_function_name, func_selector_hex, + ), + ); + } else { + // If function selector couldn't be extracted, print the original reason + call_section + .format_error(true, &format!("🔴 Revert reason: {}", reason)); + } + } + call_section.format_error(true, &format!("🔴 Error output: {:?}", output)); + if error_flag != &ErrorFlags::empty() { + call_section + .format_error(true, &format!("🔴 Error flag: {:?}", error_flag)); + } + call_section.section( + "🔴 Failed Transaction Summary", + true, + |summary_section| { + for detail in format_transaction_error_summary( + tx, + last_error_call.gas_used, + last_error_call.to, + function_signature.clone(), + ) { + summary_section.format_log(true, &detail); + } + }, + ); + } + if let Some(ref error) = last_error_call.error { + call_section.format_error(true, &format!("🔴 Error: {}", error)); + call_section.format_error(true, &format!("🔴 Error output: {:?}", output)); + if error_flag != &ErrorFlags::empty() { + call_section + .format_error(true, &format!("🔴 Error flag: {:?}", error_flag)); + } + call_section.section( + "🔴 Failed Transaction Summary", + true, + |summary_section| { + for detail in format_transaction_error_summary( + tx, + last_error_call.gas_used, + last_error_call.to, + function_signature, + ) { + summary_section.format_log(true, &detail); + } + }, + ); + } + } + }); + } + } } + // Builds the branched prefix for the structured logs. fn build_prefix(sibling_stack: &[bool], is_last_sibling: bool) -> String { let mut prefix = String::new(); @@ -652,6 +797,24 @@ fn build_prefix(sibling_stack: &[bool], is_last_sibling: bool) -> String { prefix } +/// Finds the last call containing an error or revert reason in the call stack. +fn find_last_error_call(call: &Call) -> Option<&Call> { + let mut last_error_call = None; + // If the current call contains an error or revert reason, mark it as the last seen + if call.revert_reason.is_some() || call.error.is_some() { + last_error_call = Some(call); + } + + // Recursively check subcalls + for subcall in &call.calls { + if let Some(sub_error_call) = find_last_error_call(subcall) { + last_error_call = Some(sub_error_call); + } + } + + last_error_call +} + #[derive(Debug, Deserialize, Clone, PartialEq, Eq)] pub enum ContractType { System, @@ -755,6 +918,81 @@ fn format_data(value: &[u8]) -> String { } } } +fn format_transaction_error_summary( + tx: &Transaction, + gas_used: u64, + to: H160, + fn_signature: String, +) -> Vec { + match &tx.common_data { + ExecuteTransactionCommon::L1(_) => { + vec![format!( + "{}", + "Transaction Type: L1".to_string().bold().red() + )] + } + ExecuteTransactionCommon::L2(data) => { + let mut details = vec![ + format!("{} {:?}", "Transaction Type:".bold().red(), tx.tx_format()), + format!( + "{} {}", + "Nonce:".bold().red(), + tx.nonce() + .map_or("N/A".to_string(), |nonce| nonce.to_string()) + .dimmed() + .red() + ), + format!( + "{} {}", + "From:".bold().red(), + format!("0x{:x}", tx.initiator_account()).dimmed().red() + ), + format!( + "{} {}", + "To:".bold().red(), + format!("{:?}", tx.execute.contract_address.unwrap_or(to)) + .dimmed() + .red() + ), + format!( + "{} {}", + "Function:".bold().red(), + fn_signature.dimmed().red() + ), + format!( + "{} {}", + "Gas Used:".bold().red(), + to_human_size(gas_used.into()).dimmed().red() + ), + ]; + if data.paymaster_params.paymaster != Address::zero() { + details.push(format!( + "{} {}", + "Paymaster:".bold().red(), + format!("{:?}", data.paymaster_params.paymaster) + .dimmed() + .red() + )); + details.push(format!( + "{} {}", + "Paymaster Input Params:".bold().red(), + format!("{:?}", data.paymaster_params.paymaster_input) + .dimmed() + .red() + )); + } + + details + } + ExecuteTransactionCommon::ProtocolUpgrade(_) => vec![format!( + "{}", + "Transaction Type: Protocol Upgrade" + .to_string() + .bold() + .red() + )], + } +} // Separated from print_events. Consider the same for print_calls. fn resolve_topics(topics: &[H256], resolve_hashes: bool) -> Vec { let topics = topics.to_owned(); @@ -773,6 +1011,42 @@ fn resolve_topics(topics: &[H256], resolve_hashes: bool) -> Vec { join_all(futures).await }) } +// Helper function to get the error function name from the function selector +fn get_error_function_name(func_selector_hex: String, contract_type: ContractType) -> String { + if contract_type == ContractType::Precompile { + format!("0x{}", func_selector_hex) + } else { + match block_on(resolver::decode_function_selector( + func_selector_hex.clone(), + )) { + Ok(Some(name)) => name, + Ok(None) | Err(_) => format!("0x{}", func_selector_hex), + } + } +} +// Helper function to extract function selector from the reason string +fn extract_function_selector_from_reason(reason: &str) -> Option { + // The reason string contains something like "Error function_selector = 0x03eb8b54, data = 0x..." + let pattern = "Error function_selector = 0x"; + if let Some(start) = reason.find(pattern) { + let selector_start = start + pattern.len(); + // Function selector is 4 bytes (8 hex characters), but we should handle variable lengths + let selector_end = reason[selector_start..] + .find(|c: char| c == ',' || c.is_whitespace()) + .map(|offset| selector_start + offset) + .unwrap_or(reason.len()); + if selector_end > selector_start { + let func_selector_hex = &reason[selector_start..selector_end]; + // Validate that the extracted string is valid hex and of correct length + if func_selector_hex.len() == 8 + && func_selector_hex.chars().all(|c| c.is_ascii_hexdigit()) + { + return Some(func_selector_hex.to_string()); + } + } + } + None +} /// Amount of pubdata that given write has cost. /// Used when displaying Storage Logs. @@ -825,6 +1099,8 @@ pub fn print_transaction_summary( tx: &Transaction, tx_result: &VmExecutionResultAndLogs, status: &str, + call_traces: &Vec, + error_flags: &ErrorFlags, ) { // Calculate used and refunded gas let used_gas = tx.gas_limit() - tx_result.refunds.gas_refunded; @@ -858,4 +1134,54 @@ pub fn print_transaction_summary( format_gwei(l2_gas_price.into()) ); tracing::info!("Refunded: {:.10} ETH", refunded_in_eth); + match &tx_result.result { + ExecutionResult::Success { output } => { + let output_bytes = zksync_types::web3::Bytes::from(output.clone()); + tracing::info!("Output: {}", serde_json::to_string(&output_bytes).unwrap()); + } + ExecutionResult::Revert { output } => { + print_transaction_error( + &tx, + &call_traces, + &error_flags, + &tx_result.statistics, + &ExecutionOutput::RevertReason(output.clone()), + ); + } + ExecutionResult::Halt { reason } => { + print_transaction_error( + &tx, + &call_traces, + &error_flags, + &tx_result.statistics, + &ExecutionOutput::HaltReason(reason.clone()), + ); + } + } +} +/// Print the transaction error with detailed call traces. +pub fn print_transaction_error( + tx: &Transaction, + call_traces: &[Call], + error_flags: &ErrorFlags, + tx_result: &VmExecutionStatistics, + output: &ExecutionOutput, +) { + let mut formatter = Formatter::new(); + tracing::info!(""); + tracing::error!("{}", "[Transaction Reverted]".red()); + let num_calls = call_traces.len(); + for (i, call) in call_traces.iter().enumerate() { + let is_last_sibling = i == num_calls - 1; + formatter.print_structured_error( + tx.initiator_account(), + tx.execute.contract_address, + call, + is_last_sibling, + error_flags, + &tx_result, + &output.clone(), + tx, + ); + } } diff --git a/src/node/call_error_tracer.rs b/src/node/call_error_tracer.rs index ae10614f..d2638a91 100644 --- a/src/node/call_error_tracer.rs +++ b/src/node/call_error_tracer.rs @@ -1,3 +1,5 @@ +use once_cell::sync::OnceCell; +use std::sync::Arc; use zksync_multivm::interface::storage::WriteStorage; use zksync_multivm::{ tracers::dynamic::vm_1_5_0::DynTracer, @@ -8,11 +10,13 @@ use zksync_multivm::{ }, }; -pub struct CallErrorTracer {} +pub struct CallErrorTracer { + result: Arc>, +} impl CallErrorTracer { - pub fn new() -> Self { - Self {} + pub fn new(result: Arc>) -> Self { + Self { result } } } @@ -24,37 +28,7 @@ impl DynTracer> for CallErrorTracer { _memory: &SimpleMemory, ) { if !data.error_flags_accumulated.is_empty() { - tracing::error!("!! Got error flags: "); - if data - .error_flags_accumulated - .contains(ErrorFlags::INVALID_OPCODE) - { - tracing::error!("INVALID OPCODE"); - } - if data - .error_flags_accumulated - .contains(ErrorFlags::NOT_ENOUGH_ERGS) - { - tracing::error!("NOT ENOUGH ERGS"); - } - if data - .error_flags_accumulated - .contains(ErrorFlags::PRIVILAGED_ACCESS_NOT_FROM_KERNEL) - { - tracing::error!("PRIVILEGED ACCESS"); - } - if data - .error_flags_accumulated - .contains(ErrorFlags::WRITE_IN_STATIC_CONTEXT) - { - tracing::error!("WRITE IN STATIC"); - } - if data - .error_flags_accumulated - .contains(ErrorFlags::CALLSTACK_IS_FULL) - { - tracing::error!("CALLSTACK IS FULL"); - } + let _ = self.result.set(data.error_flags_accumulated); } } } diff --git a/src/node/eth.rs b/src/node/eth.rs index 58fd7a84..0fbeb3ba 100644 --- a/src/node/eth.rs +++ b/src/node/eth.rs @@ -59,8 +59,6 @@ impl InMemoryNo if message.is_empty() { "" } else { ": " }, message ); - - tracing::info!("{}", pretty_message.on_red()); Err(Web3Error::SubmitTransactionError( pretty_message, output.encoded_data(), @@ -73,8 +71,6 @@ impl InMemoryNo if message.is_empty() { "" } else { ": " }, message ); - - tracing::info!("{}", pretty_message.on_red()); Err(Web3Error::SubmitTransactionError(pretty_message, vec![])) } } diff --git a/src/node/in_memory.rs b/src/node/in_memory.rs index f57a2700..ee185125 100644 --- a/src/node/in_memory.rs +++ b/src/node/in_memory.rs @@ -9,9 +9,9 @@ use std::{ str::FromStr, sync::{Arc, RwLock}, }; - use zksync_contracts::BaseSystemContracts; use zksync_multivm::vm_latest::HistoryEnabled; +use zksync_multivm::zk_evm_latest::vm_state::ErrorFlags; use zksync_multivm::{ interface::{ storage::{ReadStorage, StoragePtr, WriteStorage}, @@ -559,7 +559,7 @@ impl InMemoryNodeInner { // In theory, if the transaction has failed with such large gas limit, we could have returned an API error here right away, // but doing it later on keeps the code more lean. - let result = InMemoryNodeInner::estimate_gas_step( + let (result, _, _, _) = InMemoryNodeInner::estimate_gas_step( l2_tx.clone(), gas_per_pubdata_byte, BATCH_GAS_LIMIT, @@ -596,7 +596,7 @@ impl InMemoryNodeInner { ); let try_gas_limit = additional_gas_for_pubdata + mid; - let estimate_gas_result = InMemoryNodeInner::estimate_gas_step( + let (estimate_gas_result, _, _, _) = InMemoryNodeInner::estimate_gas_step( l2_tx.clone(), gas_per_pubdata_byte, try_gas_limit, @@ -627,14 +627,15 @@ impl InMemoryNodeInner { * self.fee_input_provider.estimate_gas_scale_factor) as u64; - let estimate_gas_result = InMemoryNodeInner::estimate_gas_step( - l2_tx.clone(), - gas_per_pubdata_byte, - suggested_gas_limit, - batch_env, - system_env, - &self.fork_storage, - ); + let (estimate_gas_result, call_traces, error_flags, _) = + InMemoryNodeInner::estimate_gas_step( + l2_tx.clone(), + gas_per_pubdata_byte, + suggested_gas_limit, + batch_env, + system_env, + &self.fork_storage, + ); let overhead = derive_overhead( suggested_gas_limit, @@ -646,20 +647,14 @@ impl InMemoryNodeInner { match estimate_gas_result.result { ExecutionResult::Revert { output } => { - tracing::info!("{}", format!("Unable to estimate gas for the request with our suggested gas limit of {}. The transaction is most likely unexecutable. Breakdown of estimation:", suggested_gas_limit + overhead).red()); - tracing::info!( - "{}", - format!( - "\tEstimated transaction body gas cost: {}", - tx_body_gas_limit - ) - .red() - ); - tracing::info!( - "{}", - format!("\tGas for pubdata: {}", additional_gas_for_pubdata).red() + formatter::print_transaction_error( + &tx, + &call_traces, + &error_flags, + &estimate_gas_result.statistics, + &formatter::ExecutionOutput::RevertReason(output.clone()), ); - tracing::info!("{}", format!("\tOverhead: {}", overhead).red()); + let message = output.to_string(); let pretty_message = format!( "execution reverted{}{}", @@ -667,35 +662,26 @@ impl InMemoryNodeInner { message ); let data = output.encoded_data(); - tracing::info!("{}", pretty_message.on_red()); Err(into_jsrpc_error(Web3Error::SubmitTransactionError( pretty_message, data, ))) } ExecutionResult::Halt { reason } => { - tracing::info!("{}", format!("Unable to estimate gas for the request with our suggested gas limit of {}. The transaction is most likely unexecutable. Breakdown of estimation:", suggested_gas_limit + overhead).red()); - tracing::info!( - "{}", - format!( - "\tEstimated transaction body gas cost: {}", - tx_body_gas_limit - ) - .red() + formatter::print_transaction_error( + &tx, + &call_traces, + &error_flags, + &estimate_gas_result.statistics, + &formatter::ExecutionOutput::HaltReason(reason.clone()), ); - tracing::info!( - "{}", - format!("\tGas for pubdata: {}", additional_gas_for_pubdata).red() - ); - tracing::info!("{}", format!("\tOverhead: {}", overhead).red()); + let message = reason.to_string(); let pretty_message = format!( - "execution reverted{}{}", + "execution reverted!! {}{}", if message.is_empty() { "" } else { ": " }, message ); - - tracing::info!("{}", pretty_message.on_red()); Err(into_jsrpc_error(Web3Error::SubmitTransactionError( pretty_message, vec![], @@ -754,7 +740,12 @@ impl InMemoryNodeInner { batch_env: L1BatchEnv, system_env: SystemEnv, fork_storage: &ForkStorage, - ) -> VmExecutionResultAndLogs { + ) -> ( + VmExecutionResultAndLogs, + Vec, + ErrorFlags, + BootloaderDebug, + ) { let tx: Transaction = l2_tx.clone().into(); // Set gas_limit for transaction @@ -795,7 +786,38 @@ impl InMemoryNodeInner { let tx: Transaction = l2_tx.into(); vm.push_transaction(tx); - vm.execute(InspectExecutionMode::OneTx) + let call_tracer_result = Arc::new(OnceCell::default()); + let error_flags_result = Arc::new(OnceCell::new()); + let bootloader_debug_result = Arc::new(OnceCell::default()); + + let tracers = vec![ + CallErrorTracer::new(error_flags_result.clone()).into_tracer_pointer(), + CallTracer::new(call_tracer_result.clone()).into_tracer_pointer(), + BootloaderDebugTracer { + result: bootloader_debug_result.clone(), + } + .into_tracer_pointer(), + ]; + // Ask if vm.inspect is the same as vm.execute + let tx_result = vm.inspect(&mut tracers.into(), InspectExecutionMode::OneTx); + + let call_traces = Arc::try_unwrap(call_tracer_result) + .unwrap() + .take() + .unwrap_or_default(); + + let error_flags = Arc::try_unwrap(error_flags_result) + .unwrap() + .take() + .unwrap_or_default(); + + let bootloader_debug = Arc::try_unwrap(bootloader_debug_result) + .unwrap() + .take() + .unwrap() + .unwrap(); + + (tx_result, call_traces, error_flags, bootloader_debug) } /// Archives the current state for later queries. @@ -1262,9 +1284,10 @@ impl InMemoryNode { vm.push_transaction(tx.clone()); let call_tracer_result = Arc::new(OnceCell::default()); + let error_flags_result = Arc::new(OnceCell::new()); let tracers = vec![ - CallErrorTracer::new().into_tracer_pointer(), + CallErrorTracer::new(error_flags_result.clone()).into_tracer_pointer(), CallTracer::new(call_tracer_result.clone()).into_tracer_pointer(), ]; let tx_result = vm.inspect(&mut tracers.into(), InspectExecutionMode::OneTx); @@ -1274,19 +1297,34 @@ impl InMemoryNode { .take() .unwrap_or_default(); + let error_flags = Arc::try_unwrap(error_flags_result) + .unwrap() + .take() + .unwrap_or_default(); + if inner.config.show_tx_summary { tracing::info!(""); match &tx_result.result { ExecutionResult::Success { output } => { - tracing::info!("Call: {}", "SUCCESS".green()); - let output_bytes = zksync_types::web3::Bytes::from(output.clone()); - tracing::info!("Output: {}", serde_json::to_string(&output_bytes).unwrap()); + tracing::trace!("transaction succeeded with output: {:?}", output); } ExecutionResult::Revert { output } => { - tracing::info!("Call: {}: {}", "FAILED".red(), output); + formatter::print_transaction_error( + &tx, + &call_traces, + &error_flags, + &tx_result.statistics, + &formatter::ExecutionOutput::RevertReason(output.clone()), + ); } ExecutionResult::Halt { reason } => { - tracing::info!("Call: {} {}", "HALTED".red(), reason) + formatter::print_transaction_error( + &tx, + &call_traces, + &error_flags, + &tx_result.statistics, + &formatter::ExecutionOutput::HaltReason(reason.clone()), + ); } }; } @@ -1420,9 +1458,10 @@ impl InMemoryNode { let call_tracer_result = Arc::new(OnceCell::default()); let bootloader_debug_result = Arc::new(OnceCell::default()); + let error_flags_result = Arc::new(OnceCell::new()); let tracers = vec![ - CallErrorTracer::new().into_tracer_pointer(), + CallErrorTracer::new(error_flags_result.clone()).into_tracer_pointer(), CallTracer::new(call_tracer_result.clone()).into_tracer_pointer(), BootloaderDebugTracer { result: bootloader_debug_result.clone(), @@ -1436,6 +1475,10 @@ impl InMemoryNode { let tx_result = vm.inspect(&mut tracers.into(), InspectExecutionMode::OneTx); let call_traces = call_tracer_result.get().unwrap(); + let error_flags = Arc::try_unwrap(error_flags_result) + .unwrap() + .take() + .unwrap_or_default(); let spent_on_pubdata = tx_result.statistics.gas_used - tx_result.statistics.computational_gas_used as u64; @@ -1454,6 +1497,8 @@ impl InMemoryNode { &tx, &tx_result, status, + call_traces, + &error_flags, ); tracing::info!(""); } @@ -1698,7 +1743,7 @@ impl InMemoryNode { vm.make_snapshot(); let hash = tx.hash(); if let Err(e) = self.run_l2_tx(tx, &block_ctx, &batch_env, &mut vm) { - tracing::error!("Error while executing transaction: {e}"); + tracing::debug!("Error while executing transaction: {e}"); vm.rollback_to_the_latest_snapshot(); } else { executed_tx_hashes.push(hash); diff --git a/src/resolver.rs b/src/resolver.rs index fc98c634..0f8842cf 100644 --- a/src/resolver.rs +++ b/src/resolver.rs @@ -225,7 +225,7 @@ pub enum SelectorType { Event, } /// Fetches a function signature given the selector using api.openchain.xyz -pub async fn decode_function_selector(selector: &str) -> eyre::Result> { +pub async fn decode_function_selector(selector: String) -> eyre::Result> { let client = SignEthClient::new(); { // Check cache @@ -246,7 +246,7 @@ pub async fn decode_function_selector(selector: &str) -> eyre::Result Date: Tue, 3 Dec 2024 12:28:52 -0600 Subject: [PATCH 2/6] feat: add structured errors --- src/formatter.rs | 323 ++++++++++++++++++++++------------------------- src/node/eth.rs | 1 - 2 files changed, 151 insertions(+), 173 deletions(-) diff --git a/src/formatter.rs b/src/formatter.rs index 19d4dd0c..953115fc 100644 --- a/src/formatter.rs +++ b/src/formatter.rs @@ -416,6 +416,7 @@ impl Formatter { ); } /// Prints the call stack of either the system or user calls in a structured log. + // Refactored print_call method #[allow(clippy::too_many_arguments)] pub fn print_call( &mut self, @@ -443,7 +444,7 @@ impl Formatter { (ContractType::System, ShowCalls::System) => true, }; - // Collect subcalls that should be printed (e.g. handle filtering) + // Collect subcalls that should be printed let subcalls_to_print: Vec<&Call> = call .calls .iter() @@ -467,57 +468,20 @@ impl Formatter { .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.clone()).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 - ); + let (line, function_signature, contract_type) = + format_call_info(initiator, contract_address, call, resolve_hashes); // 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 { - call_section.format_error(true, &format!("🔴 Revert reason: {}", reason)); - } - if let Some(ref error) = call.error { - call_section.format_error(true, &format!("🔴 Error: {}", error)); - } - } + format_call_errors( + call_section, + call, + None, + None, + None, + &function_signature, + contract_type, + ); if show_outputs && !call.output.is_empty() { let output_display = call @@ -546,7 +510,7 @@ impl Formatter { } }); } else { - // Call is not printed; process subcalls at the same indentation level + // 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); @@ -562,6 +526,7 @@ impl Formatter { } } } + /// Prints the storage logs of the system in a structured log. pub fn print_storage_logs( &mut self, @@ -644,6 +609,7 @@ impl Formatter { /// Prints structured error message with insights. #[allow(clippy::too_many_arguments)] + #[allow(clippy::too_many_arguments)] pub fn print_structured_error( &mut self, initiator: Address, @@ -657,120 +623,19 @@ impl Formatter { ) { // Filter to only the last error call if let Some(last_error_call) = find_last_error_call(call) { - let contract_type = KNOWN_ADDRESSES - .get(&last_error_call.to) - .cloned() - .map(|known_address| known_address.contract_type) - .unwrap_or(ContractType::Unknown); - - let call_type_display = format!("{:?}", last_error_call.r#type).blue(); - let remaining_gas_display = to_human_size(last_error_call.gas.into()).yellow(); - let gas_used_display = - format!("({})", to_human_size(last_error_call.gas_used.into())).bold(); - - let contract_display = format_address_human_readable( - last_error_call.to, - initiator, - contract_address, - format!("{:?}", last_error_call.r#type).as_str(), - ) - .unwrap_or_else(|| format!("{:}", format!("{:?}", last_error_call.to).bold())); - - let function_signature = if last_error_call.input.len() >= 4 { - let sig = hex::encode(&last_error_call.input[0..4]); - if contract_type == ContractType::Precompile { - format!("0x{}", sig) - } else { - block_on(async move { - match resolver::decode_function_selector(sig.clone()).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 - ); + let (line, function_signature, contract_type) = + format_call_info(initiator, contract_address, last_error_call, true); self.section(&line, is_last_sibling, |call_section| { - if last_error_call.revert_reason.is_some() || last_error_call.error.is_some() { - if let Some(ref reason) = last_error_call.revert_reason { - if reason.contains("Error function_selector = 0x") { - // Extract the function selector from the reason string - if let Some(func_selector_hex) = - extract_function_selector_from_reason(reason) - { - let error_function_name = get_error_function_name( - func_selector_hex.clone(), - contract_type, - ); - call_section.format_error( - true, - &format!( - "🔴 Revert reason: Error in function `{}` (selector 0x{}).", - error_function_name, func_selector_hex, - ), - ); - } else { - // If function selector couldn't be extracted, print the original reason - call_section - .format_error(true, &format!("🔴 Revert reason: {}", reason)); - } - } - call_section.format_error(true, &format!("🔴 Error output: {:?}", output)); - if error_flag != &ErrorFlags::empty() { - call_section - .format_error(true, &format!("🔴 Error flag: {:?}", error_flag)); - } - call_section.section( - "🔴 Failed Transaction Summary", - true, - |summary_section| { - for detail in format_transaction_error_summary( - tx, - last_error_call.gas_used, - last_error_call.to, - function_signature.clone(), - ) { - summary_section.format_log(true, &detail); - } - }, - ); - } - if let Some(ref error) = last_error_call.error { - call_section.format_error(true, &format!("🔴 Error: {}", error)); - call_section.format_error(true, &format!("🔴 Error output: {:?}", output)); - if error_flag != &ErrorFlags::empty() { - call_section - .format_error(true, &format!("🔴 Error flag: {:?}", error_flag)); - } - call_section.section( - "🔴 Failed Transaction Summary", - true, - |summary_section| { - for detail in format_transaction_error_summary( - tx, - last_error_call.gas_used, - last_error_call.to, - function_signature, - ) { - summary_section.format_log(true, &detail); - } - }, - ); - } - } + format_call_errors( + call_section, + last_error_call, + Some(output), + Some(error_flag), + Some(tx), + &function_signature, + contract_type, + ); }); } } @@ -796,7 +661,6 @@ fn build_prefix(sibling_stack: &[bool], is_last_sibling: bool) -> String { } prefix } - /// Finds the last call containing an error or revert reason in the call stack. fn find_last_error_call(call: &Call) -> Option<&Call> { let mut last_error_call = None; @@ -918,6 +782,121 @@ fn format_data(value: &[u8]) -> String { } } } + +// Helper function to format call information +fn format_call_info( + initiator: Address, + contract_address: Option, + call: &Call, + resolve_hashes: bool, +) -> (String, String, ContractType) { + let contract_type = KNOWN_ADDRESSES + .get(&call.to) + .cloned() + .map(|known_address| known_address.contract_type) + .unwrap_or(ContractType::Unknown); + + 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.clone()).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 + ); + + (line, function_signature, contract_type) +} + +// Helper function to handle error formatting +fn format_call_errors( + call_section: &mut Formatter, + call: &Call, + output: Option<&ExecutionOutput>, + error_flag: Option<&ErrorFlags>, + tx: Option<&Transaction>, + function_signature: &str, + contract_type: ContractType, +) { + if call.revert_reason.is_some() || call.error.is_some() { + if let Some(ref reason) = call.revert_reason { + if reason.contains("Error function_selector = 0x") { + // Extract the function selector from the reason string + if let Some(func_selector_hex) = extract_function_selector_from_reason(reason) { + let error_function_name = + get_error_function_name(func_selector_hex.clone(), contract_type); + call_section.format_error( + true, + &format!( + "🔴 Revert reason: Error in function `{}` (selector 0x{}).", + error_function_name, func_selector_hex, + ), + ); + } else { + // If function selector couldn't be extracted, print the original reason + call_section.format_error(true, &format!("🔴 Revert reason: {}", reason)); + } + } else { + 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 let Some(output) = output { + call_section.format_error(true, &format!("🔴 Error output: {:?}", output)); + } + if let Some(error_flag) = error_flag { + if error_flag != &ErrorFlags::empty() { + call_section.format_error(true, &format!("🔴 Error flag: {:?}", error_flag)); + } + } + if let Some(tx) = tx { + call_section.section("🔴 Failed Transaction Summary", true, |summary_section| { + for detail in format_transaction_error_summary( + tx, + call.gas_used, + call.to, + function_signature.to_string(), + ) { + summary_section.format_log(true, &detail); + } + }); + } + } +} + fn format_transaction_error_summary( tx: &Transaction, gas_used: u64, @@ -1099,7 +1078,7 @@ pub fn print_transaction_summary( tx: &Transaction, tx_result: &VmExecutionResultAndLogs, status: &str, - call_traces: &Vec, + call_traces: &[Call], error_flags: &ErrorFlags, ) { // Calculate used and refunded gas @@ -1141,18 +1120,18 @@ pub fn print_transaction_summary( } ExecutionResult::Revert { output } => { print_transaction_error( - &tx, - &call_traces, - &error_flags, + tx, + call_traces, + error_flags, &tx_result.statistics, &ExecutionOutput::RevertReason(output.clone()), ); } ExecutionResult::Halt { reason } => { print_transaction_error( - &tx, - &call_traces, - &error_flags, + tx, + call_traces, + error_flags, &tx_result.statistics, &ExecutionOutput::HaltReason(reason.clone()), ); @@ -1169,7 +1148,7 @@ pub fn print_transaction_error( ) { let mut formatter = Formatter::new(); tracing::info!(""); - tracing::error!("{}", "[Transaction Reverted]".red()); + tracing::error!("{}", "[Transaction Error]".red()); let num_calls = call_traces.len(); for (i, call) in call_traces.iter().enumerate() { let is_last_sibling = i == num_calls - 1; @@ -1179,7 +1158,7 @@ pub fn print_transaction_error( call, is_last_sibling, error_flags, - &tx_result, + tx_result, &output.clone(), tx, ); diff --git a/src/node/eth.rs b/src/node/eth.rs index 0fbeb3ba..637002ee 100644 --- a/src/node/eth.rs +++ b/src/node/eth.rs @@ -1,7 +1,6 @@ use std::collections::HashSet; use anyhow::Context as _; -use colored::Colorize; use futures::FutureExt; use itertools::Itertools; use zksync_multivm::interface::{ExecutionResult, TxExecutionMode}; From 088bb3de973a30c6bb45a1987ba372fe0fb16aea Mon Sep 17 00:00:00 2001 From: Dustin Brickwood Date: Tue, 3 Dec 2024 12:33:36 -0600 Subject: [PATCH 3/6] chore: fix lint --- src/formatter.rs | 15 +++------------ src/node/in_memory.rs | 4 ++-- 2 files changed, 5 insertions(+), 14 deletions(-) diff --git a/src/formatter.rs b/src/formatter.rs index 953115fc..6934236f 100644 --- a/src/formatter.rs +++ b/src/formatter.rs @@ -416,7 +416,6 @@ impl Formatter { ); } /// Prints the call stack of either the system or user calls in a structured log. - // Refactored print_call method #[allow(clippy::too_many_arguments)] pub fn print_call( &mut self, @@ -526,7 +525,6 @@ impl Formatter { } } } - /// Prints the storage logs of the system in a structured log. pub fn print_storage_logs( &mut self, @@ -606,9 +604,8 @@ impl Formatter { } }); } - - /// Prints structured error message with insights. - #[allow(clippy::too_many_arguments)] + /// Prints structured error message. + /// TODO: we can incorporate suggested actions here (e.g. insights). #[allow(clippy::too_many_arguments)] pub fn print_structured_error( &mut self, @@ -617,7 +614,7 @@ impl Formatter { call: &Call, is_last_sibling: bool, error_flag: &ErrorFlags, - _tx_result: &VmExecutionStatistics, + _tx_result: &VmExecutionStatistics, // TODO: we can use this to provide more insights output: &ExecutionOutput, tx: &Transaction, ) { @@ -640,7 +637,6 @@ impl Formatter { } } } - // Builds the branched prefix for the structured logs. fn build_prefix(sibling_stack: &[bool], is_last_sibling: bool) -> String { let mut prefix = String::new(); @@ -664,7 +660,6 @@ fn build_prefix(sibling_stack: &[bool], is_last_sibling: bool) -> String { /// Finds the last call containing an error or revert reason in the call stack. fn find_last_error_call(call: &Call) -> Option<&Call> { let mut last_error_call = None; - // If the current call contains an error or revert reason, mark it as the last seen if call.revert_reason.is_some() || call.error.is_some() { last_error_call = Some(call); } @@ -783,7 +778,6 @@ fn format_data(value: &[u8]) -> String { } } -// Helper function to format call information fn format_call_info( initiator: Address, contract_address: Option, @@ -839,7 +833,6 @@ fn format_call_info( (line, function_signature, contract_type) } -// Helper function to handle error formatting fn format_call_errors( call_section: &mut Formatter, call: &Call, @@ -1005,7 +998,6 @@ fn get_error_function_name(func_selector_hex: String, contract_type: ContractTyp } // Helper function to extract function selector from the reason string fn extract_function_selector_from_reason(reason: &str) -> Option { - // The reason string contains something like "Error function_selector = 0x03eb8b54, data = 0x..." let pattern = "Error function_selector = 0x"; if let Some(start) = reason.find(pattern) { let selector_start = start + pattern.len(); @@ -1016,7 +1008,6 @@ fn extract_function_selector_from_reason(reason: &str) -> Option { .unwrap_or(reason.len()); if selector_end > selector_start { let func_selector_hex = &reason[selector_start..selector_end]; - // Validate that the extracted string is valid hex and of correct length if func_selector_hex.len() == 8 && func_selector_hex.chars().all(|c| c.is_ascii_hexdigit()) { diff --git a/src/node/in_memory.rs b/src/node/in_memory.rs index ee185125..7e18e5fd 100644 --- a/src/node/in_memory.rs +++ b/src/node/in_memory.rs @@ -678,7 +678,7 @@ impl InMemoryNodeInner { let message = reason.to_string(); let pretty_message = format!( - "execution reverted!! {}{}", + "execution reverted{}{}", if message.is_empty() { "" } else { ": " }, message ); @@ -798,7 +798,7 @@ impl InMemoryNodeInner { } .into_tracer_pointer(), ]; - // Ask if vm.inspect is the same as vm.execute + // TODO: Ask if vm.inspect is the same as vm.execute let tx_result = vm.inspect(&mut tracers.into(), InspectExecutionMode::OneTx); let call_traces = Arc::try_unwrap(call_tracer_result) From 9199889fa363c5f1402db1e9ab5d8162ccf1a3fd Mon Sep 17 00:00:00 2001 From: Dustin Brickwood Date: Tue, 3 Dec 2024 12:42:48 -0600 Subject: [PATCH 4/6] chore: fix lint --- src/formatter.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/formatter.rs b/src/formatter.rs index 6934236f..349bbbc4 100644 --- a/src/formatter.rs +++ b/src/formatter.rs @@ -443,7 +443,7 @@ impl Formatter { (ContractType::System, ShowCalls::System) => true, }; - // Collect subcalls that should be printed + // Collect subcalls that should be printed (e.g. handle filtering) let subcalls_to_print: Vec<&Call> = call .calls .iter() @@ -509,7 +509,7 @@ impl Formatter { } }); } else { - // Process subcalls at the same indentation level + // 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); From 7560d26f9572b799846c62adb3136edcee634cf6 Mon Sep 17 00:00:00 2001 From: Dustin Brickwood Date: Tue, 3 Dec 2024 20:35:16 -0600 Subject: [PATCH 5/6] fix: make data in output hex encoded --- src/formatter.rs | 89 +++++++++++++++++++++++++++++++++++++++++++++--- 1 file changed, 84 insertions(+), 5 deletions(-) diff --git a/src/formatter.rs b/src/formatter.rs index 349bbbc4..ecb55463 100644 --- a/src/formatter.rs +++ b/src/formatter.rs @@ -3,9 +3,9 @@ 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 futures::future::join_all; +use hex::encode; use lazy_static::lazy_static; use serde::Deserialize; use std::{collections::HashMap, str}; @@ -868,7 +868,7 @@ fn format_call_errors( call_section.format_error(true, &format!("🔴 Error: {}", error)); } if let Some(output) = output { - call_section.format_error(true, &format!("🔴 Error output: {:?}", output)); + format_execution_output(call_section, output); } if let Some(error_flag) = error_flag { if error_flag != &ErrorFlags::empty() { @@ -889,6 +889,82 @@ fn format_call_errors( } } } +fn format_execution_output(call_section: &mut Formatter, output: &ExecutionOutput) { + match output { + ExecutionOutput::RevertReason(reason) => call_section.format_error( + true, + &format!("🔴 Error output: {}", format_revert_reason(reason)), + ), + ExecutionOutput::HaltReason(halt_reason) => call_section.format_error( + true, + &format!("🔴 Error output: {}", format_halt_reason(halt_reason)), + ), + } +} +fn format_revert_reason(reason: &VmRevertReason) -> String { + match reason { + VmRevertReason::General { msg, data } => { + let hex_data = encode(data); + format!( + "RevertReason(General {{ msg: \"{}\", data: 0x{} }})", + msg, hex_data + ) + } + VmRevertReason::Unknown { + function_selector, + data, + } => { + let func_selector_hex = encode(function_selector); + let hex_data = encode(data); + format!( + "RevertReason(Unknown {{ function_selector: 0x{}, data: 0x{} }})", + func_selector_hex, hex_data + ) + } + VmRevertReason::InnerTxError => "RevertReason(InnerTxError)".to_string(), + VmRevertReason::VmError => "RevertReason(VmError)".to_string(), + &_ => "RevertReason(Unknown)".to_string(), + } +} +fn format_halt_reason(halt: &Halt) -> String { + match halt { + // Group all Halt variants that use VmRevertReason + Halt::ValidationFailed(reason) + | Halt::PaymasterValidationFailed(reason) + | Halt::PrePaymasterPreparationFailed(reason) + | Halt::PayForTxFailed(reason) + | Halt::FailedToMarkFactoryDependencies(reason) + | Halt::FailedToChargeFee(reason) + | Halt::Unknown(reason) => { + format!("Halt({})", format_revert_reason(reason)) + } + // Handle non-VmRevertReason variants individually + Halt::FromIsNotAnAccount => "Halt(FromIsNotAnAccount)".to_string(), + Halt::InnerTxError => "Halt(InnerTxError)".to_string(), + Halt::UnexpectedVMBehavior(msg) => { + format!("Halt(UnexpectedVMBehavior {{ msg: \"{}\" }})", msg) + } + Halt::BootloaderOutOfGas => "Halt(BootloaderOutOfGas)".to_string(), + Halt::ValidationOutOfGas => "Halt(ValidationOutOfGas)".to_string(), + Halt::TooBigGasLimit => "Halt(TooBigGasLimit)".to_string(), + Halt::NotEnoughGasProvided => "Halt(NotEnoughGasProvided)".to_string(), + Halt::MissingInvocationLimitReached => "Halt(MissingInvocationLimitReached)".to_string(), + Halt::FailedToSetL2Block(msg) => { + format!("Halt(FailedToSetL2Block {{ msg: \"{}\" }})", msg) + } + Halt::FailedToAppendTransactionToL2Block(msg) => { + format!( + "Halt(FailedToAppendTransactionToL2Block {{ msg: \"{}\" }})", + msg + ) + } + Halt::VMPanic => "Halt(VMPanic)".to_string(), + Halt::TracerCustom(msg) => format!("Halt(TracerCustom {{ msg: \"{}\" }})", msg), + Halt::FailedToPublishCompressedBytecodes => { + "Halt(FailedToPublishCompressedBytecodes)".to_string() + } + } +} fn format_transaction_error_summary( tx: &Transaction, @@ -948,9 +1024,12 @@ fn format_transaction_error_summary( details.push(format!( "{} {}", "Paymaster Input Params:".bold().red(), - format!("{:?}", data.paymaster_params.paymaster_input) - .dimmed() - .red() + format!( + "{:?}", + encode(data.paymaster_params.paymaster_input.clone()) + ) + .dimmed() + .red() )); } From dadfe3f2df2c8abf866fa0f6372a39c7d9a04b63 Mon Sep 17 00:00:00 2001 From: Dustin Brickwood Date: Tue, 3 Dec 2024 20:36:30 -0600 Subject: [PATCH 6/6] chore: lint --- src/formatter.rs | 2 -- 1 file changed, 2 deletions(-) diff --git a/src/formatter.rs b/src/formatter.rs index ecb55463..a8ff6663 100644 --- a/src/formatter.rs +++ b/src/formatter.rs @@ -928,7 +928,6 @@ fn format_revert_reason(reason: &VmRevertReason) -> String { } fn format_halt_reason(halt: &Halt) -> String { match halt { - // Group all Halt variants that use VmRevertReason Halt::ValidationFailed(reason) | Halt::PaymasterValidationFailed(reason) | Halt::PrePaymasterPreparationFailed(reason) @@ -938,7 +937,6 @@ fn format_halt_reason(halt: &Halt) -> String { | Halt::Unknown(reason) => { format!("Halt({})", format_revert_reason(reason)) } - // Handle non-VmRevertReason variants individually Halt::FromIsNotAnAccount => "Halt(FromIsNotAnAccount)".to_string(), Halt::InnerTxError => "Halt(InnerTxError)".to_string(), Halt::UnexpectedVMBehavior(msg) => {