fix(ci): Improve Zebra acceptance test diagnostics (#4958)

* Show the arguments of acceptance test functions in the logs

* Show all the logs in the "Run tests" jobs

* Document expected "broken pipe" error from `tee`

Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com>

.github/workflows/deploy-gcp-tests.yml

@@ -546,6 +546,9 @@ jobs:
       # following until Sapling activation (or the test finishes).
       #
       # The log pipeline ignores the exit status of `docker logs`.
+      # It also ignores the expected 'broken pipe' error from `tee`,
+      # which happens when `grep` finds a matching output and moves on to the next job.
+      #
       # Errors in the tests are caught by the final test status job.
       - name: Show logs for ${{ inputs.test_id }} test (sprout)
         run: |
@@ -919,7 +922,7 @@ jobs:
           "
 
 
-  # check the results of the test
+  # check the results of the test, and show all of the test logs
   test-result:
     # TODO: update the job name here, and in the branch protection rules
     name: Run ${{ inputs.test_id }} test
@@ -959,7 +962,7 @@ jobs:
 
       # Check that the container executed at least 1 Rust test harness test, and that all tests passed.
       # Then wait for the container to finish, and exit with the test's exit status.
-      # Also shows recent test logs.
+      # Also shows all the test logs.
       #
       # If the container has already finished, `docker wait` should return its status.
       # But sometimes this doesn't work, so we use `docker inspect` as a fallback.
@@ -977,7 +980,7 @@ jobs:
           --command=' \
           set -e;
           docker logs \
-          --tail ${{ env.EXTRA_LOG_LINES }} \
+          --tail all \
           ${{ inputs.test_id }} | \
           tee --output-error=exit /dev/stderr | \
           grep --max-count=1 --extended-regexp --color=always \

zebrad/tests/acceptance.rs

@@ -354,6 +354,7 @@ fn misconfigured_ephemeral_missing_directory() -> Result<()> {
     )
 }
 
