indexer/agent 20.4 has issues with allocations

[mindstyle85]

So version 0.20.4. seems to have some kind of issue with connections to graph node/archival node. Note that graph node and archival node both work correctly and synced up:

Oct 07 14:00:10 val01-grt-t graph-indexer-agent[2165094]: {"level":50,"time":1665144010391,"pid":2165094,"hostname":"val01-grt-t","name":"IndexerAgent","err":"Failed to query Epoch Block Oracle Subgraph","allocationID":"0x6F85ee845e9870388cC5FA2FEeADafEa77843DF7","deployment":{"kind":"deployment-id","value":"0x73ad0014c964f9af0cb417fee113939492bd2928ebbec9b464618f1ffdab6165"},"msg":"Failed to fetch block for resolving allocation POI 0x73ad0014c964f9af0cb417fee113939492bd2928ebbec9b464618f1ffdab6165"}
Oct 07 14:00:10 val01-grt-t graph-indexer-agent[2165094]: {"level":50,"time":1665144010391,"pid":2165094,"hostname":"val01-grt-t","name":"IndexerAgent","action":492,"error":{"code":"IE070","explanation":"https://github.com/graphprotocol/indexer/blob/main/docs/errors.md#ie070","cause":"Failed to query Epoch Block Oracle Subgraph"},"msg":"Failed to prepare tx call data"}

downgrading to 0.20.3. fixes this issue and it all works normally and allocation was able to be closed

[hopeyen]

Hi! could you share more logs leading up to the error? what network names did you provide to the graph node?

[mindstyle85]

sure, this is directly before that log above:

Oct 07 13:56:10 val01-grt-t graph-indexer-agent[2163724]: {"level":20,"time":1665143770961,"pid":2163724,"hostname":"val01-grt-t","name":"IndexerAgent","component":"IndexerManagementClient","actions":[{"status":"approved","type":"unallocate","deploymentID":"QmW8Cbb2R4ZHWGsrYjNJKRjoKKcPeDTNK6rdipfQQaAhd6","allocationID":"0x6F85ee845e9870388cC5FA2FEeADafEa77843DF7","force":false,"source":"indexerAgent","reason":"deployment:never","priority":0}],"msg":"Execute 'queueActions' mutation"}
Oct 07 13:56:11 val01-grt-t graph-indexer-agent[2163724]: {"level":30,"time":1665143771730,"pid":2163724,"hostname":"val01-grt-t","name":"IndexerAgent","queuedAction":[{"id":491,"type":"unallocate","deploymentID":"QmW8Cbb2R4ZHWGsrYjNJKRjoKKcPeDTNK6rdipfQQaAhd6","source":"indexerAgent","reason":"deployment:never","priority":0,"status":"approved"}],"msg":"Queued unallocate action for execution"}
Oct 07 13:56:34 val01-grt-t graph-indexer-agent[2163724]: {"level":20,"time":1665143794501,"pid":2163724,"hostname":"val01-grt-t","name":"IndexerAgent","currentBatchSize":1,"meetsMinBatchSize":true,"oldestAffectedAllocationCreatedAtEpoch":892,"affectedAllocationExpiring":true,"msg":"Auto allocation management executes the batch if at least one requirement is met"}
Oct 07 13:56:34 val01-grt-t graph-indexer-agent[2163724]: {"level":30,"time":1665143794501,"pid":2163724,"hostname":"val01-grt-t","name":"IndexerAgent","actions":[{"id":491,"type":"unallocate","status":"approved","priority":0,"deploymentID":"QmW8Cbb2R4ZHWGsrYjNJKRjoKKcPeDTNK6rdipfQQaAhd6","allocationID":"0x6F85ee845e9870388cC5FA2FEeADafEa77843DF7","amount":null,"poi":null,"force":false,"source":"indexerAgent","reason":"deployment:never","createdAt":"2022-10-07T11:56:11.721Z","updatedAt":"2022-10-07T11:56:11.721Z","transaction":null,"failureReason":null}],"note":"If actions were approved very recently they may be missing from this list but will still be taken","msg":"Executing batch of approved actions"}
Oct 07 13:56:34 val01-grt-t graph-indexer-agent[2163724]: {"level":30,"time":1665143794505,"pid":2163724,"hostname":"val01-grt-t","name":"IndexerAgent","action":491,"allocationID":"0x6F85ee845e9870388cC5FA2FEeADafEa77843DF7","poi":"none provided","msg":"Preparing to close allocation (unallocate)"}

