Mysterious hang when using `tasty` with `hedgehog` and `IO`

[newhoggy]

When using tasty to run a hedgehog property that does simple IO (for example reading a file), the process can occasionally hang indefinitely.

The code for reproducing the hang can be found here: https://github.com/newhoggy/tasty-hang

The reproducer contains three executables:

• tasty-hang-bad - This executable uses tasty to invoke a hedgehog property that has withTests 1 and no generators, which effectively makes it a unit test. The test reads a small file. This can hang when run often enough.
• tasty-hang-good - This executable uses hunit instead of hedgehog to read a small file. This has not been observed to hang.
• tasty-hang-none - This executable invokes hedgehog directly form IO without using tasty at all. This has not been observed to hang.

I am running on Linux on WSL2 on Windows. The CPU has 32 cores.

To reproduce, I create a script file like this:

((date >&2; for x in {0..99999}; do echo "== $x =="; echo "== $x ==" >&2; tasty-hang-none; done) > ../stdout-1.log 2> ../stderr-1.log)
((date >&2; for x in {0..99999}; do echo "== $x =="; echo "== $x ==" >&2; tasty-hang-none; done) > ../stdout-2.log 2> ../stderr-2.log)
((date >&2; for x in {0..99999}; do echo "== $x =="; echo "== $x ==" >&2; tasty-hang-none; done) > ../stdout-3.log 2> ../stderr-3.log)
((date >&2; for x in {0..99999}; do echo "== $x =="; echo "== $x ==" >&2; tasty-hang-none; done) > ../stdout-4.log 2> ../stderr-4.log)
((date >&2; for x in {0..99999}; do echo "== $x =="; echo "== $x ==" >&2; tasty-hang-none; done) > ../stdout-5.log 2> ../stderr-5.log)
((date >&2; for x in {0..99999}; do echo "== $x =="; echo "== $x ==" >&2; tasty-hang-none; done) > ../stdout-6.log 2> ../stderr-6.log)
((date >&2; for x in {0..99999}; do echo "== $x =="; echo "== $x ==" >&2; tasty-hang-none; done) > ../stdout-7.log 2> ../stderr-7.log)
((date >&2; for x in {0..99999}; do echo "== $x =="; echo "== $x ==" >&2; tasty-hang-none; done) > ../stdout-8.log 2> ../stderr-8.log)

Then I run each loop concurrently like this:

cat script.sh | parallel

Then, in another terminal, I watch the progress of the run like this:

watch ls -la stdout-*.log

If any of the log files stop growing before the others, the associate process has hung.

This issue has been raised in with tasty as well: UnkindPartition/tasty#449

[moodmosaic]

This looks like RTS worker thread pool exhaustion by the integration between the two libraries (hedgehog and tasty via tasty-hedgehog). My gut says this is not a bug in hedgehog and at the same time not a bug in tasty.

[moodmosaic]

Looking at Test.Tasty.Hedgehog, the testProperty provider wraps a Hedgehog.Property inside a Tasty TestTree. This internally uses Tasty's singleTest to run the property, which perhaps spawns threads.

[moodmosaic]

@newhoggy have you tried using sequential or --jobs 1?

[newhoggy]

I have evidence now that check can hang on entry.

Please refer to this reproducer project: https://github.com/newhoggy/tasty-hang

In that project, there is one executable called tasty-hang-bad-bracketed.

It is like tasty-hang except it is instrumented with some counters which measure the four relevant points surrounding the call to check:

      testCaseInfo "t1" $ do
        incCounter tvOuterEnter
        void . H.check . H.withTests 1 . H.withShrinks 0 . H.property $ do
          liftIO $ incCounter tvInnerEnter
          void . H.evalIO $ void $ BS.readFile "README.md"
          liftIO $ incCounter tvInnerExit
        incCounter tvOuterExit

I compile the project using ghc-9.6.7 and then run this:

cat tasty-hang-bad-bracketed.sh | parallel

This creates 8 concurrent loops which each executes the tasty-hang-bad-bracketed executable 999999 times. This is necessary in order to trigger the hang because it is exceedingly rare.

As it runs, I wait for a hang by watching the log files with this:

watch ls -la stdout-*.log stderr-*.log

A hang can be identified when one of the stdout files stops growing like this (I annotated manually with <---:

-rw-rw-r-- 1 jky jky   669411 Jul 18 00:24 stderr-1.log
-rw-rw-r-- 1 jky jky   672371 Jul 18 00:24 stderr-2.log
-rw-rw-r-- 1 jky jky   552457 Jul 18 00:24 stderr-3.log
-rw-rw-r-- 1 jky jky   671331 Jul 18 00:24 stderr-4.log
-rw-rw-r-- 1 jky jky   671411 Jul 18 00:24 stderr-5.log
-rw-rw-r-- 1 jky jky   425749 Jul 18 00:24 stderr-6.log
-rw-rw-r-- 1 jky jky   360246 Jul 18 00:24 stderr-7.log
-rw-rw-r-- 1 jky jky   308723 Jul 18 00:24 stderr-8.log
-rw-rw-r-- 1 jky jky 76480994 Jul 18 00:24 stdout-1.log
-rw-rw-r-- 1 jky jky 76826483 Jul 18 00:24 stdout-2.log
-rw-rw-r-- 1 jky jky 61778119 Jul 18 00:21 stdout-3.log <---
-rw-rw-r-- 1 jky jky 76701610 Jul 18 00:24 stdout-4.log
-rw-rw-r-- 1 jky jky 76710866 Jul 18 00:24 stdout-5.log
-rw-rw-r-- 1 jky jky 45843672 Jul 18 00:18 stdout-6.log <---
-rw-rw-r-- 1 jky jky 37639201 Jul 18 00:17 stdout-7.log <---
-rw-rw-r-- 1 jky jky 31187858 Jul 18 00:15 stdout-8.log <---

When there is no hang, the tail of the generated stderr-*.log files looks something like this:

== 3791 ==
Stats: outer.enter=170 outer.exit=170 inner.enter=170 inner.exit=170
== 3792 ==
Stats: outer.enter=170 outer.exit=170 inner.enter=170 inner.exit=170
== 3793 ==
Stats: outer.enter=170 outer.exit=170 inner.enter=170 inner.exit=170

When there is a hang, the tail of the generated stderr-*.log files looks something like this:

Stats: outer.enter=170 outer.exit=164 inner.enter=164 inner.exit=164
Stats: outer.enter=170 outer.exit=164 inner.enter=164 inner.exit=164
Stats: outer.enter=170 outer.exit=164 inner.enter=164 inner.exit=164
Stats: outer.enter=170 outer.exit=164 inner.enter=164 inner.exit=164
Stats: outer.enter=170 outer.exit=164 inner.enter=164 inner.exit=164
Stats: outer.enter=170 outer.exit=164 inner.enter=164 inner.exit=164

In the hanging output, it shows that the counter just before entering the check call ticked 170 times.

But the enter counter in test code within the check call only ticked 164 times which shows the test call was never called.

In other words the check hung before it could call the test code, and are 6 such hangs when the process hangs.

I think this points to tasty not being responsible for the hang even though its use makes hangs more likely.

[newhoggy]

We're suspecting that the region processing code might have something to do with it. Could we get a version of check that skips that code included in hedgehog?

[newhoggy]

I can confirm the hang has nothing to do with the regions.

It's even weirder than that: https://www.youtube.com/watch?v=2qHRiZ7YzNM

The code for reproducing the hang and copy no-hang can be found in this branch: https://github.com/newhoggy/tasty-hang/tree/newhoggy/no-regions