tests: Fix Network.Wai.Middleware.LoggingSpec on Windows

[rvl]

Relates to #703.

Overview

  test/unit/Network/Wai/Middleware/LoggingSpec.hs:109:5:
  9) Network.Wai.Middleware.Logging, Logging Middleware, GET, 200, no query
       uncaught exception: IOException of type UserError
       user error (Expected exactly 3 log entries but got 1: [LogObject {loName = "request-0", loMeta = LOMeta {tstamp = 2019-11-05 04:43:05.8652477 UTC, tid = "ThreadId 13863", severity = Info, privacy = Public}, loContent = LogMessage "[GET] /get"}])

  To rerun use: --match "/Network.Wai.Middleware.Logging/Logging Middleware/GET, 200, no query/"

  test/unit/Network/Wai/Middleware/LoggingSpec.hs:117:5:
  10) Network.Wai.Middleware.Logging, Logging Middleware, GET, 200, with query
       uncaught exception: IOException of type UserError
       user error (Expected exactly 3 log entries but got 5: [LogObject {loName = "request-0", loMeta = LOMeta {tstamp = 2019-11-05 04:43:05.8652477 UTC, tid = "ThreadId 13863", severity = Info, privacy = Public}, loContent = LogMessage "200 OK in 0s"},LogObject {loName = "request-0", loMeta = LOMeta {tstamp = 2019-11-05 04:43:05.8652477 UTC, tid = "ThreadId 13863", severity = Debug, privacy = Public}, loContent = LogMessage "14"},LogObject {loName = "request-1", loMeta = LOMeta {tstamp = 2019-11-05 04:43:05.8652477 UTC, tid = "ThreadId 13863", severity = Info, privacy = Public}, loContent = LogMessage "[GET] /get?query=patate"},LogObject {loName = "request-1", loMeta = LOMeta {tstamp = 2019-11-05 04:43:05.8652477 UTC, tid = "ThreadId 13863", severity = Info, privacy = Public}, loContent = LogMessage "200 OK in 0s"},LogObject {loName = "request-1", loMeta = LOMeta {tstamp = 2019-11-05 04:43:05.8652477 UTC, tid = "ThreadId 13863", severity = Debug, privacy = Public}, loContent = LogMessage "14"}])

  To rerun use: --match "/Network.Wai.Middleware.Logging/Logging Middleware/GET, 200, with query/"

  test/unit/Network/Wai/Middleware/LoggingSpec.hs:184:13:
  11) Network.Wai.Middleware.Logging, Logging Middleware, different request ids
       Falsifiable (after 4 tests and 6 shrinks):
         NumberOfRequests 1
       expected: 1
        but got: 48

  To rerun use: --match "/Network.Wai.Middleware.Logging/Logging Middleware/different request ids/"

  test/unit/Network/Wai/Middleware/LoggingSpec.hs:198:13:
  12) Network.Wai.Middleware.Logging, Logging Middleware, correct time measures
       Falsifiable (after 1 test):
         (NumberOfRequests 5,RandomIndex 1)
       expected: 1
        but got: 0

  To rerun use: --match "/Network.Wai.Middleware.Logging/Logging Middleware/correct time measures/"

Randomized with seed 534946986

Finished in 629.7711 seconds
915 examples, 12 failures, 1 pending

C:\Users\win\cw>

• This "fixes" the tests on windows.
• "different request ids" test still fails

Comments

It seems like iohk-monitoring writes its logs asynchronously.
Or there is some other race condition with the TVar containing log messages.

[KtorZ]

Hmmm. This is a threadDelay of 1s inside a property. This will take more than a minute to run :/
Can't we force-stop the monitoring switchboard here to effectively flush the logs? Or, at the very least, only add this on for Windows tests?

[rvl]

I was looking for a way to get iohk-monitoring to flush logs but didn't find anything yet.
Unlike the other tests, in this case, the threadDelay is not even effective, and this test still fails.

[KtorZ]

I see. I'd suggest to not spend too much time on this and a possible remedy for this one might be to disable it on windows. This is testing precise timing and interleaving of log requests.

[rvl]

Yes good idea. I have made this particular spec pending (only on windows), and changed the other threadDelay so that it is only used on Windows.

[KtorZ]

bors r+

[iohk-bors]

Build failed

• buildkite/cardano-wallet

[rvl]

bors r+

(Stack cache issue)

[iohk-bors]

Build succeeded

• buildkite/cardano-wallet