From ddc7a47e3945cbe3d8860d0aead3c9402131dbd3 Mon Sep 17 00:00:00 2001 From: Giacomo Pasini Date: Thu, 5 Aug 2021 18:23:43 +0200 Subject: [PATCH] improve logs spans --- jormungandr/src/blockchain/process.rs | 127 +++++++++++++------------- 1 file changed, 62 insertions(+), 65 deletions(-) diff --git a/jormungandr/src/blockchain/process.rs b/jormungandr/src/blockchain/process.rs index c09373a26d..a9446f2907 100644 --- a/jormungandr/src/blockchain/process.rs +++ b/jormungandr/src/blockchain/process.rs @@ -31,6 +31,9 @@ type GetNextBlockScheduler = FireForgetScheduler; const TIP_UPDATE_QUEUE_SIZE: usize = 5; +// it's a bit unnecessary to display the whole hash in logs +const HASH_LOG_LENGTH: usize = 7; + const DEFAULT_TIMEOUT_PROCESS_LEADERSHIP: u64 = 5; const DEFAULT_TIMEOUT_PROCESS_ANNOUNCEMENT: u64 = 5; const DEFAULT_TIMEOUT_PROCESS_BLOCKS: u64 = 60; @@ -208,8 +211,8 @@ impl Process { parent: self.service_info.span(), Level::DEBUG, "process_leadership_block", - hash = %leadership_block.block.header.hash().to_string(), - parent = %leadership_block.block.header.parent_id().to_string(), + hash = %leadership_block.block.header.description(), + parent = %leadership_block.block.header.parent_id().to_string()[..HASH_LOG_LENGTH], date = %leadership_block.block.header.block_date().to_string() ); let _enter = span.enter(); @@ -233,8 +236,8 @@ impl Process { parent: self.service_info.span(), Level::DEBUG, "process_announced_block", - hash = %header.hash().to_string(), - parent = %header.parent_id().to_string(), + hash = %header.description(), + parent = %header.parent_id().to_string()[..HASH_LOG_LENGTH], date = %header.block_date().to_string(), peer = %node_id.to_string() ); @@ -322,22 +325,29 @@ async fn process_and_propagate_new_ref( mut network_msg_box: MessageBox, ) -> chain::Result<()> { let header = new_block_ref.header().clone(); - tracing::debug!("processing the new block and propagating"); - // Even if this fails because the queue is full we periodically recompute the tip - tip_update_mbox - .try_send(new_block_ref) - .unwrap_or_else(|err| { - tracing::error!( - "cannot send new ref to be evaluated as candidate tip: {}", - err - ) - }); + let span = span!(Level::DEBUG, "process_and_propagate_new_ref", block = %header.description()); + + async { + tracing::debug!("processing the new block and propagating"); + // Even if this fails because the queue is full we periodically recompute the tip + tip_update_mbox + .try_send(new_block_ref) + .unwrap_or_else(|err| { + tracing::error!( + "cannot send new ref to be evaluated as candidate tip: {}", + err + ) + }); - tracing::debug!("propagating block to the network"); + tracing::debug!("propagating block to the network"); - network_msg_box - .send(NetworkMsg::Propagate(PropagateMsg::Block(header))) - .await?; + network_msg_box + .send(NetworkMsg::Propagate(PropagateMsg::Block(header))) + .await?; + Ok::<(), Error>(()) + } + .instrument(span) + .await?; Ok(()) } @@ -492,38 +502,41 @@ async fn process_network_block( explorer_msg_box: Option<&mut MessageBox>, get_next_block_scheduler: &mut GetNextBlockScheduler, ) -> Result>, chain::Error> { - get_next_block_scheduler - .declare_completed(block.id()) - .unwrap_or_else( - |e| tracing::error!(reason = ?e, "get next block schedule completion failed"), - ); let header = block.header(); - let pre_checked = blockchain.pre_check_header(header, false).await?; - match pre_checked { - PreCheckedHeader::AlreadyPresent { header, .. } => { - tracing::debug!( - hash = %header.hash(), - parent = %header.parent_id(), - date = %header.block_date(), - "block is already present" - ); - Ok(None) - } - PreCheckedHeader::MissingParent { header, .. } => { - let parent_hash = header.parent_id(); - tracing::debug!( - hash = %header.hash(), - parent = %parent_hash, - date = %header.block_date(), - "block is missing a locally stored parent" + let span = tracing::span!( + Level::DEBUG, + "network_block", + block = %header.description(), + parent = %header.parent_id().to_string()[..HASH_LOG_LENGTH], + date = %header.block_date(), + ); + + async { + get_next_block_scheduler + .declare_completed(block.id()) + .unwrap_or_else( + |e| tracing::error!(reason = ?e, "get next block schedule completion failed"), ); - Err(Error::MissingParentBlock(parent_hash)) - } - PreCheckedHeader::HeaderWithCache { parent_ref, .. } => { - let r = check_and_apply_block(blockchain, parent_ref, block, explorer_msg_box).await; - r + let pre_checked = blockchain.pre_check_header(header, false).await?; + match pre_checked { + PreCheckedHeader::AlreadyPresent { .. } => { + tracing::debug!("block is already present"); + Ok(None) + } + PreCheckedHeader::MissingParent { header } => { + let parent_hash = header.parent_id(); + tracing::debug!("block is missing a locally stored parent"); + Err(Error::MissingParentBlock(parent_hash)) + } + PreCheckedHeader::HeaderWithCache { parent_ref, .. } => { + let r = + check_and_apply_block(blockchain, parent_ref, block, explorer_msg_box).await; + r + } } } + .instrument(span) + .await } async fn check_and_apply_block( @@ -536,14 +549,7 @@ async fn check_and_apply_block( let post_checked = blockchain .post_check_header(block.header(), parent_ref, CheckHeaderProof::Enabled) .await?; - let header = post_checked.header(); - let block_hash = header.hash(); - tracing::debug!( - hash = %block_hash, - parent = %header.parent_id(), - date = %header.block_date(), - "applying block to storage" - ); + tracing::debug!("applying block to storage"); let mut block_for_explorer = if explorer_enabled { Some(block.clone()) } else { @@ -553,13 +559,7 @@ async fn check_and_apply_block( .apply_and_store_block(post_checked, block) .await?; if let AppliedBlock::New(block_ref) = applied_block { - let header = block_ref.header(); - tracing::debug!( - hash = %block_hash, - parent = %header.parent_id(), - date = %header.block_date(), - "applied block to storage" - ); + tracing::debug!("applied block to storage"); if let Some(msg_box) = explorer_msg_box { msg_box .try_send(ExplorerMsg::NewBlock(block_for_explorer.take().unwrap())) @@ -567,10 +567,7 @@ async fn check_and_apply_block( } Ok(Some(block_ref)) } else { - tracing::debug!( - hash = %block_hash, - "block is already present in storage, not applied" - ); + tracing::debug!("block is already present in storage, not applied"); Ok(None) } }