Tests do not capture stdout() / stderr()

[akhouderchah]

Output capture for tests (d0d0e78, 11ce918) causes print_to (and consequently _print & macros) to redirect to OUTPUT_CAPTURE if set. IIUC, this leaves any direct usage of stdout() uncaptured.

This is inconvenient for systems which use stdout() with generic code over io::Write.

Basically a dupe of the unresolved-but-closed #12309.

[mina86]

Steps to reproduce:

$ cat src/lib.rs
#[test]
fn test() {
    use std::io::Write;

    eprintln!("eprintln");
    println!("println");
    std::io::stdout().write_all(b"stdout\n").unwrap();
    std::io::stderr().write_all(b"stderr\n").unwrap();
}
$ cargo test --tests
    Finished test [unoptimized] target(s) in 0.00s
     Running unittests (target/debug/deps/a-7d5a981fc2a1d521)

running 1 test
stdout
stderr
test test ... ok

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

$ cargo --version
cargo 1.58.0-nightly (7f08ace4f 2021-11-24)

Expected output:

$ cargo test --tests
    Finished test [unoptimized] target(s) in 0.00s
     Running unittests (target/debug/deps/a-7d5a981fc2a1d521)

running 1 test
test test ... ok

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

Without looking at libtest code, the proper solution seems to be:

old_stdout = dup(1);
old_stderr = dup(2);

tmp = mktemp(…);
tmp_fd = open(tmp);

dup2(tmp_fd, 1);
dup2(tmp_fd, 2);

success = run_the_test();

dup2(old_stdout, 1);
dup2(old_stderr, 2);

if !success {
    fseek(tmp_fd, 0);
    cat(tmp_fd);
}

close(tmp_fd);
unlink(tmp);

This would also solve #92370

[davepacheco]

I ran into this today as well. I'm not sure how hard this is to fix. Even if it's decided not to fix it, I think some better documentation around output capturing could help. I understood it to be stdout/stderr that was captured, but it's really just thread-local print! and friends. I ran into this because I was using term::stdout(), but I think you'd also be likely to see this in async tests that print output from other tasks.

[vojtechkral]

Ran into this today. This is particularly unpleasant in the following scenario:

eprintln!("Something something");
stderr.write_all(tty_escape_cursor_up_clear_line).unwrap();
eprintln!("Something else");

Running that code from the test harness leads to the eprintlns being captured, but the escape sequences not, and they then end up messing up the test harness output. The worst bit is I can't seem to find a way to detect this somehow (in tests the stderr is still a tty), I'm probably going to have to introduce some kind of a switch to disable tty stuff from tests explicitly.

[saethlin]

@rustbot label +T-libs +A-libtest

[mathstuf]

Without looking at libtest code, the proper solution seems to be: [[dup juggling]]

Alas, dup and friends are process-wide, so this strategy forces a limit of -j1 on test execution.

[vojtechkral]

Without looking at libtest code, the proper solution seems to be: [[dup juggling]]

Alas, dup and friends are process-wide, so this strategy forces a limit of -j1 on test execution.

Is that a problem though? Arguably you could dup original 1 and 2, use that for all logging/cli output and make 1 and 2 pipes (for tests to write to).

Edit: A bonus of this solution would be that test output would have no way of messing up test harness output (which it can do now since it has access to the tty).

[vojtechkral]

Anyone knows what nextest does? Chances are they've got this solved already...

[mathstuf]

make 1 and 2 pipes (for tests to write to).

Pipes to what? There still wouldn't be per-test places for things to go, so "what happened for failed tests" would be jumbled.

[vojtechkral]

Pipes to what?

A thread (not) copying that to the real std{out,err} based on settings. It could also filter out escape sequences.

There still wouldn't be per-test places for things to go, so "what happened for failed tests" would be jumbled.

Sure, but at least the output would actually be captured. And you can always use -j1 when tests fail and you need clean output.

[AlejandroFNadal]

For people searching and finding this issue:

Add in each test, instead of
#[test]
put:

#[test_log::test]

Then, to cargo toml

[dev-dependencies]
test-log = "*"

Finally, set env variable to desired debugging level:
export RUST_LOG="debug"