Capturing stdout from test code is inconsistent

[MicahChalmer]

The feature that captures "stdout" for tests doesn't capture all the ways that a test could print to stdout.

#[test]
fn output_capture_tests() {
    println!("This gets captured...");
    let _ = std::io::stdout().write_line("but this does not...");
    let _ = std::task::try(proc() { println!("..and neither does this...") });
    let _ = std::run::process_status("/bin/echo", [~"...nor this..."]);
    fail!();
}

Only the first println! call gets captured--the rest appear intermingled with the test output:

running 1 test
but this does not...
..and neither does this...
...nor this...
test output_capture_tests ... FAILED

failures:

---- output_capture_tests stdout ----
    This gets captured...
    task 'output_capture_tests' failed at 'explicit failure', subproc-test-stdout.rs:7


failures:
    output_capture_tests

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

It would be nice if all of these got captured.

[alexcrichton]

In my opinion, the only real bug here is that the child task's println isn't captured. Capturing stdout/stderr is not supposed to be comprehensive, it's supposed to clean up the output.

You'll almost always be able to subvert whatever capturing is going on, it's not supposed to be exhaustive.

[MicahChalmer]

Ok, so std::io::stdout() will always hit the process-wide FD 1 (not task-local), whereas the functions in std::io::stdio will write to a task-local "stdout" which could be redirected at spawn time. Perhaps the task-local "stdout" should have a different name? Otherwise this could get rather confusing. I think people will expect the term "stdout" to always refer to the process global version. "Task default output" maybe?

If the task-local one is still going to be named "stdout", then I think the documentation will need to be updated in a lot of places to make it explicit which "stdout" is being used. For instance, the documentation of std::io::stdio::println refers to "the stdout of the current process"--but that's no longer the case, now it's "the stdout of the current task" (and probably an explanation of how that is not the same thing as the stdout of the current process.)

Once that distinction is clear, it's natural to assume that child processes will inherit the process global FD, so I see why that's not a bug. It's easy enough to capture the output and print it to the task's "stdout".

[steveklabnik]

This is still true today with Thread::scoped.

[aturon]

Nominating for 1.0-beta P-backcompat-libs. We need to finalize our capture story.

[pnkfelix]

1.0 beta, P-backcompat-libs, I-needsdecision

[aturon]

triage: (1.0)

[aturon]

triage: P-high (1.0)

[dbrgn]

I also stumbled over this issue when starting a test server as a child process. The stdout logged by the server does not get captured.

While I could redirect the output to /dev/null, that makes it hard to debug problems. On the other hand, allowing the stdout to be printed causes pages of unnecessary output, making it hard to see the actual test results.

[nagisa]

@alexcrichton just an idea, but how about we use something like freopen (and dup to keep stdout around as a different fd) to replace the stdout file descriptor for the duration of the testing? It should be cheap enough to be able to do that for tests, it would also capture all sorts of outputs and would let us to avoid having that weird thread-local stdout overwrite code we have now.

[retep998]

@nagisa Can't use freopen to deal with Rust's stdout on Windows.

[alexcrichton]

@nagisa sounds plausible to me, I think there may also be ways to muck around with this on Windows as well. We'd likely still need to fiddle with private APIs in the standard library, however, as on Windows at least we cache the handles returned by the system so if they're reset we'd have to bust that cache.

[nagisa]

@retep998 SetStdHandle?

[retep998]

@nagisa If Rust didn't cache the result of GetStdHandle, then yes that would work.

[sanmai-NL]

@alexcrichton: these many reports and suggestions for improvement can be circumvented by removing the whole output capturing code and instead optionally report test outcomes as JSON messages on stdout, and assume tests themselves do not pollute stdout. Then we’d be done with these annoyances without putting in effort to unbreak output capturing. Are you open to a PR?

Also, this issue should be moved to the Cargo issue tracker.

[alexcrichton]

@sanmai-NL I think that such a PR would unfortunately be a breaking change and as a result needs to be considered a little more carefully (e.g. with the dev-tools team). This is still a rustc issue as-is so I don't think it should move.

[Mark-Simulacrum]

Going to go ahead and close this as a duplicate of #42474.

[glts]

I suggest that this issue be reopened. It has not been fixed, and there is no explanation for why it should not be considered further, either above or in the linked issue.

I believe it is a current best practice to use writeln!(std::io::stdout())? in place of println! in programs that should not panic on I/O error. However, this idiom results in stdout not being captured.

[mathstuf]

I think this is the issue to keep open; #42474 is "fixed" in that output is now captured. It is just "inconsistent".

FWIW, there will always be a way "around" it (talking to /dev/tty, using fd 1, etc.). Unless there's some mangling going on under cfg(test), what kinds of effects would std::io::stdout() checking some TLS structure add to non-test code?

For child processes, there would need to be some file descriptor/handle juggling in std::process to detect cfg(test) and relocate the file descriptors if not otherwise set. This also leaves things like tokio::process in the dark unless the test crate grows some APIs to use (and stabilizes them).

[mathstuf]

The docs for std::oi::stdout state:

Constructs a new handle to the standard output of the current process.

I don't think that can get an asterisk for "unless running from a #[test] function in which case it is a handle to the capture output (if any)". Note that this also gives a way to guarantee bypassing any such capturing (assuming fd 1 isn't closed…which makes me think "what is the behavior on a closed fd 1 here? how about read-only?"). Similarly for std::process, bypassing may or may not be wanted in different contexts. That sounds like API design and, again, dependent upon the test crate being stabilized anyways.

[Finomnis]

@Mark-Simulacrum Please re-open, this is not actually a duplicate, and the problem still persists.

[Houtamelo]

@Mark-Simulacrum Please re-open, this is not actually a duplicate, and the problem still persists.

If not fixed, this should at least be on the documentation.

[Mark-Simulacrum]

#90785 appears to be the current issue tracking this.