Skip to main content

nextest_runner/reporter/structured/
libtest.rs

1// Copyright (c) The nextest Contributors
2// SPDX-License-Identifier: MIT OR Apache-2.0
3
4//! libtest compatible output support
5//!
6//! Before 1.70.0 it was possible to send `--format json` to test executables and
7//! they would print out a JSON line to stdout for various events. This format
8//! was however not intended to be stabilized, so 1.70.0 made it nightly only as
9//! intended. However, machine readable output is immensely useful to other
10//! tooling that can much more easily consume it than parsing the output meant
11//! for humans.
12//!
13//! Since there already existed tooling using the libtest output format, this
14//! event aggregator replicates that format so that projects can seamlessly
15//! integrate cargo-nextest into their project, as well as get the benefit of
16//! running their tests on stable instead of being forced to use nightly.
17//!
18//! This implementation will attempt to follow the libtest format as it changes,
19//! but the rate of changes is quite low (see <https://github.com/rust-lang/rust/blob/master/library/test/src/formatters/json.rs>)
20//! so this should not be a big issue to users, however, if the format is changed,
21//! the changes will be replicated in this file with a new minor version allowing
22//! users to move to the new format or stick to the format version(s) they were
23//! using before
24
25use crate::{
26    config::elements::{FlakyResult, SlowTimeoutResult},
27    errors::{DisplayErrorChain, FormatVersionError, FormatVersionErrorInner, WriteEventError},
28    list::{RustTestSuite, TestList},
29    output_spec::{LiveSpec, OutputSpec},
30    reporter::events::{
31        ChildExecutionOutputDescription, ChildOutputDescription, ExecutionDescription,
32        ExecutionResultDescription, ExecutionStatuses, StressIndex, TestEvent, TestEventKind,
33    },
34    test_output::ChildSingleOutput,
35};
36use bstr::ByteSlice;
37use iddqd::{IdOrdItem, IdOrdMap, id_ord_map, id_upcast};
38use nextest_metadata::{RustBinaryId, TestCaseName};
39use std::fmt::Write as _;
40
41/// To support pinning the version of the output, we just use this simple enum
42/// to document changes as libtest output changes
43#[derive(Copy, Clone)]
44#[repr(u8)]
45enum FormatMinorVersion {
46    /// The libtest output as of `rustc 1.75.0-nightly (aa1a71e9e 2023-10-26)` with `--format json --report-time`
47    ///
48    /// * `{ "type": "suite", "event": "started", "test_count": <u32> }` - Start of a test binary run, always printed
49    ///   * `{ "type": "test", "event": "started", "name": "<name>" }` - Start of a single test, always printed
50    ///   * `{ "type": "test", "name": "<name>", "event": "ignored" }` - Printed if a test is ignored
51    ///     * Will have an additional `"message" = "<message>"` field if the there is a message in the ignore attribute eg. `#[ignore = "not yet implemented"]`
52    ///   * `{ "type": "test", "name": "<name>", "event": "ok", "exec_time": <f32> }` - Printed if a test runs successfully
53    ///   * `{ "type": "test", "name": "<name>", "event": "failed", "exec_time": <f32>, "stdout": "<escaped output collected during test execution>" }` - Printed if a test fails, note the stdout field actually contains both stdout and stderr despite the name
54    ///     * If `--ensure-time` is passed, libtest will add `"reason": "time limit exceeded"` if the test passes, but exceeds the time limit.
55    ///     * If `#[should_panic = "<expected message>"]` is used and message doesn't match, an additional `"message": "panic did not contain expected string\n<panic message>"` field is added
56    /// * `{ "type": "suite", "event": "<overall_status>", "passed": <u32>, "failed": <u32>, "ignored": <u32>, "measured": <u32>, "filtered_out": <u32>, "exec_time": <f32> }`
57    ///   * `event` will be `"ok"` if no failures occurred, or `"failed"` if `"failed" > 0`
58    ///   * `ignored` will be > 0 if there are `#[ignore]` tests and `--ignored` was not passed
59    ///   * `filtered_out` with be > 0 if there were tests not marked `#[ignore]` and `--ignored` was passed OR a test filter was passed and 1 or more tests were not executed
60    ///   * `measured` is only > 0 if running benchmarks
61    First = 1,
62    #[doc(hidden)]
63    _Max,
64}
65
66/// If libtest output is ever stabilized, this would most likely become the single
67/// version and we could get rid of the minor version, but who knows if that
68/// will ever happen
69#[derive(Copy, Clone)]
70#[repr(u8)]
71enum FormatMajorVersion {
72    /// The libtest output is unstable
73    Unstable = 0,
74    #[doc(hidden)]
75    _Max,
76}
77
78/// The accumulated stats for a single test binary
79struct LibtestSuite<'cfg> {
80    /// The number of tests that failed
81    failed: usize,
82    /// The number of tests that succeeded
83    succeeded: usize,
84    /// The number of tests that were ignored
85    ignored: usize,
86    /// The number of tests that were not executed due to filters
87    filtered: usize,
88    /// The number of tests in this suite that are still running
89    running: usize,
90
91    stress_index: Option<StressIndex>,
92    meta: &'cfg RustTestSuite<'cfg>,
93    /// The accumulated duration of every test that has been executed
94    total: std::time::Duration,
95    /// Libtest outputs outputs a `started` event for every test that isn't
96    /// filtered, including ignored tests, then outputs `ignored` events after
97    /// all the started events, so we just mimic that with a temporary buffer
98    ignore_block: Option<bytes::BytesMut>,
99    /// The single block of output accumulated for all tests executed in the binary,
100    /// this needs to be emitted as a single block to emulate how cargo test works,
101    /// executing each test binary serially and outputting a json line for each
102    /// event, as otherwise consumers would not be able to associate a single test
103    /// with its parent suite
104    output_block: bytes::BytesMut,
105}
106
107impl IdOrdItem for LibtestSuite<'_> {
108    type Key<'a>
109        = &'a RustBinaryId
110    where
111        Self: 'a;
112
113    fn key(&self) -> Self::Key<'_> {
114        &self.meta.binary_id
115    }
116
117    id_upcast!();
118}
119
120/// Determines whether the `nextest` subobject is added with additional metadata
121/// to events
122#[derive(Copy, Clone, Debug)]
123pub enum EmitNextestObject {
124    /// The `nextest` subobject is added
125    Yes,
126    /// The `nextest` subobject is not added
127    No,
128}
129
130const KIND_TEST: &str = "test";
131const KIND_SUITE: &str = "suite";
132
133const EVENT_STARTED: &str = "started";
134const EVENT_IGNORED: &str = "ignored";
135const EVENT_OK: &str = "ok";
136const EVENT_FAILED: &str = "failed";
137
138#[inline]
139fn fmt_err(err: std::fmt::Error) -> WriteEventError {
140    WriteEventError::Io(std::io::Error::new(std::io::ErrorKind::OutOfMemory, err))
141}
142
143/// A reporter that reports test runs in the same line-by-line JSON format as
144/// libtest itself
145pub struct LibtestReporter<'cfg> {
146    _minor: FormatMinorVersion,
147    _major: FormatMajorVersion,
148    test_list: Option<&'cfg TestList<'cfg>>,
149    test_suites: IdOrdMap<LibtestSuite<'cfg>>,
150    /// If true, we emit a `nextest` subobject with additional metadata in it
151    /// that consumers can use for easier integration if they wish
152    emit_nextest_obj: bool,
153}
154
155impl<'cfg> LibtestReporter<'cfg> {
156    /// Creates a new libtest reporter
157    ///
158    /// The version string is used to allow the reporter to evolve along with
159    /// libtest, but still be able to output a stable format for consumers. If
160    /// it is not specified the latest version of the format will be produced.
161    ///
162    /// If [`EmitNextestObject::Yes`] is passed, an additional `nextest` subobject
163    /// will be added to some events that includes additional metadata not produced
164    /// by libtest, but most consumers should still be able to consume them as
165    /// the base format itself is not changed
166    pub fn new(
167        version: Option<&str>,
168        emit_nextest_obj: EmitNextestObject,
169    ) -> Result<Self, FormatVersionError> {
170        let emit_nextest_obj = matches!(emit_nextest_obj, EmitNextestObject::Yes);
171
172        let Some(version) = version else {
173            return Ok(Self {
174                _minor: FormatMinorVersion::First,
175                _major: FormatMajorVersion::Unstable,
176                test_list: None,
177                test_suites: IdOrdMap::new(),
178                emit_nextest_obj,
179            });
180        };
181        let Some((major, minor)) = version.split_once('.') else {
182            return Err(FormatVersionError {
183                input: version.into(),
184                error: FormatVersionErrorInner::InvalidFormat {
185                    expected: "<major>.<minor>",
186                },
187            });
188        };
189
190        let major: u8 = major.parse().map_err(|err| FormatVersionError {
191            input: version.into(),
192            error: FormatVersionErrorInner::InvalidInteger {
193                which: "major",
194                err,
195            },
196        })?;
197
198        let minor: u8 = minor.parse().map_err(|err| FormatVersionError {
199            input: version.into(),
200            error: FormatVersionErrorInner::InvalidInteger {
201                which: "minor",
202                err,
203            },
204        })?;
205
206        let major = match major {
207            0 => FormatMajorVersion::Unstable,
208            o => {
209                return Err(FormatVersionError {
210                    input: version.into(),
211                    error: FormatVersionErrorInner::InvalidValue {
212                        which: "major",
213                        value: o,
214                        range: (FormatMajorVersion::Unstable as u8)
215                            ..(FormatMajorVersion::_Max as u8),
216                    },
217                });
218            }
219        };
220
221        let minor = match minor {
222            1 => FormatMinorVersion::First,
223            o => {
224                return Err(FormatVersionError {
225                    input: version.into(),
226                    error: FormatVersionErrorInner::InvalidValue {
227                        which: "minor",
228                        value: o,
229                        range: (FormatMinorVersion::First as u8)..(FormatMinorVersion::_Max as u8),
230                    },
231                });
232            }
233        };
234
235        Ok(Self {
236            _major: major,
237            _minor: minor,
238            test_list: None,
239            test_suites: IdOrdMap::new(),
240            emit_nextest_obj,
241        })
242    }
243
244    pub(crate) fn write_event(&mut self, event: &TestEvent<'cfg>) -> Result<(), WriteEventError> {
245        let mut retries = None;
246
247        // Write the pieces of data that are the same across all events
248        let (kind, eve, stress_index, test_instance) = match &event.kind {
249            TestEventKind::TestStarted {
250                stress_index,
251                test_instance,
252                ..
253            } => (KIND_TEST, EVENT_STARTED, stress_index, test_instance),
254            TestEventKind::TestSkipped {
255                stress_index,
256                test_instance,
257                reason,
258                ..
259            } if reason.is_ignore_mismatch() => {
260                // libtest only reports ignored tests as skipped, so we match
261                // the `ReportSkipPolicy::Ignored` policy here.
262                //
263                // Note: unfortunately, libtest does not expose the message test in `#[ignore = "<message>"]`
264                // so we can't replicate the behavior of libtest exactly by emitting
265                // that message as additional metadata
266                (KIND_TEST, EVENT_STARTED, stress_index, test_instance)
267            }
268            TestEventKind::TestFinished {
269                stress_index,
270                test_instance,
271                run_statuses,
272                ..
273            } => {
274                if run_statuses.len() > 1 {
275                    retries = Some(run_statuses.len());
276                }
277
278                (
279                    KIND_TEST,
280                    event_for_finished_test(run_statuses),
281                    stress_index,
282                    test_instance,
283                )
284            }
285            TestEventKind::RunStarted { test_list, .. } => {
286                self.test_list = Some(*test_list);
287                return Ok(());
288            }
289            TestEventKind::StressSubRunFinished { .. } | TestEventKind::RunFinished { .. } => {
290                for test_suite in std::mem::take(&mut self.test_suites) {
291                    self.finalize(test_suite)?;
292                }
293
294                return Ok(());
295            }
296            _ => return Ok(()),
297        };
298
299        // Look up the suite info from the test list.
300        let test_list = self
301            .test_list
302            .expect("test_list should be set by RunStarted before any test events");
303        let suite_info = test_list
304            .get_suite(test_instance.binary_id)
305            .expect("suite should exist in test list");
306        let crate_name = suite_info.package.name();
307        let binary_name = &suite_info.binary_name;
308
309        // Emit the suite start if this is the first test of the suite
310        let mut test_suite = match self.test_suites.entry(&suite_info.binary_id) {
311            id_ord_map::Entry::Vacant(e) => {
312                let (running, ignored, filtered) =
313                    suite_info.status.test_cases().fold((0, 0, 0), |acc, case| {
314                        if case.test_info.ignored {
315                            (acc.0, acc.1 + 1, acc.2)
316                        } else if case.test_info.filter_match.is_match() {
317                            (acc.0 + 1, acc.1, acc.2)
318                        } else {
319                            (acc.0, acc.1, acc.2 + 1)
320                        }
321                    });
322
323                let mut out = bytes::BytesMut::with_capacity(1024);
324                write!(
325                    &mut out,
326                    r#"{{"type":"{KIND_SUITE}","event":"{EVENT_STARTED}","test_count":{}"#,
327                    running + ignored,
328                )
329                .map_err(fmt_err)?;
330
331                if self.emit_nextest_obj {
332                    write!(
333                        out,
334                        r#","nextest":{{"crate":"{crate_name}","test_binary":"{binary_name}","kind":"{}""#,
335                        suite_info.kind,
336                    )
337                    .map_err(fmt_err)?;
338
339                    if let Some(stress_index) = stress_index {
340                        write!(out, r#","stress_index":{}"#, stress_index.current)
341                            .map_err(fmt_err)?;
342                        if let Some(total) = stress_index.total {
343                            write!(out, r#","stress_total":{total}"#).map_err(fmt_err)?;
344                        }
345                    }
346
347                    write!(out, "}}").map_err(fmt_err)?;
348                }
349
350                out.extend_from_slice(b"}\n");
351
352                e.insert(LibtestSuite {
353                    running,
354                    failed: 0,
355                    succeeded: 0,
356                    ignored,
357                    filtered,
358                    stress_index: *stress_index,
359                    meta: suite_info,
360                    total: std::time::Duration::new(0, 0),
361                    ignore_block: None,
362                    output_block: out,
363                })
364            }
365            id_ord_map::Entry::Occupied(e) => e.into_mut(),
366        };
367
368        let test_suite_mut = &mut *test_suite;
369        let out = &mut test_suite_mut.output_block;
370
371        // After all the tests have been started or ignored, put the block of
372        // tests that were ignored just as libtest does
373        if matches!(event.kind, TestEventKind::TestFinished { .. })
374            && let Some(ib) = test_suite_mut.ignore_block.take()
375        {
376            out.extend_from_slice(&ib);
377        }
378
379        // This is one place where we deviate from the behavior of libtest, by
380        // always prefixing the test name with both the crate and the binary name,
381        // as this information is quite important to distinguish tests from each
382        // other when testing inside a large workspace with hundreds or thousands
383        // of tests
384        //
385        // Additionally, a `#<n>` is used as a suffix if the test was retried,
386        // as libtest does not support that functionality
387        write!(
388            out,
389            r#"{{"type":"{kind}","event":"{eve}","name":"{}::{}"#,
390            suite_info.package.name(),
391            suite_info.binary_name,
392        )
393        .map_err(fmt_err)?;
394
395        if let Some(stress_index) = stress_index {
396            write!(out, "@stress-{}", stress_index.current).map_err(fmt_err)?;
397        }
398        write!(out, "${}", test_instance.test_name).map_err(fmt_err)?;
399        if let Some(retry_count) = retries {
400            write!(out, "#{retry_count}\"").map_err(fmt_err)?;
401        } else {
402            out.extend_from_slice(b"\"");
403        }
404
405        match &event.kind {
406            TestEventKind::TestFinished { run_statuses, .. } => {
407                let last_status = run_statuses.last_status();
408
409                test_suite_mut.total += last_status.time_taken;
410                test_suite_mut.running -= 1;
411
412                // libtest actually requires an additional `--report-time` flag to be
413                // passed for the exec_time information to be written. This doesn't
414                // really make sense when outputting structured output so we emit it
415                // unconditionally
416                write!(
417                    out,
418                    r#","exec_time":{}"#,
419                    last_status.time_taken.as_secs_f64()
420                )
421                .map_err(fmt_err)?;
422
423                // Check for flaky-fail: a test that passed on retry but is
424                // configured to be treated as a failure.
425                let is_flaky_fail = matches!(
426                    run_statuses.describe(),
427                    ExecutionDescription::Flaky {
428                        result: FlakyResult::Fail,
429                        ..
430                    }
431                );
432
433                if is_flaky_fail {
434                    test_suite_mut.failed += 1;
435                    out.extend_from_slice(br#","reason":"flaky test treated as failure""#);
436                } else {
437                    match &last_status.result {
438                        ExecutionResultDescription::Fail { .. }
439                        | ExecutionResultDescription::ExecFail => {
440                            test_suite_mut.failed += 1;
441
442                            // Write the output from the test into the `stdout` (even
443                            // though it could contain stderr output as well).
444                            write!(out, r#","stdout":""#).map_err(fmt_err)?;
445
446                            strip_human_output_from_failed_test(
447                                &last_status.output,
448                                out,
449                                test_instance.test_name,
450                            )?;
451                            out.extend_from_slice(b"\"");
452                        }
453                        ExecutionResultDescription::Timeout {
454                            result: SlowTimeoutResult::Fail,
455                        } => {
456                            test_suite_mut.failed += 1;
457                            out.extend_from_slice(br#","reason":"time limit exceeded""#);
458                        }
459                        _ => {
460                            test_suite_mut.succeeded += 1;
461                        }
462                    }
463                }
464            }
465            TestEventKind::TestSkipped { .. } => {
466                test_suite_mut.running -= 1;
467
468                if test_suite_mut.ignore_block.is_none() {
469                    test_suite_mut.ignore_block = Some(bytes::BytesMut::with_capacity(1024));
470                }
471
472                let ib = test_suite_mut
473                    .ignore_block
474                    .get_or_insert_with(|| bytes::BytesMut::with_capacity(1024));
475
476                writeln!(
477                    ib,
478                    r#"{{"type":"{kind}","event":"{EVENT_IGNORED}","name":"{}::{}${}"}}"#,
479                    suite_info.package.name(),
480                    suite_info.binary_name,
481                    test_instance.test_name,
482                )
483                .map_err(fmt_err)?;
484            }
485            _ => {}
486        };
487
488        out.extend_from_slice(b"}\n");
489
490        if self.emit_nextest_obj {
491            {
492                use std::io::Write as _;
493
494                let mut stdout = std::io::stdout().lock();
495                stdout.write_all(out).map_err(WriteEventError::Io)?;
496                stdout.flush().map_err(WriteEventError::Io)?;
497                out.clear();
498            }
499
500            if test_suite_mut.running == 0 {
501                std::mem::drop(test_suite);
502
503                if let Some(test_suite) = self.test_suites.remove(&suite_info.binary_id) {
504                    self.finalize(test_suite)?;
505                }
506            }
507        } else {
508            // If this is the last test of the suite, emit the test suite summary
509            // before emitting the entire block
510            if test_suite_mut.running > 0 {
511                return Ok(());
512            }
513
514            std::mem::drop(test_suite);
515
516            if let Some(test_suite) = self.test_suites.remove(&suite_info.binary_id) {
517                self.finalize(test_suite)?;
518            }
519        }
520
521        Ok(())
522    }
523
524    fn finalize(&self, mut test_suite: LibtestSuite) -> Result<(), WriteEventError> {
525        let event = if test_suite.failed > 0 {
526            EVENT_FAILED
527        } else {
528            EVENT_OK
529        };
530
531        let out = &mut test_suite.output_block;
532        let suite_info = test_suite.meta;
533
534        // It's possible that a test failure etc has cancelled the run, in which
535        // case we might still have tests that are "running", even ones that are
536        // actually skipped, so we just add those to the filtered list
537        if test_suite.running > 0 {
538            test_suite.filtered += test_suite.running;
539        }
540
541        write!(
542            out,
543            r#"{{"type":"{KIND_SUITE}","event":"{event}","passed":{},"failed":{},"ignored":{},"measured":0,"filtered_out":{},"exec_time":{}"#,
544            test_suite.succeeded,
545            test_suite.failed,
546            test_suite.ignored,
547            test_suite.filtered,
548            test_suite.total.as_secs_f64(),
549        )
550        .map_err(fmt_err)?;
551
552        if self.emit_nextest_obj {
553            let crate_name = suite_info.package.name();
554            let binary_name = &suite_info.binary_name;
555            write!(
556                out,
557                r#","nextest":{{"crate":"{crate_name}","test_binary":"{binary_name}","kind":"{}""#,
558                suite_info.kind,
559            )
560            .map_err(fmt_err)?;
561
562            if let Some(stress_index) = test_suite.stress_index {
563                write!(out, r#","stress_index":{}"#, stress_index.current).map_err(fmt_err)?;
564                if let Some(total) = stress_index.total {
565                    write!(out, r#","stress_total":{total}"#).map_err(fmt_err)?;
566                }
567            }
568
569            write!(out, "}}").map_err(fmt_err)?;
570        }
571
572        out.extend_from_slice(b"}\n");
573
574        {
575            use std::io::Write as _;
576
577            let mut stdout = std::io::stdout().lock();
578            stdout.write_all(out).map_err(WriteEventError::Io)?;
579            stdout.flush().map_err(WriteEventError::Io)?;
580        }
581
582        Ok(())
583    }
584}
585
586/// Returns the libtest JSON event string for a finished test.
587///
588/// Uses `ExecutionDescription` to determine the overall outcome, which
589/// correctly accounts for flaky tests configured with `flaky-result = "fail"`.
590fn event_for_finished_test<S: OutputSpec>(run_statuses: &ExecutionStatuses<S>) -> &'static str {
591    match run_statuses.describe() {
592        ExecutionDescription::Success { .. }
593        | ExecutionDescription::Flaky {
594            result: FlakyResult::Pass,
595            ..
596        } => EVENT_OK,
597        ExecutionDescription::Flaky {
598            result: FlakyResult::Fail,
599            ..
600        }
601        | ExecutionDescription::Failure { .. } => EVENT_FAILED,
602    }
603}
604
605/// Unfortunately, to replicate the libtest json output, we need to do our own
606/// filtering of the output to strip out the data emitted by libtest in the
607/// human format.
608///
609/// This function relies on the fact that nextest runs every individual test in
610/// isolation.
611fn strip_human_output_from_failed_test(
612    output: &ChildExecutionOutputDescription<LiveSpec>,
613    out: &mut bytes::BytesMut,
614    test_name: &TestCaseName,
615) -> Result<(), WriteEventError> {
616    match output {
617        ChildExecutionOutputDescription::Output {
618            result: _,
619            output,
620            errors,
621        } => {
622            match output {
623                ChildOutputDescription::Combined { output } => {
624                    strip_human_stdout_or_combined(output, out, test_name)?;
625                }
626                ChildOutputDescription::Split { stdout, stderr } => {
627                    // This is not a case that we hit because we always set CaptureStrategy to Combined. But
628                    // handle it in a reasonable fashion. (We do have a unit test for this case, so gate the
629                    // assertion with cfg(not(test)).)
630                    #[cfg(not(test))]
631                    {
632                        debug_assert!(false, "libtest output requires CaptureStrategy::Combined");
633                    }
634                    if let Some(stdout) = stdout {
635                        if !stdout.is_empty() {
636                            write!(out, "--- STDOUT ---\\n").map_err(fmt_err)?;
637                            strip_human_stdout_or_combined(stdout, out, test_name)?;
638                        }
639                    } else {
640                        write!(out, "(stdout not captured)").map_err(fmt_err)?;
641                    }
642                    // If stderr is not empty, just write all of it in.
643                    if let Some(stderr) = stderr {
644                        if !stderr.is_empty() {
645                            write!(out, "\\n--- STDERR ---\\n").map_err(fmt_err)?;
646                            write!(out, "{}", EscapedString(stderr.as_str_lossy()))
647                                .map_err(fmt_err)?;
648                        }
649                    } else {
650                        writeln!(out, "\\n(stderr not captured)").map_err(fmt_err)?;
651                    }
652                }
653                ChildOutputDescription::NotLoaded => {
654                    unreachable!(
655                        "attempted to strip output from output that was not loaded \
656                         (the libtest reporter is not used during replay, where NotLoaded \
657                         is produced)"
658                    );
659                }
660            }
661
662            if let Some(errors) = errors {
663                write!(out, "\\n--- EXECUTION ERRORS ---\\n").map_err(fmt_err)?;
664                write!(
665                    out,
666                    "{}",
667                    EscapedString(&DisplayErrorChain::new(errors).to_string())
668                )
669                .map_err(fmt_err)?;
670            }
671        }
672        ChildExecutionOutputDescription::StartError(error) => {
673            write!(out, "--- EXECUTION ERROR ---\\n").map_err(fmt_err)?;
674            write!(
675                out,
676                "{}",
677                EscapedString(&DisplayErrorChain::new(error).to_string())
678            )
679            .map_err(fmt_err)?;
680        }
681    }
682    Ok(())
683}
684
685fn strip_human_stdout_or_combined(
686    output: &ChildSingleOutput,
687    out: &mut bytes::BytesMut,
688    test_name: &TestCaseName,
689) -> Result<(), WriteEventError> {
690    if output.buf().contains_str("running 1 test\n") {
691        // This is most likely the default test harness.
692        let lines = output
693            .lines()
694            .skip_while(|line| line != b"running 1 test")
695            .skip(1)
696            .take_while(|line| {
697                if let Some(name) = line
698                    .strip_prefix(b"test ")
699                    .and_then(|np| np.strip_suffix(b" ... FAILED"))
700                    && test_name.as_bytes() == name
701                {
702                    return false;
703                }
704
705                true
706            })
707            .map(|line| line.to_str_lossy());
708
709        for line in lines {
710            // This will never fail unless we are OOM
711            write!(out, "{}\\n", EscapedString(&line)).map_err(fmt_err)?;
712        }
713    } else {
714        // This is most likely a custom test harness. Just write out the entire
715        // output.
716        write!(out, "{}", EscapedString(output.as_str_lossy())).map_err(fmt_err)?;
717    }
718
719    Ok(())
720}
721
722/// Copy of the same string escaper used in libtest
723///
724/// <https://github.com/rust-lang/rust/blob/f440b5f0ea042cb2087a36631b20878f9847ee28/library/test/src/formatters/json.rs#L222-L285>
725struct EscapedString<'s>(&'s str);
726
727impl std::fmt::Display for EscapedString<'_> {
728    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> ::std::fmt::Result {
729        let mut start = 0;
730        let s = self.0;
731
732        for (i, byte) in s.bytes().enumerate() {
733            let escaped = match byte {
734                b'"' => "\\\"",
735                b'\\' => "\\\\",
736                b'\x00' => "\\u0000",
737                b'\x01' => "\\u0001",
738                b'\x02' => "\\u0002",
739                b'\x03' => "\\u0003",
740                b'\x04' => "\\u0004",
741                b'\x05' => "\\u0005",
742                b'\x06' => "\\u0006",
743                b'\x07' => "\\u0007",
744                b'\x08' => "\\b",
745                b'\t' => "\\t",
746                b'\n' => "\\n",
747                b'\x0b' => "\\u000b",
748                b'\x0c' => "\\f",
749                b'\r' => "\\r",
750                b'\x0e' => "\\u000e",
751                b'\x0f' => "\\u000f",
752                b'\x10' => "\\u0010",
753                b'\x11' => "\\u0011",
754                b'\x12' => "\\u0012",
755                b'\x13' => "\\u0013",
756                b'\x14' => "\\u0014",
757                b'\x15' => "\\u0015",
758                b'\x16' => "\\u0016",
759                b'\x17' => "\\u0017",
760                b'\x18' => "\\u0018",
761                b'\x19' => "\\u0019",
762                b'\x1a' => "\\u001a",
763                b'\x1b' => "\\u001b",
764                b'\x1c' => "\\u001c",
765                b'\x1d' => "\\u001d",
766                b'\x1e' => "\\u001e",
767                b'\x1f' => "\\u001f",
768                b'\x7f' => "\\u007f",
769                _ => {
770                    continue;
771                }
772            };
773
774            if start < i {
775                f.write_str(&s[start..i])?;
776            }
777
778            f.write_str(escaped)?;
779
780            start = i + 1;
781        }
782
783        if start != self.0.len() {
784            f.write_str(&s[start..])?;
785        }
786
787        Ok(())
788    }
789}
790
791#[cfg(test)]
792mod test {
793    use crate::{
794        config::elements::{FlakyResult, LeakTimeoutResult, SlowTimeoutResult},
795        errors::ChildStartError,
796        output_spec::LiveSpec,
797        reporter::{
798            events::{
799                ChildExecutionOutputDescription, ExecuteStatus, ExecutionResult,
800                ExecutionResultDescription, ExecutionStatuses, FailureDescription, FailureStatus,
801                RetryData,
802            },
803            structured::libtest::{
804                EVENT_FAILED, EVENT_OK, event_for_finished_test,
805                strip_human_output_from_failed_test,
806            },
807        },
808        test_output::{ChildExecutionOutput, ChildOutput, ChildSplitOutput},
809    };
810    use bytes::{Bytes, BytesMut};
811    use chrono::Local;
812    use color_eyre::eyre::eyre;
813    use nextest_metadata::TestCaseName;
814    use std::{io, sync::Arc, time::Duration};
815
816    /// Validates that the human output portion from a failed test is stripped
817    /// out when writing a JSON string, as it is not part of the output when
818    /// libtest itself outputs the JSON, so we have 100% identical output to libtest
819    #[test]
820    fn strips_human_output() {
821        const TEST_OUTPUT: &[&str] = &[
822            "\n",
823            "running 1 test\n",
824            "[src/index.rs:185] \"boop\" = \"boop\"\n",
825            "this is stdout\n",
826            "this i stderr\nok?\n",
827            "thread 'index::test::download_url_crates_io'",
828            r" panicked at src/index.rs:206:9:
829oh no
830stack backtrace:
831    0: rust_begin_unwind
832                at /rustc/a28077b28a02b92985b3a3faecf92813155f1ea1/library/std/src/panicking.rs:597:5
833    1: core::panicking::panic_fmt
834                at /rustc/a28077b28a02b92985b3a3faecf92813155f1ea1/library/core/src/panicking.rs:72:14
835    2: tame_index::index::test::download_url_crates_io
836                at ./src/index.rs:206:9
837    3: tame_index::index::test::download_url_crates_io::{{closure}}
838                at ./src/index.rs:179:33
839    4: core::ops::function::FnOnce::call_once
840                at /rustc/a28077b28a02b92985b3a3faecf92813155f1ea1/library/core/src/ops/function.rs:250:5
841    5: core::ops::function::FnOnce::call_once
842                at /rustc/a28077b28a02b92985b3a3faecf92813155f1ea1/library/core/src/ops/function.rs:250:5
843note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
844",
845            "test index::test::download_url_crates_io ... FAILED\n",
846            "\n\nfailures:\n\nfailures:\n    index::test::download_url_crates_io\n\ntest result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 13 filtered out; finished in 0.01s\n",
847        ];
848
849        let output = {
850            let mut acc = BytesMut::new();
851            for line in TEST_OUTPUT {
852                acc.extend_from_slice(line.as_bytes());
853            }
854
855            ChildOutput::Combined {
856                output: acc.freeze().into(),
857            }
858        };
859
860        let mut actual = bytes::BytesMut::new();
861        let output_desc: ChildExecutionOutputDescription<_> = ChildExecutionOutput::Output {
862            result: None,
863            output,
864            errors: None,
865        }
866        .into();
867        strip_human_output_from_failed_test(
868            &output_desc,
869            &mut actual,
870            &TestCaseName::new("index::test::download_url_crates_io"),
871        )
872        .unwrap();
873
874        insta::assert_snapshot!(std::str::from_utf8(&actual).unwrap());
875    }
876
877    #[test]
878    fn strips_human_output_custom_test_harness() {
879        // For a custom test harness, we don't strip the human output at all.
880        const TEST_OUTPUT: &[&str] = &["\n", "this is a custom test harness!!!\n", "1 test passed"];
881
882        let output = {
883            let mut acc = BytesMut::new();
884            for line in TEST_OUTPUT {
885                acc.extend_from_slice(line.as_bytes());
886            }
887
888            ChildOutput::Combined {
889                output: acc.freeze().into(),
890            }
891        };
892
893        let mut actual = bytes::BytesMut::new();
894        let output_desc: ChildExecutionOutputDescription<_> = ChildExecutionOutput::Output {
895            result: None,
896            output,
897            errors: None,
898        }
899        .into();
900        strip_human_output_from_failed_test(
901            &output_desc,
902            &mut actual,
903            &TestCaseName::new("non-existent"),
904        )
905        .unwrap();
906
907        insta::assert_snapshot!(std::str::from_utf8(&actual).unwrap());
908    }
909
910    #[test]
911    fn strips_human_output_start_error() {
912        let inner_error = eyre!("inner error");
913        let error = io::Error::other(inner_error);
914
915        let output: ChildExecutionOutputDescription<_> =
916            ChildExecutionOutput::StartError(ChildStartError::Spawn(Arc::new(error))).into();
917
918        let mut actual = bytes::BytesMut::new();
919        strip_human_output_from_failed_test(
920            &output,
921            &mut actual,
922            &TestCaseName::new("non-existent"),
923        )
924        .unwrap();
925
926        insta::assert_snapshot!(std::str::from_utf8(&actual).unwrap());
927    }
928
929    #[test]
930    fn strips_human_output_none() {
931        let mut actual = bytes::BytesMut::new();
932        let output_desc: ChildExecutionOutputDescription<_> = ChildExecutionOutput::Output {
933            result: None,
934            output: ChildOutput::Split(ChildSplitOutput {
935                stdout: None,
936                stderr: None,
937            }),
938            errors: None,
939        }
940        .into();
941        strip_human_output_from_failed_test(
942            &output_desc,
943            &mut actual,
944            &TestCaseName::new("non-existent"),
945        )
946        .unwrap();
947
948        insta::assert_snapshot!(std::str::from_utf8(&actual).unwrap());
949    }
950
951    fn make_test_output(result: ExecutionResult) -> ChildExecutionOutputDescription<LiveSpec> {
952        ChildExecutionOutput::Output {
953            result: Some(result),
954            output: ChildOutput::Split(ChildSplitOutput {
955                stdout: Some(Bytes::new().into()),
956                stderr: Some(Bytes::new().into()),
957            }),
958            errors: None,
959        }
960        .into()
961    }
962
963    fn make_passing_status(attempt: u32, total_attempts: u32) -> ExecuteStatus<LiveSpec> {
964        ExecuteStatus {
965            retry_data: RetryData {
966                attempt,
967                total_attempts,
968            },
969            output: make_test_output(ExecutionResult::Pass),
970            result: ExecutionResultDescription::Pass,
971            start_time: Local::now().fixed_offset(),
972            time_taken: Duration::from_secs(1),
973            is_slow: false,
974            delay_before_start: Duration::ZERO,
975            error_summary: None,
976            output_error_slice: None,
977        }
978    }
979
980    fn make_failing_status(attempt: u32, total_attempts: u32) -> ExecuteStatus<LiveSpec> {
981        ExecuteStatus {
982            retry_data: RetryData {
983                attempt,
984                total_attempts,
985            },
986            output: make_test_output(ExecutionResult::Fail {
987                failure_status: FailureStatus::ExitCode(1),
988                leaked: false,
989            }),
990            result: ExecutionResultDescription::Fail {
991                failure: FailureDescription::ExitCode { code: 1 },
992                leaked: false,
993            },
994            start_time: Local::now().fixed_offset(),
995            time_taken: Duration::from_secs(1),
996            is_slow: false,
997            delay_before_start: Duration::ZERO,
998            error_summary: None,
999            output_error_slice: None,
1000        }
1001    }
1002
1003    #[test]
1004    fn event_for_finished_test_variants() {
1005        // Single pass.
1006        let statuses =
1007            ExecutionStatuses::new(vec![make_passing_status(1, 1)], FlakyResult::default());
1008        assert_eq!(event_for_finished_test(&statuses), EVENT_OK, "single pass");
1009
1010        // Single failure.
1011        let statuses =
1012            ExecutionStatuses::new(vec![make_failing_status(1, 1)], FlakyResult::default());
1013        assert_eq!(
1014            event_for_finished_test(&statuses),
1015            EVENT_FAILED,
1016            "single failure"
1017        );
1018
1019        // Flaky pass: fail then pass, default result (pass).
1020        let statuses = ExecutionStatuses::new(
1021            vec![make_failing_status(1, 2), make_passing_status(2, 2)],
1022            FlakyResult::Pass,
1023        );
1024        assert_eq!(
1025            event_for_finished_test(&statuses),
1026            EVENT_OK,
1027            "flaky with result = pass"
1028        );
1029
1030        // Flaky fail: fail then pass, result = fail.
1031        let statuses = ExecutionStatuses::new(
1032            vec![make_failing_status(1, 2), make_passing_status(2, 2)],
1033            FlakyResult::Fail,
1034        );
1035        assert_eq!(
1036            event_for_finished_test(&statuses),
1037            EVENT_FAILED,
1038            "flaky with result = fail"
1039        );
1040
1041        // All retries failed.
1042        let statuses = ExecutionStatuses::new(
1043            vec![make_failing_status(1, 2), make_failing_status(2, 2)],
1044            FlakyResult::Pass,
1045        );
1046        assert_eq!(
1047            event_for_finished_test(&statuses),
1048            EVENT_FAILED,
1049            "all retries failed"
1050        );
1051
1052        // Leak { Pass } → success.
1053        let mut leak_pass = make_passing_status(1, 1);
1054        leak_pass.result = ExecutionResultDescription::Leak {
1055            result: LeakTimeoutResult::Pass,
1056        };
1057        let statuses = ExecutionStatuses::new(vec![leak_pass], FlakyResult::default());
1058        assert_eq!(
1059            event_for_finished_test(&statuses),
1060            EVENT_OK,
1061            "leak with result = pass"
1062        );
1063
1064        // Leak { Fail } → failure.
1065        let mut leak_fail = make_passing_status(1, 1);
1066        leak_fail.result = ExecutionResultDescription::Leak {
1067            result: LeakTimeoutResult::Fail,
1068        };
1069        let statuses = ExecutionStatuses::new(vec![leak_fail], FlakyResult::default());
1070        assert_eq!(
1071            event_for_finished_test(&statuses),
1072            EVENT_FAILED,
1073            "leak with result = fail"
1074        );
1075
1076        // Timeout { Pass } → success.
1077        let mut timeout_pass = make_passing_status(1, 1);
1078        timeout_pass.result = ExecutionResultDescription::Timeout {
1079            result: SlowTimeoutResult::Pass,
1080        };
1081        let statuses = ExecutionStatuses::new(vec![timeout_pass], FlakyResult::default());
1082        assert_eq!(
1083            event_for_finished_test(&statuses),
1084            EVENT_OK,
1085            "timeout with result = pass"
1086        );
1087
1088        // Timeout { Fail } → failure.
1089        let mut timeout_fail = make_passing_status(1, 1);
1090        timeout_fail.result = ExecutionResultDescription::Timeout {
1091            result: SlowTimeoutResult::Fail,
1092        };
1093        let statuses = ExecutionStatuses::new(vec![timeout_fail], FlakyResult::default());
1094        assert_eq!(
1095            event_for_finished_test(&statuses),
1096            EVENT_FAILED,
1097            "timeout with result = fail"
1098        );
1099
1100        // ExecFail → failure.
1101        let mut exec_fail = make_passing_status(1, 1);
1102        exec_fail.result = ExecutionResultDescription::ExecFail;
1103        let statuses = ExecutionStatuses::new(vec![exec_fail], FlakyResult::default());
1104        assert_eq!(
1105            event_for_finished_test(&statuses),
1106            EVENT_FAILED,
1107            "exec fail"
1108        );
1109    }
1110}