Merge pull request #342 from 0xbillw/chore/refine-ceseal-log

chore: [ceseal] reduce some logs level and modify some logs content

crates/cestory/api/src/storage_sync.rs

@@ -223,7 +223,7 @@ where
 
         let changes = &block.storage_changes;
 
-        log::debug!(
+        log::trace!(
             "calc root ({}, {})",
             changes.main_storage_changes.len(),
             changes.child_storage_changes.len()
@@ -241,9 +241,9 @@ where
             });
         }
 
-        log::debug!("apply changes");
+        log::trace!("apply changes");
         storage.apply_changes(state_root, transaction);
-        log::debug!("applied");
+        log::trace!("applied");
 
         self.block_number_next += 1;
         state_roots.pop_front();

crates/cestory/src/ceseal_service.rs

@@ -15,7 +15,7 @@ use parity_scale_codec::Error as ScaleDecodeError;
 use std::{borrow::Borrow, fmt::Debug, time::Duration};
 use thiserror::Error;
 use tonic::{Request, Response, Status};
-use tracing::{error, info};
+use tracing::{debug, error, info, trace};
 
 type RpcResult<T> = anyhow::Result<Response<T>, Status>;
 
@@ -150,9 +150,9 @@ impl<Platform: pal::Platform + Serialize + DeserializeOwned> CesealApi for RpcSe
     async fn get_info(&self, _request: Request<()>) -> RpcResult<pb::CesealInfo> {
         let info = self.lock_ceseal(true, true)?.get_info();
         #[cfg(target_env = "gnu")]
-        info!("Got info: {:?} mallinfo: {:?}", info.debug_info(), unsafe { libc::mallinfo() });
+        trace!("Got info: {:?} mallinfo: {:?}", info.debug_info(), unsafe { libc::mallinfo() });
         #[cfg(not(target_env = "gnu"))]
-        info!("Got info: {:?}", info.debug_info());
+        trace!("Got info: {:?}", info.debug_info());
         Ok(Response::new(info))
     }
 
@@ -178,7 +178,6 @@ impl<Platform: pal::Platform + Serialize + DeserializeOwned> CesealApi for RpcSe
         // However, now in order to avoid cloning the ceseal instance (as we do not want to use mutex on its internal
         // state), we have simply locked it. Remember to optimize here!
         let synced_to = self.lock_ceseal(false, true)?.dispatch_blocks(blocks);
-        info!("Blocks are dispatched");
         Ok(Response::new(synced_to?))
     }
 
