fix(ci): test RPCs with zcash/lightwalletd, to fix post-NU5 failures in adityapk00/lightwalletd (#4553)

* Remove a duplicate lightwalletd error message

* Reactivate some error messages that have been fixed

* Fix confusing lightwalletd cached state path logs

* Add the gRPC tests to the lightwalletd test suite function

* Make test regexes compatible with zcash/lightwalletd

* Add logging to gRPC tests

* Switch to zcash/lightwalletd for testing

.github/workflows/zcash-lightwalletd.yml

@@ -3,6 +3,7 @@ name: zcash-lightwalletd
 on:
   workflow_dispatch:
 
+  # Update the lightwalletd image when related changes merge to the `zebra/main` branch
   push:
     branches:
       - 'main'
@@ -10,7 +11,7 @@ on:
       # rebuild lightwalletd whenever the related Zebra code changes
       #
       # TODO: this code isn't compiled in this docker image
-      #       rebuild whenever the actual code at adityapk00/lightwalletd/master changes
+      #       rebuild whenever the actual code at zcash/lightwalletd/master changes
       - 'zebra-rpc/**'
       - 'zebrad/tests/acceptance.rs'
       - 'zebrad/src/config.rs'
@@ -20,9 +21,6 @@ on:
       - '.github/workflows/zcash-lightwalletd.yml'
 
   # Update the lightwalletd image when each related PR changes
-  #
-  # TODO: after NU5 mainnet activation and wallet orchard features are stable,
-  #       consider just rebuilding the image on `main` merges
   pull_request:
     branches:
       - main
@@ -52,7 +50,7 @@ jobs:
     steps:
       - uses: actions/checkout@v3.0.2
         with:
-          repository: adityapk00/lightwalletd
+          repository: zcash/lightwalletd
           ref: 'master'
           persist-credentials: false
 

zebrad/tests/acceptance.rs

@@ -1042,14 +1042,20 @@ fn lightwalletd_full_sync() -> Result<()> {
 ///
 /// Runs the tests in this order:
 /// - launch lightwalletd with empty states,
-/// - if `ZEBRA_CACHED_STATE_DIR` and `LIGHTWALLETD_DATA_DIR` are set: run a quick update sync,
+/// - if `ZEBRA_CACHED_STATE_DIR` is set:
-/// - if `ZEBRA_CACHED_STATE_DIR` is set: run a full sync.
+///   - run a full sync
+/// - if `ZEBRA_CACHED_STATE_DIR` and `LIGHTWALLETD_DATA_DIR` are set:
+///   - run a quick update sync,
+///   - run a send transaction gRPC test,
+///   - run read-only gRPC tests.
+///
+/// The gRPC tests only run when the `lightwalletd-grpc-tests` is on.
 ///
 /// These tests don't work on Windows, so they are always skipped on that platform.
-#[test]
+#[tokio::test]
 #[ignore]
 #[cfg(not(target_os = "windows"))]
-fn lightwalletd_test_suite() -> Result<()> {
+async fn lightwalletd_test_suite() -> Result<()> {
     lightwalletd_integration_test(LaunchWithEmptyState)?;
 
     // Only runs when ZEBRA_CACHED_STATE_DIR is set.
@@ -1061,6 +1067,14 @@ fn lightwalletd_test_suite() -> Result<()> {
     // Only runs when LIGHTWALLETD_DATA_DIR and ZEBRA_CACHED_STATE_DIR are set
     lightwalletd_integration_test(UpdateCachedState)?;
 
+    // Only runs when LIGHTWALLETD_DATA_DIR and ZEBRA_CACHED_STATE_DIR are set,
+    // and the compile-time gRPC feature is on.
+    #[cfg(feature = "lightwalletd-grpc-tests")]
+    {
+        common::lightwalletd::send_transaction_test::run().await?;
+        common::lightwalletd::wallet_grpc_test::run().await?;
+    }
+
     Ok(())
 }
 
@@ -1106,7 +1120,12 @@ fn lightwalletd_integration_test(test_type: LightwalletdTestType) -> Result<()>
         return Ok(());
     }
 
-    tracing::info!(?test_type, "running lightwalletd & zebrad integration test");
+    tracing::info!(
+        ?test_type,
+        ?config,
+        ?lightwalletd_state_path,
+        "running lightwalletd & zebrad integration test",
+    );
 
     // Get the lists of process failure logs
     let (zebrad_failure_messages, zebrad_ignore_messages) = test_type.zebrad_failure_messages();
@@ -1159,7 +1178,7 @@ fn lightwalletd_integration_test(test_type: LightwalletdTestType) -> Result<()>
     // getblockchaininfo
     if test_type.needs_zebra_cached_state() {
         lightwalletd.expect_stdout_line_matches(
-            "Got sapling height 419200 block height [0-9]{7} chain main branchID e9ff75a6",
+            "Got sapling height 419200 block height [0-9]{7} chain main branchID [0-9a-f]{8}",
         )?;
     } else {
         // Timeout the test if we're somehow accidentally using a cached state in our temp dir
@@ -1192,31 +1211,38 @@ fn lightwalletd_integration_test(test_type: LightwalletdTestType) -> Result<()>
     //
     // Until the Sapling activation block has been downloaded,
     // lightwalletd will keep retrying getblock.
+    if !test_type.allow_lightwalletd_cached_state() {
         if test_type.needs_zebra_cached_state() {
-        lightwalletd.expect_stdout_line_matches(regex::escape("Ingestor adding block to cache"))?;
+            lightwalletd.expect_stdout_line_matches("[Aa]dding block to cache")?;
         } else {
             lightwalletd.expect_stdout_line_matches(regex::escape(
                 "Waiting for zcashd height to reach Sapling activation height (419200)",
             ))?;
         }
+    }
 
     if matches!(test_type, UpdateCachedState | FullSyncFromGenesis { .. }) {
         // Wait for Zebra to sync its cached state to the chain tip
         zebrad.expect_stdout_line_matches(SYNC_FINISHED_REGEX)?;
 
         // Wait for lightwalletd to sync to Zebra's tip
-        lightwalletd.expect_stdout_line_matches(regex::escape("Ingestor waiting for block"))?;
+        lightwalletd.expect_stdout_line_matches("[Ww]aiting for block")?;
 
         // Check Zebra is still at the tip (also clears and prints Zebra's logs)
         zebrad.expect_stdout_line_matches(SYNC_FINISHED_REGEX)?;
 
         // lightwalletd doesn't log anything when we've reached the tip.
         // But when it gets near the tip, it starts using the mempool.
+        //
+        // adityapk00/lightwalletd logs mempool changes, but zcash/lightwalletd doesn't.
+        #[cfg(adityapk00_lightwalletd)]
+        {
             lightwalletd.expect_stdout_line_matches(regex::escape(
                 "Block hash changed, clearing mempool clients",
             ))?;
             lightwalletd.expect_stdout_line_matches(regex::escape("Adding new mempool txid"))?;
         }
+    }
 
     // Cleanup both processes
     lightwalletd.kill()?;
@@ -1528,9 +1554,12 @@ async fn fully_synced_rpc_test() -> Result<()> {
 /// Test sending transactions using a lightwalletd instance connected to a zebrad instance.
 ///
 /// 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(not(target_os = "windows"))]
 async fn sending_transactions_using_lightwalletd() -> Result<()> {
     common::lightwalletd::send_transaction_test::run().await
 }
@@ -1538,9 +1567,12 @@ async fn sending_transactions_using_lightwalletd() -> Result<()> {
 /// Test all the rpc methods a wallet connected to lightwalletd can call.
 ///
 /// 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(not(target_os = "windows"))]
 async fn lightwalletd_wallet_grpc_tests() -> Result<()> {
     common::lightwalletd::wallet_grpc_test::run().await
 }

zebrad/tests/common/cached_state.rs

@@ -63,13 +63,19 @@ pub async fn load_tip_height_from_state_directory(
 
 /// Recursively copy a chain state directory into a new temporary directory.
 pub async fn copy_state_directory(source: impl AsRef<Path>) -> Result<TempDir> {
+    let source = source.as_ref();
     let destination = testdir()?;
 
-    let mut remaining_directories = vec![PathBuf::from(source.as_ref())];
+    tracing::info!(
+        ?source,
+        ?destination,
+        "copying cached state files (this may take some time)...",
+    );
+
+    let mut remaining_directories = vec![PathBuf::from(source)];
 
     while let Some(directory) = remaining_directories.pop() {
-        let sub_directories =
+        let sub_directories = copy_directory(&directory, source, destination.as_ref()).await?;
-            copy_directory(&directory, source.as_ref(), destination.as_ref()).await?;
 
         remaining_directories.extend(sub_directories);
     }

zebrad/tests/common/failure_messages.rs

@@ -74,13 +74,12 @@ pub const LIGHTWALLETD_FAILURE_MESSAGES: &[&str] = &[
     "error parsing JSON",
     "error reading JSON response",
     "error with",
-    // We expect these errors when lightwalletd reaches the end of the zebrad cached state
+    // Block error messages
-    // "error requesting block: 0: Block not found",
+    "error requesting block: 0: Block not found",
-    // "error zcashd getblock rpc",
+    "error zcashd getblock rpc",
     "received overlong message",
     "received unexpected height block",
     "Reorg exceeded max",
-    "unable to issue RPC call",
     // Missing fields for each specific RPC
     //
     // get_block_chain_info

zebrad/tests/common/lightwalletd.rs

@@ -309,10 +309,17 @@ impl LightwalletdTestType {
         match env::var_os(LIGHTWALLETD_DATA_DIR) {
             Some(path) => Some(path.into()),
             None => {
+                if self.needs_lightwalletd_cached_state() {
                     tracing::info!(
                         "skipped {test_name:?} {self:?} lightwalletd test, \
                          set the {LIGHTWALLETD_DATA_DIR:?} environment variable to run the test",
                     );
+                } else if self.allow_lightwalletd_cached_state() {
+                    tracing::info!(
+                        "running {test_name:?} {self:?} lightwalletd test without cached state, \
+                         set the {LIGHTWALLETD_DATA_DIR:?} environment variable to run with cached state",
+                    );
+                }
 
                 None
             }

zebrad/tests/common/lightwalletd/send_transaction_test.rs

@@ -54,8 +54,8 @@ pub async fn run() -> Result<()> {
     // so `UpdateCachedState` can be used as our test type
     let test_type = UpdateCachedState;
 
-    let cached_state_path = test_type.zebrad_state_path("send_transaction_tests".to_string());
+    let zebrad_state_path = test_type.zebrad_state_path("send_transaction_tests".to_string());
-    if cached_state_path.is_none() {
+    if zebrad_state_path.is_none() {
         return Ok(());
     }
 
@@ -67,12 +67,31 @@ pub async fn run() -> Result<()> {
 
     let network = Network::Mainnet;
 
+    tracing::info!(
+        ?network,
+        ?test_type,
+        ?zebrad_state_path,
+        ?lightwalletd_state_path,
+        "running gRPC send transaction test using lightwalletd & zebrad",
+    );
+
     let (transactions, partial_sync_path) =
-        load_transactions_from_a_future_block(network, cached_state_path.unwrap()).await?;
+        load_transactions_from_a_future_block(network, zebrad_state_path.unwrap()).await?;
+
+    tracing::info!(
+        transaction_count = ?transactions.len(),
+        ?partial_sync_path,
+        "got transactions to send",
+    );
 
     let (_zebrad, zebra_rpc_address) =
         spawn_zebrad_for_rpc_without_initial_peers(Network::Mainnet, partial_sync_path, test_type)?;
 
+    tracing::info!(
+        ?zebra_rpc_address,
+        "spawned disconnected zebrad with shorter chain",
+    );
+
     let (_lightwalletd, lightwalletd_rpc_port) = spawn_lightwalletd_with_rpc_server(
         zebra_rpc_address,
         lightwalletd_state_path,
@@ -80,8 +99,18 @@ pub async fn run() -> Result<()> {
         true,
     )?;
 
+    tracing::info!(
+        ?lightwalletd_rpc_port,
+        "spawned lightwalletd connected to zebrad",
+    );
+
     let mut rpc_client = connect_to_lightwalletd(lightwalletd_rpc_port).await?;
 
+    tracing::info!(
+        transaction_count = ?transactions.len(),
+        "connected gRPC client to lightwalletd, sending transactions...",
+    );
+
     for transaction in transactions {
         let expected_response = wallet_grpc::SendResponse {
             error_code: 0,
@@ -112,14 +141,28 @@ pub async fn run() -> Result<()> {
 /// synchronized chain.
 async fn load_transactions_from_a_future_block(
     network: Network,
-    cached_state_path: PathBuf,
+    zebrad_state_path: PathBuf,
 ) -> Result<(Vec<Arc<Transaction>>, TempDir)> {
+    tracing::info!(
+        ?network,
+        ?zebrad_state_path,
+        "preparing partial sync, copying files...",
+    );
+
     let (partial_sync_path, partial_sync_height) =
-        prepare_partial_sync(network, cached_state_path).await?;
+        prepare_partial_sync(network, zebrad_state_path).await?;
+
+    tracing::info!(
+        ?partial_sync_height,
+        ?partial_sync_path,
+        "performing full sync...",
+    );
 
     let full_sync_path =
         perform_full_sync_starting_from(network, partial_sync_path.as_ref()).await?;
 
+    tracing::info!(?full_sync_path, "loading transactions...");
+
     let transactions =
         load_transactions_from_block_after(partial_sync_height, network, full_sync_path.as_ref())
             .await?;
@@ -133,9 +176,9 @@ async fn load_transactions_from_a_future_block(
 /// height of the partially synchronized chain.
 async fn prepare_partial_sync(
     network: Network,
-    cached_zebra_state: PathBuf,
+    zebrad_state_path: PathBuf,
 ) -> Result<(TempDir, block::Height)> {
-    let partial_sync_path = copy_state_directory(cached_zebra_state).await?;
+    let partial_sync_path = copy_state_directory(zebrad_state_path).await?;
     let tip_height =
         load_tip_height_from_state_directory(network, partial_sync_path.as_ref()).await?;
 
@@ -149,15 +192,15 @@ async fn prepare_partial_sync(
 ///
 /// # Panics
 ///
-/// If the specified `state_path` contains a chain state that's not synchronized to a tip that's
+/// If the specified `zebrad_state_path` contains a chain state that's not synchronized to a tip that's
 /// after `height`.
 async fn load_transactions_from_block_after(
     height: block::Height,
     network: Network,
-    state_path: &Path,
+    zebrad_state_path: &Path,
 ) -> Result<Vec<Arc<Transaction>>> {
     let (_read_write_state_service, mut state, latest_chain_tip, _chain_tip_change) =
-        start_state_service_with_cache_dir(network, state_path).await?;
+        start_state_service_with_cache_dir(network, zebrad_state_path).await?;
 
     let tip_height = latest_chain_tip
         .best_tip_height()

zebrad/tests/common/lightwalletd/wallet_grpc_test.rs

@@ -83,10 +83,24 @@ pub async fn run() -> Result<()> {
     // This test is only for the mainnet
     let network = Network::Mainnet;
 
+    tracing::info!(
+        ?network,
+        ?test_type,
+        ?zebrad_state_path,
+        ?lightwalletd_state_path,
+        "running gRPC query tests using lightwalletd & zebrad, \
+         launching disconnected zebrad...",
+    );
+
     // Launch zebra using a predefined zebrad state path
     let (_zebrad, zebra_rpc_address) =
         spawn_zebrad_for_rpc_without_initial_peers(network, zebrad_state_path.unwrap(), test_type)?;
 
+    tracing::info!(
+        ?zebra_rpc_address,
+        "launching lightwalletd connected to zebrad...",
+    );
+
     // Launch lightwalletd
     let (_lightwalletd, lightwalletd_rpc_port) = spawn_lightwalletd_with_rpc_server(
         zebra_rpc_address,
@@ -98,10 +112,16 @@ pub async fn run() -> Result<()> {
     // Give lightwalletd a few seconds to open its grpc port before connecting to it
     tokio::time::sleep(std::time::Duration::from_secs(3)).await;
 
+    tracing::info!(
+        ?lightwalletd_rpc_port,
+        "connecting gRPC client to lightwalletd...",
+    );
+
     // Connect to the lightwalletd instance
     let mut rpc_client = connect_to_lightwalletd(lightwalletd_rpc_port).await?;
 
     // End of the setup and start the tests
+    tracing::info!(?lightwalletd_rpc_port, "sending gRPC queries...");
 
     // Call `GetLatestBlock`
     let block_tip = rpc_client