From f3e58cd44ed276b600cb86fd530c9de37e1b5036 Mon Sep 17 00:00:00 2001 From: Dustin Brickwood Date: Tue, 3 Dec 2024 07:07:22 -0600 Subject: [PATCH] fix: fixes broken logging and adds structure to logs (#411) * feat: add structured show call logging * feat: tx summary logs structured * chore: clean up * chore: wip for gas details * wip: broken but uses builder * chore: clean up * fix: fixes log structure * chore: clean up * fix: address issue with event topics, being filtered, clean up and udpate comments * chore: add paid field * fix: address broken test * chore: minor fixes * chore: fix lint * chore:small fix * fix: print console logs once per call, fix spacing * fix: lint --------- Co-authored-by: Roman Petriv --- src/config/cli.rs | 40 +- src/config/mod.rs | 84 +++- src/console_log.rs | 8 + src/data/address_map.json | 145 ++---- src/formatter.rs | 995 +++++++++++++++++++++++++++++--------- src/node/in_memory.rs | 292 +++-------- src/node/storage_logs.rs | 55 +-- src/utils.rs | 12 + 8 files changed, 1012 insertions(+), 619 deletions(-) diff --git a/src/config/cli.rs b/src/config/cli.rs index 7a4ffa5c..9f0e1e29 100644 --- a/src/config/cli.rs +++ b/src/config/cli.rs @@ -87,7 +87,12 @@ 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, @@ -325,22 +330,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 +339,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 +391,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..58bc84ad 100644 --- a/src/config/mod.rs +++ b/src/config/mod.rs @@ -600,6 +600,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; + self.resolve_hashes = true; + self.show_gas_details = ShowGasDetails::All; + self + } + /// Set the visibility of call logs #[must_use] pub fn with_show_calls(mut self, show_calls: Option) -> Self { @@ -658,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 { @@ -672,6 +686,62 @@ 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 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 { @@ -714,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/console_log.rs b/src/console_log.rs index f3514a4c..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 { diff --git a/src/data/address_map.json b/src/data/address_map.json index 065615b6..d3f53704 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", "System"], + ["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..b76bdb65 100644 --- a/src/formatter.rs +++ b/src/formatter.rs @@ -1,19 +1,656 @@ //! 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 futures::future::join_all; +use lazy_static::lazy_static; use serde::Deserialize; -use std::collections::HashMap; -use std::str; +use std::{collections::HashMap, str}; +use zksync_multivm::interface::{Call, VmEvent, VmExecutionResultAndLogs}; +use zksync_types::{ + fee_model::FeeModelConfigV2, Address, StorageLogWithPreviousValue, Transaction, H160, H256, + U256, +}; -use crate::fork::block_on; -use zksync_types::H160; +// @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)] +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, +} -use zksync_multivm::interface::{Call, VmEvent, VmExecutionResultAndLogs}; -use zksync_types::StorageLogWithPreviousValue; +/// 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; -use lazy_static::lazy_static; + 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, + } +} + +/// Responsible for formatting the data in a structured log. +pub struct Formatter { + sibling_stack: Vec, +} + +impl Default for Formatter { + fn default() -> Self { + Self::new() + } +} + +impl Formatter { + /// Creates a new formatter with an empty sibling stack. + pub fn new() -> Self { + Formatter { + sibling_stack: Vec::new(), + } + } + /// 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), + { + 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()), + ); + } + /// 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()); + } + /// 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; + + // 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)), + ("Paid:", to_human_size(total_gas_limit - 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; + } + + // 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; + + // 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; + + // 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; + + // 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) { + let event = event.clone(); + + 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())) + .unwrap_or_else(|| format!("{:42}", format!("{:?}", event.address).blue())); + + self.section( + &format!("Event [{}]", contract_display), + is_last_sibling, + |event_section| { + event_section.section("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. + #[allow(clippy::too_many_arguments)] + 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, + ) { + 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 + // 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)); + } + } + + 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 = [ + ( + "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)); + } + } + }); + } +} +// Builds the branched prefix for the structured logs. +fn build_prefix(sibling_stack: &[bool], is_last_sibling: bool) -> String { + let mut prefix = String::new(); + if !sibling_stack.is_empty() { + for &is_last in sibling_stack { + if !is_last { + prefix.push_str("β”‚ "); + } else { + prefix.push_str(" "); + } + } + let branch = if is_last_sibling { + "└─ " + } else { + "β”œβ”€ " + }; + prefix.push_str(branch); + } + prefix +} #[derive(Debug, Deserialize, Clone, PartialEq, Eq)] pub enum ContractType { @@ -43,192 +680,108 @@ lazy_static! { }; } +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(), + 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(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 { - 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(), - }) + format_known_address(address) } -/// Pretty-prints event object -/// if skip_resolve is false, will try to contact openchain to resolve the 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)) - .await - .unwrap(); - tt.push(selector.unwrap_or(format!("{:#x}", topic))); - } - } +fn format_address_human_readable( + address: H160, + initiator: H160, + 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()), + ]; - tracing::info!( - "{}", - address_to_human_readable(event.address) - .map(|x| format!("{:42}", x.blue())) - .unwrap_or(format!("{:42}", format!("{:?}", event.address).blue())) - ); + let is_initiator = address == initiator; + let is_contract = Some(address) == contract_address && !excluded_addresses.contains(&address); - tracing::info!("{}", " Topics:".truecolor(128, 128, 128)); - for indexed_topic in &tt { - tracing::info!(" {}", indexed_topic); - } + if is_initiator { + return Some(format_address("initiator", address, |s| { + s.bold().green().to_string() + })); + } + if call_type == "Create" { + 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() + })); + } - if event.value.is_empty() { - tracing::info!("{}", " Data: EMPTY".truecolor(128, 128, 128)); - } else { - match str::from_utf8(&event.value) { - Ok(v) => { - tracing::info!( - "{} {}", - " Data (String):".truecolor(128, 128, 128), - v.to_string() - ); - } - 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() - }; + format_known_address(address) +} - tracing::info!( - "{} 0x{}", - " Data (Hex):".truecolor(128, 128, 128), - display_str - ); +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) } - }; + } } - - tracing::info!(""); - }); + } } - -/// 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) +// 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 { + let futures = topics.into_iter().map(|topic| async move { + if resolve_hashes { + match resolver::decode_event_selector(&format!("{:#x}", topic)).await { + Ok(Some(resolved)) => resolved, + Ok(None) | Err(_) => format!("{:#x}", topic), + } } else { - block_on(async move { - let fetch = resolver::decode_function_selector(&sig).await.unwrap(); - fetch.unwrap_or(format!("{:>16}", format!("0x{}", sig).dimmed())) - }) + format!("{:#x}", topic) } - } 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) - .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, - ); - } + join_all(futures).await + }) } /// Amount of pubdata that given write has cost. +/// Used when displaying Storage Logs. pub enum PubdataBytesInfo { // This slot is free 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. @@ -238,14 +791,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)"), } } } @@ -262,61 +818,44 @@ impl PubdataBytesInfo { } } -pub fn print_logs( - log_query: &StorageLogWithPreviousValue, - pubdata_bytes: Option, +// @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, + tx_result: &VmExecutionResultAndLogs, + status: &str, ) { - let separator = "─".repeat(82); - tracing::info!("{:<15} {:?}", "Kind:", log_query.log.kind); - tracing::info!( - "{:<15} {}", - "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()); + // 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()); - tracing::info!("{:<15} {:#066x}", "Read Value:", log_query.previous_value,); + let refunded_gas = tx_result.refunds.gas_refunded; - if log_query.log.is_write() { - tracing::info!("{:<15} {:#066x}", "Written Value:", log_query.log.value); - } - if let Some(pubdata_bytes) = pubdata_bytes { - tracing::info!("{:<15} {:}", "Pubdata bytes:", pubdata_bytes); - } - tracing::info!("{}", separator); -} + // Calculate refunded gas in ETH + let refunded_in_eth = calculate_eth_cost(l2_gas_price, refunded_gas); -pub fn print_vm_details(result: &VmExecutionResultAndLogs) { - tracing::info!(""); - tracing::info!("β”Œβ”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”"); - tracing::info!("β”‚ VM EXECUTION RESULTS β”‚"); - tracing::info!("β””β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”€β”˜"); + let emoji = match status { + "SUCCESS" => "βœ…", + "FAILED" => "❌", + "HALTED" => "⏸️", + _ => "⚠️", + }; - tracing::info!("Cycles Used: {}", result.statistics.cycles_used); + tracing::info!("{} [{}] Hash: {:?}", emoji, status, tx.hash()); + tracing::info!("Initiator: {:?}", tx.initiator_account()); + tracing::info!("Payer: {:?}", tx.payer()); tracing::info!( - "Computation Gas Used: {}", - result.statistics.computational_gas_used + "Gas 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!("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!("════════════════════════════"); + 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); } diff --git a/src/node/in_memory.rs b/src/node/in_memory.rs index cf29d32c..f57a2700 100644 --- a/src/node/in_memory.rs +++ b/src/node/in_memory.rs @@ -70,7 +70,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). @@ -1259,7 +1259,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()); @@ -1275,6 +1275,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()); @@ -1291,20 +1292,26 @@ 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); - } + inner + .console_log_handler + .handle_calls_recursive(&call_traces); } if inner.config.show_calls != ShowCalls::None { tracing::info!(""); - tracing::info!("=== Call traces:"); - for call in &call_traces { - formatter::print_call( + 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, - 0, + is_last_sibling, &inner.config.show_calls, inner.config.show_outputs, inner.config.resolve_hashes, @@ -1315,6 +1322,7 @@ impl InMemoryNode { Ok(tx_result.result) } + // Prints the gas details of the transaction for debugging purposes. fn display_detailed_gas_info( &self, bootloader_debug_result: Option<&eyre::Result>, @@ -1323,163 +1331,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()) } } @@ -1574,91 +1440,77 @@ impl InMemoryNode { let spent_on_pubdata = tx_result.statistics.gas_used - tx_result.statistics.computational_gas_used as u64; - 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()), - } + let status = match &tx_result.result { + ExecutionResult::Success { .. } => "SUCCESS", + ExecutionResult::Revert { .. } => "FAILED", + ExecutionResult::Halt { .. } => "HALTED", + }; - 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()) + // Print transaction summary + if inner.config.show_tx_summary { + tracing::info!(""); + formatter::print_transaction_summary( + inner.config.get_l2_gas_price(), + &tx, + &tx_result, + status, ); + tracing::info!(""); } - + // Print gas details if enabled 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() - ); - } + 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()); + }); } - + // Print storage logs if enabled if inner.config.show_storage_logs != ShowStorageLogs::None { print_storage_logs_details(&inner.config.show_storage_logs, &tx_result); } - + // Print VM details if enabled if inner.config.show_vm_details != ShowVMDetails::None { - formatter::print_vm_details(&tx_result); + let mut formatter = formatter::Formatter::new(); + formatter.print_vm_details(&tx_result); } 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); - } + inner + .console_log_handler + .handle_calls_recursive(call_traces); } 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() + "[Transaction Execution] ({} calls)", + call_traces[0].calls.len() ); - - for call in call_traces { - formatter::print_call( + 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, - 0, + is_last_sibling, &inner.config.show_calls, inner.config.show_outputs, inner.config.resolve_hashes, ); } } - + // Print event logs if enabled if inner.config.show_event_logs { tracing::info!(""); - tracing::info!( - "==== {}", - format!("{} events", tx_result.logs.events.len()).bold() - ); - 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; + let mut formatter = formatter::Formatter::new(); + formatter.print_event(event, inner.config.resolve_hashes, is_last); } + tracing::info!(""); } let mut bytecodes = HashMap::new(); diff --git a/src/node/storage_logs.rs b/src/node/storage_logs.rs index ddf3aed4..cda90032 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,25 @@ 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; + let mut formatter = formatter::Formatter::new(); + formatter.print_storage_logs(log_query, pubdata_bytes_info, index + 1, is_last); } } } diff --git a/src/utils.rs b/src/utils.rs index 06725520..8ff0032b 100644 --- a/src/utils.rs +++ b/src/utils.rs @@ -322,6 +322,18 @@ impl TryFrom for u64 { } } +/// 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; + + // 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 + total_cost_in_gwei / 1e9 +} + #[cfg(test)] mod tests { use zksync_types::U256;