Using hspec via cabal test --show-details=streaming truncates output

[RyanGlScott]

When running an hspec test suite via cabal test --show-details=streaming (an option which was added to Cabal in version 1.20) on cmd.exe or PowerShell on Windows, it only outputs some of the tests. As an example, here is what happens when attempting to run the test suite from base-orphans on PowerShell:

Running 1 test suites...
Test suite spec: RUNNING...

Control.Applicative.Orphans
  Monoid (Const a b)
    mempty returns an empty const
    mappends const part
  Monad (WrappedMonad m)
    allows to use a Monad interface in a WrappedMonad
Control.Exception.Orphans
  ErrorCall
Test suite spec: PASS
    has an Eq instance
Test suite logged to: dist\test\base-orphans-0.1.0-spec.log
    has an Ord instance
Data.Bits.Orphans
  Bits Bool instance
1 of 1 test suites (1 of 1 test cases) passed.
    allows bitwise operations on Bools
Data.Foldable.Orphans
  Either Foldable Instance

This doesn't happen on MSYS or Cygwin, curiously enough. For comparison, here is what the test suite should look like:

Test suite spec: RUNNING...

Control.Applicative.Orphans
  Monoid (Const a b)
    mempty returns an empty const
    mappends const part
  Monad (WrappedMonad m)
    allows to use a Monad interface in a WrappedMonad
Control.Exception.Orphans
  ErrorCall
    has an Eq instance
    has an Ord instance
Data.Bits.Orphans
  Bits Bool instance
    allows bitwise operations on Bools
Data.Foldable.Orphans
  Either Foldable Instance
    foldMap returns mempty for a Left value
    foldMap returns the result of the function on the Right value
    foldr returns the accumulator for a Left value
    foldr returns the result of the function on the Right value and accumulator
  (,) Foldable Instance
    foldMap returns the result of the function applied to the second element
    foldr returns the result of the function on the second element of the tuple                         and accumulator
  Const m Foldable Instance
    foldMap always returns mempty
    foldr applies the function to the accumulator and mempty
Data.Monoid.Orphans
  Num (Sum a) instance
    allows a Sum value to be created from a number
  Num (Product a) instance
    allows a Product value to be created from a number
Data.Traversable.Orphans
  Either Traversable Instance
    traverses a Left value
    traverses a Right Value
  (,) a Traversable Instance
    traverses a (,) a value
  Const m Traversable Instance
    traverses a Const a value
Data.Version.Orphans
  Data Version instance
    allows obtaining a Version constructor
  IsList Version instance
    creates a Version from an Int list
Foreign.Storable.Orphans
  Storable Complex instance
    has twice the sizeOf its realPart
    has the alignment of its realPart
  Storable Ratio instance
    has twice the sizeOf its parameterized type
    has the alignment of its parameterized type

Finished in 0.0020 seconds
26 examples, 0 failures
Test suite spec: PASS
Test suite logged to: dist\test\base-orphans-0.1.0-spec.log
1 of 1 test suites (1 of 1 test cases) passed.

I'm tempted to think that line buffering is to blame here, as tasty once had a similar problem. I'm not familiar with hspec's internals, though, so I can't say for sure.

[sol]

@RyanGlScott Thanks for reporting. I don't have access to a Windows machine, so I can't debug this.

One thing I'm puzzled is whether this happens if you run the tests standalone, e.g.:

cabal configure --enable-tests && cabal build && ./dist/build/spec/spec

If no, I'm inclined to consider this a cabal-install bug.

[sol]

We don't mess with the buffering. So if the handle is stdout it should be LineBuffering. We may set the buffering mode and/or flush the handle if that helps. But I would rely on somebody else to investigate.

[sol]

@RyanGlScott In case you have the capacity to look into this, I pushed some code that may help to verify that it's due to a buffering issue, see #233.

[RyanGlScott]

Unfortunately, this doesn't seem to happen with .\dist\build\spec\spec alone, and sprinkling hFlush in various parts of the code doesn't change much. What's weird is that this issue does not happen with other testing frameworks (e.g., tasty).

I'm not too familiar with how streaming mode in Cabal works other than the fact that it causes the Test suite logged to: <file>.log message to be printed out in a separate thread.

[sol]

There are two more things I'm puzzled about:

