From 65c1ef8177fdc6f9202751b0b1373fbded75b9ad Mon Sep 17 00:00:00 2001 From: teor Date: Wed, 23 Mar 2022 11:34:37 +1000 Subject: [PATCH] T3. add(test): check for failure messages in lightwalletd and Zebra logs (#3903) * Make command test matching code accept generic regexes And add generic conversions to regexes. * Document test command structs * Support matching multiple regexes internally in the test command * Make it easier to call the generic regex methods * Add a missing API usage comment * Fix a potential hang in test child error reports * Revert Option process handling * Revert "Revert Option process handling" This reverts commit 2af30086858d104dcb0ec87383996c36bcaa7371. * Add a set of failure regexes to test command output * Allow debug-printing TestChild again * When the child is dropped, check any remaining output * Document a wait_with_output edge case * Improve failure regex panic output * Improve builder ergonomics * Add internal tests for failure regex panics It would be easy to disable these panics, and never realise. * Add some module structure TODOs * Stop panicking if the child process has already been taken * Add test APIs for consuming child output lines * Fix a hang on child process drop * Handle output being already taken in wait_with_output And document some edge cases we don't handle yet * Use bash's read command in the TestChild stderr test And check the actual command we're using to see if it errors. * Pretty print full failure regex list * Add the test child command line to the failure regex logs * Simplify the sync_until test code * Check logs for failure messages in lightwalletd integration tests * Add more TODOs and improve comments * Allow missing branch ID 00000000 provided by zcashd --- zebrad/tests/acceptance.rs | 122 ++++++++++++++++++++++++++++++++++--- 1 file changed, 115 insertions(+), 7 deletions(-) diff --git a/zebrad/tests/acceptance.rs b/zebrad/tests/acceptance.rs index d7937ac5..cf5e9ca9 100644 --- a/zebrad/tests/acceptance.rs +++ b/zebrad/tests/acceptance.rs @@ -659,7 +659,7 @@ fn full_sync_testnet() { /// The timeout is specified using an environment variable, with the name configured by the /// `timeout_argument_name` parameter. The value of the environment variable must the number of /// minutes specified as an integer. -fn full_sync_test(network: Network, timeout_argument_name: &'static str) -> Result<()> { +fn full_sync_test(network: Network, timeout_argument_name: &str) -> Result<()> { let timeout_argument: Option = env::var(timeout_argument_name) .ok() .and_then(|timeout_string| timeout_string.parse().ok()); @@ -678,8 +678,7 @@ fn full_sync_test(network: Network, timeout_argument_name: &'static str) -> Resu // TODO: if full validation performance improves, do another test with checkpoint_sync off true, true, - ) - .map(|_| ()) + )?; } else { tracing::info!( ?network, @@ -687,9 +686,9 @@ fn full_sync_test(network: Network, timeout_argument_name: &'static str) -> Resu set the {:?} environmental variable to run the test", timeout_argument_name, ); - - Ok(()) } + + Ok(()) } fn create_cached_database(network: Network) -> Result<()> { @@ -989,6 +988,95 @@ async fn rpc_endpoint() -> Result<()> { Ok(()) } +/// Failure log messages for any process, from the OS or shell. +const PROCESS_FAILURE_MESSAGES: &[&str] = &[ + // Linux + "Aborted", + // macOS / BSDs + "Abort trap", + // TODO: add other OS or C library errors? +]; + +/// Failure log messages from Zebra. +const ZEBRA_FAILURE_MESSAGES: &[&str] = &[ + // Rust-specific panics + "The application panicked", + // RPC port errors + "Unable to start RPC server", + // TODO: disable if this actually happens during test zebrad shutdown + "Stopping RPC endpoint", + // Missing RPCs in zebrad logs (this log is from PR #3860) + // + // TODO: temporarily disable until enough RPCs are implemented, if needed + "Received unrecognized RPC request", + // RPC argument errors: parsing and data + // + // These logs are produced by jsonrpc_core inside Zebra, + // but it doesn't log them yet. + // + // TODO: log these errors in Zebra, and check for them in the Zebra logs? + "Invalid params", + "Method not found", +]; + +/// Failure log messages from lightwalletd. +const LIGHTWALLETD_FAILURE_MESSAGES: &[&str] = &[ + // Go-specific panics + "panic:", + // Missing RPCs in lightwalletd logs + // TODO: temporarily disable until enough RPCs are implemented, if needed + "unable to issue RPC call", + // RPC response errors: parsing and data + // + // jsonrpc_core error messages from Zebra, + // received by lightwalletd and written to its logs + "Invalid params", + "Method not found", + // Early termination + // + // TODO: temporarily disable until enough RPCs are implemented, if needed + "Lightwalletd died with a Fatal error", + // Go json package error messages: + "json: cannot unmarshal", + "into Go value of type", + // lightwalletd RPC error messages from: + // https://github.com/adityapk00/lightwalletd/blob/master/common/common.go + "block requested is newer than latest block", + "Cache add failed", + "error decoding", + "error marshaling", + "error parsing JSON", + "error reading JSON response", + "error with", + // We expect these errors when lightwalletd reaches the end of the zebrad cached state + // "error requesting block: 0: Block not found", + // "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 + // + // TODO: enable these checks after PR #3891 merges + // + // invalid sapling height + //"Got sapling height 0", + // missing BIP70 chain name, should be "main" or "test" + //" chain ", + // missing branchID, should be 8 hex digits + //" branchID \"", + // + // TODO: complete this list for each RPC with fields? + // get_info + // get_raw_transaction + // z_get_tree_state + // get_address_txids + // get_address_balance + // get_address_utxos +]; + /// Launch `zebrad` with an RPC port, and make sure `lightwalletd` works with Zebra. /// /// This test only runs when the `ZEBRA_TEST_LIGHTWALLETD` env var is set. @@ -1011,7 +1099,16 @@ fn lightwalletd_integration() -> Result<()> { let mut config = random_known_rpc_port_config()?; let zdir = testdir()?.with_config(&mut config)?; - let mut zebrad = zdir.spawn_child(&["start"])?.with_timeout(LAUNCH_DELAY); + let mut zebrad = zdir + .spawn_child(&["start"])? + .with_timeout(LAUNCH_DELAY) + .with_failure_regex_iter( + // TODO: replace with a function that returns the full list and correct return type + ZEBRA_FAILURE_MESSAGES + .iter() + .chain(PROCESS_FAILURE_MESSAGES) + .cloned(), + ); // Wait until `zebrad` has opened the RPC endpoint zebrad.expect_stdout_line_matches( @@ -1027,7 +1124,15 @@ fn lightwalletd_integration() -> Result<()> { // Launch the lightwalletd process let result = ldir.spawn_lightwalletd_child(&[]); let (lightwalletd, zebrad) = zebrad.kill_on_error(result)?; - let mut lightwalletd = lightwalletd.with_timeout(LIGHTWALLETD_DELAY); + let mut lightwalletd = lightwalletd + .with_timeout(LIGHTWALLETD_DELAY) + .with_failure_regex_iter( + // TODO: replace with a function that returns the full list and correct return type + LIGHTWALLETD_FAILURE_MESSAGES + .iter() + .chain(PROCESS_FAILURE_MESSAGES) + .cloned(), + ); // Wait until `lightwalletd` has launched let result = lightwalletd.expect_stdout_line_matches("Starting gRPC server"); @@ -1036,6 +1141,9 @@ fn lightwalletd_integration() -> Result<()> { // Check that `lightwalletd` is calling the expected Zebra RPCs // getblockchaininfo + // + // TODO: add correct sapling height, chain, branchID (PR #3891) + // add "Waiting for zcashd height to reach Sapling activation height" let result = lightwalletd.expect_stdout_line_matches("Got sapling height"); let (_, zebrad) = zebrad.kill_on_error(result)?;