From e54a132e57784a2e7218e6280d1c2058627f8ce6 Mon Sep 17 00:00:00 2001 From: Rain Date: Sun, 1 Dec 2024 06:22:04 +0000 Subject: [PATCH] [nextest-runner] improve error handling for child process management * Don't eat up stdout/stderr if there's an error that occurs after the process is spawned * Scripts can now combine stdout and stderr (though this isn't exposed in the UI yet). * Fix up names to reflect that "child" can mean either a test process or a script process. This is going to need a bunch of TLC, but I think this is generally a good shape for the types to be in. --- nextest-runner/src/config/scripts.rs | 34 ++-- nextest-runner/src/errors.rs | 142 ++++++++++------- nextest-runner/src/reporter/aggregator.rs | 24 +-- nextest-runner/src/reporter/displayer.rs | 129 +++++++-------- .../src/reporter/structured/libtest.rs | 124 +++++++++------ ...test__strips_human_output_start_error.snap | 6 + nextest-runner/src/runner.rs | 150 +++++++++--------- nextest-runner/src/test_command.rs | 2 +- nextest-runner/src/test_command/imp.rs | 20 +-- nextest-runner/src/test_output.rs | 39 +++-- nextest-runner/tests/integration/basic.rs | 8 +- nextest-runner/tests/integration/fixtures.rs | 7 +- 12 files changed, 375 insertions(+), 310 deletions(-) create mode 100644 nextest-runner/src/reporter/structured/snapshots/nextest_runner__reporter__structured__libtest__test__strips_human_output_start_error.snap diff --git a/nextest-runner/src/config/scripts.rs b/nextest-runner/src/config/scripts.rs index 2f32a399b87..2da33480767 100644 --- a/nextest-runner/src/config/scripts.rs +++ b/nextest-runner/src/config/scripts.rs @@ -10,8 +10,8 @@ use super::{ use crate::{ double_spawn::{DoubleSpawnContext, DoubleSpawnInfo}, errors::{ - ConfigCompileError, ConfigCompileErrorKind, ConfigCompileSection, InvalidConfigScriptName, - SetupScriptError, + ChildStartError, ConfigCompileError, ConfigCompileErrorKind, ConfigCompileSection, + InvalidConfigScriptName, SetupScriptOutputError, }, list::TestList, platform::BuildPlatforms, @@ -28,6 +28,7 @@ use std::{ collections::{BTreeMap, HashMap, HashSet}, fmt, process::Command, + sync::Arc, time::Duration, }; use tokio::io::{AsyncBufReadExt, BufReader}; @@ -169,7 +170,7 @@ impl SetupScriptCommand { config: &ScriptConfig, double_spawn: &DoubleSpawnInfo, test_list: &TestList<'_>, - ) -> Result { + ) -> Result { let mut cmd = create_command(config.program().to_owned(), config.args(), double_spawn); // NB: we will always override user-provided environment variables with the @@ -179,7 +180,7 @@ impl SetupScriptCommand { let env_path = camino_tempfile::Builder::new() .prefix("nextest-env") .tempfile() - .map_err(SetupScriptError::TempPath)? + .map_err(|error| ChildStartError::TempPath(Arc::new(error)))? .into_temp_path(); cmd.current_dir(test_list.workspace_root()) @@ -249,31 +250,32 @@ pub(crate) struct SetupScriptEnvMap { } impl SetupScriptEnvMap { - pub(crate) async fn new(env_path: &Utf8Path) -> Result { + pub(crate) async fn new(env_path: &Utf8Path) -> Result { let mut env_map = BTreeMap::new(); let f = tokio::fs::File::open(env_path).await.map_err(|error| { - SetupScriptError::EnvFileOpen { + SetupScriptOutputError::EnvFileOpen { path: env_path.to_owned(), - error, + error: Arc::new(error), } })?; let reader = BufReader::new(f); let mut lines = reader.lines(); loop { - let line = lines - .next_line() - .await - .map_err(|error| SetupScriptError::EnvFileRead { - path: env_path.to_owned(), - error, - })?; + let line = + lines + .next_line() + .await + .map_err(|error| SetupScriptOutputError::EnvFileRead { + path: env_path.to_owned(), + error: Arc::new(error), + })?; let Some(line) = line else { break }; // Split this line into key and value. let (key, value) = match line.split_once('=') { Some((key, value)) => (key, value), None => { - return Err(SetupScriptError::EnvFileParse { + return Err(SetupScriptOutputError::EnvFileParse { path: env_path.to_owned(), line: line.to_owned(), }) @@ -282,7 +284,7 @@ impl SetupScriptEnvMap { // Ban keys starting with `NEXTEST`. if key.starts_with("NEXTEST") { - return Err(SetupScriptError::EnvFileReservedKey { + return Err(SetupScriptOutputError::EnvFileReservedKey { key: key.to_owned(), }); } diff --git a/nextest-runner/src/errors.rs b/nextest-runner/src/errors.rs index 33f0ecdb80d..a3fde7fd131 100644 --- a/nextest-runner/src/errors.rs +++ b/nextest-runner/src/errors.rs @@ -274,40 +274,21 @@ impl ConfigCompileErrorKind { } } -/// An execution error was returned while running a test. -/// -/// Internal error type. -#[derive(Debug, Error)] -#[non_exhaustive] -pub(crate) enum RunTestError { - #[error("error spawning test process")] - Spawn(#[source] std::io::Error), - - #[error("errors while managing test process")] - Child { - /// The errors that occurred; guaranteed to be non-empty. - errors: ErrorList, - }, -} - -/// An error that occurred while setting up or running a setup script. -#[derive(Debug, Error)] -pub(crate) enum SetupScriptError { - /// An error occurred while creating a temporary path for the setup script. +/// An execution error occurred while attempting to start a test. +#[derive(Clone, Debug, Error)] +pub enum ChildStartError { + /// An error occurred while creating a temporary path for a setup script. #[error("error creating temporary path for setup script")] - TempPath(#[source] std::io::Error), - - /// An error occurred while executing the setup script. - #[error("error executing setup script")] - ExecFail(#[source] std::io::Error), + TempPath(#[source] Arc), - /// One or more errors occurred while managing the child process. - #[error("errors while managing setup script process")] - Child { - /// The errors that occurred; guaranteed to be non-empty. - errors: ErrorList, - }, + /// An error occurred while spawning the child process. + #[error("error spawning child process")] + Spawn(#[source] Arc), +} +/// An error that occurred while reading the output of a setup script. +#[derive(Clone, Debug, Error)] +pub enum SetupScriptOutputError { /// An error occurred while opening the setup script environment file. #[error("error opening environment file `{path}`")] EnvFileOpen { @@ -316,7 +297,7 @@ pub(crate) enum SetupScriptError { /// The underlying error. #[source] - error: std::io::Error, + error: Arc, }, /// An error occurred while reading the setup script environment file. @@ -327,16 +308,24 @@ pub(crate) enum SetupScriptError { /// The underlying error. #[source] - error: std::io::Error, + error: Arc, }, /// An error occurred while parsing the setup script environment file. #[error("line `{line}` in environment file `{path}` not in KEY=VALUE format")] - EnvFileParse { path: Utf8PathBuf, line: String }, + EnvFileParse { + /// The path to the environment file. + path: Utf8PathBuf, + /// The line at issue. + line: String, + }, /// An environment variable key was reserved. #[error("key `{key}` begins with `NEXTEST`, which is reserved for internal use")] - EnvFileReservedKey { key: String }, + EnvFileReservedKey { + /// The environment variable name. + key: String, + }, } /// A list of errors that implements `Error`. @@ -344,25 +333,53 @@ pub(crate) enum SetupScriptError { /// In the future, we'll likely want to replace this with a `miette::Diagnostic`-based error, since /// that supports multiple causes via "related". #[derive(Clone, Debug)] -pub struct ErrorList(pub Vec); +pub struct ErrorList { + // A description of what the errors are. + description: &'static str, + // Invariant: this list is non-empty. + inner: Vec, +} + +impl ErrorList { + pub(crate) fn new(description: &'static str, errors: Vec) -> Option + where + T: From, + { + if errors.is_empty() { + None + } else { + Some(Self { + description, + inner: errors.into_iter().map(T::from).collect(), + }) + } + } -impl ErrorList { - /// Returns true if the error list is empty. - pub fn is_empty(&self) -> bool { - self.0.is_empty() + /// Returns a 1 line summary of the error list. + pub(crate) fn as_one_line_summary(&self) -> String { + if self.inner.len() == 1 { + format!("{}", self.inner[0]) + } else { + format!("{} errors occurred {}", self.inner.len(), self.description) + } } } impl fmt::Display for ErrorList { fn fmt(&self, mut f: &mut fmt::Formatter) -> fmt::Result { // If a single error occurred, pretend that this is just that. - if self.0.len() == 1 { - return write!(f, "{}", self.0[0]); + if self.inner.len() == 1 { + return write!(f, "{}", self.inner[0]); } // Otherwise, list all errors. - writeln!(f, "{} errors occurred:", self.0.len())?; - for error in &self.0 { + writeln!( + f, + "{} errors occurred {}:", + self.inner.len(), + self.description, + )?; + for error in &self.inner { let mut indent = IndentWriter::new_skip_initial(" ", f); writeln!(indent, "* {}", DisplayErrorChain(error))?; f = indent.into_inner(); @@ -373,8 +390,8 @@ impl fmt::Display for ErrorList { impl std::error::Error for ErrorList { fn source(&self) -> Option<&(dyn std::error::Error + 'static)> { - if self.0.len() == 1 { - self.0[0].source() + if self.inner.len() == 1 { + self.inner[0].source() } else { // More than one error occurred, so we can't return a single error here. Instead, we // return `None` and display the chain of causes in `fmt::Display`. @@ -421,10 +438,21 @@ where } } -/// An error was returned during the process of managing a child process. +/// An error was returned while managing a child process or reading its output. #[derive(Clone, Debug, Error)] -#[non_exhaustive] pub enum ChildError { + /// An error occurred while reading from a child file descriptor. + #[error(transparent)] + Fd(#[from] ChildFdError), + + /// An error occurred while reading the output of a setup script. + #[error(transparent)] + SetupScriptOutput(#[from] SetupScriptOutputError), +} + +/// An error was returned while reading from child a file descriptor. +#[derive(Clone, Debug, Error)] +pub enum ChildFdError { /// An error occurred while reading standard output. #[error("error reading standard output")] ReadStdout(#[source] Arc), @@ -1822,14 +1850,18 @@ mod tests { fn display_error_list() { let err1 = StringError::new("err1", None); - let error_list = ErrorList(vec![err1.clone()]); + let error_list = + ErrorList::::new("waiting on the water to boil", vec![err1.clone()]) + .expect(">= 1 error"); insta::assert_snapshot!(format!("{}", error_list), @"err1"); insta::assert_snapshot!(format!("{}", DisplayErrorChain::new(&error_list)), @"err1"); let err2 = StringError::new("err2", Some(err1)); let err3 = StringError::new("err3", Some(err2)); - let error_list = ErrorList(vec![err3.clone()]); + let error_list = + ErrorList::::new("waiting on flowers to bloom", vec![err3.clone()]) + .expect(">= 1 error"); insta::assert_snapshot!(format!("{}", error_list), @"err3"); insta::assert_snapshot!(format!("{}", DisplayErrorChain::new(&error_list)), @r" err3 @@ -1842,10 +1874,14 @@ mod tests { let err5 = StringError::new("err5", Some(err4)); let err6 = StringError::new("err6\nerr6 line 2", Some(err5)); - let error_list = ErrorList(vec![err3, err6]); + let error_list = ErrorList::::new( + "waiting for the heat death of the universe", + vec![err3, err6], + ) + .expect(">= 1 error"); insta::assert_snapshot!(format!("{}", error_list), @r" - 2 errors occurred: + 2 errors occurred waiting for the heat death of the universe: * err3 caused by: - err2 @@ -1857,7 +1893,7 @@ mod tests { - err4 "); insta::assert_snapshot!(format!("{}", DisplayErrorChain::new(&error_list)), @r" - 2 errors occurred: + 2 errors occurred waiting for the heat death of the universe: * err3 caused by: - err2 diff --git a/nextest-runner/src/reporter/aggregator.rs b/nextest-runner/src/reporter/aggregator.rs index 33e4e87abf9..da90ffd49f3 100644 --- a/nextest-runner/src/reporter/aggregator.rs +++ b/nextest-runner/src/reporter/aggregator.rs @@ -6,11 +6,11 @@ use super::TestEvent; use crate::{ config::{EvaluatableProfile, NextestJunitConfig}, - errors::WriteEventError, + errors::{DisplayErrorChain, WriteEventError}, list::TestInstance, reporter::TestEventKind, runner::{ExecuteStatus, ExecutionDescription, ExecutionResult}, - test_output::{TestExecutionOutput, TestOutput}, + test_output::{ChildExecutionResult, ChildOutput}, }; use camino::Utf8PathBuf; use debug_ignore::DebugIgnore; @@ -303,8 +303,13 @@ fn set_execute_status_props( mut out: TestcaseOrRerun<'_>, ) { match &execute_status.output { - TestExecutionOutput::Output(output) => { + ChildExecutionResult::Output { output, errors } => { if !is_success { + if let Some(errors) = errors { + // Use the child errors as the message and description. + out.set_message(errors.as_one_line_summary()); + out.set_description(DisplayErrorChain::new(errors).to_string()); + }; let description = output.heuristic_extract_description(execute_status.result); if let Some(description) = description { out.set_description(description.display_human().to_string()); @@ -313,7 +318,7 @@ fn set_execute_status_props( if store_stdout_stderr { match output { - TestOutput::Split(split) => { + ChildOutput::Split(split) => { if let Some(stdout) = &split.stdout { out.set_system_out(stdout.as_str_lossy()); } @@ -321,19 +326,16 @@ fn set_execute_status_props( out.set_system_err(stderr.as_str_lossy()); } } - TestOutput::Combined { output } => { + ChildOutput::Combined { output } => { out.set_system_out(output.as_str_lossy()) .set_system_err("(stdout and stderr are combined)"); } } } } - TestExecutionOutput::ExecFail { - message, - description, - } => { - out.set_message(format!("Test execution failed: {message}")); - out.set_description(description); + ChildExecutionResult::StartError(error) => { + out.set_message(format!("Test execution failed: {error}")); + out.set_description(DisplayErrorChain::new(error).to_string()); } } } diff --git a/nextest-runner/src/reporter/displayer.rs b/nextest-runner/src/reporter/displayer.rs index 4ced4769478..038d138ebcc 100644 --- a/nextest-runner/src/reporter/displayer.rs +++ b/nextest-runner/src/reporter/displayer.rs @@ -11,7 +11,7 @@ use super::{ }; use crate::{ config::{CompiledDefaultFilter, EvaluatableProfile, ScriptId}, - errors::WriteEventError, + errors::{DisplayErrorChain, WriteEventError}, helpers::{plural, DisplayScriptInstance, DisplayTestInstance}, list::{SkipCounts, TestInstance, TestList}, reporter::{aggregator::EventAggregator, helpers::highlight_end}, @@ -19,7 +19,7 @@ use crate::{ AbortStatus, ExecuteStatus, ExecutionDescription, ExecutionResult, ExecutionStatuses, FinalRunStats, RetryData, RunStats, RunStatsFailureKind, SetupScriptExecuteStatus, }, - test_output::{ChildSingleOutput, ChildSplitOutput, TestExecutionOutput, TestOutput}, + test_output::{ChildExecutionResult, ChildOutput, ChildSingleOutput}, }; use bstr::ByteSlice; use debug_ignore::DebugIgnore; @@ -1376,39 +1376,25 @@ impl<'a> TestReporterImpl<'a> { ) -> io::Result<()> { let spec = self.output_spec_for_script(script_id, command, args, run_status); - self.write_script_output(&spec, &run_status.output, writer)?; - - writeln!(writer) - } + match &run_status.output { + ChildExecutionResult::Output { output, errors } => { + // Show execution failures first so that they show up + // immediately after the failure notification. + if let Some(errors) = errors { + let error_chain = DisplayErrorChain::new(errors); + writeln!(writer, "{}\n{error_chain}", spec.exec_fail_header)?; + } - fn write_script_output( - &self, - spec: &ChildOutputSpec, - output: &ChildSplitOutput, - mut writer: &mut dyn Write, - ) -> io::Result<()> { - if let Some(stdout) = &output.stdout { - if self.display_empty_outputs || !stdout.is_empty() { - writeln!(writer, "{}", spec.stdout_header)?; - - let mut indent_writer = IndentWriter::new(spec.output_indent, writer); - self.write_test_single_output(stdout, &mut indent_writer)?; - indent_writer.flush()?; - writer = indent_writer.into_inner(); + self.write_child_output(&spec, output, None, writer)?; } - } - - if let Some(stderr) = &output.stderr { - if self.display_empty_outputs || !stderr.is_empty() { - writeln!(writer, "{}", spec.stderr_header)?; - let mut indent_writer = IndentWriter::new(spec.output_indent, writer); - self.write_test_single_output(stderr, &mut indent_writer)?; - indent_writer.flush()?; + ChildExecutionResult::StartError(error) => { + let error_chain = DisplayErrorChain::new(error); + writeln!(writer, "{}\n{error_chain}", spec.exec_fail_header)?; } } - Ok(()) + writeln!(writer) } fn write_test_execute_status( @@ -1421,38 +1407,41 @@ impl<'a> TestReporterImpl<'a> { let spec = self.output_spec_for_test(test_instance, run_status, is_retry); match &run_status.output { - TestExecutionOutput::Output(output) => { + ChildExecutionResult::Output { output, errors } => { + // Show execution failures first so that they show up + // immediately after the failure notification. + if let Some(errors) = errors { + let error_chain = DisplayErrorChain::new(errors); + writeln!(writer, "{}\n{error_chain}", spec.exec_fail_header)?; + } + let description = if self.styles.is_colorized { output.heuristic_extract_description(run_status.result) } else { None }; let spec = self.output_spec_for_test(test_instance, run_status, is_retry); - self.write_test_output(&spec, output, description, writer)?; + self.write_child_output(&spec, output, description, writer)?; } - TestExecutionOutput::ExecFail { description, .. } => { - writeln!( - writer, - "{}\n{description}", - spec.exec_fail_header - .expect("test output should have exec-fail header") - )?; + ChildExecutionResult::StartError(error) => { + let error_chain = DisplayErrorChain::new(error); + writeln!(writer, "{}\n{error_chain}", spec.exec_fail_header)?; } } writeln!(writer) } - fn write_test_output( + fn write_child_output( &self, spec: &ChildOutputSpec, - output: &TestOutput, + output: &ChildOutput, description: Option>, mut writer: &mut dyn Write, ) -> io::Result<()> { match output { - TestOutput::Split(split) => { + ChildOutput::Split(split) => { if let Some(stdout) = &split.stdout { if self.display_empty_outputs || !stdout.is_empty() { writeln!(writer, "{}", spec.stdout_header)?; @@ -1486,15 +1475,9 @@ impl<'a> TestReporterImpl<'a> { } } } - TestOutput::Combined { output } => { + ChildOutput::Combined { output } => { if self.display_empty_outputs || !output.is_empty() { - writeln!( - writer, - "{}", - spec.combined_header - .as_ref() - .expect("for TestOutput, combined header should be present") - )?; + writeln!(writer, "{}", spec.combined_header)?; let mut indent_writer = IndentWriter::new(spec.output_indent, writer); self.write_test_single_output_with_description( @@ -1510,16 +1493,6 @@ impl<'a> TestReporterImpl<'a> { Ok(()) } - /// Writes a test output to the writer. - fn write_test_single_output( - &self, - output: &ChildSingleOutput, - writer: &mut dyn Write, - ) -> io::Result<()> { - // SAFETY: The description is not provided. - self.write_test_single_output_with_description(output, None, writer) - } - /// Writes a test output to the writer, along with optionally a subslice of the output to /// highlight. /// @@ -1647,8 +1620,8 @@ impl<'a> TestReporterImpl<'a> { ChildOutputSpec { stdout_header, stderr_header, - combined_header: Some(combined_header), - exec_fail_header: Some(exec_fail_header), + combined_header, + exec_fail_header, // No output indent for now -- maybe this should be supported? // Definitely worth trying out. output_indent: "", @@ -1688,11 +1661,29 @@ impl<'a> TestReporterImpl<'a> { ) }; + let combined_header = { + format!( + "{} {:19} {}", + hbar.style(header_style), + "OUTPUT:".style(header_style), + self.display_script_instance(script_id.clone(), command, args), + ) + }; + + let exec_fail_header = { + format!( + "{} {:19} {}", + hbar.style(header_style), + "EXECFAIL:".style(header_style), + self.display_script_instance(script_id.clone(), command, args), + ) + }; + ChildOutputSpec { stdout_header, stderr_header, - combined_header: None, - exec_fail_header: None, + combined_header, + exec_fail_header, output_indent: "", } } @@ -1717,16 +1708,8 @@ const RESET_COLOR: &[u8] = b"\x1b[0m"; struct ChildOutputSpec { stdout_header: String, stderr_header: String, - // None if this spec does not write out combined output. - // - // XXX should this be represented differently? Maybe scripts should support - // combined output? - combined_header: Option, - // None if this spec does not write out exec-fail output. - // - // XXX script exec fail needs to be handled better -- we should treat it the - // same as tests. - exec_fail_header: Option, + combined_header: String, + exec_fail_header: String, output_indent: &'static str, } diff --git a/nextest-runner/src/reporter/structured/libtest.rs b/nextest-runner/src/reporter/structured/libtest.rs index dd47cd7caea..65eb4bb58fa 100644 --- a/nextest-runner/src/reporter/structured/libtest.rs +++ b/nextest-runner/src/reporter/structured/libtest.rs @@ -24,11 +24,11 @@ use super::{TestEvent, WriteEventError}; use crate::{ - errors::{FormatVersionError, FormatVersionErrorInner}, + errors::{DisplayErrorChain, FormatVersionError, FormatVersionErrorInner}, list::RustTestSuite, reporter::TestEventKind, runner::ExecutionResult, - test_output::{ChildSingleOutput, TestExecutionOutput, TestOutput}, + test_output::{ChildExecutionResult, ChildOutput, ChildSingleOutput}, }; use bstr::ByteSlice; use nextest_metadata::MismatchReason; @@ -491,43 +491,63 @@ impl<'cfg> LibtestReporter<'cfg> { /// This function relies on the fact that nextest runs every individual test in /// isolation. fn strip_human_output_from_failed_test( - output: &TestExecutionOutput, + output: &ChildExecutionResult, out: &mut bytes::BytesMut, test_name: &str, ) -> Result<(), WriteEventError> { match output { - TestExecutionOutput::Output(TestOutput::Combined { output }) => { - strip_human_stdout_or_combined(output, out, test_name)?; - } - TestExecutionOutput::Output(TestOutput::Split(split)) => { - // This is not a case that we hit because we always set CaptureStrategy to Combined. But - // handle it in a reasonable fashion. (We do have a unit test for this case, so gate the - // assertion with cfg(not(test)).) - #[cfg(not(test))] - { - debug_assert!(false, "libtest output requires CaptureStrategy::Combined"); - } - if let Some(stdout) = &split.stdout { - if !stdout.is_empty() { - write!(out, "--- STDOUT ---\\n").map_err(fmt_err)?; - strip_human_stdout_or_combined(stdout, out, test_name)?; + ChildExecutionResult::Output { output, errors } => { + match output { + ChildOutput::Combined { output } => { + strip_human_stdout_or_combined(output, out, test_name)?; } - } else { - write!(out, "(stdout not captured)").map_err(fmt_err)?; - } - // If stderr is not empty, just write all of it in. - if let Some(stderr) = &split.stderr { - if !stderr.is_empty() { - write!(out, "\\n--- STDERR ---\\n").map_err(fmt_err)?; - write!(out, "{}", EscapedString(stderr.as_str_lossy())).map_err(fmt_err)?; + ChildOutput::Split(split) => { + // This is not a case that we hit because we always set CaptureStrategy to Combined. But + // handle it in a reasonable fashion. (We do have a unit test for this case, so gate the + // assertion with cfg(not(test)).) + #[cfg(not(test))] + { + debug_assert!(false, "libtest output requires CaptureStrategy::Combined"); + } + if let Some(stdout) = &split.stdout { + if !stdout.is_empty() { + write!(out, "--- STDOUT ---\\n").map_err(fmt_err)?; + strip_human_stdout_or_combined(stdout, out, test_name)?; + } + } else { + write!(out, "(stdout not captured)").map_err(fmt_err)?; + } + // If stderr is not empty, just write all of it in. + if let Some(stderr) = &split.stderr { + if !stderr.is_empty() { + write!(out, "\\n--- STDERR ---\\n").map_err(fmt_err)?; + write!(out, "{}", EscapedString(stderr.as_str_lossy())) + .map_err(fmt_err)?; + } + } else { + writeln!(out, "\\n(stderr not captured)").map_err(fmt_err)?; + } } - } else { - writeln!(out, "\\n(stderr not captured)").map_err(fmt_err)?; + } + + if let Some(errors) = errors { + write!(out, "\\n--- EXECUTION ERRORS ---\\n").map_err(fmt_err)?; + write!( + out, + "{}", + EscapedString(&DisplayErrorChain::new(errors).to_string()) + ) + .map_err(fmt_err)?; } } - TestExecutionOutput::ExecFail { description, .. } => { - write!(out, "--- EXEC FAIL ---\\n").map_err(fmt_err)?; - write!(out, "{}", EscapedString(description)).map_err(fmt_err)?; + ChildExecutionResult::StartError(error) => { + write!(out, "--- EXECUTION ERROR ---\\n").map_err(fmt_err)?; + write!( + out, + "{}", + EscapedString(&DisplayErrorChain::new(error).to_string()) + ) + .map_err(fmt_err)?; } } Ok(()) @@ -643,10 +663,13 @@ impl std::fmt::Display for EscapedString<'_> { #[cfg(test)] mod test { use crate::{ + errors::ChildStartError, reporter::structured::libtest::strip_human_output_from_failed_test, - test_output::{ChildSplitOutput, TestExecutionOutput, TestOutput}, + test_output::{ChildExecutionResult, ChildOutput, ChildSplitOutput}, }; use bytes::BytesMut; + use color_eyre::eyre::eyre; + use std::{io, sync::Arc}; /// Validates that the human output portion from a failed test is stripped /// out when writing a JSON string, as it is not part of the output when @@ -687,14 +710,17 @@ note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose bac acc.extend_from_slice(line.as_bytes()); } - TestOutput::Combined { + ChildOutput::Combined { output: acc.freeze().into(), } }; let mut actual = bytes::BytesMut::new(); strip_human_output_from_failed_test( - &TestExecutionOutput::Output(output), + &ChildExecutionResult::Output { + output, + errors: None, + }, &mut actual, "index::test::download_url_crates_io", ) @@ -714,14 +740,17 @@ note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose bac acc.extend_from_slice(line.as_bytes()); } - TestOutput::Combined { + ChildOutput::Combined { output: acc.freeze().into(), } }; let mut actual = bytes::BytesMut::new(); strip_human_output_from_failed_test( - &TestExecutionOutput::Output(output), + &ChildExecutionResult::Output { + output, + errors: None, + }, &mut actual, "non-existent", ) @@ -731,13 +760,11 @@ note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose bac } #[test] - fn strips_human_output_exec_fail() { - let output = { - TestExecutionOutput::ExecFail { - message: "this is a message".to_owned(), - description: "this is a message\nthis is a description\n".to_owned(), - } - }; + fn strips_human_output_start_error() { + let inner_error = eyre!("inner error"); + let error = io::Error::new(io::ErrorKind::Other, inner_error); + + let output = ChildExecutionResult::StartError(ChildStartError::Spawn(Arc::new(error))); let mut actual = bytes::BytesMut::new(); strip_human_output_from_failed_test(&output, &mut actual, "non-existent").unwrap(); @@ -749,10 +776,13 @@ note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose bac fn strips_human_output_none() { let mut actual = bytes::BytesMut::new(); strip_human_output_from_failed_test( - &TestExecutionOutput::Output(TestOutput::Split(ChildSplitOutput { - stdout: None, - stderr: None, - })), + &ChildExecutionResult::Output { + output: ChildOutput::Split(ChildSplitOutput { + stdout: None, + stderr: None, + }), + errors: None, + }, &mut actual, "non-existent", ) diff --git a/nextest-runner/src/reporter/structured/snapshots/nextest_runner__reporter__structured__libtest__test__strips_human_output_start_error.snap b/nextest-runner/src/reporter/structured/snapshots/nextest_runner__reporter__structured__libtest__test__strips_human_output_start_error.snap new file mode 100644 index 00000000000..bda76123931 --- /dev/null +++ b/nextest-runner/src/reporter/structured/snapshots/nextest_runner__reporter__structured__libtest__test__strips_human_output_start_error.snap @@ -0,0 +1,6 @@ +--- +source: nextest-runner/src/reporter/structured/libtest.rs +expression: "std::str::from_utf8(&actual).unwrap()" +snapshot_kind: text +--- +--- EXECUTION ERROR ---\nerror spawning child process\n caused by:\n - inner error diff --git a/nextest-runner/src/runner.rs b/nextest-runner/src/runner.rs index a4baeb60c53..e1d75c704ed 100644 --- a/nextest-runner/src/runner.rs +++ b/nextest-runner/src/runner.rs @@ -13,8 +13,8 @@ use crate::{ }, double_spawn::DoubleSpawnInfo, errors::{ - ChildError, ConfigureHandleInheritanceError, DisplayErrorChain, ErrorList, RunTestError, - SetupScriptError, TestRunnerBuildError, TestRunnerExecuteErrors, + ChildError, ChildFdError, ChildStartError, ConfigureHandleInheritanceError, ErrorList, + TestRunnerBuildError, TestRunnerExecuteErrors, }, list::{TestExecuteContext, TestInstance, TestInstanceId, TestList}, reporter::{ @@ -22,8 +22,8 @@ use crate::{ }, signal::{JobControlEvent, ShutdownEvent, SignalEvent, SignalHandler, SignalHandlerKind}, target_runner::TargetRunner, - test_command::{ChildAccumulator, ChildFds, ChildOutputMut}, - test_output::{CaptureStrategy, ChildSplitOutput, TestExecutionOutput}, + test_command::{ChildAccumulator, ChildFds}, + test_output::{CaptureStrategy, ChildExecutionResult}, time::{PausableSleep, StopwatchSnapshot, StopwatchStart}, }; use async_scoped::TokioScope; @@ -36,7 +36,6 @@ use rand::{distributions::OpenClosed01, thread_rng, Rng}; use std::{ collections::BTreeMap, convert::Infallible, - fmt::Write, num::NonZeroUsize, pin::Pin, process::{ExitStatus, Stdio}, @@ -771,26 +770,16 @@ impl<'a> TestRunnerInner<'a> { .await { Ok((status, env_map)) => (status, env_map), - Err(error) => { - // Put the error chain inside stderr. (This is not a great solution, but it's fine - // for now.) - let mut stderr = bytes::BytesMut::new(); - writeln!(&mut stderr, "{}", DisplayErrorChain::new(error)).unwrap(); - - ( - InternalSetupScriptExecuteStatus { - output: ChildSplitOutput { - stdout: None, - stderr: Some(stderr.freeze().into()), - }, - result: ExecutionResult::ExecFail, - stopwatch_end: stopwatch.snapshot(), - is_slow: false, - env_count: 0, - }, - None, - ) - } + Err(error) => ( + InternalSetupScriptExecuteStatus { + output: ChildExecutionResult::StartError(error), + result: ExecutionResult::ExecFail, + stopwatch_end: stopwatch.snapshot(), + is_slow: false, + env_count: 0, + }, + None, + ), } } @@ -800,7 +789,7 @@ impl<'a> TestRunnerInner<'a> { stopwatch: &mut StopwatchStart, resp_tx: &UnboundedSender>, req_rx: &mut UnboundedReceiver, - ) -> Result<(InternalSetupScriptExecuteStatus, Option), SetupScriptError> + ) -> Result<(InternalSetupScriptExecuteStatus, Option), ChildStartError> { let mut cmd = script.make_command(&self.double_spawn, self.test_list)?; let command_mut = cmd.command_mut(); @@ -823,7 +812,9 @@ impl<'a> TestRunnerInner<'a> { } } - let (mut child, env_path) = cmd.spawn().map_err(SetupScriptError::ExecFail)?; + let (mut child, env_path) = cmd + .spawn() + .map_err(|error| ChildStartError::Spawn(Arc::new(error)))?; // If assigning the child to the job fails, ignore this. This can happen if the process has // exited. @@ -949,39 +940,39 @@ impl<'a> TestRunnerInner<'a> { let exit_status = match res { Ok(exit_status) => Some(exit_status), Err(err) => { - child_acc.errors.push(ChildError::Wait(Arc::new(err))); + child_acc.errors.push(ChildFdError::Wait(Arc::new(err))); None } }; - if !child_acc.errors.is_empty() { - // TODO: we may wish to return whatever parts of the output we did collect here. - return Err(SetupScriptError::Child { - errors: ErrorList(child_acc.errors), - }); - } - let exit_status = exit_status.expect("None always results in early return"); - let status = status.unwrap_or_else(|| create_execution_result(exit_status, leaked)); + let status = status + .unwrap_or_else(|| create_execution_result(exit_status, &child_acc.errors, leaked)); + // Read from the environment map. If there's an error here, add it to the list of child errors. + let mut errors: Vec<_> = child_acc.errors.into_iter().map(ChildError::from).collect(); let env_map = if status.is_success() { - Some(SetupScriptEnvMap::new(&env_path).await?) + match SetupScriptEnvMap::new(&env_path).await { + Ok(env_map) => Some(env_map), + Err(error) => { + errors.push(ChildError::SetupScriptOutput(error)); + None + } + } } else { None }; - let (stdout, stderr) = match child_acc.output { - ChildOutputMut::Split { stdout, stderr } => ( - stdout.map(|x| x.freeze().into()), - stderr.map(|x| x.freeze().into()), - ), - ChildOutputMut::Combined(_) => unreachable!("setup scripts are always split"), - }; - Ok(( InternalSetupScriptExecuteStatus { - output: ChildSplitOutput { stdout, stderr }, + output: ChildExecutionResult::Output { + output: child_acc.output.freeze(), + errors: ErrorList::new( + ChildExecutionResult::WAITING_ON_SETUP_SCRIPT_MESSAGE, + errors, + ), + }, result: status, stopwatch_end: stopwatch.snapshot(), is_slow, @@ -1006,20 +997,13 @@ impl<'a> TestRunnerInner<'a> { .await { Ok(run_status) => run_status, - Err(error) => { - let message = error.to_string(); - let description = DisplayErrorChain::new(error).to_string(); - InternalExecuteStatus { - output: TestExecutionOutput::ExecFail { - message, - description, - }, - result: ExecutionResult::ExecFail, - stopwatch_end: stopwatch.snapshot(), - is_slow: false, - delay_before_start, - } - } + Err(error) => InternalExecuteStatus { + output: ChildExecutionResult::StartError(error), + result: ExecutionResult::ExecFail, + stopwatch_end: stopwatch.snapshot(), + is_slow: false, + delay_before_start, + }, } } @@ -1029,7 +1013,7 @@ impl<'a> TestRunnerInner<'a> { stopwatch: &mut StopwatchStart, resp_tx: &UnboundedSender>, req_rx: &mut UnboundedReceiver, - ) -> Result { + ) -> Result { let ctx = TestExecuteContext { double_spawn: &self.double_spawn, target_runner: &self.target_runner, @@ -1057,7 +1041,7 @@ impl<'a> TestRunnerInner<'a> { child_fds, } = cmd .spawn(self.capture_strategy) - .map_err(RunTestError::Spawn)?; + .map_err(|error| ChildStartError::Spawn(Arc::new(error)))?; // If assigning the child to the job fails, ignore this. This can happen if the process has // exited. @@ -1189,23 +1173,23 @@ impl<'a> TestRunnerInner<'a> { let exit_status = match res { Ok(exit_status) => Some(exit_status), Err(err) => { - child_acc.errors.push(ChildError::Wait(Arc::new(err))); + child_acc.errors.push(ChildFdError::Wait(Arc::new(err))); None } }; - if !child_acc.errors.is_empty() { - // TODO: we may wish to return whatever parts of the output we did collect here. - return Err(RunTestError::Child { - errors: ErrorList(child_acc.errors), - }); - } - let exit_status = exit_status.expect("None always results in early return"); - let result = status.unwrap_or_else(|| create_execution_result(exit_status, leaked)); + let result = status + .unwrap_or_else(|| create_execution_result(exit_status, &child_acc.errors, leaked)); Ok(InternalExecuteStatus { - output: TestExecutionOutput::Output(child_acc.output.freeze()), + output: ChildExecutionResult::Output { + output: child_acc.output.freeze(), + errors: ErrorList::new( + ChildExecutionResult::WAITING_ON_TEST_MESSAGE, + child_acc.errors, + ), + }, result, stopwatch_end: stopwatch.snapshot(), is_slow, @@ -1288,8 +1272,16 @@ async fn handle_signal_request( } } -fn create_execution_result(exit_status: ExitStatus, leaked: bool) -> ExecutionResult { - if exit_status.success() { +fn create_execution_result( + exit_status: ExitStatus, + child_errors: &[ChildFdError], + leaked: bool, +) -> ExecutionResult { + if !child_errors.is_empty() { + // If an error occurred while waiting on the child handles, treat it as + // an execution failure. + ExecutionResult::ExecFail + } else if exit_status.success() { if leaked { ExecutionResult::Leak } else { @@ -1483,7 +1475,7 @@ pub struct ExecuteStatus { /// Retry-related data. pub retry_data: RetryData, /// The stdout and stderr output for this test. - pub output: TestExecutionOutput, + pub output: ChildExecutionResult, /// The execution result for this test: pass, fail or execution error. pub result: ExecutionResult, /// The time at which the test started. @@ -1497,7 +1489,7 @@ pub struct ExecuteStatus { } struct InternalExecuteStatus { - output: TestExecutionOutput, + output: ChildExecutionResult, result: ExecutionResult, stopwatch_end: StopwatchSnapshot, is_slow: bool, @@ -1522,7 +1514,7 @@ impl InternalExecuteStatus { #[derive(Clone, Debug)] pub struct SetupScriptExecuteStatus { /// Output for this setup script. - pub output: ChildSplitOutput, + pub output: ChildExecutionResult, /// The execution result for this setup script: pass, fail or execution error. pub result: ExecutionResult, /// The time at which the script started. @@ -1536,7 +1528,7 @@ pub struct SetupScriptExecuteStatus { } struct InternalSetupScriptExecuteStatus { - output: ChildSplitOutput, + output: ChildExecutionResult, result: ExecutionResult, stopwatch_end: StopwatchSnapshot, is_slow: bool, @@ -1837,7 +1829,7 @@ impl<'a> SetupScriptPacket<'a> { &self, double_spawn: &DoubleSpawnInfo, test_list: &TestList<'_>, - ) -> Result { + ) -> Result { SetupScriptCommand::new(self.config, double_spawn, test_list) } diff --git a/nextest-runner/src/test_command.rs b/nextest-runner/src/test_command.rs index 7ef4b65bbba..52b737e49a2 100644 --- a/nextest-runner/src/test_command.rs +++ b/nextest-runner/src/test_command.rs @@ -20,7 +20,7 @@ use std::{ use tracing::warn; mod imp; -pub(crate) use imp::{Child, ChildAccumulator, ChildFds, ChildOutputMut}; +pub(crate) use imp::{Child, ChildAccumulator, ChildFds}; #[derive(Clone, Debug)] pub(crate) struct LocalExecuteContext<'a> { diff --git a/nextest-runner/src/test_command/imp.rs b/nextest-runner/src/test_command/imp.rs index 9aabebdf1ce..a51bd618778 100644 --- a/nextest-runner/src/test_command/imp.rs +++ b/nextest-runner/src/test_command/imp.rs @@ -2,8 +2,8 @@ // SPDX-License-Identifier: MIT OR Apache-2.0 use crate::{ - errors::ChildError, - test_output::{CaptureStrategy, ChildSplitOutput, TestOutput}, + errors::ChildFdError, + test_output::{CaptureStrategy, ChildOutput, ChildSplitOutput}, }; use bytes::BytesMut; use std::{io, process::Stdio, sync::Arc}; @@ -142,7 +142,7 @@ pub(crate) struct ChildAccumulator { // for `fill_buf` to select over it. pub(crate) fds: ChildFds, pub(crate) output: ChildOutputMut, - pub(crate) errors: Vec, + pub(crate) errors: Vec, } impl ChildAccumulator { @@ -218,17 +218,17 @@ impl ChildFds { /// We follow this "externalized progress" pattern rather than having the collect output futures /// own the data they're collecting, to enable future improvements where we can dump /// currently-captured output to the terminal. - pub(crate) async fn fill_buf(&mut self, acc: &mut ChildOutputMut) -> Result<(), ChildError> { + pub(crate) async fn fill_buf(&mut self, acc: &mut ChildOutputMut) -> Result<(), ChildFdError> { match self { Self::Split { stdout, stderr } => { let (stdout_acc, stderr_acc) = acc.as_split_mut(); // Wait until either of these make progress. tokio::select! { res = fill_buf_opt(stdout.as_mut(), stdout_acc), if !is_done_opt(stdout) => { - res.map_err(|error| ChildError::ReadStdout(Arc::new(error))) + res.map_err(|error| ChildFdError::ReadStdout(Arc::new(error))) } res = fill_buf_opt(stderr.as_mut(), stderr_acc), if !is_done_opt(stderr) => { - res.map_err(|error| ChildError::ReadStderr(Arc::new(error))) + res.map_err(|error| ChildFdError::ReadStderr(Arc::new(error))) } // If both are done, do nothing. else => { @@ -241,7 +241,7 @@ impl ChildFds { combined .fill_buf(acc.as_combined_mut()) .await - .map_err(|error| ChildError::ReadCombined(Arc::new(error))) + .map_err(|error| ChildFdError::ReadCombined(Arc::new(error))) } else { Ok(()) } @@ -277,13 +277,13 @@ impl ChildOutputMut { } /// Marks the collection as done, returning a `TestOutput`. - pub(crate) fn freeze(self) -> TestOutput { + pub(crate) fn freeze(self) -> ChildOutput { match self { - Self::Split { stdout, stderr } => TestOutput::Split(ChildSplitOutput { + Self::Split { stdout, stderr } => ChildOutput::Split(ChildSplitOutput { stdout: stdout.map(|x| x.freeze().into()), stderr: stderr.map(|x| x.freeze().into()), }), - Self::Combined(combined) => TestOutput::Combined { + Self::Combined(combined) => ChildOutput::Combined { output: combined.freeze().into(), }, } diff --git a/nextest-runner/src/test_output.rs b/nextest-runner/src/test_output.rs index 8e012ce2eec..b84e5165aa4 100644 --- a/nextest-runner/src/test_output.rs +++ b/nextest-runner/src/test_output.rs @@ -1,6 +1,7 @@ //! Utilities for capture output from tests run in a child process use crate::{ + errors::{ChildError, ChildStartError, ErrorList}, reporter::{heuristic_extract_description, DescriptionKind}, runner::ExecutionResult, }; @@ -88,27 +89,35 @@ impl ChildSingleOutput { } } -/// The complete captured output of a child process. +/// The result of executing a child process: either that the process was run and +/// at least some output was captured, or that the process could not be started +/// at all. #[derive(Clone, Debug)] -pub enum TestExecutionOutput { +pub enum ChildExecutionResult { /// The process was run and the output was captured. - Output(TestOutput), - - /// There was an execution failure. - ExecFail { - /// A single-line message. - message: String, + Output { + /// The captured output. + output: ChildOutput, - /// The full description, including other errors, to print out. - description: String, + /// Errors that occurred while waiting on the child process or parsing + /// its output. + errors: Option>, }, + + /// There was a failure to start the process. + StartError(ChildStartError), +} + +impl ChildExecutionResult { + pub(crate) const WAITING_ON_TEST_MESSAGE: &str = "waiting on test process"; + pub(crate) const WAITING_ON_SETUP_SCRIPT_MESSAGE: &str = "waiting on setup script process"; } -/// The output of a test. +/// The output of a child process: stdout and/or stderr. /// -/// Part of [`TestExecutionOutput`]. +/// Part of [`ChildExecutionResult`], and can be used independently as well. #[derive(Clone, Debug)] -pub enum TestOutput { +pub enum ChildOutput { /// The output was split into stdout and stderr. Split(ChildSplitOutput), @@ -121,7 +130,7 @@ pub enum TestOutput { /// The output of a child process (test or setup script) with split stdout and stderr. /// -/// Part of [`TestOutput`], and can be used independently as well. +/// One of the variants of [`ChildOutput`]. #[derive(Clone, Debug)] pub struct ChildSplitOutput { /// The captured stdout, or `None` if the output was not captured. @@ -131,7 +140,7 @@ pub struct ChildSplitOutput { pub stderr: Option, } -impl TestOutput { +impl ChildOutput { /// Attempts to extract a description of a test failure from the output of the test. pub fn heuristic_extract_description( &self, diff --git a/nextest-runner/tests/integration/basic.rs b/nextest-runner/tests/integration/basic.rs index 117fafa924e..25fb4e0d970 100644 --- a/nextest-runner/tests/integration/basic.rs +++ b/nextest-runner/tests/integration/basic.rs @@ -23,7 +23,7 @@ use nextest_runner::{ signal::SignalHandlerKind, target_runner::TargetRunner, test_filter::{RunIgnored, TestFilterBuilder, TestFilterPatterns}, - test_output::{TestExecutionOutput, TestOutput}, + test_output::{ChildExecutionResult, ChildOutput}, }; use pretty_assertions::assert_eq; use std::{io::Cursor, time::Duration}; @@ -172,8 +172,10 @@ fn test_run() -> Result<()> { if can_extract_description { // Check that stderr can be parsed heuristically. - let TestExecutionOutput::Output(TestOutput::Split(split)) = - &run_status.output + let ChildExecutionResult::Output { + output: ChildOutput::Split(split), + .. + } = &run_status.output else { panic!("this test should always use split output") }; diff --git a/nextest-runner/tests/integration/fixtures.rs b/nextest-runner/tests/integration/fixtures.rs index 5ae5ce7347c..79e204819fd 100644 --- a/nextest-runner/tests/integration/fixtures.rs +++ b/nextest-runner/tests/integration/fixtures.rs @@ -25,7 +25,7 @@ use nextest_runner::{ }, target_runner::TargetRunner, test_filter::{FilterBound, TestFilterBuilder}, - test_output::{TestExecutionOutput, TestOutput}, + test_output::{ChildExecutionResult, ChildOutput}, }; use once_cell::sync::Lazy; use std::{ @@ -295,7 +295,10 @@ impl fmt::Debug for InstanceStatus { InstanceStatus::Skipped(reason) => write!(f, "skipped: {reason}"), InstanceStatus::Finished(run_statuses) => { for run_status in run_statuses.iter() { - let TestExecutionOutput::Output(TestOutput::Split(split)) = &run_status.output + let ChildExecutionResult::Output { + output: ChildOutput::Split(split), + .. + } = &run_status.output else { panic!("this test should always use split output") };