From 8a4245daab49ba79e097baa721097e92e306674b Mon Sep 17 00:00:00 2001 From: teor Date: Fri, 4 Sep 2020 08:06:21 +1000 Subject: [PATCH] Improve zebra-consensus logging and metrics (#989) --- zebra-consensus/src/block.rs | 21 +++++++++++++++++--- zebra-consensus/src/chain.rs | 32 +++++++++++++++++-------------- zebra-consensus/src/checkpoint.rs | 28 +++++++++++++++++++++------ 3 files changed, 58 insertions(+), 23 deletions(-) diff --git a/zebra-consensus/src/block.rs b/zebra-consensus/src/block.rs index 6e440865..992204d7 100644 --- a/zebra-consensus/src/block.rs +++ b/zebra-consensus/src/block.rs @@ -123,20 +123,35 @@ where // Skip contextual checks for the genesis block let previous_block_hash = block.header.previous_block_hash; if previous_block_hash != crate::parameters::GENESIS_PREVIOUS_BLOCK_HASH { - tracing::debug!(?height, "Awaiting previous block from state"); + if height == block::Height(0) { + Err("Invalid block: height is 0, but previous block hash is not null.")?; + } + + let expected_height = block::Height(height.0 - 1); + tracing::trace!(?expected_height, ?previous_block_hash, "Waiting for previous block"); + metrics::gauge!("block.waiting.block.height", expected_height.0 as i64); + metrics::counter!("block.waiting.count", 1); + let previous_block = BlockVerifier::await_block( &mut state, previous_block_hash, - block::Height(height.0 - 1), + expected_height, ) .await?; let previous_height = previous_block.coinbase_height().unwrap(); - if height.0 != previous_height.0 + 1 { + if previous_height != expected_height { Err("Invalid block height: must be 1 more than the previous block height.")?; } } + tracing::trace!(?height, ?hash, "Verified block"); + metrics::gauge!( + "block.verified.block.height", + height.0 as _ + ); + metrics::counter!("block.verified.block.count", 1); + Ok(hash) } .boxed() diff --git a/zebra-consensus/src/chain.rs b/zebra-consensus/src/chain.rs index 3e4a6587..4d18e966 100644 --- a/zebra-consensus/src/chain.rs +++ b/zebra-consensus/src/chain.rs @@ -111,12 +111,9 @@ where fn call(&mut self, block: Arc) -> Self::Future { // TODO(jlusby): Error = Report, handle errors from state_service. - let span = tracing::debug_span!( - "block_verify", - height = ?block.coinbase_height(), - hash = ?block.hash() - ); - let block_height = block.coinbase_height(); + let height = block.coinbase_height(); + let hash = block.hash(); + let span = tracing::debug_span!("block_verify", ?height, ?hash,); let mut block_verifier = self.block_verifier.clone(); let mut state_service = self.state_service.clone(); @@ -124,15 +121,15 @@ where let max_checkpoint_height = self.checkpoint.clone().map(|c| c.max_height); // Log an info-level message on unexpected high blocks - let is_unexpected_high_block = match (block_height, self.last_block_height) { - (Some(block::Height(block_height)), Some(block::Height(last_block_height))) - if (block_height > last_block_height + MAX_EXPECTED_BLOCK_GAP) => + let is_unexpected_high_block = match (height, self.last_block_height) { + (Some(block::Height(height)), Some(block::Height(last_block_height))) + if (height > last_block_height + MAX_EXPECTED_BLOCK_GAP) => { - self.last_block_height = Some(block::Height(block_height)); + self.last_block_height = Some(block::Height(height)); true } - (Some(block_height), _) => { - self.last_block_height = Some(block_height); + (Some(height), _) => { + self.last_block_height = Some(height); false } // The other cases are covered by the verifiers @@ -144,7 +141,7 @@ where // to use BlockVerifier, CheckpointVerifier, or both. // Call a verifier based on the block height and checkpoints. - if is_higher_than_max_checkpoint(block_height, max_checkpoint_height) { + if is_higher_than_max_checkpoint(height, max_checkpoint_height) { // Log a message on early high blocks. // The sync service rejects most of these blocks, but we // still want to know if a large number get through. @@ -153,7 +150,7 @@ where // low blocks. (We can't distinguish between these cases, until // we've verified the blocks.) if is_unexpected_high_block { - tracing::debug!(?block_height, "unexpected high block, or recent unexpected low blocks"); + tracing::debug!(?height, "unexpected high block, or recent unexpected low blocks"); } block_verifier @@ -170,6 +167,13 @@ where .await?; } + tracing::trace!(?height, ?hash, "Verified block"); + metrics::gauge!( + "chain.verified.block.height", + height.expect("Valid blocks have a block height").0 as _ + ); + metrics::counter!("chain.verified.block.count", 1); + let add_block = state_service .ready_and() .await? diff --git a/zebra-consensus/src/checkpoint.rs b/zebra-consensus/src/checkpoint.rs index 59b12390..9a65d122 100644 --- a/zebra-consensus/src/checkpoint.rs +++ b/zebra-consensus/src/checkpoint.rs @@ -180,6 +180,7 @@ impl CheckpointVerifier { if initial_height >= checkpoint_list.max_height() { (None, Progress::FinalCheckpoint) } else { + metrics::gauge!("checkpoint.previous.height", initial_height.0 as i64); ( Some(initial_tip.hash()), Progress::InitialTip(initial_height), @@ -243,6 +244,8 @@ impl CheckpointVerifier { let mut pending_height = match self.previous_checkpoint_height() { // Check if we have the genesis block as a special case, to simplify the loop BeforeGenesis if !self.queued.contains_key(&block::Height(0)) => { + tracing::trace!("Waiting for genesis block"); + metrics::counter!("checkpoint.waiting.count", 1); return WaitingForBlocks; } BeforeGenesis => block::Height(0), @@ -288,12 +291,18 @@ impl CheckpointVerifier { .checkpoint_list .max_height_in_range((start, Included(pending_height))); - tracing::debug!( + tracing::trace!( checkpoint_start = ?start, highest_contiguous_block = ?pending_height, ?target_checkpoint ); + if let Some(block::Height(target_checkpoint)) = target_checkpoint { + metrics::gauge!("checkpoint.target.height", target_checkpoint as i64); + } else { + metrics::counter!("checkpoint.waiting.count", 1); + } + target_checkpoint .map(Checkpoint) .unwrap_or(WaitingForBlocks) @@ -366,8 +375,10 @@ impl CheckpointVerifier { // Ignore heights that aren't checkpoint heights if verified_height == self.checkpoint_list.max_height() { + metrics::gauge!("checkpoint.previous.height", verified_height.0 as i64); self.verifier_progress = FinalCheckpoint; } else if self.checkpoint_list.contains(verified_height) { + metrics::gauge!("checkpoint.previous.height", verified_height.0 as i64); self.verifier_progress = PreviousCheckpoint(verified_height); // We're done with the initial tip hash now self.initial_tip_hash = None; @@ -403,7 +414,7 @@ impl CheckpointVerifier { Ok(height) => height, Err(error) => { // Block errors happen frequently on mainnet, due to bad peers. - tracing::debug!(?error); + tracing::trace!(?error); // Sending might fail, depending on what the caller does with rx, // but there's nothing we can do about it. @@ -426,7 +437,7 @@ impl CheckpointVerifier { if qb.hash == hash { let old_tx = std::mem::replace(&mut qb.tx, tx); let e = "rejected older of duplicate verification requests".into(); - tracing::debug!(?e); + tracing::trace!(?e); let _ = old_tx.send(Err(e)); return rx; } @@ -447,7 +458,7 @@ impl CheckpointVerifier { qblocks.push(new_qblock); let is_checkpoint = self.checkpoint_list.contains(height); - tracing::debug!(?height, ?hash, ?is_checkpoint, "Queued block"); + tracing::trace!(?height, ?hash, ?is_checkpoint, "Queued block"); // TODO(teor): // - Remove this log once the CheckpointVerifier is working? @@ -555,7 +566,6 @@ impl CheckpointVerifier { .expect("every checkpoint height must have a hash"), ), WaitingForBlocks => { - tracing::debug!("waiting for blocks to complete checkpoint range"); return; } FinishedVerifying => { @@ -642,7 +652,13 @@ impl CheckpointVerifier { "the previous checkpoint should match: bad checkpoint list, zebra bug, or bad chain" ); - tracing::info!(?current_range, "Verified checkpoint range"); + let block_count = rev_valid_blocks.len(); + tracing::info!(?block_count, ?current_range, "Verified checkpoint range"); + metrics::gauge!( + "checkpoint.verified.block.height", + target_checkpoint_height.0 as _ + ); + metrics::counter!("checkpoint.verified.block.count", block_count as _); // All the blocks we've kept are valid, so let's verify them // in height order.