Skip to content

Commit

Permalink
improve logs spans
Browse files Browse the repository at this point in the history
  • Loading branch information
@zeegomo
zeegomo committed Sep 24, 2021
1 parent 2846e1d commit ddc7a47
Showing 1 changed file with 62 additions and 65 deletions.
127 changes: 62 additions & 65 deletions jormungandr/src/blockchain/process.rs
View file
Expand Up @@ -31,6 +31,9 @@ type GetNextBlockScheduler = FireForgetScheduler<HeaderHash, Address, ()>;

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;
Expand Down Expand Up @@ -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();
Expand All @@ -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()
);
Expand Down Expand Up @@ -322,22 +325,29 @@ async fn process_and_propagate_new_ref(
mut network_msg_box: MessageBox<NetworkMsg>,
) -> 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(())
}
Expand Down Expand Up @@ -492,38 +502,41 @@ async fn process_network_block(
explorer_msg_box: Option<&mut MessageBox<ExplorerMsg>>,
get_next_block_scheduler: &mut GetNextBlockScheduler,
) -> Result<Option<Arc<Ref>>, 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(
Expand All @@ -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 {
Expand All @@ -553,24 +559,15 @@ 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()))
.unwrap_or_else(|err| tracing::error!("cannot add block to explorer: {}", err));
}
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)
}
}
Expand Down

0 comments on commit ddc7a47

Please sign in to comment.