Fix timing issues with version upgrades and other logs

zebrad/tests/acceptance.rs

@@ -1849,31 +1849,36 @@ fn lightwalletd_integration_test(test_type: TestType) -> Result<()> {
         zebrad.expect_stdout_line_matches("loaded Zebra state cache .*tip.*=.*None")?;
     }
 
-    // Wait for the state to upgrade, if the upgrade is short.
+    // Wait for the state to upgrade and the RPC port, if the upgrade is short.
+    //
     // If incompletely upgraded states get written to the CI cache,
     // change DATABASE_FORMAT_UPGRADE_IS_LONG to true.
-    //
-    // If this line hangs, move it after the lightwalletd launch.
-    if !DATABASE_FORMAT_UPGRADE_IS_LONG {
+    if test_type.launches_lightwalletd() && !DATABASE_FORMAT_UPGRADE_IS_LONG {
+        tracing::info!(
+            ?test_type,
+            ?zebra_rpc_address,
+            "waiting for zebrad to open its RPC port..."
+        );
+        wait_for_state_version_upgrade(
+            &mut zebrad,
+            &state_version_message,
+            database_format_version_in_code(),
+            [format!(
+                "Opened RPC endpoint at {}",
+                zebra_rpc_address.expect("lightwalletd test must have RPC port")
+            )],
+        )?;
+    } else {
         wait_for_state_version_upgrade(
             &mut zebrad,
             &state_version_message,
             database_format_version_in_code(),
+            None,
         )?;
     }
 
     // Launch lightwalletd, if needed
     let lightwalletd_and_port = if test_type.launches_lightwalletd() {
-        tracing::info!(
-            ?test_type,
-            ?zebra_rpc_address,
-            "waiting for zebrad to open its RPC port..."
-        );
-        zebrad.expect_stdout_line_matches(format!(
-            "Opened RPC endpoint at {}",
-            zebra_rpc_address.expect("lightwalletd test must have RPC port")
-        ))?;
-
         tracing::info!(
             ?zebra_rpc_address,
             "launching lightwalletd connected to zebrad",
@@ -1973,12 +1978,14 @@ fn lightwalletd_integration_test(test_type: TestType) -> Result<()> {
                 )?;
 
                 // Wait for the state to upgrade, if the upgrade is long.
-                // If this line hangs, change DATABASE_FORMAT_UPGRADE_IS_LONG to false.
+                // If this line hangs, change DATABASE_FORMAT_UPGRADE_IS_LONG to false,
+                // or combine "wait for sync" with "wait for state version upgrade".
                 if DATABASE_FORMAT_UPGRADE_IS_LONG {
                     wait_for_state_version_upgrade(
                         &mut zebrad,
                         &state_version_message,
                         database_format_version_in_code(),
+                        None,
                     )?;
                 }
 
@@ -2004,6 +2011,7 @@ fn lightwalletd_integration_test(test_type: TestType) -> Result<()> {
                     &mut zebrad,
                     &state_version_message,
                     database_format_version_in_code(),
+                    None,
                 )?;
             }
 
@@ -2730,30 +2738,18 @@ async fn fully_synced_rpc_z_getsubtreesbyindex_snapshot_test() -> Result<()> {
     // Store the state version message so we can wait for the upgrade later if needed.
     let state_version_message = wait_for_state_version_message(&mut zebrad)?;
 
-    // Wait for the state to upgrade, if the upgrade is short.
-    // If incompletely upgraded states get written to the CI cache,
-    // change DATABASE_FORMAT_UPGRADE_IS_LONG to true.
-    if !DATABASE_FORMAT_UPGRADE_IS_LONG {
-        wait_for_state_version_upgrade(
-            &mut zebrad,
-            &state_version_message,
-            database_format_version_in_code(),
-        )?;
-    }
+    // It doesn't matter how long the state version upgrade takes,
+    // because the sync finished regex is repeated every minute.
+    wait_for_state_version_upgrade(
+        &mut zebrad,
+        &state_version_message,
+        database_format_version_in_code(),
+        None,
+    )?;
 
     // Wait for zebrad to load the full cached blockchain.
     zebrad.expect_stdout_line_matches(SYNC_FINISHED_REGEX)?;
 
-    // Wait for the state to upgrade, if the upgrade is long.
-    // If this line hangs, change DATABASE_FORMAT_UPGRADE_IS_LONG to false.
-    if DATABASE_FORMAT_UPGRADE_IS_LONG {
-        wait_for_state_version_upgrade(
-            &mut zebrad,
-            &state_version_message,
-            database_format_version_in_code(),
-        )?;
-    }
-
     // Create an http client
     let client =
         RpcRequestClient::new(zebra_rpc_address.expect("already checked that address is valid"));

zebrad/tests/common/cached_state.rs

@@ -6,6 +6,7 @@
 #![allow(dead_code)]
 
 use std::{
+    iter,
     path::{Path, PathBuf},
     time::Duration,
 };
@@ -74,31 +75,41 @@ pub fn wait_for_state_version_message<T>(zebrad: &mut TestChild<T>) -> Result<St
 }
 
 /// Waits for the `required_version` state upgrade to complete, if needed.
+/// If `extra_required_log_regexes` are supplied, also waits for those logs before returning.
 ///
 /// This function should be called with the output of [`wait_for_state_version_message()`].
 #[tracing::instrument(skip(zebrad))]
 pub fn wait_for_state_version_upgrade<T>(
     zebrad: &mut TestChild<T>,
     state_version_message: &str,
     required_version: Version,
+    extra_required_log_regexes: impl IntoIterator<Item = String> + std::fmt::Debug,
 ) -> Result<()> {
     if state_version_message.contains("launching upgrade task") {
         tracing::info!(
             zebrad = ?zebrad.cmd,
             %state_version_message,
             %required_version,
+            ?extra_required_log_regexes,
             "waiting for zebrad state upgrade..."
         );
 
-        let upgrade_message = zebrad.expect_stdout_line_matches(&format!(
+        let upgrade_pattern = format!(
             "marked database format as upgraded.*format_upgrade_version.*=.*{required_version}"
-        ))?;
+        );
+        let extra_required_log_regexes = extra_required_log_regexes.into_iter();
+        let required_logs: Vec<String> = iter::once(upgrade_pattern)
+            .chain(extra_required_log_regexes)
+            .collect();
+
+        let upgrade_messages = zebrad.expect_stdout_line_matches_all_unordered(&required_logs)?;
 
         tracing::info!(
             zebrad = ?zebrad.cmd,
             %state_version_message,
             %required_version,
-            %upgrade_message,
+            ?required_logs,
+            ?upgrade_messages,
             "zebrad state has been upgraded"
         );
     }

zebrad/tests/common/checkpoints.rs

@@ -87,12 +87,19 @@ pub async fn run(network: Network) -> Result<()> {
 
         // Before we write a cached state image, wait for a database upgrade.
         //
+        // It is ok if the logs are in the wrong order and the test sometimes fails,
+        // because testnet is unreliable anyway.
+        //
         // TODO: this line will hang if the state upgrade is slower than the RPC server spawn.
         // But that is unlikely, because both 25.1 and 25.2 are quick on testnet.
+        //
+        // TODO: combine this check with the CHECKPOINT_VERIFIER_REGEX and RPC endpoint checks.
+        // This is tricky because we need to get the last checkpoint log.
         wait_for_state_version_upgrade(
             &mut zebrad,
             &state_version_message,
             database_format_version_in_code(),
+            None,
         )?;
     }
 
@@ -105,6 +112,7 @@ pub async fn run(network: Network) -> Result<()> {
     );
 
     let last_checkpoint = zebrad.expect_stdout_line_matches(CHECKPOINT_VERIFIER_REGEX)?;
+
     // TODO: do this with a regex?
     let (_prefix, last_checkpoint) = last_checkpoint
         .split_once("max_checkpoint_height")

zebrad/tests/common/lightwalletd/wallet_grpc_test.rs

@@ -110,7 +110,6 @@ pub async fn run() -> Result<()> {
         ?zebra_rpc_address,
         "launched zebrad, waiting for zebrad to open its RPC port..."
     );
-    zebrad.expect_stdout_line_matches(&format!("Opened RPC endpoint at {zebra_rpc_address}"))?;
 
     // Wait for the state to upgrade, if the upgrade is short.
     //
@@ -124,6 +123,7 @@ pub async fn run() -> Result<()> {
             &mut zebrad,
             &state_version_message,
             database_format_version_in_code(),
+            [format!("Opened RPC endpoint at {zebra_rpc_address}")],
         )?;
     }
 
@@ -160,6 +160,7 @@ pub async fn run() -> Result<()> {
             &mut zebrad,
             &state_version_message,
             database_format_version_in_code(),
+            None,
         )?;
     }