From 0dd02e5a041750ef58dc59c41b0e330a1cfc9e6d Mon Sep 17 00:00:00 2001 From: Rain Date: Sun, 1 Dec 2024 08:16:42 +0000 Subject: [PATCH] [nextest-runner] improve data model for child error management I realized that we need a central way to identify and manage all the different ways in which a test or script can error out. Add a `UnitErrorDescription` struct which is responsible for all this management. --- cargo-nextest/src/dispatch.rs | 47 +- nextest-runner/src/errors.rs | 14 +- nextest-runner/src/reporter/aggregator.rs | 57 +- nextest-runner/src/reporter/displayer.rs | 70 +-- .../src/reporter/error_description.rs | 582 ++++++++++++++++++ nextest-runner/src/reporter/events.rs | 33 + nextest-runner/src/reporter/helpers.rs | 454 -------------- nextest-runner/src/reporter/mod.rs | 4 +- .../src/reporter/structured/libtest.rs | 25 +- nextest-runner/src/runner.rs | 41 +- nextest-runner/src/test_output.rs | 43 +- nextest-runner/tests/integration/basic.rs | 15 +- nextest-runner/tests/integration/fixtures.rs | 4 +- 13 files changed, 755 insertions(+), 634 deletions(-) create mode 100644 nextest-runner/src/reporter/error_description.rs diff --git a/cargo-nextest/src/dispatch.rs b/cargo-nextest/src/dispatch.rs index 4f3bfb348b7..576301b37c5 100644 --- a/cargo-nextest/src/dispatch.rs +++ b/cargo-nextest/src/dispatch.rs @@ -29,14 +29,11 @@ use nextest_runner::{ platform::{BuildPlatforms, HostPlatform, PlatformLibdir, TargetPlatform}, redact::Redactor, reporter::{ - heuristic_extract_description, highlight_end, structured, DescriptionKind, - FinalStatusLevel, StatusLevel, TestOutputDisplay, TestReporterBuilder, + heuristic_slice_from_output, highlight_end, structured, FinalStatusLevel, StatusLevel, + TestOutputDisplay, TestOutputErrorSlice, TestReporterBuilder, }, reuse_build::{archive_to_file, ArchiveReporter, PathMapper, ReuseBuildInfo}, - runner::{ - configure_handle_inheritance, ExecutionResult, FinalRunStats, RunStatsFailureKind, - TestRunnerBuilder, - }, + runner::{configure_handle_inheritance, FinalRunStats, RunStatsFailureKind, TestRunnerBuilder}, show_config::{ShowNextestVersion, ShowTestGroupSettings, ShowTestGroups, ShowTestGroupsMode}, signal::SignalHandlerKind, target_runner::{PlatformRunner, TargetRunner}, @@ -2083,8 +2080,8 @@ impl DebugCommand { } })?; - let description_kind = extract_description(&combined, &combined); - display_description_kind(description_kind, output_format)?; + let description_kind = extract_slice_from_output(&combined, &combined); + display_output_slice(description_kind, output_format)?; } else { let stdout = stdout .map(|path| { @@ -2111,8 +2108,8 @@ impl DebugCommand { .transpose()? .unwrap_or_default(); - let description_kind = extract_description(&stdout, &stderr); - display_description_kind(description_kind, output_format)?; + let output_slice = extract_slice_from_output(&stdout, &stderr); + display_output_slice(output_slice, output_format)?; } } } @@ -2121,25 +2118,20 @@ impl DebugCommand { } } -fn extract_description<'a>(stdout: &'a [u8], stderr: &'a [u8]) -> Option> { - // The execution result is a generic one. - heuristic_extract_description( - ExecutionResult::Fail { - abort_status: None, - leaked: false, - }, - Some(stdout), - Some(stderr), - ) +fn extract_slice_from_output<'a>( + stdout: &'a [u8], + stderr: &'a [u8], +) -> Option> { + heuristic_slice_from_output(Some(stdout), Some(stderr)) } -fn display_description_kind( - kind: Option>, +fn display_output_slice( + output_slice: Option>, output_format: ExtractOutputFormat, ) -> Result<()> { match output_format { ExtractOutputFormat::Raw => { - if let Some(kind) = kind { + if let Some(kind) = output_slice { if let Some(out) = kind.combined_subslice() { return std::io::stdout().write_all(out.slice).map_err(|err| { ExpectedError::DebugExtractWriteError { @@ -2151,15 +2143,12 @@ fn display_description_kind( } } ExtractOutputFormat::JunitDescription => { - if let Some(kind) = kind { - println!( - "{}", - XmlString::new(kind.display_human().to_string()).as_str() - ); + if let Some(kind) = output_slice { + println!("{}", XmlString::new(kind.to_string()).as_str()); } } ExtractOutputFormat::Highlight => { - if let Some(kind) = kind { + if let Some(kind) = output_slice { if let Some(out) = kind.combined_subslice() { let end = highlight_end(out.slice); return std::io::stdout() diff --git a/nextest-runner/src/errors.rs b/nextest-runner/src/errors.rs index a3fde7fd131..23c075b6211 100644 --- a/nextest-runner/src/errors.rs +++ b/nextest-runner/src/errors.rs @@ -355,14 +355,24 @@ impl ErrorList { } } - /// Returns a 1 line summary of the error list. - pub(crate) fn as_one_line_summary(&self) -> String { + /// Returns a short summary of the error list. + pub(crate) fn short_message(&self) -> String { if self.inner.len() == 1 { + // This assumes that the error's `std::error::Error` implementation + // provides a short message as its `Display` implementation. That + // isn't always true -- in fact, `ErrorList`'s own `Display` + // implementation is multi-line -- but it is true in practice for + // all the errors we have in place right now. We may want to make + // this better in the future. format!("{}", self.inner[0]) } else { format!("{} errors occurred {}", self.inner.len(), self.description) } } + + pub(crate) fn iter(&self) -> impl Iterator { + self.inner.iter() + } } impl fmt::Display for ErrorList { diff --git a/nextest-runner/src/reporter/aggregator.rs b/nextest-runner/src/reporter/aggregator.rs index da90ffd49f3..9c206862c93 100644 --- a/nextest-runner/src/reporter/aggregator.rs +++ b/nextest-runner/src/reporter/aggregator.rs @@ -3,14 +3,14 @@ //! Metadata management. -use super::TestEvent; +use super::{TestEvent, UnitErrorDescription, UnitKind}; use crate::{ config::{EvaluatableProfile, NextestJunitConfig}, errors::{DisplayErrorChain, WriteEventError}, list::TestInstance, reporter::TestEventKind, runner::{ExecuteStatus, ExecutionDescription, ExecutionResult}, - test_output::{ChildExecutionResult, ChildOutput}, + test_output::{ChildExecutionOutput, ChildOutput}, }; use camino::Utf8PathBuf; use debug_ignore::DebugIgnore; @@ -150,7 +150,7 @@ impl<'cfg> MetadataJunit<'cfg> { .set_type(ty); set_execute_status_props( - rerun, + &rerun.output, // Reruns are always failures. false, junit_store_failure_output, @@ -176,7 +176,7 @@ impl<'cfg> MetadataJunit<'cfg> { || (junit_store_failure_output && !is_success); set_execute_status_props( - main_status, + &main_status.output, is_success, store_stdout_stderr, TestcaseOrRerun::Testcase(&mut testcase), @@ -297,45 +297,34 @@ impl TestcaseOrRerun<'_> { } fn set_execute_status_props( - execute_status: &ExecuteStatus, + exec_output: &ChildExecutionOutput, is_success: bool, store_stdout_stderr: bool, mut out: TestcaseOrRerun<'_>, ) { - match &execute_status.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()); - } - } + // Currently we only aggregate test results, so always specify UnitKind::Test. + let description = UnitErrorDescription::new(UnitKind::Test, &exec_output); + if let Some(errors) = description.all_error_list() { + out.set_message(errors.short_message()); + out.set_description(DisplayErrorChain::new(errors).to_string()); + } - if store_stdout_stderr { - match output { - ChildOutput::Split(split) => { - if let Some(stdout) = &split.stdout { - out.set_system_out(stdout.as_str_lossy()); - } - if let Some(stderr) = &split.stderr { - out.set_system_err(stderr.as_str_lossy()); - } + if !is_success && store_stdout_stderr { + if let ChildExecutionOutput::Output { output, .. } = exec_output { + match output { + ChildOutput::Split(split) => { + if let Some(stdout) = &split.stdout { + out.set_system_out(stdout.as_str_lossy()); } - ChildOutput::Combined { output } => { - out.set_system_out(output.as_str_lossy()) - .set_system_err("(stdout and stderr are combined)"); + if let Some(stderr) = &split.stderr { + out.set_system_err(stderr.as_str_lossy()); } } + ChildOutput::Combined { output } => { + out.set_system_out(output.as_str_lossy()) + .set_system_err("(stdout and stderr are combined)"); + } } } - 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 038d138ebcc..06017872fc4 100644 --- a/nextest-runner/src/reporter/displayer.rs +++ b/nextest-runner/src/reporter/displayer.rs @@ -6,20 +6,20 @@ //! The main structure in this module is [`TestReporter`]. use super::{ - helpers::ByteSubslice, structured::StructuredReporter, CancelReason, DescriptionKind, - TestEvent, TestEventKind, + structured::StructuredReporter, ByteSubslice, CancelReason, TestEvent, TestEventKind, + TestOutputErrorSlice, UnitKind, }; use crate::{ config::{CompiledDefaultFilter, EvaluatableProfile, ScriptId}, errors::{DisplayErrorChain, WriteEventError}, helpers::{plural, DisplayScriptInstance, DisplayTestInstance}, list::{SkipCounts, TestInstance, TestList}, - reporter::{aggregator::EventAggregator, helpers::highlight_end}, + reporter::{aggregator::EventAggregator, helpers::highlight_end, UnitErrorDescription}, runner::{ AbortStatus, ExecuteStatus, ExecutionDescription, ExecutionResult, ExecutionStatuses, FinalRunStats, RetryData, RunStats, RunStatsFailureKind, SetupScriptExecuteStatus, }, - test_output::{ChildExecutionResult, ChildOutput, ChildSingleOutput}, + test_output::{ChildExecutionOutput, ChildOutput, ChildSingleOutput}, }; use bstr::ByteSlice; use debug_ignore::DebugIgnore; @@ -1375,26 +1375,7 @@ impl<'a> TestReporterImpl<'a> { writer: &mut dyn Write, ) -> io::Result<()> { let spec = self.output_spec_for_script(script_id, command, args, run_status); - - 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)?; - } - - self.write_child_output(&spec, output, None, writer)?; - } - - ChildExecutionResult::StartError(error) => { - let error_chain = DisplayErrorChain::new(error); - writeln!(writer, "{}\n{error_chain}", spec.exec_fail_header)?; - } - } - - writeln!(writer) + self.write_child_execution_output(&spec, &run_status.output, writer) } fn write_test_execute_status( @@ -1405,26 +1386,40 @@ impl<'a> TestReporterImpl<'a> { writer: &mut dyn Write, ) -> io::Result<()> { let spec = self.output_spec_for_test(test_instance, run_status, is_retry); + self.write_child_execution_output(&spec, &run_status.output, writer) + } + + fn write_child_execution_output( + &self, + spec: &ChildOutputSpec, + exec_output: &ChildExecutionOutput, + writer: &mut dyn Write, + ) -> io::Result<()> { + match exec_output { + ChildExecutionOutput::Output { + output, + // result and errors are captured by desc. + result: _, + errors: _, + } => { + let desc = UnitErrorDescription::new(spec.kind, exec_output); - 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 { + if let Some(errors) = desc.exec_fail_error_list() { 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) + let highlight_slice = if self.styles.is_colorized { + desc.output_slice() } else { None }; - let spec = self.output_spec_for_test(test_instance, run_status, is_retry); - self.write_child_output(&spec, output, description, writer)?; + self.write_child_output(&spec, output, highlight_slice, writer)?; } - ChildExecutionResult::StartError(error) => { + ChildExecutionOutput::StartError(error) => { let error_chain = DisplayErrorChain::new(error); writeln!(writer, "{}\n{error_chain}", spec.exec_fail_header)?; } @@ -1437,7 +1432,7 @@ impl<'a> TestReporterImpl<'a> { &self, spec: &ChildOutputSpec, output: &ChildOutput, - description: Option>, + highlight_slice: Option>, mut writer: &mut dyn Write, ) -> io::Result<()> { match output { @@ -1453,7 +1448,7 @@ impl<'a> TestReporterImpl<'a> { let mut indent_writer = IndentWriter::new(spec.output_indent, writer); self.write_test_single_output_with_description( stdout, - description.and_then(|d| d.stdout_subslice()), + highlight_slice.and_then(|d| d.stdout_subslice()), &mut indent_writer, )?; indent_writer.flush()?; @@ -1468,7 +1463,7 @@ impl<'a> TestReporterImpl<'a> { let mut indent_writer = IndentWriter::new(spec.output_indent, writer); self.write_test_single_output_with_description( stderr, - description.and_then(|d| d.stderr_subslice()), + highlight_slice.and_then(|d| d.stderr_subslice()), &mut indent_writer, )?; indent_writer.flush()?; @@ -1482,7 +1477,7 @@ impl<'a> TestReporterImpl<'a> { let mut indent_writer = IndentWriter::new(spec.output_indent, writer); self.write_test_single_output_with_description( output, - description.and_then(|d| d.combined_subslice()), + highlight_slice.and_then(|d| d.combined_subslice()), &mut indent_writer, )?; indent_writer.flush()?; @@ -1618,6 +1613,7 @@ impl<'a> TestReporterImpl<'a> { }; ChildOutputSpec { + kind: UnitKind::Test, stdout_header, stderr_header, combined_header, @@ -1680,6 +1676,7 @@ impl<'a> TestReporterImpl<'a> { }; ChildOutputSpec { + kind: UnitKind::Script, stdout_header, stderr_header, combined_header, @@ -1706,6 +1703,7 @@ const RESET_COLOR: &[u8] = b"\x1b[0m"; /// measurably slow. #[derive(Debug)] struct ChildOutputSpec { + kind: UnitKind, stdout_header: String, stderr_header: String, combined_header: String, diff --git a/nextest-runner/src/reporter/error_description.rs b/nextest-runner/src/reporter/error_description.rs new file mode 100644 index 00000000000..cde41996036 --- /dev/null +++ b/nextest-runner/src/reporter/error_description.rs @@ -0,0 +1,582 @@ +// Copyright (c) The nextest Contributors +// SPDX-License-Identifier: MIT OR Apache-2.0 + +use super::UnitKind; +use crate::{ + errors::{ChildError, ChildStartError, ErrorList}, + runner::{AbortStatus, ExecutionResult}, + test_output::{ChildExecutionOutput, ChildOutput}, +}; +use bstr::ByteSlice; +use once_cell::sync::Lazy; +use regex::bytes::{Regex, RegexBuilder}; +use std::fmt; +use thiserror::Error; + +/// Given an error or failure running a test or script, collects and aggregates +/// the most relevant information related to the issue. +#[derive(Clone, Debug)] +pub struct UnitErrorDescription<'a> { + kind: UnitKind, + start_error: Option<&'a ChildStartError>, + output_errors: Option<&'a ErrorList>, + abort: Option, + output_slice: Option>, +} + +impl<'a> UnitErrorDescription<'a> { + /// Adds the execution output of a child process to the description. + pub fn new(kind: UnitKind, output: &'a ChildExecutionOutput) -> Self { + let mut start_error = None; + let mut output_errors = None; + let mut abort = None; + let mut output_slice = None; + + match output { + ChildExecutionOutput::StartError(error) => { + start_error = Some(error); + } + ChildExecutionOutput::Output { + result, + output, + errors, + } => { + output_errors = errors.as_ref(); + if let Some(result) = result { + if kind == UnitKind::Test { + match output { + // Scanning the output for the most relevant slice + // only makes sense for completed tests. + ChildOutput::Split(output) => { + output_slice = heuristic_slice_from_output( + output.stdout.as_ref().map(|x| x.buf.as_ref()), + output.stderr.as_ref().map(|x| x.buf.as_ref()), + ); + } + ChildOutput::Combined { output } => { + output_slice = heuristic_slice_from_output( + Some(output.buf.as_ref()), + Some(output.buf.as_ref()), + ); + } + } + } + + if let ExecutionResult::Fail { + abort_status: Some(status), + leaked, + } = result + { + abort = Some(UnitAbortDescription { + status: *status, + leaked: *leaked, + }); + } + } + } + } + + Self { + kind, + start_error, + output_errors, + abort, + output_slice, + } + } + + /// Makes an `ErrorList` of all errors. + pub(crate) fn all_error_list(&self) -> Option> { + ErrorList::new(self.kind.executing_message(), self.all_errors().collect()) + } + + /// Makes an `ErrorList` of execution failure errors. + /// + /// This includes start and output errors, but not aborts or output slices. + pub(crate) fn exec_fail_error_list(&self) -> Option> { + ErrorList::new( + self.kind.executing_message(), + self.exec_fail_errors().collect(), + ) + } + + /// Makes an `ErrorList` of abort and output errors. + /// + /// This consists of all errors that are generated by the child process. + pub fn child_process_error_list(&self) -> Option> { + ErrorList::new( + self.kind.executing_message(), + self.child_process_errors().collect(), + ) + } + + pub(crate) fn output_slice(&self) -> Option> { + self.output_slice + } + + /// Builds an iterator over all of the reasons for the error. + fn all_errors(&self) -> impl Iterator { + self.exec_fail_errors().chain(self.child_process_errors()) + } + + fn exec_fail_errors(&self) -> impl Iterator { + self.start_error + .as_ref() + .map(|error| error as &dyn std::error::Error) + .into_iter() + .chain( + self.output_errors + .as_ref() + .into_iter() + .flat_map(|errors| errors.iter().map(|error| error as &dyn std::error::Error)), + ) + } + + fn child_process_errors(&self) -> impl Iterator { + self.abort + .as_ref() + .map(|abort| abort as &dyn std::error::Error) + .into_iter() + .chain( + self.output_slice + .as_ref() + .map(|slice| slice as &dyn std::error::Error), + ) + } +} + +#[derive(Clone, Copy, Debug, Error)] +struct UnitAbortDescription { + status: AbortStatus, + leaked: bool, +} + +impl fmt::Display for UnitAbortDescription { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + write!(f, "process aborted")?; + match self.status { + #[cfg(unix)] + AbortStatus::UnixSignal(sig) => { + let signal_str = crate::helpers::signal_str(sig) + .map(|signal_str| format!("SIG{signal_str}")) + .unwrap_or_else(|| sig.to_string()); + write!(f, " with signal {signal_str}")?; + } + #[cfg(windows)] + AbortStatus::WindowsNtStatus(exception) => { + write!( + f, + " with code {}", + crate::helpers::display_nt_status(exception) + )?; + } + } + if self.leaked { + write!(f, ", and also leaked handles")?; + } + Ok(()) + } +} + +/// The return result of [`heuristic_extract_description`]. +#[derive(Clone, Copy, Debug, Error)] +pub enum TestOutputErrorSlice<'a> { + /// A panic message was found in the output. + /// + /// The output is borrowed from standard error. + PanicMessage { + /// The subslice of standard error that contains the stack trace. + stderr_subslice: ByteSubslice<'a>, + }, + + /// An error string was found in the output. + /// + /// The output is borrowed from standard error. + ErrorStr { + /// The subslice of standard error that contains the stack trace. + stderr_subslice: ByteSubslice<'a>, + }, + + /// A should-panic test did not panic. + /// + /// The output is borrowed from standard output. + ShouldPanic { + /// The subslice of standard output that contains the should-panic message. + stdout_subslice: ByteSubslice<'a>, + }, +} + +impl<'a> TestOutputErrorSlice<'a> { + /// Returns the subslice of standard error that contains the description. + pub fn stderr_subslice(&self) -> Option> { + match self { + Self::PanicMessage { stderr_subslice } + | Self::ErrorStr { + stderr_subslice, .. + } => Some(*stderr_subslice), + Self::ShouldPanic { .. } => None, + } + } + + /// Returns the subslice of standard output that contains the description. + pub fn stdout_subslice(&self) -> Option> { + match self { + Self::PanicMessage { .. } => None, + Self::ErrorStr { .. } => None, + Self::ShouldPanic { + stdout_subslice, .. + } => Some(*stdout_subslice), + } + } + + /// Returns the subslice of combined output (either stdout or stderr) that contains the description. + pub fn combined_subslice(&self) -> Option> { + match self { + Self::PanicMessage { stderr_subslice } + | Self::ErrorStr { + stderr_subslice, .. + } => Some(*stderr_subslice), + Self::ShouldPanic { + stdout_subslice, .. + } => Some(*stdout_subslice), + } + } +} + +impl fmt::Display for TestOutputErrorSlice<'_> { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + match self { + Self::PanicMessage { stderr_subslice } => { + write!(f, "{}", String::from_utf8_lossy(stderr_subslice.slice)) + } + Self::ErrorStr { stderr_subslice } => { + write!(f, "{}", String::from_utf8_lossy(stderr_subslice.slice)) + } + Self::ShouldPanic { stdout_subslice } => { + write!(f, "{}", String::from_utf8_lossy(stdout_subslice.slice)) + } + } + } +} + +/// A subslice of a byte slice. +/// +/// This type tracks the start index of the subslice from the parent slice. +#[derive(Clone, Copy, Debug)] +pub struct ByteSubslice<'a> { + /// The slice. + pub slice: &'a [u8], + + /// The start index of the subslice from the parent slice. + pub start: usize, +} + +/// Attempts to heuristically extract a description of the test failure from the +/// output of the test. +/// +/// `None` indicates that output wasn't captured -- in those cases there isn't +/// much we can do. +pub fn heuristic_slice_from_output<'a>( + stdout: Option<&'a [u8]>, + stderr: Option<&'a [u8]>, +) -> Option> { + // Try the heuristic stack trace extraction first to try and grab more + // information first. + if let Some(stderr) = stderr { + if let Some(stderr_subslice) = heuristic_panic_message(stderr) { + return Some(TestOutputErrorSlice::PanicMessage { stderr_subslice }); + } + if let Some(stderr_subslice) = heuristic_error_str(stderr) { + return Some(TestOutputErrorSlice::ErrorStr { stderr_subslice }); + } + } + + if let Some(stdout) = stdout { + if let Some(stdout_subslice) = heuristic_should_panic(stdout) { + return Some(TestOutputErrorSlice::ShouldPanic { stdout_subslice }); + } + } + + None +} + +fn heuristic_should_panic(stdout: &[u8]) -> Option> { + let line = stdout + .lines() + .find(|line| line.contains_str("note: test did not panic as expected"))?; + + // SAFETY: line is a subslice of stdout. + let start = unsafe { line.as_ptr().offset_from(stdout.as_ptr()) }; + + let start = usize::try_from(start).unwrap_or_else(|error| { + panic!( + "negative offset from stdout.as_ptr() ({:x}) to line.as_ptr() ({:x}): {}", + stdout.as_ptr() as usize, + line.as_ptr() as usize, + error + ) + }); + Some(ByteSubslice { slice: line, start }) +} + +fn heuristic_panic_message(stderr: &[u8]) -> Option> { + // Look for the last instance to handle situations like proptest which repeatedly print out + // `panicked at ...` messages. + let panicked_at_match = PANICKED_AT_REGEX.find_iter(stderr).last()?; + // If the previous line starts with "Error: ", grab it as well -- it contains the error with + // result-based test failures. + let mut start = panicked_at_match.start(); + let prefix = stderr[..start].trim_end_with(|c| c == '\n' || c == '\r'); + if let Some(prev_line_start) = prefix.rfind("\n") { + if prefix[prev_line_start..].starts_with_str("\nError:") { + start = prev_line_start + 1; + } + } + + // TODO: this grabs too much -- it is possible that destructors print out further messages so we + // should be more careful. But it's hard to tell what's printed by the panic and what's printed + // by destructors, so we lean on the side of caution. + Some(ByteSubslice { + slice: stderr[start..].trim_end_with(|c| c.is_whitespace()), + start, + }) +} + +fn heuristic_error_str(stderr: &[u8]) -> Option> { + // Starting Rust 1.66, Result-based errors simply print out "Error: ". + let error_match = ERROR_REGEX.find(stderr)?; + let start = error_match.start(); + + // TODO: this grabs too much -- it is possible that destructors print out further messages so we + // should be more careful. But it's hard to tell what's printed by the error and what's printed + // by destructors, so we lean on the side of caution. + Some(ByteSubslice { + slice: stderr[start..].trim_end_with(|c| c.is_whitespace()), + start, + }) +} + +// This regex works for the default panic handler for Rust -- other panic handlers may not work, +// which is why this is heuristic. +static PANICKED_AT_REGEX_STR: &str = "^thread '([^']+)' panicked at "; +static PANICKED_AT_REGEX: Lazy = Lazy::new(|| { + let mut builder = RegexBuilder::new(PANICKED_AT_REGEX_STR); + builder.multi_line(true); + builder.build().unwrap() +}); + +static ERROR_REGEX_STR: &str = "^Error: "; +static ERROR_REGEX: Lazy = Lazy::new(|| { + let mut builder = RegexBuilder::new(ERROR_REGEX_STR); + builder.multi_line(true); + builder.build().unwrap() +}); + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn test_heuristic_should_panic() { + let tests: &[(&str, &str)] = &[( + "running 1 test +test test_failure_should_panic - should panic ... FAILED + +failures: + +---- test_failure_should_panic stdout ---- +note: test did not panic as expected + +failures: + test_failure_should_panic + +test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 13 filtered out; finished in 0.00s", + "note: test did not panic as expected", + )]; + + for (input, output) in tests { + let extracted = heuristic_should_panic(input.as_bytes()) + .expect("should-panic message should have been found"); + assert_eq!( + DisplayWrapper(extracted.slice), + DisplayWrapper(output.as_bytes()) + ); + assert_eq!( + extracted.start, + extracted.slice.as_ptr() as usize - input.as_bytes().as_ptr() as usize + ); + } + } + + #[test] + fn test_heuristic_panic_message() { + let tests: &[(&str, &str)] = &[ + ( + "thread 'main' panicked at 'foo', src/lib.rs:1\n", + "thread 'main' panicked at 'foo', src/lib.rs:1", + ), + ( + "foobar\n\ + thread 'main' panicked at 'foo', src/lib.rs:1\n\n", + "thread 'main' panicked at 'foo', src/lib.rs:1", + ), + ( + r#" +text: foo +Error: Custom { kind: InvalidData, error: "this is an error" } +thread 'test_result_failure' panicked at 'assertion failed: `(left == right)` + left: `1`, + right: `0`: the test returned a termination value with a non-zero status code (1) which indicates a failure', /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/test/src/lib.rs:186:5 +note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace +more text at the end, followed by some newlines + + + "#, + r#"Error: Custom { kind: InvalidData, error: "this is an error" } +thread 'test_result_failure' panicked at 'assertion failed: `(left == right)` + left: `1`, + right: `0`: the test returned a termination value with a non-zero status code (1) which indicates a failure', /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/test/src/lib.rs:186:5 +note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace +more text at the end, followed by some newlines"#, + ), + // Multiple panics: only the last one should be extracted. + ( + r#" +thread 'main' panicked at src/lib.rs:1: +foo +thread 'main' panicked at src/lib.rs:2: +bar +"#, + r#"thread 'main' panicked at src/lib.rs:2: +bar"#, + ), // With RUST_BACKTRACE=1 + ( + r#" +some initial text +line 2 +line 3 +thread 'reporter::helpers::tests::test_heuristic_stack_trace' panicked at nextest-runner/src/reporter/helpers.rs:237:9: +test +stack backtrace: + 0: rust_begin_unwind + at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/panicking.rs:652:5 + 1: core::panicking::panic_fmt + at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/panicking.rs:72:14 + 2: nextest_runner::reporter::helpers::tests::test_heuristic_stack_trace + at ./src/reporter/helpers.rs:237:9 + 3: nextest_runner::reporter::helpers::tests::test_heuristic_stack_trace::{{closure}} + at ./src/reporter/helpers.rs:236:36 + 4: core::ops::function::FnOnce::call_once + at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/ops/function.rs:250:5 + 5: core::ops::function::FnOnce::call_once + at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/ops/function.rs:250:5 +note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace. +more text at the end, followed by some newlines + + +"#, + r#"thread 'reporter::helpers::tests::test_heuristic_stack_trace' panicked at nextest-runner/src/reporter/helpers.rs:237:9: +test +stack backtrace: + 0: rust_begin_unwind + at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/panicking.rs:652:5 + 1: core::panicking::panic_fmt + at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/panicking.rs:72:14 + 2: nextest_runner::reporter::helpers::tests::test_heuristic_stack_trace + at ./src/reporter/helpers.rs:237:9 + 3: nextest_runner::reporter::helpers::tests::test_heuristic_stack_trace::{{closure}} + at ./src/reporter/helpers.rs:236:36 + 4: core::ops::function::FnOnce::call_once + at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/ops/function.rs:250:5 + 5: core::ops::function::FnOnce::call_once + at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/ops/function.rs:250:5 +note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace. +more text at the end, followed by some newlines"#, + ), + // RUST_BACKTRACE=full + ( + r#" +some initial text +thread 'reporter::helpers::tests::test_heuristic_stack_trace' panicked at nextest-runner/src/reporter/helpers.rs:237:9: +test +stack backtrace: + 0: 0x61e6da135fe5 - std::backtrace_rs::backtrace::libunwind::trace::h23054e327d0d4b55 + at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/../../backtrace/src/backtrace/libunwind.rs:116:5 + 1: 0x61e6da135fe5 - std::backtrace_rs::backtrace::trace_unsynchronized::h0cc587407d7f7f64 + at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5 + 2: 0x61e6da135fe5 - std::sys_common::backtrace::_print_fmt::h4feeb59774730d6b + at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/sys_common/backtrace.rs:68:5 + 3: 0x61e6da135fe5 - ::fmt::hd736fd5964392270 + at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/sys_common/backtrace.rs:44:22 + 4: 0x61e6da16433b - core::fmt::rt::Argument::fmt::h105051d8ea1ade1e + at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/fmt/rt.rs:165:63 + 5: 0x61e6da16433b - core::fmt::write::hc6043626647b98ea + at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/fmt/mod.rs:1168:21 +some more text at the end, followed by some newlines + + +"#, + r#"thread 'reporter::helpers::tests::test_heuristic_stack_trace' panicked at nextest-runner/src/reporter/helpers.rs:237:9: +test +stack backtrace: + 0: 0x61e6da135fe5 - std::backtrace_rs::backtrace::libunwind::trace::h23054e327d0d4b55 + at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/../../backtrace/src/backtrace/libunwind.rs:116:5 + 1: 0x61e6da135fe5 - std::backtrace_rs::backtrace::trace_unsynchronized::h0cc587407d7f7f64 + at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5 + 2: 0x61e6da135fe5 - std::sys_common::backtrace::_print_fmt::h4feeb59774730d6b + at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/sys_common/backtrace.rs:68:5 + 3: 0x61e6da135fe5 - ::fmt::hd736fd5964392270 + at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/sys_common/backtrace.rs:44:22 + 4: 0x61e6da16433b - core::fmt::rt::Argument::fmt::h105051d8ea1ade1e + at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/fmt/rt.rs:165:63 + 5: 0x61e6da16433b - core::fmt::write::hc6043626647b98ea + at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/fmt/mod.rs:1168:21 +some more text at the end, followed by some newlines"#, + ), + ]; + + for (input, output) in tests { + let extracted = heuristic_panic_message(input.as_bytes()) + .expect("stack trace should have been found"); + assert_eq!( + DisplayWrapper(extracted.slice), + DisplayWrapper(output.as_bytes()) + ); + assert_eq!( + extracted.start, + extracted.slice.as_ptr() as usize - input.as_bytes().as_ptr() as usize + ); + } + } + + #[test] + fn test_heuristic_error_str() { + let tests: &[(&str, &str)] = &[( + "foobar\nError: \"this is an error\"\n", + "Error: \"this is an error\"", + )]; + + for (input, output) in tests { + let extracted = + heuristic_error_str(input.as_bytes()).expect("error string should have been found"); + assert_eq!( + DisplayWrapper(extracted.slice), + DisplayWrapper(output.as_bytes()) + ); + assert_eq!( + extracted.start, + extracted.slice.as_ptr() as usize - input.as_bytes().as_ptr() as usize + ); + } + } + + // Wrapper so that panic messages show up nicely in the test output. + #[derive(Eq, PartialEq)] + struct DisplayWrapper<'a>(&'a [u8]); + + impl fmt::Debug for DisplayWrapper<'_> { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + write!(f, "{}", String::from_utf8_lossy(self.0)) + } + } +} diff --git a/nextest-runner/src/reporter/events.rs b/nextest-runner/src/reporter/events.rs index 6ba46b5df2d..271f9c9ab64 100644 --- a/nextest-runner/src/reporter/events.rs +++ b/nextest-runner/src/reporter/events.rs @@ -289,3 +289,36 @@ impl CancelReason { } } } + +/// The kind of unit of work that nextest is executing. +#[derive(Clone, Copy, Debug, PartialEq, Eq)] +pub enum UnitKind { + /// A test. + Test, + + /// A script (e.g. a setup script). + Script, +} + +impl UnitKind { + pub(crate) const WAITING_ON_TEST_MESSAGE: &str = "waiting on test process"; + pub(crate) const WAITING_ON_SCRIPT_MESSAGE: &str = "waiting on script process"; + + pub(crate) const EXECUTING_TEST_MESSAGE: &str = "executing test"; + pub(crate) const EXECUTING_SCRIPT_MESSAGE: &str = "executing script"; + + #[expect(dead_code)] + pub(crate) fn waiting_on_message(&self) -> &'static str { + match self { + UnitKind::Test => Self::WAITING_ON_TEST_MESSAGE, + UnitKind::Script => Self::WAITING_ON_SCRIPT_MESSAGE, + } + } + + pub(crate) fn executing_message(&self) -> &'static str { + match self { + UnitKind::Test => Self::EXECUTING_TEST_MESSAGE, + UnitKind::Script => Self::EXECUTING_SCRIPT_MESSAGE, + } + } +} diff --git a/nextest-runner/src/reporter/helpers.rs b/nextest-runner/src/reporter/helpers.rs index 99bba6ba0fe..58064b96aab 100644 --- a/nextest-runner/src/reporter/helpers.rs +++ b/nextest-runner/src/reporter/helpers.rs @@ -1,257 +1,7 @@ // Copyright (c) The nextest Contributors // SPDX-License-Identifier: MIT OR Apache-2.0 -use crate::runner::{AbortStatus, ExecutionResult}; use bstr::ByteSlice; -use once_cell::sync::Lazy; -use regex::bytes::{Regex, RegexBuilder}; -use std::fmt; - -// This regex works for the default panic handler for Rust -- other panic handlers may not work, -// which is why this is heuristic. -static PANICKED_AT_REGEX_STR: &str = "^thread '([^']+)' panicked at "; -static PANICKED_AT_REGEX: Lazy = Lazy::new(|| { - let mut builder = RegexBuilder::new(PANICKED_AT_REGEX_STR); - builder.multi_line(true); - builder.build().unwrap() -}); - -static ERROR_REGEX_STR: &str = "^Error: "; -static ERROR_REGEX: Lazy = Lazy::new(|| { - let mut builder = RegexBuilder::new(ERROR_REGEX_STR); - builder.multi_line(true); - builder.build().unwrap() -}); - -/// The return result of [`heuristic_extract_description`]. -#[derive(Clone, Copy, Debug)] -pub enum DescriptionKind<'a> { - /// This was some kind of abort. - Abort { - /// The reason for the abort. - status: AbortStatus, - /// Whether the test leaked handles. - leaked: bool, - }, - - /// A panic message was found in the output. - /// - /// The output is borrowed from standard error. - PanicMessage { - /// The subslice of standard error that contains the stack trace. - stderr_subslice: ByteSubslice<'a>, - }, - - /// An error string was found in the output. - /// - /// The output is borrowed from standard error. - ErrorStr { - /// The subslice of standard error that contains the stack trace. - stderr_subslice: ByteSubslice<'a>, - }, - - /// A should-panic test did not panic. - /// - /// The output is borrowed from standard output. - ShouldPanic { - /// The subslice of standard output that contains the should-panic message. - stdout_subslice: ByteSubslice<'a>, - }, -} - -impl<'a> DescriptionKind<'a> { - /// Returns the subslice of standard error that contains the description. - pub fn stderr_subslice(&self) -> Option> { - match self { - DescriptionKind::Abort { .. } => None, - DescriptionKind::PanicMessage { stderr_subslice } - | DescriptionKind::ErrorStr { - stderr_subslice, .. - } => Some(*stderr_subslice), - DescriptionKind::ShouldPanic { .. } => None, - } - } - - /// Returns the subslice of standard output that contains the description. - pub fn stdout_subslice(&self) -> Option> { - match self { - DescriptionKind::Abort { .. } => None, - DescriptionKind::PanicMessage { .. } => None, - DescriptionKind::ErrorStr { .. } => None, - DescriptionKind::ShouldPanic { - stdout_subslice, .. - } => Some(*stdout_subslice), - } - } - - /// Returns the subslice of combined output (either stdout or stderr) that contains the description. - pub fn combined_subslice(&self) -> Option> { - match self { - DescriptionKind::Abort { .. } => None, - DescriptionKind::PanicMessage { stderr_subslice } - | DescriptionKind::ErrorStr { - stderr_subslice, .. - } => Some(*stderr_subslice), - DescriptionKind::ShouldPanic { - stdout_subslice, .. - } => Some(*stdout_subslice), - } - } - - /// Displays the description as a user-friendly string. - pub fn display_human(&self) -> DescriptionKindDisplay<'_> { - DescriptionKindDisplay(*self) - } -} - -/// A subslice of a byte slice. -/// -/// This type tracks the start index of the subslice from the parent slice. -#[derive(Clone, Copy, Debug)] -pub struct ByteSubslice<'a> { - /// The slice. - pub slice: &'a [u8], - - /// The start index of the subslice from the parent slice. - pub start: usize, -} - -/// A display wrapper for [`DescriptionKind`]. -#[derive(Clone, Copy, Debug)] -pub struct DescriptionKindDisplay<'a>(DescriptionKind<'a>); - -impl fmt::Display for DescriptionKindDisplay<'_> { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - match self.0 { - DescriptionKind::Abort { status, leaked } => { - write!(f, "Test aborted")?; - match status { - #[cfg(unix)] - AbortStatus::UnixSignal(sig) => { - let signal_str = crate::helpers::signal_str(sig) - .map(|signal_str| format!("SIG{signal_str}")) - .unwrap_or_else(|| sig.to_string()); - write!(f, " with signal {signal_str}")?; - } - #[cfg(windows)] - AbortStatus::WindowsNtStatus(exception) => { - write!( - f, - " with code {}", - crate::helpers::display_nt_status(exception) - )?; - } - } - if leaked { - write!(f, ", and also leaked handles")?; - } - Ok(()) - } - DescriptionKind::PanicMessage { stderr_subslice } => { - // Strip invalid XML characters. - write!(f, "{}", String::from_utf8_lossy(stderr_subslice.slice)) - } - DescriptionKind::ErrorStr { stderr_subslice } => { - write!(f, "{}", String::from_utf8_lossy(stderr_subslice.slice)) - } - DescriptionKind::ShouldPanic { stdout_subslice } => { - write!(f, "{}", String::from_utf8_lossy(stdout_subslice.slice)) - } - } - } -} - -/// Attempts to heuristically extract a description of the test failure from the output of the test. -/// -/// `None` indicates that output wasn't captured -- in those cases there isn't much we can do. -pub fn heuristic_extract_description<'a>( - exec_result: ExecutionResult, - stdout: Option<&'a [u8]>, - stderr: Option<&'a [u8]>, -) -> Option> { - // If the test crashed with a signal, use that. - if let ExecutionResult::Fail { - abort_status: Some(status), - leaked, - } = exec_result - { - return Some(DescriptionKind::Abort { status, leaked }); - } - - // Try the heuristic stack trace extraction first to try and grab more information first. - if let Some(stderr) = stderr { - if let Some(stderr_subslice) = heuristic_panic_message(stderr) { - return Some(DescriptionKind::PanicMessage { stderr_subslice }); - } - if let Some(stderr_subslice) = heuristic_error_str(stderr) { - return Some(DescriptionKind::ErrorStr { stderr_subslice }); - } - } - - if let Some(stdout) = stdout { - if let Some(stdout_subslice) = heuristic_should_panic(stdout) { - return Some(DescriptionKind::ShouldPanic { stdout_subslice }); - } - } - - None -} - -fn heuristic_should_panic(stdout: &[u8]) -> Option> { - let line = stdout - .lines() - .find(|line| line.contains_str("note: test did not panic as expected"))?; - - // SAFETY: line is a subslice of stdout. - let start = unsafe { line.as_ptr().offset_from(stdout.as_ptr()) }; - - let start = usize::try_from(start).unwrap_or_else(|error| { - panic!( - "negative offset from stdout.as_ptr() ({:x}) to line.as_ptr() ({:x}): {}", - stdout.as_ptr() as usize, - line.as_ptr() as usize, - error - ) - }); - Some(ByteSubslice { slice: line, start }) -} - -fn heuristic_panic_message(stderr: &[u8]) -> Option> { - // Look for the last instance to handle situations like proptest which repeatedly print out - // `panicked at ...` messages. - let panicked_at_match = PANICKED_AT_REGEX.find_iter(stderr).last()?; - // If the previous line starts with "Error: ", grab it as well -- it contains the error with - // result-based test failures. - let mut start = panicked_at_match.start(); - let prefix = stderr[..start].trim_end_with(|c| c == '\n' || c == '\r'); - if let Some(prev_line_start) = prefix.rfind("\n") { - if prefix[prev_line_start..].starts_with_str("\nError:") { - start = prev_line_start + 1; - } - } - - // TODO: this grabs too much -- it is possible that destructors print out further messages so we - // should be more careful. But it's hard to tell what's printed by the panic and what's printed - // by destructors, so we lean on the side of caution. - Some(ByteSubslice { - slice: stderr[start..].trim_end_with(|c| c.is_whitespace()), - start, - }) -} - -fn heuristic_error_str(stderr: &[u8]) -> Option> { - // Starting Rust 1.66, Result-based errors simply print out "Error: ". - let error_match = ERROR_REGEX.find(stderr)?; - let start = error_match.start(); - - // TODO: this grabs too much -- it is possible that destructors print out further messages so we - // should be more careful. But it's hard to tell what's printed by the error and what's printed - // by destructors, so we lean on the side of caution. - Some(ByteSubslice { - slice: stderr[start..].trim_end_with(|c| c.is_whitespace()), - start, - }) -} /// Given a slice, find the index of the point at which highlighting should end. /// @@ -276,200 +26,6 @@ pub fn highlight_end(slice: &[u8]) -> usize { mod tests { use super::*; - #[test] - fn test_heuristic_should_panic() { - let tests: &[(&str, &str)] = &[( - "running 1 test -test test_failure_should_panic - should panic ... FAILED - -failures: - ----- test_failure_should_panic stdout ---- -note: test did not panic as expected - -failures: - test_failure_should_panic - -test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 13 filtered out; finished in 0.00s", - "note: test did not panic as expected", - )]; - - for (input, output) in tests { - let extracted = heuristic_should_panic(input.as_bytes()) - .expect("should-panic message should have been found"); - assert_eq!( - DisplayWrapper(extracted.slice), - DisplayWrapper(output.as_bytes()) - ); - assert_eq!( - extracted.start, - extracted.slice.as_ptr() as usize - input.as_bytes().as_ptr() as usize - ); - } - } - - #[test] - fn test_heuristic_panic_message() { - let tests: &[(&str, &str)] = &[ - ( - "thread 'main' panicked at 'foo', src/lib.rs:1\n", - "thread 'main' panicked at 'foo', src/lib.rs:1", - ), - ( - "foobar\n\ - thread 'main' panicked at 'foo', src/lib.rs:1\n\n", - "thread 'main' panicked at 'foo', src/lib.rs:1", - ), - ( - r#" -text: foo -Error: Custom { kind: InvalidData, error: "this is an error" } -thread 'test_result_failure' panicked at 'assertion failed: `(left == right)` - left: `1`, - right: `0`: the test returned a termination value with a non-zero status code (1) which indicates a failure', /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/test/src/lib.rs:186:5 -note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace -more text at the end, followed by some newlines - - - "#, - r#"Error: Custom { kind: InvalidData, error: "this is an error" } -thread 'test_result_failure' panicked at 'assertion failed: `(left == right)` - left: `1`, - right: `0`: the test returned a termination value with a non-zero status code (1) which indicates a failure', /rustc/fe5b13d681f25ee6474be29d748c65adcd91f69e/library/test/src/lib.rs:186:5 -note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace -more text at the end, followed by some newlines"#, - ), - // Multiple panics: only the last one should be extracted. - ( - r#" -thread 'main' panicked at src/lib.rs:1: -foo -thread 'main' panicked at src/lib.rs:2: -bar -"#, - r#"thread 'main' panicked at src/lib.rs:2: -bar"#, - ), // With RUST_BACKTRACE=1 - ( - r#" -some initial text -line 2 -line 3 -thread 'reporter::helpers::tests::test_heuristic_stack_trace' panicked at nextest-runner/src/reporter/helpers.rs:237:9: -test -stack backtrace: - 0: rust_begin_unwind - at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/panicking.rs:652:5 - 1: core::panicking::panic_fmt - at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/panicking.rs:72:14 - 2: nextest_runner::reporter::helpers::tests::test_heuristic_stack_trace - at ./src/reporter/helpers.rs:237:9 - 3: nextest_runner::reporter::helpers::tests::test_heuristic_stack_trace::{{closure}} - at ./src/reporter/helpers.rs:236:36 - 4: core::ops::function::FnOnce::call_once - at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/ops/function.rs:250:5 - 5: core::ops::function::FnOnce::call_once - at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/ops/function.rs:250:5 -note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace. -more text at the end, followed by some newlines - - -"#, - r#"thread 'reporter::helpers::tests::test_heuristic_stack_trace' panicked at nextest-runner/src/reporter/helpers.rs:237:9: -test -stack backtrace: - 0: rust_begin_unwind - at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/panicking.rs:652:5 - 1: core::panicking::panic_fmt - at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/panicking.rs:72:14 - 2: nextest_runner::reporter::helpers::tests::test_heuristic_stack_trace - at ./src/reporter/helpers.rs:237:9 - 3: nextest_runner::reporter::helpers::tests::test_heuristic_stack_trace::{{closure}} - at ./src/reporter/helpers.rs:236:36 - 4: core::ops::function::FnOnce::call_once - at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/ops/function.rs:250:5 - 5: core::ops::function::FnOnce::call_once - at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/ops/function.rs:250:5 -note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace. -more text at the end, followed by some newlines"#, - ), - // RUST_BACKTRACE=full - ( - r#" -some initial text -thread 'reporter::helpers::tests::test_heuristic_stack_trace' panicked at nextest-runner/src/reporter/helpers.rs:237:9: -test -stack backtrace: - 0: 0x61e6da135fe5 - std::backtrace_rs::backtrace::libunwind::trace::h23054e327d0d4b55 - at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/../../backtrace/src/backtrace/libunwind.rs:116:5 - 1: 0x61e6da135fe5 - std::backtrace_rs::backtrace::trace_unsynchronized::h0cc587407d7f7f64 - at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5 - 2: 0x61e6da135fe5 - std::sys_common::backtrace::_print_fmt::h4feeb59774730d6b - at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/sys_common/backtrace.rs:68:5 - 3: 0x61e6da135fe5 - ::fmt::hd736fd5964392270 - at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/sys_common/backtrace.rs:44:22 - 4: 0x61e6da16433b - core::fmt::rt::Argument::fmt::h105051d8ea1ade1e - at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/fmt/rt.rs:165:63 - 5: 0x61e6da16433b - core::fmt::write::hc6043626647b98ea - at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/fmt/mod.rs:1168:21 -some more text at the end, followed by some newlines - - -"#, - r#"thread 'reporter::helpers::tests::test_heuristic_stack_trace' panicked at nextest-runner/src/reporter/helpers.rs:237:9: -test -stack backtrace: - 0: 0x61e6da135fe5 - std::backtrace_rs::backtrace::libunwind::trace::h23054e327d0d4b55 - at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/../../backtrace/src/backtrace/libunwind.rs:116:5 - 1: 0x61e6da135fe5 - std::backtrace_rs::backtrace::trace_unsynchronized::h0cc587407d7f7f64 - at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5 - 2: 0x61e6da135fe5 - std::sys_common::backtrace::_print_fmt::h4feeb59774730d6b - at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/sys_common/backtrace.rs:68:5 - 3: 0x61e6da135fe5 - ::fmt::hd736fd5964392270 - at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/sys_common/backtrace.rs:44:22 - 4: 0x61e6da16433b - core::fmt::rt::Argument::fmt::h105051d8ea1ade1e - at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/fmt/rt.rs:165:63 - 5: 0x61e6da16433b - core::fmt::write::hc6043626647b98ea - at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/fmt/mod.rs:1168:21 -some more text at the end, followed by some newlines"#, - ), - ]; - - for (input, output) in tests { - let extracted = heuristic_panic_message(input.as_bytes()) - .expect("stack trace should have been found"); - assert_eq!( - DisplayWrapper(extracted.slice), - DisplayWrapper(output.as_bytes()) - ); - assert_eq!( - extracted.start, - extracted.slice.as_ptr() as usize - input.as_bytes().as_ptr() as usize - ); - } - } - - #[test] - fn test_heuristic_error_str() { - let tests: &[(&str, &str)] = &[( - "foobar\nError: \"this is an error\"\n", - "Error: \"this is an error\"", - )]; - - for (input, output) in tests { - let extracted = - heuristic_error_str(input.as_bytes()).expect("error string should have been found"); - assert_eq!( - DisplayWrapper(extracted.slice), - DisplayWrapper(output.as_bytes()) - ); - assert_eq!( - extracted.start, - extracted.slice.as_ptr() as usize - input.as_bytes().as_ptr() as usize - ); - } - } - #[test] fn test_highlight_end() { let tests: &[(&str, usize)] = &[ @@ -492,14 +48,4 @@ some more text at the end, followed by some newlines"#, ); } } - - // Wrapper so that panic messages show up nicely in the test output. - #[derive(Eq, PartialEq)] - struct DisplayWrapper<'a>(&'a [u8]); - - impl fmt::Debug for DisplayWrapper<'_> { - fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - write!(f, "{}", String::from_utf8_lossy(self.0)) - } - } } diff --git a/nextest-runner/src/reporter/mod.rs b/nextest-runner/src/reporter/mod.rs index 3905d9e4c0d..6ffd135a1c8 100644 --- a/nextest-runner/src/reporter/mod.rs +++ b/nextest-runner/src/reporter/mod.rs @@ -7,10 +7,12 @@ mod aggregator; mod displayer; +mod error_description; mod events; mod helpers; pub mod structured; pub use displayer::*; +pub use error_description::*; pub use events::*; -pub use helpers::{heuristic_extract_description, highlight_end, DescriptionKind}; +pub use helpers::highlight_end; diff --git a/nextest-runner/src/reporter/structured/libtest.rs b/nextest-runner/src/reporter/structured/libtest.rs index 65eb4bb58fa..3265b53ef3b 100644 --- a/nextest-runner/src/reporter/structured/libtest.rs +++ b/nextest-runner/src/reporter/structured/libtest.rs @@ -28,7 +28,7 @@ use crate::{ list::RustTestSuite, reporter::TestEventKind, runner::ExecutionResult, - test_output::{ChildExecutionResult, ChildOutput, ChildSingleOutput}, + test_output::{ChildExecutionOutput, ChildOutput, ChildSingleOutput}, }; use bstr::ByteSlice; use nextest_metadata::MismatchReason; @@ -491,12 +491,16 @@ 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: &ChildExecutionResult, + output: &ChildExecutionOutput, out: &mut bytes::BytesMut, test_name: &str, ) -> Result<(), WriteEventError> { match output { - ChildExecutionResult::Output { output, errors } => { + ChildExecutionOutput::Output { + result: _, + output, + errors, + } => { match output { ChildOutput::Combined { output } => { strip_human_stdout_or_combined(output, out, test_name)?; @@ -540,7 +544,7 @@ fn strip_human_output_from_failed_test( .map_err(fmt_err)?; } } - ChildExecutionResult::StartError(error) => { + ChildExecutionOutput::StartError(error) => { write!(out, "--- EXECUTION ERROR ---\\n").map_err(fmt_err)?; write!( out, @@ -665,7 +669,7 @@ mod test { use crate::{ errors::ChildStartError, reporter::structured::libtest::strip_human_output_from_failed_test, - test_output::{ChildExecutionResult, ChildOutput, ChildSplitOutput}, + test_output::{ChildExecutionOutput, ChildOutput, ChildSplitOutput}, }; use bytes::BytesMut; use color_eyre::eyre::eyre; @@ -717,7 +721,8 @@ note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose bac let mut actual = bytes::BytesMut::new(); strip_human_output_from_failed_test( - &ChildExecutionResult::Output { + &ChildExecutionOutput::Output { + result: None, output, errors: None, }, @@ -747,7 +752,8 @@ note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose bac let mut actual = bytes::BytesMut::new(); strip_human_output_from_failed_test( - &ChildExecutionResult::Output { + &ChildExecutionOutput::Output { + result: None, output, errors: None, }, @@ -764,7 +770,7 @@ note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose bac 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 output = ChildExecutionOutput::StartError(ChildStartError::Spawn(Arc::new(error))); let mut actual = bytes::BytesMut::new(); strip_human_output_from_failed_test(&output, &mut actual, "non-existent").unwrap(); @@ -776,7 +782,8 @@ 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( - &ChildExecutionResult::Output { + &ChildExecutionOutput::Output { + result: None, output: ChildOutput::Split(ChildSplitOutput { stdout: None, stderr: None, diff --git a/nextest-runner/src/runner.rs b/nextest-runner/src/runner.rs index ed277cb89fb..0e03323ce4b 100644 --- a/nextest-runner/src/runner.rs +++ b/nextest-runner/src/runner.rs @@ -19,11 +19,12 @@ use crate::{ list::{TestExecuteContext, TestInstance, TestInstanceId, TestList}, reporter::{ CancelReason, FinalStatusLevel, StatusLevel, TestEvent, TestEventKind, TestOutputDisplay, + UnitKind, }, signal::{JobControlEvent, ShutdownEvent, SignalEvent, SignalHandler, SignalHandlerKind}, target_runner::TargetRunner, test_command::{ChildAccumulator, ChildFds}, - test_output::{CaptureStrategy, ChildExecutionResult}, + test_output::{CaptureStrategy, ChildExecutionOutput}, time::{PausableSleep, StopwatchSnapshot, StopwatchStart}, }; use async_scoped::TokioScope; @@ -771,7 +772,7 @@ impl<'a> TestRunnerInner<'a> { { Ok(status) => status, Err(error) => InternalSetupScriptExecuteStatus { - output: ChildExecutionResult::StartError(error), + output: ChildExecutionOutput::StartError(error), result: ExecutionResult::ExecFail, stopwatch_end: stopwatch.snapshot(), is_slow: false, @@ -943,12 +944,12 @@ impl<'a> TestRunnerInner<'a> { let exit_status = exit_status.expect("None always results in early return"); - let status = status + let exec_result = 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() { + let env_map = if exec_result.is_success() { match SetupScriptEnvMap::new(&env_path).await { Ok(env_map) => Some(env_map), Err(error) => { @@ -961,14 +962,12 @@ impl<'a> TestRunnerInner<'a> { }; Ok(InternalSetupScriptExecuteStatus { - output: ChildExecutionResult::Output { + output: ChildExecutionOutput::Output { + result: Some(exec_result), output: child_acc.output.freeze(), - errors: ErrorList::new( - ChildExecutionResult::WAITING_ON_SETUP_SCRIPT_MESSAGE, - errors, - ), + errors: ErrorList::new(UnitKind::WAITING_ON_SCRIPT_MESSAGE, errors), }, - result: status, + result: exec_result, stopwatch_end: stopwatch.snapshot(), is_slow, env_map, @@ -991,7 +990,7 @@ impl<'a> TestRunnerInner<'a> { { Ok(run_status) => run_status, Err(error) => InternalExecuteStatus { - output: ChildExecutionResult::StartError(error), + output: ChildExecutionOutput::StartError(error), result: ExecutionResult::ExecFail, stopwatch_end: stopwatch.snapshot(), is_slow: false, @@ -1172,18 +1171,16 @@ impl<'a> TestRunnerInner<'a> { }; let exit_status = exit_status.expect("None always results in early return"); - let result = status + let exec_result = status .unwrap_or_else(|| create_execution_result(exit_status, &child_acc.errors, leaked)); Ok(InternalExecuteStatus { - output: ChildExecutionResult::Output { + output: ChildExecutionOutput::Output { + result: Some(exec_result), output: child_acc.output.freeze(), - errors: ErrorList::new( - ChildExecutionResult::WAITING_ON_TEST_MESSAGE, - child_acc.errors, - ), + errors: ErrorList::new(UnitKind::WAITING_ON_TEST_MESSAGE, child_acc.errors), }, - result, + result: exec_result, stopwatch_end: stopwatch.snapshot(), is_slow, delay_before_start: test.delay_before_start, @@ -1468,7 +1465,7 @@ pub struct ExecuteStatus { /// Retry-related data. pub retry_data: RetryData, /// The stdout and stderr output for this test. - pub output: ChildExecutionResult, + pub output: ChildExecutionOutput, /// The execution result for this test: pass, fail or execution error. pub result: ExecutionResult, /// The time at which the test started. @@ -1482,7 +1479,7 @@ pub struct ExecuteStatus { } struct InternalExecuteStatus { - output: ChildExecutionResult, + output: ChildExecutionOutput, result: ExecutionResult, stopwatch_end: StopwatchSnapshot, is_slow: bool, @@ -1507,7 +1504,7 @@ impl InternalExecuteStatus { #[derive(Clone, Debug)] pub struct SetupScriptExecuteStatus { /// Output for this setup script. - pub output: ChildExecutionResult, + pub output: ChildExecutionOutput, /// The execution result for this setup script: pass, fail or execution error. pub result: ExecutionResult, /// The time at which the script started. @@ -1524,7 +1521,7 @@ pub struct SetupScriptExecuteStatus { } struct InternalSetupScriptExecuteStatus { - output: ChildExecutionResult, + output: ChildExecutionOutput, result: ExecutionResult, stopwatch_end: StopwatchSnapshot, is_slow: bool, diff --git a/nextest-runner/src/test_output.rs b/nextest-runner/src/test_output.rs index b84e5165aa4..a793fea3953 100644 --- a/nextest-runner/src/test_output.rs +++ b/nextest-runner/src/test_output.rs @@ -2,7 +2,6 @@ use crate::{ errors::{ChildError, ChildStartError, ErrorList}, - reporter::{heuristic_extract_description, DescriptionKind}, runner::ExecutionResult, }; use bstr::{ByteSlice, Lines}; @@ -93,9 +92,14 @@ impl ChildSingleOutput { /// at least some output was captured, or that the process could not be started /// at all. #[derive(Clone, Debug)] -pub enum ChildExecutionResult { +pub enum ChildExecutionOutput { /// The process was run and the output was captured. Output { + /// If the process has finished executing, the final state it is in. + /// + /// `None` means execution is currently in progress. + result: Option, + /// The captured output. output: ChildOutput, @@ -108,10 +112,7 @@ pub enum ChildExecutionResult { 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"; -} +impl ChildExecutionOutput {} /// The output of a child process: stdout and/or stderr. /// @@ -139,33 +140,3 @@ pub struct ChildSplitOutput { /// The captured stderr, or `None` if the output was not captured. pub stderr: Option, } - -impl ChildOutput { - /// Attempts to extract a description of a test failure from the output of the test. - pub fn heuristic_extract_description( - &self, - exec_result: ExecutionResult, - ) -> Option> { - match self { - Self::Split(split) => { - if let Some(kind) = heuristic_extract_description( - exec_result, - split.stdout.as_ref().map(|x| x.buf.as_ref()), - split.stderr.as_ref().map(|x| x.buf.as_ref()), - ) { - return Some(kind); - } - } - Self::Combined { output } => { - // Pass in the same buffer for both stdout and stderr. - if let Some(kind) = - heuristic_extract_description(exec_result, Some(&output.buf), Some(&output.buf)) - { - return Some(kind); - } - } - } - - None - } -} diff --git a/nextest-runner/tests/integration/basic.rs b/nextest-runner/tests/integration/basic.rs index 25fb4e0d970..7eb6f87621b 100644 --- a/nextest-runner/tests/integration/basic.rs +++ b/nextest-runner/tests/integration/basic.rs @@ -15,7 +15,7 @@ use nextest_runner::{ double_spawn::DoubleSpawnInfo, list::BinaryList, platform::BuildPlatforms, - reporter::heuristic_extract_description, + reporter::{UnitErrorDescription, UnitKind}, runner::{ ExecutionDescription, ExecutionResult, FinalRunStats, RunStatsFailureKind, TestRunnerBuilder, @@ -23,7 +23,7 @@ use nextest_runner::{ signal::SignalHandlerKind, target_runner::TargetRunner, test_filter::{RunIgnored, TestFilterBuilder, TestFilterPatterns}, - test_output::{ChildExecutionResult, ChildOutput}, + test_output::{ChildExecutionOutput, ChildOutput}, }; use pretty_assertions::assert_eq; use std::{io::Cursor, time::Duration}; @@ -172,7 +172,7 @@ fn test_run() -> Result<()> { if can_extract_description { // Check that stderr can be parsed heuristically. - let ChildExecutionResult::Output { + let ChildExecutionOutput::Output { output: ChildOutput::Split(split), .. } = &run_status.output @@ -183,13 +183,10 @@ fn test_run() -> Result<()> { let stderr = split.stderr.as_ref().expect("stderr should be captured"); println!("stderr: {}", stderr.as_str_lossy()); - let description = heuristic_extract_description( - run_status.result, - Some(&stdout.buf), - Some(&stderr.buf), - ); + let desc = + UnitErrorDescription::new(UnitKind::Test, &run_status.output); assert!( - description.is_some(), + desc.child_process_error_list().is_some(), "failed to extract description from {}\n*** stdout:\n{}\n*** stderr:\n{}\n", fixture.name, stdout.as_str_lossy(), diff --git a/nextest-runner/tests/integration/fixtures.rs b/nextest-runner/tests/integration/fixtures.rs index 79e204819fd..c2f8372cc8b 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::{ChildExecutionResult, ChildOutput}, + test_output::{ChildExecutionOutput, ChildOutput}, }; use once_cell::sync::Lazy; use std::{ @@ -295,7 +295,7 @@ impl fmt::Debug for InstanceStatus { InstanceStatus::Skipped(reason) => write!(f, "skipped: {reason}"), InstanceStatus::Finished(run_statuses) => { for run_status in run_statuses.iter() { - let ChildExecutionResult::Output { + let ChildExecutionOutput::Output { output: ChildOutput::Split(split), .. } = &run_status.output