nextest-rs / nextest

A next-generation test runner for Rust.
https://nexte.st
Apache License 2.0
2.22k stars 99 forks source link

Bug: leak detection swallows test failure output #1891

Closed dcarley closed 5 days ago

dcarley commented 1 week ago

Description of the issue

Description: The output of a failing assertion is swallowed when the test also leaks a subprocess.

This makes it hard to debug the original cause of the failure, which might be that the clean-up was just never reached.

Steps to reproduce:

Run cargo nextest run with the following test that makes a failing assertion before the process is cleaned up:

    #[test]
    fn nextest_fail_and_leak() {
        let mut proc = Command::new("sleep").arg("2").spawn().unwrap();
        assert_eq!(1, 2);
        proc.wait().unwrap();
    }

Expected outcome

Output from the assert_eq should be displayed along with the fact that it leaked.

Fabricated output:

Nextest run ID 3b8651bc-c52c-4b42-a95a-f2bf97211344 with nextest profile: default
    Starting 1 test across 1 binary (15 tests skipped)
 FAIL + LEAK [   2.008s] flox-watchdog::bin/flox-watchdog process::test::nextest_fail_and_leak

--- STDOUT:              flox-watchdog::bin/flox-watchdog process::test::nextest_fail_and_leak ---

running 1 test
test process::test::nextest_fail_and_leak ... FAILED

failures:

failures:
    process::test::nextest_fail_and_leak

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 15 filtered out; finished in 2.00s

--- STDERR:              flox-watchdog::bin/flox-watchdog process::test::nextest_fail_and_leak ---
thread 'process::test::nextest_fail_and_leak' panicked at flox-watchdog/src/process.rs:581:9:
assertion `left == right` failed
  left: 1
 right: 2
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

   Canceling due to test failure
------------
     Summary [   2.011s] 1 test run: 0 passed, 1 failed, 15 skipped
 FAIL + LEAK [   2.008s] flox-watchdog::bin/flox-watchdog process::test::nextest_fail_and_leak

Actual result

We only get information that it failed and leaked, but not why it failed:

Nextest run ID d24f3bcc-f941-41f8-a1ab-b0605da2026f with nextest profile: default
    Starting 1 test across 1 binary (15 tests skipped)
 FAIL + LEAK [   0.108s] flox-watchdog::bin/flox-watchdog process::test::nextest_fail_and_leak

   Canceling due to test failure
------------
     Summary [   0.109s] 1 test run: 0 passed, 1 failed, 15 skipped
 FAIL + LEAK [   0.108s] flox-watchdog::bin/flox-watchdog process::test::nextest_fail_and_leak
error: test run failed

Nextest version

% cargo nextest --version
cargo-nextest 0.9.79
release: 0.9.79
host: aarch64-apple-darwin


### Additional context

_No response_
sunshowers commented 6 days ago

Thank you for the detailed bug report! Looking into it now.

sunshowers commented 6 days ago

Looks like this was fixed in 0.9.83, likely as part of the way outputs are collected being refactored (https://github.com/nextest-rs/nextest/commit/f1966f791c136d4d5ebd9e6c1c2b8d1ad0df3883). Could you update to the latest nextest (0.9.84 currently) and try again?

sunshowers commented 6 days ago

However it is concerning that I didn't realize this bug existed! I think it must have gotten introduced as a regression at some point.

https://github.com/nextest-rs/nextest/pull/1892 adds coverage for this situation.

sunshowers commented 5 days ago

Going to close this out as fixed in the latest version of nextest. Please reopen if you're still seeing it.

dcarley commented 4 days ago

My bad, I should have checked the latest version.

Thanks for the quick response, additional test, and great project!