`cargo test` output, --nocapture and --format

[mchernyavsky]

There is an unexpected behavior when using --nocapture option, especially when combined with --format option.

Example file:

#[cfg(test)]
mod tests {
    #[test]
    fn test1() {
        println!("Hello from test #1");
        panic!();
    }
    #[test]
    fn test2() {
        println!("Hello from test #2");
    }
}

1. cargo test output:

    Finished dev [unoptimized + debuginfo] target(s) in 0.03s                                                                                                                        
     Running target/debug/deps/rust_sandbox-3aca71fd58cbc041

running 0 tests

test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out

     Running target/debug/deps/tests-03a860f74891dd25

running 2 tests
test tests::test2 ... ok
test tests::test1 ... FAILED

failures:

---- tests::test1 stdout ----
Hello from test #1
thread 'tests::test1' panicked at 'explicit panic', tests/tests.rs:6:9
note: Run with `RUST_BACKTRACE=1` for a backtrace.


failures:
    tests::test1

test result: FAILED. 1 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out

error: test failed, to rerun pass '--test tests'

2. cargo test -- --nocapture output:

    Finished dev [unoptimized + debuginfo] target(s) in 0.03s                                                                                                                        
     Running target/debug/deps/rust_sandbox-3aca71fd58cbc041

running 0 tests

test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out

     Running target/debug/deps/tests-03a860f74891dd25

running 2 tests
Hello from test #1
Hello from test #2
thread 'tests::test1' panicked at 'explicit panic', tests/tests.rs:6:9
note: Run with `RUST_BACKTRACE=1` for a backtrace.
test tests::test2 ... ok
test tests::test1 ... FAILED

failures:

failures:
    tests::test1

test result: FAILED. 1 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out

error: test failed, to rerun pass '--test tests'

3. cargo test -- -Z unstable-options --format=json output:

    Finished dev [unoptimized + debuginfo] target(s) in 0.03s                                                                                                                        
     Running target/debug/deps/rust_sandbox-3aca71fd58cbc041
{ "type": "suite", "event": "started", "test_count": "0" }
{ "type": "suite", "event": "ok", "passed": 0, "failed": 0, "allowed_fail": 0, "ignored": 0, "measured": 0, "filtered_out": "0" }
     Running target/debug/deps/tests-03a860f74891dd25
{ "type": "suite", "event": "started", "test_count": "2" }
{ "type": "test", "event": "started", "name": "tests::test1" }
{ "type": "test", "event": "started", "name": "tests::test2" }
{ "type": "test", "name": "tests::test2", "event": "ok" }
{ "type": "test", "name": "tests::test1", "event": "failed", "stdout": "Hello from test #1\nthread 'tests::test1' panicked at 'explicit panic', tests/tests.rs:6:9\nnote: Run with `RUST_BACKTRACE=1` for a backtrace.\n" }
{ "type": "suite", "event": "failed", "passed": 1, "failed": 1, "allowed_fail": 0, "ignored": 0, "measured": 0, "filtered_out": "0" }
error: test failed, to rerun pass '--test tests'

4. cargo test -- --nocapture -Z unstable-options --format=json output:

    Finished dev [unoptimized + debuginfo] target(s) in 0.03s                                                                                                                        
     Running target/debug/deps/rust_sandbox-3aca71fd58cbc041
{ "type": "suite", "event": "started", "test_count": "0" }
{ "type": "suite", "event": "ok", "passed": 0, "failed": 0, "allowed_fail": 0, "ignored": 0, "measured": 0, "filtered_out": "0" }
     Running target/debug/deps/tests-03a860f74891dd25
{ "type": "suite", "event": "started", "test_count": "2" }
{ "type": "test", "event": "started", "name": "tests::test1" }
{ "type": "test", "event": "started", "name": "tests::test2" }
Hello from test #1
Hello from test #2
thread 'tests::test1' panicked at 'explicit panic', tests/tests.rs:6:9
note: Run with `RUST_BACKTRACE=1` for a backtrace.
{ "type": "test", "name": "tests::test2", "event": "ok" }
{ "type": "test", "name": "tests::test1", "event": "failed" }
{ "type": "suite", "event": "failed", "passed": 1, "failed": 1, "allowed_fail": 0, "ignored": 0, "measured": 0, "filtered_out": "0" }
error: test failed, to rerun pass '--test tests'

I expected to see this happen:

• In 1st case, the Hello from test #1 line doesn't appear in the tests::test1 stdout section.
• In 2nd case, thread error is not captured (!).
• In 3rd case, the Hello from test #1 line doesn't appear in the stdout field.
• In 4th case, the println! output and thread error are recorded in different fields (e.g. stdout and stderr).

Instead, normal output and errors are written to the same output stream (?) and processed in the same way, depending on --nocapture option.

I'm using:

• cargo 1.29.0 (524a578 2018-08-05)
• rustc 1.29.1 (b801ae664 2018-09-20)

p.s. Expected behavior for the 4th case can be useful for integrating test frameworks with IDEs and editors.

[alexcrichton]

Thanks for the report! I think though that these are issues with the libtest testing harness in upstream rust-lang/rust. Would you be ok reporting this issue upstream there?

[mchernyavsky]

Yes, sure.
=> rust-lang/rust#54669