search

graphprotocol / indexer

Graph Protocol indexer components and infrastructure
MIT License
240 stars 130 forks source link

indexer-service : Unable to sign the query response attestation #122

Closed suntzu93 closed 3 years ago

suntzu93 commented 3 years ago

More log : https://drive.google.com/file/d/1S1tRRijZQBv5HN8VaypPP6do1kT76XIe/view?usp=sharing

{"level":50,"time":1606053149791,"pid":37618,"hostname":"suntzu-server","name":"IndexerService","indexer":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","operator":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","indexer":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","operator":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","component":"Server","err":{"type":"Error","message":"Unable to sign the query response attestation","stack":"Error: Unable to sign the query response attestation\n at QueryProcessor.<anonymous> (/usr/local/lib/node_modules/@graphprotocol/indexer-service/dist/queries.js:71:31)\n at Generator.next (<anonymous>)\n at fulfilled (/usr/local/lib/node_modules/@graphprotocol/indexer-service/dist/queries.js:5:58)\n at processTicksAndRejections (internal/process/task_queues.js:93:5)","envelopedResponse":"{\"walletVersion\":\"@statechannels/server-wallet@1.12.0\",\"signedStates\":[{\"chainId\":\"0x00\",\"participants\":[{\"destination\":\"0x0000000000000000000000004d85f8d90f2E7a88bf1BFaBEBb02B0bC62a9932D\",\"participantId\":\"0x06d3B8d2e278adAAEcFB343f9A7a4E1206e489B9\",\"signingAddress\":\"0x06d3B8d2e278adAAEcFB343f9A7a4E1206e489B9\"},{\"destination\":\"0x000000000000000000000000AD8B03a2133FFb40dc3416ceC81c7377fC89d8E2\",\"participantId\":\"http://135.181.16.220/\",\"signingAddress\":\"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016\"}],\"channelNonce\":14584,\"appDefinition\":\"0x65F7089292CEa554e92b3Bf5531BB9f522268081\",\"challengeDuration\":9001,\"turnNum\":3715,\"appData\":\"0x00000000000000000000000000000000000000000000000000000000000000200000000000000000000000000000000000000000000000000000000000000000000000000000000000000000AD8B03a2133FFb40dc3416ceC81c7377fC89d8E200000000000000000000000030e767CBad10956aCa592d2330B51C132D3dac4B11e3ed0db95163788a6e0f4a2ee7d20a170a5166b893b24710b99dec12ad058d00000000000000000000000000000000000000000000000000000000000000a00000000000000000000000000000000000000000000000000001c6bf526340000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000800000000000000000000000000000000000000000000000000000000000000000\",\"isFinal\":false,\"outcome\":[{\"assetHolderAddress\":\"0x2A7fC13Bd6Ba6A79eC95c4b9f78f1DeFC9BC5124\",\"allocationItems\":[{\"destination\":\"0x0000000000000000000000004d85f8d90f2E7a88bf1BFaBEBb02B0bC62a9932D\",\"amount\":\"0x00000000000000000000000000000000000000000000d3c217e6b62b70ba4000\"},{\"destination\":\"0x000000000000000000000000AD8B03a2133FFb40dc3416ceC81c7377fC89d8E2\",\"amount\":\"0x00000000000000000000000000000000000000000000000003e816c23045c000\"}]}],\"channelId\":\"0x315ebabb98af12d56dfb6f403649cf0d3c3c43984dd291d0219939db1eb85e00\",\"signatures\":[\"0xe77b08711c36fb4106db1aa95bc9f7e674257a259a1f5bd16120daae635f31bf23b16758635654d6b5307811d2d64bd96fb096e4d431131f07ba69b57971a8001b\"]}]}","status":500},"msg":"Failed to handle paid query"}

davaymne commented 3 years ago

Hi, On 2020-11-22 at around 9:30 UTC started getting error messages in the indexer-service log "Unable to sign the query response attestation".

*Please see indexer-service log: indexer-service.query_declined_20201122.log

