From 64f21cc48e781084ea39c609083ef46d3285e08d Mon Sep 17 00:00:00 2001 From: Roman Date: Wed, 15 May 2024 17:50:42 +0800 Subject: [PATCH] Add logging (first tier) (#567) * Add logging (first tier) * Review fixes --- crates/bitcoin-da/src/helpers/builders.rs | 27 +++++++++++ crates/bitcoin-da/src/rpc.rs | 12 +++-- crates/bitcoin-da/src/service.rs | 26 ++++++++++- crates/ethereum-rpc/src/lib.rs | 7 +-- crates/evm/src/call.rs | 13 ++++-- crates/evm/src/evm/executor.rs | 11 ++++- crates/evm/src/evm/handler.rs | 21 +++++++-- crates/sequencer/src/commitment_controller.rs | 4 +- crates/sequencer/src/deposit_data_mempool.rs | 2 + crates/sequencer/src/rpc.rs | 4 +- crates/sequencer/src/sequencer.rs | 5 +- .../sov-prover-storage-manager/src/lib.rs | 46 ++++++++++--------- .../full-node/sov-stf-runner/src/runner.rs | 9 +++- 13 files changed, 143 insertions(+), 44 deletions(-) diff --git a/crates/bitcoin-da/src/helpers/builders.rs b/crates/bitcoin-da/src/helpers/builders.rs index 599b38cd9..d7b641163 100644 --- a/crates/bitcoin-da/src/helpers/builders.rs +++ b/crates/bitcoin-da/src/helpers/builders.rs @@ -1,3 +1,4 @@ +use core::fmt; use core::result::Result::Ok; use core::str::FromStr; use std::fs::File; @@ -21,6 +22,7 @@ use bitcoin::{ Witness, }; use brotli::{CompressorWriter, DecompressorWriter}; +use tracing::{instrument, trace, warn}; use crate::helpers::{BODY_TAG, PUBLICKEY_TAG, RANDOM_TAG, ROLLUP_NAME_TAG, SIGNATURE_TAG}; use crate::spec::utxo::UTXO; @@ -140,6 +142,7 @@ fn choose_utxos( } } +#[instrument(level = "trace", skip(utxos), err)] fn build_commit_transaction( prev_tx: Option, // reuse outputs to add commit tx order utxos: Vec, @@ -184,9 +187,16 @@ fn build_commit_transaction( } else { (None, utxos) }; + let mut iteration = 0; let mut last_size = size; let tx = loop { + if iteration % 100 == 0 { + trace!(iteration, "Trying to find commitment size"); + if iteration > 5000 { + warn!("Too many iterations"); + } + } let fee = ((last_size as f64) * fee_rate).ceil() as u64; let input_total = output_value + fee; @@ -247,6 +257,7 @@ fn build_commit_transaction( } last_size = size; + iteration += 1; }; Ok(tx) @@ -308,10 +319,20 @@ pub struct TxWithId { pub tx: Transaction, } +impl fmt::Debug for TxWithId { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + f.debug_struct("TxWithId") + .field("id", &self.id) + .field("tx", &"...") + .finish() + } +} + // TODO: parametrize hardness // so tests are easier // Creates the inscription transactions (commit and reveal) #[allow(clippy::too_many_arguments)] +#[instrument(level = "trace", skip_all, err)] pub fn create_inscription_transactions( rollup_name: &str, body: Vec, @@ -358,6 +379,12 @@ pub fn create_inscription_transactions( // Start loop to find a 'nonce' i.e. random number that makes the reveal tx hash starting with zeros given length let mut nonce: i64 = 0; loop { + if nonce % 100 == 0 { + trace!(nonce, "Trying to find commit & reveal nonce"); + if nonce > 1000 { + warn!("Too many iterations"); + } + } let utxos = utxos.clone(); let recipient = recipient.clone(); // ownerships are moved to the loop diff --git a/crates/bitcoin-da/src/rpc.rs b/crates/bitcoin-da/src/rpc.rs index d034bac4a..c139d3b2d 100644 --- a/crates/bitcoin-da/src/rpc.rs +++ b/crates/bitcoin-da/src/rpc.rs @@ -1,4 +1,4 @@ -use core::fmt::Display; +use core::fmt::{Debug, Display}; use core::str::FromStr; use bitcoin::block::{Header, Version}; @@ -9,6 +9,7 @@ use reqwest::header::HeaderMap; use serde::{Deserialize, Serialize}; use serde_json::value::RawValue; use serde_json::{json, to_value}; +use tracing::{instrument, warn}; use crate::helpers::parsers::parse_hex_transaction; use crate::spec::block::BitcoinBlock; @@ -44,6 +45,7 @@ pub struct BitcoinNode { client: reqwest::Client, } impl BitcoinNode { + #[instrument(level = "trace", ret)] pub fn new(url: String, username: String, password: String) -> Self { let mut headers = HeaderMap::new(); headers.insert( @@ -69,6 +71,7 @@ impl BitcoinNode { Self { url, client } } + #[instrument(level = "trace", skip_all, err)] async fn call_inner( &self, method: &str, @@ -89,6 +92,7 @@ impl BitcoinNode { let response = response.json::>().await?; if let Some(error) = response.error { + warn!(error=?error, "RPC returned error"); return Ok(Err(error)); } @@ -96,7 +100,8 @@ impl BitcoinNode { } // TODO: add max retries - async fn call( + #[instrument(level = "trace", skip(self), err, ret)] + async fn call( &self, method: &str, params: Vec, @@ -112,7 +117,7 @@ impl BitcoinNode { // sometimes requests to bitcoind are dropped without a reason // TODO: maybe remove is_request() check? if error.is_connect() || error.is_timeout() || error.is_request() { - tracing::warn!(error=?error, attempt=attempt, "Failed to send a call to bitcoind"); + warn!(error=?error, attempt=attempt, "Failed to send a call to bitcoind"); attempt += 1; tokio::time::sleep(tokio::time::Duration::from_millis(500)).await; continue; // retry @@ -221,6 +226,7 @@ impl BitcoinNode { } // estimate_smart_fee estimates the fee to confirm a transaction in the next block + #[instrument(level = "trace", skip(self), err, ret)] pub async fn estimate_smart_fee(&self) -> Result { let result = self .call::>("estimatesmartfee", vec![to_value(1)?]) diff --git a/crates/bitcoin-da/src/service.rs b/crates/bitcoin-da/src/service.rs index 79e250734..fceb301dc 100644 --- a/crates/bitcoin-da/src/service.rs +++ b/crates/bitcoin-da/src/service.rs @@ -1,3 +1,6 @@ +// fix clippy for tracing::instrument +#![allow(clippy::blocks_in_conditions)] + use core::result::Result::Ok; use core::str::FromStr; use core::time::Duration; @@ -16,7 +19,7 @@ use tokio::sync::mpsc::{unbounded_channel, UnboundedSender}; use tokio::sync::oneshot::{ channel as oneshot_channel, Receiver as OneshotReceiver, Sender as OneshotSender, }; -use tracing::info; +use tracing::{error, info, instrument, trace}; use crate::helpers::builders::{ compress_blob, create_inscription_transactions, decompress_blob, sign_blob_with_private_key, @@ -104,8 +107,11 @@ impl BitcoinService { // TODO find last tx by utxo chain let mut prev_tx = None; + trace!("BitcoinDA queue is initialized. Waiting for the first request..."); + // We execute commit and reveal txs one by one to chain them while let Some(request) = rx.recv().await { + trace!("A new request is received"); let fee_sat_per_vbyte = match this.get_fee_rate().await { Ok(rate) => rate, Err(e) => { @@ -123,14 +129,18 @@ impl BitcoinService { { Ok(tx) => { let tx_id = TxidWrapper(tx.id); + info!(%tx.id, "Send tx to BitcoinDA"); prev_tx = Some(tx); let _ = request.notify.send(Ok(tx_id)); } Err(e) => { + error!(?e, "Failed to send transaction to DA layer"); let _ = request.notify.send(Err(e)); } } } + + error!("BitcoinDA queue stopped"); }); }); @@ -187,6 +197,7 @@ impl BitcoinService { } } + #[instrument(level = "trace", skip_all, ret)] async fn get_utxos(&self) -> Result, anyhow::Error> { let utxos = self.client.get_utxos().await?; if utxos.is_empty() { @@ -204,6 +215,7 @@ impl BitcoinService { Ok(utxos) } + #[instrument(level = "trace", fields(prev_tx), ret, err)] pub async fn send_transaction_with_fee_rate( &self, prev_tx: Option, @@ -276,6 +288,7 @@ impl BitcoinService { Ok(reveal_tx) } + #[instrument(level = "trace", skip_all, ret)] pub async fn get_fee_rate(&self) -> Result { if self.network == bitcoin::Network::Regtest { // sometimes local mempool is empty, node cannot estimate @@ -310,6 +323,7 @@ impl DaService for BitcoinService { // Make an RPC call to the node to get the block at the given height // If no such block exists, block until one does. + #[instrument(level = "trace", skip(self), err)] async fn get_block_at(&self, height: u64) -> Result { info!("Getting block at height {}", height); @@ -344,6 +358,7 @@ impl DaService for BitcoinService { } // Fetch the [`DaSpec::BlockHeader`] of the last finalized block. + #[instrument(level = "trace", skip(self), err)] async fn get_last_finalized_block_header( &self, ) -> Result<::BlockHeader, Self::Error> { @@ -364,6 +379,7 @@ impl DaService for BitcoinService { } // Fetch the head block of DA. + #[instrument(level = "trace", skip(self), err)] async fn get_head_block_header( &self, ) -> Result<::BlockHeader, Self::Error> { @@ -375,6 +391,7 @@ impl DaService for BitcoinService { } // Extract the blob transactions relevant to a particular rollup from a block. + #[instrument(level = "trace", skip_all)] fn extract_relevant_blobs( &self, block: &Self::FilteredBlock, @@ -418,6 +435,7 @@ impl DaService for BitcoinService { txs } + #[instrument(level = "trace", skip_all)] async fn get_extraction_proof( &self, block: &Self::FilteredBlock, @@ -483,6 +501,7 @@ impl DaService for BitcoinService { (txs, inclusion_proof, completeness_proof) } + #[instrument(level = "trace", skip_all)] async fn send_transaction( &self, _blob: &[u8], @@ -490,6 +509,7 @@ impl DaService for BitcoinService { unimplemented!("Use send_tx_no_wait instead") } + #[instrument(level = "trace", skip_all)] async fn send_tx_no_wait( &self, blob: Vec, @@ -513,14 +533,16 @@ impl DaService for BitcoinService { unimplemented!(); } + #[instrument(level = "trace", skip(self))] async fn get_fee_rate(&self) -> Result { // This already returns ceil, so the conversion should work - let res = self.client.estimate_smart_fee().await.unwrap() as u128; + let res = self.client.estimate_smart_fee().await? as u128; // multiply with 10^10/4 = 25*10^8 = 2_500_000_000 let multiplied_fee = res.saturating_mul(2_500_000_000); Ok(multiplied_fee) } + #[instrument(level = "trace", skip(self))] async fn get_block_by_hash(&self, hash: [u8; 32]) -> Result { info!("Getting block with hash {:?}", hash); diff --git a/crates/ethereum-rpc/src/lib.rs b/crates/ethereum-rpc/src/lib.rs index 7729cc7f8..340de29da 100644 --- a/crates/ethereum-rpc/src/lib.rs +++ b/crates/ethereum-rpc/src/lib.rs @@ -28,7 +28,7 @@ use serde_json::json; use sov_modules_api::utils::to_jsonrpsee_error_object; use sov_modules_api::WorkingSet; use sov_rollup_interface::services::da::DaService; -use tracing::info; +use tracing::{info, instrument}; const MAX_TRACE_BLOCK: u32 = 1000; @@ -127,6 +127,7 @@ impl Ethereum { } impl Ethereum { + #[instrument(level = "trace", skip_all)] async fn max_fee_per_gas(&self, working_set: &mut WorkingSet) -> (U256, U256) { let suggested_tip = self .gas_price_oracle @@ -610,7 +611,7 @@ fn register_rpc_methods( // else; calls the debug_trace_transaction_block function in evm // that function traces the entire block, returns all the traces to here // then we put them into cache and return the trace of the requested transaction - info!("eth module: debug_traceTransaction"); + info!(params = ?parameters, "eth module: debug_traceTransaction"); let mut params = parameters.sequence(); @@ -716,7 +717,7 @@ fn register_rpc_methods( rpc.register_async_method::, _, _>( "eth_sendRawTransaction", |parameters, ethereum| async move { - info!("Full Node: eth_sendRawTransaction"); + info!(params = ?parameters, "Full Node: eth_sendRawTransaction"); // send this directly to the sequencer let data: Bytes = parameters.one()?; // sequencer client should send it diff --git a/crates/evm/src/call.rs b/crates/evm/src/call.rs index 6f8218b71..3e2dbff2c 100644 --- a/crates/evm/src/call.rs +++ b/crates/evm/src/call.rs @@ -5,6 +5,7 @@ use reth_primitives::TransactionSignedEcRecovered; use revm::primitives::{CfgEnv, CfgEnvWithHandlerCfg, EVMError, SpecId}; use sov_modules_api::prelude::*; use sov_modules_api::{CallResponse, WorkingSet}; +use tracing::{error, instrument}; use crate::evm::db::EvmDb; use crate::evm::executor::{self}; @@ -30,6 +31,7 @@ pub struct CallMessage { impl Evm { /// Executes system events for the current block and push tx to pending_transactions. + #[instrument(level = "debug", skip_all, ret)] pub(crate) fn execute_system_events( &self, system_events: Vec, @@ -53,13 +55,13 @@ impl Evm { .get(&BitcoinLightClient::address(), working_set) .is_some(); if !l1_block_hash_exists { - tracing::error!("System contract not found: BitcoinLightClient"); + error!("System contract not found: BitcoinLightClient"); return; } let bridge_contract_exists = self.accounts.get(&Bridge::address(), working_set).is_some(); if !bridge_contract_exists { - tracing::error!("System contract not found: Bridge"); + error!("System contract not found: Bridge"); return; } @@ -125,6 +127,7 @@ impl Evm { } /// Executes a call message. + #[instrument(level = "debug", skip_all, ret, err)] pub(crate) fn execute_call( &self, txs: Vec, @@ -217,7 +220,7 @@ impl Evm { // Adopted from https://github.com/paradigmxyz/reth/blob/main/crates/payload/basic/src/lib.rs#L884 Err(err) => match err { EVMError::Transaction(_) => { - tracing::error!("evm: Transaction error: {:?}", err); + error!("evm: Transaction error: {:?}", err); // This is a transactional error, so we can skip it without doing anything. continue; } @@ -230,11 +233,11 @@ impl Evm { .push(&evm_tx_recovered.hash(), &mut working_set.accessory_state()); } // This is a custom error - we need to log it but no need to shutdown the system as of now. - tracing::error!("evm: Custom error: {:?}", msg); + error!("evm: Custom error: {:?}", msg); continue; } err => { - tracing::error!("evm: Transaction error: {:?}", err); + error!("evm: Transaction error: {:?}", err); // This is a fatal error, so we need to return it. return Err(err.into()); } diff --git a/crates/evm/src/evm/executor.rs b/crates/evm/src/evm/executor.rs index f37c8b7e9..36b88e35b 100644 --- a/crates/evm/src/evm/executor.rs +++ b/crates/evm/src/evm/executor.rs @@ -3,6 +3,7 @@ use revm::primitives::{ CfgEnvWithHandlerCfg, EVMError, Env, ExecutionResult, ResultAndState, State, }; use revm::{self, Context, Database, DatabaseCommit, EvmContext}; +use tracing::{error, instrument, trace, trace_span}; use super::conversions::create_tx_env; use super::handler::{citrea_handler, CitreaExternalExt}; @@ -44,6 +45,7 @@ where /// Runs a single transaction in the configured environment and proceeds /// to return the result and state diff (without applying it). + #[instrument(level = "debug", skip_all)] fn transact( &mut self, tx: &TransactionSignedEcRecovered, @@ -54,6 +56,7 @@ where } /// Commits the given state diff to the database. + #[instrument(level = "debug", skip_all, ret)] fn commit(&mut self, state: State) where DB: DatabaseCommit, @@ -74,6 +77,7 @@ pub(crate) fn execute_tx( evm.transact_commit(tx) } +#[instrument(level = "debug", skip_all)] pub(crate) fn execute_multiple_tx< DB: Database + DatabaseCommit, EXT: CitreaExternalExt, @@ -96,10 +100,13 @@ pub(crate) fn execute_multiple_tx< let mut evm = CitreaEvm::new(db, block_env, config_env, ext); let mut tx_results = Vec::with_capacity(txs.len()); - for tx in txs { + for (i, tx) in txs.iter().enumerate() { + let _span = + trace_span!("Processing tx", i, signer = %tx.signer(), tx_hash = %tx.hash()).entered(); let result_and_state = match evm.transact(tx) { Ok(result_and_state) => result_and_state, Err(e) => { + error!(error = %e, "Transaction failed"); tx_results.push(Err(e)); continue; } @@ -107,6 +114,7 @@ pub(crate) fn execute_multiple_tx< // Check if the transaction used more gas than the available block gas limit let result = if cumulative_gas_used + result_and_state.result.gas_used() > block_gas_limit { + error!("Gas used exceeds block gas limit"); Err(EVMError::Custom(format!( "Gas used exceeds block gas limit {:?}", block_gas_limit @@ -117,6 +125,7 @@ pub(crate) fn execute_multiple_tx< hex::encode(tx.hash()) ))) } else { + trace!("Commiting tx to DB"); evm.commit(result_and_state.state); cumulative_gas_used += result_and_state.result.gas_used(); Ok(result_and_state.result) diff --git a/crates/evm/src/evm/handler.rs b/crates/evm/src/evm/handler.rs index f5e6cec41..cd94b1324 100644 --- a/crates/evm/src/evm/handler.rs +++ b/crates/evm/src/evm/handler.rs @@ -16,10 +16,11 @@ use revm::primitives::{ use revm::{Context, Database, FrameResult, InnerEvmContext, JournalEntry}; #[cfg(feature = "native")] use revm::{EvmContext, Inspector}; +use tracing::{debug, error, instrument, warn}; use crate::system_events::SYSTEM_SIGNER; -#[derive(Copy, Clone, Default)] +#[derive(Copy, Clone, Default, Debug)] pub struct TxInfo { pub diff_size: u64, pub l1_fee: U256, @@ -76,15 +77,17 @@ impl CitreaExternalExt for CitreaExternal { fn l1_fee_rate(&self) -> u128 { self.l1_fee_rate } + #[instrument(level = "trace", skip(self))] fn set_current_tx_hash(&mut self, hash: B256) { self.current_tx_hash.replace(hash); } + #[instrument(level = "trace", skip(self))] fn set_tx_info(&mut self, info: TxInfo) { let current_tx_hash = self.current_tx_hash.take(); if let Some(hash) = current_tx_hash { self.tx_infos.insert(hash, info); } else { - tracing::error!("No hash set for the current tx in Citrea handler"); + error!("No hash set for the current tx in Citrea handler"); } } fn get_tx_info(&self, tx_hash: B256) -> Option { @@ -199,6 +202,7 @@ impl CitreaEnv for &'_ Env { } impl CitreaEnv for &'_ mut Context { + #[instrument(level = "debug", skip(self), ret)] fn is_system_caller(&self) -> bool { (&*self.evm.env).is_system_caller() } @@ -280,6 +284,7 @@ impl CitreaHandler(context) } + #[instrument(level = "trace", skip_all)] fn deduct_caller(context: &mut Context) -> Result<(), EVMError> { if context.is_system_caller() { // System caller doesn't spend gas. @@ -299,6 +304,7 @@ impl CitreaHandler(context) } + #[instrument(level = "trace", skip_all)] fn reimburse_caller( context: &mut Context, gas: &Gas, @@ -309,6 +315,7 @@ impl CitreaHandler(context, gas) } + #[instrument(level = "trace", fields(gas), skip_all)] fn reward_beneficiary( context: &mut Context, gas: &Gas, @@ -340,6 +347,7 @@ impl CitreaHandler, result: FrameResult, @@ -368,6 +376,7 @@ impl CitreaHandler( context: &mut Context, ) -> Result::Error> { @@ -434,6 +443,10 @@ fn calc_diff_size( _ => {} } } + debug!( + accounts = account_changes.len(), + "Total accounts for diff size" + ); let slot_size = 2 * size_of::(); // key + value; let mut diff_size = 0usize; @@ -481,7 +494,7 @@ fn calc_diff_size( if let Some(code) = account.info.code.as_ref() { diff_size += code.len() } else { - tracing::warn!( + warn!( "Code must exist for account when calculating diff: {}", addr, ); @@ -513,6 +526,7 @@ fn calc_diff_size( Ok(diff_size) } +#[instrument(level = "trace", skip(context))] fn change_balance( context: &mut Context, amount: U256, @@ -529,6 +543,7 @@ fn change_balance( account.mark_touch(); let balance = &mut account.info.balance; + debug!(%balance); let new_balance = if positive { balance.saturating_add(amount) diff --git a/crates/sequencer/src/commitment_controller.rs b/crates/sequencer/src/commitment_controller.rs index cbf05c43e..24cd71397 100644 --- a/crates/sequencer/src/commitment_controller.rs +++ b/crates/sequencer/src/commitment_controller.rs @@ -7,7 +7,7 @@ use sov_db::ledger_db::LedgerDB; use sov_db::schema::types::{BatchNumber, SlotNumber}; use sov_rollup_interface::da::SequencerCommitment; use sov_rollup_interface::rpc::LedgerRpcProvider; -use tracing::debug; +use tracing::{debug, instrument}; #[derive(Clone, Debug)] pub struct CommitmentInfo { @@ -24,6 +24,7 @@ pub struct CommitmentInfo { /// Checks if the sequencer should commit /// Returns none if the commitable L2 block range is shorter than `min_soft_confirmations_per_commitment` /// Returns `CommitmentInfo` if the sequencer should commit +#[instrument(level = "debug", skip_all, fields(prev_l1_height), err)] pub fn get_commitment_info( ledger_db: &LedgerDB, min_soft_confirmations_per_commitment: u64, @@ -116,6 +117,7 @@ pub fn get_commitment_info( })) } +#[instrument(level = "debug", skip_all, err)] pub fn get_commitment( commitment_info: CommitmentInfo, soft_confirmation_hashes: Vec<[u8; 32]>, diff --git a/crates/sequencer/src/deposit_data_mempool.rs b/crates/sequencer/src/deposit_data_mempool.rs index dc20d59c2..41ea9c502 100644 --- a/crates/sequencer/src/deposit_data_mempool.rs +++ b/crates/sequencer/src/deposit_data_mempool.rs @@ -3,6 +3,7 @@ use std::collections::VecDeque; use citrea_evm::system_contracts::Bridge; use reth_primitives::{self, address}; use reth_rpc_types::{TransactionInput, TransactionRequest}; +use tracing::instrument; #[derive(Clone, Debug)] pub struct DepositDataMempool { @@ -37,6 +38,7 @@ impl DepositDataMempool { .collect() } + #[instrument(level = "trace", skip_all, ret)] pub fn add_deposit_tx(&mut self, req: Vec) { self.accepted_deposit_txs.push_back(req); } diff --git a/crates/sequencer/src/rpc.rs b/crates/sequencer/src/rpc.rs index fae3a8fb5..581deac58 100644 --- a/crates/sequencer/src/rpc.rs +++ b/crates/sequencer/src/rpc.rs @@ -14,7 +14,7 @@ use shared_backup_db::PostgresConnector; use sov_mock_da::{MockAddress, MockDaService}; use sov_modules_api::WorkingSet; use tokio::sync::Mutex; -use tracing::info; +use tracing::{error, info}; use crate::deposit_data_mempool::DepositDataMempool; use crate::mempool::CitreaMempool; @@ -152,7 +152,7 @@ pub(crate) fn create_rpc_module( .add_deposit_tx(deposit.to_vec()); } Err(e) => { - tracing::error!("Error processing deposit tx: {:?}", e); + error!("Error processing deposit tx: {:?}", e); return Err(e); } } diff --git a/crates/sequencer/src/sequencer.rs b/crates/sequencer/src/sequencer.rs index b5922191c..828edcf00 100644 --- a/crates/sequencer/src/sequencer.rs +++ b/crates/sequencer/src/sequencer.rs @@ -39,7 +39,7 @@ use sov_stf_runner::{InitVariant, RollupPublicKeys, RpcConfig}; use tokio::sync::oneshot::Receiver as OneshotReceiver; use tokio::sync::Mutex; use tokio::time::sleep; -use tracing::{debug, error, info, warn}; +use tracing::{debug, error, info, instrument, warn}; use crate::commitment_controller::{self, CommitmentInfo}; use crate::config::SequencerConfig; @@ -214,6 +214,7 @@ where Ok(()) } + #[instrument(level = "debug", skip_all, err, ret)] async fn produce_l2_block( &mut self, da_block: ::FilteredBlock, @@ -439,6 +440,7 @@ where Ok(()) } + #[instrument(level = "trace", skip_all, err, ret)] pub async fn build_block(&mut self, pg_pool: &Option) -> anyhow::Result<()> { // best txs with base fee // get base fee from last blocks => header => next base fee() function @@ -589,6 +591,7 @@ where Ok(()) } + #[instrument(level = "trace", skip(self), err, ret)] pub async fn run(&mut self) -> Result<(), anyhow::Error> { // TODO: hotfix for mock da self.da_service diff --git a/crates/sovereign-sdk/full-node/sov-prover-storage-manager/src/lib.rs b/crates/sovereign-sdk/full-node/sov-prover-storage-manager/src/lib.rs index 68f8077ac..5914b6249 100644 --- a/crates/sovereign-sdk/full-node/sov-prover-storage-manager/src/lib.rs +++ b/crates/sovereign-sdk/full-node/sov-prover-storage-manager/src/lib.rs @@ -9,6 +9,7 @@ use sov_rollup_interface::da::{BlockHeaderTrait, DaSpec}; use sov_rollup_interface::storage::HierarchicalStorageManager; use sov_schema_db::snapshot::{DbSnapshot, ReadOnlyLock, SnapshotId}; use sov_state::{MerkleProofSpec, ProverStorage}; +use tracing::{debug, instrument, trace}; pub use crate::snapshot_manager::SnapshotManager; @@ -106,6 +107,7 @@ where Ok(ProverStorage::with_db_handles(state_db, native_db)) } + #[instrument(level = "info", skip(self), err, ret)] fn finalize_by_l2_height(&mut self, l2_block_height: u64) -> anyhow::Result<()> { let snapshot_id = self .block_height_to_snapshot_id @@ -129,10 +131,9 @@ where prev_block_hash: Da::SlotHash, current_block_hash: Da::SlotHash, ) -> anyhow::Result<()> { - tracing::debug!( + debug!( "Finalizing block prev_hash={:?}; current_hash={:?}", - prev_block_hash, - current_block_hash + prev_block_hash, current_block_hash ); // Check if this is the oldest block if self @@ -175,7 +176,7 @@ where self.blocks_to_parent.remove(&block_hash).unwrap(); let snapshot_id = self.block_hash_to_snapshot_id.remove(&block_hash).unwrap(); - tracing::debug!("Discarding snapshot={}", snapshot_id); + debug!("Discarding snapshot={}", snapshot_id); snapshot_id_to_parent.remove(&snapshot_id); state_manager.discard_snapshot(&snapshot_id); native_manager.discard_snapshot(&snapshot_id); @@ -207,7 +208,7 @@ where &mut self, l2_block_height: u64, ) -> anyhow::Result { - tracing::trace!( + trace!( "Requested native storage for block at height: {:?} ", l2_block_height ); @@ -221,19 +222,20 @@ where new_snapshot_id } }; - tracing::debug!( + debug!( "Requested native storage for block at height: {:?}, giving snapshot id={}", - l2_block_height, - snapshot_id + l2_block_height, snapshot_id ); self.get_storage_with_snapshot_id(snapshot_id) } + #[instrument(level = "info", skip(self), err, ret)] fn finalize_l2(&mut self, l2_block_height: u64) -> anyhow::Result<()> { self.finalize_by_l2_height(l2_block_height) } + #[instrument(level = "info", skip(self, change_set), err, ret)] fn save_change_set_l2( &mut self, l2_block_height: u64, @@ -255,7 +257,7 @@ where } if self.orphaned_snapshots.remove(&snapshot_id) { - tracing::debug!( + debug!( "Discarded reference to 'finalized' snapshot={}", snapshot_id ); @@ -269,10 +271,9 @@ where state_manager.add_snapshot(state_snapshot); native_manager.add_snapshot(native_snapshot); } - tracing::debug!( + debug!( "Snapshot id={} for block at height={} has been saved to StorageManager", - snapshot_id, - l2_block_height + snapshot_id, l2_block_height ); Ok(()) } @@ -281,7 +282,10 @@ where &mut self, block_header: &Da::BlockHeader, ) -> anyhow::Result { - tracing::trace!("Requested native storage for block {:?} ", block_header); + trace!( + "Requested native storage for block {:?}", + block_header.hash() + ); let current_block_hash = block_header.hash(); let prev_block_hash = block_header.prev_hash(); assert_ne!( @@ -324,10 +328,9 @@ where new_snapshot_id } }; - tracing::debug!( + debug!( "Requested native storage for block {:?}, giving snapshot id={}", - block_header, - new_snapshot_id + block_header, new_snapshot_id ); self.get_storage_with_snapshot_id(new_snapshot_id) @@ -336,7 +339,7 @@ where fn create_finalized_storage(&mut self) -> anyhow::Result { self.latest_snapshot_id += 1; let snapshot_id = self.latest_snapshot_id; - tracing::debug!("Giving 'finalized' storage ref with id {}", snapshot_id); + debug!("Giving 'finalized' storage ref with id {}", snapshot_id); self.orphaned_snapshots.insert(snapshot_id); let state_db_snapshot = DbSnapshot::new( snapshot_id, @@ -382,7 +385,7 @@ where } if self.orphaned_snapshots.remove(&snapshot_id) { - tracing::debug!( + debug!( "Discarded reference to 'finalized' snapshot={}", snapshot_id ); @@ -406,16 +409,15 @@ where state_manager.add_snapshot(state_snapshot); native_manager.add_snapshot(native_snapshot); } - tracing::debug!( + debug!( "Snapshot id={} for block={:?} has been saved to StorageManager", - snapshot_id, - block_header + snapshot_id, block_header ); Ok(()) } fn finalize(&mut self, block_header: &Da::BlockHeader) -> anyhow::Result<()> { - tracing::debug!("Finalizing block: {:?}", block_header); + debug!("Finalizing block: {:?}", block_header.hash()); let current_block_hash = block_header.hash(); let prev_block_hash = block_header.prev_hash(); self.finalize_by_hash_pair(prev_block_hash, current_block_hash) diff --git a/crates/sovereign-sdk/full-node/sov-stf-runner/src/runner.rs b/crates/sovereign-sdk/full-node/sov-stf-runner/src/runner.rs index e79d05719..9a8dfbf0c 100644 --- a/crates/sovereign-sdk/full-node/sov-stf-runner/src/runner.rs +++ b/crates/sovereign-sdk/full-node/sov-stf-runner/src/runner.rs @@ -25,7 +25,7 @@ use sov_rollup_interface::storage::HierarchicalStorageManager; use sov_rollup_interface::zk::{Proof, StateTransitionData, Zkvm, ZkvmHost}; use tokio::sync::oneshot; use tokio::time::{sleep, Duration, Instant}; -use tracing::{debug, error, info}; +use tracing::{debug, error, info, instrument, warn}; use crate::prover_helpers::get_initial_slot_height; use crate::verifier::StateTransitionVerifier; @@ -218,11 +218,13 @@ where } /// Returns the head soft batch + #[instrument(level = "trace", skip_all, err)] pub fn get_head_soft_batch(&self) -> anyhow::Result> { self.ledger_db.get_head_soft_batch() } /// Runs the prover process. + #[instrument(level = "trace", skip_all, err)] pub async fn run_prover_process(&mut self) -> Result<(), anyhow::Error> { // Prover node should sync when a new sequencer commitment arrives // Check da block get and sync up to the latest block in the latest commitment @@ -287,11 +289,13 @@ where ); } } else { + warn!("Force transactions are not implemented yet"); // TODO: This is where force transactions will land - try to parse DA data force transaction } }); if !zk_proofs.is_empty() { + warn!("ZK proofs are not empty"); // TODO: Implement this } @@ -562,6 +566,7 @@ where } /// Runs the rollup. + #[instrument(level = "trace", skip_all, err)] pub async fn run_in_process(&mut self) -> Result<(), anyhow::Error> { let mut last_l1_height = 0; let mut cur_l1_block = None; @@ -666,11 +671,13 @@ where ); } } else { + warn!("Force transactions are not implemented yet"); // TODO: This is where force transactions will land - try to parse DA data force transaction } }); if !zk_proofs.is_empty() { + warn!("ZK proofs are not empty"); // TODO: Implement this }