Merge pull request #879 from near/xiangyi/logging

adjust log levels and remove tracing::trace!()

chain-signatures/node/src/cli.rs

@@ -216,7 +216,7 @@ pub fn run(cmd: Cli) -> anyhow::Result<()> {
                 client_headers.insert(http::header::REFERER, referer_param.parse().unwrap());
             }
 
-            tracing::debug!(rpc_addr = rpc_client.rpc_addr(), "rpc client initialized");
+            tracing::info!(rpc_addr = rpc_client.rpc_addr(), "rpc client initialized");
             let signer = InMemorySigner::from_secret_key(account_id.clone(), account_sk);
             let (protocol, protocol_state) = MpcSignProtocol::init(
                 my_address,
@@ -238,18 +238,18 @@ pub fn run(cmd: Cli) -> anyhow::Result<()> {
             );
 
             rt.block_on(async {
-                tracing::debug!("protocol initialized");
+                tracing::info!("protocol initialized");
                 let protocol_handle = tokio::spawn(async move { protocol.run().await });
-                tracing::debug!("protocol thread spawned");
+                tracing::info!("protocol thread spawned");
                 let cipher_sk = hpke::SecretKey::try_from_bytes(&hex::decode(cipher_sk)?)?;
                 let web_handle = tokio::spawn(async move {
                     web::run(web_port, sender, cipher_sk, protocol_state, indexer).await
                 });
-                tracing::debug!("protocol http server spawned");
+                tracing::info!("protocol http server spawned");
 
                 protocol_handle.await??;
                 web_handle.await??;
-                tracing::debug!("spinning down");
+                tracing::info!("spinning down");
 
                 indexer_handle.join().unwrap()?;
                 anyhow::Ok(())

chain-signatures/node/src/http_client.rs

@@ -169,7 +169,7 @@ impl MessageQueue {
         }
 
         if uncompacted > 0 {
-            tracing::debug!(
+            tracing::info!(
                 uncompacted,
                 compacted,
                 "{from:?} sent messages in {:?};",

chain-signatures/node/src/indexer.rs

@@ -146,7 +146,7 @@ impl Indexer {
         block_height: BlockHeight,
         gcp: &GcpService,
     ) -> Result<(), DatastoreStorageError> {
-        tracing::trace!(block_height, "update_block_height");
+        tracing::debug!(block_height, "update_block_height");
         *self.last_updated_timestamp.write().await = Instant::now();
         self.latest_block_height
             .write()
@@ -170,11 +170,11 @@ async fn handle_block(
     mut block: near_lake_primitives::block::Block,
     ctx: &Context,
 ) -> anyhow::Result<()> {
-    tracing::trace!(block_height = block.block_height(), "handle_block");
+    tracing::debug!(block_height = block.block_height(), "handle_block");
     let mut pending_requests = Vec::new();
     for action in block.actions().cloned().collect::<Vec<_>>() {
         if action.receiver_id() == ctx.mpc_contract_id {
-            tracing::trace!("got action targeting {}", ctx.mpc_contract_id);
+            tracing::debug!("got action targeting {}", ctx.mpc_contract_id);
             let Some(receipt) = block.receipt_by_id(&action.receipt_id()) else {
                 let err = format!(
                     "indexer unable to find block for receipt_id={}",
@@ -190,7 +190,7 @@ async fn handle_block(
                 continue;
             };
             if function_call.method_name() == "sign" {
-                tracing::trace!("found `sign` function call");
+                tracing::debug!("found `sign` function call");
                 let arguments =
                     match serde_json::from_slice::<'_, SignArguments>(function_call.args()) {
                         Ok(arguments) => arguments,
@@ -369,7 +369,7 @@ pub fn run(
             let outcome = rt.block_on(async {
                 if i > 0 {
                     // give it some time to catch up
-                    tracing::trace!("giving indexer some time to catch up");
+                    tracing::debug!("giving indexer some time to catch up");
                     backoff(i, 10, 300);
                 }
                 // while running, we will keep the task spinning, and check every so often if
@@ -383,7 +383,7 @@ pub fn run(
 
                 // Abort the indexer task if it's still running.
                 if !join_handle.is_finished() {
-                    tracing::trace!("aborting indexer task");
+                    tracing::debug!("aborting indexer task");
                     join_handle.abort();
                 }
 

chain-signatures/node/src/protocol/consensus.rs

@@ -255,7 +255,7 @@ impl ConsensusProtocol for GeneratingState {
     ) -> Result<NodeState, ConsensusError> {
         match contract_state {
             ProtocolState::Initializing(_) => {
-                tracing::debug!("generating(initializing): continuing generation, contract state has not been finalized yet");
+                tracing::info!("generating(initializing): continuing generation, contract state has not been finalized yet");
                 Ok(NodeState::Generating(self))
             }
             ProtocolState::Running(contract_state) => {
@@ -305,7 +305,7 @@ impl ConsensusProtocol for WaitingForConsensusState {
     ) -> Result<NodeState, ConsensusError> {
         match contract_state {
             ProtocolState::Initializing(contract_state) => {
-                tracing::debug!("waiting(initializing): waiting for consensus, contract state has not been finalized yet");
+                tracing::info!("waiting(initializing): waiting for consensus, contract state has not been finalized yet");
                 let public_key = self.public_key.into_near_public_key();
                 let has_voted = contract_state
                     .pk_votes
@@ -427,7 +427,7 @@ impl ConsensusProtocol for WaitingForConsensusState {
                     }
                     Ordering::Less => Err(ConsensusError::EpochRollback),
                     Ordering::Equal => {
-                        tracing::debug!(
+                        tracing::info!(
                             "waiting(resharing): waiting for resharing consensus, contract state has not been finalized yet"
                         );
                         let has_voted = contract_state.finished_votes.contains(ctx.my_account_id());
@@ -494,7 +494,7 @@ impl ConsensusProtocol for RunningState {
                 }
                 Ordering::Less => Err(ConsensusError::EpochRollback),
                 Ordering::Equal => {
-                    tracing::trace!("running(running): continuing to run as normal");
+                    tracing::debug!("running(running): continuing to run as normal");
                     if contract_state.participants != self.participants {
                         return Err(ConsensusError::MismatchedParticipants);
                     }
@@ -599,7 +599,7 @@ impl ConsensusProtocol for ResharingState {
                     }
                     Ordering::Less => Err(ConsensusError::EpochRollback),
                     Ordering::Equal => {
-                        tracing::debug!("resharing(resharing): continue to reshare as normal");
+                        tracing::info!("resharing(resharing): continue to reshare as normal");
                         if contract_state.old_participants != self.old_participants {
                             return Err(ConsensusError::MismatchedParticipants);
                         }
@@ -685,7 +685,7 @@ impl ConsensusProtocol for JoiningState {
                     tracing::info!("joining(resharing): joining as a new participant");
                     start_resharing(None, ctx, contract_state).await
                 } else {
-                    tracing::debug!("joining(resharing): network is resharing without us, waiting for them to finish");
+                    tracing::info!("joining(resharing): network is resharing without us, waiting for them to finish");
                     Ok(NodeState::Joining(self))
                 }
             }

chain-signatures/node/src/protocol/cryptography.rs

@@ -90,7 +90,7 @@ impl CryptographicProtocol for GeneratingState {
             match action {
                 Action::Wait => {
                     drop(protocol);
-                    tracing::trace!("generating: waiting");
+                    tracing::debug!("generating: waiting");
                     let failures = self
                         .messages
                         .write()
@@ -246,7 +246,7 @@ impl CryptographicProtocol for ResharingState {
             match action {
                 Action::Wait => {
                     drop(protocol);
-                    tracing::trace!("resharing: waiting");
+                    tracing::debug!("resharing: waiting");
                     let failures = self
                         .messages
                         .write()
@@ -359,7 +359,7 @@ impl CryptographicProtocol for RunningState {
         let protocol_cfg = &ctx.cfg().protocol;
         let active = ctx.mesh().active_participants();
         if active.len() < self.threshold {
-            tracing::info!(
+            tracing::warn!(
                 active = ?active.keys_vec(),
                 "running: not enough participants to progress"
             );
@@ -427,7 +427,7 @@ impl CryptographicProtocol for RunningState {
         // block height is up to date, such that they too can process signature requests. If they cannot
         // then they are considered unstable and should not be a part of signature generation this round.
         let stable = ctx.mesh().stable_participants().await;
-        tracing::trace!(?stable, "stable participants");
+        tracing::debug!(?stable, "stable participants");
 
         let mut sign_queue = self.sign_queue.write().await;
         crate::metrics::SIGN_QUEUE_SIZE

chain-signatures/node/src/protocol/message.rs

@@ -333,7 +333,7 @@ impl MessageHandler for RunningState {
                 ) => {
                     // This triple has already been generated or removed from the triple manager, so we will have to bin
                     // the entirety of the messages we received for this presignature id, and have the other nodes timeout
-                    tracing::debug!(id, ?err, "presignature cannot be generated");
+                    tracing::warn!(id, ?err, "presignature cannot be generated");
                     queue.clear();
                     continue;
                 }
@@ -437,7 +437,7 @@ impl MessageHandler for RunningState {
                     // and have the other nodes timeout in the following cases:
                     // - If a presignature is in GC, then it was used already or failed to be produced.
                     // - If a presignature is missing, that means our system cannot process this signature.
-                    tracing::debug!(%receipt_id, ?err, "signature cannot be generated");
+                    tracing::warn!(%receipt_id, ?err, "signature cannot be generated");
                     queue.clear();
                     continue;
                 }

chain-signatures/node/src/protocol/mod.rs

@@ -226,20 +226,20 @@ impl MpcSignProtocol {
 
         loop {
             let protocol_time = Instant::now();
-            tracing::trace!("trying to advance chain signatures protocol");
+            tracing::debug!("trying to advance chain signatures protocol");
             loop {
                 let msg_result = self.receiver.try_recv();
                 match msg_result {
                     Ok(msg) => {
-                        tracing::trace!("received a new message");
+                        tracing::debug!("received a new message");
                         queue.push(msg);
                     }
                     Err(TryRecvError::Empty) => {
-                        tracing::trace!("no new messages received");
+                        tracing::debug!("no new messages received");
                         break;
                     }
                     Err(TryRecvError::Disconnected) => {
-                        tracing::debug!("communication was disconnected, no more messages will be received, spinning down");
+                        tracing::warn!("communication was disconnected, no more messages will be received, spinning down");
                         return Ok(());
                     }
                 }
@@ -296,7 +296,7 @@ impl MpcSignProtocol {
             let crypto_time = Instant::now();
             let mut state = match state.progress(&mut self).await {
                 Ok(state) => {
-                    tracing::trace!("progress ok: {state}");
+                    tracing::debug!("progress ok: {state}");
                     state
                 }
                 Err(err) => {

chain-signatures/node/src/protocol/presignature.rs

@@ -234,7 +234,7 @@ impl PresignatureManager {
             )));
         }
 
-        tracing::debug!(id, "starting protocol to generate a new presignature");
+        tracing::info!(id, "starting protocol to generate a new presignature");
         let generator = Self::generate_internal(
             participants,
             self.me,
@@ -279,15 +279,15 @@ impl PresignatureManager {
         };
 
         if not_enough_presignatures {
-            tracing::trace!("not enough presignatures, generating");
+            tracing::debug!("not enough presignatures, generating");
             // To ensure there is no contention between different nodes we are only using triples
             // that we proposed. This way in a non-BFT environment we are guaranteed to never try
             // to use the same triple as any other node.
             if let Some((triple0, triple1)) = triple_manager.take_two_mine().await {
                 let presig_participants = active
                     .intersection(&[&triple0.public.participants, &triple1.public.participants]);
                 if presig_participants.len() < self.threshold {
-                    tracing::debug!(
+                    tracing::warn!(
                         participants = ?presig_participants.keys_vec(),
                         "running: the intersection of participants is less than the threshold"
                     );
@@ -307,7 +307,7 @@ impl PresignatureManager {
                     )?;
                 }
             } else {
-                tracing::debug!("running: we don't have enough triples to generate a presignature");
+                tracing::warn!("running: we don't have enough triples to generate a presignature");
             }
         }
 
@@ -333,10 +333,10 @@ impl PresignatureManager {
         cfg: &ProtocolConfig,
     ) -> Result<&mut PresignatureProtocol, GenerationError> {
         if self.presignatures.contains_key(&id) {
-            tracing::debug!(id, "presignature already generated");
+            tracing::warn!(id, "presignature already generated");
             Err(GenerationError::AlreadyGenerated)
         } else if self.gc.contains_key(&id) {
-            tracing::debug!(id, "presignature was garbage collected");
+            tracing::warn!(id, "presignature was garbage collected");
             Err(GenerationError::PresignatureIsGarbageCollected(id))
         } else {
             match self.generators.entry(id) {
@@ -405,7 +405,7 @@ impl PresignatureManager {
 
     pub fn take_mine(&mut self) -> Option<Presignature> {
         let my_presignature_id = self.mine.pop_front()?;
-        tracing::debug!(my_presignature_id, "take presignature of mine");
+        tracing::info!(my_presignature_id, "take presignature of mine");
         // SAFETY: This unwrap is safe because taking mine will always succeed since it is only
         // present when generation completes where the determination of ownership is made.
         Some(self.take(my_presignature_id).unwrap())
@@ -414,7 +414,7 @@ impl PresignatureManager {
     pub fn take(&mut self, id: PresignatureId) -> Result<Presignature, GenerationError> {
         if let Some(presignature) = self.presignatures.remove(&id) {
             self.gc.insert(id, Instant::now());
-            tracing::trace!(id, "took presignature");
+            tracing::info!(id, "took presignature");
             return Ok(presignature);
         }
 
@@ -431,7 +431,7 @@ impl PresignatureManager {
     }
 
     pub fn insert_mine(&mut self, presig: Presignature) {
-        tracing::trace!(id = ?presig.id, "inserting presignature");
+        tracing::debug!(id = ?presig.id, "inserting presignature");
         // Remove from taken list if it was there
         self.gc.remove(&presig.id);
         self.mine.push_back(presig.id);
@@ -461,7 +461,7 @@ impl PresignatureManager {
                 };
                 match action {
                     Action::Wait => {
-                        tracing::trace!("waiting");
+                        tracing::debug!("presignature: waiting");
                         // Retain protocol until we are finished
                         return true;
                     }

chain-signatures/node/src/protocol/signature.rs

@@ -539,7 +539,7 @@ impl SignatureManager {
                 };
                 match action {
                     Action::Wait => {
-                        tracing::trace!("waiting");
+                        tracing::debug!("signature: waiting");
                         // Retain protocol until we are finished
                         return true;
                     }

chain-signatures/node/src/protocol/triple.rs

@@ -226,7 +226,7 @@ impl TripleManager {
             )));
         }
 
-        tracing::debug!(id, "starting protocol to generate a new triple");
+        tracing::info!(id, "starting protocol to generate a new triple");
         let participants: Vec<_> = participants.keys().cloned().collect();
         let protocol: TripleProtocol = Box::new(cait_sith::triples::generate_triple::<Secp256k1>(
             &participants,
@@ -267,7 +267,7 @@ impl TripleManager {
         };
 
         if not_enough_triples {
-            tracing::trace!("not enough triples, genertion");
+            tracing::debug!("not enough triples, generating");
             self.generate(participants, cfg.triple.generation_timeout)?;
         }
         Ok(())
@@ -391,7 +391,7 @@ impl TripleManager {
     }
 
     pub async fn insert_mine(&mut self, triple: Triple) {
-        tracing::trace!(id = triple.id, "inserting mine triple");
+        tracing::debug!(id = triple.id, "inserting mine triple");
         self.mine.push_back(triple.id);
         self.triples.insert(triple.id, triple.clone());
         self.gc.remove(&triple.id);
@@ -421,7 +421,7 @@ impl TripleManager {
                         return Ok(None);
                     }
 
-                    tracing::debug!(id, "joining protocol to generate a new triple");
+                    tracing::info!(id, "joining protocol to generate a new triple");
                     let participants = participants.keys_vec();
                     let protocol = Box::new(cait_sith::triples::generate_triple::<Secp256k1>(
                         &participants,
@@ -489,7 +489,7 @@ impl TripleManager {
 
                 match action {
                     Action::Wait => {
-                        tracing::trace!("waiting");
+                        tracing::debug!("triple: waiting");
                         // Retain protocol until we are finished
                         break true;
                     }

chain-signatures/node/src/storage/secret_storage.rs

@@ -95,7 +95,7 @@ impl DiskNodeStorage {
 #[async_trait]
 impl SecretNodeStorage for DiskNodeStorage {
     async fn store(&mut self, data: &PersistentNodeData) -> SecretResult<()> {
-        tracing::debug!("storing PersistentNodeData using DiskNodeStorage");
+        tracing::info!("storing PersistentNodeData using DiskNodeStorage");
         let mut file = File::create(self.path.as_os_str()).await?;
         // Serialize the person object to JSON and convert directly to bytes
         let json_bytes = serde_json::to_vec(data)?;
@@ -114,10 +114,10 @@ impl SecretNodeStorage for DiskNodeStorage {
             Ok(mut file) => {
                 let mut contents = Vec::new();
                 // Read the contents of the file into the vector
-                tracing::debug!("loading PersistentNodeData using DiskNodeStorage: reading");
+                tracing::info!("loading PersistentNodeData using DiskNodeStorage: reading");
                 file.read_to_end(&mut contents).await?;
 
-                tracing::debug!("loading PersistentNodeData using DiskNodeStorage: read done");
+                tracing::info!("loading PersistentNodeData using DiskNodeStorage: read done");
                 // Deserialize the JSON content to a PersistentNodeData object
                 let data: PersistentNodeData = serde_json::from_slice(&contents)?;