From a5d7b9c1e0a924ba5b6b954e8adfe256af108c93 Mon Sep 17 00:00:00 2001 From: teor Date: Wed, 23 Mar 2022 09:53:24 +1000 Subject: [PATCH] T2. add(test): add test API that checks process logs for failures (#3899) * 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 --- zebra-test/src/command.rs | 478 ++++++++++++++++++++++++++++++------ zebra-test/tests/command.rs | 266 +++++++++++++++++++- zebrad/tests/common/sync.rs | 2 +- 3 files changed, 672 insertions(+), 74 deletions(-) diff --git a/zebra-test/src/command.rs b/zebra-test/src/command.rs index d89361e2..6d0561c0 100644 --- a/zebra-test/src/command.rs +++ b/zebra-test/src/command.rs @@ -3,9 +3,9 @@ use std::{ convert::Infallible as NoDir, fmt::{self, Debug, Write as _}, - io::{BufRead, BufReader, Lines, Read, Write as _}, + io::{BufRead, BufReader, Read, Write as _}, path::Path, - process::{Child, ChildStderr, ChildStdout, Command, ExitStatus, Output, Stdio}, + process::{Child, Command, ExitStatus, Output, Stdio}, time::{Duration, Instant}, }; @@ -25,6 +25,11 @@ use to_regex::{CollectRegexSet, ToRegex}; use self::to_regex::ToRegexSet; +/// A super-trait for [`Iterator`] + [`Debug`]. +pub trait IteratorDebug: Iterator + Debug {} + +impl IteratorDebug for T where T: Iterator + Debug {} + /// Runs a command pub fn test_cmd(command_path: &str, tempdir: &Path) -> Result { let mut cmd = Command::new(command_path); @@ -33,6 +38,8 @@ pub fn test_cmd(command_path: &str, tempdir: &Path) -> Result { Ok(cmd) } +// TODO: split these extensions into their own module + /// Wrappers for `Command` methods to integrate with [`zebra_test`]. pub trait CommandExt { /// wrapper for `status` fn on `Command` that constructs informative error @@ -91,12 +98,13 @@ impl CommandExt for Command { .with_section(|| cmd.clone().header("Command:"))?; Ok(TestChild { - child, + dir: Some(dir), cmd, - dir, - deadline: None, + child: Some(child), stdout: None, stderr: None, + failure_regexes: RegexSet::empty(), + deadline: None, bypass_test_capture: false, }) } @@ -162,22 +170,39 @@ impl TestStatus { } /// A test command child process. +// TODO: split this struct into its own module (or multiple modules) #[derive(Debug)] pub struct TestChild { /// The working directory of the command. - pub dir: T, + /// + /// `None` when the command has been waited on, + /// and its output has been taken. + pub dir: Option, /// The original command string. pub cmd: String, /// The child process itself. - pub child: Child, + /// + /// `None` when the command has been waited on, + /// and its output has been taken. + pub child: Option, /// The standard output stream of the child process. - pub stdout: Option>>, + /// + /// TODO: replace with `Option. + pub stdout: Option>>>, /// The standard error stream of the child process. - pub stderr: Option>>, + pub stderr: Option>>>, + + /// Command outputs which indicate test failure. + /// + /// This list of regexes is matches against `stdout` or `stderr`, + /// in every method that reads command output. + /// + /// If any line matches any failure regex, the test fails. + failure_regexes: RegexSet, /// The deadline for this command to finish. /// @@ -189,7 +214,139 @@ pub struct TestChild { bypass_test_capture: bool, } +/// Checks command output log `line` from `cmd` against a `failure_regexes` regex set, +/// and panics if any regex matches the log line. +/// +/// # Panics +/// +/// - if any stdout or stderr lines match any failure regex +pub fn check_failure_regexes( + line: &std::io::Result, + failure_regexes: &RegexSet, + cmd: &str, +) { + if let Ok(line) = line { + let failure_matches = failure_regexes.matches(line); + let failure_matches: Vec<&str> = failure_matches + .iter() + .map(|index| failure_regexes.patterns()[index].as_str()) + .collect(); + + assert!( + failure_matches.is_empty(), + "test command:\n\ + {cmd}\n\n\ + Logged a failure message:\n\ + {line}\n\n\ + Matching failure regex: \ + {failure_matches:#?}\n\n\ + All Failure regexes: \ + {:#?}\n", + failure_regexes.patterns(), + ); + } +} + impl TestChild { + /// Sets up command output so it is checked against a failure regex set. + /// The failure regexes are ignored by `wait_with_output`. + /// + /// [`TestChild::with_failure_regexes`] wrapper for strings, [`Regex`]es, + /// and [`RegexSet`]s. + /// + /// # Panics + /// + /// - adds a panic to any method that reads output, + /// if any stdout or stderr lines match any failure regex + pub fn with_failure_regex_set(self, failure_regexes: R) -> Self + where + R: ToRegexSet, + { + let failure_regexes = failure_regexes + .to_regex_set() + .expect("regexes must be valid"); + + self.with_failure_regexes(failure_regexes) + } + + /// Sets up command output so it is checked against a failure regex set. + /// The failure regexes are ignored by `wait_with_output`. + /// + /// [`TestChild::with_failure_regexes`] wrapper for regular expression iterators. + /// + /// # Panics + /// + /// - adds a panic to any method that reads output, + /// if any stdout or stderr lines match any failure regex + pub fn with_failure_regex_iter(self, failure_regexes: I) -> Self + where + I: CollectRegexSet, + { + let failure_regexes = failure_regexes + .collect_regex_set() + .expect("regexes must be valid"); + + self.with_failure_regexes(failure_regexes) + } + + /// Sets up command output so it is checked against a failure regex set. + /// The failure regexes are ignored by `wait_with_output`. + /// + /// # Panics + /// + /// - adds a panic to any method that reads output, + /// if any stdout or stderr lines match any failure regex + pub fn with_failure_regexes(mut self, failure_regexes: RegexSet) -> Self { + self.failure_regexes = failure_regexes; + + self.apply_failure_regexes_to_outputs(); + + self + } + + /// Applies the failure regex set to command output. + /// The failure regexes are ignored by `wait_with_output`. + /// + /// # Panics + /// + /// - adds a panic to any method that reads output, + /// if any stdout or stderr lines match any failure regex + pub fn apply_failure_regexes_to_outputs(&mut self) { + if self.stdout.is_none() { + self.stdout = self + .child + .as_mut() + .and_then(|child| child.stdout.take()) + .map(|output| self.map_into_string_lines(output)) + } + + if self.stderr.is_none() { + self.stderr = self + .child + .as_mut() + .and_then(|child| child.stderr.take()) + .map(|output| self.map_into_string_lines(output)) + } + } + + /// Maps a reader into a string line iterator. + fn map_into_string_lines( + &self, + reader: R, + ) -> Box>> + where + R: Read + Debug + 'static, + { + let failure_regexes = self.failure_regexes.clone(); + let cmd = self.cmd.clone(); + + let reader = BufReader::new(reader); + let lines = BufRead::lines(reader) + .inspect(move |line| check_failure_regexes(line, &failure_regexes, &cmd)); + + Box::new(lines) as _ + } + /// Kill the child process. /// /// ## BUGS @@ -198,27 +355,156 @@ impl TestChild { /// processes that have panicked. See #1781. #[spandoc::spandoc] pub fn kill(&mut self) -> 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 - self.child.kill().context_from(self)?; + child.kill().context_from(self.as_mut())?; Ok(()) } + /// Kill the process, and consume all its remaining output. + /// + /// Returns the result of the kill. + pub fn kill_and_consume_output(&mut self) -> 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(); + + // Read unread child output. + // + // 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()); + + while self.wait_for_stdout_line(None) {} + + if wrote_lines { + self.write_to_test_logs(""); + } + } + + if self.child.is_some() || self.stderr.is_some() { + let wrote_lines = self.wait_for_stderr_line("Child Stderr:".to_string()); + + while self.wait_for_stderr_line(None) {} + + if wrote_lines { + self.write_to_test_logs(""); + } + } + + kill_result + } + + /// Waits until a line of standard output is available, then consumes it. + /// + /// If there is a line, and `write_context` is `Some`, writes the context to the test logs. + /// Then writes the line to the test logs. + /// + /// Returns `true` if a line was available, + /// or `false` if the standard output has finished. + pub fn wait_for_stdout_line(&mut self, write_context: OptS) -> bool + where + OptS: Into>, + { + self.apply_failure_regexes_to_outputs(); + + if let Some(Ok(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); + + return true; + } + + false + } + + /// Waits until a line of standard error is available, then consumes it. + /// + /// If there is a line, and `write_context` is `Some`, writes the context to the test logs. + /// Then writes the line to the test logs. + /// + /// Returns `true` if a line was available, + /// or `false` if the standard error has finished. + pub fn wait_for_stderr_line(&mut self, write_context: OptS) -> bool + where + OptS: Into>, + { + self.apply_failure_regexes_to_outputs(); + + if let Some(Ok(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); + + return true; + } + + false + } + /// Waits for the child process to exit, then returns its output. /// + /// The other test child output methods take one or both outputs, + /// making them unavailable to this method. + /// /// Ignores any configured timeouts. + /// + /// Returns an error if the child has already been taken, + /// or both outputs have already been taken. #[spandoc::spandoc] - pub fn wait_with_output(self) -> Result> { + pub fn wait_with_output(mut self) -> Result> { + let child = match self.child.take() { + Some(child) => child, + + // Also checks the taken child output for failure regexes, + // 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", + )) + .context_from(self.as_mut()) + } + }; + + // TODO: fix the usage in the zebrad acceptance tests, or fix the bugs in TestChild, + // then re-enable this check + /* + if child.stdout.is_none() && child.stderr.is_none() { + // Also checks the taken child output for failure regexes, + // either in `context_from`, or on drop. + return Err(eyre!( + "child stdout and stderr were already taken.\n\ + Hint: choose one of these alternatives:\n\ + 1. use wait_with_output once on each child process, or\n\ + 2. replace wait_with_output with the other TestChild output methods" + )) + .context_from(self.as_mut()); + }; + */ + /// SPANDOC: waiting for command to exit - let output = self.child.wait_with_output().with_section({ + let output = child.wait_with_output().with_section({ let cmd = self.cmd.clone(); || cmd.header("Command:") })?; Ok(TestOutput { output, - cmd: self.cmd, - dir: Some(self.dir), + cmd: self.cmd.clone(), + dir: self.dir.take(), }) } @@ -237,31 +523,24 @@ impl TestChild { self } - /// Checks each line of the child's stdout against `regex`, and returns Ok + /// Checks each line of the child's stdout against `success_regex`, and returns Ok /// if a line matches. /// /// Kills the child on error, or after the configured timeout has elapsed. /// See `expect_line_matching` for details. #[instrument(skip(self))] - pub fn expect_stdout_line_matches(&mut self, regex: R) -> Result<&mut Self> + pub fn expect_stdout_line_matches(&mut self, success_regex: R) -> Result<&mut Self> where R: ToRegex + Debug, { - if self.stdout.is_none() { - self.stdout = self - .child - .stdout - .take() - .map(BufReader::new) - .map(BufRead::lines) - } + self.apply_failure_regexes_to_outputs(); let mut lines = self .stdout .take() .expect("child must capture stdout to call expect_stdout_line_matches, and it can't be called again after an error"); - match self.expect_line_matching_regex_set(&mut lines, regex, "stdout") { + match self.expect_line_matching_regex_set(&mut lines, success_regex, "stdout") { Ok(()) => { self.stdout = Some(lines); Ok(self) @@ -270,31 +549,24 @@ impl TestChild { } } - /// Checks each line of the child's stderr against `regex`, and returns Ok + /// Checks each line of the child's stderr against `success_regex`, and returns Ok /// if a line matches. /// /// Kills the child on error, or after the configured timeout has elapsed. /// See `expect_line_matching` for details. #[instrument(skip(self))] - pub fn expect_stderr_line_matches(&mut self, regex: R) -> Result<&mut Self> + pub fn expect_stderr_line_matches(&mut self, success_regex: R) -> Result<&mut Self> where R: ToRegex + Debug, { - if self.stderr.is_none() { - self.stderr = self - .child - .stderr - .take() - .map(BufReader::new) - .map(BufRead::lines) - } + self.apply_failure_regexes_to_outputs(); let mut lines = self .stderr .take() .expect("child must capture stderr to call expect_stderr_line_matches, and it can't be called again after an error"); - match self.expect_line_matching_regex_set(&mut lines, regex, "stderr") { + match self.expect_line_matching_regex_set(&mut lines, success_regex, "stderr") { Ok(()) => { self.stderr = Some(lines); Ok(self) @@ -303,42 +575,48 @@ impl TestChild { } } + /// Checks each line in `lines` against a regex set, and returns Ok if a line matches. + /// /// [`TestChild::expect_line_matching`] wrapper for strings, [`Regex`]es, /// and [`RegexSet`]s. pub fn expect_line_matching_regex_set( &mut self, lines: &mut L, - regex_set: R, + success_regexes: R, stream_name: &str, ) -> Result<()> where L: Iterator>, R: ToRegexSet, { - let regex_set = regex_set.to_regex_set().expect("regexes must be valid"); + let success_regexes = success_regexes + .to_regex_set() + .expect("regexes must be valid"); - self.expect_line_matching(lines, regex_set, stream_name) + self.expect_line_matching_regexes(lines, success_regexes, stream_name) } + /// Checks each line in `lines` against a regex set, and returns Ok if a line matches. + /// /// [`TestChild::expect_line_matching`] wrapper for regular expression iterators. pub fn expect_line_matching_regex_iter( &mut self, lines: &mut L, - regex_iter: I, + success_regexes: I, stream_name: &str, ) -> Result<()> where L: Iterator>, I: CollectRegexSet, { - let regex_set = regex_iter + let success_regexes = success_regexes .collect_regex_set() .expect("regexes must be valid"); - self.expect_line_matching(lines, regex_set, stream_name) + self.expect_line_matching_regexes(lines, success_regexes, stream_name) } - /// Checks each line in `lines` against `regex_set`, and returns Ok if a line + /// Checks each line in `lines` against `success_regexes`, and returns Ok if a line /// matches. Uses `stream_name` as the name for `lines` in error reports. /// /// Kills the child on error, or after the configured timeout has elapsed. @@ -346,11 +624,10 @@ impl TestChild { /// Note: the timeout is only checked after each full line is received from /// the child (#1140). #[instrument(skip(self, lines))] - #[allow(clippy::print_stdout)] - pub fn expect_line_matching( + pub fn expect_line_matching_regexes( &mut self, lines: &mut L, - regex_set: RegexSet, + success_regexes: RegexSet, stream_name: &str, ) -> Result<()> where @@ -369,21 +646,10 @@ impl TestChild { break; }; - // Since we're about to discard this line write it to stdout, so it - // can be preserved. May cause weird reordering for stdout / stderr. - // Uses stdout even if the original lines were from stderr. - if self.bypass_test_capture { - // Send lines directly to the terminal (or process stdout file redirect). - #[allow(clippy::explicit_write)] - writeln!(std::io::stdout(), "{}", line).unwrap(); - } else { - // If the test fails, the test runner captures and displays this output. - println!("{}", line); - } - // Some OSes require a flush to send all output to the terminal. - std::io::stdout().lock().flush()?; + // Since we're about to discard this line write it to stdout. + self.write_to_test_logs(&line); - if regex_set.is_match(&line) { + if success_regexes.is_match(&line) { return Ok(()); } } @@ -400,11 +666,39 @@ impl TestChild { stream_name ) .context_from(self) - .with_section(|| format!("{:?}", regex_set).header("Match Regex:")); + .with_section(|| format!("{:?}", success_regexes).header("Match Regex:")); Err(report) } + /// Write `line` to stdout, so it can be seen in the test logs. + /// + /// Use [bypass_test_capture(true)](TestChild::bypass_test_capture) or + /// `cargo test -- --nocapture` to see this output. + /// + /// 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) + where + S: AsRef, + { + let line = line.as_ref(); + + if self.bypass_test_capture { + // Send lines directly to the terminal (or process stdout file redirect). + #[allow(clippy::explicit_write)] + writeln!(std::io::stdout(), "{}", line).unwrap(); + } else { + // If the test fails, the test runner captures and displays this output. + // To show this output unconditionally, use `cargo test -- --nocapture`. + println!("{}", line); + } + + // Some OSes require a flush to send all output to the terminal. + let _ = std::io::stdout().lock().flush(); + } + /// Kill `child`, wait for its output, and use that output as the context for /// an error report based on `error`. #[instrument(skip(self, result))] @@ -441,15 +735,50 @@ impl TestChild { /// Is this process currently running? /// - /// ## BUGS + /// ## Bugs /// /// On Windows and macOS, this function can return `true` for processes that /// have panicked. See #1781. + /// + /// ## Panics + /// + /// If the child process was already been taken using wait_with_output. pub fn is_running(&mut self) -> bool { - matches!(self.child.try_wait(), Ok(None)) + matches!( + self.child + .as_mut() + .expect("child has not been taken") + .try_wait(), + Ok(None), + ) } } +impl AsRef> for TestChild { + fn as_ref(&self) -> &Self { + self + } +} + +impl AsMut> for TestChild { + fn as_mut(&mut self) -> &mut Self { + self + } +} + +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(); + } +} + +/// Test command output logs. +// TODO: split this struct into its own module +#[derive(Debug)] pub struct TestOutput { /// The test directory for this test output. /// @@ -709,6 +1038,7 @@ impl TestOutput { } /// Add context to an error report +// TODO: split this trait into its own module pub trait ContextFrom { type Return; @@ -745,13 +1075,17 @@ impl ContextFrom<&mut TestChild> for Report { fn context_from(mut self, source: &mut TestChild) -> Self::Return { self = self.section(source.cmd.clone().header("Command:")); - if let Ok(Some(status)) = source.child.try_wait() { - self = self.context_from(&status); + if let Some(child) = &mut source.child { + if let Ok(Some(status)) = child.try_wait() { + self = self.context_from(&status); + } } // Reading test child process output could hang if the child process is still running, // so kill it first. - let _ = source.child.kill(); + if let Some(child) = source.child.as_mut() { + let _ = child.kill(); + } let mut stdout_buf = String::new(); let mut stderr_buf = String::new(); @@ -761,8 +1095,10 @@ impl ContextFrom<&mut TestChild> for Report { let line = if let Ok(line) = line { line } else { break }; let _ = writeln!(&mut stdout_buf, "{}", line); } - } else if let Some(stdout) = &mut source.child.stdout { - let _ = stdout.read_to_string(&mut stdout_buf); + } else if let Some(child) = &mut source.child { + if let Some(stdout) = &mut child.stdout { + let _ = stdout.read_to_string(&mut stdout_buf); + } } if let Some(stderr) = &mut source.stderr { @@ -770,8 +1106,10 @@ impl ContextFrom<&mut TestChild> for Report { let line = if let Ok(line) = line { line } else { break }; let _ = writeln!(&mut stderr_buf, "{}", line); } - } else if let Some(stderr) = &mut source.child.stderr { - let _ = stderr.read_to_string(&mut stderr_buf); + } else if let Some(child) = &mut source.child { + if let Some(stderr) = &mut child.stderr { + let _ = stderr.read_to_string(&mut stderr_buf); + } } self.section(stdout_buf.header("Unread Stdout:")) diff --git a/zebra-test/tests/command.rs b/zebra-test/tests/command.rs index 9086ac0f..0025750c 100644 --- a/zebra-test/tests/command.rs +++ b/zebra-test/tests/command.rs @@ -1,6 +1,6 @@ use std::{process::Command, time::Duration}; -use color_eyre::eyre::Result; +use color_eyre::eyre::{eyre, Result}; use tempfile::tempdir; use zebra_test::{command::TestDirExt, prelude::Stdio}; @@ -70,7 +70,7 @@ fn kill_on_timeout_output_continuous_lines() -> Result<()> { /// Test if the tests pass for a process that produces a single line of output, /// then exits before the timeout. // -// TODO: create a similar test that pauses after output +// TODO: create a similar test that pauses after output (#1140) #[test] fn finish_before_timeout_output_single_line() -> Result<()> { zebra_test::init(); @@ -126,7 +126,7 @@ fn kill_on_timeout_continuous_output_no_newlines() -> Result<()> { /// Test if tests pass for a process that produces a small amount of output, /// with no newlines, then exits before the timeout. // -// TODO: create a similar test that pauses after output +// TODO: create a similar test that pauses after output (#1140) #[test] fn finish_before_timeout_short_output_no_newlines() -> Result<()> { zebra_test::init(); @@ -178,3 +178,263 @@ fn kill_on_timeout_no_output() -> Result<()> { Ok(()) } + +/// Make sure failure regexes 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_matches_stdout_failure_message() { + 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" + ); + } + + let mut child = tempdir() + .unwrap() + .spawn_child_with_command(TEST_CMD, &["failure_message"]) + .unwrap() + .with_timeout(Duration::from_secs(2)) + .with_failure_regex_set("fail"); + + // Any method that reads output should work here. + // We use a non-matching regex, to trigger the failure panic. + child + .expect_stdout_line_matches("this regex should not match") + .unwrap_err(); +} + +/// 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() { + zebra_test::init(); + + // The read command prints its prompt to stderr. + // + // This is tricky to get right, because: + // - some read command versions only accept integer timeouts + // - some installs only have read as a shell builtin + // - some `sh` shells don't allow the `-t` option for read + 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" + ); + } + + let mut child = tempdir() + .unwrap() + .spawn_child_with_command(TEST_CMD, &["-c", "read -t 1 -p failure_message"]) + .unwrap() + .with_timeout(Duration::from_secs(5)) + .with_failure_regex_set("fail"); + + // Any method that reads output should work here. + // We use a non-matching regex, to trigger the failure panic. + child + .expect_stderr_line_matches("this regex should not match") + .unwrap_err(); +} + +/// Make sure failure regexes detect when a child process prints a failure message to stdout, +/// then the child process is dropped without being killed. +#[test] +#[should_panic(expected = "Logged a failure message")] +fn failure_regex_matches_stdout_failure_message_drop() { + 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" + ); + } + + let _child = tempdir() + .unwrap() + .spawn_child_with_command(TEST_CMD, &["failure_message"]) + .unwrap() + .with_timeout(Duration::from_secs(5)) + .with_failure_regex_set("fail"); + + // 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] +#[should_panic(expected = "Logged a failure message")] +fn failure_regex_matches_stdout_failure_message_kill() { + 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" + ); + } + + let mut child = tempdir() + .unwrap() + .spawn_child_with_command(TEST_CMD, &["failure_message"]) + .unwrap() + .with_timeout(Duration::from_secs(5)) + .with_failure_regex_set("fail"); + + // Give the child process enough time to print its output. + std::thread::sleep(Duration::from_secs(1)); + + // Kill should read all unread output to generate the error context, + // or the output should be read on drop. + child.kill().unwrap(); +} + +/// Make sure failure regexes detect when a child process prints a failure message to stdout, +/// then the child process is killed on error. +#[test] +#[should_panic(expected = "Logged a failure message")] +fn failure_regex_matches_stdout_failure_message_kill_on_error() { + 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" + ); + } + + let child = tempdir() + .unwrap() + .spawn_child_with_command(TEST_CMD, &["failure_message"]) + .unwrap() + .with_timeout(Duration::from_secs(5)) + .with_failure_regex_set("fail"); + + // Give the child process enough time to print its output. + std::thread::sleep(Duration::from_secs(1)); + + // Kill on error should read all unread output to generate the error context, + // or the output should be read on drop. + let test_error: Result<()> = Err(eyre!("test error")); + child.kill_on_error(test_error).unwrap(); +} + +/// Make sure failure regexes detect when a child process prints a failure message to stdout, +/// then the child process is not killed because there is no error. +#[test] +#[should_panic(expected = "Logged a failure message")] +fn failure_regex_matches_stdout_failure_message_no_kill_on_error() { + 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" + ); + } + + let child = tempdir() + .unwrap() + .spawn_child_with_command(TEST_CMD, &["failure_message"]) + .unwrap() + .with_timeout(Duration::from_secs(5)) + .with_failure_regex_set("fail"); + + // Give the child process enough time to print its output. + std::thread::sleep(Duration::from_secs(1)); + + // Kill on error should read all unread output to generate the error context, + // or the output should be read on drop. + let test_ok: Result<()> = Ok(()); + child.kill_on_error(test_ok).unwrap(); +} + +/// Make sure failure regexes detect when a child process prints a failure message to stdout, +/// then times out waiting for a specific output line. +/// +/// 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() { + zebra_test::init(); + + // Ideally, we'd want to use the 'yes' command here, but BSD yes treats + // every string as an argument to repeat - so we can't test if it is + // present on the system. + 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" + ); + } + + // Without '-v', hexdump hides duplicate lines. But we want duplicate lines + // in this test. + let mut child = tempdir() + .unwrap() + .spawn_child_with_command(TEST_CMD, &["-v", "/dev/zero"]) + .unwrap() + .with_timeout(Duration::from_secs(2)) + .with_failure_regex_set("0"); + + // 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 + .expect_stdout_line_matches("this regex should not match") + .unwrap_err(); +} + +/// Make sure failure regexes are checked when a child process prints a failure message to stdout, +/// then the child process' output is waited for. +/// +/// This is an error, but we still want to check failure logs. +#[test] +#[should_panic(expected = "Logged a failure message")] +fn failure_regex_matches_stdout_failure_message_wait_for_output() { + 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" + ); + } + + let child = tempdir() + .unwrap() + .spawn_child_with_command(TEST_CMD, &["failure_message"]) + .unwrap() + .with_timeout(Duration::from_secs(5)) + .with_failure_regex_set("fail"); + + // Give the child process enough time to print its output. + std::thread::sleep(Duration::from_secs(1)); + + // Wait with output should read all unread output to generate the error context, + // or the output should be read on drop. + child.wait_with_output().unwrap_err(); +} diff --git a/zebrad/tests/common/sync.rs b/zebrad/tests/common/sync.rs index de81628c..12da493a 100644 --- a/zebrad/tests/common/sync.rs +++ b/zebrad/tests/common/sync.rs @@ -223,7 +223,7 @@ pub fn sync_until( // if it has already exited, ignore that error let _ = child.kill(); - Ok(child.dir) + Ok(child.dir.take().expect("dir was not already taken")) } else { // Require that the mempool didn't activate, // checking the entire `zebrad` output after it exits.