search

graphprotocol / indexer

Graph Protocol indexer components and infrastructure
MIT License
242 stars 133 forks source link

Agent automatically reallocate after closed. #575

Open suntzu93 opened 1 year ago

suntzu93 commented 1 year ago

This bug I reported before in discord but its still unresolved, it wastes gas money + time waiting for another epoch, while i'm trying to support new subgraph.

agent version : 0.20.8

I unallocated by these cmd :

graph indexer actions queue unallocate Qme66ZNMxSdCQKzaDuvS381whCVYCQjf637sGZCqJHAWHB 0xe58e1642a32d3eb3193199b44a4b9f8ba263c5e2 0x775e7bcdf46a33395e0a3a0c62ae8f83b9686f3934a866c1fc3aa4cf65cbe63c true
graph indexer actions queue unallocate QmecPw1iYuu85rtdYL2J2W9qcr6p8ijich9P5GbEAmmbW5 0x16d2101929f62b1c31e7e66ed0bf7f2551c5ead5 0x1d9a270c42a70aea4b837e4ba354db0e8ac778c533a448e6ecb34e9318f1d0c0 true 
graph indexer actions queue unallocate QmQexc4twpqt4nHs73DJTVpjQsCz5U9v8eXRYvMg9qmLjE 0x191d681a4e5ca61fab8010504608a6ed1f9962e2

unallocate was successful, and the agent reallocated to these subgraphs.

Screenshot 2023-01-20 at 06 07 52

Logs :

