Integration Test Failure in pab-executables

[tbidne]

Summary

The integration test as described in plutus-apps/plutus-pab-executables fails. I believe this is the cause of #451.

Steps to reproduce the behavior

Copying these instructions from the README:

1. Build necessary components:

> cabal build plutus-pab-local-cluster

2. Get config data:

Clone https://github.com/input-output-hk/cardano-wallet/ to $DIR and set the
SHELLEY_TEST_DATA environment variable:

export SHELLEY_TEST_DATA=$DIR/lib/shelley/test/data/cardano-node-shelley

3. Run the local cluster:

> cabal exec plutus-pab-local-cluster

4. Wait until the message Starting PAB backend server on port 9080 appears.

5. Run the integration test:

curl -H "Content-Type: application/json" -v \
       -X POST \
       -d '{"caID":{"tag":"IntegrationTest"},"caWallet":{"getWalletId":"2d4cc31a4b3116ab86bfe529d30d9c362acd0b44"}}' \
       localhost:9080/api/contract/activate

Actual Result

Error in logs:

[pab:Info:1684] [2022-05-23 03:18:28.17 UTC] 19a347c2-67ec-428e-86bc-c89935f74203: "Starting integration test"
[pab:Info:1684] [2022-05-23 03:18:28.17 UTC] Initialising contract IntegrationTest with ID 19a347c2-67ec-428e-86bc-c89935f74203
[pab:Info:1684] [2022-05-23 03:18:28.17 UTC] Activated instance 19a347c2-67ec-428e-86bc-c89935f74203 on W2d4cc31
[chain-index:Warning:1701] [2022-05-23 03:18:29.50 UTC] TxOut not found with: bd6cc1f2408bd53fc80df79190c00ef57be60427c92f33b038d8924ce19fe8df!0
[pab:Info:1686] [2022-05-23 03:18:29.51 UTC] 19a347c2-67ec-428e-86bc-c89935f74203: "pubKey contract complete:"
[pab:Info:1686] [2022-05-23 03:18:29.51 UTC] 19a347c2-67ec-428e-86bc-c89935f74203: {
    "txOutRefId": {
        "getTxId": "bd6cc1f2408bd53fc80df79190c00ef57be60427c92f33b038d8924ce19fe8df"
    },
    "txOutRefIdx": 0
}
[pab:Warning:1686] [2022-05-23 03:18:29.51 UTC] 19a347c2-67ec-428e-86bc-c89935f74203: "An error occurred. Integration test failed."
[pab:Warning:1686] [2022-05-23 03:18:29.51 UTC] 19a347c2-67ec-428e-86bc-c89935f74203: {
    "contents": {
        "contents": {
            "txOutRefId": {
                "getTxId": "bd6cc1f2408bd53fc80df79190c00ef57be60427c92f33b038d8924ce19fe8df"
            },
            "txOutRefIdx": 0
        },
        "tag": "TxOutRefNotFound"
    },
    "tag": "ConstraintResolutionContractError"
}

Expected Result

From the README:

A couple of log messages appear, the last one should say something like "Tx
confirmed. Integration test complete."

In particular, this is what successful logs look like:

[pab:Info:1625] [2022-05-23 03:50:41.30 UTC] Activated instance c4ed7636-6005-483e-828e-37afe5f086c3 on W2d4cc31
[pab:Info:1627] [2022-05-23 03:50:42.13 UTC] c4ed7636-6005-483e-828e-37afe5f086c3: "pubKey contract complete:"
[pab:Info:1627] [2022-05-23 03:50:42.13 UTC] c4ed7636-6005-483e-828e-37afe5f086c3: {
    "txOutRefId": {
        "getTxId": "1d7a7908ae2cd7ea68dafa34ae46056e3a04ea5280849a428c23097eaf05252b"
    },
    "txOutRefIdx": 0
}
[pab:Info:1627] [2022-05-23 03:50:42.40 UTC] c4ed7636-6005-483e-828e-37afe5f086c3: "Waiting for tx cfc60a42e6616a720379ce28114a294c2c39ec288920393efa1420223bf47e55 to complete"
[pab:Info:1627] [2022-05-23 03:50:42.69 UTC] c4ed7636-6005-483e-828e-37afe5f086c3: "Tx confirmed. Integration test complete."

Describe the approach you would take to fix this

I performed a bisection and obtained the following results. Unfortunately the tests fail in several different ways depending on the hash, so there are multiple "causes" to look at.

First, the last commit that works for me is 7f543e2. The integration test passes as expected.

1st Error

Starting with 93f6293, I no longer see the success message Integration test complete. Note: I do not see an error, either. Instead, I see continuous logs like:

[chain-index:Info:1646] [2022-05-19 11:31:28.29 UTC] Still in sync. Applied 104 blocks, 8 rollbacks in the last 30s. Current tip is Point(Slot 325, BlockId 76d82f0beba2b799b07b561660fdd23941e41e8b751a872ca8687ced05f97446)

Perhaps it would finish if I waited long enough.

2nd Error

The behavior changes with 63deb7d. Instead of hanging, I see:

[pab:Info:1690] [2022-05-19 22:53:24.05 UTC] Activated instance e8a50837-de4d-4864-8f25-1ac4297f4cee on W2d4cc31
Deserialisation failed. Delete your chain index database and resync.
CallStack (from HasCallStack):
  error, called at src/Plutus/ChainIndex/DbSchema.hs:232:22 in plutus-chain-index-core-0.1.0.0-inplace:Plutus.ChainIndex.DbSchema
[chain-index:Info:1681] [2022-05-19 22:53:44.19 UTC] Still in sync. Applied 95 blocks, 8 rollbacks in the last 30s. Current tip is Point(Slot 326, BlockId 8a0d1a275d46e8a655383752da7e9d936b4119332714803744530af983b9b6d4)

