From 6c0f62545d2bc8065163fba14ba52b8ed5844747 Mon Sep 17 00:00:00 2001 From: teor Date: Wed, 24 Aug 2022 12:08:24 +1000 Subject: [PATCH 01/10] Handle test failure regexes using Result::Err, rather than panicking --- zebra-test/src/command.rs | 144 +++++++++++++++++++++--------------- zebra-test/tests/command.rs | 89 +++++++++++----------- zebrad/tests/acceptance.rs | 33 +++++---- zebrad/tests/common/sync.rs | 4 +- 4 files changed, 148 insertions(+), 122 deletions(-) diff --git a/zebra-test/src/command.rs b/zebra-test/src/command.rs index 6ccdc59c38e..e933ec81bc6 100644 --- a/zebra-test/src/command.rs +++ b/zebra-test/src/command.rs @@ -3,7 +3,7 @@ use std::{ convert::Infallible as NoDir, fmt::{self, Debug, Write as _}, - io::{BufRead, BufReader, Read, Write as _}, + io::{BufRead, BufReader, ErrorKind, Read, Write as _}, path::Path, process::{Child, Command, ExitStatus, Output, Stdio}, time::{Duration, Instant}, @@ -227,53 +227,62 @@ pub struct TestChild { } /// Checks command output log `line` from `cmd` against a `failure_regexes` regex set, -/// and panics if any regex matches. The line is skipped if it matches `ignore_regexes`. +/// and returns an error if any regex matches. The line is skipped if it matches `ignore_regexes`. /// -/// # Panics -/// -/// - if any stdout or stderr lines match any failure regex, but do not match any ignore regex +/// Passes through errors from the underlying reader. pub fn check_failure_regexes( - line: &std::io::Result, + line: std::io::Result, failure_regexes: &RegexSet, ignore_regexes: &RegexSet, cmd: &str, bypass_test_capture: bool, -) { - if let Ok(line) = line { - let ignore_matches = ignore_regexes.matches(line); - let ignore_matches: Vec<&str> = ignore_matches - .iter() - .map(|index| ignore_regexes.patterns()[index].as_str()) - .collect(); - - let failure_matches = failure_regexes.matches(line); - let failure_matches: Vec<&str> = failure_matches - .iter() - .map(|index| failure_regexes.patterns()[index].as_str()) - .collect(); - - if !ignore_matches.is_empty() { - let ignore_matches = ignore_matches.join(","); - - let ignore_msg = if failure_matches.is_empty() { - format!( - "Log matched ignore regexes: {:?}, but no failure regexes", - ignore_matches, - ) - } else { - let failure_matches = failure_matches.join(","); - format!( - "Ignoring failure regexes: {:?}, because log matched ignore regexes: {:?}", - failure_matches, ignore_matches, - ) - }; +) -> std::io::Result { + let line = line?; + + // Check if the line matches any patterns + let ignore_matches = ignore_regexes.matches(&line); + let ignore_matches: Vec<&str> = ignore_matches + .iter() + .map(|index| ignore_regexes.patterns()[index].as_str()) + .collect(); + + let failure_matches = failure_regexes.matches(&line); + let failure_matches: Vec<&str> = failure_matches + .iter() + .map(|index| failure_regexes.patterns()[index].as_str()) + .collect(); + + // If we match an ignore pattern, ignore any failure matches + if !ignore_matches.is_empty() { + let ignore_matches = ignore_matches.join(","); + + let ignore_msg = if failure_matches.is_empty() { + format!( + "Log matched ignore regexes: {:?}, but no failure regexes", + ignore_matches, + ) + } else { + let failure_matches = failure_matches.join(","); + format!( + "Ignoring failure regexes: {:?}, because log matched ignore regexes: {:?}", + failure_matches, ignore_matches, + ) + }; - write_to_test_logs(ignore_msg, bypass_test_capture); - return; - } + write_to_test_logs(ignore_msg, bypass_test_capture); + + return Ok(line); + } + + // If there were no failures, pass the log line through + if failure_matches.is_empty() { + return Ok(line); + } - assert!( - failure_matches.is_empty(), + // Otherwise, if the process logged a failure message, return an error + let error = std::io::Error::new( + ErrorKind::Other, + format!( "test command:\n\ {cmd}\n\n\ Logged a failure message:\n\ @@ -283,8 +292,10 @@ pub fn check_failure_regexes( All Failure regexes: \ {:#?}\n", failure_regexes.patterns(), - ); - } + ), + ); + + Err(error) } /// Write `line` to stdout, so it can be seen in the test logs. @@ -444,7 +455,7 @@ impl TestChild { let bypass_test_capture = self.bypass_test_capture; let reader = BufReader::new(reader); - let lines = BufRead::lines(reader).inspect(move |line| { + let lines = BufRead::lines(reader).map(move |line| { check_failure_regexes( line, &failure_regexes, @@ -459,32 +470,48 @@ impl TestChild { /// Kill the child process. /// + /// If `ignore_exited` is `true`, log "can't kill an exited process" errors, + /// rather than returning them. + /// + /// Returns the result of the kill. + /// /// ## BUGS /// /// On Windows (and possibly macOS), this function can return `Ok` for /// processes that have panicked. See #1781. #[spandoc::spandoc] - pub fn kill(&mut self) -> Result<()> { + pub fn kill(&mut self, ignore_exited: bool) -> Result<()> { let child = match self.child.as_mut() { Some(child) => child, None => return Err(eyre!("child was already taken")).context_from(self.as_mut()), }; /// SPANDOC: Killing child process - child.kill().context_from(self.as_mut())?; + let kill_result = child.kill().or_else(|error| { + if ignore_exited && error.kind() == ErrorKind::InvalidInput { + Ok(()) + } else { + Err(error) + } + }); + + kill_result.context_from(self.as_mut())?; Ok(()) } /// Kill the process, and consume all its remaining output. /// + /// If `ignore_exited` is `true`, log "can't kill an exited process" errors, + /// rather than returning them. + /// /// Returns the result of the kill. - pub fn kill_and_consume_output(&mut self) -> Result<()> { + pub fn kill_and_consume_output(&mut self, ignore_exited: bool) -> Result<()> { self.apply_failure_regexes_to_outputs(); // Prevent a hang when consuming output, // by making sure the child's output actually finishes. - let kill_result = self.kill(); + let kill_result = self.kill(ignore_exited); // Read unread child output. // @@ -526,12 +553,12 @@ impl TestChild { { self.apply_failure_regexes_to_outputs(); - if let Some(Ok(line)) = self.stdout.as_mut().and_then(|iter| iter.next()) { + if let Some(line) = self.stdout.as_mut().and_then(|iter| iter.next()) { if let Some(write_context) = write_context.into() { self.write_to_test_logs(write_context); } - self.write_to_test_logs(line); + self.write_to_test_logs(line.expect("failure reading test process logs")); return true; } @@ -552,12 +579,12 @@ impl TestChild { { self.apply_failure_regexes_to_outputs(); - if let Some(Ok(line)) = self.stderr.as_mut().and_then(|iter| iter.next()) { + if let Some(line) = self.stderr.as_mut().and_then(|iter| iter.next()) { if let Some(write_context) = write_context.into() { self.write_to_test_logs(write_context); } - self.write_to_test_logs(line); + self.write_to_test_logs(line.expect("failure reading test process logs")); return true; } @@ -771,9 +798,9 @@ impl TestChild { if self.is_running() { // If the process exits between is_running and kill, we will see - // spurious errors here. If that happens, ignore "no such process" + // spurious errors here. So we want to ignore "no such process" // errors from kill. - self.kill()?; + self.kill(true)?; } let report = eyre!( @@ -814,7 +841,7 @@ impl TestChild { }; if self.is_running() { - let kill_res = self.kill(); + let kill_res = self.kill(true); if let Err(kill_err) = kill_res { error = error.wrap_err(kill_err); } @@ -872,9 +899,8 @@ impl Drop for TestChild { fn drop(&mut self) { // Clean up child processes when the test finishes, // and check for failure logs. - // - // We don't care about the kill result here. - let _ = self.kill_and_consume_output(); + self.kill_and_consume_output(true) + .expect("failure reading test process logs") } } @@ -1198,7 +1224,7 @@ impl ContextFrom<&mut TestChild> for Report { if let Some(stdout) = &mut source.stdout { for line in stdout { - let line = if let Ok(line) = line { line } else { break }; + let line = line.expect("failure reading test process logs"); let _ = writeln!(&mut stdout_buf, "{}", line); } } else if let Some(child) = &mut source.child { @@ -1209,7 +1235,7 @@ impl ContextFrom<&mut TestChild> for Report { if let Some(stderr) = &mut source.stderr { for line in stderr { - let line = if let Ok(line) = line { line } else { break }; + let line = line.expect("failure reading test process logs"); let _ = writeln!(&mut stderr_buf, "{}", line); } } else if let Some(child) = &mut source.child { diff --git a/zebra-test/tests/command.rs b/zebra-test/tests/command.rs index 0fac169f0e0..61ef41ce3c1 100644 --- a/zebra-test/tests/command.rs +++ b/zebra-test/tests/command.rs @@ -185,19 +185,15 @@ fn kill_on_timeout_no_output() -> Result<()> { } /// Make sure failure regexes detect when a child process prints a failure message to stdout, -/// and panic with a test failure message. +/// and fail with a test failure message. #[test] -#[should_panic(expected = "Logged a failure message")] fn failure_regex_matches_stdout_failure_message() { let _init_guard = zebra_test::init(); const TEST_CMD: &str = "echo"; // Skip the test if the test system does not have the command if !is_command_available(TEST_CMD, &[]) { - panic!( - "skipping test: command not available\n\ - fake panic message: Logged a failure message" - ); + return; } let mut child = tempdir() @@ -209,15 +205,21 @@ fn failure_regex_matches_stdout_failure_message() { // Any method that reads output should work here. // We use a non-matching regex, to trigger the failure panic. - child + let expected_error = child .expect_stdout_line_matches("this regex should not match") .unwrap_err(); + + let expected_error = format!("{:?}", expected_error); + assert!( + expected_error.contains("Logged a failure message"), + "error did not contain expected failure message: {}", + expected_error, + ); } /// Make sure failure regexes detect when a child process prints a failure message to stderr, /// and panic with a test failure message. #[test] -#[should_panic(expected = "Logged a failure message")] fn failure_regex_matches_stderr_failure_message() { let _init_guard = zebra_test::init(); @@ -230,10 +232,7 @@ fn failure_regex_matches_stderr_failure_message() { const TEST_CMD: &str = "bash"; // Skip the test if the test system does not have the command if !is_command_available(TEST_CMD, &["-c", "read -t 1 -p failure_message"]) { - panic!( - "skipping test: command not available\n\ - fake panic message: Logged a failure message" - ); + return; } let mut child = tempdir() @@ -245,9 +244,16 @@ fn failure_regex_matches_stderr_failure_message() { // Any method that reads output should work here. // We use a non-matching regex, to trigger the failure panic. - child + let expected_error = child .expect_stderr_line_matches("this regex should not match") .unwrap_err(); + + let expected_error = format!("{:?}", expected_error); + assert!( + expected_error.contains("Logged a failure message"), + "error did not contain expected failure message: {}", + expected_error, + ); } /// Make sure failure regexes detect when a child process prints a failure message to stdout, @@ -260,10 +266,7 @@ fn failure_regex_matches_stdout_failure_message_drop() { const TEST_CMD: &str = "echo"; // Skip the test if the test system does not have the command if !is_command_available(TEST_CMD, &[]) { - panic!( - "skipping test: command not available\n\ - fake panic message: Logged a failure message" - ); + return; } let _child = tempdir() @@ -289,10 +292,7 @@ fn failure_regex_matches_stdout_failure_message_kill() { const TEST_CMD: &str = "echo"; // Skip the test if the test system does not have the command if !is_command_available(TEST_CMD, &[]) { - panic!( - "skipping test: command not available\n\ - fake panic message: Logged a failure message" - ); + return; } let mut child = tempdir() @@ -307,7 +307,7 @@ fn failure_regex_matches_stdout_failure_message_kill() { // Kill should read all unread output to generate the error context, // or the output should be read on drop. - child.kill().unwrap(); + child.kill(true).unwrap(); } /// Make sure failure regexes detect when a child process prints a failure message to stdout, @@ -320,10 +320,7 @@ fn failure_regex_matches_stdout_failure_message_kill_on_error() { const TEST_CMD: &str = "echo"; // Skip the test if the test system does not have the command if !is_command_available(TEST_CMD, &[]) { - panic!( - "skipping test: command not available\n\ - fake panic message: Logged a failure message" - ); + return; } let child = tempdir() @@ -352,10 +349,7 @@ fn failure_regex_matches_stdout_failure_message_no_kill_on_error() { const TEST_CMD: &str = "echo"; // Skip the test if the test system does not have the command if !is_command_available(TEST_CMD, &[]) { - panic!( - "skipping test: command not available\n\ - fake panic message: Logged a failure message" - ); + return; } let child = tempdir() @@ -379,7 +373,6 @@ fn failure_regex_matches_stdout_failure_message_no_kill_on_error() { /// /// TODO: test the failure regex on timeouts with no output (#1140) #[test] -#[should_panic(expected = "Logged a failure message")] fn failure_regex_timeout_continuous_output() { let _init_guard = zebra_test::init(); @@ -389,10 +382,7 @@ fn failure_regex_timeout_continuous_output() { const TEST_CMD: &str = "hexdump"; // Skip the test if the test system does not have the command if !is_command_available(TEST_CMD, &["/dev/null"]) { - panic!( - "skipping test: command not available\n\ - fake panic message: Logged a failure message" - ); + return; } // Without '-v', hexdump hides duplicate lines. But we want duplicate lines @@ -406,9 +396,16 @@ fn failure_regex_timeout_continuous_output() { // We need to use expect_stdout_line_matches, because wait_with_output ignores timeouts. // We use a non-matching regex, to trigger the timeout and the failure panic. - child + let expected_error = child .expect_stdout_line_matches("this regex should not match") .unwrap_err(); + + let expected_error = format!("{:?}", expected_error); + assert!( + expected_error.contains("Logged a failure message"), + "error did not contain expected failure message: {}", + expected_error, + ); } /// Make sure failure regexes are checked when a child process prints a failure message to stdout, @@ -423,10 +420,7 @@ fn failure_regex_matches_stdout_failure_message_wait_for_output() { const TEST_CMD: &str = "echo"; // Skip the test if the test system does not have the command if !is_command_available(TEST_CMD, &[]) { - panic!( - "skipping test: command not available\n\ - fake panic message: Logged a failure message" - ); + return; } let child = tempdir() @@ -447,17 +441,13 @@ fn failure_regex_matches_stdout_failure_message_wait_for_output() { /// Make sure failure regex iters detect when a child process prints a failure message to stdout, /// and panic with a test failure message. #[test] -#[should_panic(expected = "Logged a failure message")] fn failure_regex_iter_matches_stdout_failure_message() { let _init_guard = zebra_test::init(); const TEST_CMD: &str = "echo"; // Skip the test if the test system does not have the command if !is_command_available(TEST_CMD, &[]) { - panic!( - "skipping test: command not available\n\ - fake panic message: Logged a failure message" - ); + return; } let mut child = tempdir() @@ -472,9 +462,16 @@ fn failure_regex_iter_matches_stdout_failure_message() { // Any method that reads output should work here. // We use a non-matching regex, to trigger the failure panic. - child + let expected_error = child .expect_stdout_line_matches("this regex should not match") .unwrap_err(); + + let expected_error = format!("{:?}", expected_error); + assert!( + expected_error.contains("Logged a failure message"), + "error did not contain expected failure message: {}", + expected_error, + ); } /// Make sure ignore regexes override failure regexes. diff --git a/zebrad/tests/acceptance.rs b/zebrad/tests/acceptance.rs index 94b042f78cd..92af794865c 100644 --- a/zebrad/tests/acceptance.rs +++ b/zebrad/tests/acceptance.rs @@ -258,7 +258,7 @@ fn start_no_args() -> Result<()> { // Run the program and kill it after a few seconds std::thread::sleep(LAUNCH_DELAY); - child.kill()?; + child.kill(false)?; let output = child.wait_with_output()?; let output = output.assert_failure()?; @@ -285,7 +285,7 @@ fn start_args() -> Result<()> { let mut child = testdir.spawn_child(args!["start"])?; // Run the program and kill it after a few seconds std::thread::sleep(LAUNCH_DELAY); - child.kill()?; + child.kill(false)?; let output = child.wait_with_output()?; // Make sure the command was killed @@ -312,7 +312,7 @@ fn persistent_mode() -> Result<()> { // Run the program and kill it after a few seconds std::thread::sleep(LAUNCH_DELAY); - child.kill()?; + child.kill(false)?; let output = child.wait_with_output()?; // Make sure the command was killed @@ -379,7 +379,7 @@ fn ephemeral(cache_dir_config: EphemeralConfig, cache_dir_check: EphemeralCheck) .spawn_child(args!["start"])?; // Run the program and kill it after a few seconds std::thread::sleep(LAUNCH_DELAY); - child.kill()?; + child.kill(false)?; let output = child.wait_with_output()?; // Make sure the command was killed @@ -545,7 +545,7 @@ fn valid_generated_config(command: &str, expect_stdout_line_contains: &str) -> R // Run command using temp dir and kill it after a few seconds let mut child = testdir.spawn_child(args![command])?; std::thread::sleep(LAUNCH_DELAY); - child.kill()?; + child.kill(false)?; let output = child.wait_with_output()?; let output = output.assert_failure()?; @@ -627,8 +627,11 @@ fn invalid_generated_config() -> Result<()> { // and terminate. std::thread::sleep(Duration::from_secs(2)); if child.is_running() { - child.kill()?; - return Err(eyre!("Zebra should not be running anymore.")); + // We're going to error anyway, so return an error that makes sense to the developer. + child.kill(true)?; + return Err(eyre!( + "Zebra should have exited after reading the invalid config" + )); } let output = child.wait_with_output()?; @@ -652,7 +655,7 @@ fn stored_config_works() -> Result<()> { child.expect_stdout_line_matches("Starting zebrad".to_string())?; // finish - child.kill()?; + child.kill(false)?; let output = child.wait_with_output()?; let output = output.assert_failure()?; @@ -1002,7 +1005,7 @@ async fn metrics_endpoint() -> Result<()> { assert!(res.status().is_success()); let body = hyper::body::to_bytes(res).await; let (body, mut child) = child.kill_on_error(body)?; - child.kill()?; + child.kill(false)?; let output = child.wait_with_output()?; let output = output.assert_failure()?; @@ -1077,7 +1080,7 @@ async fn tracing_endpoint() -> Result<()> { let tracing_body = hyper::body::to_bytes(tracing_res).await; let (tracing_body, mut child) = child.kill_on_error(tracing_body)?; - child.kill()?; + child.kill(false)?; let output = child.wait_with_output()?; let output = output.assert_failure()?; @@ -1175,7 +1178,7 @@ async fn rpc_endpoint() -> Result<()> { let subversion = parsed["result"]["subversion"].as_str().unwrap(); assert!(subversion.contains("Zebra"), "Got {}", subversion); - child.kill()?; + child.kill(false)?; let output = child.wait_with_output()?; let output = output.assert_failure()?; @@ -1497,10 +1500,10 @@ fn lightwalletd_integration_test(test_type: LightwalletdTestType) -> Result<()> // // zcash/lightwalletd exits by itself, but // adityapk00/lightwalletd keeps on going, so it gets killed by the test harness. - zebrad.kill()?; + zebrad.kill(false)?; if let Some(mut lightwalletd) = lightwalletd { - lightwalletd.kill()?; + lightwalletd.kill(false)?; let lightwalletd_output = lightwalletd.wait_with_output()?.assert_failure()?; @@ -1712,7 +1715,7 @@ where // Wait a few seconds and kill first node. // Second node is terminated by panic, no need to kill. std::thread::sleep(LAUNCH_DELAY); - let node1_kill_res = node1.kill(); + let node1_kill_res = node1.kill(false); let (_, mut node2) = node2.kill_on_error(node1_kill_res)?; // node2 should have panicked due to a conflict. Kill it here anyway, so it @@ -1865,7 +1868,7 @@ async fn delete_old_databases() -> Result<()> { assert!(outside_dir.as_path().exists()); // finish - child.kill()?; + child.kill(false)?; let output = child.wait_with_output()?; let output = output.assert_failure()?; diff --git a/zebrad/tests/common/sync.rs b/zebrad/tests/common/sync.rs index a9a8d283bd8..1a03f49a42a 100644 --- a/zebrad/tests/common/sync.rs +++ b/zebrad/tests/common/sync.rs @@ -248,7 +248,7 @@ pub fn sync_until( // make sure the child process is dead // if it has already exited, ignore that error - let _ = child.kill(); + let _ = child.kill(true); Ok(child.dir.take().expect("dir was not already taken")) } else { @@ -389,7 +389,7 @@ pub fn create_cached_database_height( child.expect_stdout_line_matches(stop_regex)?; - child.kill()?; + child.kill(true)?; Ok(()) } From 04fed99ccadd1491e581700910c8edc859a252c6 Mon Sep 17 00:00:00 2001 From: teor Date: Wed, 24 Aug 2022 13:03:56 +1000 Subject: [PATCH 02/10] Add output logs to test context, and add tests for that --- zebra-test/src/command.rs | 63 +++++++++++++++++++++++------- zebra-test/tests/command.rs | 78 +++++++++++++++++++++++++++++++++++++ 2 files changed, 126 insertions(+), 15 deletions(-) diff --git a/zebra-test/src/command.rs b/zebra-test/src/command.rs index e933ec81bc6..47527caf05d 100644 --- a/zebra-test/src/command.rs +++ b/zebra-test/src/command.rs @@ -523,7 +523,7 @@ impl TestChild { if wrote_lines { // Write an empty line, to make output more readable - self.write_to_test_logs(""); + Self::write_to_test_logs("", self.bypass_test_capture); } } @@ -533,7 +533,7 @@ impl TestChild { while self.wait_for_stderr_line(None) {} if wrote_lines { - self.write_to_test_logs(""); + Self::write_to_test_logs("", self.bypass_test_capture); } } @@ -554,11 +554,17 @@ impl TestChild { self.apply_failure_regexes_to_outputs(); if let Some(line) = self.stdout.as_mut().and_then(|iter| iter.next()) { + let bypass_test_capture = self.bypass_test_capture; + if let Some(write_context) = write_context.into() { - self.write_to_test_logs(write_context); + Self::write_to_test_logs(write_context, bypass_test_capture); } - self.write_to_test_logs(line.expect("failure reading test process logs")); + Self::write_to_test_logs( + line.context_from(self) + .expect("failure reading test process logs"), + bypass_test_capture, + ); return true; } @@ -580,11 +586,17 @@ impl TestChild { self.apply_failure_regexes_to_outputs(); if let Some(line) = self.stderr.as_mut().and_then(|iter| iter.next()) { + let bypass_test_capture = self.bypass_test_capture; + if let Some(write_context) = write_context.into() { - self.write_to_test_logs(write_context); + Self::write_to_test_logs(write_context, bypass_test_capture); } - self.write_to_test_logs(line.expect("failure reading test process logs")); + Self::write_to_test_logs( + line.context_from(self) + .expect("failure reading test process logs"), + bypass_test_capture, + ); return true; } @@ -681,10 +693,17 @@ impl TestChild { match self.expect_line_matching_regex_set(&mut lines, success_regex, "stdout") { Ok(()) => { + // Replace the log lines for the next check self.stdout = Some(lines); Ok(self) } - Err(report) => Err(report), + Err(report) => { + // Read all the log lines for error context + self.stdout = Some(lines); + let error = Err(report).context_from(self); + + error + } } } @@ -708,10 +727,17 @@ impl TestChild { match self.expect_line_matching_regex_set(&mut lines, success_regex, "stderr") { Ok(()) => { + // Replace the log lines for the next check self.stderr = Some(lines); Ok(self) } - Err(report) => Err(report), + Err(report) => { + // Read all the log lines for error context + self.stderr = Some(lines); + let error = Err(report).context_from(self); + + error + } } } @@ -789,7 +815,7 @@ impl TestChild { }; // Since we're about to discard this line write it to stdout. - self.write_to_test_logs(&line); + Self::write_to_test_logs(&line, self.bypass_test_capture); if success_regexes.is_match(&line) { return Ok(()); @@ -800,14 +826,13 @@ impl TestChild { // If the process exits between is_running and kill, we will see // spurious errors here. So we want to ignore "no such process" // errors from kill. - self.kill(true)?; + self.kill(true).context_from(self)?; } let report = eyre!( "{} of command did not contain any matches for the given regex", stream_name ) - .context_from(self) .with_section(|| format!("{:#?}", success_regexes.patterns()).header("Match Regex:")); Err(report) @@ -821,11 +846,11 @@ impl TestChild { /// May cause weird reordering for stdout / stderr. /// Uses stdout even if the original lines were from stderr. #[allow(clippy::print_stdout)] - fn write_to_test_logs(&self, line: S) + fn write_to_test_logs(line: S, bypass_test_capture: bool) where S: AsRef, { - write_to_test_logs(line, self.bypass_test_capture); + write_to_test_logs(line, bypass_test_capture); } /// Kill `child`, wait for its output, and use that output as the context for @@ -1224,24 +1249,32 @@ impl ContextFrom<&mut TestChild> for Report { if let Some(stdout) = &mut source.stdout { for line in stdout { - let line = line.expect("failure reading test process logs"); + let line = line.unwrap_or_else(|error| { + format!("failure reading test process logs: {:?}", error) + }); let _ = writeln!(&mut stdout_buf, "{}", line); } + source.stdout = None; } else if let Some(child) = &mut source.child { if let Some(stdout) = &mut child.stdout { let _ = stdout.read_to_string(&mut stdout_buf); } + child.stdout = None; } if let Some(stderr) = &mut source.stderr { for line in stderr { - let line = line.expect("failure reading test process logs"); + let line = line.unwrap_or_else(|error| { + format!("failure reading test process logs: {:?}", error) + }); let _ = writeln!(&mut stderr_buf, "{}", line); } + source.stderr = None; } else if let Some(child) = &mut source.child { if let Some(stderr) = &mut child.stderr { let _ = stderr.read_to_string(&mut stderr_buf); } + child.stderr = None; } self.section(stdout_buf.header("Unread Stdout:")) diff --git a/zebra-test/tests/command.rs b/zebra-test/tests/command.rs index 61ef41ce3c1..449058bc1cb 100644 --- a/zebra-test/tests/command.rs +++ b/zebra-test/tests/command.rs @@ -282,6 +282,84 @@ fn failure_regex_matches_stdout_failure_message_drop() { // Drop should read all unread output. } +/// When checking output, make sure failure regexes detect when a child process +/// prints a failure message to stdout, then they fail the test, +/// and read any extra multi-line output from the child process. +#[test] +fn failure_regex_reads_multi_line_output_on_expect_line() { + let _init_guard = zebra_test::init(); + + const TEST_CMD: &str = "echo"; + // Skip the test if the test system does not have the command + if !is_command_available(TEST_CMD, &[]) { + return; + } + + let mut child = tempdir() + .unwrap() + .spawn_child_with_command( + TEST_CMD, + args![ + "failure_message\n\ + multi-line failure message" + ], + ) + .unwrap() + .with_timeout(Duration::from_secs(5)) + .with_failure_regex_set("failure_message", RegexSet::empty()); + + // Any method that reads output should work here. + // We use a non-matching regex, to trigger the failure panic. + let expected_error = child + .expect_stdout_line_matches("this regex should not match") + .unwrap_err(); + + let expected_error = format!("{:?}", expected_error); + assert!( + expected_error.contains( + "\ +Unread Stdout: + multi-line failure message\ + " + ), + "error did not contain expected failure message: {}", + expected_error, + ); +} + +/// On drop, make sure failure regexes detect when a child process prints a failure message. +/// then they fail the test, and read any extra multi-line output from the child process. +#[test] +#[should_panic(expected = "Unread Stdout: + multi-line failure message")] +fn failure_regex_reads_multi_line_output_on_drop() { + let _init_guard = zebra_test::init(); + + const TEST_CMD: &str = "echo"; + // Skip the test if the test system does not have the command + if !is_command_available(TEST_CMD, &[]) { + return; + } + + let _child = tempdir() + .unwrap() + .spawn_child_with_command( + TEST_CMD, + args![ + "failure_message\n\ + multi-line failure message" + ], + ) + .unwrap() + .with_timeout(Duration::from_secs(5)) + .with_failure_regex_set("failure_message", RegexSet::empty()); + + // Give the child process enough time to print its output. + std::thread::sleep(Duration::from_secs(1)); + + // Drop should read all unread output. +} + /// Make sure failure regexes detect when a child process prints a failure message to stdout, /// then the child process is killed. #[test] From 39997b8202afbea59e64c3c717460018cfd29420 Mon Sep 17 00:00:00 2001 From: teor Date: Wed, 24 Aug 2022 13:05:46 +1000 Subject: [PATCH 03/10] Let empty test child logs be read again (and produce empty output) --- zebra-test/src/command.rs | 4 ---- 1 file changed, 4 deletions(-) diff --git a/zebra-test/src/command.rs b/zebra-test/src/command.rs index 47527caf05d..68c3b6499b8 100644 --- a/zebra-test/src/command.rs +++ b/zebra-test/src/command.rs @@ -1254,12 +1254,10 @@ impl ContextFrom<&mut TestChild> for Report { }); let _ = writeln!(&mut stdout_buf, "{}", line); } - source.stdout = None; } else if let Some(child) = &mut source.child { if let Some(stdout) = &mut child.stdout { let _ = stdout.read_to_string(&mut stdout_buf); } - child.stdout = None; } if let Some(stderr) = &mut source.stderr { @@ -1269,12 +1267,10 @@ impl ContextFrom<&mut TestChild> for Report { }); let _ = writeln!(&mut stderr_buf, "{}", line); } - source.stderr = None; } else if let Some(child) = &mut source.child { if let Some(stderr) = &mut child.stderr { let _ = stderr.read_to_string(&mut stderr_buf); } - child.stderr = None; } self.section(stdout_buf.header("Unread Stdout:")) From 36c6660b752b91cb6ecd54d1a3eede2b93b0fb12 Mon Sep 17 00:00:00 2001 From: teor Date: Wed, 24 Aug 2022 13:18:03 +1000 Subject: [PATCH 04/10] Ignore missing test children when killing with ignore_exited --- zebra-test/src/command.rs | 20 +++++++++++++++++--- 1 file changed, 17 insertions(+), 3 deletions(-) diff --git a/zebra-test/src/command.rs b/zebra-test/src/command.rs index 68c3b6499b8..3cbc0bf39a9 100644 --- a/zebra-test/src/command.rs +++ b/zebra-test/src/command.rs @@ -483,7 +483,21 @@ impl TestChild { pub fn kill(&mut self, ignore_exited: bool) -> Result<()> { let child = match self.child.as_mut() { Some(child) => child, - None => return Err(eyre!("child was already taken")).context_from(self.as_mut()), + None if ignore_exited => { + Self::write_to_test_logs( + "test child was already taken\n\ + ignoring kill because ignore_exited is true", + self.bypass_test_capture, + ); + return Ok(()); + } + None => { + return Err(eyre!( + "test child was already taken\n\ + call kill() once for each child process, or set ignore_exited to true" + )) + .context_from(self.as_mut()) + } }; /// SPANDOC: Killing child process @@ -622,8 +636,8 @@ impl TestChild { // either in `context_from`, or on drop. None => { return Err(eyre!( - "child was already taken.\n\ - wait_with_output can only be called once for each child process", + "test child was already taken\n\ + wait_with_output can only be called once for each child process", )) .context_from(self.as_mut()) } From 9d4c709d714ae85ac0de4cda112c491ea153ebd0 Mon Sep 17 00:00:00 2001 From: teor Date: Wed, 24 Aug 2022 13:20:04 +1000 Subject: [PATCH 05/10] Fix a clippy lint --- zebra-test/src/command.rs | 8 ++------ 1 file changed, 2 insertions(+), 6 deletions(-) diff --git a/zebra-test/src/command.rs b/zebra-test/src/command.rs index 3cbc0bf39a9..9f1e5ffac7f 100644 --- a/zebra-test/src/command.rs +++ b/zebra-test/src/command.rs @@ -714,9 +714,7 @@ impl TestChild { Err(report) => { // Read all the log lines for error context self.stdout = Some(lines); - let error = Err(report).context_from(self); - - error + Err(report).context_from(self) } } } @@ -748,9 +746,7 @@ impl TestChild { Err(report) => { // Read all the log lines for error context self.stderr = Some(lines); - let error = Err(report).context_from(self); - - error + Err(report).context_from(self) } } } From 9006e6811c0c7fbf816f8974148c1f9c77f49b31 Mon Sep 17 00:00:00 2001 From: teor Date: Thu, 25 Aug 2022 09:46:04 +1000 Subject: [PATCH 06/10] Rename `line` to `line_result` for clarity --- zebra-test/src/command.rs | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/zebra-test/src/command.rs b/zebra-test/src/command.rs index 9f1e5ffac7f..b32b205d10d 100644 --- a/zebra-test/src/command.rs +++ b/zebra-test/src/command.rs @@ -567,7 +567,7 @@ impl TestChild { { self.apply_failure_regexes_to_outputs(); - if let Some(line) = self.stdout.as_mut().and_then(|iter| iter.next()) { + if let Some(line_result) = self.stdout.as_mut().and_then(|iter| iter.next()) { let bypass_test_capture = self.bypass_test_capture; if let Some(write_context) = write_context.into() { @@ -575,7 +575,8 @@ impl TestChild { } Self::write_to_test_logs( - line.context_from(self) + line_result + .context_from(self) .expect("failure reading test process logs"), bypass_test_capture, ); @@ -599,7 +600,7 @@ impl TestChild { { self.apply_failure_regexes_to_outputs(); - if let Some(line) = self.stderr.as_mut().and_then(|iter| iter.next()) { + if let Some(line_result) = self.stderr.as_mut().and_then(|iter| iter.next()) { let bypass_test_capture = self.bypass_test_capture; if let Some(write_context) = write_context.into() { @@ -607,7 +608,8 @@ impl TestChild { } Self::write_to_test_logs( - line.context_from(self) + line_result + .context_from(self) .expect("failure reading test process logs"), bypass_test_capture, ); From ac15152daef98096f0cec0fd9c69d3d2eb93e7bd Mon Sep 17 00:00:00 2001 From: teor Date: Thu, 25 Aug 2022 09:47:14 +1000 Subject: [PATCH 07/10] Revert a redundant context_from() on kill() --- zebra-test/src/command.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/zebra-test/src/command.rs b/zebra-test/src/command.rs index b32b205d10d..596997d1de3 100644 --- a/zebra-test/src/command.rs +++ b/zebra-test/src/command.rs @@ -838,7 +838,7 @@ impl TestChild { // If the process exits between is_running and kill, we will see // spurious errors here. So we want to ignore "no such process" // errors from kill. - self.kill(true).context_from(self)?; + self.kill(true)?; } let report = eyre!( From 23ef6736b3821f5a444fa23713b051917a6d8f6d Mon Sep 17 00:00:00 2001 From: teor Date: Thu, 25 Aug 2022 09:54:13 +1000 Subject: [PATCH 08/10] Only ignore "no such process" kill() errors in sync_until() tests --- zebrad/tests/common/sync.rs | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/zebrad/tests/common/sync.rs b/zebrad/tests/common/sync.rs index 1a03f49a42a..e9d7c69f30a 100644 --- a/zebrad/tests/common/sync.rs +++ b/zebrad/tests/common/sync.rs @@ -248,7 +248,7 @@ pub fn sync_until( // make sure the child process is dead // if it has already exited, ignore that error - let _ = child.kill(true); + child.kill(true)?; Ok(child.dir.take().expect("dir was not already taken")) } else { @@ -389,6 +389,8 @@ pub fn create_cached_database_height( child.expect_stdout_line_matches(stop_regex)?; + // make sure the child process is dead + // if it has already exited, ignore that error child.kill(true)?; Ok(()) From 3eeb3a30b150326f720bf9b2b3be0443298ab6e6 Mon Sep 17 00:00:00 2001 From: teor Date: Fri, 26 Aug 2022 14:14:19 +1000 Subject: [PATCH 09/10] Log the command timeout when an acceptance test fails --- Cargo.lock | 1 + zebra-test/Cargo.toml | 2 ++ zebra-test/src/command.rs | 17 +++++++++++++++-- 3 files changed, 18 insertions(+), 2 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index c1943aea5a7..b5f4fc6e2a1 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6543,6 +6543,7 @@ dependencies = [ "color-eyre", "futures", "hex", + "humantime", "indexmap", "insta", "lazy_static", diff --git a/zebra-test/Cargo.toml b/zebra-test/Cargo.toml index 1538a87b410..a68db9466dd 100644 --- a/zebra-test/Cargo.toml +++ b/zebra-test/Cargo.toml @@ -26,9 +26,11 @@ color-eyre = "0.6.1" # Enable a feature that makes tinyvec compile much faster. tinyvec = { version = "1.6.0", features = ["rustc_1_55"] } +humantime = "2.1.0" owo-colors = "3.4.0" spandoc = "0.2.2" thiserror = "1.0.32" + tracing-subscriber = { version = "0.3.11", features = ["env-filter"] } tracing-error = "0.2.0" tracing = "0.1.31" diff --git a/zebra-test/src/command.rs b/zebra-test/src/command.rs index 596997d1de3..c5a8d1d7b51 100644 --- a/zebra-test/src/command.rs +++ b/zebra-test/src/command.rs @@ -107,6 +107,7 @@ impl CommandExt for Command { failure_regexes: RegexSet::empty(), ignore_regexes: RegexSet::empty(), deadline: None, + timeout: None, bypass_test_capture: false, }) } @@ -221,6 +222,11 @@ pub struct TestChild { /// Only checked when the command outputs each new line (#1140). pub deadline: Option, + /// The timeout for this command to finish. + /// + /// Only used for debugging output. + pub timeout: Option, + /// If true, write child output directly to standard output, /// bypassing the Rust test harness output capture. bypass_test_capture: bool, @@ -678,7 +684,9 @@ impl TestChild { /// /// Does not apply to `wait_with_output`. pub fn with_timeout(mut self, timeout: Duration) -> Self { + self.timeout = Some(timeout); self.deadline = Some(Instant::now() + timeout); + self } @@ -841,9 +849,14 @@ impl TestChild { self.kill(true)?; } + let timeout = + humantime::format_duration(self.timeout.expect("already checked past_deadline()")); + let report = eyre!( - "{} of command did not contain any matches for the given regex", - stream_name + "{} of command did not log any matches for the given regex,\n\ + within the {:?} command timeout", + stream_name, + timeout, ) .with_section(|| format!("{:#?}", success_regexes.patterns()).header("Match Regex:")); From b76450e1451169cb42c99fc40d3318a84e36d40d Mon Sep 17 00:00:00 2001 From: Alfredo Garcia Date: Fri, 26 Aug 2022 12:24:19 -0300 Subject: [PATCH 10/10] fix clippy --- zebra-test/src/command.rs | 1 + 1 file changed, 1 insertion(+) diff --git a/zebra-test/src/command.rs b/zebra-test/src/command.rs index c5a8d1d7b51..d56c94716c2 100644 --- a/zebra-test/src/command.rs +++ b/zebra-test/src/command.rs @@ -812,6 +812,7 @@ impl TestChild { /// Note: the timeout is only checked after each full line is received from /// the child (#1140). #[instrument(skip(self, lines))] + #[allow(clippy::unwrap_in_result)] pub fn expect_line_matching_regexes( &mut self, lines: &mut L,