Exception: "makeOperations: impossible." sometimes thrown
akegalj opened this issue · 7 comments
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 testswe 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
semanticsbut 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 hps, it might be not related to file handle at all (the first example) but failure is still unexpected (at least to me)
Can you please check if you can reproduce it with HEAD? I fixed a makeOperations: impossible problem in fa757ec .
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 1it is obvious now what is the underlying problem - but it is still unexpected that file handle gets closed, right?
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?
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 f2I 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 100we are running it only once (usingonce) - increased minimum commands generated of
forAllCommands sm (just 10)to 10 (not to trigger test coverage failure)
we have ended up with this input-output-hk/cardano-sl@e42ef40 :
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_failIn 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
tasty is used in this example input-output-hk/cardano-sl@c3d5db9 :
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
By using idempotentIOProperty instead of ioProperty in this example input-output-hk/cardano-sl@0769300 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 input-output-hk/cardano-sl@5d2edf2 is using tasty without ioProperty and without idempotentIOProperty and everything works as expected. Shrinking works as expected. Sorry for disturbance and thanks for handholding