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.