Exception: "makeOperations: impossible." sometimes thrown

[akegalj]

In this example https://github.com/input-output-hk/cardano-sl/blob/akegalj/co-412/quickcheck-state-machine-error/wallet-new/test/state-machine/Spec.hs :

tests :: Spec
tests =
    describe "Tests" $ parallel $ do
        before (liftIO $ F.openFile "bla" F.WriteMode) $ after (liftIO . F.hClose) $
            describe "IO" $ do
                it "expected failure" $ withMaxSuccess 100 . prop_test_ok
                it "file handle failure" $ withMaxSuccess 100 . prop_test_fail

------------------------------------------------------------------------

main :: IO ()
main = do
    hspec tests

we open a file and give file handle to the both properties, prop_test_ok and prop_test_fail. prop_test_ok will expectedly fail with :

       Falsifiable (after 1 test):
         PostconditionFailed "BotC" /= Ok

and prop_test_fail will usually fail with:

       Falsifiable (after 2 tests):
         Commands { unCommands = [ Command ResetWalletA (fromList []) ] }
         PostconditionFailed "BotC" /= Ok

but sometimes (if run enough times) will fail with :

       *** Failed! Falsifiable (after 3 tests and 1 shrink): 
       Commands { unCommands = [ Command ResetWalletA (fromList []) ] }
       *** Exception running callback: 
       makeOperations: impossible.
       CallStack (from HasCallStack):
         error, called at src/Test/StateMachine/Types/History.hs:87:20 in quickcheck-state-machine-0.4.2-EkwNGvEAI1QBI8p1gDciRE:Test.StateMachine.Types.History

What seems common is that prop_test_ok doesn't run any shrinking code where prop_test_fail runs shrinking code sometimes (When its not run everything is expected).

Seems like there is a problem with shrinking code at https://hackage.haskell.org/package/quickcheck-state-machine-0.4.2/docs/src/Test.StateMachine.Types.History.html#makeOperations . When error is thrown (I don't know reason yet) - file handle gets closed (probably because error is propagated).

We noticed a problem in a more complicated test which involves talking to the db where test framework started failing with:

       uncaught exception: SQLError
       SQLite3 returned ErrorMisuse while attempting to perform prepare "BEGIN TRANSACTION": bad parameter or other API misuse
       (after 4 tests and 2 shrinks)
         Commands { unCommands = [ Command ResetWalletA (fromList []) ] }

The problem wasn't as obvious as in the smaller example but clues are the same:

• db handle closed in shrinking stage (probably because error was propagated)
• after db got closed shrinking still tried to use semantics but because db handle was closed there was sqlite error msg

I will paste the rest of the code here:

data Action (r :: * -> *)
    = ResetWalletA
    deriving (Show, Generic1, Rank2.Functor, Rank2.Foldable, Rank2.Traversable)

data Response (r :: * -> *)
    = ResetWalletR
    deriving (Show, Generic1, Rank2.Foldable)

------------------------------------------------------------------------

-- Wallet state

data Model (r :: * -> *) = Model
    deriving (Eq, Show, Generic)

deriving instance ToExpr (Model Concrete)

initModel :: Model r
initModel = Model

-- If you need more fine grained distribution, use preconditions
preconditions :: Model Symbolic -> Action Symbolic -> Logic
preconditions _ _      = Top

transitions :: Model r -> Action r -> Response r -> Model r
transitions _ _ _ = Model

postconditions :: Model Concrete -> Action Concrete -> Response Concrete -> Logic
postconditions _ _ _ = Bot

------------------------------------------------------------------------

-- Action generator

generator :: Model Symbolic -> Gen (Action Symbolic)
-- if wallet has not been reset, then we should first reset it!
generator _ = pure ResetWalletA

shrinker :: Action Symbolic -> [Action Symbolic]
shrinker _ = []

