Suggest --nocapture flag when a test fails with abort

[matklad]

Problem

Consider the following test

#[test]
fn rayon_panic() {
    rayon::spawn(|| panic!("o_O"));
    loop {}
}

cargo test for it produces the following output:

λ cargo t
   Compiling rt v0.1.0 (/home/matklad/tmp/rt)
    Finished test [unoptimized + debuginfo] target(s) in 0.17s
     Running unittests src/lib.rs (target/debug/deps/rt-fb003f4fc4a43299)

running 1 test
error: test failed, to rerun pass '--lib'

Caused by:
  process didn't exit successfully: `/home/matklad/tmp/rt/target/debug/deps/rt-fb003f4fc4a43299` (signal: 6, SIGABRT: process abort signal)

Note how it's super unclear what exactly failed and why. Passing --nocapture flags helps a bit, but only an expert user would realize that such a flag might be helpful!

λ cargo t -- --nocapture
    Finished test [unoptimized + debuginfo] target(s) in 0.01s
     Running unittests src/lib.rs (target/debug/deps/rt-fb003f4fc4a43299)

running 1 test
thread '<unnamed>' panicked at 'o_O', src/lib.rs:3:21
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
Rayon: detected unexpected panic; aborting
error: test failed, to rerun pass '--lib'

Caused by:
  process didn't exit successfully: `/home/matklad/tmp/rt/target/debug/deps/rt-fb003f4fc4a43299 --nocapture` (signal: 6, SIGABRT: process abort signal)

---

What happens here is that the test calls std::process::abort. Because, by default, cargo test captures stderr, and because abort doesn't unwind, libtest doesn't get a chance to flush stderr. This seems like a fundamental limitation of libtest.

Proposed Solution

It'd be cool if cargo realised that cargo test process was killed with a singnal, and suggested re-running with --nocapture in this case. Note that this won't always help (it might be the case that a test died without printing anything to stderr), but it doesn't seem that the note like the following would hurt:

error: test failed, to rerun pass '--lib'
 note: test was terminated by the signal, stderr might be truncated, pass `--nocapture` disable output buffering.

Notes

No response

[stupendoussuperpowers]

I'd love to help out here, could someone guide me on the relevant files which contain error strings for this?

[stupendoussuperpowers]

I see that the lines in cargo_test.rs, prints out test errors based on relevant TestKind and cli arguments.

Would the correct implementation to be to add the "--nocapture" note in here? This would work only if we want the note to be displayed after every failed test.

let mut err = format_err!("{}, to rerun pass `{}`", which, unit_err.cli_args(ws, opts));

https://github.com/rust-lang/cargo/blob/bfb0d197d20a19f7cd811493081b4f769a1377cf/src/cargo/ops/cargo_test.rs#L414C1-L420

I can make this change, if this is the correct implementation. Please suggest any alternate implementation that would make more sense of this issue.

[epage]

Could you create mockups of what you are proposing so we have something more concrete to focus the discussion on?

[epage]

