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

nextest_runner/reporter/
error_description.rs
