From 4285e6d468c3eaf8e047c9d815bb018e9a001e5e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Juli=C3=A1n=20Gonz=C3=A1lez=20Calder=C3=B3n?= Date: Fri, 28 Jun 2024 13:09:08 -0300 Subject: [PATCH 01/12] Add tracing dep in workspace --- Cargo.toml | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index 8298dc5..853adad 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,8 +1,5 @@ [workspace] -members = [ - "rpc-state-reader", - "replay", -] +members = ["rpc-state-reader", "replay"] # Explicitly set the resolver to the default for edition >= 2021 @@ -13,3 +10,4 @@ resolver = "2" thiserror = "1.0.32" starknet_api = "=0.12.0-dev.1" blockifier = { git = "https://github.com/NethermindEth/blockifier", rev = "3b16c2a3601b9a594c94c325d3c64552b2061a95" } +tracing = "0.1" From a3ce4705cd2b483bd7868585d8b5ed875a9112a4 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Juli=C3=A1n=20Gonz=C3=A1lez=20Calder=C3=B3n?= Date: Fri, 28 Jun 2024 13:15:07 -0300 Subject: [PATCH 02/12] Update tracing dep in binary --- replay/Cargo.toml | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/replay/Cargo.toml b/replay/Cargo.toml index 526ccf2..65252c1 100644 --- a/replay/Cargo.toml +++ b/replay/Cargo.toml @@ -8,15 +8,14 @@ benchmark = [] [dependencies] # starknet specific crates -blockifier = {workspace = true} +blockifier = { workspace = true } rpc-state-reader = { path = "../rpc-state-reader" } starknet_api = { workspace = true } # CLI specific crates clap = { version = "4.4.6", features = ["derive"] } indicatif = "0.17.7" # logs -tracing = "0.1" -tracing-subscriber = "0.3.17" +tracing = { workspace = true } +tracing-subscriber = { version = "0.3.18", features = ["env-filter"] } # error handling anyhow = "1.0" - From d5f731d636a7c2a4960efd7d713cf117f93ea861 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Juli=C3=A1n=20Gonz=C3=A1lez=20Calder=C3=B3n?= Date: Fri, 28 Jun 2024 14:34:09 -0300 Subject: [PATCH 03/12] Initialize global subscriber --- replay/src/main.rs | 22 ++++++++++++++++++++-- 1 file changed, 20 insertions(+), 2 deletions(-) diff --git a/replay/src/main.rs b/replay/src/main.rs index 2e45909..8295b7a 100644 --- a/replay/src/main.rs +++ b/replay/src/main.rs @@ -33,8 +33,12 @@ use starknet_in_rust::{ }; #[cfg(feature = "benchmark")] use std::ops::Div; +use std::str::FromStr; #[cfg(feature = "benchmark")] use std::{collections::HashMap, sync::Arc, time::Instant}; +use tracing::info; +use tracing_subscriber::filter::Directive; +use tracing_subscriber::{util::SubscriberInitExt, EnvFilter}; #[derive(Debug, Parser)] #[command(about = "Replay is a tool for executing Starknet transactions.", long_about = None)] @@ -79,8 +83,9 @@ Caches all rpc data before the benchmark runs to provide accurate results" } fn main() { - let cli = ReplayCLI::parse(); + set_global_subscriber(); + let cli = ReplayCLI::parse(); match cli.subcommand { ReplayExecute::Tx { tx_hash, @@ -96,7 +101,7 @@ fn main() { chain, silent, } => { - println!("Executing block number: {}", block_number); + info!("executing block {number}", number = block_number); let mut state = build_cached_state(&chain, block_number); @@ -330,3 +335,16 @@ fn get_transaction_hashes(network: &str, block_number: u64) -> Result Date: Fri, 28 Jun 2024 14:40:34 -0300 Subject: [PATCH 04/12] Remove silent flag --- replay/src/main.rs | 46 ++++++++++++++++------------------------------ 1 file changed, 16 insertions(+), 30 deletions(-) diff --git a/replay/src/main.rs b/replay/src/main.rs index 8295b7a..8062512 100644 --- a/replay/src/main.rs +++ b/replay/src/main.rs @@ -54,20 +54,14 @@ enum ReplayExecute { tx_hash: String, chain: String, block_number: u64, - silent: Option, }, #[clap(about = "Execute all the transactions in a given block.")] - Block { - chain: String, - block_number: u64, - silent: Option, - }, + Block { chain: String, block_number: u64 }, #[clap(about = "Execute all the transactions in a given range of blocks.")] BlockRange { block_start: u64, block_end: u64, chain: String, - silent: Option, }, #[cfg(feature = "benchmark")] #[clap( @@ -91,15 +85,13 @@ fn main() { tx_hash, chain, block_number, - silent, } => { let mut state = build_cached_state(&chain, block_number); - show_execution_data(&mut state, tx_hash, &chain, block_number, silent); + show_execution_data(&mut state, tx_hash, &chain, block_number); } ReplayExecute::Block { block_number, chain, - silent, } => { info!("executing block {number}", number = block_number); @@ -107,16 +99,14 @@ fn main() { let transaction_hashes = get_transaction_hashes(&chain, block_number) .expect("Unable to fetch the transaction hashes."); - for tx_hash in transaction_hashes { - show_execution_data(&mut state, tx_hash, &chain, block_number, silent); + show_execution_data(&mut state, tx_hash, &chain, block_number); } } ReplayExecute::BlockRange { block_start, block_end, chain, - silent, } => { println!("Executing block range: {} - {}", block_start, block_end); @@ -127,7 +117,7 @@ fn main() { .expect("Unable to fetch the transaction hashes."); for tx_hash in transaction_hashes { - show_execution_data(&mut state, tx_hash, &chain, block_number, silent); + show_execution_data(&mut state, tx_hash, &chain, block_number); } } } @@ -285,13 +275,11 @@ fn show_execution_data( tx_hash: String, chain: &str, block_number: u64, - silent: Option, ) { - if silent.is_none() || !silent.unwrap() { - println!("Executing transaction with hash: {}", tx_hash); - println!("Block number: {}", block_number); - println!("Chain: {}", chain); - } + println!("Executing transaction with hash: {}", tx_hash); + println!("Block number: {}", block_number); + println!("Chain: {}", chain); + let previous_block_number = BlockNumber(block_number - 1); let (tx_info, _trace, receipt) = @@ -316,17 +304,15 @@ fn show_execution_data( .. } = receipt; - if silent.is_none() || !silent.unwrap() { - println!("[RPC] Execution status: {:?}", execution_status); - if let Some(revert_error) = revert_error { - println!("[SIR] Revert error: {}", revert_error); - } - println!( - "[RPC] Actual fee: {} {}", - actual_fee.amount, actual_fee.unit - ); - println!("[SIR] Actual fee: {:?} wei", sir_actual_fee); + println!("[RPC] Execution status: {:?}", execution_status); + if let Some(revert_error) = revert_error { + println!("[SIR] Revert error: {}", revert_error); } + println!( + "[RPC] Actual fee: {} {}", + actual_fee.amount, actual_fee.unit + ); + println!("[SIR] Actual fee: {:?} wei", sir_actual_fee); } fn get_transaction_hashes(network: &str, block_number: u64) -> Result, RpcStateError> { From 120b7d45bd622ca5ef2c2e88c9a33c7794d9cfb9 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Juli=C3=A1n=20Gonz=C3=A1lez=20Calder=C3=B3n?= Date: Fri, 28 Jun 2024 15:24:19 -0300 Subject: [PATCH 05/12] Use tracing instead of println --- replay/src/main.rs | 32 ++++++++++++++++++-------------- 1 file changed, 18 insertions(+), 14 deletions(-) diff --git a/replay/src/main.rs b/replay/src/main.rs index b8fb0ee..9ec4b9a 100644 --- a/replay/src/main.rs +++ b/replay/src/main.rs @@ -36,7 +36,7 @@ use std::ops::Div; use std::str::FromStr; #[cfg(feature = "benchmark")] use std::{collections::HashMap, sync::Arc, time::Instant}; -use tracing::info; +use tracing::{error, info, info_span}; use tracing_subscriber::filter::Directive; use tracing_subscriber::{util::SubscriberInitExt, EnvFilter}; @@ -93,9 +93,9 @@ fn main() { block_number, chain, } => { - info!("executing block {number}", number = block_number); + info!("executing block {}", block_number); - let mut state = build_cached_state(&chain, block_number); + let mut state = build_cached_state(&chain, block_number - 1); let transaction_hashes = get_transaction_hashes(&chain, block_number) .expect("Unable to fetch the transaction hashes."); @@ -108,7 +108,7 @@ fn main() { block_end, chain, } => { - println!("Executing block range: {} - {}", block_start, block_end); + info!("executing block range: {} - {}", block_start, block_end); for block_number in block_start..=block_end { let mut state = build_cached_state(&chain, block_number); @@ -259,8 +259,8 @@ fn parse_network(network: &str) -> RpcChain { } } -fn build_cached_state(network: &str, current_block_number: u64) -> CachedState { - let previous_block_number = BlockNumber(current_block_number - 1); +fn build_cached_state(network: &str, block_number: u64) -> CachedState { + let previous_block_number = BlockNumber(block_number); let rpc_chain = parse_network(&network); let rpc_reader = RpcStateReader( RpcState::new_rpc(rpc_chain, previous_block_number.into()) @@ -276,9 +276,13 @@ fn show_execution_data( chain: &str, block_number: u64, ) { - println!("Executing transaction with hash: {}", tx_hash); - println!("Block number: {}", block_number); - println!("Chain: {}", chain); + let _transaction_execution_span = info_span!( + "transaction execution", + hash = tx_hash, + block_number = block_number, + chain = chain + ) + .entered(); let previous_block_number = BlockNumber(block_number - 1); @@ -286,7 +290,7 @@ fn show_execution_data( match execute_tx_configurable(state, &tx_hash, previous_block_number, false, true) { Ok(x) => x, Err(error_reason) => { - println!("Error: {}", error_reason); + error!("transaction execution failed: {}", error_reason); return; } }; @@ -304,15 +308,15 @@ fn show_execution_data( .. } = receipt; - println!("[RPC] Execution status: {:?}", execution_status); + info!("[RPC] Execution status: {:?}", execution_status); if let Some(revert_error) = revert_error { - println!("[Blockifier] Revert error: {}", revert_error); + error!("[Blockifier] Revert error: {}", revert_error); } - println!( + info!( "[RPC] Actual fee: {} {}", actual_fee.amount, actual_fee.unit ); - println!("[Blockifier] Actual fee: {:?} wei", blockifier_actual_fee); + info!("[Blockifier] Actual fee: {:?} wei", blockifier_actual_fee); } fn get_transaction_hashes(network: &str, block_number: u64) -> Result, RpcStateError> { From 7efbc2e280ccc0b8a1d09fb002b9c58702956185 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Juli=C3=A1n=20Gonz=C3=A1lez=20Calder=C3=B3n?= Date: Fri, 28 Jun 2024 17:59:51 -0300 Subject: [PATCH 06/12] Add logging --- replay/src/main.rs | 66 ++++++++++++++++++++++++---------------------- 1 file changed, 34 insertions(+), 32 deletions(-) diff --git a/replay/src/main.rs b/replay/src/main.rs index 9ec4b9a..edbee69 100644 --- a/replay/src/main.rs +++ b/replay/src/main.rs @@ -1,10 +1,10 @@ use blockifier::{ - state::cached_state::CachedState, transaction::objects::TransactionExecutionInfo, + execution, state::cached_state::CachedState, transaction::objects::TransactionExecutionInfo, }; use clap::{Parser, Subcommand}; use rpc_state_reader::{ blockifier_state_reader::RpcStateReader, - rpc_state::{BlockValue, RpcChain, RpcState, RpcTransactionReceipt}, + rpc_state::{self, BlockValue, RpcChain, RpcState, RpcTransactionReceipt}, rpc_state_errors::RpcStateError, }; @@ -36,7 +36,7 @@ use std::ops::Div; use std::str::FromStr; #[cfg(feature = "benchmark")] use std::{collections::HashMap, sync::Arc, time::Instant}; -use tracing::{error, info, info_span}; +use tracing::{error, field, info, info_span}; use tracing_subscriber::filter::Directive; use tracing_subscriber::{util::SubscriberInitExt, EnvFilter}; @@ -93,7 +93,7 @@ fn main() { block_number, chain, } => { - info!("executing block {}", block_number); + let _block_span = info_span!("block", number = block_number).entered(); let mut state = build_cached_state(&chain, block_number - 1); @@ -111,6 +111,8 @@ fn main() { info!("executing block range: {} - {}", block_start, block_end); for block_number in block_start..=block_end { + let _block_span = info_span!("block", number = block_number).entered(); + let mut state = build_cached_state(&chain, block_number); let transaction_hashes = get_transaction_hashes(&chain, block_number) @@ -276,47 +278,44 @@ fn show_execution_data( chain: &str, block_number: u64, ) { - let _transaction_execution_span = info_span!( - "transaction execution", - hash = tx_hash, - block_number = block_number, - chain = chain - ) - .entered(); + let transaction_execution_span = + info_span!("transaction", hash = tx_hash, chain, status = field::Empty).entered(); + + info!("starting execution"); let previous_block_number = BlockNumber(block_number - 1); - let (tx_info, _trace, receipt) = + let (execution_info, _trace, rpc_receipt) = match execute_tx_configurable(state, &tx_hash, previous_block_number, false, true) { Ok(x) => x, Err(error_reason) => { - error!("transaction execution failed: {}", error_reason); + error!("execution failed unexpectedly: {}", error_reason); return; } }; - let TransactionExecutionInfo { - revert_error, - actual_fee, - .. - } = tx_info; - let blockifier_actual_fee = actual_fee; + let execution_status = match &execution_info.revert_error { + Some(_) => "REVERTED", + None => "SUCCEEDED", + }; + let rpc_status = rpc_receipt.execution_status; + let status_matches = execution_status == rpc_status; + transaction_execution_span.record("status", execution_status); - let RpcTransactionReceipt { - actual_fee, - execution_status, - .. - } = receipt; + info!(execution_status, rpc_status, "execution finished"); - info!("[RPC] Execution status: {:?}", execution_status); - if let Some(revert_error) = revert_error { - error!("[Blockifier] Revert error: {}", revert_error); + // let execution_gas = execution_info.actual_fee; + // let rpc_gas = rpc_receipt.actual_fee; + // info!(?execution_gas, ?rpc_gas, "execution actual fee"); + + if !status_matches { + let execution_error_message = execution_info.revert_error.unwrap_or_default(); + // todo: if logging is filtered by error level, then the transaction span is not shown. + // it should also log the transaction span + error!(execution_error_message, "rpc and execution status diverged") + } else if let Some(revert_reason) = execution_info.revert_error { + info!(revert_reason, "blockifier transaction reverted"); } - info!( - "[RPC] Actual fee: {} {}", - actual_fee.amount, actual_fee.unit - ); - info!("[Blockifier] Actual fee: {:?} wei", blockifier_actual_fee); } fn get_transaction_hashes(network: &str, block_number: u64) -> Result, RpcStateError> { @@ -335,6 +334,9 @@ fn set_global_subscriber() { .with_default_directive(default_directive) .from_env_lossy() }) + // .pretty() + .with_file(false) + .with_line_number(false) .finish() .init(); } From ed2a3727a1437728381f5c0ba7405e5a70b22d82 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Juli=C3=A1n=20Gonz=C3=A1lez=20Calder=C3=B3n?= Date: Fri, 28 Jun 2024 18:02:58 -0300 Subject: [PATCH 07/12] Use pretty format --- replay/src/main.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/replay/src/main.rs b/replay/src/main.rs index edbee69..e6bd081 100644 --- a/replay/src/main.rs +++ b/replay/src/main.rs @@ -334,7 +334,7 @@ fn set_global_subscriber() { .with_default_directive(default_directive) .from_env_lossy() }) - // .pretty() + .pretty() .with_file(false) .with_line_number(false) .finish() From 35b441fe11b33c0bb4dc68511f11054cd55bb373 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Juli=C3=A1n=20Gonz=C3=A1lez=20Calder=C3=B3n?= Date: Mon, 1 Jul 2024 11:40:56 -0300 Subject: [PATCH 08/12] Show context in event arguments --- replay/src/main.rs | 37 +++++++++++++++++++++---------------- 1 file changed, 21 insertions(+), 16 deletions(-) diff --git a/replay/src/main.rs b/replay/src/main.rs index e6bd081..2bf83c4 100644 --- a/replay/src/main.rs +++ b/replay/src/main.rs @@ -36,7 +36,7 @@ use std::ops::Div; use std::str::FromStr; #[cfg(feature = "benchmark")] use std::{collections::HashMap, sync::Arc, time::Instant}; -use tracing::{error, field, info, info_span}; +use tracing::{debug, error, field, info, info_span, span}; use tracing_subscriber::filter::Directive; use tracing_subscriber::{util::SubscriberInitExt, EnvFilter}; @@ -278,8 +278,7 @@ fn show_execution_data( chain: &str, block_number: u64, ) { - let transaction_execution_span = - info_span!("transaction", hash = tx_hash, chain, status = field::Empty).entered(); + let _transaction_execution_span = info_span!("transaction", hash = tx_hash, chain).entered(); info!("starting execution"); @@ -300,22 +299,28 @@ fn show_execution_data( }; let rpc_status = rpc_receipt.execution_status; let status_matches = execution_status == rpc_status; - transaction_execution_span.record("status", execution_status); - - info!(execution_status, rpc_status, "execution finished"); - - // let execution_gas = execution_info.actual_fee; - // let rpc_gas = rpc_receipt.actual_fee; - // info!(?execution_gas, ?rpc_gas, "execution actual fee"); if !status_matches { - let execution_error_message = execution_info.revert_error.unwrap_or_default(); - // todo: if logging is filtered by error level, then the transaction span is not shown. - // it should also log the transaction span - error!(execution_error_message, "rpc and execution status diverged") - } else if let Some(revert_reason) = execution_info.revert_error { - info!(revert_reason, "blockifier transaction reverted"); + error!( + transaction_hash = tx_hash, + chain = chain, + execution_status, + execution_error_message = execution_info.revert_error, + "rpc and execution status diverged" + ) + } else { + info!( + transaction_hash = tx_hash, + chain = chain, + execution_status, + execution_error_message = execution_info.revert_error, + "execution finished successfully" + ); } + + let execution_gas = execution_info.actual_fee; + let rpc_gas = rpc_receipt.actual_fee; + debug!(?execution_gas, ?rpc_gas, "execution actual fee"); } fn get_transaction_hashes(network: &str, block_number: u64) -> Result, RpcStateError> { From d8a5cfc6d2a9482ea21f95c3b6b02ebdd9571fa1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Juli=C3=A1n=20Gonz=C3=A1lez=20Calder=C3=B3n?= Date: Mon, 1 Jul 2024 18:35:23 -0300 Subject: [PATCH 09/12] Add rpc_execution_status to events --- replay/src/main.rs | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/replay/src/main.rs b/replay/src/main.rs index 2bf83c4..91b37e4 100644 --- a/replay/src/main.rs +++ b/replay/src/main.rs @@ -297,14 +297,15 @@ fn show_execution_data( Some(_) => "REVERTED", None => "SUCCEEDED", }; - let rpc_status = rpc_receipt.execution_status; - let status_matches = execution_status == rpc_status; + let rpc_execution_status = rpc_receipt.execution_status; + let status_matches = execution_status == rpc_execution_status; if !status_matches { error!( transaction_hash = tx_hash, chain = chain, execution_status, + rpc_execution_status, execution_error_message = execution_info.revert_error, "rpc and execution status diverged" ) @@ -313,6 +314,7 @@ fn show_execution_data( transaction_hash = tx_hash, chain = chain, execution_status, + rpc_execution_status, execution_error_message = execution_info.revert_error, "execution finished successfully" ); From d426a59a8cead20454371378b9dad9757a690bf7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Juli=C3=A1n=20Gonz=C3=A1lez=20Calder=C3=B3n?= Date: Mon, 1 Jul 2024 19:09:13 -0300 Subject: [PATCH 10/12] Add logging to the readme --- README.md | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/README.md b/README.md index 601aa2f..28a0a25 100644 --- a/README.md +++ b/README.md @@ -34,3 +34,12 @@ You can use the replay crate to execute transactions or blocks via the CLI. For * cargo run block mainnet 648655 * cargo run block-range 90000 90002 mainnet ``` + +### Logging + +This projects uses tracing with env-filter, so logging can be modified by the RUST_LOG environment variable. By default, only info events from the replay crate are shown. + +As an example, to show only error messages from the replay crate, run: +```bash +RUST_LOG=replay=error cargo run block mainnet 648461 +``` From 871b9fe006962d24f28adb92551dbc06660b23c9 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Juli=C3=A1n=20Gonz=C3=A1lez=20Calder=C3=B3n?= Date: Tue, 2 Jul 2024 10:23:47 -0300 Subject: [PATCH 11/12] Fix bug --- replay/src/main.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/replay/src/main.rs b/replay/src/main.rs index 91b37e4..8e4f374 100644 --- a/replay/src/main.rs +++ b/replay/src/main.rs @@ -86,7 +86,7 @@ fn main() { chain, block_number, } => { - let mut state = build_cached_state(&chain, block_number); + let mut state = build_cached_state(&chain, block_number - 1); show_execution_data(&mut state, tx_hash, &chain, block_number); } ReplayExecute::Block { From a2cab97551270b1720d6080df0e60339ead545c9 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Juli=C3=A1n=20Gonz=C3=A1lez=20Calder=C3=B3n?= Date: Tue, 2 Jul 2024 12:31:37 -0300 Subject: [PATCH 12/12] Fix bug --- replay/src/main.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/replay/src/main.rs b/replay/src/main.rs index 8e4f374..7434c4f 100644 --- a/replay/src/main.rs +++ b/replay/src/main.rs @@ -113,7 +113,7 @@ fn main() { for block_number in block_start..=block_end { let _block_span = info_span!("block", number = block_number).entered(); - let mut state = build_cached_state(&chain, block_number); + let mut state = build_cached_state(&chain, block_number - 1); let transaction_hashes = get_transaction_hashes(&chain, block_number) .expect("Unable to fetch the transaction hashes.");