suntzu93 commented 3 years ago

More log before and after error :

0|start_indexer_service | {"level":20,"time":1606131894126,"pid":166440,"hostname":"suntzu-server","name":"IndexerService","indexer":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","operator":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","component":"ReceiptManager","channel":"0xe54e8db86e017667ec720af38588c4611de85168d979a80da54aae8611d146e0","msg":"Query decline state created"} 0|start_indexer_service | {"level":20,"time":1606131894128,"pid":166440,"hostname":"suntzu-server","name":"IndexerService","indexer":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","operator":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","component":"ReceiptManager","channelId":"0xf9f6fd977a94fc7fee353ead40b917fb80b5ac87ea4371ba13b32e1f6675b87e","turnNum":18150,"status":"running","indexerBal":"0x038d7ea4c68000","gatewayBal":"0xd3c21bcb3f6efc398000","msg":"Payment pushed"} 0|start_indexer_service | {"level":20,"time":1606131894128,"pid":166440,"hostname":"suntzu-server","name":"IndexerService","indexer":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","operator":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","component":"ReceiptManager","channel":"0xf9f6fd977a94fc7fee353ead40b917fb80b5ac87ea4371ba13b32e1f6675b87e","msg":"Query decline state created"} 0|start_indexer_service | {"level":20,"time":1606131894130,"pid":166440,"hostname":"suntzu-server","name":"IndexerService","indexer":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","operator":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","component":"ReceiptManager","channelId":"0xae0d360b43ead6b24caadd189e402c577a60229038989405cbfec0c9e933e846","turnNum":17312,"status":"running","indexerBal":"0x41b9a6e8584000","gatewayBal":"0xd3c21b8d1346b8a7c000","msg":"Payment pushed"} 0|start_indexer_service | {"level":20,"time":1606131894130,"pid":166440,"hostname":"suntzu-server","name":"IndexerService","indexer":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","operator":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","component":"ReceiptManager","channel":"0xae0d360b43ead6b24caadd189e402c577a60229038989405cbfec0c9e933e846","msg":"Query decline state created"} 0|start_indexer_service | {"level":20,"time":1606131894131,"pid":166440,"hostname":"suntzu-server","name":"IndexerService","indexer":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","operator":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","component":"ReceiptManager","channelId":"0xe54e8db86e017667ec720af38588c4611de85168d979a80da54aae8611d146e0","turnNum":6734,"status":"running","indexerBal":"0xe6ed27d6668000","gatewayBal":"0xd3c21ae7dfc5ca998000","msg":"Query decline embedded in state channel update"} 0|start_indexer_service | {"level":50,"time":1606131894131,"pid":166440,"hostname":"suntzu-server","name":"IndexerService","indexer":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","operator":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","indexer":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","operator":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","component":"Server","err":{"type":"Error","message":"Unable to sign the query response attestation","stack":"Error: Unable to sign the query response attestation\n at QueryProcessor.<anonymous> (/usr/local/lib/node_modules/@graphprotocol/indexer-service/dist/queries.js:71:31)\n at Generator.next (<anonymous>)\n at fulfilled (/usr/local/lib/node_modules/@graphprotocol/indexer-service/dist/queries.js:5:58)\n at runMicrotasks (<anonymous>)\n at processTicksAndRejections (internal/process/task_queues.js:93:5)","envelopedResponse":"{\"walletVersion\":\"@statechannels/server-wallet@1.12.0\",\"signedStates\":[{\"chainId\":\"0x00\",\"participants\":[{\"destination\":\"0x000000000000000000000000bded54EceEE03FB073dC2228A12880Aac1E545Be\",\"participantId\":\"0x2eb6622C08a67DA64209C80Eb3E3b37287D45630\",\"signingAddress\":\"0x2eb6622C08a67DA64209C80Eb3E3b37287D45630\"},{\"destination\":\"0x0000000000000000000000006471ADf3F738dA6cAB1Fb1aC3CD9b2d513e47965\",\"participantId\":\"http://135.181.16.220/\",\"signingAddress\":\"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016\"}],\"channelNonce\":7374,\"appDefinition\":\"0x65F7089292CEa554e92b3Bf5531BB9f522268081\",\"challengeDuration\":9001,\"turnNum\":6735,\"appData\":\"0x000000000000000000000000000000000000000000000000000000000000002000000000000000000000000000000000000000000000000000000000000000000000000000000000000000006471ADf3F738dA6cAB1Fb1aC3CD9b2d513e4796500000000000000000000000030e767CBad10956aCa592d2330B51C132D3dac4Bcd5b188df465db8f833b689d1d7672e9d57e720a197d28f1f7731141e39e7a0900000000000000000000000000000000000000000000000000000000000000a00000000000000000000000000000000000000000000000000001c6bf526340000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000800000000000000000000000000000000000000000000000000000000000000000\",\"isFinal\":false,\"outcome\":[{\"assetHolderAddress\":\"0x2A7fC13Bd6Ba6A79eC95c4b9f78f1DeFC9BC5124\",\"allocationItems\":[{\"destination\":\"0x000000000000000000000000bded54EceEE03FB073dC2228A12880Aac1E545Be\",\"amount\":\"0x00000000000000000000000000000000000000000000d3c21ae7dfc5ca998000\"},{\"destination\":\"0x0000000000000000000000006471ADf3F738dA6cAB1Fb1aC3CD9b2d513e47965\",\"amount\":\"0x00000000000000000000000000000000000000000000000000e6ed27d6668000\"}]}],\"channelId\":\"0xe54e8db86e017667ec720af38588c4611de85168d979a80da54aae8611d146e0\",\"signatures\":[\"0xfa266e79dab71648c17bec713cd462aa5063247caeb4a81511800a845ffe60c64a326dd6e38dfdfddcd36ac569cf62b363cbad01d86cb68a105bc4867af29db11c\"]}]}","status":500},"msg":"Failed to handle paid query"} 0|start_indexer_service | {"level":20,"time":1606131894131,"pid":166440,"hostname":"suntzu-server","name":"IndexerService","indexer":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","operator":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","indexer":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","operator":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","component":"Server","msg":"POST /subgraphs/id/QmcAGrSedyweWQhKCbdMUxbX2ddMiSJwWRRc3NcDtoXnDE 500 57 - 11.830 ms"} 0|start_indexer_service | {"level":30,"time":1606131894133,"pid":166440,"hostname":"suntzu-server","name":"IndexerService","indexer":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","operator":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","indexer":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","operator":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","component":"Server","deployment":{"bytes32":"0xcd5b188df465db8f833b689d1d7672e9d57e720a197d28f1f7731141e39e7a09","ipfsHash":"QmcAGrSedyweWQhKCbdMUxbX2ddMiSJwWRRc3NcDtoXnDE"},"msg":"Received paid query"} 0|start_indexer_service | {"level":30,"time":1606131894134,"pid":166440,"hostname":"suntzu-server","name":"IndexerService","indexer":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","operator":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","indexer":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","operator":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","component":"QueryProcessor","deployment":{"bytes32":"0xcd5b188df465db8f833b689d1d7672e9d57e720a197d28f1f7731141e39e7a09","ipfsHash":"QmcAGrSedyweWQhKCbdMUxbX2ddMiSJwWRRc3NcDtoXnDE"},"allocationID":"0x6471ADf3F738dA6cAB1Fb1aC3CD9b2d513e47965","msg":"Execute paid query"} 0|start_indexer_service | {"level":20,"time":1606131894134,"pid":166440,"hostname":"suntzu-server","name":"IndexerService","indexer":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","operator":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","component":"ReceiptManager","states":[{"channel":"0xaacbe2a2884e03222df233d340f918c1107b05720e4ba770783cbbe594e3b4ad","nonce":6862,"turnNum":28312}],"msg":"Payment received"} 0|start_indexer_service | {"level":20,"time":1606131894136,"pid":166440,"hostname":"suntzu-server","name":"IndexerService","indexer":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","operator":"0xD96d4B52CAb35cF3DF1d58765bD2eA7cb1Fb6016","component":"ReceiptManager","channelId":"0xae0d360b43ead6b24caadd189e402c577a60229038989405cbfec0c9e933e846","turnNum":17312,"status":"running","indexerBal":"0x41b9a6e8584000","gatewayBal":"0xd3c21b8d1346b8a7c000","msg":"Query decline embedded in state channel update"}

novy4 commented 3 years ago

https://gist.github.com/novy4/8fdc3de032476a16a9334a75d9e8cea4 same on my node

Jannis commented 3 years ago

After https://github.com/graphprotocol/indexer/issues/117, these errors should only show sporadically. I have a few ideas on how to eliminate them altogether.

Current behavior

Right now, what happens is that the indexer-agent creates an allocation on-chain. Then, independently, the gateway and indexer-service detect it by querying the network subgraph or contracts. And because gateway and indexer-service don't detect them at the same time, it can happen that the gateway sees an allocation before the indexer-service does, and sends payments through a state channel created for this allocation before the indexer-service has created an attestation signer for the allocation.

Potential improvements

chriswessels commented 3 years ago

Short excerpt from logs (passed through graph-pino):

DBG 14:35:53.677 POST /subgraphs/id/QmZ6noN8Ek4dPpyvmSv4AdAtefVWtUsopBc8hFKFiWo1Uw 200 753 - 85.213 ms, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:35:57.564 Received paid query, deployment: QmZ6noN8Ek4dPpyvmSv4AdAtefVWtUsopBc8hFKFiWo1Uw, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:35:57.564 Execute paid query, deployment: QmZ6noN8Ek4dPpyvmSv4AdAtefVWtUsopBc8hFKFiWo1Uw, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, allocation: 0xe5C4B6be27af8E6f50c073f499AeB3db18763004
DBG 14:35:57.590 Payment received, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:35:57.616 Payment pushed, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0x9c8525072ed9f1ac407fb53a3d95d9b7c06779adcdacaeae56da796275d12620
DBG 14:35:57.616 Attestation signed, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:35:57.642 Attestation embedded in state channel update, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0x9c8525072ed9f1ac407fb53a3d95d9b7c06779adcdacaeae56da796275d12620
DBG 14:35:57.643 POST /subgraphs/id/QmZ6noN8Ek4dPpyvmSv4AdAtefVWtUsopBc8hFKFiWo1Uw 200 739 - 79.215 ms, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:35:58.777 Received paid query, deployment: QmZ6noN8Ek4dPpyvmSv4AdAtefVWtUsopBc8hFKFiWo1Uw, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:35:58.780 Execute paid query, deployment: QmZ6noN8Ek4dPpyvmSv4AdAtefVWtUsopBc8hFKFiWo1Uw, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, allocation: 0xedE13876c752B37D75c89bF33a7bd9E5374ad1fb
DBG 14:35:58.780 Payment received, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:35:58.805 Payment pushed, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0x36c08a88373fd60f9ee347078e712f3fbbce1309fac94e854d0df5b93b19c6f3
DBG 14:35:58.806 Query decline state created, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0x36c08a88373fd60f9ee347078e712f3fbbce1309fac94e854d0df5b93b19c6f3
DBG 14:35:58.823 Query decline embedded in state channel update, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0x36c08a88373fd60f9ee347078e712f3fbbce1309fac94e854d0df5b93b19c6f3
ERR 14:35:58.823 Failed to handle paid query, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, err: Unable to sign the query response attestation
DBG 14:35:58.824 POST /subgraphs/id/QmZ6noN8Ek4dPpyvmSv4AdAtefVWtUsopBc8hFKFiWo1Uw 500 57 - 47.023 ms, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:35:59.372 Received paid query, deployment: QmZ6noN8Ek4dPpyvmSv4AdAtefVWtUsopBc8hFKFiWo1Uw, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:35:59.373 Execute paid query, deployment: QmZ6noN8Ek4dPpyvmSv4AdAtefVWtUsopBc8hFKFiWo1Uw, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, allocation: 0xC6E9C33FebbBEF4588FFD6c81a833D7D04FFb884
DBG 14:35:59.373 Payment received, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:35:59.408 Payment pushed, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0x013ff1624542b5ff4df7c7a50e9097a0c47d01749c0f25a71ac636debaa2c8c4
DBG 14:35:59.408 Query decline state created, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0x013ff1624542b5ff4df7c7a50e9097a0c47d01749c0f25a71ac636debaa2c8c4
DBG 14:35:59.428 Query decline embedded in state channel update, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0x013ff1624542b5ff4df7c7a50e9097a0c47d01749c0f25a71ac636debaa2c8c4
ERR 14:35:59.429 Failed to handle paid query, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, err: Unable to sign the query response attestation
DBG 14:35:59.430 POST /subgraphs/id/QmZ6noN8Ek4dPpyvmSv4AdAtefVWtUsopBc8hFKFiWo1Uw 500 57 - 57.833 ms, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:35:59.977 Received paid query, deployment: QmZ4fvpTgWCL3oQbf7uzy9bszotLTxv6pGbYfGk7VopTst, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:35:59.978 Execute paid query, deployment: QmZ4fvpTgWCL3oQbf7uzy9bszotLTxv6pGbYfGk7VopTst, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, allocation: 0x66581Ba343db0431B5d88833923e47d25C0950B1
DBG 14:35:59.978 Payment received, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:36:00.000 Payment pushed, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0x3a44e691d7360a4dbe0ced4db0dbd47932322e3867bcad60f820b3b9e36d9c80
DBG 14:36:00.001 Query decline state created, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0x3a44e691d7360a4dbe0ced4db0dbd47932322e3867bcad60f820b3b9e36d9c80
DBG 14:36:00.020 Query decline embedded in state channel update, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0x3a44e691d7360a4dbe0ced4db0dbd47932322e3867bcad60f820b3b9e36d9c80
ERR 14:36:00.020 Failed to handle paid query, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, err: Unable to sign the query response attestation
DBG 14:36:00.021 POST /subgraphs/id/QmZ4fvpTgWCL3oQbf7uzy9bszotLTxv6pGbYfGk7VopTst 500 57 - 44.899 ms, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:36:00.288 Received paid query, deployment: QmZ6noN8Ek4dPpyvmSv4AdAtefVWtUsopBc8hFKFiWo1Uw, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:36:00.288 Execute paid query, deployment: QmZ6noN8Ek4dPpyvmSv4AdAtefVWtUsopBc8hFKFiWo1Uw, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, allocation: 0xad33eDF027e12C29F4f7Da1408F8c829DfA77Ab1
DBG 14:36:00.288 Payment received, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:36:00.311 Payment pushed, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0x6fcb49a2e932ac0624d569e8acbe7aee3277658750d4eb4a5859b7cab6a85689
DBG 14:36:00.312 Query decline state created, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0x6fcb49a2e932ac0624d569e8acbe7aee3277658750d4eb4a5859b7cab6a85689
DBG 14:36:00.327 Query decline embedded in state channel update, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0x6fcb49a2e932ac0624d569e8acbe7aee3277658750d4eb4a5859b7cab6a85689
ERR 14:36:00.327 Failed to handle paid query, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, err: Unable to sign the query response attestation
DBG 14:36:00.329 POST /subgraphs/id/QmZ6noN8Ek4dPpyvmSv4AdAtefVWtUsopBc8hFKFiWo1Uw 500 57 - 41.560 ms, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:36:01.033 Received paid query, deployment: QmbS7vmAWXJqsJEnAbvNSBYQXxCUmZWHFQygHPbyb3vy3N, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:36:01.033 Execute paid query, deployment: QmbS7vmAWXJqsJEnAbvNSBYQXxCUmZWHFQygHPbyb3vy3N, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, allocation: 0x909f6c2Fb30C69Ed2D9b29a10b0f5Df9eD53820f
DBG 14:36:01.058 Payment received, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:36:01.082 Payment pushed, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0x830c6d9430f7cd83fec3d6202f9316c0892b6f09a2301c37fa524cbce543ed7a
DBG 14:36:01.083 Attestation signed, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:36:01.100 Attestation embedded in state channel update, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0x830c6d9430f7cd83fec3d6202f9316c0892b6f09a2301c37fa524cbce543ed7a
DBG 14:36:01.101 POST /subgraphs/id/QmbS7vmAWXJqsJEnAbvNSBYQXxCUmZWHFQygHPbyb3vy3N 200 17037 - 68.500 ms, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:36:01.135 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:36:04.247 Received paid query, deployment: QmbS7vmAWXJqsJEnAbvNSBYQXxCUmZWHFQygHPbyb3vy3N, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:36:04.247 Execute paid query, deployment: QmbS7vmAWXJqsJEnAbvNSBYQXxCUmZWHFQygHPbyb3vy3N, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, allocation: 0xA7F91C667f297426e590072a6c759488bbBF6f2E
DBG 14:36:04.355 Payment received, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:36:04.358 Received paid query, deployment: QmbS7vmAWXJqsJEnAbvNSBYQXxCUmZWHFQygHPbyb3vy3N, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:36:04.358 Execute paid query, deployment: QmbS7vmAWXJqsJEnAbvNSBYQXxCUmZWHFQygHPbyb3vy3N, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, allocation: 0xA7F91C667f297426e590072a6c759488bbBF6f2E
DBG 14:36:04.387 Payment pushed, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0x587801d191930b7ed259d95d55880b0f54ed99ea1153a1a622cb0e6c2b068bcd
DBG 14:36:04.388 Attestation signed, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:36:04.401 Attestation embedded in state channel update, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0x587801d191930b7ed259d95d55880b0f54ed99ea1153a1a622cb0e6c2b068bcd
DBG 14:36:04.429 Payment received, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:36:04.431 POST /subgraphs/id/QmbS7vmAWXJqsJEnAbvNSBYQXxCUmZWHFQygHPbyb3vy3N 200 969115 - 176.416 ms, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:36:04.448 Payment pushed, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0xca22c941cd58ba0820ed103dd7a4a4613ae92e64bd43310b616f201e7e78f113
DBG 14:36:04.448 Attestation signed, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:36:04.467 Attestation embedded in state channel update, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0xca22c941cd58ba0820ed103dd7a4a4613ae92e64bd43310b616f201e7e78f113
DBG 14:36:04.468 POST /subgraphs/id/QmbS7vmAWXJqsJEnAbvNSBYQXxCUmZWHFQygHPbyb3vy3N 200 3164 - 110.414 ms, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:36:05.198 Received paid query, deployment: QmbS7vmAWXJqsJEnAbvNSBYQXxCUmZWHFQygHPbyb3vy3N, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:36:05.199 Execute paid query, deployment: QmbS7vmAWXJqsJEnAbvNSBYQXxCUmZWHFQygHPbyb3vy3N, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, allocation: 0xC6836D678a8A939dAEB0c4AA3D026e87Caf0932C
DBG 14:36:05.199 Payment received, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:36:05.220 Payment pushed, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0x6d34889a2538d94d90369373c1b1798a3e188a82b74c466bcca532dd022a5250
DBG 14:36:05.220 Query decline state created, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0x6d34889a2538d94d90369373c1b1798a3e188a82b74c466bcca532dd022a5250
DBG 14:36:05.237 Query decline embedded in state channel update, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0x6d34889a2538d94d90369373c1b1798a3e188a82b74c466bcca532dd022a5250
ERR 14:36:05.237 Failed to handle paid query, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, err: Unable to sign the query response attestation

Shortly after, matching Active allocations:

WRN 14:38:31.368 Failed to query allocations, keeping existing, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, err: [GraphQL] Request failed with status code 502
DBG 14:38:41.139 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:38:51.141 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:39:01.140 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:39:11.141 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:39:11.405 Active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:39:11.408 Updating attestation signers, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:39:21.141 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:39:31.141 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:39:41.141 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:39:51.142 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:40:01.143 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:40:01.735 Active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:40:01.736 Updating attestation signers, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:40:11.144 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:40:12.019 Active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:40:12.021 Updating attestation signers, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:40:21.144 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:40:28.964 Payload received, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:40:29.624 Received paid query, deployment: QmbS7vmAWXJqsJEnAbvNSBYQXxCUmZWHFQygHPbyb3vy3N, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:40:29.626 Execute paid query, deployment: QmbS7vmAWXJqsJEnAbvNSBYQXxCUmZWHFQygHPbyb3vy3N, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, allocation: 0xC6836D678a8A939dAEB0c4AA3D026e87Caf0932C
DBG 14:40:29.627 Payment received, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:40:29.668 Payment pushed, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0xf32bed7151ec42123816240bdedf884265824074657d6543c85e930ccb2354d1
DBG 14:40:29.668 Query decline state created, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0xf32bed7151ec42123816240bdedf884265824074657d6543c85e930ccb2354d1
DBG 14:40:29.687 Query decline embedded in state channel update, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, channel: 0xf32bed7151ec42123816240bdedf884265824074657d6543c85e930ccb2354d1
ERR 14:40:29.687 Failed to handle paid query, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71, err: Unable to sign the query response attestation
DBG 14:40:29.690 POST /subgraphs/id/QmbS7vmAWXJqsJEnAbvNSBYQXxCUmZWHFQygHPbyb3vy3N 500 57 - 65.309 ms, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:40:30.500 Payload pushed, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:40:30.502 Channel proposals detected. Joining channels., indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:40:31.144 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:40:33.867 Channels joined successfully, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:40:33.872 POST /channel-messages-inbox 200 194972 - 4911.479 ms, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:40:38.715 Payload received, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:40:39.790 Payload pushed, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:40:39.791 Ignoring running channels that aren't on our turn., indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:40:39.792 POST /channel-messages-inbox 200 - - 1080.880 ms, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:40:41.143 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:40:51.144 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:41:01.145 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:41:11.145 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:41:21.145 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:41:23.421 Payload received, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:41:25.330 Payload pushed, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:41:25.331 Channel proposals detected. Joining channels., indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:41:28.939 Channels joined successfully, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:41:28.944 POST /channel-messages-inbox 200 194972 - 5522.845 ms, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:41:31.145 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:41:41.145 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:41:41.346 Active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:41:41.347 Updating attestation signers, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:41:51.145 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:42:01.145 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:42:01.427 Active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:42:01.427 Updating attestation signers, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:42:02.627 Payload received, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:42:03.649 Payload pushed, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:42:03.650 Ignoring running channels that aren't on our turn., indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:42:03.651 POST /channel-messages-inbox 200 - - 1024.958 ms, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:42:11.145 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:42:11.418 Active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
INF 14:42:11.418 Updating attestation signers, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:42:21.145 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:42:31.145 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:42:41.145 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:42:51.145 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:43:01.145 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:43:11.144 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
DBG 14:43:21.145 Refresh active allocations, indexer: 0x59E9AA17AeA53028fD0C2648E86C6125fB5f8b71
Jannis commented 3 years ago

This turned out to be an issue in the gateway, where the gateway would be stuck waiting for a transaction to be mined and would not refresh its allocations for over 18h. As a consequence, its indexer data was out of date and it sent queries to indexers against old allocations. At that point the indexers had already "forgotten" about these allocations and thus didn't have any attestation signers loaded up any more.

The above improvements that I mentioned still apply but I'd rather create a new enhancement issue for this.

Jannis commented 3 years ago

I've created https://github.com/graphprotocol/indexer/issues/123 for the corresponding improvement.