plutus-pab-test-full can non-deterministically break.

[zmrocze]

Summary

One test from plutus-pab-test-full namely can wait for tx output status change fails in my branch about once every 10th test. I reproduced the fail in the main branch by running tests in a loop.

Subjectively it feels like the test fails less often in main and also i could only reproduce it with the error in Actual result. But on my branch that forks from next-node I could also get the error shown below (1).
I definitely could have introduced an additional bug.

Error (1)

[INFO] W79f9602: Signing tx: 9056fcfce1f248c624d91e6e135c293545375dbe5b0936be0f910be243f96786
[INFO] W79f9602: Submitting tx: 9056fcfce1f248c624d91e6e135c293545375dbe5b0936be0f910be243f96786
FAIL
        Exception: OtherError "tx output 1 should be tentatively confirmed of depth 1 Expected: TentativelyConfirmed (Depth {unDepth = 1}) TxValid (Spent 9056fcfce1f248c624d91e6e135c293545375dbe5b0936be0f910be243f96786) Actual: TentativelyConfirmed (Depth {unDepth = 1}) TxValid Unspent"
        CallStack (from HasCallStack):
          error, called at test/full/Plutus/PAB/CoreSpec.hs:103:21 in main:Plutus.PAB.CoreSpec

Reproduced on next-node also getting a new error message:

FAIL
        Exception: OtherError "tx output 1 should be committed Expected: Committed TxValid (Spent 04fd3feec8742efd0504593e9a7a5d795a16bdbba9ee803a6bd5f582f25a60ef) Actual: TentativelyConfirmed (Depth {unDepth = 8}) TxValid (Spent 04fd3feec8742efd0504593e9a7a5d795a16bdbba9ee803a6bd5f582f25a60ef)"
        CallStack (from HasCallStack):
          error, called at test/full/Plutus/PAB/CoreSpec.hs:103:21 in main:Plutus.PAB.CoreSpec

Steps to reproduce the behavior

1. go to main, next-node or Update tx with missing fields. #468
2. run LANG=C.UTF-8 cabal run plutus-pab-test-full -- -p '/can wait for tx output status change/'
3. Observe the test either failing or succeding. Can run

until ! LANG=C.UTF-8 cabal run plutus-pab-test-full -- -p '/can wait for tx output status change/'; do
echo ...;
done

to run test in a loop until fails.

Actual Result

all tests
  Plutus.PAB.Core
    Executing contracts.
      can wait for tx output status change: [INFO] Slot 0: TxnValidate 08111487e032e647e23e6e6866665ab726a4c92532e9589f9e670f2585e35807
[INFO] W[2]: Balancing an unbalanced transaction:
               Tx:
                 Tx 77a99befc425c61ae28f56e90f5673e25c8ced285117a3a7611d54fb4624b971:
                   {inputs:
                   collateral inputs:
                   outputs:
                     - Value (Map [(,Map [("",10000000000)])]) addressed to
                       PubKeyCredential: c9602425ed6b20a59e95a815c5d401014d02fa18ecc16c9a0b420d69 (no staking credential)
                   mint: Value (Map [])
                   fee: Value (Map [])
                   mps:
                   signatures:
                   validity range: Interval {ivFrom = LowerBound NegInf True, ivTo = UpperBound PosInf True}
                   data:}
               Requires signatures:
               Utxo index:
               Validity range:
                 (-∞ , +∞)
[INFO] W[2]: Finished balancing:
               Tx 7cf50ed34f7e9e6155a0e6e22502db26f0efd2fe4adbc03f45ecf7d9c6c2d5c8:
                 {inputs:
                    - 08111487e032e647e23e6e6866665ab726a4c92532e9589f9e670f2585e35807!20

                    - 08111487e032e647e23e6e6866665ab726a4c92532e9589f9e670f2585e35807!21

                 collateral inputs:
                   - 08111487e032e647e23e6e6866665ab726a4c92532e9589f9e670f2585e35807!20

                 outputs:
                   - Value (Map [(,Map [("",10000000000)])]) addressed to
                     PubKeyCredential: c9602425ed6b20a59e95a815c5d401014d02fa18ecc16c9a0b420d69 (no staking credential)
                   - Value (Map [(,Map [("",9999822047)])]) addressed to
                     PubKeyCredential: 80a4f45b56b88d1139da23bc4c3c75ec6d32943c087f250b86193ca7 (no staking credential)
                 mint: Value (Map [])
                 fee: Value (Map [(,Map [("",177953)])])
                 mps:
                 signatures:
                 validity range: Interval {ivFrom = LowerBound NegInf True, ivTo = UpperBound PosInf True}
                 data:}