+#[tracing::instrument]
 fn ephemeral(cache_dir_config: EphemeralConfig, cache_dir_check: EphemeralCheck) -> Result<()> {
     use std::io::ErrorKind;
 
@@ -520,6 +521,7 @@ fn config_test() -> Result<()> {
 }
 
 /// Test that `zebrad start` can parse the output from `zebrad generate`.
+#[tracing::instrument]
 fn valid_generated_config(command: &str, expect_stdout_line_contains: &str) -> Result<()> {
     let _init_guard = zebra_test::init();
 
@@ -823,6 +825,7 @@ fn sync_large_checkpoints_mempool_mainnet() -> Result<()> {
     .map(|_tempdir| ())
 }
 
+#[tracing::instrument]
 fn create_cached_database(network: Network) -> Result<()> {
     let height = network.mandatory_checkpoint_height();
     let checkpoint_stop_regex = format!("{}.*CommitFinalized request", STOP_AT_HEIGHT_REGEX);
@@ -839,6 +842,7 @@ fn create_cached_database(network: Network) -> Result<()> {
     )
 }
 
+#[tracing::instrument]
 fn sync_past_mandatory_checkpoint(network: Network) -> Result<()> {
     let height = network.mandatory_checkpoint_height() + 1200;
     let full_validation_stop_regex =
@@ -862,6 +866,7 @@ fn sync_past_mandatory_checkpoint(network: Network) -> Result<()> {
 /// `timeout_argument_name` parameter. The value of the environment variable must the number of
 /// minutes specified as an integer.
 #[allow(clippy::print_stderr)]
+#[tracing::instrument]
 fn full_sync_test(network: Network, timeout_argument_name: &str) -> Result<()> {
     let timeout_argument: Option<u64> = env::var(timeout_argument_name)
         .ok()
@@ -1284,6 +1289,7 @@ async fn lightwalletd_test_suite() -> Result<()> {
 /// Set `FullSyncFromGenesis { allow_lightwalletd_cached_state: true }` to speed up manual full sync tests.
 ///
 /// The random ports in this test can cause [rare port conflicts.](#Note on port conflict)
+#[tracing::instrument]
 fn lightwalletd_integration_test(test_type: LightwalletdTestType) -> Result<()> {
     let _init_guard = zebra_test::init();
 
@@ -1686,6 +1692,7 @@ fn zebra_state_conflict() -> Result<()> {
 /// `second_dir`. Check that the first node's stdout contains
 /// `first_stdout_regex`, and the second node's stderr contains
 /// `second_stderr_regex`.
+#[tracing::instrument]
 fn check_config_conflict<T, U>(
     first_dir: T,
     first_stdout_regex: &str,
@@ -1693,8 +1700,8 @@ fn check_config_conflict<T, U>(
     second_stderr_regex: &str,
 ) -> Result<()>
 where
-    T: ZebradTestDirExt,
-    U: ZebradTestDirExt,
+    T: ZebradTestDirExt + std::fmt::Debug,
+    U: ZebradTestDirExt + std::fmt::Debug,
 {
     // Start the first node
     let mut node1 = first_dir.spawn_child(args!["start"])?;

zebrad/tests/common/cached_state.rs

@@ -25,6 +25,7 @@ pub type BoxStateService =
     BoxService<zebra_state::Request, zebra_state::Response, zebra_state::BoxError>;
 
 /// Starts a state service using the provided `cache_dir` as the directory with the chain state.
+#[tracing::instrument(skip(cache_dir))]
 pub async fn start_state_service_with_cache_dir(
     network: Network,
     cache_dir: impl Into<PathBuf>,
@@ -47,6 +48,7 @@ pub async fn start_state_service_with_cache_dir(
 }
 
 /// Loads the chain tip height from the state stored in a specified directory.
+#[tracing::instrument]
 pub async fn load_tip_height_from_state_directory(
     network: Network,
     state_path: &Path,
@@ -87,6 +89,7 @@ pub async fn copy_state_directory(source: impl AsRef<Path>) -> Result<TempDir> {
 ///
 /// Copies all files from the `directory` into the destination specified by the concatenation of
 /// the `base_destination_path` and `directory` stripped of its `prefix`.
+#[tracing::instrument]
 async fn copy_directory(
     directory: &Path,
     prefix: &Path,

zebrad/tests/common/launch.rs

@@ -206,7 +206,8 @@ where
 ///
 /// This prevents it from downloading blocks. Instead, the `zebra_directory` parameter allows
 /// providing an initial state to the zebrad instance.
-pub fn spawn_zebrad_for_rpc_without_initial_peers<P: ZebradTestDirExt>(
+#[tracing::instrument]
+pub fn spawn_zebrad_for_rpc_without_initial_peers<P: ZebradTestDirExt + std::fmt::Debug>(
     network: Network,
     zebra_directory: P,
     test_type: LightwalletdTestType,

zebrad/tests/common/lightwalletd/send_transaction_test.rs

@@ -145,6 +145,7 @@ pub async fn run() -> Result<()> {
 ///
 /// Returns a list of valid transactions that are not in any of the blocks present in the
 /// original `zebrad_state_path`.
+#[tracing::instrument]
 async fn load_transactions_from_a_future_block(
     network: Network,
     zebrad_state_path: PathBuf,
@@ -179,6 +180,7 @@ async fn load_transactions_from_a_future_block(
 ///
 /// If the specified `zebrad_state_path` contains a chain state that's not synchronized to a tip that's
 /// after `height`.
+#[tracing::instrument]
 async fn load_transactions_from_block_after(
     height: block::Height,
     network: Network,
@@ -213,6 +215,7 @@ async fn load_transactions_from_block_after(
 
 /// Performs a request to the provided read-only `state` service to fetch all transactions from a
 /// block at the specified `height`.
+#[tracing::instrument(skip(state))]
 async fn load_transactions_from_block<ReadStateService>(
     height: block::Height,
     state: &mut ReadStateService,

zebrad/tests/common/lightwalletd/wallet_grpc.rs

@@ -25,6 +25,7 @@ pub type LightwalletdRpcClient =
 /// Waits for `lightwalletd` to sync to near the tip, if `wait_for_sync` is true.
 ///
 /// Returns the lightwalletd instance and the port number that it is listening for RPC connections.
+#[tracing::instrument]
 pub fn spawn_lightwalletd_with_rpc_server(
     zebrad_rpc_address: SocketAddr,
     lightwalletd_state_path: Option<PathBuf>,
@@ -56,6 +57,7 @@ pub fn spawn_lightwalletd_with_rpc_server(
 }
 
 /// Connect to a lightwalletd RPC instance.
+#[tracing::instrument]
 pub async fn connect_to_lightwalletd(lightwalletd_rpc_port: u16) -> Result<LightwalletdRpcClient> {
     let lightwalletd_rpc_address = format!("http://127.0.0.1:{lightwalletd_rpc_port}");
 

zebrad/tests/common/sync.rs

@@ -86,6 +86,7 @@ pub const MIN_HEIGHT_FOR_DEFAULT_LOOKAHEAD: Height =
     Height(3 * sync::DEFAULT_CHECKPOINT_CONCURRENCY_LIMIT as u32);
 
 /// What the expected behavior of the mempool is for a test that uses [`sync_until`].
+#[derive(Copy, Clone, Debug, Eq, PartialEq)]
 pub enum MempoolBehavior {
     /// The mempool should be forced to activate at a certain height, for debug purposes.
     ///
@@ -177,6 +178,7 @@ impl MempoolBehavior {
 /// On success, returns the associated `TempDir`. Returns an error if
 /// the child exits or `timeout` elapses before `stop_regex` is found.
 #[allow(clippy::too_many_arguments)]
+#[tracing::instrument(skip(reuse_tempdir))]
 pub fn sync_until(
     height: Height,
     network: Network,
@@ -297,6 +299,7 @@ pub fn sync_until(
 /// The zebrad instance is executed on a copy of the partially synchronized chain state. This copy
 /// is returned afterwards, containing the fully synchronized chain state.
 #[allow(dead_code)]
+#[tracing::instrument]
 pub async fn perform_full_sync_starting_from(
     network: Network,
     partial_sync_path: &Path,
@@ -354,6 +357,7 @@ pub fn cached_mandatory_checkpoint_test_config() -> Result<ZebradConfig> {
 /// Returns an error if the child exits or the fixed timeout elapses
 /// before `STOP_AT_HEIGHT_REGEX` is found.
 #[allow(clippy::print_stderr)]
+#[tracing::instrument]
 pub fn create_cached_database_height(
     network: Network,
     height: Height,