Increase the delay of awaiting in plutus-pab-executables tests

[ghost]

Pre-submit checklist:

• Branch
  • Tests are provided (if possible)
  • Commit sequence broadly makes sense
  • Key commits have useful messages
  • Formatting, PNG optimization, etc. are updated
• PR
  • Self-reviewed the diff
  • Useful pull request description
  • Reference the ADR in the PR and reference the PR in the ADR (if revelant)
  • Reviewer requested

[koslambrou]

BTW, I've also noticed this problem with waitForTxStatusChange. So it will probably be a similar change.

[koslambrou]

My intuition is that it doesn't solve the hidden problem. Considering the fact the following testcase works

  assertEqual "tx output 1 should be tentatively confirmed of depth 1"
              (TentativelyConfirmed 1 TxValid (Spent $ getCardanoTxId tx2))
txOutStatus1'

and that a depth of > 8 means confirmed, and that we wait for at least 8 slots => this should mean that the transaction is definitely confirmed. Maybe there's a slot discrepancy between waitForTxOutStatusChange and waitNSlots.

[ghost]

My hypothesis, based on the hydra error message, was that we don't wait enough and waitForTxOutStatusChange returns one of the status changes but not the latest. TentativelyConfirmed 7 ~> TentativelyConfirmed 8 instead of TentativelyConfirmed 8 ~> Confirmed. That's why I tried to specify the status that we want to be changed from.

Now, I think, maybe we should instead wait for the specified status? Like waitForTxOutStatusChangeTo status and it will wait until the status will be changed to the given status. And we can provide a timeout 10s for example to throw an exception if the desired status wasn't reached. What do you think?

[koslambrou]

I understand the solution you're proposing and it makes sense. However, I still feel like the current test should work. We're calling Simulator.waitNSlots 1 9 times, and a transaction should be confirmed once the transaction is 8 blocks deep. So it doesn't make sense for the test to fail unless there's a problem with the Simulator. I'll also take a look and see what the problem might be.

[ghost]

I have added one more waitNSlots 1 to waitForTxOutStatusChangeTest but waitForTxStatusChangeTest also failed with the similar error as on hydra. Maybe the tests in this test-suite are not isolated and they depend on each other? Maybe the simulator runs things and accumulates the delay?

[ghost]

Now it fails with a plutus-example test's error, nice

[koslambrou]

Just noticed something. When running: cabal test plutus-pab-executables:test:plutus-pab-test-full --test-options="-p \"can wait for tx status change\"" I wouldn't get any test fail (ran it 20 times).

Then, I tried: cabal test plutus-pab-executables:test:plutus-pab-test-full --test-options="-p \"can wait for tx\"" which would match both test cases we're interested in. Then, the can wait for tx status change failed, but not the other one.

So, like you said, the test don't seem isolated.

[ghost]

Hmmm, have you managed to get these results with the latest commit? I have tried many times but seems the adding more slots to await fixed it for me. But it's hard to tell anything with delays...

[koslambrou]

Oh sorry, I tried this on main directly. Adding delays simply hides the underneath problem, no?

[koslambrou]

Running on main with the bash script:

#!/usr/bin/env sh
until ! LANG=C.UTF-8 cabal test plutus-pab-executables:test:plutus-pab-test-full --test-options="-p \"can wait for tx\""; do
echo ...;
done

