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

nextest_runner/reporter/
error_description.rs