-- ------------------------------------------------------------------------
--
semantics :: Handle -> Action Concrete -> IO (Response Concrete)
semantics h cmd = case cmd of
    ResetWalletA -> do
        -- Error seems to be goone if line bellow is removed?
        hPutStrLn h "oooo"
        return ResetWalletR

mock :: Model Symbolic -> Action Symbolic -> GenSym (Response Symbolic)
mock _ _      = pure ResetWalletR

------------------------------------------------------------------------

-- TODO: model invariant?
-- TODO: model distribution?
stateMachine :: Handle -> StateMachine Model Action IO Response
stateMachine h =
    StateMachine
        initModel
        transitions
        preconditions
        postconditions
        Nothing
        generator
        Nothing
        shrinker
        (semantics h)
        mock

sleepSeconds :: MonadIO m => Integer -> m ()
sleepSeconds sec =
    liftIO . delay $ sec * 1000 * 1000
  where
    delay time = do
        let maxWait = min time $ toInteger (maxBound :: Int)
        liftIO $ threadDelay (fromInteger maxWait)
        when (maxWait /= time) $ delay (time - maxWait)

prop_test_ok :: Handle -> Property
prop_test_ok h = monadicIO $ do
    -- artificial delay
    -- it works even with the delay
    liftIO $ sleepSeconds 1
    let cmds = Commands [Command ResetWalletA mempty]
    print $ commandNamesInOrder cmds
    (hist, _, res) <- runCommands sm cmds
    prettyCommands sm hist $
        checkCommandNames cmds (res === Ok)
  where
    sm = stateMachine h

prop_test_fail :: Handle -> Property
prop_test_fail h = forAllCommands sm Nothing $ \cmds -> monadicIO $ do
    print $ commandNamesInOrder cmds
    (hist, _, res) <- runCommands sm cmds
    prettyCommands sm hist $
        checkCommandNames cmds (res === Ok)
  where
    sm = stateMachine h

[akegalj]

ps, it might be not related to file handle at all (the first example) but failure is still unexpected (at least to me)

[stevana]

Can you please check if you can reproduce it with HEAD? I fixed a makeOperations: impossible problem in https://github.com/advancedtelematic/quickcheck-state-machine/commit/fa757ec4f05494c85f4feef1b7630902d9fe48d9 .

[akegalj]

With new version seems like error handling is improved, but file handle still gets closed :

Model

   == ResetWalletA ==> bla: hPutStr: illegal operation (handle is closed) [ 0 ]
    file handle failure FAILED [2]

Failures:

  /home/akegalj/projects/serokell/cardano-sl/wallet-new/test/state-machine/Spec.hs:22:17: 
  1) Tests.IO expected failure
       Falsifiable (after 1 test):
         PostconditionFailed "BotC" /= Ok

  /home/akegalj/projects/serokell/cardano-sl/wallet-new/test/state-machine/Spec.hs:23:17: 
  2) Tests.IO file handle failure
       Falsifiable (after 3 tests and 1 shrink):
         Commands { unCommands = [ Command ResetWalletA (fromList []) ] }
         ExceptionThrown /= Ok

Randomized with seed 1787723843

Finished in 1.0197 seconds
2 examples, 2 failures
*** Exception: ExitFailure 1

it is obvious now what is the underlying problem - but it is still unexpected that file handle gets closed, right?

[stevana]

I'm never really understood hspec, but could it be that after is called after the first test finishes, closing the handle, causing the second test to fail? Perhaps try without parallelor using two different files for the two tests?

[akegalj]

At first it seemed like a good idea (I totally forgot we have added parallel there - good catch) but when I:

• removed parallel
• instead of before f1 $ after f2 I added explicit bracket: around $ bracket f1 f2
• removed second spec item which was suspicius on doing the problem
• instead of running single spec item multiple times with withMaxSuccess 100 we are running it only once (using once)
• increased minimum commands generated of forAllCommands sm (just 10) to 10 (not to trigger test coverage failure)

we have ended up with this https://github.com/input-output-hk/cardano-sl/commit/e42ef40acbb4ffceafc7a3ea5a63b27fdb8d9dbb :