nothing special was before this except an IE35 error:

Oct 07 11:55:20 val02-grt-t graph-indexer-agent[1570536]: {"level":40,"time":1665143720356,"pid":1570536,"hostname":"val02-grt-t","name":"IndexerAgent","err":{"type":"IndexerError","message":"Unhandled promise rejection","stack":"IndexerError: Unhandled promise rejection\n at indexerError (/home/pops/indexer/packages/indexer-common/dist/errors.js:165:12)\n at process.<anonymous> (/home/pops/indexer/packages/indexer-agent/dist/commands/start.js:435:56)\n at process.emit (node:events:513:28)\n at process.emit (node:domain:489:12)\n at emit (node:internal/process/promises:140:20)\n at processPromiseRejections (node:internal/process/promises:274:27)\n at processTicksAndRejections (node:internal/process/task_queues:97:32)","code":"IE035","explanation":"https://github.com/graphprotocol/indexer/blob/main/docs/errors.md#ie035","cause":{"type":"Error","message":"call revert exception [ See: https://links.ethers.org/v5-errors-CALL_EXCEPTION ] (method=\"decimals()\", data=\"0x\", errorArgs=null, errorName=null, errorSignature=null, reason=null, code=CALL_EXCEPTION, version=abi/5.6.1)","stack":"Error: call revert exception [ See: https://links.ethers.org/v5-errors-CALL_EXCEPTION ] (method=\"decimals()\", data=\"0x\", errorArgs=null, errorName=null, errorSignature=null, reason=null, code=CALL_EXCEPTION, version=abi/5.6.1)\n at Logger.makeError (/home/pops/indexer/node_modules/@ethersproject/logger/lib/index.js:233:21)\n at Logger.throwError (/home/pops/indexer/node_modules/@ethersproject/logger/lib/index.js:242:20)\n at Interface.decodeFunctionResult (/home/pops/indexer/node_modules/@ethersproject/contracts/node_modules/@ethersproject/abi/lib/interface.js:389:23)\n at Contract.<anonymous> (/home/pops/indexer/node_modules/@ethersproject/contracts/lib/index.js:395:56)\n at step (/home/pops/indexer/node_modules/@ethersproject/contracts/lib/index.js:48:23)\n at Object.next (/home/pops/indexer/node_modules/@ethersproject/contracts/lib/index.js:29:53)\n at fulfilled (/home/pops/indexer/node_modules/@ethersproject/contracts/lib/index.js:20:58)\n at processTicksAndRejections (node:internal/process/task_queues:96:5)","reason":null,"code":"CALL_EXCEPTION","method":"decimals()","data":"0x","errorArgs":null,"errorName":null,"errorSignature":null,"address":"0xA0b86991c6218b36c1d19D4a2e9Eb0cE3606eB48","args":[],"transaction":{"data":"0x313ce567","to":"0xA0b86991c6218b36c1d19D4a2e9Eb0cE3606eB48"}}},"msg":"Unhandled promise rejection"}

note that downgrading to 0.20.3 got rid of these errors, as like i said, both graph node and archival node (gnosis) were working correctly

[hopeyen]

thanks for the logs! 0.20.4 includes new feature to support allocations with network specific epoch start blocks using the epoch block oracle, so it would be great to identify why it has failed (the same deployment were able to close on my local setup). Would you be able to share logs such as

INFO (IndexerAgent/64201 on book): Reconcile with the network
    component: "Agent"
    protocolChainLatestValidEpoch: {
      "network": "goerli",
      "epochNumber": 913,
      "startBlockNumber": 7730126,
      "startBlockHash": "0xfce1717148cfb653d34b399d6c4c847211b25a7608e202f62015750d936e6b08"
    }

and just making sure that you have provided gnosis:[api_key] to your graph node's ethereum-rpc?

[mindstyle85]

sure, here they are:

Oct 05 22:44:58 val01-grt-t graph-indexer-agent[2024109]: {"level":30,"time":1665002698307,"pid":2024109,"hostname":"val01-grt-t","name":"IndexerAgent","component":"Agent","protocolChainLatestValidEpoch":{"network":"goerli","epochNumber":891,"startBlockNumber":7717938,"startBlockHash":"0xf5bb75145a3ef0c472da4405edc913b99f1287445f6e7c3dd9e0ef5473b1d1a1"},"msg":"Reconcile with the network"}

