utxosAt just hangs using pab-cli on the testnet

[locallycompact]

Summary

Hi, I'm using an NFT contract through the PAB.

https://gitlab.homotopic.tech/plutus/contracts/nft/-/blob/master/src/Plutus/Contracts/NFT.hs

Pasted here:

type Schema = Endpoint "mint" [TokenName]

mint :: [TokenName] -> Contract [(PaymentPubKeyHash, [AssetClass])] Schema Text ()
mint tns = do
  logInfo @String $ "Starting Minting Process For " <> show tns

  pk    <- Contract.ownPaymentPubKeyHash

  logInfo @String $ "Minting NFTs to send to " <> show pk

  utxos <- utxosAt (pubKeyHashAddress pk Nothing)

  logInfo @String $ "Found " <> show (length $ Map.keys utxos) <> " UTxOs"

  case Map.keys utxos of
    [] -> Contract.logError @String "No UTxO Found To use For Minting Process"
    oref : _ -> do

      let cSym            = curSymbol oref tns
          val             = mconcat $ fmap (\x -> Value.singleton cSym x 1) tns
          lookups         = Constraints.mintingPolicy (policy oref tns)
                         <> Constraints.unspentOutputs utxos

          tx              = Constraints.mustMintValue val
                         <> Constraints.mustSpendPubKeyOutput oref

      logInfo @String $ "Submitting NFT Minting Transaction For " <> show tns
      mkTxConstraints @Void lookups tx >>= submitTxConfirmed . adjustUnbalancedTx
      logInfo @String $ "NFT Minting Transaction Confirmed For " <> show tns
      tell [(pk, fmap (assetClass cSym) tns)]

contract :: Contract [(PaymentPubKeyHash, [AssetClass])] Schema Text ()
contract = do
  logInfo @String "Waiting for mint endpoint"
  selectList [ endpoint @"mint" mint ] >> contract

The output that I get from calling the "mint" endpoint through the pab-cli using the wallet backend is as follows:

 {
    "cicStatus": "Active",
    "cicCurrentState": {
      "hooks": [],
      "logs": [
        {
          "_logLevel": "Info",
          "_logMessageContent": "Waiting for mint endpoint"
        },
        {
          "_logLevel": "Info",
          "_logMessageContent": "Starting Minting Process For [\"Ident1\"]"
        },
        {
          "_logLevel": "Info",
          "_logMessageContent": "Minting NFTs to send to 1de53fae5176b350235dd4ca6c984f2166727ddf14d23210a7fc226f"
        }
      ],
      "observableState": [],
      "err": null,
      "lastLogs": [
        {
          "_logLevel": "Info",
          "_logMessageContent": "Minting NFTs to send to 1de53fae5176b350235dd4ca6c984f2166727ddf14d23210a7fc226f"
        }
      ]
    },
    "cicWallet": {
      "getWalletId": "86042932f7aeab55f69316a6685c2383cc1d3d81",
      "prettyWalletName": null
    },
    "cicDefinition": "MintIdents",
    "cicYieldedExportTxs": [],
    "cicContract": {
      "unContractInstanceId": "cfbc0a6f-df9f-4b93-8913-6844fc0ed58e"
    }
  },

There is no additional information the testnet output from pab-cli that indicates an error. So, it seems like it gets as far as the utxosAt call and then just stops doing anything.

Steps to reproduce the behavior

The PAB I'm using is here: https://gitlab.homotopic.tech/plutus/apps/multi-pab with the above contract as a package dependency.

nix run.

Actual Result

No log

Expected Result

Some log

Describe the approach you would take to fix this

No response

System info

NixOS

[locallycompact]

I saw it mentioned in a comment here that the chain index is slow and utxosAt could take hours to complete.

#249 (comment)

[ghost]

Indeed it's not effective at the moment. There is #319 that should improve the speed of chain index.

[kk-hainq]

Not sure how easy it is with your current setup, but can you try removing the utxosAt call and passing the UTxOs in through PAB endpoint parameters instead? If it's your own address on the testnet I guess you can also try hardcoding the UTxOs in to see if the problem is really on utxosAt, and in turn the Plutus chain index behind it.

[locallycompact]

So just an update for this. I'm on latest master for everything. I have cardano-node, cardano-wallet and plutus-chain-index running independently on ports, and the plutus-pab.yaml is configured with those ports, the chain index is fully synced, but utxosAt does not return. There doesn't seem to be any reference to the endpoint "/utxo-at-address" anywhere in the code except for the tests. So is the PAB interpreter even calling this?

Edit: I can call utxo-at-address just fine with the API using curl, now I will try what @kk-hainq suggested and pass that in through the endpoint.