DBG 23:44:52.083 Execute 'queueActions' mutation 
DBG 23:44:52.173 POST / 200 392 - 123.847 ms 
DBG 23:44:52.595 Execute 'queueActions' mutation 
DBG 23:44:52.665 POST / 200 392 - 103.996 ms 
DBG 23:44:53.091 Execute 'queueActions' mutation 
DBG 23:44:53.163 POST / 200 329 - 104.049 ms 
DBG 23:44:53.607 Execute 'actions' query 
DBG 23:44:53.629 POST / 200 1146 - 42.555 ms 
DBG 23:44:53.652 Execute 'approveActions' mutation 
DBG 23:44:53.660 POST / 200 1096 - 26.536 ms 
DBG 23:45:06.041 Query subgraph deployments in batches of 10 
INF 23:45:06.079 Reconcile with the network 
DBG 23:45:06.101 Execute 'actions' query 
INF 23:45:06.132 There are 3 approved actions awaiting execution, will reconcile with the network once they are executed 
INF 23:45:07.780 Current operator ETH balance 
DBG 23:45:12.491 Finished fetching subgraph deployments published to network 
DBG 23:45:15.743 Auto allocation management executes the batch if at least one requirement is met 
INF 23:45:15.743 Executing batch of approved actions 
INF 23:45:15.749 Preparing to close allocation (unallocate) 
INF 23:45:15.749 Preparing to close allocation (unallocate) 
INF 23:45:15.749 Preparing to close allocation (unallocate) 
DBG 23:45:15.793 Populating closeAllocation transaction 
DBG 23:45:15.794 Populating closeAllocation transaction 
DBG 23:45:16.197 Populating closeAllocation transaction 
WRN 23:45:16.204 Max base fee per gas has been reached, waiting until the base fee falls below to resume transaction execution. 
INF 23:45:46.211 Base gas fee per gas estimation still above max threshold 
INF 23:46:16.270 Sending transaction 
INF 23:46:16.270 Transaction pending 
INF 23:46:55.639 Transaction successfully included in block 
INF 23:46:55.642 Confirming 'closeAllocation' transaction 
INF 23:46:55.652 Successfully closed allocation, deployment: Qme66ZNMxSdCQKzaDuvS381whCVYCQjf637sGZCqJHAWHB, indexer: 0x4167EB613d784C910f5dc0F3f0515D61Ec6EC8DF, allocation: 0xe58E1642A32d3eB3193199B44A4B9f8bA263c5e2 
INF 23:46:55.652 Identifying receipts worth collecting, allocation: 0xe58E1642A32d3eB3193199B44A4B9f8bA263c5e2 
INF 23:46:55.653 Confirming 'closeAllocation' transaction 
INF 23:46:55.655 Successfully closed allocation, deployment: QmecPw1iYuu85rtdYL2J2W9qcr6p8ijich9P5GbEAmmbW5, indexer: 0x4167EB613d784C910f5dc0F3f0515D61Ec6EC8DF, allocation: 0x16d2101929f62B1C31e7e66ED0bF7f2551C5Ead5 
INF 23:46:55.655 Identifying receipts worth collecting, allocation: 0x16d2101929f62B1C31e7e66ED0bF7f2551C5Ead5 
INF 23:46:55.655 Confirming 'closeAllocation' transaction 
INF 23:46:55.657 Successfully closed allocation, deployment: QmQexc4twpqt4nHs73DJTVpjQsCz5U9v8eXRYvMg9qmLjE, indexer: 0x4167EB613d784C910f5dc0F3f0515D61Ec6EC8DF, allocation: 0x191D681a4e5Ca61FAB8010504608A6Ed1F9962e2 
INF 23:46:55.657 Identifying receipts worth collecting, allocation: 0x191D681a4e5Ca61FAB8010504608A6Ed1F9962e2 
DBG 23:46:55.665 Queue allocation receipts for collecting, deployment: Qme66ZNMxSdCQKzaDuvS381whCVYCQjf637sGZCqJHAWHB, allocation: 0xe58E1642A32d3eB3193199B44A4B9f8bA263c5e2 
DBG 23:46:55.665 Queue allocation receipts for collecting, deployment: QmQexc4twpqt4nHs73DJTVpjQsCz5U9v8eXRYvMg9qmLjE, allocation: 0x191D681a4e5Ca61FAB8010504608A6Ed1F9962e2 
DBG 23:46:55.668 Queue allocation receipts for collecting, deployment: QmecPw1iYuu85rtdYL2J2W9qcr6p8ijich9P5GbEAmmbW5, allocation: 0x16d2101929f62B1C31e7e66ED0bF7f2551C5Ead5 
INF 23:46:55.674 Successfully queued allocation receipts for collecting, deployment: Qme66ZNMxSdCQKzaDuvS381whCVYCQjf637sGZCqJHAWHB, allocation: 0xe58E1642A32d3eB3193199B44A4B9f8bA263c5e2 
DBG 23:46:55.674 Updating indexing rules so indexer-agent keeps the deployment synced but doesn't reallocate to it 
INF 23:46:55.677 Successfully queued allocation receipts for collecting, deployment: QmQexc4twpqt4nHs73DJTVpjQsCz5U9v8eXRYvMg9qmLjE, allocation: 0x191D681a4e5Ca61FAB8010504608A6Ed1F9962e2 
DBG 23:46:55.677 Updating indexing rules so indexer-agent keeps the deployment synced but doesn't reallocate to it 
INF 23:46:55.678 Successfully queued allocation receipts for collecting, deployment: QmecPw1iYuu85rtdYL2J2W9qcr6p8ijich9P5GbEAmmbW5, allocation: 0x16d2101929f62B1C31e7e66ED0bF7f2551C5Ead5 
DBG 23:46:55.678 Updating indexing rules so indexer-agent keeps the deployment synced but doesn't reallocate to it 
DBG 23:46:55.679 DecisionBasis.offchain rule merged into indexing rules 
DBG 23:46:55.680 DecisionBasis.offchain rule merged into indexing rules 
DBG 23:46:55.681 DecisionBasis.offchain rule merged into indexing rules 
DBG 23:46:55.681 Completed batch action execution 
INF 23:47:07.778 Current operator ETH balance 
INF 23:47:07.820 Reconcile with the network 
DBG 23:47:07.853 Execute 'actions' query 
DBG 23:47:08.030 Reconcile deployments 
INF 23:47:08.119 No active allocation for deployment, creating one now, deployment: Qme66ZNMxSdCQKzaDuvS381whCVYCQjf637sGZCqJHAWHB 
DBG 23:47:08.151 Execute 'queueActions' mutation 
INF 23:47:08.152 No active allocation for deployment, creating one now, deployment: QmQexc4twpqt4nHs73DJTVpjQsCz5U9v8eXRYvMg9qmLjE 
DBG 23:47:08.183 Execute 'queueActions' mutation 
INF 23:47:08.185 No active allocation for deployment, creating one now, deployment: QmecPw1iYuu85rtdYL2J2W9qcr6p8ijich9P5GbEAmmbW5 
DBG 23:47:08.217 Execute 'queueActions' mutation 
INF 23:47:08.250 Queued allocate action for execution 
INF 23:47:08.268 Queued allocate action for execution 
INF 23:47:08.277 Queued allocate action for execution 
INF 23:47:08.277 Reconcile with the network 
DBG 23:47:08.309 Execute 'actions' query 
INF 23:47:08.345 There are 3 approved actions awaiting execution, will reconcile with the network once they are executed 
INF 23:47:15.892 Reconcile with the network 
DBG 23:47:15.912 Execute 'actions' query 
INF 23:47:15.944 There are 3 approved actions awaiting execution, will reconcile with the network once they are executed 
INF 23:47:15.944 Reconcile with the network 
DBG 23:47:15.963 Execute 'actions' query 
INF 23:47:15.985 There are 3 approved actions awaiting execution, will reconcile with the network once they are executed 
DBG 23:47:16.020 Auto allocation management executes the batch if at least one requirement is met 
INF 23:47:16.020 Executing batch of approved actions 
INF 23:47:16.022 Preparing to allocate, deployment: QmQexc4twpqt4nHs73DJTVpjQsCz5U9v8eXRYvMg9qmLjE 
INF 23:47:16.022 Preparing to allocate, deployment: QmecPw1iYuu85rtdYL2J2W9qcr6p8ijich9P5GbEAmmbW5 
INF 23:47:16.023 Preparing to allocate, deployment: Qme66ZNMxSdCQKzaDuvS381whCVYCQjf637sGZCqJHAWHB 
ERR 23:47:16.034 Allocation of 5417916.0 GRT cancelled: indexer only has a free stake amount of 3708524.612796621516070726 GRT 
ERR 23:47:16.034 Failed to prepare tx call data 
INF 23:47:16.034 Create subgraph name 
INF 23:47:16.039 Successfully created subgraph name 
INF 23:47:16.039 Deploy subgraph, deployment: Qme66ZNMxSdCQKzaDuvS381whCVYCQjf637sGZCqJHAWHB 
INF 23:47:16.041 Create subgraph name 
INF 23:47:16.042 Successfully created subgraph name 
INF 23:47:16.042 Deploy subgraph, deployment: QmQexc4twpqt4nHs73DJTVpjQsCz5U9v8eXRYvMg9qmLjE 
INF 23:47:16.108 Successfully deployed subgraph, deployment: QmQexc4twpqt4nHs73DJTVpjQsCz5U9v8eXRYvMg9qmLjE 
INF 23:47:16.108 Reassign subgraph deployment, deployment: QmQexc4twpqt4nHs73DJTVpjQsCz5U9v8eXRYvMg9qmLjE 
DBG 23:47:16.110 Obtain a unique Allocation ID 
DBG 23:47:16.154 Generating new allocation ID proof 
DBG 23:47:16.155 Successfully generated allocation ID proof 
DBG 23:47:16.155 Populating allocateFrom transaction, indexer: 0x4167EB613d784C910f5dc0F3f0515D61Ec6EC8DF, allocation: 0xAA1D10D727EE90E1f7eE7C36A3528e56648BB78e 
INF 23:47:17.736 Successfully deployed subgraph, deployment: Qme66ZNMxSdCQKzaDuvS381whCVYCQjf637sGZCqJHAWHB 
INF 23:47:17.736 Reassign subgraph deployment, deployment: Qme66ZNMxSdCQKzaDuvS381whCVYCQjf637sGZCqJHAWHB 
DBG 23:47:17.738 Obtain a unique Allocation ID 
DBG 23:47:17.768 Generating new allocation ID proof 
DBG 23:47:17.768 Successfully generated allocation ID proof 
DBG 23:47:17.768 Populating allocateFrom transaction, indexer: 0x4167EB613d784C910f5dc0F3f0515D61Ec6EC8DF, allocation: 0x50576b40153fF0214322e1898F1CcA5DFEB6A652 
DBG 23:47:17.769 Completed batch action execution 
DBG 23:47:46.002 Auto allocation management executes the batch if at least one requirement is met 
INF 23:47:46.002 Executing batch of approved actions 
INF 23:47:46.007 Preparing to allocate, deployment: QmQexc4twpqt4nHs73DJTVpjQsCz5U9v8eXRYvMg9qmLjE 
INF 23:47:46.007 Preparing to allocate, deployment: Qme66ZNMxSdCQKzaDuvS381whCVYCQjf637sGZCqJHAWHB 
INF 23:47:46.046 Create subgraph name 
INF 23:47:46.046 Create subgraph name 
INF 23:47:46.049 Successfully created subgraph name 
INF 23:47:46.049 Deploy subgraph, deployment: Qme66ZNMxSdCQKzaDuvS381whCVYCQjf637sGZCqJHAWHB 
INF 23:47:46.049 Successfully created subgraph name 
INF 23:47:46.049 Deploy subgraph, deployment: QmQexc4twpqt4nHs73DJTVpjQsCz5U9v8eXRYvMg9qmLjE 
INF 23:47:46.180 Successfully deployed subgraph, deployment: Qme66ZNMxSdCQKzaDuvS381whCVYCQjf637sGZCqJHAWHB 
INF 23:47:46.180 Reassign subgraph deployment, deployment: Qme66ZNMxSdCQKzaDuvS381whCVYCQjf637sGZCqJHAWHB 
DBG 23:47:46.182 Obtain a unique Allocation ID 
DBG 23:47:46.237 Generating new allocation ID proof 
DBG 23:47:46.238 Successfully generated allocation ID proof 
DBG 23:47:46.238 Populating allocateFrom transaction, indexer: 0x4167EB613d784C910f5dc0F3f0515D61Ec6EC8DF, allocation: 0x50576b40153fF0214322e1898F1CcA5DFEB6A652 
INF 23:47:47.411 Successfully deployed subgraph, deployment: QmQexc4twpqt4nHs73DJTVpjQsCz5U9v8eXRYvMg9qmLjE 
INF 23:47:47.411 Reassign subgraph deployment, deployment: QmQexc4twpqt4nHs73DJTVpjQsCz5U9v8eXRYvMg9qmLjE 
DBG 23:47:47.414 Obtain a unique Allocation ID 
DBG 23:47:47.474 Generating new allocation ID proof 
DBG 23:47:47.475 Successfully generated allocation ID proof 
DBG 23:47:47.475 Populating allocateFrom transaction, indexer: 0x4167EB613d784C910f5dc0F3f0515D61Ec6EC8DF, allocation: 0xAA1D10D727EE90E1f7eE7C36A3528e56648BB78e 
INF 23:47:47.501 Sending transaction 
INF 23:47:47.501 Transaction pending 
INF 23:48:31.946 Transaction successfully included in block 
INF 23:48:31.947 Confirming 'allocateFrom' transaction 
INF 23:48:31.949 Successfully allocated to subgraph deployment, deployment: 0x226810383a3fc1d31c8a32ace2226636b492f16b96a156951284483a4f7a62dd, allocation: 0xAA1D10D727EE90E1f7eE7C36A3528e56648BB78e 
INF 23:48:31.950 Remember allocations for collecting receipts later 
INF 23:48:31.950 Confirming 'allocateFrom' transaction 
INF 23:48:31.952 Successfully allocated to subgraph deployment, deployment: 0xea0081b34c9d8ae0c52c2131711f093d33bd6efb8638f0a5bbc3da0a08462a46, allocation: 0x50576b40153fF0214322e1898F1CcA5DFEB6A652 
INF 23:48:31.952 Remember allocations for collecting receipts later 
DBG 23:48:32.004 No matching indexing rule found; updating indexing rules so indexer-agent will now manage the active allocation 
DBG 23:48:32.008 DecisionBasis.always rule merged into indexing rules 
DBG 23:48:32.015 No matching indexing rule found; updating indexing rules so indexer-agent will now manage the active allocation 
DBG 23:48:32.017 DecisionBasis.always rule merged into indexing rules 
DBG 23:48:32.017 Completed batch action execution 
INF 23:48:36.258 Reconcile with the network 
DBG 23:48:36.291 Execute 'actions' query 
DBG 23:48:36.469 Reconcile deployments 
INF 23:48:36.561 No active allocation for deployment, creating one now, deployment: QmQexc4twpqt4nHs73DJTVpjQsCz5U9v8eXRYvMg9qmLjE 
DBG 23:48:36.601 Execute 'queueActions' mutation 
INF 23:48:36.603 No active allocation for deployment, creating one now, deployment: Qme66ZNMxSdCQKzaDuvS381whCVYCQjf637sGZCqJHAWHB 
DBG 23:48:36.644 Execute 'queueActions' mutation 
WRN 23:48:36.655 Recently executed 'allocate' action found in queue targeting 'QmQexc4twpqt4nHs73DJTVpjQsCz5U9v8eXRYvMg9qmLjE', ignoring. 
WRN 23:48:36.670 Exited early while reconciling deployments/allocations, err: Failed to reconcile indexer and network 
INF 23:48:36.671 Reconcile with the network 
DBG 23:48:36.707 Execute 'actions' query 
WRN 23:48:36.708 Recently executed 'allocate' action found in queue targeting 'Qme66ZNMxSdCQKzaDuvS381whCVYCQjf637sGZCqJHAWHB', ignoring. 
DBG 23:48:36.910 Reconcile deployments 
INF 23:48:37.005 No active allocation for deployment, creating one now, deployment: QmQexc4twpqt4nHs73DJTVpjQsCz5U9v8eXRYvMg9qmLjE 
DBG 23:48:37.039 Execute 'queueActions' mutation 
INF 23:48:37.041 No active allocation for deployment, creating one now, deployment: Qme66ZNMxSdCQKzaDuvS381whCVYCQjf637sGZCqJHAWHB 
DBG 23:48:37.074 Execute 'queueActions' mutation 
WRN 23:48:37.082 Recently executed 'allocate' action found in queue targeting 'Qme66ZNMxSdCQKzaDuvS381whCVYCQjf637sGZCqJHAWHB', ignoring. 
WRN 23:48:37.090 Exited early while reconciling deployments/allocations, err: Failed to reconcile indexer and network 
WRN 23:48:37.090 Recently executed 'allocate' action found in queue targeting 'QmQexc4twpqt4nHs73DJTVpjQsCz5U9v8eXRYvMg9qmLjE', ignoring. 
DBG 23:49:06.041 Query subgraph deployments in batches of 10 
INF 23:49:06.078 Reconcile with the network 
DBG 23:49:06.118 Execute 'actions' query 
DBG 23:49:06.326 Reconcile deployments 
INF 23:49:06.418 No active allocation for deployment, creating one now, deployment: Qme66ZNMxSdCQKzaDuvS381whCVYCQjf637sGZCqJHAWHB 
DBG 23:49:06.459 Execute 'queueActions' mutation 
INF 23:49:06.460 No active allocation for deployment, creating one now, deployment: QmQexc4twpqt4nHs73DJTVpjQsCz5U9v8eXRYvMg9qmLjE 
DBG 23:49:06.500 Execute 'queueActions' mutation 
WRN 23:49:06.534 Recently executed 'allocate' action found in queue targeting 'QmQexc4twpqt4nHs73DJTVpjQsCz5U9v8eXRYvMg9qmLjE', ignoring. 
WRN 23:49:06.544 Exited early while reconciling deployments/allocations, err: Failed to reconcile indexer and network 
WRN 23:49:06.549 Recently executed 'allocate' action found in queue targeting 'Qme66ZNMxSdCQKzaDuvS381whCVYCQjf637sGZCqJHAWHB', ignoring. 
INF 23:49:07.778 Current operator ETH balance 
INF 23:49:07.816 Reconcile with the network 
DBG 23:49:07.848 Execute 'actions' query
hopeyen commented 1 year ago

