chore: add more logs to core enclave (#318)

Author: hu55a1n1

crates/enclave/core/src/attestor.rs

@@ -4,6 +4,7 @@ use std::{
     io::{Error as IoError, ErrorKind, Write},
 };
 
+use log::{debug, error, trace};
 use mc_sgx_dcap_sys_types::sgx_ql_qve_collateral_t;
 use quartz_contract_core::{
     msg::{
@@ -58,6 +59,7 @@ impl Attestor for DcapAttestor {
     type RawAttestation = RawDcapAttestation;
 
     fn quote(&self, user_data: impl HasUserData) -> Result<Vec<u8>, Self::Error> {
+        debug!("Generating DCAP quote");
         let user_data = user_data.user_data();
         let mut user_report_data = File::create("/dev/attestation/user_report_data")?;
         user_report_data.write_all(user_data.as_slice())?;
@@ -66,16 +68,20 @@ impl Attestor for DcapAttestor {
     }
 
     fn mr_enclave(&self) -> Result<MrEnclave, Self::Error> {
+        debug!("Retrieving MRENCLAVE");
         let quote = self.quote(NullUserData)?;
         Ok(quote[112..(112 + 32)]
             .try_into()
             .expect("hardcoded array size"))
     }
 
     fn attestation(&self, user_data: impl HasUserData) -> Result<Self::Attestation, Self::Error> {
+        debug!("Generating DCAP attestation");
+
         fn pccs_query_pck(pccs_url: Url) -> Result<(Vec<u8>, String), Box<dyn Error>> {
             let mut pccs_url = pccs_url.join("pckcrl/").expect("hardcoded URL");
             pccs_url.set_query(Some("ca=processor"));
+            trace!("Querying PCCS for PCK certificate: {pccs_url}");
 
             let client = Client::builder()
                 .danger_accept_invalid_certs(true) // FIXME(hu55a1n1): required?
@@ -144,15 +150,20 @@ impl Attestor for DcapAttestor {
         let quote = self.quote(user_data)?;
 
         let collateral = {
-            let (pck_crl, pck_crl_issuer_chain) = pccs_query_pck(self.pccs_url.clone())
-                .map_err(|e| IoError::new(ErrorKind::Other, e.to_string()))?;
+            let (pck_crl, pck_crl_issuer_chain) =
+                pccs_query_pck(self.pccs_url.clone()).map_err(|e| {
+                    error!("Failed to query PCCS: {}", e);
+                    IoError::new(ErrorKind::Other, e.to_string())
+                })?;
             collateral(&self.fmspc.to_string(), pck_crl, pck_crl_issuer_chain)
         };
 
+        debug!("Successfully generated DCAP attestation");
         Ok(DcapAttestation::new(
-            quote
-                .try_into()
-                .map_err(|e: Quote3Error| IoError::other(e.to_string()))?,
+            quote.try_into().map_err(|e: Quote3Error| {
+                error!("Failed to convert quote: {}", e);
+                IoError::other(e.to_string())
+            })?,
             collateral,
         ))
     }
@@ -169,15 +180,18 @@ impl Attestor for MockAttestor {
     type RawAttestation = RawMockAttestation;
 
     fn quote(&self, user_data: impl HasUserData) -> Result<Vec<u8>, Self::Error> {
+        debug!("Generating mock quote");
         let user_data = user_data.user_data();
         Ok(user_data.to_vec())
     }
 
     fn mr_enclave(&self) -> Result<MrEnclave, Self::Error> {
+        debug!("Retrieving mock MRENCLAVE");
         Ok(Default::default())
     }
 
     fn attestation(&self, user_data: impl HasUserData) -> Result<Self::Attestation, Self::Error> {
+        debug!("Generating mock attestation");
         Ok(MockAttestation(user_data.user_data()))
     }
 }

crates/enclave/core/src/chain_client/default.rs

@@ -2,6 +2,7 @@ use anyhow::anyhow;
 use cosmrs::{crypto::secp256k1::SigningKey, AccountId};
 use cw_client::{CwClient, GrpcClient};
 use futures_util::StreamExt;
+use log::{debug, error, info, trace};
 use quartz_tm_prover::{
     config::{Config as TmProverConfig, ProofOutput},
     prover::prove,
@@ -38,6 +39,7 @@ impl DefaultChainClient {
         trusted_height: Height,
         trusted_hash: Hash,
     ) -> Self {
+        info!("Creating new default chain client for chain ID: {chain_id}");
         DefaultChainClient {
             chain_id,
             grpc_client: GrpcClient::new(signer, grpc_url),
@@ -80,9 +82,16 @@ impl ChainClient for DefaultChainClient {
         contract: &Self::Contract,
         query: impl Into<Self::Query> + Send,
     ) -> Result<R, Self::Error> {
+        debug!("Querying contract: {contract}");
         match query.into() {
-            Query::Json(q) => self.grpc_client.query_smart(contract, q).await,
-            Query::String(q) => self.grpc_client.query_raw(contract, q).await,
+            Query::Json(q) => {
+                trace!("Executing JSON query");
+                self.grpc_client.query_smart(contract, q).await
+            }
+            Query::String(q) => {
+                trace!("Executing raw query");
+                self.grpc_client.query_raw(contract, q).await
+            }
         }
     }
 
@@ -91,6 +100,8 @@ impl ChainClient for DefaultChainClient {
         contract: &Self::Contract,
         storage_key: &str,
     ) -> Result<Self::Proof, Self::Error> {
+        debug!("Generating existence proof for contract {contract} with storage key {storage_key}");
+
         let prover_config = TmProverConfig {
             primary: self.node_url.as_str().parse()?,
             witnesses: self.node_url.as_str().parse()?,
@@ -104,12 +115,14 @@ impl ChainClient for DefaultChainClient {
         };
 
         let proof_output = tokio::task::spawn_blocking(move || {
+            trace!("Spawning blocking task for proof generation");
             // Create a new runtime inside the blocking thread.
             let rt = tokio::runtime::Runtime::new()?;
             rt.block_on(async {
-                prove(prover_config)
-                    .await
-                    .map_err(|report| anyhow!("Tendermint prover failed. Report: {}", report))
+                prove(prover_config).await.map_err(|report| {
+                    error!("Tendermint prover failed: {}", report);
+                    anyhow!("Tendermint prover failed. Report: {}", report)
+                })
             })
         })
         .await??; // Handle both JoinError and your custom error
@@ -122,6 +135,10 @@ impl ChainClient for DefaultChainClient {
         tx: T,
         config: Self::TxConfig,
     ) -> Result<Self::TxOutput, Self::Error> {
+        debug!(
+            "Sending transaction to contract {contract} with gas {}",
+            config.gas
+        );
         self.grpc_client
             .tx_execute(
                 contract,
@@ -134,7 +151,8 @@ impl ChainClient for DefaultChainClient {
             .await
     }
 
-    async fn wait_for_blocks(&self, _blocks: u8) -> Result<(), Self::Error> {
+    async fn wait_for_blocks(&self, blocks: u8) -> Result<(), Self::Error> {
+        debug!("Waiting for {} blocks", blocks);
         let (client, driver) = WebSocketClient::new(self.ws_url.to_string().as_str()).await?;
 
         let driver_handle = tokio::spawn(async move { driver.run().await });
@@ -148,6 +166,7 @@ impl ChainClient for DefaultChainClient {
         while let Some(res) = subs.next().await {
             let _ev = res?;
             ev_count -= 1;
+            trace!("Received new block event, {} remaining", ev_count);
             if ev_count == 0 {
                 break;
             }

crates/enclave/core/src/handler.rs

@@ -1,5 +1,6 @@
 use cosmrs::AccountId;
 use k256::ecdsa::VerifyingKey;
+use log::{debug, error};
 use quartz_proto::quartz::{
     InstantiateRequest, InstantiateResponse, SessionCreateRequest, SessionCreateResponse,
     SessionSetPubKeyRequest, SessionSetPubKeyResponse,
@@ -69,16 +70,21 @@ where
     async fn handle(self, ctx: &E) -> Result<Self::Response, Self::Error> {
         match self {
             CoreEnclaveRequest::Instantiate(req) => {
+                debug!("Handling instantiate request");
                 req.handle(ctx).await.map(CoreEnclaveResponse::Instantiate)
             }
-            CoreEnclaveRequest::SessionCreate(req) => req
-                .handle(ctx)
-                .await
-                .map(CoreEnclaveResponse::SessionCreate),
-            CoreEnclaveRequest::SessionSetPubKey(req) => req
-                .handle(ctx)
-                .await
-                .map(CoreEnclaveResponse::SessionSetPubKey),
+            CoreEnclaveRequest::SessionCreate(req) => {
+                debug!("Handling session create request");
+                req.handle(ctx)
+                    .await
+                    .map(CoreEnclaveResponse::SessionCreate)
+            }
+            CoreEnclaveRequest::SessionSetPubKey(req) => {
+                debug!("Handling session set pubkey request");
+                req.handle(ctx)
+                    .await
+                    .map(CoreEnclaveResponse::SessionSetPubKey)
+            }
         }
     }
 }
@@ -88,17 +94,31 @@ pub fn ensure_seq_num_consistency(
     seq_num_on_chain: u64,
     pending_sequenced_requests: usize,
 ) -> Result<(), Status> {
+    debug!(
+        "Checking sequence number consistency - store: {}, chain: {}, pending: {}",
+        seq_num_in_store, seq_num_on_chain, pending_sequenced_requests
+    );
+
     if seq_num_on_chain < seq_num_in_store {
+        error!(
+            "Replay attempt detected - chain seq num ({}) < store seq num ({})",
+            seq_num_on_chain, seq_num_in_store
+        );
         return Err(Status::failed_precondition("replay attempted"));
     }
 
     // make sure number of pending requests are equal to the diff b/w on-chain v/s in-mem seq num
     let seq_num_diff = seq_num_on_chain - seq_num_in_store;
     if seq_num_diff != pending_sequenced_requests as u64 {
+        error!(
+            "Sequence number mismatch - diff: {}, pending: {}",
+            seq_num_diff, pending_sequenced_requests
+        );
         return Err(Status::failed_precondition(format!(
             "seq_num_diff mismatch: num({seq_num_diff}) v/s diff({pending_sequenced_requests})"
         )));
     }
 
+    debug!("Sequence number consistency check passed");
     Ok(())
 }

crates/enclave/core/src/key_manager/default.rs

@@ -1,4 +1,5 @@
 use k256::ecdsa::{SigningKey, VerifyingKey};
+use log::{debug, info};
 
 use crate::key_manager::KeyManager;
 
@@ -10,6 +11,7 @@ pub struct DefaultKeyManager {
 
 impl Default for DefaultKeyManager {
     fn default() -> Self {
+        info!("Creating new default key manager with random signing key");
         Self {
             sk: SigningKey::random(&mut rand::thread_rng()),
         }
@@ -21,6 +23,7 @@ impl KeyManager for DefaultKeyManager {
     type PubKey = PubKey;
 
     async fn pub_key(&self) -> Self::PubKey {
+        debug!("Retrieving public key from key manager");
         PubKey(self.sk.clone().into())
     }
 }

crates/enclave/core/src/lib.rs

@@ -80,6 +80,7 @@ See the app enclaves in the `examples` directory for usage examples.
 )]
 
 use cosmrs::AccountId;
+use log::{debug, trace, warn};
 use quartz_contract_core::state::Config;
 
 use crate::{
@@ -168,6 +169,7 @@ impl<C: Send + Sync + 'static> DefaultSharedEnclave<C> {
         self,
         key_manager: K,
     ) -> DefaultEnclave<C, <Self as Enclave>::Attestor, K, <Self as Enclave>::Store> {
+        debug!("Updating enclave with new key manager");
         DefaultEnclave {
             attestor: self.attestor,
             key_manager,
@@ -190,14 +192,17 @@ where
     type Store = S;
 
     async fn attestor(&self) -> Self::Attestor {
+        trace!("Retrieving enclave attestor");
         self.attestor.clone()
     }
 
     async fn key_manager(&self) -> Self::KeyManager {
+        trace!("Retrieving enclave key manager");
         self.key_manager.clone()
     }
 
     async fn store(&self) -> &Self::Store {
+        trace!("Retrieving enclave store");
         &self.store
     }
 }

crates/enclave/core/src/store/default.rs

@@ -2,6 +2,7 @@ use std::sync::Arc;
 
 use cosmrs::AccountId;
 use displaydoc::Display;
+use log::{debug, info, trace};
 use quartz_contract_core::state::{Config, Nonce};
 use tokio::sync::RwLock;
 
@@ -18,6 +19,7 @@ pub struct DefaultStore {
 
 impl DefaultStore {
     pub fn new(config: Config) -> Self {
+        info!("Creating new default store with config: {config:?}");
         DefaultStore {
             config: Arc::new(RwLock::new(Some(config))),
             contract: Default::default(),
@@ -36,40 +38,53 @@ impl Store for DefaultStore {
     type Error = StoreError;
 
     async fn get_config(&self) -> Result<Option<Config>, Self::Error> {
+        debug!("Retrieving enclave configuration");
         Ok(self.config.read().await.clone())
     }
 
     async fn set_config(&self, config: Config) -> Result<Option<Config>, Self::Error> {
+        debug!("Setting new enclave configuration");
         Ok(self.config.write().await.replace(config))
     }
 
     async fn get_contract(&self) -> Result<Option<Self::Contract>, Self::Error> {
+        debug!("Retrieving enclave contract");
         Ok(self.contract.read().await.clone())
     }
 
     async fn set_contract(
         &self,
         contract: Self::Contract,
     ) -> Result<Option<Self::Contract>, Self::Error> {
+        debug!("Setting new enclave contract: {contract}");
         Ok(self.contract.write().await.replace(contract))
     }
 
     async fn get_nonce(&self) -> Result<Option<Nonce>, Self::Error> {
+        debug!("Retrieving enclave nonce");
         Ok(*self.nonce.read().await)
     }
 
     async fn set_nonce(&self, nonce: Nonce) -> Result<Option<Nonce>, Self::Error> {
+        debug!("Setting new enclave nonce: {nonce:?}");
         Ok(self.nonce.write().await.replace(nonce))
     }
 
     async fn get_seq_num(&self) -> Result<u64, Self::Error> {
+        debug!("Retrieving sequence number");
         Ok(*self.seq_num.read().await)
     }
 
     async fn inc_seq_num(&self, count: usize) -> Result<u64, Self::Error> {
+        debug!("Incrementing sequence number by {count}");
         let mut seq_num = self.seq_num.write().await;
         let prev_seq_num = *seq_num;
         *seq_num += count as u64;
+        trace!(
+            "Sequence number incremented from {} to {}",
+            prev_seq_num,
+            *seq_num
+        );
         Ok(prev_seq_num)
     }
 }