chore(raiko-lib): auto logging (#219)

* chore(install): source env if sp1 bin not in path * chore: actual new line instead of `\n` symbols * chore(log): tracing logs instead println; levels; * chore: debug assertinos print inline * chore: removed unnecesary re-init; prints in db; * chore: warnings and cfg fixes * console only progress tracking * fix * feat: disable inplace print in container env * fix; merge conflict fixes * chore: cleaned up repeated output for info/debug --------- Co-authored-by: brechtpd <[email protected]> Co-authored-by: john xu <[email protected]>
taikoxyz · Jun 3, 2024 · 18bbfc9 · 18bbfc9
1 parent 93c8f61
commit 18bbfc9
Show file tree

Hide file tree

Showing 19 changed files with 93 additions and 72 deletions.
diff --git a/Cargo.lock b/Cargo.lock
diff --git a/core/src/interfaces.rs b/core/src/interfaces.rs
@@ -1,5 +1,4 @@
-use std::{collections::HashMap, path::Path, str::FromStr};
-
+use crate::{merge, prover::NativeProver};
 use alloy_primitives::{Address, B256};
 use clap::{Args, ValueEnum};
 use raiko_lib::{
@@ -9,10 +8,9 @@ use raiko_lib::{
 use serde::{Deserialize, Serialize};
 use serde_json::Value;
 use serde_with::{serde_as, DisplayFromStr};
+use std::{collections::HashMap, path::Path, str::FromStr};
 use utoipa::ToSchema;
 
-use crate::{merge, prover::NativeProver};
-
 #[derive(Debug, thiserror::Error, ToSchema)]
 pub enum RaikoError {
     /// For invalid proof type generation request.
@@ -139,23 +137,23 @@ impl ProofType {
                 return sp1_driver::Sp1Prover::run(input, output, config)
                     .await
                     .map_err(|e| e.into());
-
+                #[cfg(not(feature = "sp1"))]
                 Err(RaikoError::FeatureNotSupportedError(self.clone()))
             }
             ProofType::Risc0 => {
                 #[cfg(feature = "risc0")]
                 return risc0_driver::Risc0Prover::run(input, output, config)
                     .await
                     .map_err(|e| e.into());
-
+                #[cfg(not(feature = "risc0"))]
                 Err(RaikoError::FeatureNotSupportedError(self.clone()))
             }
             ProofType::Sgx => {
                 #[cfg(feature = "sgx")]
                 return sgx_prover::SgxProver::run(input, output, config)
                     .await
                     .map_err(|e| e.into());
-
+                #[cfg(not(feature = "sgx"))]
                 Err(RaikoError::FeatureNotSupportedError(self.clone()))
             }
         }

diff --git a/core/src/lib.rs b/core/src/lib.rs
@@ -1,5 +1,3 @@
-use std::collections::HashMap;
-
 use alloy_primitives::{Address, FixedBytes};
 use alloy_rpc_types::EIP1186AccountProofResponse;
 use raiko_lib::{
@@ -11,7 +9,8 @@ use raiko_lib::{
     utils::HeaderHasher,
 };
 use serde_json::Value;
-use tracing::{error, info, warn};
+use std::collections::HashMap;
+use tracing::{debug, error, info, warn};
 
 pub mod interfaces;
 pub mod preflight;
@@ -68,7 +67,7 @@ impl Raiko {
             Ok((header, _mpt_node)) => {
                 info!("Verifying final state using provider data ...");
                 info!("Final block hash derived successfully. {}", header.hash());
-                info!("Final block header derived successfully. {header:?}");
+                debug!("Final block header derived successfully. {header:?}");
                 let pi = ProtocolInstance::new(input, &header, VerifierType::None)?.instance_hash();
 
                 // Check against the expected value of all fields for easy debugability

diff --git a/core/src/preflight.rs b/core/src/preflight.rs
@@ -1,3 +1,7 @@
+use crate::{
+    interfaces::{RaikoError, RaikoResult},
+    provider::{db::ProviderDb, rpc::RpcBlockDataProvider, BlockDataProvider},
+};
 use alloy_consensus::{
     SignableTransaction, TxEip1559, TxEip2930, TxEip4844, TxEip4844Variant, TxEnvelope, TxLegacy,
 };
@@ -11,7 +15,9 @@ use raiko_lib::{
     builder::{
         prepare::TaikoHeaderPrepStrategy, BlockBuilder, OptimisticDatabase, TkoTxExecStrategy,
     },
+    clear_line,
     consts::ChainSpec,
+    inplace_print,
     input::{
         decode_anchor, proposeBlockCall, BlockProposed, GuestInput, TaikoGuestInput,
         TaikoProverData,
@@ -25,12 +31,7 @@ use raiko_lib::{
 };
 use serde::{Deserialize, Serialize};
 use std::{collections::HashSet, sync::Arc};
-use tracing::{info, warn};
-
-use crate::{
-    interfaces::{RaikoError, RaikoResult},
-    provider::{db::ProviderDb, rpc::RpcBlockDataProvider, BlockDataProvider},
-};
+use tracing::{debug, info, warn};
 
 pub async fn preflight<BDP: BlockDataProvider>(
     provider: BDP,
@@ -58,10 +59,13 @@ pub async fn preflight<BDP: BlockDataProvider>(
         RaikoError::Preflight("No block hash for the requested block".to_string())
     })?;
 
-    info!("\nblock.hash: {hash:?}");
-    info!("block.parent_hash: {:?}", block.header.parent_hash);
-    info!("block gas used: {:?}", block.header.gas_used);
-    info!("block transactions: {:?}", block.transactions.len());
+    info!(
+        "Processing block {:?} with block.hash: {:?}",
+        block.header.number, block.header.hash
+    );
+    debug!("block.parent_hash: {:?}", block.header.parent_hash);
+    debug!("block gas used: {:?}", block.header.gas_used);
+    debug!("block transactions: {:?}", block.transactions.len());
 
     let taiko_guest_input = if taiko_chain_spec.is_taiko() {
         prepare_taiko_chain_input(
@@ -162,14 +166,17 @@ pub async fn preflight<BDP: BlockDataProvider>(
     let mut done = false;
     let mut num_iterations = 0;
     while !done {
-        info!("Execution iteration {num_iterations}...");
+        inplace_print(&format!("Execution iteration {num_iterations}..."));
         builder.mut_db().unwrap().optimistic = num_iterations + 1 < max_iterations;
         builder = builder.execute_transactions::<TkoTxExecStrategy>()?;
         if builder.mut_db().unwrap().fetch_data().await {
             done = true;
         }
         num_iterations += 1;
     }
+    clear_line();
+    println!("State data fetched in {num_iterations} iterations");
+
     let provider_db = builder.mut_db().unwrap();
 
     // Gather inclusion proofs for the initial and final state
@@ -233,8 +240,10 @@ async fn prepare_taiko_chain_input(
     let l1_state_block_number = anchor_call.l1BlockId;
     let l1_inclusion_block_number = l1_state_block_number + 1;
 
-    info!("anchor L1 block id: {:?}", anchor_call.l1BlockId);
-    info!("anchor L1 state root: {:?}", anchor_call.l1StateRoot);
+    debug!(
+        "anchor L1 block id: {:?}\nanchor L1 state root: {:?}",
+        anchor_call.l1BlockId, anchor_call.l1StateRoot
+    );
 
     // Get the L1 block in which the L2 block was included so we can fetch the DA data.
     // Also get the L1 state block header so that we can prove the L1 state root.
@@ -250,7 +259,7 @@ async fn prepare_taiko_chain_input(
         RaikoError::Preflight("No L1 state block hash for the requested block".to_owned())
     })?;
 
-    info!("l1_state_root_block hash: {l1_state_block_hash:?}");
+    debug!("l1_state_root_block hash: {l1_state_block_hash:?}");
 
     let l1_inclusion_block_hash = l1_inclusion_block.header.hash.ok_or_else(|| {
         RaikoError::Preflight("No L1 inclusion block hash for the requested block".to_owned())
@@ -267,7 +276,7 @@ async fn prepare_taiko_chain_input(
 
     // Fetch the tx data from either calldata or blobdata
     let (tx_data, tx_blob_hash) = if proposal_event.meta.blobUsed {
-        info!("blob active");
+        debug!("blob active");
         // Get the blob hashes attached to the propose tx
         let blob_hashes = proposal_tx.blob_versioned_hashes.unwrap_or_default();
         assert!(!blob_hashes.is_empty());

diff --git a/core/src/provider/rpc.rs b/core/src/provider/rpc.rs
@@ -1,13 +1,13 @@
-use std::collections::HashMap;
-
 use alloy_primitives::{Address, Bytes, StorageKey, Uint, U256};
 use alloy_provider::{ProviderBuilder, ReqwestProvider, RootProvider};
 use alloy_rpc_client::{ClientBuilder, RpcClient};
 use alloy_rpc_types::{Block, BlockId, BlockNumberOrTag, EIP1186AccountProofResponse};
 use alloy_transport_http::Http;
-use raiko_lib::{clear_line, inplace_print};
+use raiko_lib::clear_line;
 use reqwest_alloy::Client;
 use revm::primitives::{AccountInfo, Bytecode};
+use std::collections::HashMap;
+use tracing::trace;
 
 use crate::{
     interfaces::{RaikoError, RaikoResult},
@@ -229,9 +229,13 @@ impl BlockDataProvider for RpcBlockDataProvider {
 
         let batch_limit = 1000;
         while !accounts.is_empty() {
-            inplace_print(&format!(
-                "fetching storage proof {idx}/{num_storage_proofs}..."
-            ));
+            if cfg!(debug_assertions) {
+                raiko_lib::inplace_print(&format!(
+                    "fetching storage proof {idx}/{num_storage_proofs}..."
+                ));
+            } else {
+                trace!("Fetching storage proof {idx}/{num_storage_proofs}...");
+            }
 
             // Create a batch for all storage proofs
             let mut batch = self.client.new_batch();

diff --git a/docker/entrypoint.sh b/docker/entrypoint.sh
@@ -2,6 +2,8 @@
 
 set -xeo pipefail
 
+export IN_CONTAINER=1
+
 GRAMINE_PRIV_KEY="$HOME/.config/gramine/enclave-key.pem"
 RAIKO_DOCKER_VOLUME_PATH="/root/.config/raiko"
 RAIKO_DOCKER_VOLUME_CONFIG_PATH="$RAIKO_DOCKER_VOLUME_PATH/config"

diff --git a/host/src/bin/main.rs b/host/src/bin/main.rs
@@ -1,8 +1,7 @@
 #![allow(incomplete_features)]
-use std::path::PathBuf;
-
 use raiko_host::{interfaces::HostResult, server::serve, ProverState};
-use tracing::info;
+use std::path::PathBuf;
+use tracing::{debug, info};
 use tracing_appender::{
     non_blocking::WorkerGuard,
     rolling::{Builder, Rotation},
@@ -18,6 +17,8 @@ async fn main() -> HostResult<()> {
         &state.opts.log_level,
         state.opts.max_log,
     );
+    debug!("Start config:\n{:#?}", state.opts.proof_request_opt);
+    debug!("Args:\n{:#?}", state.opts);
 
     info!("Supported chains: {:?}", state.chain_specs);
     info!("Start config:\n{:#?}", state.opts.proof_request_opt);

diff --git a/host/src/lib.rs b/host/src/lib.rs
@@ -151,7 +151,7 @@ impl ProverState {
 }
 
 mod memory {
-    use tracing::info;
+    use tracing::debug;
 
     use crate::ALLOCATOR;
 
@@ -165,7 +165,7 @@ mod memory {
 
     pub(crate) fn print_stats(title: &str) {
         let max_memory = get_max_allocated();
-        info!(
+        debug!(
             "{title}{}.{:06} MB",
             max_memory / 1_000_000,
             max_memory % 1_000_000

diff --git a/host/src/server/mod.rs b/host/src/server/mod.rs
@@ -1,10 +1,8 @@
-use std::{net::SocketAddr, str::FromStr};
-
+use crate::{interfaces::HostError, server::api::create_router, ProverState};
 use anyhow::Context;
+use std::{net::SocketAddr, str::FromStr};
 use tokio::net::TcpListener;
-use tracing::debug;
-
-use crate::{interfaces::HostError, server::api::create_router, ProverState};
+use tracing::info;
 
 pub mod api;
 
@@ -14,7 +12,7 @@ pub async fn serve(state: ProverState) -> anyhow::Result<()> {
         .map_err(|_| HostError::InvalidAddress(state.opts.address.clone()))?;
     let listener = TcpListener::bind(addr).await?;
 
-    debug!("Listening on: {}", listener.local_addr()?);
+    info!("Listening on: {}", listener.local_addr()?);
 
     let router = create_router(
         state.opts.concurrency_limit,

diff --git a/lib/Cargo.toml b/lib/Cargo.toml
@@ -36,6 +36,7 @@ sha2 = { workspace = true }
 sha3 = { workspace = true }
 rlp = { workspace = true, features = ["std"] }
 cfg-if = { workspace = true }
+tracing = { workspace = true }
 
 # [target.'cfg(feature = "std")'.dependencies]
 flate2 = { workspace = true, optional = true }

diff --git a/lib/src/builder/execute.rs b/lib/src/builder/execute.rs
@@ -12,12 +12,10 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 
-use core::{fmt::Debug, mem::take, str::from_utf8};
-use std::collections::HashSet;
-
 use alloy_consensus::{constants::BEACON_ROOTS_ADDRESS, TxEnvelope};
 use alloy_primitives::{TxKind, U256};
 use anyhow::{anyhow, bail, ensure, Context, Error, Result};
+use core::{fmt::Debug, mem::take, str::from_utf8};
 #[cfg(feature = "std")]
 use log::debug;
 use revm::{
@@ -28,6 +26,8 @@ use revm::{
     },
     taiko, Database, DatabaseCommit, Evm, JournaledState,
 };
+use std::collections::HashSet;
+use tracing::trace;
 cfg_if::cfg_if! {
     if #[cfg(feature = "tracer")] {
         use std::{fs::{OpenOptions, File}, io::{BufWriter, Write}, sync::{Arc, Mutex}};
@@ -48,7 +48,6 @@ use crate::{
     print_duration,
     time::{AddAssign, Duration, Instant},
     utils::{check_anchor_tx, generate_transactions},
-    Measurement,
 };
 
 /// Minimum supported protocol version: SHANGHAI
@@ -83,7 +82,7 @@ impl TxExecStrategy for TkoTxExecStrategy {
         let chain_spec = &block_builder.input.chain_spec;
         let chain_id = chain_spec.chain_id();
         let is_taiko = chain_spec.is_taiko();
-        println!("spec_id: {spec_id:?}");
+        trace!("spec_id: {spec_id:?}");
 
         // generate the transactions from the tx list
         // For taiko blocks, insert the anchor tx as the first transaction
@@ -176,7 +175,11 @@ impl TxExecStrategy for TkoTxExecStrategy {
         let mut actual_tx_no = 0usize;
         let num_transactions = transactions.len();
         for (tx_no, tx) in take(&mut transactions).into_iter().enumerate() {
-            inplace_print(&format!("\rprocessing tx {tx_no}/{num_transactions}..."));
+            if !is_optimistic {
+                inplace_print(&format!("\rprocessing tx {tx_no}/{num_transactions}..."));
+            } else {
+                trace!("\rprocessing tx {tx_no}/{num_transactions}...");
+            }
 
             #[cfg(feature = "tracer")]
             let trace = set_trace_writer(
@@ -284,7 +287,7 @@ impl TxExecStrategy for TkoTxExecStrategy {
                 }
             };
             #[cfg(feature = "std")]
-            debug!("  Ok: {result:?}");
+            trace!("  Ok: {result:?}");
 
             #[cfg(feature = "tracer")]
             // Flush the trace writer
@@ -332,14 +335,15 @@ impl TxExecStrategy for TkoTxExecStrategy {
 
             tx_misc_duration.add_assign(start.elapsed());
         }
-        clear_line();
-        print_duration("Tx transact time: ", tx_transact_duration);
-        print_duration("Tx misc time: ", tx_misc_duration);
+        if !is_optimistic {
+            clear_line();
+            print_duration("Tx transact time: ", tx_transact_duration);
+            print_duration("Tx misc time: ", tx_misc_duration);
+        }
 
         let mut db = &mut evm.context.evm.db;
 
         // process withdrawals unconditionally after any transactions
-        let measurement = Measurement::start("Processing withdrawals...", true);
         let mut withdrawals_trie = MptNode::default();
         for (i, withdrawal) in block_builder.input.withdrawals.iter().enumerate() {
             // the withdrawal amount is given in Gwei
@@ -354,10 +358,8 @@ impl TxExecStrategy for TkoTxExecStrategy {
                 .insert_rlp(&i.to_rlp(), withdrawal)
                 .with_context(|| "failed to insert withdrawal")?;
         }
-        measurement.stop();
 
         // Update result header with computed values
-        let measurement = Measurement::start("Generating block header...", true);
         header.transactions_root = tx_trie.hash();
         header.receipts_root = receipt_trie.hash();
         header.logs_bloom = logs_bloom;
@@ -368,7 +370,6 @@ impl TxExecStrategy for TkoTxExecStrategy {
         if spec_id >= SpecId::CANCUN {
             header.blob_gas_used = Some(blob_gas_used.into());
         }
-        measurement.stop();
 
         // Leak memory, save cycles
         guest_mem_forget([tx_trie, receipt_trie, withdrawals_trie]);