this is the last one before we downgraded to 20.3:

Oct 07 14:12:09 val01-grt-t graph-indexer-agent[2165094]: {"level":30,"time":1665144729641,"pid":2165094,"hostname":"val01-grt-t","name":"IndexerAgent","component":"Agent","protocolChainLatestValidEpoch":{"network":"goerli","epochNumber":908,"startBlockNumber":7727356,"startBlockHash":"0x9def25ef0760320d31abb146e963b66dec67c5990f7184a732f9c960dd3f1bd4"},"msg":"Reconcile with the network"}

and one with logs below it (above seems nothing special):

Oct 07 14:08:09 val01-grt-t graph-indexer-agent[2165094]: {"level":30,"time":1665144489641,"pid":2165094,"hostname":"val01-grt-t","name":"IndexerAgent","component":"Agent","protocolChainLatestValidEpoch":{"network":"goerli","epochNumber":908,"startBlockNumber":7727356,"startBlockHash":"0x9def25ef0760320d31abb146e963b66dec67c5990f7184a732f9c960dd3f1bd4"},"msg":"Reconcile with the network"}
Oct 07 14:08:09 val01-grt-t graph-indexer-agent[2165094]: {"level":20,"time":1665144489642,"pid":2165094,"hostname":"val01-grt-t","name":"IndexerAgent","component":"IndexerManagementClient","filter":{"status":"approved"},"msg":"Execute 'actions' query"}
Oct 07 14:08:09 val01-grt-t graph-indexer-agent[2165094]: {"level":20,"time":1665144489647,"pid":2165094,"hostname":"val01-grt-t","name":"IndexerAgent","component":"Agent","syncing":[{"bytes32":"0x42c56f2f5137183c21db1228e818d4be7275706a53aa457dd88b0bd6911ecf64","ipfsHash":"QmSqJEGHp1PcgvBYKFF2u8vhJZt8JTq18EV7mCuuZZiutX"},{"bytes32":"0x73ad0014c964f9af0cb417fee113939492bd2928ebbec9b464618f1ffdab6165","ipfsHash":"QmW8Cbb2R4ZHWGsrYjNJKRjoKKcPeDTNK6rdipfQQaAhd6"},{"bytes32":"0x7e21a1ff3e6cb31710f8763c404419809796ae592b1932ca1f37bbb0795aa64b","ipfsHash":"QmWq1pmnhEvx25qxpYYj9Yp6E1xMKMVoUjXVQBxUJmreSe"},{"bytes32":"0xf000df3a17075aaf25c36757a47ef58f3913d3205efac530fa338b4ad22d1264","ipfsHash":"QmeVXKzGKSyfEQib4MzeZveJgDYJCYDMMHc1pPevWeSbsq"}],"target":[{"bytes32":"0xf000df3a17075aaf25c36757a47ef58f3913d3205efac530fa338b4ad22d1264","ipfsHash":"QmeVXKzGKSyfEQib4MzeZveJgDYJCYDMMHc1pPevWeSbsq"},{"bytes32":"0x42c56f2f5137183c21db1228e818d4be7275706a53aa457dd88b0bd6911ecf64","ipfsHash":"QmSqJEGHp1PcgvBYKFF2u8vhJZt8JTq18EV7mCuuZZiutX"},{"bytes32":"0x7e21a1ff3e6cb31710f8763c404419809796ae592b1932ca1f37bbb0795aa64b","ipfsHash":"QmWq1pmnhEvx25qxpYYj9Yp6E1xMKMVoUjXVQBxUJmreSe"}],"withActiveOrRecentlyClosedAllocation":[{"bytes32":"0x73ad0014c964f9af0cb417fee113939492bd2928ebbec9b464618f1ffdab6165","ipfsHash":"QmW8Cbb2R4ZHWGsrYjNJKRjoKKcPeDTNK6rdipfQQaAhd6"}],"msg":"Reconcile deployments"}
Oct 07 14:08:09 val01-grt-t graph-indexer-agent[2165094]: {"level":30,"time":1665144489657,"pid":2165094,"hostname":"val01-grt-t","name":"IndexerAgent","component":"Agent","deployment":"QmW8Cbb2R4ZHWGsrYjNJKRjoKKcPeDTNK6rdipfQQaAhd6","epoch":908,"eligibleForClose":["0x6F85ee845e9870388cC5FA2FEeADafEa77843DF7"],"msg":"Deployment is not (or no longer) worth allocating towards, close allocation"}
Oct 07 14:08:09 val01-grt-t graph-indexer-agent[2165094]: {"level":20,"time":1665144489665,"pid":2165094,"hostname":"val01-grt-t","name":"IndexerAgent","component":"IndexerManagementClient","actions":[{"status":"approved","type":"unallocate","deploymentID":"QmW8Cbb2R4ZHWGsrYjNJKRjoKKcPeDTNK6rdipfQQaAhd6","allocationID":"0x6F85ee845e9870388cC5FA2FEeADafEa77843DF7","force":false,"source":"indexerAgent","reason":"deployment:never","priority":0}],"msg":"Execute 'queueActions' mutation"}
Oct 07 14:08:10 val01-grt-t graph-indexer-agent[2165094]: {"level":30,"time":1665144490272,"pid":2165094,"hostname":"val01-grt-t","name":"IndexerAgent","queuedAction":[{"id":495,"type":"unallocate","deploymentID":"QmW8Cbb2R4ZHWGsrYjNJKRjoKKcPeDTNK6rdipfQQaAhd6","source":"indexerAgent","reason":"deployment:never","priority":0,"status":"approved"}],"msg":"Queued unallocate action for execution"}
--
Oct 07 14:08:40 val01-grt-t graph-indexer-agent[2165094]: {"level":50,"time":1665144520249,"pid":2165094,"hostname":"val01-grt-t","name":"IndexerAgent","action":495,"error":{"code":"IE070","explanation":"https://github.com/graphprotocol/indexer/blob/main/docs/errors.md#ie070","cause":"Failed to query Epoch Block Oracle Subgraph"},"msg":"Failed to prepare tx call data"}
Oct 07 14:08:40 val01-grt-t graph-indexer-agent[2165094]: {"level":20,"time":1665144520249,"pid":2165094,"hostname":"val01-grt-t","name":"IndexerAgent","results":[{"actionID":495,"failureReason":"IE070"}],"msg":"Completed batch action execution"}
Oct 07 14:10:09 val01-grt-t graph-indexer-agent[2165094]: {"level":30,"time":1665144609346,"pid":2165094,"hostname":"val01-grt-t","name":"IndexerAgent","component":"ETHBalanceMonitor","balance":0.2993691044925867,"msg":"Current operator ETH balance"}
Oct 07 14:12:09 val01-grt-t graph-indexer-agent[2165094]: {"level":30,"time":1665144729365,"pid":2165094,"hostname":"val01-grt-t","name":"IndexerAgent","component":"ETHBalanceMonitor","balance":0.2993691044925867,"msg":"Current operator ETH balance"}
Oct 07 14:12:09 val01-grt-t graph-indexer-agent[2165094]: {"level":20,"time":1665144729639,"pid":2165094,"hostname":"val01-grt-t","name":"IndexerAgent","msg":"Query subgraph deployments in batches of 10"}

[hopeyen]

It looks like Epoch oracle subgraph endpoint is working fine. What is the version for your graph node? Also wondering if you could please try to grab a block number from gnosis and query block hash similar to the following

curl -g \
-X POST \
-H "Content-Type: application/json" \
-d '{"query": "{blockHashFromNumber(network:\"gnosis\", blockNumber:24553563)}"}' \
http://localhost:8030/graphql

Ideally you should get something like {"data":{"blockHashFromNumber":"ab35f141e9b91cad9514667a9955fae38cbe82b9ce4d554d464e28ec76913112"}}%

[mindstyle85]

its graph-node 0.27.0 :: integer (c628e4374 2022-07-28)

when i try your exact command it gives this:

{"errors":[{"locations":[{"line":1,"column":2}],"message":"TypeQueryhas no fieldblockHashFromNumber"}]}

could it be graph node version we use wasnt compatible with 0.20.4?

[hopeyen]

Yes that's correct! 0.20.4 currently utilizes a feature from graph node v0.28.0.

Though now that we have identified the issue, we will add fallback such that indexers aren't required for a graph-node update. We'll also update the error messages so that it's more clear in the future:)

[mindstyle85]

great, will close this issue then if not needed, otherwise you can reopen it