fix(ci): improve test output and test reliability (#5014)

* Rename a function to prepare_block_header_and_transaction_data_batch()

* Fix formatting of test command timeouts and child process output

* Put some #[cfg()]s in the standard Rust location

* Update some test timings

* Allow code timers to be ignored

zebra-chain/src/diagnostic.rs

@@ -66,6 +66,11 @@ impl CodeTimer {
         self.finish_inner(Some(module_path), Some(line), description);
     }
 
+    /// Ignore this timer: it will not check the elapsed time or log any warnings.
+    pub fn ignore(mut self) {
+        self.has_finished = true;
+    }
+
     /// Finish timing the execution of a function, method, or other code region.
     ///
     /// This private method can be called from [`CodeTimer::finish()`] or `drop()`.

zebra-state/src/service/finalized_state/zebra_db/block.rs

@@ -395,7 +395,7 @@ impl DiskWriteBatch {
 
         // Commit block and transaction data.
         // (Transaction indexes, note commitments, and UTXOs are committed later.)
-        self.prepare_block_header_transactions_batch(db, &finalized)?;
+        self.prepare_block_header_and_transaction_data_batch(db, &finalized)?;
 
         // # Consensus
         //
@@ -432,14 +432,14 @@ impl DiskWriteBatch {
         Ok(())
     }
 
-    /// Prepare a database batch containing the block header and transactions
+    /// Prepare a database batch containing the block header and transaction data
     /// from `finalized.block`, and return it (without actually writing anything).
     ///
     /// # Errors
     ///
     /// - This method does not currently return any errors.
     #[allow(clippy::unwrap_in_result)]
-    pub fn prepare_block_header_transactions_batch(
+    pub fn prepare_block_header_and_transaction_data_batch(
         &mut self,
         db: &DiskDb,
         finalized: &FinalizedBlock,

zebra-state/src/service/finalized_state/zebra_db/block/tests/vectors.rs

@@ -117,7 +117,7 @@ fn test_block_db_round_trip_with(
         // Skip validation by writing the block directly to the database
         let mut batch = DiskWriteBatch::new(Mainnet);
         batch
-            .prepare_block_header_transactions_batch(&state.db, &finalized)
+            .prepare_block_header_and_transaction_data_batch(&state.db, &finalized)
             .expect("block is valid for batch");
         state.db.write(batch).expect("block is valid for writing");
 

zebra-test/src/command.rs

@@ -537,7 +537,7 @@ impl<T> TestChild<T> {
         //
         // This checks for failure logs, and prevents some test hangs and deadlocks.
         if self.child.is_some() || self.stdout.is_some() {
-            let wrote_lines = self.wait_for_stdout_line("Child Stdout:".to_string());
+            let wrote_lines = self.wait_for_stdout_line("\nChild Stdout:".to_string());
 
             while self.wait_for_stdout_line(None) {}
 
@@ -548,7 +548,7 @@ impl<T> TestChild<T> {
         }
 
         if self.child.is_some() || self.stderr.is_some() {
-            let wrote_lines = self.wait_for_stderr_line("Child Stderr:".to_string());
+            let wrote_lines = self.wait_for_stderr_line("\nChild Stderr:".to_string());
 
             while self.wait_for_stderr_line(None) {}
 
@@ -854,10 +854,8 @@ impl<T> TestChild<T> {
             humantime::format_duration(self.timeout.expect("already checked past_deadline()"));
 
         let report = eyre!(
-            "{} of command did not log any matches for the given regex,\n\
+            "{stream_name} of command did not log any matches for the given regex,\n\
-             within the {:?} command timeout",
+             within the {timeout} command timeout",
-            stream_name,
-            timeout,
         )
         .with_section(|| format!("{:#?}", success_regexes.patterns()).header("Match Regex:"));
 

zebrad/tests/acceptance.rs

@@ -1909,9 +1909,9 @@ async fn delete_old_databases() -> Result<()> {
 /// See [`common::lightwalletd::send_transaction_test`] for more information.
 ///
 /// This test doesn't work on Windows, so it is always skipped on that platform.
-#[cfg(feature = "lightwalletd-grpc-tests")]
 #[tokio::test]
 #[ignore]
+#[cfg(feature = "lightwalletd-grpc-tests")]
 #[cfg(not(target_os = "windows"))]
 async fn sending_transactions_using_lightwalletd() -> Result<()> {
     common::lightwalletd::send_transaction_test::run().await
@@ -1922,9 +1922,9 @@ async fn sending_transactions_using_lightwalletd() -> Result<()> {
 /// See [`common::lightwalletd::wallet_grpc_test`] for more information.
 ///
 /// This test doesn't work on Windows, so it is always skipped on that platform.
-#[cfg(feature = "lightwalletd-grpc-tests")]
 #[tokio::test]
 #[ignore]
+#[cfg(feature = "lightwalletd-grpc-tests")]
 #[cfg(not(target_os = "windows"))]
 async fn lightwalletd_wallet_grpc_tests() -> Result<()> {
     common::lightwalletd::wallet_grpc_test::run().await

zebrad/tests/common/launch.rs

@@ -33,14 +33,17 @@ use crate::common::lightwalletd::{random_known_rpc_port_config, LightwalletdTest
 pub const LAUNCH_DELAY: Duration = Duration::from_secs(15);
 
 /// After we launch `lightwalletd`, wait this long for the command to start up,
-/// take the actions expected by the tests, and log the expected logs.
+/// take the actions expected by the quick tests, and log the expected logs.
 ///
 /// `lightwalletd`'s actions also depend on the actions of the `zebrad` instance
 /// it is using for its RPCs.
 pub const LIGHTWALLETD_DELAY: Duration = Duration::from_secs(60);
 
 /// The amount of time we wait between launching two conflicting nodes.
-pub const BETWEEN_NODES_DELAY: Duration = Duration::from_secs(2);
+///
+/// We use a longer time to make sure the first node has launched before the second starts,
+/// even if CI is under load.
+pub const BETWEEN_NODES_DELAY: Duration = Duration::from_secs(5);
 
 /// The amount of time we wait for lightwalletd to update to the tip.
 ///