[INFO] W[2]: Signing tx: 7cf50ed34f7e9e6155a0e6e22502db26f0efd2fe4adbc03f45ecf7d9c6c2d5c8
[INFO] W[2]: Submitting tx: 7cf50ed34f7e9e6155a0e6e22502db26f0efd2fe4adbc03f45ecf7d9c6c2d5c8
[INFO] W[2]: Balancing an unbalanced transaction:
               Tx:
                 Tx fc98bb57fca13880e007e9be0d7e966b55906885d4946d85cbc61631542043d0:
                   {inputs:
                   collateral inputs:
                   outputs:
                     - Value (Map [(,Map [("",10000000000)])]) addressed to
                       PubKeyCredential: 17e66b3611d2ce9806538871f85055074f85580e67d8901aa36fa06e (no staking credential)
                   mint: Value (Map [])
                   fee: Value (Map [])
                   mps:
                   signatures:
                   validity range: Interval {ivFrom = LowerBound NegInf True, ivTo = UpperBound PosInf True}
                   data:}
               Requires signatures:
               Utxo index:
               Validity range:
                 (-∞ , +∞)
[INFO] W[2]: Finished balancing:
               Tx 3f1f07ee432214393df51fbbdc98fb6b59259b490c6be776ef3b536356f2f0c2:
                 {inputs:
                    - 08111487e032e647e23e6e6866665ab726a4c92532e9589f9e670f2585e35807!20

                    - 08111487e032e647e23e6e6866665ab726a4c92532e9589f9e670f2585e35807!21

                 collateral inputs:
                   - 08111487e032e647e23e6e6866665ab726a4c92532e9589f9e670f2585e35807!20

                 outputs:
                   - Value (Map [(,Map [("",10000000000)])]) addressed to
                     PubKeyCredential: 17e66b3611d2ce9806538871f85055074f85580e67d8901aa36fa06e (no staking credential)
                   - Value (Map [(,Map [("",9999822047)])]) addressed to
                     PubKeyCredential: 80a4f45b56b88d1139da23bc4c3c75ec6d32943c087f250b86193ca7 (no staking credential)
                 mint: Value (Map [])
                 fee: Value (Map [(,Map [("",177953)])])
                 mps:
                 signatures:
                 validity range: Interval {ivFrom = LowerBound NegInf True, ivTo = UpperBound PosInf True}
                 data:}
[INFO] W[2]: Signing tx: 3f1f07ee432214393df51fbbdc98fb6b59259b490c6be776ef3b536356f2f0c2
[INFO] W[2]: Submitting tx: 3f1f07ee432214393df51fbbdc98fb6b59259b490c6be776ef3b536356f2f0c2
[INFO] Slot 4: TxnValidate 3f1f07ee432214393df51fbbdc98fb6b59259b490c6be776ef3b536356f2f0c2
[WARNING] Slot 4: TxnValidationFail Phase1 7cf50ed34f7e9e6155a0e6e22502db26f0efd2fe4adbc03f45ecf7d9c6c2d5c8: TxOutRefNotFound (TxOutRef {txOutRefId = 08111487e032e647e23e6e6866665ab726a4c92532e9589f9e670f2585e35807, txOutRefIdx = 20})
[INFO] W6fa9714: Balancing an unbalanced transaction:
                   Tx:
                     Tx d123f58279ff18c8df16d37e9fe87d8cfea047201aa2bcb6c1aed34c448a484d:
                       {inputs:
                       collateral inputs:
                       outputs:
                         - Value (Map [(,Map [("",100000000)])]) addressed to
                           PubKeyCredential: 17e66b3611d2ce9806538871f85055074f85580e67d8901aa36fa06e (no staking credential)
                       mint: Value (Map [])
                       fee: Value (Map [])
                       mps:
                       signatures:
                       validity range: Interval {ivFrom = LowerBound NegInf True, ivTo = UpperBound PosInf True}
                       data:}
                   Requires signatures:
                   Utxo index:
                   Validity range:
                     (-∞ , +∞)
FAIL
        Exception: WalletError (InsufficientFunds "Total: Value (Map []) expected: Value (Map [(,Map [(\"\",100300000)])])")
        CallStack (from HasCallStack):
          error, called at test/full/Plutus/PAB/CoreSpec.hs:103:21 in main:Plutus.PAB.CoreSpec

1 out of 1 tests failed (0.05s)

Expected Result

No errors observed.

Describe the approach you would take to fix this

I will try reproduce on next-node.

I will look for a bug that I might have introduced, but also let me know if some nondeterminism is expected here and in what form.

System info

plutus-apps:

• main 530c68c
• next-node c2b3109
• Update tx with missing fields. #468 f61e2d7

[zmrocze]

this is much more seldom on main compared to next-node