Adjust logging level and messages (#2857)

* adjust log level * use trace lvl * more log * fix clippy
litentry · Jul 4, 2024 · c8f1d87 · c8f1d87
1 parent 05bbdd4
commit c8f1d87
Show file tree

Hide file tree

Showing 21 changed files with 51 additions and 56 deletions.
diff --git a/bitacross-worker/core-primitives/substrate-sgx/sp-io/src/lib.rs b/bitacross-worker/core-primitives/substrate-sgx/sp-io/src/lib.rs
@@ -169,7 +169,7 @@ pub mod storage {
 	pub fn clear(key: &[u8]) {
 		with_externalities(|ext| {
 			if ext.remove(key).is_none() {
-				info!("Tried to clear storage that was not existing");
+				debug!("Tried to clear storage that was not existing");
 			}
 		});
 	}
@@ -272,7 +272,7 @@ pub mod storage {
 	/// in unbalanced transactions. For example, FRAME users should use high level storage
 	/// abstractions.
 	pub fn start_transaction() {
-		warn!("storage::start_transaction unimplemented");
+		debug!("storage::start_transaction unimplemented");
 	}
 
 	/// Rollback the last transaction started by `start_transaction`.
@@ -283,7 +283,7 @@ pub mod storage {
 	///
 	/// Will panic if there is no open transaction.
 	pub fn rollback_transaction() {
-		warn!("storage::rollback_transaction unimplemented");
+		debug!("storage::rollback_transaction unimplemented");
 	}
 
 	/// Commit the last transaction started by `start_transaction`.
@@ -294,7 +294,7 @@ pub mod storage {
 	///
 	/// Will panic if there is no open transaction.
 	pub fn commit_transaction() {
-		warn!("storage::commit_transaction unimplemented");
+		debug!("storage::commit_transaction unimplemented");
 	}
 }
 

diff --git a/bitacross-worker/service/src/ocall_bridge/bridge_api.rs b/bitacross-worker/service/src/ocall_bridge/bridge_api.rs
@@ -43,7 +43,7 @@ pub struct Bridge;
 
 impl Bridge {
 	pub fn get_ra_api() -> Arc<dyn RemoteAttestationBridge> {
-		debug!("Requesting RemoteAttestation OCall API instance");
+		trace!("Requesting RemoteAttestation OCall API instance");
 
 		COMPONENT_FACTORY
 			.read()
@@ -53,7 +53,7 @@ impl Bridge {
 	}
 
 	pub fn get_oc_api() -> Arc<dyn WorkerOnChainBridge> {
-		debug!("Requesting WorkerOnChain OCall API instance");
+		trace!("Requesting WorkerOnChain OCall API instance");
 
 		COMPONENT_FACTORY
 			.read()
@@ -63,7 +63,7 @@ impl Bridge {
 	}
 
 	pub fn get_ipfs_api() -> Arc<dyn IpfsBridge> {
-		debug!("Requesting IPFS OCall API instance");
+		trace!("Requesting IPFS OCall API instance");
 
 		COMPONENT_FACTORY
 			.read()
@@ -81,7 +81,7 @@ impl Bridge {
 	}
 
 	pub fn initialize(component_factory: Arc<dyn GetOCallBridgeComponents + Send + Sync>) {
-		debug!("Initializing OCall bridge with component factory");
+		trace!("Initializing OCall bridge with component factory");
 
 		*COMPONENT_FACTORY.write() = Some(component_factory);
 	}

diff --git a/bitacross-worker/service/src/ocall_bridge/worker_on_chain_ocall.rs b/bitacross-worker/service/src/ocall_bridge/worker_on_chain_ocall.rs
@@ -83,7 +83,7 @@ where
 		request: Vec<u8>,
 		parentchain_id: Vec<u8>,
 	) -> OCallBridgeResult<Vec<u8>> {
-		debug!("    Entering ocall_worker_request");
+		trace!("    Entering ocall_worker_request");
 
 		let requests: Vec<WorkerRequest> = Decode::decode(&mut request.as_slice())?;
 		if requests.is_empty() {

diff --git a/bitacross-worker/service/src/parentchain_handler.rs b/bitacross-worker/service/src/parentchain_handler.rs
@@ -290,7 +290,7 @@ where
 					.expect("Can decode previously encoded header; qed");
 
 			start_block = until_synced_header.number + 1;
-			println!(
+			info!(
 				"[{:?}] Synced {} out of {} finalized parentchain blocks",
 				id, until_synced_header.number, curr_block_number,
 			);
@@ -321,7 +321,7 @@ where
 				shard,
 				true,
 			)?;
-			println!("[{:?}] synced block number: #{}", id, last_synced_header.number);
+			info!("[{:?}] synced block number: #{}", id, last_synced_header.number);
 			std::thread::sleep(std::time::Duration::from_secs(1));
 		}
 		Ok(last_synced_header)

diff --git a/tee-worker/core-primitives/substrate-sgx/sp-io/src/lib.rs b/tee-worker/core-primitives/substrate-sgx/sp-io/src/lib.rs
@@ -169,7 +169,7 @@ pub mod storage {
 	pub fn clear(key: &[u8]) {
 		with_externalities(|ext| {
 			if ext.remove(key).is_none() {
-				info!("Tried to clear storage that was not existing");
+				debug!("Tried to clear storage that was not existing");
 			}
 		});
 	}

diff --git a/tee-worker/core-primitives/top-pool-author/src/author.rs b/tee-worker/core-primitives/top-pool-author/src/author.rs
@@ -330,7 +330,7 @@ impl<
 					}) {
 						error!("Could not send broadcasted request, reason: {:?}", e);
 					} else {
-						info!("Broadcast request OK, hash = {}", hash);
+						debug!("Broadcast request OK, hash = {}", hash);
 					}
 				}
 				result

diff --git a/tee-worker/core/direct-rpc-server/src/rpc_connection_registry.rs b/tee-worker/core/direct-rpc-server/src/rpc_connection_registry.rs
@@ -76,7 +76,7 @@ where
 		rpc_response: RpcResponse,
 		force_wait: ForceWait,
 	) {
-		log::info!("Store hash {:?} to connection registry, force_wait: {}", hash, force_wait);
+		log::debug!("Store hash {:?} to connection registry, force_wait: {}", hash, force_wait);
 		let mut map = self.connection_map.write().expect("Lock poisoning");
 		map.insert(hash, (connection, rpc_response, force_wait));
 	}

diff --git a/tee-worker/core/direct-rpc-server/src/rpc_responder.rs b/tee-worker/core/direct-rpc-server/src/rpc_responder.rs
@@ -75,7 +75,7 @@ where
 		hash: Hash,
 		status_update: TrustedOperationStatus,
 	) -> DirectRpcResult<()> {
-		info!("updating status event, hash: {}, status: {:?}", hash.to_hex(), status_update);
+		debug!("updating status event, hash: {}, status: {:?}", hash.to_hex(), status_update);
 
 		// withdraw removes it from the registry
 		let (connection_token, rpc_response, force_wait) = self
@@ -167,7 +167,7 @@ where
 		encoded_value: Vec<u8>,
 		force_wait: bool,
 	) -> DirectRpcResult<()> {
-		info!(
+		debug!(
 			"updating connection state for hash {:?}: encoded_value {:?}, force_wait: {:?}",
 			hash,
 			encoded_value.to_hex(),

diff --git a/tee-worker/litentry/core/evm-dynamic-assertions/src/repository.rs b/tee-worker/litentry/core/evm-dynamic-assertions/src/repository.rs
@@ -104,7 +104,7 @@ pub mod sgx_tests {
 	use ethabi::ethereum_types::H160;
 	use itp_sgx_temp_dir::TempDir;
 	use lc_dynamic_assertion::AssertionLogicRepository;
-	use sgx_tstd::{path::Path, string::ToString, vec, vec::Vec};
+	use sgx_tstd::{string::ToString, vec, vec::Vec};
 
 	pub fn restores_state_from_seal() {
 		let seal_file_name = "test_sealed_assertion.bin";

diff --git a/tee-worker/litentry/core/stf-task/receiver/src/lib.rs b/tee-worker/litentry/core/stf-task/receiver/src/lib.rs
@@ -236,7 +236,6 @@ where
 	let context_cloned = context.clone();
 	thread::spawn(move || loop {
 		if let Ok((shard, hash, call)) = receiver.recv() {
-			info!("Submitting trusted call to the pool");
 			if let Err(e) = context_cloned.submit_trusted_call(&shard, Some(hash), &call) {
 				error!("Submit Trusted Call failed: {:?}", e);
 			}

diff --git a/tee-worker/litentry/core/vc-task/receiver/src/lib.rs b/tee-worker/litentry/core/vc-task/receiver/src/lib.rs
@@ -103,7 +103,6 @@ pub fn run_vc_handler_runner<ShieldingKeyRepository, A, S, H, O, N, AR>(
 	let context_cloned = context.clone();
 	thread::spawn(move || loop {
 		if let Ok((shard, call)) = tc_receiver.recv() {
-			info!("Submitting trusted call to the pool");
 			if let Err(e) = context_cloned.submit_trusted_call(&shard, None, &call) {
 				error!("Submit Trusted Call failed: {:?}", e);
 			}
@@ -434,6 +433,11 @@ where
 
 	// The `call` should always be `TrustedCall:request_vc`. Once decided to remove 'request_vc', this part can be refactored regarding the parameters.
 	if let TrustedCall::request_vc(signer, who, assertion, maybe_key, req_ext_hash) = call {
+		info!(
+			"Processing vc request for {}, assertion: {:?}",
+			who.to_did().unwrap_or_default(),
+			assertion
+		);
 		let (mut id_graph, is_already_linked, parachain_block_number, sidechain_block_number) =
 			context
 				.state_handler
@@ -481,7 +485,7 @@ where
 
 		let mut should_create_id_graph = false;
 		if id_graph.is_empty() {
-			info!("IDGraph is empty, will pre-create one");
+			debug!("IDGraph is empty, will pre-create one");
 			// To create IDGraph upon first vc request (see P-410), there're two options:
 			//
 			// 1. synchronous creation:
@@ -585,7 +589,7 @@ where
 			.enclave_signer
 			.get_enclave_account()
 			.map_err(|_| RequestVcErrorDetail::EnclaveSignerRetrievalFailed)?;
-		let c = TrustedCall::maybe_create_id_graph(enclave_signer.into(), who);
+		let c = TrustedCall::maybe_create_id_graph(enclave_signer.into(), who.clone());
 		tc_sender
 			.send((shard, c))
 			.map_err(|e| RequestVcErrorDetail::TrustedCallSendingFailed(e.to_string()))?;
@@ -595,11 +599,12 @@ where
 
 		if let Err(e) = context
 			.ocall_api
-			.update_metric(EnclaveMetric::VCBuildTime(assertion, start_time.elapsed()))
+			.update_metric(EnclaveMetric::VCBuildTime(assertion.clone(), start_time.elapsed()))
 		{
 			warn!("Failed to update metric for vc build time: {:?}", e);
 		}
 
+		info!("Vc issued for {}, assertion: {:?}", who.to_did().unwrap_or_default(), assertion);
 		Ok(res.encode())
 	} else {
 		// Would never come here.

diff --git a/tee-worker/service/src/ocall_bridge/bridge_api.rs b/tee-worker/service/src/ocall_bridge/bridge_api.rs
@@ -43,7 +43,7 @@ pub struct Bridge;
 
 impl Bridge {
 	pub fn get_ra_api() -> Arc<dyn RemoteAttestationBridge> {
-		debug!("Requesting RemoteAttestation OCall API instance");
+		trace!("Requesting RemoteAttestation OCall API instance");
 
 		COMPONENT_FACTORY
 			.read()
@@ -61,7 +61,7 @@ impl Bridge {
 	}
 
 	pub fn get_oc_api() -> Arc<dyn WorkerOnChainBridge> {
-		debug!("Requesting WorkerOnChain OCall API instance");
+		trace!("Requesting WorkerOnChain OCall API instance");
 
 		COMPONENT_FACTORY
 			.read()
@@ -71,7 +71,7 @@ impl Bridge {
 	}
 
 	pub fn get_ipfs_api() -> Arc<dyn IpfsBridge> {
-		debug!("Requesting IPFS OCall API instance");
+		trace!("Requesting IPFS OCall API instance");
 
 		COMPONENT_FACTORY
 			.read()
@@ -89,7 +89,7 @@ impl Bridge {
 	}
 
 	pub fn initialize(component_factory: Arc<dyn GetOCallBridgeComponents + Send + Sync>) {
-		debug!("Initializing OCall bridge with component factory");
+		trace!("Initializing OCall bridge with component factory");
 
 		*COMPONENT_FACTORY.write() = Some(component_factory);
 	}

diff --git a/tee-worker/service/src/ocall_bridge/ffi/get_peers.rs b/tee-worker/service/src/ocall_bridge/ffi/get_peers.rs
@@ -17,7 +17,7 @@ fn get_trusted_peers_urls(
 	peers_size: u32,
 	sidechain_api: Arc<dyn SidechainBridge>,
 ) -> sgx_status_t {
-	debug!("    Entering ocall_get_trusted_peers_urls");
+	trace!("    Entering ocall_get_trusted_peers_urls");
 
 	let peers_encoded = match sidechain_api.get_trusted_peers_urls() {
 		Ok(r) => r,

diff --git a/tee-worker/service/src/ocall_bridge/worker_on_chain_ocall.rs b/tee-worker/service/src/ocall_bridge/worker_on_chain_ocall.rs
@@ -83,7 +83,7 @@ where
 		request: Vec<u8>,
 		parentchain_id: Vec<u8>,
 	) -> OCallBridgeResult<Vec<u8>> {
-		debug!("    Entering ocall_worker_request");
+		trace!("    Entering ocall_worker_request");
 
 		let requests: Vec<WorkerRequest> = Decode::decode(&mut request.as_slice())?;
 		if requests.is_empty() {

diff --git a/tee-worker/service/src/parentchain_handler.rs b/tee-worker/service/src/parentchain_handler.rs
@@ -220,7 +220,7 @@ where
 					id, curr_block_number, until_synced_header.number, immediate_import, format_duration(remaining_time_estimate)
 				);
 			}
-			debug!(
+			trace!(
 				"[{:?}] Found {} block(s) to sync in this chunk. immediate import={} ",
 				id,
 				block_chunk_to_sync.len(),
@@ -252,7 +252,7 @@ where
 						self.parentchain_api.get_events_for_block(Some(block.block.header.hash()))
 					})
 					.collect::<Result<Vec<_>, _>>()?;
-				debug!("[{:?}] Found {} event vector(s) to sync in this chunk", id, evs.len());
+				trace!("[{:?}] Found {} event vector(s) to sync in this chunk", id, evs.len());
 				evs
 			};
 
@@ -290,7 +290,7 @@ where
 					.expect("Can decode previously encoded header; qed");
 
 			start_block = until_synced_header.number + 1;
-			println!(
+			info!(
 				"[{:?}] Synced {} out of {} finalized parentchain blocks",
 				id, until_synced_header.number, curr_block_number,
 			);
@@ -321,7 +321,7 @@ where
 				shard,
 				true,
 			)?;
-			println!("[{:?}] synced block number: #{}", id, last_synced_header.number);
+			info!("[{:?}] synced block number: #{}", id, last_synced_header.number);
 			std::thread::sleep(std::time::Duration::from_secs(1));
 		}
 		Ok(last_synced_header)

diff --git a/tee-worker/sidechain/consensus/aura/src/slot_proposer.rs b/tee-worker/sidechain/consensus/aura/src/slot_proposer.rs
@@ -196,8 +196,8 @@ impl<
 			warn!("Failed to update metric for sidechain slot block composition time: {:?}", e);
 		};
 
-		println!(
-			"[Sidechain] propose block {} summary: executed {}, failed {}, from {} in queue in {}ms",
+		info!(
+			"Proposing sidechain block {} summary: executed {}, failed {}, from {} in queue in {}ms",
 			sidechain_block.block().header().block_number(),
 			number_executed_transactions,
 			nr_failed_operations,

diff --git a/tee-worker/sidechain/consensus/common/src/block_import.rs b/tee-worker/sidechain/consensus/common/src/block_import.rs
@@ -152,7 +152,7 @@ where
 			let encrypted_state_diff =
 				block_import_params.block().block_data().encrypted_state_diff();
 
-			info!(
+			debug!(
 				"Applying state diff for block {} of size {} bytes",
 				block_number,
 				encrypted_state_diff.len()
@@ -166,7 +166,7 @@ where
 
 			Ok(state)
 		})?;
-		info!(
+		debug!(
 			"Applying state update from block {} took {} ms",
 			block_number,
 			state_update_start_time.elapsed().as_millis()
@@ -178,7 +178,7 @@ where
 		self.get_context().store_sidechain_blocks(vec![signed_sidechain_block])?;
 
 		let import_duration = start_time.elapsed();
-		info!("Importing block {} took {} ms", block_number, import_duration.as_millis());
+		debug!("Importing block {} took {} ms", block_number, import_duration.as_millis());
 		if let Err(e) = self
 			.get_context()
 			.update_metric(EnclaveMetric::SidechainBlockImportTime(import_duration))

diff --git a/tee-worker/sidechain/consensus/common/src/peer_block_sync.rs b/tee-worker/sidechain/consensus/common/src/peer_block_sync.rs
@@ -212,7 +212,7 @@ where
 				_ => Err(e),
 			},
 			Ok(latest_parentchain_header) => {
-				println!("[Sidechain] imported block (number: {}, tcalls: {}, author: {}), based on parentchain block {:?}",
+				info!("Imported sidechain block (number: {}, tcalls: {}, author: {}), based on parentchain block {:?}",
 					sidechain_block_number, sidechain_block.block().block_data().signed_top_hashes().len(),
 						 hex_encode(sidechain_block.block().block_data().block_author().encode().as_slice()) ,latest_parentchain_header.number());
 

diff --git a/tee-worker/sidechain/consensus/slots/src/lib.rs b/tee-worker/sidechain/consensus/slots/src/lib.rs
@@ -401,7 +401,7 @@ pub trait SimpleSlotWorker<ParentchainBlock: ParentchainBlockTrait> {
 		};
 		trace!(
 			"on_slot: a posteriori latest Litentry block number (if there is a new one): {:?}",
-			last_imported_integritee_header.clone().map(|h| *h.number())
+			last_imported_integritee_header.map(|h| *h.number())
 		);
 
 		let maybe_last_imported_target_a_header =
@@ -466,7 +466,7 @@ pub trait SimpleSlotWorker<ParentchainBlock: ParentchainBlockTrait> {
 		};
 
 		if is_single_worker {
-			warn!("Running as single worker, skipping timestamp within slot check")
+			debug!("Running as single worker, skipping timestamp within slot check")
 		} else if !timestamp_within_slot(&slot_info, &proposing.block) {
 			warn!(
 				"⌛️ Discarding proposal for slot {}, block number {}; block production took too long",
@@ -476,19 +476,10 @@ pub trait SimpleSlotWorker<ParentchainBlock: ParentchainBlockTrait> {
 			return None
 		}
 
-		if last_imported_integritee_header.is_some() {
-			println!(
-				"Syncing Parentchains: Litentry: {:?} TargetA: {:?}, TargetB: {:?}, Sidechain: {:?}",
-				latest_integritee_parentchain_header.number(),
-				maybe_latest_target_a_parentchain_header.map(|h| *h.number()),
-				maybe_latest_target_b_parentchain_header.map(|h| *h.number()),
-				proposing.block.block().header().block_number()
-			);
-		}
-
-		info!("Proposing sidechain block (number: {}, hash: {}) based on integritee parentchain block (number: {:?}, hash: {:?})",
-			proposing.block.block().header().block_number(), proposing.block.hash(),
-			latest_integritee_parentchain_header.number(), latest_integritee_parentchain_header.hash()
+		info!(
+			"Proposed sidechain block {} based on parentchain block {:?}",
+			proposing.block.block().header().block_number(),
+			latest_integritee_parentchain_header.number()
 		);
 
 		Some(SlotResult {