Assertions fail with `RefException` messages when using `tasty-1.5.4.0`

[jorisdral]

Updating the index-state brought version 1.5.4.0 into scope. If we use that tasty version with lsm-tree in debug mode (see cabal.project.debug), our tests non-deterministically fail with "Reference is never released" assertion errors. For example:

Example

❯ cabal run lsm-tree-test --constraint="tasty==1.5.4" -- --quickcheck-shrinks=0  -p '/Test.Database.LSMTree.Class.Real/' 2>&1 | tee test.log
lsm-tree
  Test.Database.LSMTree.Class
    Real
      lookup-insert:               OK (2.12s)
        +++ OK, passed 100 tests.
      lookup-insert-else:          OK (2.09s)
        +++ OK, passed 100 tests.
      lookup-insert-blob:          OK (1.86s)
        +++ OK, passed 100 tests.
      lookup-delete:               OK (1.96s)
        +++ OK, passed 100 tests.
      lookup-delete-else:          OK (2.44s)
        +++ OK, passed 100 tests.
      insert-insert:               OK (1.98s)
        +++ OK, passed 100 tests.
      insert-insert-blob:          OK (1.98s)
        +++ OK, passed 100 tests.
      insert-commutes:             OK (2.31s)
        +++ OK, passed 100 tests; 9 discarded.
      insert-commutes-blob:        OK (1.87s)
        +++ OK, passed 100 tests; 8 discarded.
      invalidated-blob-references: OK (2.32s)
        +++ OK, passed 100 tests:
        61% blob reference invalidated
        39% blob reference valid
      dup-insert-insert:           OK (1.86s)
        +++ OK, passed 100 tests.
      dup-insert-comm:             OK (1.98s)
        +++ OK, passed 100 tests; 3 discarded.
      dup-nochanges:               OK (2.68s)
        +++ OK, passed 100 tests.
      lookupRange-like-lookups:    OK (2.26s)
        +++ OK, passed 100 tests.
      lookupRange-insert:          OK (2.13s)
        +++ OK, passed 100 tests.
      readCursor-sorted:           OK (1.74s)
        +++ OK, passed 100 tests.
      readCursor-num-results:      OK (1.89s)
        +++ OK, passed 100 tests.
      readCursor-insert:           OK (1.76s)
        +++ OK, passed 100 tests.
      readCursor-delete:           OK (1.59s)
        +++ OK, passed 100 tests.
      readCursor-delete-else:      OK (2.23s)
        +++ OK, passed 100 tests.
      readCursor-stable-view:      FAIL (0.30s)
        *** Failed! (after 21 tests):
        Exception:
          Reference is never released: RefId 73
          Allocation site: CallStack (from HasCallStack):
            newRefWithTracker, called at src-control/Control/RefCount.hs:325:5 in lsm-tree-1.0.0.2-inplace-control:Control.RefCount
            dupRef, called at src-core/Database/LSMTree/Internal/MergingRun.hs:290:47 in lsm-tree-1.0.0.2-inplace-core:Database.LSMTree.Internal.MergingRun
        TableConfig {confMergePolicy = LazyLevelling, confMergeSchedule = Incremental, confSizeRatio = Four, confWriteBufferAlloc = AllocNumEntries 2, confBloomFilterAlloc = AllocFixed 10.0, confFencePointerIndex = OrdinaryIndex, confDiskCachePolicy = DiskCacheNone, confMergeBatchSize = MergeBatchSize 3}
        [(33647,Insert (Value "\209JySR/H\v\133Y9\176d\200\159") (Just "\ENQ\204\157\ETX")),(22126,Upsert (Value "\129\150d\a")),(34532,Upsert (Value "1l\214\&8lH\SO\211\191\156\220")),(21443,Insert (Value "$\DC4") (Just "\144z\255\163\197\241I\"j\131\185{\179a#")),(32048,Insert (Value "\ESC\ENQ\170\184\202\153\183\152i%X\187M") (Just "\211\132A\206")),(1757,Insert (Value "\DEL\255\FS ") (Just "\180q\163\140~L\206\168\NUL\NAK&\DEL\236\233")),(41817,Delete),(2379,Upsert (Value "\DLEf\193\200\&5\193u\242")),(8197,Delete),(26279,Insert (Value "7s\a\162&") (Just "r;\b")),(37064,Delete),(58287,Insert (Value "N\186\EM\149y\190\DEL\187\150\250\206") Nothing),(9626,Insert (Value "\169\DC1\249\129\180\&4\183as\186i5i") (Just "")),(42391,Upsert (Value "W\213\ENQ#\217$\188"))]
        Just 64819
        <infinite list>
        [(63804,Insert (Value "p") Nothing),(15887,Insert (Value "\208\NAKR\NUL\146\&7Av\155\186d:\236\245\247\218") (Just "=\130G=C1e\130<\198[\251\229")),(8338,Insert (Value "L\140\224\221\200\209C,!\156\131\ETX\160G\176t") Nothing),(24273,Delete),(34667,Insert (Value "n~\248\a5M\143dSa") Nothing),(24532,Insert (Value "(\SOH:)\ETBL\187\158)\244iF\NAK\159\140K") (Just ":\STX76j\194\219\246\192E\224\210;\150"))]
        Use --quickcheck-replay="(SMGen 9390145442189564736 16876747880694427441,20)" to reproduce.
        Use -p '/Test.Database.LSMTree.Class.Real/&&/readCursor-stable-view/' to rerun this test only.
      readCursor-offset:           OK (1.66s)
        +++ OK, passed 100 tests.
      snapshot-nochanges:          OK (3.07s)
        +++ OK, passed 100 tests.
      snapshot-nochanges2:         OK (3.06s)
        +++ OK, passed 100 tests.
      lookup-mupsert:              OK (1.26s)
        +++ OK, passed 100 tests.
      union:                       OK (1.95s)
        +++ OK, passed 100 tests.

1 out of 26 tests failed (7.65s)

Looking at the tasty-1.5.4 changelog, the only thing that jumps out at me is that it seems some things have changed with respect to how tests are run concurrently. I have no working hypothesis on how that would cause the reference assertions to start failing.

Originally posted by @jorisdral in #843 (comment)

[jorisdral]

It is also unclear whether this is a true bug in lsm-tree or a bug in the reference checking mechanism. And we should also make sure to verify that it is indeed tasty-1.5.4.0 that is problematic, and that it is not a red herring. So far I checked this by running the tests with tasty-1.5.3.0 (no problems) and then separately running the tests with tasty-1.5.4.0 (errors).

[jasagredo]

tasty-1.5.4-output.log

Tests failing with 1.5.4. They pass with 1.5.3.