I tried the migrations described in the same README i.e.

cabal exec plutus-pab-examples -- migrate --config plutus-pab.yaml.sample

But I receive the same result.

3rd (Current) Error

Finally, we have the cause of the current issue: ffa0cd4. This leads to the TxOutRefNotFound error.

Is this a bug? Or does the documentation need to be updated? Incidentally, I wonder if the setup for export SHELLEY_TEST_DATA=... should be changed to use plutus-pab/local-cluster/cluster-data/cardano-node-shelley instead of cardano-wallet/.... It's unclear to me why the data dir in this repository is not sufficient (indeed it appears to work, the problems in this issue notwithstanding).

System info

OS: NixOS (nix 2.7.0)
Plutus: main (37c54aa)

[tbidne]

Hi @koslambrou, thanks for working on this! I went to run the the tests after pulling in the latest main, and I still get the same error. However, this may be because I ran the curl command before the chain index was synced. The problem is, my chain index does not appear to sync at all.

Specifically, when I run cabal exec plutus-pab-local-cluster, I see many logs like:

[chain-index:Info:1754] [2022-06-22 11:25:00.38 UTC] Still in sync. Processed 1 blocks, 0 rollbacks in the last 0s. Current tip is Point(Slot 1337, BlockId 2f3ffec5199bc2568ccb67ad02a276e26c0e4fcf96a9a6b8027d76258ad54a3b)

I have left the test running for an hour, and it does not seem to progress past this point. Is this expected, or am I doing something wrong? Thanks!

[koslambrou]

@tbidne You're right, it doesn't work. I'm working on a PR right now which needs the plutus-pab-local-cluster to work, so I'll fix it there.

[tbidne]

Thank you!

[tbidne]

@koslambrou I still see the same issue i.e. endless Still in sync... logs, thus the integration test fails to complete. I see there is ongoing discussion/development regarding a "proper" fix (i.e. #550), so if I should wait until that is resolved then no problem. I just wanted to provide an update.

[koslambrou]

@tbidne Did you pull from main? Just tried it out and it works. Here's the log:

[pab:Info:1746] [2022-07-14 18:32:33.67 UTC] 8ab95710-e00f-4562-8a8e-ad582d6fb299: "Starting integration test"
[pab:Info:1746] [2022-07-14 18:32:33.67 UTC] Initialising contract IntegrationTest with ID 8ab95710-e00f-4562-8a8e-ad582d6fb299
[pab:Info:1746] [2022-07-14 18:32:33.69 UTC] Activated instance 8ab95710-e00f-4562-8a8e-ad582d6fb299 on W2d4cc31
[chain-index:Info:1736] [2022-07-14 18:32:34.74 UTC] Still in sync. Processed 1 blocks, 0 rollbacks in the last 2s. Current tip is Point(Slot 296, BlockId 2817e2dce95cc19dc5ef7df4d662c7e9d917d910f738253b73b026c4caefe9f9)
[...]
[chain-index:Info:1736] [2022-07-14 18:32:36.76 UTC] Still in sync. Processed 1 blocks, 0 rollbacks in the last 0s. Current tip is Point(Slot 301, BlockId 9fcaf44a573133da9d545a3a93fcff4ad6496ed7586dd86bfe970eb82bd071a2)
[pab:Info:1748] [2022-07-14 18:33:36.85 UTC] 8ab95710-e00f-4562-8a8e-ad582d6fb299: "pubKey contract complete:"
[pab:Info:1748] [2022-07-14 18:33:37.51 UTC] 8ab95710-e00f-4562-8a8e-ad582d6fb299: "Waiting for tx d1f6aa19a91bc043f41dd071ffc0617d1c815248ea131c8a47163d47d669164b to complete"
[chain-index:Info:1736] [2022-07-14 18:33:37.58 UTC] Still in sync. Processed 1 blocks, 0 rollbacks in the last 2s. Current tip is Point(Slot 608, BlockId 0d3924be1837093381117fca9474d46d6a9ac74ce1fc2929185b7c15532ee346)
[chain-index:Info:1736] [2022-07-14 18:33:37.61 UTC] Still in sync. Processed 1 blocks, 0 rollbacks in the last 0s. Current tip is Point(Slot 611, BlockId e7b6c23ef2b40f17eae072ce1b894e17001d0453ca81505af0a1f0205029c718)
[pab:Info:1748] [2022-07-14 18:33:37.95 UTC] 8ab95710-e00f-4562-8a8e-ad582d6fb299: "Tx confirmed. Integration test complete."

[tbidne]

@koslambrou apologies, I thought I posted a response. I am afraid I see the same behavior. Endless logs like:

[chain-index:Info:1704] [2022-07-25 22:15:53.66 UTC] Still in sync. Processed 7 blocks, 0 rollbacks in the last 2s. Current tip is Point(Slot 389, BlockId c049a8c20a4e347eb0a51a02608453c11822f83b44b2790ffc8d341cc86865f7)

I can in fact start the test:

[pab:Info:1714] [2022-07-25 22:15:41.62 UTC] 3e04c5fa-a3f1-42f2-9a57-77738f001725: "Starting integration test"
[pab:Info:1714] [2022-07-25 22:15:41.62 UTC] Initialising contract IntegrationTest with ID 3e04c5fa-a3f1-42f2-9a57-77738f001725
[pab:Info:1714] [2022-07-25 22:15:41.63 UTC] Activated instance 3e04c5fa-a3f1-42f2-9a57-77738f001725 on W2d4cc31

However I never see it finish, presumably due to the chain index syncing. This is on the latest main with a fresh checkout: 69988b041ba661f4364f7534c03efc32cf9835ae.