Feature/logging

derivation/src/derivation.rs

@@ -1,6 +1,8 @@
-use crate::errors;
 use crate::errors::Error;
 use crate::oracle::{MemoryOracleClient, NopeHintWriter};
+use crate::{errors, logger};
+use alloc::fmt::format;
+use alloc::format;
 use alloc::sync::Arc;
 use alloy_consensus::Header;
 use alloy_primitives::{keccak256, Sealed, B256};
@@ -73,6 +75,12 @@
             rollup_config: rollup_config.clone(),
         };
         let rollup_config = Arc::new(boot.rollup_config.clone());
+
+        logger::info(&format!(
+            "fetching safe head hash {:?} for L2 derivation",
+            boot.agreed_l2_output_root
+        ));
+
         let safe_head_hash = fetch_safe_head_hash(&oracle, boot.agreed_l2_output_root).await?;
         let oracle_for_preimage = oracle.clone();
         let oracle = Arc::new(oracle);
@@ -106,6 +114,7 @@
         )
         .await?;
 
+        logger::info(&format!("create evm factory"));
         let evm_factory = FpvmOpEvmFactory::new(NopeHintWriter, oracle_for_preimage);
         let executor = KonaExecutor::new(
             rollup_config.as_ref(),
@@ -118,10 +127,18 @@
 
         // Run the derivation pipeline until we are able to produce the output root of the claimed
         // L2 block.
+        logger::info(&format!(
+            "start advancing to target L2 block {}",
+            boot.claimed_l2_block_number
+        ));
         let (_, output_root) = driver
             .advance_to_target(&boot.rollup_config, Some(boot.claimed_l2_block_number))
             .await?;
 
+        logger::info(&format!(
+            "end advancing to target L2 block {}",
+            boot.claimed_l2_block_number
+        ));
         ////////////////////////////////////////////////////////////////
         //                          EPILOGUE                          //
         ////////////////////////////////////////////////////////////////

derivation/src/lib.rs

@@ -3,6 +3,7 @@ extern crate alloc;
 
 pub mod derivation;
 pub mod errors;
+pub mod logger;
 pub mod oracle;
 pub mod types;
 

derivation/src/logger.rs

@@ -0,0 +1,26 @@
+use alloc::vec::Vec;
+
+extern "C" {
+    fn ocall_info(msg: *const i8);
+    fn ocall_debug(msg: *const i8);
+}
+
+#[no_mangle]
+pub extern "C" fn info(msg: &str) {
+    let mut buf: Vec<u8> = msg.as_bytes().to_vec();
+    buf.push(0); // Append NUL terminator
+
+    unsafe {
+        ocall_info(buf.as_ptr() as *const i8);
+    }
+}
+
+#[no_mangle]
+pub extern "C" fn debug(msg: &str) {
+    let mut buf: Vec<u8> = msg.as_bytes().to_vec();
+    buf.push(0); // Append NUL terminator
+
+    unsafe {
+        ocall_debug(buf.as_ptr() as *const i8);
+    }
+}

derivation/src/oracle.rs

@@ -1,7 +1,7 @@
 use crate::errors::Error;
 use crate::errors::Error::UnexpectedPreimageKeySize;
 use crate::types::Preimage;
-use crate::POSITION_FIELD_ELEMENT;
+use crate::{logger, POSITION_FIELD_ELEMENT};
 use alloc::boxed::Box;
 use alloc::format;
 use alloc::sync::Arc;
@@ -108,15 +108,26 @@ impl TryFrom<Vec<Preimage>> for MemoryOracleClient {
     type Error = Error;
 
     fn try_from(value: Vec<Preimage>) -> Result<Self, Self::Error> {
+        logger::info(&format!(
+            "try from MemoryOracleClient capacity={}",
+            value.len()
+        ));
         let mut inner = HashMap::with_capacity(value.len());
-        for preimage in value {
+        logger::info("MemoryOracleClient start to insert into hash ");
+        for (i, preimage) in value.into_iter().enumerate() {
+            if i % 10000 == 0 {
+                logger::info(&format!("MemoryOracleClient insert into hash {}", i));
+            }
             let key: [u8; 32] = preimage
                 .key
                 .try_into()
                 .map_err(|v: Vec<u8>| UnexpectedPreimageKeySize(v.len()))?;
             let preimage_key = PreimageKey::try_from(key)
                 .map_err(|e| Error::UnexpectedPreimageKey { source: e, key })?;
 
+            if i % 10000 == 0 {
+                logger::info(&format!("verify hash {}", i));
+            }
             // Ensure hash type preimage is valid
             match preimage_key.key_type() {
                 PreimageKeyType::Keccak256 => {
@@ -137,10 +148,14 @@ impl TryFrom<Vec<Preimage>> for MemoryOracleClient {
             }
         }
 
+        logger::info("generate_valid_suffixes");
         // Ensure blob preimage is valid
         let (valid_suffixes, roots_of_unity) = generate_valid_suffixes();
         let mut kzg_cache = HashSet::<Vec<u8>>::new();
-        for (key, _) in inner.iter() {
+        for (i, (key, _)) in inner.iter().enumerate() {
+            if i % 10000 == 0 {
+                logger::info(&format!("verify_blob and precompile {}", i));
+            }
             if key.key_type() == PreimageKeyType::Blob {
                 verify_blob_preimage(
                     key,
@@ -153,6 +168,7 @@ impl TryFrom<Vec<Preimage>> for MemoryOracleClient {
                 verify_precompile(key, &inner)?
             }
         }
+        logger::info("try from MemoryOracleClient success");
         Ok(Self {
             preimages: Arc::new(inner),
         })

light-client/src/client.rs

@@ -6,8 +6,8 @@ use crate::header::Header;
 use crate::message::ClientMessage;
 use crate::misbehaviour::Misbehaviour;
 use alloc::string::{String, ToString};
-use alloc::vec;
 use alloc::vec::Vec;
+use alloc::{format, vec};
 use alloy_primitives::keccak256;
 use core::time::Duration;
 use ethereum_consensus::types::H256;
@@ -21,6 +21,7 @@ use light_client::{
     CreateClientResult, Error as LightClientError, HostClientReader, LightClient, MisbehaviourData,
     UpdateClientResult, UpdateStateData, VerifyMembershipResult, VerifyNonMembershipResult,
 };
+use optimism_derivation::logger;
 
 pub struct OptimismLightClient<const L1_SYNC_COMMITTEE_SIZE: usize>;
 
@@ -86,6 +87,7 @@ impl<const L1_SYNC_COMMITTEE_SIZE: usize> LightClient
         client_id: ClientId,
         client_message: Any,
     ) -> Result<UpdateClientResult, light_client::Error> {
+        logger::info(&format!("update_client {}", client_id.to_string()));
         match ClientMessage::<L1_SYNC_COMMITTEE_SIZE>::try_from(client_message.clone())? {
             ClientMessage::Header(header) => Ok(self.update_state(ctx, client_id, header)?.into()),
             ClientMessage::Misbehaviour(misbehaviour) => Ok(self
@@ -173,6 +175,11 @@ impl<const L1_SYNC_COMMITTEE_SIZE: usize> OptimismLightClient<L1_SYNC_COMMITTEE_
         client_id: ClientId,
         header: Header<L1_SYNC_COMMITTEE_SIZE>,
     ) -> Result<UpdateStateData, Error> {
+        logger::info(&format!(
+            "update_state {} trusted_height={}",
+            client_id.to_string(),
+            header.trusted_height.revision_height()
+        ));
         let trusted_height = header.trusted_height;
         let any_client_state = ctx.client_state(&client_id).map_err(Error::LCPError)?;
         let any_consensus_state = ctx

light-client/src/client_state.rs

@@ -8,6 +8,7 @@ use crate::misc::{
     validate_state_timestamp_within_trusting_period,
 };
 use alloc::borrow::ToOwned;
+use alloc::format;
 use alloc::vec::Vec;
 use alloy_primitives::B256;
 use ethereum_consensus::beacon::Version;
@@ -17,6 +18,7 @@ use ethereum_light_client_verifier::context::Fraction;
 use ethereum_light_client_verifier::execution::ExecutionVerifier;
 use kona_genesis::RollupConfig;
 use light_client::types::{Any, ClientId, Height, Time};
+use optimism_derivation::logger;
 use optimism_ibc_proto::google::protobuf::Any as IBCAny;
 use optimism_ibc_proto::ibc::lightclients::ethereum::v1::{
     Fork as ProtoFork, ForkParameters as ProtoForkParameters, ForkSpec as ProtoForkSpec,
@@ -70,6 +72,10 @@ impl ClientState {
         trusted_consensus_state: &ConsensusState,
         header: Header<L1_SYNC_COMMITTEE_SIZE>,
     ) -> Result<(ClientState, ConsensusState, Height), Error> {
+        logger::info(&format!(
+            "check_header_and_update_state trusted_height={}",
+            header.trusted_height.revision_height()
+        ));
         // Since the L1 block hash is used for L2 derivation, the validity of L1 must be verified.
         let l1_consensus = header.verify_l1(
             &self.l1_config,

light-client/src/header.rs

@@ -3,11 +3,13 @@ use crate::consensus_state::ConsensusState;
 use crate::errors::Error;
 use crate::l1::{L1Config, L1Consensus, L1Header};
 use alloc::boxed::Box;
+use alloc::format;
 use alloc::vec::Vec;
 use alloy_primitives::B256;
 use kona_genesis::RollupConfig;
 use light_client::types::{Any, Height};
 use optimism_derivation::derivation::Derivation;
+use optimism_derivation::logger;
 use optimism_derivation::oracle::MemoryOracleClient;
 use optimism_derivation::types::Preimages;
 use optimism_ibc_proto::google::protobuf::Any as IBCAny;
@@ -51,6 +53,10 @@ impl<const L1_SYNC_COMMITTEE_SIZE: usize> L1Headers<L1_SYNC_COMMITTEE_SIZE> {
 
         let mut updated_as_next = false;
         for (i, l1_header) in self.trusted_to_deterministic.iter().enumerate() {
+            logger::info(&format!(
+                "verify l1 trusted_to_deterministic index={i} number={}",
+                l1_header.execution_update.block_number
+            ));
             let result = l1_header.verify(now_sec, l1_config, &l1_consensus);
             let result = result.map_err(|e| {
                 Error::L1HeaderTrustedToDeterministicVerifyError(
@@ -67,6 +73,10 @@ impl<const L1_SYNC_COMMITTEE_SIZE: usize> L1Headers<L1_SYNC_COMMITTEE_SIZE> {
         // Verify finalized l1 header by last l1 consensus for L2 derivation
         let mut l1_consensus_for_verify_only = l1_consensus.clone();
         for (i, l1_header) in self.deterministic_to_latest.iter().enumerate() {
+            logger::info(&format!(
+                "verify l1 deterministic_to_latest index={i} number={}",
+                l1_header.execution_update.block_number
+            ));
             let result = l1_header.verify(now_sec, l1_config, &l1_consensus_for_verify_only);
             let result = result.map_err(|e| {
                 Error::L1HeaderDeterministicToLatestVerifyError(
@@ -110,6 +120,10 @@ impl<const L1_SYNC_COMMITTEE_SIZE: usize> Header<L1_SYNC_COMMITTEE_SIZE> {
         trusted_output_root: B256,
         rollup_config: &RollupConfig,
     ) -> Result<(alloy_consensus::Header, u64, B256), Error> {
+        logger::info(&format!(
+            "verify l2 derivation={:?}",
+            self.derivation.l2_block_number
+        ));
         // Ensure trusted
         if self.derivation.agreed_l2_output_root != trusted_output_root {
             return Err(Error::UnexpectedTrustedOutputRoot(
@@ -131,18 +145,21 @@ impl<const L1_SYNC_COMMITTEE_SIZE: usize> TryFrom<RawHeader> for Header<L1_SYNC_
     type Error = Error;
 
     fn try_from(header: RawHeader) -> Result<Self, Self::Error> {
+        logger::info("try from trusted_to_deterministic");
         let mut trusted_to_deterministic: Vec<L1Header<L1_SYNC_COMMITTEE_SIZE>> =
             Vec::with_capacity(header.trusted_to_deterministic.len());
         for l1_header in header.trusted_to_deterministic {
             trusted_to_deterministic.push(l1_header.try_into()?);
         }
+        logger::info("try from deterministic_to_latest");
         let mut deterministic_to_latest: Vec<L1Header<L1_SYNC_COMMITTEE_SIZE>> =
             Vec::with_capacity(header.deterministic_to_latest.len());
         for l1_header in header.deterministic_to_latest {
             deterministic_to_latest.push(l1_header.try_into()?);
         }
         let raw_derivation = header.derivation.ok_or(Error::UnexpectedEmptyDerivations)?;
 
+        logger::info("try from derivation");
         let derivation = Derivation::new(
             B256::from(
                 deterministic_to_latest
@@ -159,13 +176,16 @@ impl<const L1_SYNC_COMMITTEE_SIZE: usize> TryFrom<RawHeader> for Header<L1_SYNC_
             raw_derivation.l2_block_number,
         );
 
+        logger::info("try from Preimages decode");
         let preimages =
             Preimages::decode(header.preimages.as_slice()).map_err(Error::ProtoDecodeError)?;
+        logger::info("try from account update");
         let account_update_info = header
             .account_update
             .ok_or(Error::MissingAccountUpdate)?
             .try_into()?;
 
+        logger::info("try from MemoryOracleClient");
         let oracle: MemoryOracleClient = preimages
             .preimages
             .try_into()