T2. add(test): add test API that checks process logs for failures (#3899)

* Revert "Revert Option<Child> 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

@@ -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<T> IteratorDebug for T where T: Iterator + Debug {}
+
 /// Runs a command
 pub fn test_cmd(command_path: &str, tempdir: &Path) -> Result<Command> {
     let mut cmd = Command::new(command_path);
@@ -33,6 +38,8 @@ pub fn test_cmd(command_path: &str, tempdir: &Path) -> Result<Command> {
     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<T> {
     /// 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<T>,
 
     /// 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<Child>,
 
     /// The standard output stream of the child process.
-    pub stdout: Option<Lines<BufReader<ChildStdout>>>,
+    ///
+    /// TODO: replace with `Option<ChildOutput { stdout, stderr }>.
+    pub stdout: Option<Box<dyn IteratorDebug<Item = std::io::Result<String>>>>,
 
     /// The standard error stream of the child process.
-    pub stderr: Option<Lines<BufReader<ChildStderr>>>,
+    pub stderr: Option<Box<dyn IteratorDebug<Item = std::io::Result<String>>>>,
+
+    /// 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<T> {
     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<String>,
+    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<T> TestChild<T> {
+    /// 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<R>(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<I>(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<R>(
+        &self,
+        reader: R,
+    ) -> Box<dyn IteratorDebug<Item = std::io::Result<String>>>
+    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<T> TestChild<T> {
     /// 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<OptS>(&mut self, write_context: OptS) -> bool
+    where
+        OptS: Into<Option<String>>,
+    {
+        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<OptS>(&mut self, write_context: OptS) -> bool
+    where
+        OptS: Into<Option<String>>,
+    {
+        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<TestOutput<T>> {
+    pub fn wait_with_output(mut self) -> Result<TestOutput<T>> {
+        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<T> TestChild<T> {
         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<R>(&mut self, regex: R) -> Result<&mut Self>
+    pub fn expect_stdout_line_matches<R>(&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<T> TestChild<T> {
         }
     }
 
-    /// 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<R>(&mut self, regex: R) -> Result<&mut Self>
+    pub fn expect_stderr_line_matches<R>(&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<T> TestChild<T> {
         }
     }
 
+    /// 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<L, R>(
         &mut self,
         lines: &mut L,
-        regex_set: R,
+        success_regexes: R,
         stream_name: &str,
     ) -> Result<()>
     where
         L: Iterator<Item = std::io::Result<String>>,
         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<L, I>(
         &mut self,
         lines: &mut L,
-        regex_iter: I,
+        success_regexes: I,
         stream_name: &str,
     ) -> Result<()>
     where
         L: Iterator<Item = std::io::Result<String>>,
         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<T> TestChild<T> {
     /// 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<L>(
+    pub fn expect_line_matching_regexes<L>(
         &mut self,
         lines: &mut L,
-        regex_set: RegexSet,
+        success_regexes: RegexSet,
         stream_name: &str,
     ) -> Result<()>
     where
@@ -369,21 +646,10 @@ impl<T> TestChild<T> {
                 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<T> TestChild<T> {
             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<S>(&self, line: S)
+    where
+        S: AsRef<str>,
+    {
+        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<T> TestChild<T> {
 
     /// 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<T> AsRef<TestChild<T>> for TestChild<T> {
+    fn as_ref(&self) -> &Self {
+        self
+    }
+}
+
+impl<T> AsMut<TestChild<T>> for TestChild<T> {
+    fn as_mut(&mut self) -> &mut Self {
+        self
+    }
+}
+
+impl<T> Drop for TestChild<T> {
+    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<T> {
     /// The test directory for this test output.
     ///
@@ -709,6 +1038,7 @@ impl<T> TestOutput<T> {
 }
 
 /// Add context to an error report
+// TODO: split this trait into its own module
 pub trait ContextFrom<S> {
     type Return;
 
@@ -745,13 +1075,17 @@ impl<T> ContextFrom<&mut TestChild<T>> for Report {
     fn context_from(mut self, source: &mut TestChild<T>) -> 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<T> ContextFrom<&mut TestChild<T>> 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<T> ContextFrom<&mut TestChild<T>> 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:"))

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();
+}

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.