Capturing `stdout` in a test makes the testsuite fail non-deterministically

[andreasabel]

I wonder whether there is a way to integrate a test whose stdout I want to capture into a tasty test tree.
The problem is that tests are run concurrently, and other tests also write to stdout, e.g. quickcheck tests report progress.
These printouts can sometimes pollute the captured stdout of the test.

Here is a small reproducer:

import Control.Concurrent (threadDelay)
import Data.Functor
import System.IO.Silently (capture_)
import Test.Tasty
import Test.Tasty.HUnit
import Test.Tasty.QuickCheck

main :: IO ()
main = defaultMain $ testGroup "" $ concat
  [ -- Some quickcheck tests before
    map qc [0..9]
  , -- Some test that captures stdout
    [ testCase "capture_stdout" $ do
        assertEqual "" (unlines strs) =<< do
          capture_ $ printAll strs
    ]
  , -- Some quickcheck tests after
    map qc [10..19]
  ]
  where
    -- Some random quickcheck property.
    qc i = testProperty ("prop_" ++ show i) prop

-- A random property about numbers.
prop :: Double -> Double -> Bool
prop x y = x*x + y*y >= x*y + y*x

-- Some random text.
strs :: [String]
strs = [9,8..0] <&> \ n -> unwords [ show n, "bottles of beer" ]

-- Print the given lines with delay, simulating some work.
printAll :: [String] -> IO ()
printAll = mapM_ $ \ s -> do
  putStrLn s
  threadDelay 50000

The exact details here are not important. What matters is that we have a test that uses capture_ after some quickcheck tests.

For completeness, here is the package.yaml:

name: tasty-capture
version: 0

tests:
  test:
    source-dirs: .
    main: Main.hs

dependencies:
- base
- silently
- tasty
- tasty-hunit
- tasty-quickcheck

and the stack.yaml:

resolver: lts-21.25

A run of stack test should produce this:

...
  prop_8:         OK
    +++ OK, passed 100 tests.
  prop_9:         OK
    +++ OK, passed 100 tests.
  capture_stdout: OK (0.53s)
  prop_10:        OK
    +++ OK, passed 100 tests.
  prop_11:        OK
    +++ OK, passed 100 tests.
...

When running stack test many times, one gets runs that fail because some of the output of the other tests gets captured by capture_.
E.g. I got this:

...
  prop_8:         OK
    +++ OK, passed 100 tests.
  prop_9:         OKFAIL (0.53s)
    Main.hs:16:
    expected: "9 bottles of beer\n8 bottles of beer\n7 bottles of beer\n6 bottles of beer\n5 bottles of beer\n4 bottles of beer\n3 bottles of beer\n2 bottles of beer\n1 bottles of beer\n0 bottles of beer\n"
     but got: "\ESC[m9 bottles of beer\n\ESC[32;22m\n\ESC[m\ESC[37;22m    +++ OK, passed 100 tests.\n\ESC[m  capture_stdout: 8 bottles of beer\n7 bottles of beer\n6 bottles of beer\n5 bottles of beer\n4 bottles of beer\n3 bottles of beer\n2 bottles of beer\n1 bottles of beer\n0 bottles of beer\n"
    Use -p '/capture_stdout/' to rerun this test only.
  prop_10:        OK
    +++ OK, passed 100 tests.
...

What happened here is that capture_ caught some of the tasty (and quickcheck?) output:

\ESC[32;22m\n\ESC[m\ESC[37;22m    +++ OK, passed 100 tests.\n\ESC[m  capture_stdout: 

So basically the test capture_stdout was started before even its heading capture_stdout: was printed.

I tried to use sequentialTestTree but this did not help (at least in the real world example that triggered this MWE).
This still starts tests concurrently, only that each test waits that each previous test has finished. The waiting does not seem to include waiting for the test report to have finished printing.

The only effective workaround I found was to insert some waiting time at the beginning of test capture_stdout, say a threadDelay 500000. This gives the reporter the time to finish its writing to stdout before capture_ becomes active.

The malaise seems to be caused by all threads sharing stdout and there being no way to tell a thread to use a different handle for stdout.
For processes instead of threads this should be possible, in theory.
Can I start some IO () action as a process instead with some redirected stdout? (This would replace capture_.)
I only found forkProcess (from unix) but this does not let me redirect stdout.

CC: @oskeri

[Bodigrim]

Would it help to hFlush more often?

[Bodigrim]

I think the only robust solution is to run tests single-threaded with -j1. Otherwise even if tasty itself applies some hypothetical locks for its own output, nothing prevents you from having two concurrent tests both capturing their stdout. Underlying problem is that indeed silently is not thread-safe.

[LeventErkok]

@andreasabel I just ran into this issue myself; and your solution (of putting a threadDelay) indeed seems to work. (With all the caveats of it of course, like possibly waiting much longer than needed.) Thanks!

Were you able to find some other, perhaps more reliable, solution?

@Bodigrim Given that silently isn't thread-safe, how about adding this sort of a feature straight to tasty itself? Doctest (or doc-spec) can run output producing functions and test-them inline, so surely that technology can be ported to tasty?

I'll file a separate ticket as a request.

[andreasabel]

@LeventErkok

Were you able to find some other, perhaps more reliable, solution?

Unfortunately, no, and I think there is no proper solution, as all threads of a process share the same stdout. One would need to fork an IO () action into a new process, but the forkProcess of unix does not seem to be portable (it is not part of unix-compat and I haven't found a Windows equivalent).

[Bodigrim]

I think the easiest workaround is to check that the actual output String is a subsequence of the expected one, but not necessarily equal to. Admittedly it’s not ideal, but probably gives you 90% of utility.