Improve zebra-consensus logging and metrics (#989)

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()

zebra-consensus/src/chain.rs

@@ -111,12 +111,9 @@ where
 
     fn call(&mut self, block: Arc<Block>) -> Self::Future {
         // TODO(jlusby): Error = Report, handle errors from state_service.
-        let span = tracing::debug_span!(
+        let height = block.coinbase_height();
-            "block_verify",
+        let hash = block.hash();
-            height = ?block.coinbase_height(),
+        let span = tracing::debug_span!("block_verify", ?height, ?hash,);
-            hash = ?block.hash()
-        );
-        let block_height = block.coinbase_height();
 
         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) {
+        let is_unexpected_high_block = match (height, self.last_block_height) {
-            (Some(block::Height(block_height)), Some(block::Height(last_block_height)))
+            (Some(block::Height(height)), Some(block::Height(last_block_height)))
-                if (block_height > last_block_height + MAX_EXPECTED_BLOCK_GAP) =>
+                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), _) => {
+            (Some(height), _) => {
-                self.last_block_height = Some(block_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?

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.