Weird, the log for successfully updating the indexing rules such that allocations do not reallocate should also printing out the updated rule, but I didn't see that here 

DBG 23:46:55.679 DecisionBasis.offchain rule merged into indexing rules

Do you have the details of that log to share? I wonder if the rules weren't actually merged which would explain why agent still think there should be active allocations. They should look something like 

DEBUG (IndexerAgent/4358 on book): DecisionBasis.offchain rule merged into indexing rules
component: "AllocationManager"
    action: 33
    rule: {
      "id": ...,
      "identifier": ...
      "identifierType": ...,
      "allocationAmount": ...,
      "allocationLifetime": ...,
      "autoRenewal": ...,
      "parallelAllocations": ...,
      "maxAllocationPercentage": ...,
      "minSignal": ...,
      "minStake": ...,
      "maxSignal": ...,
      "minAverageQueryFees": ...,
      "custom": ...,
      "decisionBasis": "offchain",
      "requireSupported": ...,
      "createdAt": "2023-01-12T13:40:07.384Z",
      "updatedAt": "2023-01-20T03:30:52.740Z"
     }
suntzu93 commented 1 year ago

Another logs with graph-pino from 2 months ago : Log

I'm keeping a log of graph-pino usage so it's not as detailed as you want, I've removed graph-pino so if I get the error again there will be details.

hopeyen commented 1 year ago

Thanks, please do share when you get the error again. In the meantime, to avoid waiting gas, it might be a good idea to use the oversight management mode so that actions created by the agent are manually approved before executing.

datanexus-vincent commented 1 year ago

I've also been getting this abnormal behavior. Most recently when trying to unallocate while gas was higher than my max base fee. Once the gas prices came back down, it unallocated, then immediately reallocated. Unfortunately I don't have the most verbose logs set, but here are the logs anyway. I removed lines related to reconciling deployments and AllocationReceiptCollector.

Logs: https://gist.github.com/datanexus-vincent/1b894e86a8b87519e785c94084ff908e

Thanks, please do share when you get the error again. In the meantime, to avoid waiting gas, it might be a good idea to use the oversight management mode so that actions created by the agent are manually approved before executing.

The different management modes slipped my mind, though, so I'll get that set in the meantime. Thanks!

I'd still love it if this bug could be tracked down though. It's quite useful to not have to worry about allocations expiring and being force closed. If I can be helpful in any way with tracking this down, please let me know.

uzzer commented 1 year ago

I am also having an issue that indexer does not work and clear indication is a missing balance INF 23:45:07.780 Current operator ETH balance

Perhaps you have an idea how to fix it?