(note this is tagged with "needs mentor" rather than "accepted" which means if you take this on, you'll have to take a lot more responsibility for your path with this issue which you are already showing by finding some relevant code)

[ehuss]

A passing by comment: I would suggest only giving that suggestion on a nonstandard exit (like a signal), only if it is using the standard test harness, and only if that flag is not already specified.

[stupendoussuperpowers]

I've made the relevant changes here - https://github.com/stupendoussuperpowers/cargo/blob/97f5f99ef2e9bf009a3dd3e80db3532ff6bdf403/src/cargo/ops/cargo_test.rs#L428C3-L438C6

File: cargo/src/cargo/ops/cargo_test.rs

  let mut err = format_err!("{}, to rerun pass `{}`", which, unit_err.cli_args(ws, opts));
   // Don't show "process didn't exit successfully" for simple errors.
   // libtest exits with 101 for normal errors.
   let is_simple = test_error
       .downcast_ref::<ProcessError>()
       .and_then(|proc_err| proc_err.code)
       .map_or(false, |code| code == 101);

  if !is_simple {
        err = test_error.context(err);
    }

    crate::display_error(&err, &mut ws.config().shell());

+   if !is_simple {
+      drop(ws.config().shell().note(
+       "test was terminated by the signal, stderr might be truncated, pass `--nocapture` disable output buffering.",
+      ));
+   }

Turns out, we already track whether a process was terminated abruptly with the is_simple flag. This value is set to false if a process terminates normally, and true when it's killed by a signal.

I'm utilizing this to add the note that was suggested in the issue.

I've built and tested this on linux-x86, and it seems to be generating the output as expected.

Test terminated by a signal (outputs the note) :

 running 1 test
    error: test failed, to rerun pass `--lib`

    Caused by:
    process didn't exit successfully: `/home/sanchit/Code/rustpress/target/debug/deps/rustpress-1838d8567bb57635 --nocapture` (signal: 6, SIGABRT: process abort signal)
    note: test was terminated by the signal, stderr might be truncated, pass `--nocapture` disable output buffering.

Regular failing test (does not show the note) :

    failures:

    failures:
        tests::non_breaking

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

    error: test failed, to rerun pass `--lib`

Open for suggestions here on how to proceed further on this, if I should add more checks before displaying the message, etc.

[stupendoussuperpowers]

... and only if that flag is not already specified.

I looked into this, and this might require a larger change to accomplish.

We do not pass the cli args used to run the test to the function where we check for failures/log messages.

This is the logging function -

fn report_test_error(
    ws: &Workspace<'_>,
    opts: &ops::CompileOptions,
    unit_err: &UnitTestError,
    test_error: anyhow::Error,
)

We do have access to test_args in the immediate calling function -

fn run_unit_tests(
    ws: &Workspace<'_>,
    options: &TestOptions,
    test_args: &[&str],
    compilation: &Compilation<'_>,
    test_kind: TestKind,
)

However, I don't think we can process the output message in the run_unit_tests function, and we don't pass down any information related to test_args to report_test_error currently, so I'm not sure if there's a straightforward way of proceeding here.

Reference: /src/cargo/ops/cargo_test.rs

[epage]

To clarify something else that ehuss said

only if it is using the standard test harness

This is referring to the harness field. This might end up being higher in the stack as well though I eventually want to leverage related information for more interesting processing of tests.

[epage]

note: test was terminated by the signal, stderr might be truncated, pass --nocapture disable output buffering.

Something else to note is that this that --nocapture needs to be passed to the harness, rather than cargo. This is tricky to communicate because if they have no harness arguments, then they probably should do -- --nocapture. If they have harness arguments, then I'm not sure what would be a good way to clarify which side of -- it goes on. Maybe we punt and say "pass --nocapture to the harness"?

[stupendoussuperpowers]

changing the string to "pass --nocapture to the test harness" seems like a simpler/more concise option, since we currently don't have access to whether or not the harness arguments were set.

[stupendoussuperpowers]

okay, we can access the harness flag using unit_err.unit.target.harness() inside the report_test_error function, however I feel like we can just stick with the "pass it to the harness" string.

[epage]

libtest is the default harness and has a --nocapture flag. You can provide a custom harness by specifying harness=false. There is no guarantee what flags the harness may have though most try to conform to libtest's CLI.

[stupendoussuperpowers]

so, just to summarize, we have two implementations we can go with -

1. show the nocapture prompt regardless of harness flag
2. show the nocapture prompt only if we use libtest / harness = true (as suggested by ehuss above).

I don't have much experience with custom test harnesses, so I am not sure if it's a fair assumption to make that they would implement the nocapture flag. If it is a fair assumption to make, we can go for the the 1st implementation, otherwise we can go with the 2nd.

[epage]

The two most common libtest harnesses have a --nocapture flag but do nothing with it

• https://github.com/LukasKalbertodt/libtest-mimic/blob/master/src/args.rs#L45
• https://github.com/bheisler/criterion.rs/blob/dc2b06cd31f7aa34cff6a83a00598e0523186dad/src/lib.rs#L899

This is because full --nocapture support requires use of unstable std library features.

Especially if you have easy access to the harness flag, let's take advantage of it. Later I want to better define the relationship between cargo and custom test harnesses and when I do, it'll let us know when a harness supports a standard CLI.

[stupendoussuperpowers]

I've made the changes here: master...stupendoussuperpowers:cargo:issue-10855

Let me know if I should go ahead and submit a pull request.

[epage]

• If the immediate caller of report_test_error has the args, let's go ahead and skip the message if it was passed in. I'm not normally a fan of parsing args for other programs but this is a relatively trivial case
• I feel like the message couild be a little more succinct but we can handle that in the PR
• Ideally the PR would contain 2 commits, the first is a commit that adds tests for these cases (tests abort with a custom test harness, without one, and with --nocapture passed in, showing the current output) with the second commit making the behavior change and updating the tests for the new output.

[stupendoussuperpowers]

Thanks for the feedback. I'll make these changes and submit a PR.

[stupendoussuperpowers]

I've staged the changes here: diff

I've modified and added tests so that they cover all the cases mentioned above. The tests are passing, but I need someone to advise if I followed the guidelines for writing tests properly.

For tracking the --nocapture flag the best alternative I found was just to pass down test_args to the report_test_error function -

• This is because the other flags needed to check the boundary condition are more readily available in this function, and processing just one argument in the parent function and the rest in the report_test_error function would likely cause issues and lead to some redundant code.
• This function is private and is only called at 2 places, I've made appropriate changes to both these places, I don't think there's going to be regression based on this, as all the tests passed.

However, please let me know if you see a better way of handling this.

[epage]

At this point the discussion is mroe on the implementation side. How about we move it to a PR?