Use the block verifier and non-finalized state in the cached state tests (#2463)

* Use the block verifier and non-finalized state in the cached state tests

This substantially increases test coverage.

Previously, the cached state tests were configured with
`checkpoint_sync = true`, which only uses the checkpoint
verifier and the finalized state.

* Log the source of blocks in commit_finalized_direct

This lets us check that we're actually testing the non-finalized state
and block verifier in the cached state tests.

It also improves diagnostics for state errors.

* Fail cached state tests if they're using incorrect heights or configs

This makes sure that the cached state tests actually test the transition
from checkpoint to block verification, and the non-finalized state.

zebra-state/src/service.rs

@@ -158,7 +158,7 @@ impl StateService {
             tracing::trace!("finalizing block past the reorg limit");
             let finalized = self.mem.finalize();
             self.disk
-                .commit_finalized_direct(finalized)
+                .commit_finalized_direct(finalized, "best non-finalized chain root")
                 .expect("expected that disk errors would not occur");
         }
 

zebra-state/src/service/finalized_state.rs

@@ -177,9 +177,12 @@ impl FinalizedState {
     }
 
     /// Immediately commit `finalized` to the finalized state.
+    ///
+    /// Use `source` as the source of the block in log messages.
     pub fn commit_finalized_direct(
         &mut self,
         finalized: FinalizedBlock,
+        source: &str,
     ) -> Result<block::Hash, BoxError> {
         block_precommit_metrics(&finalized);
 
@@ -204,12 +207,14 @@ impl FinalizedState {
         if self.is_empty(hash_by_height) {
             assert_eq!(
                 GENESIS_PREVIOUS_BLOCK_HASH, block.header.previous_block_hash,
-                "the first block added to an empty state must be a genesis block"
+                "the first block added to an empty state must be a genesis block, source: {}",
+                source,
             );
             assert_eq!(
                 block::Height(0),
                 height,
-                "cannot commit genesis: invalid height"
+                "cannot commit genesis: invalid height, source: {}",
+                source,
             );
         } else {
             assert_eq!(
@@ -217,13 +222,15 @@ impl FinalizedState {
                     .expect("state must have a genesis block committed")
                     + 1,
                 Some(height),
-                "committed block height must be 1 more than the finalized tip height"
+                "committed block height must be 1 more than the finalized tip height, source: {}",
+                source,
             );
 
             assert_eq!(
                 self.finalized_tip_hash(),
                 block.header.previous_block_hash,
-                "committed block must be a child of the finalized tip"
+                "committed block must be a child of the finalized tip, source: {}",
+                source,
             );
         }
 
@@ -297,7 +304,10 @@ impl FinalizedState {
 
         let result = self.db.write(batch).map(|()| hash);
 
+        tracing::trace!(?source, "committed block from");
+
         if result.is_ok() && self.is_at_stop_height(height) {
+            tracing::info!(?source, "committed block from");
             tracing::info!(?height, ?hash, "stopping at configured height");
             // We'd like to drop the database here, because that closes the
             // column families and the database. But Rust's ownership rules
@@ -318,7 +328,7 @@ impl FinalizedState {
     /// [`FinalizedState`].
     fn commit_finalized(&mut self, queued_block: QueuedFinalized) {
         let (finalized, rsp_tx) = queued_block;
-        let result = self.commit_finalized_direct(finalized);
+        let result = self.commit_finalized_direct(finalized, "CommitFinalized request");
         let _ = rsp_tx.send(result.map_err(Into::into));
     }
 

zebra-state/src/service/finalized_state/tests/prop.rs

@@ -25,7 +25,10 @@ fn blocks_with_v5_transactions() -> Result<()> {
             let mut height = Height(0);
             // use `count` to minimize test failures, so they are easier to diagnose
             for block in chain.iter().take(count) {
-                let hash = state.commit_finalized_direct(FinalizedBlock::from(block.clone()));
+                let hash = state.commit_finalized_direct(
+                    FinalizedBlock::from(block.clone()),
+                    "blocks_with_v5_transactions test"
+                );
                 prop_assert_eq!(Some(height), state.finalized_tip_height());
                 prop_assert_eq!(hash.unwrap(), block.hash);
                 // TODO: check that the nullifiers were correctly inserted (#2230)

zebrad/tests/acceptance.rs

@@ -858,12 +858,26 @@ fn sync_until(
 
 fn cached_mandatory_checkpoint_test_config() -> Result<ZebradConfig> {
     let mut config = persistent_test_config()?;
-    config.consensus.checkpoint_sync = true;
     config.state.cache_dir = "/zebrad-cache".into();
     Ok(config)
 }
 
-fn create_cached_database_height(network: Network, height: Height) -> Result<()> {
+/// Create or update a cached state for `network`, stopping at `height`.
+///
+/// Callers can supply an extra `test_child_predicate`, which is called on
+/// the `TestChild` between the startup checks, and the final
+/// `STOP_AT_HEIGHT_REGEX` check.
+///
+/// The `TestChild` is spawned with a timeout, so the predicate should use
+/// `expect_stdout_line_matches` or `expect_stderr_line_matches`.
+fn create_cached_database_height<P>(
+    network: Network,
+    height: Height,
+    test_child_predicate: impl Into<Option<P>>,
+) -> Result<()>
+where
+    P: FnOnce(&mut TestChild<PathBuf>) -> Result<()>,
+{
     println!("Creating cached database");
     // 8 hours
     let timeout = Duration::from_secs(60 * 60 * 8);
@@ -887,6 +901,10 @@ fn create_cached_database_height(network: Network, height: Height) -> Result<()>
     child.expect_stdout_line_matches("starting legacy chain check")?;
     child.expect_stdout_line_matches("no legacy chain found")?;
 
+    if let Some(test_child_predicate) = test_child_predicate.into() {
+        test_child_predicate(&mut child)?;
+    }
+
     child.expect_stdout_line_matches(STOP_AT_HEIGHT_REGEX)?;
 
     child.kill()?;
@@ -896,12 +914,25 @@ fn create_cached_database_height(network: Network, height: Height) -> Result<()>
 
 fn create_cached_database(network: Network) -> Result<()> {
     let height = network.mandatory_checkpoint_height();
-    create_cached_database_height(network, height)
+    create_cached_database_height(network, height, |test_child: &mut TestChild<PathBuf>| {
+        // make sure pre-cached databases finish before the mandatory checkpoint
+        test_child.expect_stdout_line_matches("CommitFinalized request")?;
+        Ok(())
+    })
 }
 
 fn sync_past_mandatory_checkpoint(network: Network) -> Result<()> {
     let height = network.mandatory_checkpoint_height() + 1200;
-    create_cached_database_height(network, height.unwrap())
+    create_cached_database_height(
+        network,
+        height.unwrap(),
+        |test_child: &mut TestChild<PathBuf>| {
+            // make sure cached database tests finish after the mandatory checkpoint,
+            // using the non-finalized state (the checkpoint_sync config must be false)
+            test_child.expect_stdout_line_matches("best non-finalized chain root")?;
+            Ok(())
+        },
+    )
 }
 
 // These tests are ignored because they're too long running to run during our