[locallycompact]

I just realised I can't really hardcode it because I need something to pass into the lookups.

[waalge]

I think I have the same issue. Running PAB in verbose the final line before "hanging" is

[pab:Debug:28] [2022-03-28 13:00:57.69 UTC] Handling 1 requests for c835ae89-0aef-4a95-b8e6-d202f367cf4f
    Iteration 3 request ID 1
    Request: Chain index query: requesting utxos located at addresses with the credential PubKeyCredential: dada5e7c74f6c15d1c7899d6620dd17963e8a3e0697f631cd2877ea1
[pab:Debug:28] [2022-03-28 13:00:57.69 UTC] Slot 0: W4231afb: handleChainIndexQueries start

If I query the chain-index directly with what I guess utxosAt should be doing, its slow but does respond

curl -X 'POST'   'http://localhost:9083/utxo-at-address'   -H 'accept: application/json;charset=utf-8'   -H 'Content-Type: application/json;charset=utf-8'   -d '{
  "credential": {
    "contents": {"getPubKeyHash" : "dada5e7c74f6c15d1c7899d6620dd17963e8a3e0697f631cd2877ea1"},
    "tag": "PubKeyCredential"
  }
}'
...
{"currentTip":{"tag":"Tip","tipBlockNo":3431466,"tipBlockId":"adb80a72985e7446bbc7b5b22219e90b8533b972c3ffb88a99f7cb6a68670c9d","tipSlot":{"getSlot":54102725}},"page":{"currentPageQuery":{"pageQueryLastItem":null,"pageQuerySize":{"getPageSize":50}},"pageItems":[{"txOutRefId":{"getTxId":"1253f04ef06d8a3c415713ac5995c414029aeb9687b7890ed4f12b1ffeecfa1e"},"txOutRefIdx":0},{"txOutRefId":{"getTxId":"a439edf4ab362b676152fa8ab759d048d9512bd7c7888b4f01a09d948f34ecdb"},"txOutRefIdx":0},{"txOutRefId":{"getTxId":"e6eb1c810297e4b835f8b52a69297e074b4e07426448851f9cd54e95253fb3d9"},"txOutRefIdx":0},{"txOutRefId":{"getTxId":"fc006af9d370c12b26d615dcabc5f50f9941aa1802cd65f0cd7383b501b69be4"},"txOutRefIdx":0}],"nextPageQuery":null}}

The chain index also logs the request from the curl command, while I see nothing when I expect the PAB to hit it.

---

PS chain index swagger says credential.contents is expecting a string, when it actually requires an object. This happens in a few places.

---

PPS I was gonna try to follow @kk-hainq suggestion of shoe horning the utxo data in by other means, but I thought I'd first try bumping my dependencies. This did not go well, but my issues are no longer as above so I just wanted to point that out before it took up too much of anyone elses attention.

The PAB now says "utxo not found". I am guessing this is because I've set pabResumeFrom to be too recent, but if I push it back my machine falls over. I don't entirely understand why the PAB needs to sync at all, and doesn't leave this to the Chain Index, Wallet and Node. And I still can't see the PAB actually talking to the chain index, according to the chain index logs.

Plutus-apps commit c9c1e917edbf

[waalge]

Apologies for spamming the thread. A further update.
(This is all above my head but) I think I've diagnosed that the PAB is posting to an endpoint that the chain-index doesn't have. At least not my version.

Piping the requests through a socat relay dumps the following output:

POST /unspent-tx-out HTTP/1.1\r
Host: localhost:9084\r
Accept-Encoding: gzip\r
Content-Length: 109\r
Accept: application/json;charset=utf-8,application/json\r
Content-Type: application/json;charset=utf-8\r
\r
{"txOutRefId":{"getTxId":"1253f04ef06d8a3c415713ac5995c414029aeb9687b7890ed4f12b1ffeecfa1e"},"txOutRefIdx":1}< 2022/03/29 11:29:41.512195  length=117 from=0 to=116
HTTP/1.1 404 Not Found\r
Transfer-Encoding: chunked\r
Date: Tue, 29 Mar 2022 11:29:41 GMT\r
Server: Warp/3.3.18\r

This is running Lars's PPP#3L6 mint.
PAB reporting the error from here since the return is Nothing

[locallycompact]

My version of the chain index has /unspent-tx-out, but it doesn't work. Perhaps this is related. #377

[koslambrou]

When chain-index is syncing, the querying is blocked until the next set of blocks are processed (because of a blocking MVar).

The following PR will probably solve it #386 .

[koslambrou]

@locallycompact Can you try again? Should be solved in main with the PR #386 .

[locallycompact]

Oh yes I did get this working. Thanks!