• Does the output get colorized in streaming mode? If yes, does passing --no-color to the spec change anything?
• Does this happen for other Hspec test suites too?

Sent from my iPhone

On 3 May 2015, at 2:01 am, Ryan Scott notifications@github.com wrote:

Unfortunately, this doesn't seem to happen with .\dist\build\spec\spec alone, and sprinkling hFlush in various parts of the code doesn't change much. What's weird is that this issue does not happen with other testing frameworks (e.g., tasty).

I'm not too familiar with how streaming mode in Cabal works other than the fact that it causes the Test suite logged to: .log message to be printed out in a separate thread.

—
Reply to this email directly or view it on GitHub.

[RyanGlScott]

Does the output get colorized in streaming mode? If yes, does passing --no-color to the spec change anything?

That's an interesting question since, as far as I can tell, none of the output gets colorized at all when a test suite is run via cabal test. I can manually pass --test-options="--color" or "--no-color", but that doesn't fix the issue.

(Weirdly enough, cabal test --test-options="--color" isn't colorized, regardless of whether streaming or always is used, and instead prints out ←[0m←[32m mojibake. That's probably a different issue with ansi-terminal or cabal, though.)

Does this happen for other Hspec test suites too?

Yes. I've also had this happen with the base-compat and text-show Hspec test suites.

[sol]

Unless proven otherwise I would not exclude the possibility that this is a cabal-install issue. But I would still love to get to the core of this. Unfortunately I don't have access to a windows system to get a better insight. If anybody can help with this, that would be more than appreciated.

[snoyberg]

I ran into an issue somewhat related to this (though not on Windows). In my case, turning on the multithreaded runtime (i.e. ghc-options: -threaded) for the test suite solve the issue. But this may be completely unrelated to the problem you're having.

[RyanGlScott]

Ah, it looks like I can reproduce this on Linux with the base-orphans test suite as well:

Running 1 test suites...
Test suite spec: RUNNING...

Control.Applicative.Orphans
  Monoid (Const a b)
    mempty returns an empty const
    mappends const part
Test suite spec: PASS
  Monad (WrappedMonad m)
Test suite logged to: dist/test/base-orphans-0.4.1-spec.log
    allows to use a Monad interface in a WrappedMonad
Control.Exception.Orphans
  ErrorCall
1 of 1 test suites (1 of 1 test cases) passed.
    has an Eq instance
    has an Ord instance
Data.Bits.Orphans
  Bits Bool instance
    allows bitwise operations on Bools
Data.Foldable.Orphans
  Either Foldable Instance

When I run the test suite several times in a row with cabal test --show-details=streaming, varying amounts of output are displayed before eventually stopping. I can also confirm that @snoyberg's suggestion of using the -threaded option does fix the issue.

I'll change the title to reflect this.

[peti]

I was wondering whether we should run all test suites in Nix with --show-details=streaming, but now I am a little worried that this might be a bad idea. Has anyone ever made any progress understanding what is happening in those cases @RyanGlScott reported? Does this issue still exist with recent compilers, like GHC 7.10.3?

[snoyberg]

FWIW, in Stack we found the test running code from Cabal too unstable to be used, so instead run the test suites ourselves manually, which also allowed more fine-grained control of output redirection.

[peti]

Interesting ... I never considered that. I guess I sort-of assumed that Cabal would create some magic, special environment for tests to run in, but now that I think about it, that's probably exactly the kind of thing we don't want.

[snoyberg]

IIRC, I found I needed to do two things to get reliable test runs in Stack:

• Make sure the multithreaded runtime was turned on in the program executing the tests
• Call the executables directly

Doing a directly executable run is fairly simple:

• Get the list of tests from the .cabal file
• Find the appropriate paths inside the dist directory
• Run the tests, logging or displaying to stdout as desired, and check ExitFailure afterward

[DaveCTurner]

Note that (following a convention from libc) the default buffering mode for stdout changes depending on whether it's connected to a terminal or a pipe:

http://stackoverflow.com/questions/19520885/haskell-default-io-buffering

This may well explain the difference in behaviour between running a spec directly and running it via a wrapper executable.

OTOH when running a subprocess to completion the parent should really take care to read all the way to EOF even after the child process has exited. My guess would be that cabal is not doing so.

[sol]

This is a Cabal bug.

A workaround is to use direct instead of streaming.

$ cabal test --show-details=direct