Normalise log message levels (#1915)

Merge pull request #1915 Normalise log message levels
tari-project · May 26, 2020 · 4039de1 · 4039de1
2 parents 742ff8b + ec8700d
commit 4039de1
Show file tree

Hide file tree

Showing 50 changed files with 259 additions and 235 deletions.
diff --git a/applications/tari_base_node/src/builder.rs b/applications/tari_base_node/src/builder.rs
@@ -213,7 +213,7 @@ impl NodeContainer {
         let mut miner = ctx.miner.take().expect("Miner was not constructed");
         let mut rx = miner.get_utxo_receiver_channel();
         rt.spawn(async move {
-            debug!(target: LOG_TARGET, "Mining wallet ready to receive coins.");
+            info!(target: LOG_TARGET, " ⚒️ Mining wallet ready to receive coins.");
             while let Some(utxo) = rx.next().await {
                 match wallet_output_handle.add_output(utxo).await {
                     Ok(_) => {
@@ -233,14 +233,11 @@ impl NodeContainer {
             }
         });
         rt.spawn(async move {
-            debug!(target: LOG_TARGET, "Starting miner");
+            info!(target: LOG_TARGET, "⚒️ Starting miner");
             miner.mine().await;
-            debug!(target: LOG_TARGET, "Miner has shutdown");
+            info!(target: LOG_TARGET, "⚒️ Miner has shutdown");
         });
-        info!(
-            target: LOG_TARGET,
-            "Starting node - It will run until a fatal error occurs or until the stop flag is activated."
-        );
+        info!(target: LOG_TARGET, "Starting main base node event loop");
         ctx.node.run().await;
         info!(target: LOG_TARGET, "Initiating communications stack shutdown");
         future::join(ctx.base_node_comms.shutdown(), ctx.wallet_comms.shutdown()).await;
@@ -606,10 +603,10 @@ where
         config.num_mining_threads,
     );
     if config.enable_mining {
-        debug!(target: LOG_TARGET, "Enabling solo miner");
+        info!(target: LOG_TARGET, "Enabling solo miner");
         miner.enable_mining_flag().store(true, Ordering::Relaxed);
     } else {
-        debug!(
+        info!(
             target: LOG_TARGET,
             "Mining is disabled in the config file. This node will not mine for Tari unless enabled in the UI"
         );
@@ -652,11 +649,11 @@ async fn sync_peers(
                     Ok(mut peer) => {
                         peer.unset_id();
                         if let Err(err) = wallet_peer_manager.add_peer(peer).await {
-                            error!(target: LOG_TARGET, "Failed to add peer to wallet: {:?}", err);
+                            warn!(target: LOG_TARGET, "Failed to add peer to wallet: {:?}", err);
                         }
                     },
                     Err(err) => {
-                        error!(target: LOG_TARGET, "Failed to find peer in base node: {:?}", err);
+                        warn!(target: LOG_TARGET, "Failed to find peer in base node: {:?}", err);
                     },
                 }
             }

diff --git a/applications/tari_base_node/src/main.rs b/applications/tari_base_node/src/main.rs
@@ -144,7 +144,7 @@ fn main_inner() -> Result<(), ExitCodes> {
         ExitCodes::ConfigError
     })?;
 
-    trace!(target: LOG_TARGET, "Using configuration: {:?}", node_config);
+    debug!(target: LOG_TARGET, "Using configuration: {:?}", node_config);
 
     // Set up the Tokio runtime
     let mut rt = setup_runtime(&node_config).map_err(|err| {
@@ -248,7 +248,7 @@ fn setup_runtime(config: &GlobalConfig) -> Result<Runtime, String> {
     let num_blocking_threads = config.blocking_threads;
     let num_mining_threads = config.num_mining_threads;
 
-    debug!(
+    info!(
         target: LOG_TARGET,
         "Configuring the node to run on {} core threads, {} blocking worker threads and {} mining threads.",
         num_core_threads,

diff --git a/applications/tari_base_node/src/utils.rs b/applications/tari_base_node/src/utils.rs
@@ -48,7 +48,7 @@ where S: Stream<Item = Result<Arc<TransactionEvent>, RecvError>> + Unpin {
                     }
                 },
                 Err(e) => {
-                    log::error!(target: LOG_TARGET, "Error reading from event broadcast channel {:?}", e);
+                    log::warn!(target: LOG_TARGET, "Error reading from event broadcast channel {:?}", e);
                     break false;
                 },
             },

diff --git a/base_layer/core/src/base_node/chain_metadata_service/service.rs b/base_layer/core/src/base_node/chain_metadata_service/service.rs
@@ -27,7 +27,7 @@ use crate::{
         comms_interface::{BlockEvent, LocalNodeCommsInterface},
         proto,
     },
-    chain_storage::BlockAddResult,
+    chain_storage::{BlockAddResult, ChainMetadata},
 };
 use chrono::{NaiveDateTime, Utc};
 use futures::{stream::StreamExt, SinkExt};
@@ -211,9 +211,11 @@ impl ChainMetadataService {
     ) -> Result<(), ChainMetadataSyncError>
     {
         if let Some(chain_metadata_bytes) = metadata.get(MetadataKey::ChainMetadata) {
-            let chain_metadata = proto::ChainMetadata::decode(chain_metadata_bytes.as_slice())?.into();
-            debug!(target: LOG_TARGET, "Received chain metadata from NodeId '{}'", node_id);
-            trace!(target: LOG_TARGET, "{}", chain_metadata);
+            let chain_metadata: ChainMetadata = proto::ChainMetadata::decode(chain_metadata_bytes.as_slice())?.into();
+            debug!(
+                target: LOG_TARGET,
+                "Received chain metadata from NodeId '{}' - #{:?}", node_id, chain_metadata.height_of_longest_chain
+            );
 
             if let Some(pos) = self
                 .peer_chain_metadata
@@ -239,9 +241,11 @@ impl ChainMetadataService {
             .get(MetadataKey::ChainMetadata)
             .ok_or_else(|| ChainMetadataSyncError::NoChainMetadata)?;
 
-        let chain_metadata = proto::ChainMetadata::decode(chain_metadata_bytes.as_slice())?.into();
-        debug!(target: LOG_TARGET, "Received chain metadata from NodeId '{}'", node_id);
-        trace!(target: LOG_TARGET, "{}", chain_metadata);
+        let chain_metadata: ChainMetadata = proto::ChainMetadata::decode(chain_metadata_bytes.as_slice())?.into();
+        debug!(
+            target: LOG_TARGET,
+            "Received chain metadata from NodeId '{}' - #{:?}", node_id, chain_metadata.height_of_longest_chain
+        );
 
         if let Some(pos) = self
             .peer_chain_metadata

diff --git a/base_layer/core/src/base_node/comms_interface/inbound_handlers.rs b/base_layer/core/src/base_node/comms_interface/inbound_handlers.rs
@@ -199,7 +199,7 @@ where T: BlockchainBackend + 'static
                         Ok(block) => blocks.push(block),
                         // We need to suppress the error as another node might ask for a block we dont have, so we
                         // return ok([])
-                        Err(e) => info!(
+                        Err(e) => debug!(
                             target: LOG_TARGET,
                             "Could not provide requested block {} to peer because: {}",
                             block_num,
@@ -219,12 +219,12 @@ where T: BlockchainBackend + 'static
                     );
                     match async_db::fetch_block_with_hash(self.blockchain_db.clone(), block_hash.clone()).await {
                         Ok(Some(block)) => blocks.push(block),
-                        Ok(None) => info!(
+                        Ok(None) => warn!(
                             target: LOG_TARGET,
                             "Could not provide requested block {} to peer because not stored",
                             block_hash.to_hex(),
                         ),
-                        Err(e) => info!(
+                        Err(e) => warn!(
                             target: LOG_TARGET,
                             "Could not provide requested block {} to peer because: {}",
                             block_hash.to_hex(),
@@ -261,7 +261,10 @@ where T: BlockchainBackend + 'static
 
                 let block_template =
                     NewBlockTemplate::from(header.into_builder().with_transactions(transactions).build());
-                trace!(target: LOG_TARGET, "New block template requested {}", block_template);
+                debug!(
+                    target: LOG_TARGET,
+                    "New block template requested at height {}", block_template.header.height
+                );
                 Ok(NodeCommsResponse::NewBlockTemplate(block_template))
             },
             NodeCommsRequest::GetNewBlock(block_template) => {
@@ -298,11 +301,11 @@ where T: BlockchainBackend + 'static
         let mut result = Ok(());
         let block_event = match add_block_result.clone() {
             Ok(block_add_result) => {
-                debug!(target: LOG_TARGET, "Block event created: {}", block_add_result);
+                trace!(target: LOG_TARGET, "Block event created: {}", block_add_result);
                 BlockEvent::Verified((Box::new(block.clone()), block_add_result, *broadcast))
             },
             Err(e) => {
-                error!(target: LOG_TARGET, "Block validation failed: {:?}", e);
+                warn!(target: LOG_TARGET, "Block validation failed: {:?}", e);
                 result = Err(CommsInterfaceError::ChainStorageError(e.clone()));
                 BlockEvent::Invalid((Box::new(block.clone()), e, *broadcast))
             },
@@ -320,7 +323,7 @@ where T: BlockchainBackend + 'static
                 BlockAddResult::ChainReorg(_) => true,
             };
             if propagate && bool::from(*broadcast) {
-                debug!(
+                info!(
                     target: LOG_TARGET,
                     "Propagate block ({}) to network.",
                     block.hash().to_hex()
@@ -337,9 +340,11 @@ where T: BlockchainBackend + 'static
             .await?
             .height_of_longest_chain
             .ok_or_else(|| CommsInterfaceError::UnexpectedApiResponse)?;
-        debug!(
+        trace!(
             target: LOG_TARGET,
-            "Calculating target difficulty at height:{} for PoW:{}", height_of_longest_chain, pow_algo
+            "Calculating target difficulty at height:{} for PoW:{}",
+            height_of_longest_chain,
+            pow_algo
         );
         let constants = self.consensus_manager.consensus_constants();
         let target_difficulties = self.blockchain_db.fetch_target_difficulties(

diff --git a/base_layer/core/src/base_node/service/service.rs b/base_layer/core/src/base_node/service/service.rs
@@ -562,7 +562,7 @@ async fn handle_incoming_block<B: BlockchainBackend + 'static>(
 {
     let DomainMessage::<_> { source_peer, inner, .. } = domain_block_msg;
 
-    info!(
+    debug!(
         "New candidate block #{} (accum_diff: {}, hash: ({})) received.",
         inner.header.height,
         inner.header.total_accumulated_difficulty_inclusive(),

diff --git a/base_layer/core/src/base_node/state_machine.rs b/base_layer/core/src/base_node/state_machine.rs
@@ -157,7 +157,7 @@ impl<B: BlockchainBackend + 'static> BaseNodeStateMachine<B> {
             if let Shutdown(reason) = &state {
                 debug!(
                     target: LOG_TARGET,
-                    "=== Base Node state machine is shutting down because {}", reason
+                    "Base Node state machine is shutting down because {}", reason
                 );
                 break;
             }
@@ -169,9 +169,11 @@ impl<B: BlockchainBackend + 'static> BaseNodeStateMachine<B> {
             let next_event = select_next_state_event(interrupt_signal, next_state_future).await;
             // Publish the event on the event bus
             let _ = self.event_sender.send(next_event.clone()).await;
-            debug!(
+            trace!(
                 target: LOG_TARGET,
-                "=== Base Node event in State [{}]:  {}", state, next_event
+                "Base Node event in State [{}]:  {}",
+                state,
+                next_event
             );
             state = self.transition(state, next_event);
         }

diff --git a/base_layer/core/src/base_node/states/block_sync.rs b/base_layer/core/src/base_node/states/block_sync.rs
@@ -285,7 +285,7 @@ async fn synchronize_blocks<B: BlockchainBackend + 'static>(
     let local_metadata = shared.db.get_metadata()?;
     if let Some(local_block_hash) = local_metadata.best_block.clone() {
         if let Some(network_block_hash) = network_metadata.best_block.clone() {
-            info!(
+            debug!(
                 target: LOG_TARGET,
                 "Checking if current chain lagging on best network chain."
             );
@@ -302,19 +302,18 @@ async fn synchronize_blocks<B: BlockchainBackend + 'static>(
             )
             .await?
             {
-                info!(target: LOG_TARGET, "Chain split detected, finding chain split height.");
+                debug!(target: LOG_TARGET, "Chain split detected, finding chain split height.");
                 let min_tip_height = min(local_tip_height, network_tip_height);
                 sync_height = find_chain_split_height(shared, sync_peers, min_tip_height).await?;
                 info!(target: LOG_TARGET, "Chain split found at height {}.", sync_height);
             } else {
-                trace!(
+                debug!(
                     target: LOG_TARGET,
                     "Block hash {} is common between our chain and the network.",
                     local_block_hash.to_hex()
                 );
             }
 
-            info!(target: LOG_TARGET, "Synchronize missing blocks.");
             if let StatusInfo::BlockSync(ref mut info) = shared.info {
                 info.tip_height = Some(network_tip_height);
             }
@@ -443,16 +442,15 @@ async fn request_and_add_blocks<B: BlockchainBackend + 'static>(
                         block.header.height,
                         block_hash.to_hex()
                     );
-                    trace!(target: LOG_TARGET, "Block added to database: {}", block,);
                     block_nums.remove(0);
                 },
                 Err(CommsInterfaceError::ChainStorageError(ChainStorageError::InvalidBlock)) => {
                     warn!(
                         target: LOG_TARGET,
-                        "Invalid block {} received from peer. Retrying",
+                        "Invalid block {} received from peer.",
                         block_hash.to_hex(),
                     );
-                    warn!(
+                    debug!(
                         target: LOG_TARGET,
                         "Banning peer {} from local node, because they supplied invalid block", sync_peer
                     );
@@ -468,11 +466,11 @@ async fn request_and_add_blocks<B: BlockchainBackend + 'static>(
                 Err(CommsInterfaceError::ChainStorageError(ChainStorageError::ValidationError { source })) => {
                     warn!(
                         target: LOG_TARGET,
-                        "Validation on block {} from peer failed due to: {:?}. Retrying",
+                        "Validation on block {} from peer failed due to: {:?}.",
                         block_hash.to_hex(),
                         source,
                     );
-                    warn!(
+                    debug!(
                         target: LOG_TARGET,
                         "Banning peer {} from local node, because they supplied invalid block", sync_peer
                     );
@@ -491,7 +489,7 @@ async fn request_and_add_blocks<B: BlockchainBackend + 'static>(
         if block_nums.is_empty() {
             return Ok(());
         }
-        info!(target: LOG_TARGET, "Retrying block add. Attempt {}", attempt);
+        debug!(target: LOG_TARGET, "Retrying block add. Attempt {}", attempt);
     }
     Err(BlockSyncError::MaxAddBlockAttemptsReached)
 }
@@ -506,11 +504,9 @@ async fn request_blocks<B: BlockchainBackend + 'static>(
     let config = shared.config.block_sync_config;
     for attempt in 1..=config.max_block_request_retry_attempts {
         let sync_peer = select_sync_peer(&config, sync_peers)?;
-        trace!(
+        debug!(
             target: LOG_TARGET,
-            "Requesting blocks {:?} from {}.",
-            block_nums,
-            sync_peer
+            "Requesting blocks {:?} from {}.", block_nums, sync_peer
         );
         if let StatusInfo::BlockSync(ref mut info) = shared.info {
             info.local_height = Some(block_nums[0]);
@@ -533,7 +529,7 @@ async fn request_blocks<B: BlockchainBackend + 'static>(
                         return Ok((blocks, sync_peer));
                     } else {
                         debug!(target: LOG_TARGET, "This was NOT the blocks we were expecting.");
-                        warn!(
+                        debug!(
                             target: LOG_TARGET,
                             "Banning peer {} from local node, because they supplied the incorrect blocks", sync_peer
                         );
@@ -552,7 +548,7 @@ async fn request_blocks<B: BlockchainBackend + 'static>(
                         block_nums.len(),
                         hist_blocks.len()
                     );
-                    warn!(
+                    debug!(
                         target: LOG_TARGET,
                         "Banning peer {} from local node, because they supplied the incorrect number of blocks",
                         sync_peer
@@ -577,7 +573,7 @@ async fn request_blocks<B: BlockchainBackend + 'static>(
                 .await?;
             },
             Err(CommsInterfaceError::RequestTimedOut) => {
-                warn!(
+                debug!(
                     target: LOG_TARGET,
                     "Failed to fetch blocks from peer: {:?}. Retrying.",
                     CommsInterfaceError::RequestTimedOut,
@@ -621,7 +617,7 @@ async fn request_headers<B: BlockchainBackend + 'static>(
     let config = shared.config.block_sync_config;
     for attempt in 1..=config.max_header_request_retry_attempts {
         let sync_peer = select_sync_peer(&config, sync_peers)?;
-        trace!(target: LOG_TARGET, "Requesting headers from {}.", sync_peer);
+        debug!(target: LOG_TARGET, "Requesting headers from {}.", sync_peer);
         match shared
             .comms
             .request_headers_from_peer(block_nums.to_vec(), Some(sync_peer.clone()))
@@ -634,7 +630,7 @@ async fn request_headers<B: BlockchainBackend + 'static>(
                         return Ok((headers, sync_peer));
                     } else {
                         debug!(target: LOG_TARGET, "This was NOT the headers we were expecting.");
-                        warn!(
+                        debug!(
                             target: LOG_TARGET,
                             "Banning peer {} from local node, because they supplied the incorrect headers", sync_peer
                         );
@@ -653,7 +649,7 @@ async fn request_headers<B: BlockchainBackend + 'static>(
                         block_nums.len(),
                         headers.len()
                     );
-                    warn!(
+                    debug!(
                         target: LOG_TARGET,
                         "Banning peer {} from local node, because they supplied the incorrect number of headers",
                         sync_peer
@@ -669,7 +665,7 @@ async fn request_headers<B: BlockchainBackend + 'static>(
             },
             Err(CommsInterfaceError::UnexpectedApiResponse) => {
                 debug!(target: LOG_TARGET, "Remote node provided an unexpected api response.",);
-                warn!(
+                debug!(
                     target: LOG_TARGET,
                     "Banning peer {} from local node, because they provided an unexpected api response", sync_peer
                 );
@@ -682,7 +678,7 @@ async fn request_headers<B: BlockchainBackend + 'static>(
                 .await?;
             },
             Err(CommsInterfaceError::RequestTimedOut) => {
-                warn!(
+                debug!(
                     target: LOG_TARGET,
                     "Failed to fetch header from peer: {:?}. Retrying.",
                     CommsInterfaceError::RequestTimedOut,
@@ -750,7 +746,7 @@ async fn ban_sync_peer<B: BlockchainBackend + 'static>(
     ban_duration: Duration,
 ) -> Result<(), BlockSyncError>
 {
-    warn!(target: LOG_TARGET, "Banning peer {} from local node.", sync_peer);
+    info!(target: LOG_TARGET, "Banning peer {} from local node.", sync_peer);
     sync_peers.retain(|p| *p != sync_peer);
     shared.connectivity.ban_peer(sync_peer.clone(), ban_duration).await?;
     exclude_sync_peer(sync_peers, sync_peer).await