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

nextest_runner/reporter/
error_description.rs
