From 52002ac3c550753e6019f41d8bb36747115b2bcb Mon Sep 17 00:00:00 2001 From: teor Date: Tue, 21 Jul 2020 23:02:20 +1000 Subject: [PATCH] feature: Add tracing to chain and checkpoint verifiers --- zebra-consensus/src/chain.rs | 48 +++++++++++++++++++++++--- zebra-consensus/src/checkpoint.rs | 57 ++++++++++++++++++++++++++++++- 2 files changed, 99 insertions(+), 6 deletions(-) diff --git a/zebra-consensus/src/chain.rs b/zebra-consensus/src/chain.rs index c1af6ffa..de84c8b9 100644 --- a/zebra-consensus/src/chain.rs +++ b/zebra-consensus/src/chain.rs @@ -80,33 +80,64 @@ where let mut state_service = self.state_service.clone(); let max_checkpoint_height = self.max_checkpoint_height; + let height = block.coinbase_height(); + // Report each 1000th block at info level + let info_log = match height { + Some(BlockHeight(height)) if (height % 1000 == 0) => true, + _ => false, + }; + + if info_log { + tracing::info!(?height, "ChainVerifier received block"); + } else { + tracing::debug!(?height, "ChainVerifier received block"); + } + async move { - // Call a verifier based on the block height and checkpoints - // // TODO(teor): for post-sapling checkpoint blocks, allow callers // to use BlockVerifier, CheckpointVerifier, or both. - match block.coinbase_height() { + + // Call a verifier based on the block height and checkpoints. + let hash = match height { Some(height) if (height <= max_checkpoint_height) => { + if info_log { + tracing::info!(?height, "sending block to CheckpointVerifier"); + } else { + tracing::debug!(?height, "sending block to CheckpointVerifier"); + } checkpoint_verifier .ready_and() .await? .call(block.clone()) .await? } - Some(_) => { + Some(height) => { + if info_log { + tracing::info!(?height, "sending block to BlockVerifier"); + } else { + tracing::debug!(?height, "sending block to BlockVerifier"); + } block_verifier .ready_and() .await? .call(block.clone()) .await? } - None => return Err("Invalid block: must have a coinbase height".into()), + None => { + tracing::debug!("rejecting block with no coinbase height"); + return Err("Invalid block: must have a coinbase height".into()); + } }; // TODO(teor): // - handle chain reorgs // - adjust state_service "unique block height" conditions + if info_log { + tracing::info!(?height, ?hash, "ChainVerifier sent block to state"); + } else { + tracing::debug!(?height, ?hash, "ChainVerifier sent block to state"); + } // `Tower::Buffer` requires a 1:1 relationship between `poll()`s // and `call()`s, because it reserves a buffer slot in each // `call()`. @@ -153,6 +184,8 @@ where + 'static, S::Future: Send + 'static, { + tracing::debug!(?network, "initialising ChainVerifier from network"); + let block_verifier = crate::block::init(state_service.clone()); let checkpoint_verifier = CheckpointVerifier::new(network); @@ -197,6 +230,11 @@ where S::Future: Send + 'static, { let max_checkpoint_height = checkpoint_verifier.list().max_height(); + tracing::debug!( + ?max_checkpoint_height, + "initialising ChainVerifier with max checkpoint height" + ); + // Wrap the checkpoint verifier in a buffer, so we can share it let checkpoint_verifier = Buffer::new(checkpoint_verifier, 1); diff --git a/zebra-consensus/src/checkpoint.rs b/zebra-consensus/src/checkpoint.rs index d4859656..2c0aab6a 100644 --- a/zebra-consensus/src/checkpoint.rs +++ b/zebra-consensus/src/checkpoint.rs @@ -118,7 +118,10 @@ impl CheckpointVerifier { /// Clone a CheckpointVerifier, you might need to wrap it in a /// `tower::Buffer` service. pub fn new(network: Network) -> Self { - Self::from_checkpoint_list(CheckpointList::new(network)) + let checkpoint_list = CheckpointList::new(network); + let max_height = checkpoint_list.max_height(); + tracing::info!(?max_height, ?network, "initialising CheckpointVerifier"); + Self::from_checkpoint_list(checkpoint_list) } /// Return a checkpoint verification service using `list`. @@ -328,10 +331,27 @@ impl CheckpointVerifier { // Set up a oneshot channel to send results let (tx, rx) = oneshot::channel(); + let height = block.coinbase_height(); + // Report each 1000th block at info level + let info_log = match height { + Some(BlockHeight(height)) if (height % 1000 == 0) => true, + _ => false, + }; + if info_log { + tracing::info!(?height, "queue_block received block"); + } else { + tracing::debug!(?height, "queue_block received block"); + } + // Check for a valid height let height = match self.check_block(&block) { Ok(height) => height, Err(error) => { + tracing::warn!( + ?height, + ?error, + "queue_block rejected block with block height error" + ); // Sending might fail, depending on what the caller does with rx, // but there's nothing we can do about it. let _ = tx.send(Err(error)); @@ -349,6 +369,10 @@ impl CheckpointVerifier { // Memory DoS resistance: limit the queued blocks at each height if qblocks.len() >= MAX_QUEUED_BLOCKS_PER_HEIGHT { + tracing::warn!( + ?height, + "queue_block rejected block with too many blocks at height error" + ); let _ = tx.send(Err("too many queued blocks at this height".into())); return rx; } @@ -360,6 +384,12 @@ impl CheckpointVerifier { qblocks.reserve_exact(1); qblocks.push(new_qblock); + if info_log { + tracing::info!(?height, "queue_block added block to queue"); + } else { + tracing::debug!(?height, "queue_block added block to queue"); + } + rx } @@ -615,10 +645,29 @@ impl Service> for CheckpointVerifier { fn call(&mut self, block: Arc) -> Self::Future { // TODO(jlusby): Error = Report + let height = block.coinbase_height(); + // Report each 1000th block at info level + let info_log = match height { + Some(BlockHeight(height)) if (height % 1000 == 0) => true, + _ => false, + }; + + if info_log { + tracing::info!(?height, "CheckpointVerifier received block"); + } else { + tracing::debug!(?height, "CheckpointVerifier received block"); + } + // Queue the block for verification, until we receive all the blocks for // the current checkpoint range. let rx = self.queue_block(block); + if info_log { + tracing::info!(?height, "CheckpointVerifier added block to queue"); + } else { + tracing::debug!(?height, "CheckpointVerifier added block to queue"); + } + // Try to verify from the previous checkpoint to a target checkpoint. // // If there are multiple checkpoints in the target range, and one of @@ -629,6 +678,12 @@ impl Service> for CheckpointVerifier { // TODO(teor): retry on failure (low priority, failures should be rare) self.process_checkpoint_range(); + if info_log { + tracing::info!(?height, "CheckpointVerifier processed checkpoint range"); + } else { + tracing::debug!(?height, "CheckpointVerifier processed checkpoint range"); + } + async move { // Remove the Result<..., RecvError> wrapper from the channel future rx.await