tests :: Spec
tests =
    describe "Tests" $ do
        around (bracket (liftIO $ F.openFile "bla" F.WriteMode) (liftIO . F.hClose)) $
            describe "IO" $ do
                it "file handle failure" $ once . prop_test_fail

In this example I am expecting hspec to run prop_test_fail only once but I am getting:

Tests
  IO
["ResetWalletA","ResetWalletA"]
[]
["ResetWalletA"]
[]

Model

   == ResetWalletA ==> bla: hPutStr: illegal operation (handle is closed) [ 0 ]
    file handle failure FAILED [1]

Failures:

  /home/akegalj/projects/serokell/cardano-sl/wallet-new/test/state-machine/Spec.hs:23:17: 
  1) Tests.IO file handle failure
       Falsifiable (after 1 test and 1 shrink):
         Commands { unCommands = [ Command ResetWalletA (fromList []) ] }
         ExceptionThrown /= Ok

Again it seems that shrinking tried to use semantics after handle got closed.

I am going to rewrite it using tasty to compare the results and report back

[akegalj]

tasty is used in this example https://github.com/input-output-hk/cardano-sl/commit/c3d5db923dca6ec01676d6c50e9708e5c041e38a :

testsTasty :: TestTree
testsTasty = testGroup "Tests tasty"
    [ testGroup "IO"
        [ fileHandle "file handle failure" $ once . prop_test_fail
        ]
    ]
  where
    fileHandle test prop =
      withResource (liftIO $ F.openFile "bla" F.WriteMode) (liftIO . F.hClose)
        (\h -> testProperty test (ioProperty (prop <$> h)))

this is based on an quickcheck-state-machine example TicketDispenser. Handle is not closed using this implementation, but quickcheck shrinking was also not triggered even once. I believe problem might be in ioProperty which dissables shrinking of generated commands (at least this is my understanding) https://hackage.haskell.org/package/QuickCheck-2.12.6.1/docs/Test-QuickCheck.html#v:ioProperty:

any random values generated inside of the argument to ioProperty will not currently be shrunk. For best results, generate all random values before calling ioProperty, or use idempotentIOProperty if that is safe.

I am going to check can I avoid using ioProperty and that way disabling shrinking in this example. I would expect when shrinking is enabled I will trigger the same problem as with hspec. I am going to try to remove ioProperty to check this hypothesis

[akegalj]

By using idempotentIOProperty instead of ioProperty in this example https://github.com/input-output-hk/cardano-sl/commit/0769300f65966959ef0e868eb7eb5122b0767f60 which apperently caches some IO which is not what we want in general, but it served as a good example to check will somehow handle get closed. Quickcheck started shrinking and handle wasn't closed unnexpectendly - so everything behaved as expected:

...
["ResetWalletA","ResetWalletA","ResetWalletA"]
[]
["ResetWalletA","ResetWalletA"]
[]
["ResetWalletA"]
[]

Model

   == ResetWalletA ==> ResetWalletR [ 0 ]

Model

FAIL
      *** Failed! Falsifiable (after 1 test and 4 shrinks): 
      Commands { unCommands = [ Command ResetWalletA (fromList []) ] }
      PostconditionFailed "BotC" /= Ok
      Use --quickcheck-replay=201112 to reproduce.

This raises suspicion on hspec and functionalities around, before, after which seems like get triggered before shrinking is finished.

Closing this issue as problem doesn't seem related to quickcheck-state-machine internals

EDIT: in fact, idempotentIOProperty might have cached writing to file - so in that case problem might be masked (existing but not showing up)

EDIT2: I am confident problem is in hspec. This example https://github.com/input-output-hk/cardano-sl/commit/5d2edf254d7011f4c1d7b58d686e6c283ffbea8b is using tasty without ioProperty and without idempotentIOProperty and everything works as expected. Shrinking works as expected. Sorry for disturbance and thanks for handholding