cabal test outputs stdout and stderr out of order

[hdgarrood]

With https://github.com/hdgarrood/cabal-test-stderr, if you run cabal test, you get this:

Preprocessing test suite 'tests' for cabal-test-stderr-0.1.0.0...
Running 1 test suites...
Test suite tests: RUNNING...
oops, failed
lol
Test suite tests: FAIL
Test suite logged to: dist/test/cabal-test-stderr-0.1.0.0-tests.log
0 of 1 test suites (0 of 1 test cases) passed.

But if you run the test executable directly, you get this:

lol
oops, failed

That is, lol and oops, failed appear the other way around.

The source code is:

import Control.Monad
import System.IO
import System.Exit

main = do
  putStrLn "lol"
  hPutStrLn stderr "oops, failed"
  exitFailure

I expected cabal test to produce text output in the same order as running the executable directly, even if the test executable outputs text to both stderr and stdout.

Possibly related: #1601. Being able to easily run the test suite directly would make this less of a problem.

[Blaisorblade]

Have you tried different --show-details= settings, in particular --show-details=streaming? Since you dislike cabal's filtering anyway, that might be what you want (and the implementation might be doing what you want, guessing from https://github.com/haskell/cabal/pull/1727/files#diff-604b1e3eaf4c44ccd162dc7c95128ee5R73).

Also, it's unclear whether (and where) ordering between stdout and stderr is well-defined, even on *x systems (let alone Windows), so it's unclear how the interface of cabal test should be refined (and if your expectation makes sense). I can't find a proper reference for now, only hints in https://en.wikipedia.org/wiki/Standard_streams#Standard_error_.28stderr.29 and e.g.
http://superuser.com/a/517905 (by googling ordering between stdout and stderr); some info on the buffering behavior is here.

In particular, it seems clearly hard to preserve order when performing filtering. (I am assuming that you're only printing complete lines to stdout, otherwise not even running the program standalone would preserve buffering).

[hdgarrood]

Perhaps it will help to talk about where I'm coming from: essentially, what I would like to have is a command to run all the test suites without doing any kind of buffering or filtering. The only problem (as far as I'm aware) with just running ./dist/build/tests/tests directly is that if I add another test suite to my cabal file, I also need to add another call to my test script, and it seems quite easy to forget to do so.

I realise that an ordering between stdout and stderr is probably not well-defined in general, but I'm really thinking about test suites which run sequentially and output text line-by-line, where it seems that it ought to be easier. I think that a lot of test suites are like this; possibly even most are.

I hadn't tried different --show-details settings, but I have now, and they don't appear to have any effect. I still get oops, failed before lol when I run with --show-details=streaming.

[Blaisorblade]

I'm not sure on the exact requirements, but I suspect in a perfect world it'd be overall easier to do fancy error reporting on test reports before stringifying them. I think that's also what happens on the JVM in most cases, by loading test classes at runtime; in Haskell, I'd rather exchange structured data (JSON? YAML?).

Perhaps it will help to talk about where I'm coming from

👍 I'd even go one step back to user requirements.
What's your test framework? Why does the stdout/stderr interleaving matter to you? Does this matter because you have debug output?

[Blaisorblade]

in Haskell, I'd rather exchange structured data (JSON? YAML?).

Whoops, people are onto that already: #1601 (comment)

[hdgarrood]

This is PureScript. No test framework; just a bunch of tests and a call to exitFailure if any of them fail. (There are two test suites in the cabal file, and both use the exit code interface, not detailed).

The interleaving matters to me because one of the tests has two different sections; the first happens to output to stdout, and the second to stderr. The interleaving meant that it was annoying when the first passed and the second failed, because it looked like the second was not outputting anything before failing, when really, the second section's output was just a few lines back, mixed in with the first's.

I suppose I could also fix this problem by a) flushing stdout and stderr between each section, or b) only outputting to one of those two streams, too. But it would be nice not to have to.

[ezyang]

Maybe the reason it doesn't work with streaming is that we forgot to turn off stdout/stderr buffering. Should be an easy patch to try, and might fix the problem.

[Blaisorblade]

Maybe the reason it doesn't work with streaming is that we forgot to turn off stdout/stderr buffering. Should be an easy patch to try, and might fix the problem.

I'd advise to try forcing line buffering in the launched test suite; line buffering is enabled by default when process run against terminals, but not when they run against pipes. That should be actually easy and, if you're right, should fix the problem. Maybe you want to have cabal tell the testsuite to do that if you don't always want that (but why?), but I'll leave that up to you.

---

Otherwise, doing that just from inside cabal-install through hSetBuffering (if that's what you suggest) seems harder, because buffering behavior is not a flag set through a syscall that is inherited by child processes; you essentially need, somehow, to ensure hSetBuffering or equivalent get called by the child process.

While Haskell libraries appear not to use C buffering, the implementation appears to be similar enough; it might be instructive to look at the hacks used in Unix around this behavior (search for unbuffer and stdbuf in this reference I already mentioned). The sanest (!) approach seems to run the process against a terminal emulator, but even that (unbuffer) has somehow issues.

[ezyang]

Then it seems reasonable for Cabal to present a pseudo-terminal to the subprocess when it intends to pass the information straight through to the user's terminal. (Well, someone has to implement it first though...)

[ttuegel]

@ezyang The only reason I didn't do that in the first place is that Windows doesn't seem to have a notion analogous to pseudoterminals; I think the Cabal library should have the same features on all platforms. As discussed elsewhere, I think the correct way forward on this is to make the library "dumb" with respect to logging, i.e. only supporting --show-details=direct. (The presence of that option should serve as a workaround for this issue, by the way.) How logging should be handled is a question best left to the library clients: cabal-install, stack, etc. In cabal-install, I'm much happier to offer platform-dependent options, like direct-to-pty output on Unix-alikes.

[Blaisorblade]

👍 to --show-details=direct.

On pseudoterminals: I said "sanest", but I did mean "still not sane, just less so". The TL;DR is "it's low-level UNIX APIs, so let's please run away from that complexity and maintenance hell".

I implicitly assumed that pseudoterminals would be a pain to support, based on everything I hear about TTYs in general (not on having actually done it); it's low-level leaky UNIX APIs. Example puzzler: can you portably call grantpt if there's a signal handler for SIGCHLD? Answer: no, but this should in practice work on Linux, so bugs here will be fun to debug. Plus, correctness of Cabal becomes dependent on implementation details of the runtime system.

Especially because the motivation is:

This is PureScript. No test framework; just a bunch of tests and a call to exitFailure if any of them fail.

I expect it'd be better (in terms of overall effort) to put together the needed PureScript test framework (if missing) to use the detailed interface, instead of dealing with pseudoterminals, especially if (as I assume) there are more contributors able to maintain option 1 than option 2.

But if some UNIX API expert contributes robust code to support that and guarantees long-term maintenance for it, even though I still expect that effort to be bigger, I might well turn out to be wrong.

[hdgarrood]

Just in case I wasn't clear: This is for the PureScript compiler, which is all written in Haskell.

Looking at this discussion, I think it probably does make more sense just to make our test suite stop outputting to stderr, and send everything to stdout. It wouldn't be very much effort to do so. I'm not really sold on the detailed interface, but that's perhaps beside the point.