I'm even getting errors like:

  Plutus.PAB.Core
    Executing contracts.
      can wait for tx status change:        [INFO] W05a87dc: Balancing an unbalanced transaction:
                   Tx:
                     Tx 047d0b8f72d7fa4e91e1092c93509f2347098f948f942226f3ed6a0887120468:
                       {inputs:
                       collateral inputs:
                       outputs:
                         - Value (Map [(,Map [("",100000000)])]) addressed to
                           PubKeyCredential: f6c178746fb2c96caa40f9c1202e11a6f20b261b823bca280425d748 (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:104:21 in main:Plutus.PAB.CoreSpec
        Use -p '/can wait for tx/&&/can wait for tx status change/' to rerun this test only.

I'm sometimes getting the same thing in next-node branch.

[koslambrou]

Ok, I think I found the problem concerning the error:

[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

I noticed that when beLastSyncedBlockNumber is 11, then everything works in the test case. However, sometimes, the value is < 11 (like 10), then the test case fails. After looking at the processMockBlock function, I noticed that then there is no transactions in the block, we don't increment beLastSyncedBlockNumber. So in the call transactionStatus of waitForTxStatusChange, we use beLastSyncedBlockNumber which wasn't updated to the latest slot, so we incorrectly calculate the transaction status. Solution would be to use beCurrentSlot instead and we would need to modify the signature of transactionStatus in order to use Slot instead of BlockNumber, since we can just as well calculate the transaction status using the current slot instead of the current block number.

[koslambrou]

Also, I don't understand why the printed slots in the logging are going until Slot 54 in the next-node branch when in main branch the tests stops (as expected) at Slot 14. 😭

I'm going to look at the error in the main branch: why does the wallet say Insufficient funds

[ghost]

I'm going to look at the error in the main branch: why does the wallet say Insufficient funds

Oh, I had this error but it occurred only once without any idea how to reproduce it.

I noticed that when beLastSyncedBlockNumber is 11, then everything works in the test case. However, sometimes, the value is < 11 (like 10), then the test case fails. After looking at the processMockBlock function, I noticed that then there is no transactions in the block, we don't increment beLastSyncedBlockNumber. So in the call transactionStatus of waitForTxStatusChange, we use beLastSyncedBlockNumber which wasn't updated to the latest slot, so we incorrectly calculate the transaction status. Solution would be to use beCurrentSlot instead and we would need to modify the signature of transactionStatus in order to use Slot instead of BlockNumber, since we can just as well calculate the transaction status using the current slot instead of the current block number.

Wow, nice catch! I guess I'm not that familiar with the simulator yet and haven't looked there. I will take a look!

[ghost]

So in the call transactionStatus of waitForTxStatusChange, we use beLastSyncedBlockNumber which wasn't updated to the latest slot, so we incorrectly calculate the transaction status.

Or just increment the beLastSyncedBlockNumber if null transactions? :) or it's incorrect and that's the point, that the last synced block is a non-empty block?

UPD. Interesting, by incrementing the beLastSyncedBlockNumber the failure of the test became consistent.

FAIL
        Exception: OtherError "tx output 2 should be tentatively confirmed of depth 2 Expected: TentativelyConfirmed (Depth {unDepth = 2}) TxValid Unspent Actual: Committed TxValid Unspent"
        CallStack (from HasCallStack):
          error, called at test/full/Plutus/PAB/CoreSpec.hs:104:21 in main:Plutus.PAB.CoreSpec
        Use -p '/can wait for tx/&&/can wait for tx output status change/' to rerun this test only.

[koslambrou]

Right! That's probably because of the fact that slots go by too fast (see comment above)

[ghost]

@koslambrou hmmm, I have changed waitForTxStatusChange and waitForTxOutStatusChange to use the beCurrentSlot instead of beLastSyncedBlockNumber, and pass it to transactionOutputStatus which resulted in an another stable error:

        Exception: OtherError "tx output 1 should be tentatively confirmed of depth 1 Expected: TentativelyConfirmed (Depth {unDepth = 1}) TxValid Unspent Actual: Committed TxValid Unspent"
        CallStack (from HasCallStack):
          error, called at test/full/Plutus/PAB/CoreSpec.hs:104:21 in main:Plutus.PAB.CoreSpec
        Use -p '/can wait for tx/&&/can wait for tx output status change/' to rerun this test only.

Please note, that this time the error happens a bit earlier, on tx output 1 should be tentatively confirmed of depth 1 check.

Is it correct to compare currentSlot with an added block number in transactionStatus?

UPD. Looking at transactionStatus I see

      isCommitted addedInBlock = currentBlock > addedInBlock + fromIntegral chainConstant

Does it mean that by using currentSlot here we go too fast and get the confirmation status right away? Skipping the TentativelyConfirmed step.

Maybe, if we try to rely on the counter from another thread, it's hard to predict if it will be good enough in sync with our expectation in the test? We can rely on it only if it happens locally in the same thread with test.

[koslambrou]

Does it mean that by using currentSlot here we go too fast and get the confirmation status right away? Skipping the TentativelyConfirmed step.

That's exactly what I was going to say. Maybe try to fix this? beCurrentSlot should not go that fast. It only does this on next-node, not on main.

Maybe, if we try to rely on the counter from another thread, it's hard to predict if it will be good enough in sync with our expectation in the test? We can rely on it only if it happens locally in the same thread with test.

What do you mean exactly by "counter from another thread".

[ghost]

What do you mean exactly by "counter from another thread".

Sorry, bad wording I suppose. I meant the interaction with the states between threads in general.

That's exactly what I was going to say. Maybe try to fix this? beCurrentSlot should not go that fast. It only does this on next-node, not on main.

That's interesting, I will take a look.

[ghost]

@koslambrou Yeah, beCurrentSlot was too fast.

I checked how we use the processMockBlock in the Simulator. Turned out we use it in makeBlock via handleChainControl where wait with delayThread using scSlotLength which is in Millisecond. Setting the default option 1000 makes the slot behave normally.

UPD. I suppose we want the scSlotLength to be 1 here to have fast tests (added in c5083fc and worked fine)? Maybe something is unsynced? And doesn't use the scSlotLength. Or the delay is too little for STM to communicate between threads. And one of threads just goes too fast. Then the question why it worked fine before. 🤔

[koslambrou]

Still failing locally when running the tests in a loop. The slots still advance too quickly.

[ghost]

@koslambrou could you check please that the branch is up to date? I force-pushed again, so maybe the local branch was not updated. I had the script running for 20 mins without failures...

[koslambrou]

@ak3n You're right :| Forgot to git pull.

Yep the slots work. However, each new slot logs every 1 second. Can you make this so faster? Like 1 slot every 1 ms so that tests can go faster?

[ghost]

Yeah, figuring out why it's so slow now.

Also I think I found how to reproduce the Insufficient funds error. Removing (commenting) the Core.waitUntilSlot 1 line in mkSimulatorHandlers's onStartup helps to make it fail on regular basis.

[koslambrou]

Also I think I found how to reproduce the Insufficient funds error. Removing (commenting) the Core.waitUntilSlot 1 line in mkSimulatorHandlers's onStartup helps to make it fail on regular basis.

Nice find!

[koslambrou]

Remove?

[koslambrou]

Delete

[koslambrou]

RTD is broken in next-node, but fixed in main. I'm getting the fix in next-node in #609

[ghost]

Yep, saw your PR, thanks for this!