nextest_runner/reporter/
error_description.rs

1// Copyright (c) The nextest Contributors
2// SPDX-License-Identifier: MIT OR Apache-2.0
3
4use super::events::{AbortDescription, ExecutionResult, FailureStatus, UnitKind};
5use crate::{
6    errors::{ChildError, ChildStartError, ErrorList},
7    test_output::{ChildExecutionOutput, ChildOutput},
8};
9use bstr::ByteSlice;
10use regex::bytes::{Regex, RegexBuilder};
11use std::{fmt, sync::LazyLock};
12use thiserror::Error;
13
14/// Given an error or failure running a test or script, collects and aggregates
15/// the most relevant information related to the issue.
16#[derive(Clone, Debug)]
17pub struct UnitErrorDescription<'a> {
18    kind: UnitKind,
19    start_error: Option<&'a ChildStartError>,
20    output_errors: Option<&'a ErrorList<ChildError>>,
21    abort: Option<UnitAbortDescription>,
22    output_slice: Option<TestOutputErrorSlice<'a>>,
23}
24
25impl<'a> UnitErrorDescription<'a> {
26    /// Adds the execution output of a child process to the description.
27    pub fn new(kind: UnitKind, output: &'a ChildExecutionOutput) -> Self {
28        let mut start_error = None;
29        let mut output_errors = None;
30        let mut abort = None;
31        let mut output_slice = None;
32
33        match output {
34            ChildExecutionOutput::StartError(error) => {
35                start_error = Some(error);
36            }
37            ChildExecutionOutput::Output {
38                result,
39                output,
40                errors,
41            } => {
42                output_errors = errors.as_ref();
43                if let Some(result) = result {
44                    if kind == UnitKind::Test {
45                        match output {
46                            // Scanning the output for the most relevant slice
47                            // only makes sense for completed tests.
48                            ChildOutput::Split(output) => {
49                                output_slice = TestOutputErrorSlice::heuristic_extract(
50                                    output.stdout.as_ref().map(|x| x.buf.as_ref()),
51                                    output.stderr.as_ref().map(|x| x.buf.as_ref()),
52                                );
53                            }
54                            ChildOutput::Combined { output } => {
55                                output_slice = TestOutputErrorSlice::heuristic_extract(
56                                    Some(output.buf.as_ref()),
57                                    Some(output.buf.as_ref()),
58                                );
59                            }
60                        }
61                    }
62
63                    if let ExecutionResult::Fail {
64                        failure_status: FailureStatus::Abort(status),
65                        leaked,
66                    } = result
67                    {
68                        abort = Some(UnitAbortDescription {
69                            description: AbortDescription::from(*status),
70                            leaked: *leaked,
71                        });
72                    }
73                }
74            }
75        }
76
77        Self {
78            kind,
79            start_error,
80            output_errors,
81            abort,
82            output_slice,
83        }
84    }
85
86    /// Makes an `ErrorList` of all errors.
87    pub(crate) fn all_error_list(&self) -> Option<ErrorList<&dyn std::error::Error>> {
88        ErrorList::new(self.kind.executing_message(), self.all_errors().collect())
89    }
90
91    /// Makes an `ErrorList` of execution failure errors.
92    ///
93    /// This includes start and output errors, but not aborts or output slices.
94    pub(crate) fn exec_fail_error_list(&self) -> Option<ErrorList<&dyn std::error::Error>> {
95        ErrorList::new(
96            self.kind.executing_message(),
97            self.exec_fail_errors().collect(),
98        )
99    }
100
101    /// Makes an `ErrorList` of abort and output errors.
102    ///
103    /// This consists of all errors that are generated by the child process.
104    pub fn child_process_error_list(&self) -> Option<ErrorList<&dyn std::error::Error>> {
105        ErrorList::new(
106            self.kind.executing_message(),
107            self.child_process_errors().collect(),
108        )
109    }
110
111    pub(crate) fn output_slice(&self) -> Option<TestOutputErrorSlice<'a>> {
112        self.output_slice
113    }
114
115    /// Builds an iterator over all of the reasons for the error.
116    fn all_errors(&self) -> impl Iterator<Item = &dyn std::error::Error> {
117        self.exec_fail_errors().chain(self.child_process_errors())
118    }
119
120    fn exec_fail_errors(&self) -> impl Iterator<Item = &dyn std::error::Error> {
121        self.start_error
122            .as_ref()
123            .map(|error| error as &dyn std::error::Error)
124            .into_iter()
125            .chain(
126                self.output_errors
127                    .as_ref()
128                    .into_iter()
129                    .flat_map(|errors| errors.iter().map(|error| error as &dyn std::error::Error)),
130            )
131    }
132
133    fn child_process_errors(&self) -> impl Iterator<Item = &dyn std::error::Error> {
134        self.abort
135            .as_ref()
136            .map(|abort| abort as &dyn std::error::Error)
137            .into_iter()
138            .chain(
139                self.output_slice
140                    .as_ref()
141                    .map(|slice| slice as &dyn std::error::Error),
142            )
143    }
144}
145
146#[derive(Clone, Debug, Error)]
147struct UnitAbortDescription {
148    description: AbortDescription,
149    leaked: bool,
150}
151
152impl fmt::Display for UnitAbortDescription {
153    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
154        write!(f, "process {}", self.description)?;
155        if self.leaked {
156            write!(f, ", and also leaked handles")?;
157        }
158        Ok(())
159    }
160}
161
162/// A part of a test output that identifies the most relevant location of a test failure.
163///
164/// The process of extracting errors is heuristic and may not always be
165/// accurate.
166#[derive(Clone, Copy, Debug, Error)]
167pub enum TestOutputErrorSlice<'a> {
168    /// A panic message was found in the output.
169    ///
170    /// The output is borrowed from standard error.
171    PanicMessage {
172        /// The subslice of standard error that contains the stack trace.
173        stderr_subslice: ByteSubslice<'a>,
174    },
175
176    /// An error string was found in the output.
177    ///
178    /// The output is borrowed from standard error.
179    ErrorStr {
180        /// The subslice of standard error that contains the stack trace.
181        stderr_subslice: ByteSubslice<'a>,
182    },
183
184    /// A should-panic test did not panic.
185    ///
186    /// The output is borrowed from standard output.
187    ShouldPanic {
188        /// The subslice of standard output that contains the should-panic message.
189        stdout_subslice: ByteSubslice<'a>,
190    },
191}
192
193impl<'a> TestOutputErrorSlice<'a> {
194    /// Attempts to heuristically extract a description of the test failure from the
195    /// output of the test.
196    ///
197    /// `None` indicates that output wasn't captured -- in those cases there isn't
198    /// much we can do.
199    pub fn heuristic_extract(stdout: Option<&'a [u8]>, stderr: Option<&'a [u8]>) -> Option<Self> {
200        // Try the heuristic stack trace extraction first to try and grab more
201        // information first.
202        if let Some(stderr) = stderr {
203            if let Some(stderr_subslice) = heuristic_panic_message(stderr) {
204                return Some(TestOutputErrorSlice::PanicMessage { stderr_subslice });
205            }
206            if let Some(stderr_subslice) = heuristic_error_str(stderr) {
207                return Some(TestOutputErrorSlice::ErrorStr { stderr_subslice });
208            }
209        }
210
211        if let Some(stdout) = stdout
212            && let Some(stdout_subslice) = heuristic_should_panic(stdout)
213        {
214            return Some(TestOutputErrorSlice::ShouldPanic { stdout_subslice });
215        }
216
217        None
218    }
219
220    /// Returns the subslice of standard error that contains the description.
221    pub fn stderr_subslice(&self) -> Option<ByteSubslice<'a>> {
222        match self {
223            Self::PanicMessage { stderr_subslice }
224            | Self::ErrorStr {
225                stderr_subslice, ..
226            } => Some(*stderr_subslice),
227            Self::ShouldPanic { .. } => None,
228        }
229    }
230
231    /// Returns the subslice of standard output that contains the description.
232    pub fn stdout_subslice(&self) -> Option<ByteSubslice<'a>> {
233        match self {
234            Self::PanicMessage { .. } => None,
235            Self::ErrorStr { .. } => None,
236            Self::ShouldPanic {
237                stdout_subslice, ..
238            } => Some(*stdout_subslice),
239        }
240    }
241
242    /// Returns the subslice of combined output (either stdout or stderr) that contains the description.
243    pub fn combined_subslice(&self) -> Option<ByteSubslice<'a>> {
244        match self {
245            Self::PanicMessage { stderr_subslice }
246            | Self::ErrorStr {
247                stderr_subslice, ..
248            } => Some(*stderr_subslice),
249            Self::ShouldPanic {
250                stdout_subslice, ..
251            } => Some(*stdout_subslice),
252        }
253    }
254}
255
256impl fmt::Display for TestOutputErrorSlice<'_> {
257    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
258        match self {
259            Self::PanicMessage { stderr_subslice } => {
260                write!(f, "{}", String::from_utf8_lossy(stderr_subslice.slice))
261            }
262            Self::ErrorStr { stderr_subslice } => {
263                write!(f, "{}", String::from_utf8_lossy(stderr_subslice.slice))
264            }
265            Self::ShouldPanic { stdout_subslice } => {
266                write!(f, "{}", String::from_utf8_lossy(stdout_subslice.slice))
267            }
268        }
269    }
270}
271
272/// A subslice of a byte slice.
273///
274/// This type tracks the start index of the subslice from the parent slice.
275#[derive(Clone, Copy, Debug)]
276pub struct ByteSubslice<'a> {
277    /// The slice.
278    pub slice: &'a [u8],
279
280    /// The start index of the subslice from the parent slice.
281    pub start: usize,
282}
283
284fn heuristic_should_panic(stdout: &[u8]) -> Option<ByteSubslice<'_>> {
285    let line = stdout
286        .lines()
287        .find(|line| line.contains_str("note: test did not panic as expected"))?;
288
289    // SAFETY: line is a subslice of stdout.
290    let start = unsafe { line.as_ptr().offset_from(stdout.as_ptr()) };
291
292    let start = usize::try_from(start).unwrap_or_else(|error| {
293        panic!(
294            "negative offset from stdout.as_ptr() ({:x}) to line.as_ptr() ({:x}): {}",
295            stdout.as_ptr() as usize,
296            line.as_ptr() as usize,
297            error
298        )
299    });
300    Some(ByteSubslice { slice: line, start })
301}
302
303fn heuristic_panic_message(stderr: &[u8]) -> Option<ByteSubslice<'_>> {
304    // Look for the last instance to handle situations like proptest which repeatedly print out
305    // `panicked at ...` messages.
306    let panicked_at_match = PANICKED_AT_REGEX.find_iter(stderr).last()?;
307    // If the previous line starts with "Error: ", grab it as well -- it contains the error with
308    // result-based test failures.
309    let mut start = panicked_at_match.start();
310    let prefix = stderr[..start].trim_end_with(|c| c == '\n' || c == '\r');
311    if let Some(prev_line_start) = prefix.rfind("\n")
312        && prefix[prev_line_start..].starts_with_str("\nError:")
313    {
314        start = prev_line_start + 1;
315    }
316
317    // TODO: this grabs too much -- it is possible that destructors print out further messages so we
318    // should be more careful. But it's hard to tell what's printed by the panic and what's printed
319    // by destructors, so we lean on the side of caution.
320    Some(ByteSubslice {
321        slice: stderr[start..].trim_end_with(|c| c.is_whitespace()),
322        start,
323    })
324}
325
326fn heuristic_error_str(stderr: &[u8]) -> Option<ByteSubslice<'_>> {
327    // Starting Rust 1.66, Result-based errors simply print out "Error: ".
328    let error_match = ERROR_REGEX.find(stderr)?;
329    let start = error_match.start();
330
331    // TODO: this grabs too much -- it is possible that destructors print out further messages so we
332    // should be more careful. But it's hard to tell what's printed by the error and what's printed
333    // by destructors, so we lean on the side of caution.
334    Some(ByteSubslice {
335        slice: stderr[start..].trim_end_with(|c| c.is_whitespace()),
336        start,
337    })
338}
339
340// This regex works for the default panic handler for Rust -- other panic handlers may not work,
341// which is why this is heuristic.
342static PANICKED_AT_REGEX_STR: &str = "^thread '([^']+)' (\\(\\d+\\) )?panicked at ";
343static PANICKED_AT_REGEX: LazyLock<Regex> = LazyLock::new(|| {
344    let mut builder = RegexBuilder::new(PANICKED_AT_REGEX_STR);
345    builder.multi_line(true);
346    builder.build().unwrap()
347});
348
349static ERROR_REGEX_STR: &str = "^Error: ";
350static ERROR_REGEX: LazyLock<Regex> = LazyLock::new(|| {
351    let mut builder = RegexBuilder::new(ERROR_REGEX_STR);
352    builder.multi_line(true);
353    builder.build().unwrap()
354});
355
356#[cfg(test)]
357mod tests {
358    use super::*;
359
360    #[test]
361    fn test_heuristic_should_panic() {
362        let tests: &[(&str, &str)] = &[(
363            "running 1 test
364test test_failure_should_panic - should panic ... FAILED
365
366failures:
367
368---- test_failure_should_panic stdout ----
369note: test did not panic as expected
370
371failures:
372    test_failure_should_panic
373
374test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 13 filtered out; finished in 0.00s",
375            "note: test did not panic as expected",
376        )];
377
378        for (input, output) in tests {
379            let extracted = heuristic_should_panic(input.as_bytes())
380                .expect("should-panic message should have been found");
381            assert_eq!(
382                DisplayWrapper(extracted.slice),
383                DisplayWrapper(output.as_bytes())
384            );
385            assert_eq!(
386                extracted.start,
387                extracted.slice.as_ptr() as usize - input.as_bytes().as_ptr() as usize
388            );
389        }
390    }
391
392    #[test]
393    fn test_heuristic_panic_message() {
394        let tests: &[(&str, &str)] = &[
395            (
396                "thread 'main' panicked at 'foo', src/lib.rs:1\n",
397                "thread 'main' panicked at 'foo', src/lib.rs:1",
398            ),
399            (
400                "foobar\n\
401            thread 'main' panicked at 'foo', src/lib.rs:1\n\n",
402                "thread 'main' panicked at 'foo', src/lib.rs:1",
403            ),
404            (
405                r#"
406text: foo
407Error: Custom { kind: InvalidData, error: "this is an error" }
408thread 'test_result_failure' panicked at 'assertion failed: `(left == right)`
409  left: `1`,
410 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
411note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
412more text at the end, followed by some newlines
413
414
415            "#,
416                r#"Error: Custom { kind: InvalidData, error: "this is an error" }
417thread 'test_result_failure' panicked at 'assertion failed: `(left == right)`
418  left: `1`,
419 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
420note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
421more text at the end, followed by some newlines"#,
422            ),
423            // Multiple panics: only the last one should be extracted.
424            (
425                r"
426thread 'main' panicked at src/lib.rs:1:
427foo
428thread 'main' panicked at src/lib.rs:2:
429bar
430",
431                r"thread 'main' panicked at src/lib.rs:2:
432bar",
433            ), // With RUST_BACKTRACE=1
434            (
435                r"
436some initial text
437line 2
438line 3
439thread 'reporter::helpers::tests::test_heuristic_stack_trace' panicked at nextest-runner/src/reporter/helpers.rs:237:9:
440test
441stack backtrace:
442   0: rust_begin_unwind
443             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/panicking.rs:652:5
444   1: core::panicking::panic_fmt
445             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/panicking.rs:72:14
446   2: nextest_runner::reporter::helpers::tests::test_heuristic_stack_trace
447             at ./src/reporter/helpers.rs:237:9
448   3: nextest_runner::reporter::helpers::tests::test_heuristic_stack_trace::{{closure}}
449             at ./src/reporter/helpers.rs:236:36
450   4: core::ops::function::FnOnce::call_once
451             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/ops/function.rs:250:5
452   5: core::ops::function::FnOnce::call_once
453             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/ops/function.rs:250:5
454note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
455more text at the end, followed by some newlines
456
457
458",
459                r"thread 'reporter::helpers::tests::test_heuristic_stack_trace' panicked at nextest-runner/src/reporter/helpers.rs:237:9:
460test
461stack backtrace:
462   0: rust_begin_unwind
463             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/panicking.rs:652:5
464   1: core::panicking::panic_fmt
465             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/panicking.rs:72:14
466   2: nextest_runner::reporter::helpers::tests::test_heuristic_stack_trace
467             at ./src/reporter/helpers.rs:237:9
468   3: nextest_runner::reporter::helpers::tests::test_heuristic_stack_trace::{{closure}}
469             at ./src/reporter/helpers.rs:236:36
470   4: core::ops::function::FnOnce::call_once
471             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/ops/function.rs:250:5
472   5: core::ops::function::FnOnce::call_once
473             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/ops/function.rs:250:5
474note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
475more text at the end, followed by some newlines",
476            ),
477            // RUST_BACKTRACE=full
478            (
479                r"
480some initial text
481thread 'reporter::helpers::tests::test_heuristic_stack_trace' panicked at nextest-runner/src/reporter/helpers.rs:237:9:
482test
483stack backtrace:
484   0:     0x61e6da135fe5 - std::backtrace_rs::backtrace::libunwind::trace::h23054e327d0d4b55
485                               at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/../../backtrace/src/backtrace/libunwind.rs:116:5
486   1:     0x61e6da135fe5 - std::backtrace_rs::backtrace::trace_unsynchronized::h0cc587407d7f7f64
487                               at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
488   2:     0x61e6da135fe5 - std::sys_common::backtrace::_print_fmt::h4feeb59774730d6b
489                               at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/sys_common/backtrace.rs:68:5
490   3:     0x61e6da135fe5 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hd736fd5964392270
491                               at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/sys_common/backtrace.rs:44:22
492   4:     0x61e6da16433b - core::fmt::rt::Argument::fmt::h105051d8ea1ade1e
493                               at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/fmt/rt.rs:165:63
494   5:     0x61e6da16433b - core::fmt::write::hc6043626647b98ea
495                               at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/fmt/mod.rs:1168:21
496some more text at the end, followed by some newlines
497
498
499",
500                r"thread 'reporter::helpers::tests::test_heuristic_stack_trace' panicked at nextest-runner/src/reporter/helpers.rs:237:9:
501test
502stack backtrace:
503   0:     0x61e6da135fe5 - std::backtrace_rs::backtrace::libunwind::trace::h23054e327d0d4b55
504                               at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/../../backtrace/src/backtrace/libunwind.rs:116:5
505   1:     0x61e6da135fe5 - std::backtrace_rs::backtrace::trace_unsynchronized::h0cc587407d7f7f64
506                               at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
507   2:     0x61e6da135fe5 - std::sys_common::backtrace::_print_fmt::h4feeb59774730d6b
508                               at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/sys_common/backtrace.rs:68:5
509   3:     0x61e6da135fe5 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hd736fd5964392270
510                               at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/sys_common/backtrace.rs:44:22
511   4:     0x61e6da16433b - core::fmt::rt::Argument::fmt::h105051d8ea1ade1e
512                               at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/fmt/rt.rs:165:63
513   5:     0x61e6da16433b - core::fmt::write::hc6043626647b98ea
514                               at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/fmt/mod.rs:1168:21
515some more text at the end, followed by some newlines",
516            ),
517        ];
518
519        for (input, output) in tests {
520            let extracted = heuristic_panic_message(input.as_bytes())
521                .expect("stack trace should have been found");
522            assert_eq!(
523                DisplayWrapper(extracted.slice),
524                DisplayWrapper(output.as_bytes())
525            );
526            assert_eq!(
527                extracted.start,
528                extracted.slice.as_ptr() as usize - input.as_bytes().as_ptr() as usize
529            );
530        }
531    }
532
533    #[test]
534    fn test_heuristic_error_str() {
535        let tests: &[(&str, &str)] = &[(
536            "foobar\nError: \"this is an error\"\n",
537            "Error: \"this is an error\"",
538        )];
539
540        for (input, output) in tests {
541            let extracted =
542                heuristic_error_str(input.as_bytes()).expect("error string should have been found");
543            assert_eq!(
544                DisplayWrapper(extracted.slice),
545                DisplayWrapper(output.as_bytes())
546            );
547            assert_eq!(
548                extracted.start,
549                extracted.slice.as_ptr() as usize - input.as_bytes().as_ptr() as usize
550            );
551        }
552    }
553
554    // Wrapper so that panic messages show up nicely in the test output.
555    #[derive(Eq, PartialEq)]
556    struct DisplayWrapper<'a>(&'a [u8]);
557
558    impl fmt::Debug for DisplayWrapper<'_> {
559        fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
560            write!(f, "{}", String::from_utf8_lossy(self.0))
561        }
562    }
563}
nextest_runner/reporter/error_description.rs

nextest_runner/reporter/
error_description.rs