@@ -620,7 +619,7 @@ impl<Platform: pal::Platform + Serialize + DeserializeOwned> Ceseal<Platform> {
         headers: Vec<blocks::HeaderToSync>,
         authority_set_change: Option<blocks::AuthoritySetChange>,
     ) -> CesealResult<pb::SyncedTo> {
-        info!(
+        trace!(
             range=?(
                 headers.first().map(|h| h.header.number),
                 headers.last().map(|h| h.header.number)
@@ -641,7 +640,7 @@ impl<Platform: pal::Platform + Serialize + DeserializeOwned> Ceseal<Platform> {
         &mut self,
         mut blocks: Vec<blocks::BlockHeaderWithChanges>,
     ) -> CesealResult<pb::SyncedTo> {
-        info!(
+        trace!(
             range=?(
                 blocks.first().map(|h| h.block_header.number),
                 blocks.last().map(|h| h.block_header.number)
@@ -659,7 +658,7 @@ impl<Platform: pal::Platform + Serialize + DeserializeOwned> Ceseal<Platform> {
         let safe_mode_level = self.args.safe_mode_level;
 
         for block in blocks.into_iter() {
-            info!(block = block.block_header.number, "Dispatching");
+            trace!(block = block.block_header.number, "Dispatching");
             let state = self.runtime_state()?;
             {
                 let mut chain_storage = state.chain_storage.write();
@@ -672,7 +671,7 @@ impl<Platform: pal::Platform + Serialize + DeserializeOwned> Ceseal<Platform> {
             if safe_mode_level > 0 {
                 continue
             }
-            info!("State synced");
+            trace!("State synced");
             state.purge_mq();
             let block_number = block.block_header.number;
 
@@ -732,6 +731,7 @@ impl<Platform: pal::Platform + Serialize + DeserializeOwned> Ceseal<Platform> {
         };
         self.dev_mode = rt_data.dev_mode;
         self.trusted_sk = rt_data.trusted_sk;
+        info!("trusted_sk: {}", self.trusted_sk);
 
         self.attestation_provider = attestation_provider;
         info!("attestation_provider: {:?}", self.attestation_provider);
@@ -884,11 +884,23 @@ impl<Platform: pal::Platform + Serialize + DeserializeOwned> Ceseal<Platform> {
     }
 
     fn get_egress_messages(&mut self) -> CesealResult<pb::EgressMessages> {
-        let messages: Vec<_> = self
+        use ces_mq::{MessageOrigin, SignedMessage};
+        let messages: Vec<(MessageOrigin, Vec<SignedMessage>)> = self
             .runtime_state
             .as_ref()
             .map(|state| state.send_mq.all_messages_grouped().into_iter().collect())
             .unwrap_or_default();
+        if log::log_enabled!(log::Level::Debug) {
+            for (_, msgs) in &messages {
+                for (index, SignedMessage { message, sequence, .. }) in msgs.iter().enumerate() {
+                    debug!(
+                        target: "ces_mq",
+                        "mq egress message {index} [seq: {}, sender: {}, destination: {:?}]",
+                        sequence, message.sender, message.destination
+                    );
+                }
+            }
+        }
         Ok(messages)
     }
 

crates/cestory/src/light_validation/mod.rs

@@ -33,7 +33,7 @@ use std::marker::PhantomData;
 use anyhow::Result;
 use error::JustificationError;
 use justification::GrandpaJustification;
-use log::{error, info};
+use log::{error, trace};
 use ces_serde_more as more;
 use serde::{Deserialize, Serialize};
 use storage_proof::{StorageProof, StorageProofChecker};
@@ -298,16 +298,16 @@ where
     H: Header<Hash = H256>,
 {
     {
-        info!("ancestor_hash: {}", ancestor_hash);
+        trace!("ancestor_hash: {}", ancestor_hash);
         for h in proof.iter() {
-            info!(
+            trace!(
                 "block {:?} - hash: {} parent: {}",
                 h.number(),
                 h.hash(),
                 h.parent_hash()
             );
         }
-        info!(
+        trace!(
             "child block {:?} - hash: {} parent: {}",
             child.number(),
             child.hash(),

crates/cestory/src/system/mod.rs

@@ -163,10 +163,6 @@ impl<Platform: pal::Platform> System<Platform> {
     pub fn will_process_block(&mut self, block: &mut BlockDispatchContext) {
         self.block_number = block.block_number;
         self.now_ms = block.now_ms;
-
-        // if let Some(keyfairy) = &mut self.keyfairy {
-        //     keyfairy.will_process_block(block);
-        // }
     }
 
     pub fn process_messages(&mut self, block: &mut BlockDispatchContext) {
@@ -181,16 +177,9 @@ impl<Platform: pal::Platform> System<Platform> {
                     },
             }
         }
-        // if let Some(keyfairy) = &mut self.keyfairy {
-        //     keyfairy.process_messages(block);
-        // }
     }
 
-    pub fn did_process_block(&mut self, _block: &mut BlockDispatchContext) {
-        // if let Some(keyfairy) = &mut self.keyfairy {
-        //     keyfairy.did_process_block(block);
-        // }
-    }
+    pub fn did_process_block(&mut self, _block: &mut BlockDispatchContext) {}
 
     fn process_worker_event(&mut self, _block: &BlockDispatchContext, event: &WorkerEvent) {
         match event {
@@ -215,7 +204,6 @@ impl<Platform: pal::Platform> System<Platform> {
             return
         }
 
-        info!("incoming master key launch event: {:?}", event);
         match event {
             MasterKeyLaunch::LaunchRequest(worker_pubkey, _) =>
                 self.process_master_key_launch_reqeust(block, origin, worker_pubkey),
@@ -279,7 +267,7 @@ impl<Platform: pal::Platform> System<Platform> {
 
         let master_pubkey = new_master_key.sr25519_public_key();
         // upload the master key on chain via worker egress
-        info!("upload master key {} on chain", hex::encode(master_pubkey));
+        info!("upload master pubkey: {} on chain", hex::encode(master_pubkey));
         let master_pubkey = MasterKeySubmission::MasterPubkey { master_pubkey };
         self.egress.push_message(&master_pubkey);
 
@@ -331,17 +319,16 @@ impl<Platform: pal::Platform> System<Platform> {
         }
 
         if self.identity_key.public() != event.dest {
-            debug!("ignore no self event: {:?}", event);
+            trace!("ignore DispatchMasterKeyEvent that do not belong to you");
             return Ok(())
         }
 
         if self.keyfairy.is_some() {
-            warn!("ignore master key distribution, keyfariy has already inited");
+            warn!("ignore DispatchMasterKeyEvent as the keyfariy has already inited");
             return Ok(())
         }
 
         let rsa_der = self.decrypt_key_from(&event.ecdh_pubkey, &event.encrypted_master_key, &event.iv);
-        info!("Keyfairy: successfully decrypt received master key");
         let master_key =
             CesealMasterKey::from_rsa_der(&rsa_der).context("failed build CesealMasterKey from rsa_der")?;
         master_key.seal(&self.sealing_path, &self.identity_key.0, &self.platform);
@@ -365,7 +352,7 @@ impl<Platform: pal::Platform> System<Platform> {
                 }
 
                 if worker_pubkey == self.identity_key.public() {
-                    info!("ignore self master key apply");
+                    trace!("ignore MasterKeyApply event that you send out");
                     return
                 }
 
@@ -408,7 +395,7 @@ impl<P: pal::Platform> System<P> {
         if self.keyfairy.is_some() {
             info!("system.on_restored(), keyfairy was assigned");
         } else {
-            warn!("system.on_restored(), keyfairy was none");
+            warn!("system.on_restored(), keyfairy is not set");
         }
         Ok(())
     }