search

ava-labs / hypersdk

Opinionated Framework for Building Hyper-Scalable Blockchains on Avalanche
Other
197 stars 101 forks source link

Sync Readiness Not Triggering after State Sync Reboot #262

Closed patrick-ogrady closed 1 year ago

patrick-ogrady commented 1 year ago

In E2E tests, occasionally the sync engine will not trigger readiness.

[sync] [07-22|16:43:19.622] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 3601, "responseLen": 18}
waiting for health check to pass...broadcasting tx while waiting: rpc error: code = Unknown desc = node "sync" failed to become healthy within timeout, or network stopped
[sync] [07-22|16:43:19.724] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 3602, "responseLen": 18}
[sync] [07-22|16:43:19.727] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:579 parsed block {"id": "c15J1VXYTcJT8JNQDeKTFZPfEvm6FHFTUXeRJ1UwnA8apivWU", "height": 1450}
[bootstrap] [07-22|16:43:19.728] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:579 parsed block {"id": "c15J1VXYTcJT8JNQDeKTFZPfEvm6FHFTUXeRJ1UwnA8apivWU", "height": 1450}
[bootstrap] [07-22|16:43:19.729] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> chain/block.go:439 verify context {"height": 1450, "unit price": 1}
[sync] [07-22|16:43:19.729] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> chain/block.go:317 skipping verification, state not ready {"height": 1450, "blkID": "c15J1VXYTcJT8JNQDeKTFZPfEvm6FHFTUXeRJ1UwnA8apivWU"}
[sync] [07-22|16:43:19.729] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/resolutions.go:113 verified block {"blkID": "c15J1VXYTcJT8JNQDeKTFZPfEvm6FHFTUXeRJ1UwnA8apivWU", "height": 1450, "txs": 1, "state ready": false}
[bootstrap] [07-22|16:43:19.729] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/resolutions.go:113 verified block {"blkID": "c15J1VXYTcJT8JNQDeKTFZPfEvm6FHFTUXeRJ1UwnA8apivWU", "height": 1450, "txs": 1, "state ready": true}
[sync] [07-22|16:43:19.734] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> chain/block.go:594 updated state sync target {"id": "c15J1VXYTcJT8JNQDeKTFZPfEvm6FHFTUXeRJ1UwnA8apivWU", "root": "2WvRwXF3tPhPNzkiZ3xSamoXzwg1o4EbwE7E4WJj8DXdsmq22N"}
[bootstrap] [07-22|16:43:19.735] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/resolutions.go:263 accepted block {"blkID": "c15J1VXYTcJT8JNQDeKTFZPfEvm6FHFTUXeRJ1UwnA8apivWU", "height": 1450, "txs": 1, "size": 378, "units": 440, "dropped mempool txs": 0, "state ready": true}
[bootstrap] [07-22|16:43:19.735] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/resolutions.go:200 block processed {"blkID": "c15J1VXYTcJT8JNQDeKTFZPfEvm6FHFTUXeRJ1UwnA8apivWU", "height": 1450}
[sync] [07-22|16:43:19.825] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 3603, "responseLen": 18}
patrick-ogrady commented 1 year ago

This occurs on node restart:

2023-07-22T16:35:40.1871895Z [sync] [07-22|16:35:40.187] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> syncer/state_syncer.go:389 starting state sync
2023-07-22T16:35:40.1873937Z [sync] [07-22|16:35:40.187] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:382 state sync started
2023-07-22T16:35:40.1883461Z [sync] [07-22|16:35:40.188] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> syncer/state_syncer.go:415 starting state sync
2023-07-22T16:35:40.1898897Z [sync] [07-22|16:35:40.189] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/syncervm_server.go:47 parsed state summary {"summary": "1426:YVPjDeS6bLFWxbNdtjSeTRJowH6benoic5C12kLGNNiGKDTLA root=2JneVzxCQpc8bi8qG2ZXmLeV5RyXmyEU5pEGPVwZFfJPPUiGRb"}
2023-07-22T16:35:40.1902424Z [sync] [07-22|16:35:40.190] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:579 parsed block {"id": "YVPjDeS6bLFWxbNdtjSeTRJowH6benoic5C12kLGNNiGKDTLA", "height": 1426}
2023-07-22T16:35:40.1905646Z [sync] [07-22|16:35:40.190] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/syncervm_server.go:47 parsed state summary {"summary": "1426:YVPjDeS6bLFWxbNdtjSeTRJowH6benoic5C12kLGNNiGKDTLA root=2JneVzxCQpc8bi8qG2ZXmLeV5RyXmyEU5pEGPVwZFfJPPUiGRb"}
2023-07-22T16:35:40.1908352Z [sync] [07-22|16:35:40.190] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/syncervm_server.go:47 parsed state summary {"summary": "1426:YVPjDeS6bLFWxbNdtjSeTRJowH6benoic5C12kLGNNiGKDTLA root=2JneVzxCQpc8bi8qG2ZXmLeV5RyXmyEU5pEGPVwZFfJPPUiGRb"}
2023-07-22T16:35:40.1911422Z [sync] [07-22|16:35:40.190] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/syncervm_server.go:47 parsed state summary {"summary": "1426:YVPjDeS6bLFWxbNdtjSeTRJowH6benoic5C12kLGNNiGKDTLA root=2JneVzxCQpc8bi8qG2ZXmLeV5RyXmyEU5pEGPVwZFfJPPUiGRb"}
2023-07-22T16:35:40.1915056Z [sync] [07-22|16:35:40.191] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/syncervm_server.go:47 parsed state summary {"summary": "1426:YVPjDeS6bLFWxbNdtjSeTRJowH6benoic5C12kLGNNiGKDTLA root=2JneVzxCQpc8bi8qG2ZXmLeV5RyXmyEU5pEGPVwZFfJPPUiGRb"}
2023-07-22T16:35:40.1928148Z [sync] [07-22|16:35:40.192] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/syncervm_server.go:47 parsed state summary {"summary": "1426:YVPjDeS6bLFWxbNdtjSeTRJowH6benoic5C12kLGNNiGKDTLA root=2JneVzxCQpc8bi8qG2ZXmLeV5RyXmyEU5pEGPVwZFfJPPUiGRb"}
2023-07-22T16:35:40.1929351Z [sync] [07-22|16:35:40.192] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/syncervm_client.go:111 starting state sync {"height": 1426, "summary": "1426:YVPjDeS6bLFWxbNdtjSeTRJowH6benoic5C12kLGNNiGKDTLA root=2JneVzxCQpc8bi8qG2ZXmLeV5RyXmyEU5pEGPVwZFfJPPUiGRb", "already syncing": false}
2023-07-22T16:35:40.1930076Z [sync] [07-22|16:35:40.192] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:35:40.1931059Z [sync] [07-22|16:35:40.192] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/resolutions.go:263 accepted block {"blkID": "YVPjDeS6bLFWxbNdtjSeTRJowH6benoic5C12kLGNNiGKDTLA", "height": 1426, "txs": 4, "size": 948, "units": 1760, "dropped mempool txs": 0, "state ready": false}
2023-07-22T16:35:40.1932130Z [sync] [07-22|16:35:40.192] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/resolutions.go:153 skipping unprocessed block {"height": 1426}
2023-07-22T16:35:40.1932930Z [sync] [07-22|16:35:40.192] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> syncer/state_syncer.go:316 accepted state summary {"summaryID": "2qvQfr25ngbzcefzvc2CnMuXPbYeXciBBxpMg7Qsaz6MRrtmiR", "syncMode": "Dynamic", "numTotalSummaries": 1}
2023-07-22T16:35:40.1933603Z [sync] [07-22|16:35:40.192] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> bootstrap/bootstrapper.go:115 starting bootstrapper
2023-07-22T16:35:40.1934403Z [sync] [07-22|16:35:40.193] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:405 bootstrapping started {"state sync started": true}
2023-07-22T16:35:40.1942977Z [sync] [07-22|16:35:40.194] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> common/bootstrapper.go:254 bootstrapping started syncing {"numVerticesInFrontier": 1}
2023-07-22T16:35:40.1943616Z [sync] [07-22|16:35:40.194] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> bootstrap/bootstrapper.go:554 executing blocks {"numPendingJobs": 0}
2023-07-22T16:35:40.1944188Z [sync] [07-22|16:35:40.194] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> queue/jobs.go:224 executed operations {"numExecuted": 0}
2023-07-22T16:35:40.1947919Z [sync] [07-22|16:35:40.194] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> snowman/transitive.go:400 consensus starting {"lastAcceptedBlock": "2L38nK1cHQvTrEUhWQMp52aSvEayG876KwhJtC2TRfjm38J2Bd"}
2023-07-22T16:35:40.1948842Z [sync] [07-22|16:35:40.194] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:409 normal operation started {"state sync started": true}
2023-07-22T16:35:40.3003376Z [sync] [07-22|16:35:40.300] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 0, "responseLen": 98478}
2023-07-22T16:35:40.3385911Z [sync] [07-22|16:35:40.338] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "", "end": "ABCH"}
2023-07-22T16:35:40.3805731Z [bootstrap] [07-22|16:35:40.380] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:579 parsed block {"id": "2eKg5a8CB2WJGTCkbH7QLYWUJkmkGRXJborhS6ti8yLx11cqnY", "height": 1427}
2023-07-22T16:35:40.3807175Z [sync] [07-22|16:35:40.380] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:579 parsed block {"id": "2eKg5a8CB2WJGTCkbH7QLYWUJkmkGRXJborhS6ti8yLx11cqnY", "height": 1427}
2023-07-22T16:35:40.3820185Z [bootstrap] [07-22|16:35:40.381] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> chain/block.go:439 verify context {"height": 1427, "unit price": 1}
2023-07-22T16:35:40.3823127Z [sync] [07-22|16:35:40.382] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> chain/block.go:317 skipping verification, state not ready {"height": 1427, "blkID": "2eKg5a8CB2WJGTCkbH7QLYWUJkmkGRXJborhS6ti8yLx11cqnY"}
2023-07-22T16:35:40.3824112Z [sync] [07-22|16:35:40.382] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/resolutions.go:113 verified block {"blkID": "2eKg5a8CB2WJGTCkbH7QLYWUJkmkGRXJborhS6ti8yLx11cqnY", "height": 1427, "txs": 4, "state ready": false}
2023-07-22T16:35:40.3825143Z [bootstrap] [07-22|16:35:40.382] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/resolutions.go:113 verified block {"blkID": "2eKg5a8CB2WJGTCkbH7QLYWUJkmkGRXJborhS6ti8yLx11cqnY", "height": 1427, "txs": 4, "state ready": true}
2023-07-22T16:35:40.3880137Z [bootstrap] [07-22|16:35:40.387] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/resolutions.go:263 accepted block {"blkID": "2eKg5a8CB2WJGTCkbH7QLYWUJkmkGRXJborhS6ti8yLx11cqnY", "height": 1427, "txs": 4, "size": 948, "units": 1760, "dropped mempool txs": 0, "state ready": true}
2023-07-22T16:35:40.3881120Z [bootstrap] [07-22|16:35:40.387] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/resolutions.go:200 block processed {"blkID": "2eKg5a8CB2WJGTCkbH7QLYWUJkmkGRXJborhS6ti8yLx11cqnY", "height": 1427}
2023-07-22T16:35:40.3885780Z [sync] [07-22|16:35:40.388] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> chain/block.go:594 updated state sync target {"id": "2eKg5a8CB2WJGTCkbH7QLYWUJkmkGRXJborhS6ti8yLx11cqnY", "root": "25brDB1cyAAdELwG1PAgw37mQFqsw4gpq3k9e7Rag4PAeakqjj"}
2023-07-22T16:35:40.4401034Z [sync] [07-22|16:35:40.439] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-A5GNnGLY96XzzQfjKSFU2m67rDvoKh8c5", "requestID": 1, "responseLen": 54}
2023-07-22T16:35:40.4402491Z [sync] [07-22|16:35:40.440] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "gAhD", "end": ""}
2023-07-22T16:35:40.4461060Z [sync] [07-22|16:35:40.445] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 2, "responseLen": 100147}
2023-07-22T16:35:40.4788312Z [sync] [07-22|16:35:40.478] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "ABCH", "end": "ACGn"}
2023-07-22T16:35:40.4902585Z [sync] [07-22|16:35:40.489] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-FZ4uKBNjztHA1zt2PQ7BdtXCyxdzynnda", "requestID": 3, "responseLen": 18}
2023-07-22T16:35:40.5421937Z [sync] [07-22|16:35:40.541] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-7ahuhysKthMLShd8EJHA1YnY2xY1w3LCY", "requestID": 4, "responseLen": 58}
2023-07-22T16:35:40.5422898Z [sync] [07-22|16:35:40.541] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "wAQh", "end": ""}
2023-07-22T16:35:40.5423878Z [sync] [07-22|16:35:40.542] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 5, "responseLen": 58}
2023-07-22T16:35:40.5424751Z [sync] [07-22|16:35:40.542] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "gAhD", "end": "wAQh"}
2023-07-22T16:35:40.5857049Z [sync] [07-22|16:35:40.585] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 6, "responseLen": 100071}
2023-07-22T16:35:40.6022916Z [sync] [07-22|16:35:40.602] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-A5GNnGLY96XzzQfjKSFU2m67rDvoKh8c5", "requestID": 7, "responseLen": 18}
2023-07-22T16:35:40.6196963Z [sync] [07-22|16:35:40.619] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "ACGn", "end": "ADIg"}
2023-07-22T16:35:40.6440953Z [sync] [07-22|16:35:40.643] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-7ahuhysKthMLShd8EJHA1YnY2xY1w3LCY", "requestID": 8, "responseLen": 3053}
2023-07-22T16:35:40.6442486Z [sync] [07-22|16:35:40.643] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 9, "responseLen": 3155}
2023-07-22T16:35:40.6443557Z [sync] [07-22|16:35:40.644] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "ABCH", "end": "ABkX"}
2023-07-22T16:35:40.6445668Z [sync] [07-22|16:35:40.644] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "ABkX", "end": "ACGn"}
2023-07-22T16:35:40.7246798Z [sync] [07-22|16:35:40.724] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-A5GNnGLY96XzzQfjKSFU2m67rDvoKh8c5", "requestID": 11, "responseLen": 18}
2023-07-22T16:35:40.7302879Z [sync] [07-22|16:35:40.729] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 10, "responseLen": 100110}
2023-07-22T16:35:40.7460455Z [sync] [07-22|16:35:40.745] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 12, "responseLen": 54}
2023-07-22T16:35:40.7461446Z [sync] [07-22|16:35:40.745] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "ICOKfw==", "end": "QBT1"}
2023-07-22T16:35:40.7462622Z [sync] [07-22|16:35:40.745] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-7ahuhysKthMLShd8EJHA1YnY2xY1w3LCY", "requestID": 13, "responseLen": 54}
2023-07-22T16:35:40.7463457Z [sync] [07-22|16:35:40.746] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "QBT1", "end": "gAhD"}
2023-07-22T16:35:40.7616697Z [sync] [07-22|16:35:40.761] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "ADIg", "end": "AEJw"}
2023-07-22T16:35:40.8579810Z [sync] [07-22|16:35:40.857] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-7ahuhysKthMLShd8EJHA1YnY2xY1w3LCY", "requestID": 14, "responseLen": 18}
2023-07-22T16:35:40.8632145Z [sync] [07-22|16:35:40.862] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 15, "responseLen": 54}
2023-07-22T16:35:40.8637164Z [sync] [07-22|16:35:40.863] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "EDL9P38=", "end": "ICOKfw=="}
2023-07-22T16:35:40.8688541Z [sync] [07-22|16:35:40.868] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 16, "responseLen": 100208}
2023-07-22T16:35:40.9023661Z [sync] [07-22|16:35:40.902] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AEJw", "end": "AFOs"}
2023-07-22T16:35:41.0040735Z [sync] [07-22|16:35:41.003] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 17, "responseLen": 676}
2023-07-22T16:35:41.0041548Z [sync] [07-22|16:35:41.003] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "CENUn79/", "end": "EDL9P38="}
2023-07-22T16:35:41.0092072Z [sync] [07-22|16:35:41.009] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 19, "responseLen": 18}
2023-07-22T16:35:41.0093179Z [sync] [07-22|16:35:41.009] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 18, "responseLen": 100208}
2023-07-22T16:35:41.0469912Z [sync] [07-22|16:35:41.046] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AFOs", "end": "AGSY"}
2023-07-22T16:35:41.1486267Z [sync] [07-22|16:35:41.148] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 20, "responseLen": 676}
2023-07-22T16:35:41.1487081Z [sync] [07-22|16:35:41.148] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "BFP2T9+/fw==", "end": "CENUn79/"}
2023-07-22T16:35:41.1533466Z [sync] [07-22|16:35:41.153] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 21, "responseLen": 100094}
2023-07-22T16:35:41.1821636Z [sync] [07-22|16:35:41.181] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-7ahuhysKthMLShd8EJHA1YnY2xY1w3LCY", "requestID": 22, "responseLen": 18}
2023-07-22T16:35:41.1839782Z [sync] [07-22|16:35:41.183] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/proposer_monitor.go:82 refreshed proposer monitor {"previous": 0, "new": 21, "t": "721.874µs"}
2023-07-22T16:35:41.1843745Z [sync] [07-22|16:35:41.184] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:41.1896239Z [sync] [07-22|16:35:41.189] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AGSY", "end": "AHWQ"}
2023-07-22T16:35:41.2915669Z [sync] [07-22|16:35:41.291] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 23, "responseLen": 676}
2023-07-22T16:35:41.2918477Z [sync] [07-22|16:35:41.291] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AmTDJ+/fv38=", "end": "BFP2T9+/fw=="}
2023-07-22T16:35:41.2955438Z [sync] [07-22|16:35:41.295] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 24, "responseLen": 100132}
2023-07-22T16:35:41.3304245Z [sync] [07-22|16:35:41.330] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AHWQ", "end": "AIZg"}
2023-07-22T16:35:41.3952367Z [sync] [07-22|16:35:41.394] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 25, "responseLen": 18}
2023-07-22T16:35:41.4324521Z [sync] [07-22|16:35:41.432] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 26, "responseLen": 676}
2023-07-22T16:35:41.4325783Z [sync] [07-22|16:35:41.432] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AXWRk/fv379/", "end": "AmTDJ+/fv38="}
2023-07-22T16:35:41.4371906Z [sync] [07-22|16:35:41.436] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-A5GNnGLY96XzzQfjKSFU2m67rDvoKh8c5", "requestID": 27, "responseLen": 100079}
2023-07-22T16:35:41.4663574Z [sync] [07-22|16:35:41.466] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AIZg", "end": "AJcD"}
2023-07-22T16:35:41.5679587Z [sync] [07-22|16:35:41.567] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 28, "responseLen": 676}
2023-07-22T16:35:41.5681384Z [sync] [07-22|16:35:41.567] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AQZKSfv379+/fw==", "end": "AXWRk/fv379/"}
2023-07-22T16:35:41.5730400Z [sync] [07-22|16:35:41.572] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-7ahuhysKthMLShd8EJHA1YnY2xY1w3LCY", "requestID": 29, "responseLen": 100170}
2023-07-22T16:35:41.6109072Z [sync] [07-22|16:35:41.610] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AJcD", "end": "AKfg"}
2023-07-22T16:35:41.6681286Z [sync] [07-22|16:35:41.667] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 30, "responseLen": 18}
2023-07-22T16:35:41.7395658Z [sync] [07-22|16:35:41.739] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 31, "responseLen": 99889}
2023-07-22T16:35:41.7679296Z [sync] [07-22|16:35:41.767] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 32, "responseLen": 99980}
2023-07-22T16:35:41.7787115Z [sync] [07-22|16:35:41.778] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "ANcVJP379+/fv38=", "end": "AOfc"}
2023-07-22T16:35:41.8034484Z [sync] [07-22|16:35:41.803] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AKfg", "end": "ALhY"}
2023-07-22T16:35:41.8832442Z [sync] [07-22|16:35:41.883] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 33, "responseLen": 53678}
2023-07-22T16:35:41.8847850Z [sync] [07-22|16:35:41.884] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-7ahuhysKthMLShd8EJHA1YnY2xY1w3LCY", "requestID": 34, "responseLen": 89369}
2023-07-22T16:35:41.9098000Z [sync] [07-22|16:35:41.909] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 35, "responseLen": 91764}
2023-07-22T16:35:41.9134874Z [sync] [07-22|16:35:41.913] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "APcTJP379+/fv38=", "end": "AQZKSfv379+/fw=="}
2023-07-22T16:35:41.9347727Z [sync] [07-22|16:35:41.934] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AOfc", "end": "APcTJP379+/fv38="}
2023-07-22T16:35:41.9633586Z [sync] [07-22|16:35:41.963] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "ALhY", "end": "AMe2kn79+/fv379/"}
2023-07-22T16:35:42.0106721Z [sync] [07-22|16:35:42.010] INFO health/worker.go:258 check started passing {"namespace": "health", "name": "network", "tags": ["application"]}
2023-07-22T16:35:42.0107355Z [sync] [07-22|16:35:42.010] INFO health/worker.go:258 check started passing {"namespace": "health", "name": "C", "tags": ["11111111111111111111111111111111LpoYY"]}
2023-07-22T16:35:42.0107889Z [sync] [07-22|16:35:42.010] INFO health/worker.go:258 check started passing {"namespace": "health", "name": "X", "tags": ["11111111111111111111111111111111LpoYY"]}
2023-07-22T16:35:42.0108430Z [sync] [07-22|16:35:42.010] INFO health/worker.go:258 check started passing {"namespace": "health", "name": "P", "tags": ["11111111111111111111111111111111LpoYY"]}
2023-07-22T16:35:42.0109121Z [sync] [07-22|16:35:42.010] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:35:42.0194149Z [sync] [07-22|16:35:42.019] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 36, "responseLen": 94969}
2023-07-22T16:35:42.0202745Z [sync] [07-22|16:35:42.020] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 37, "responseLen": 18}
2023-07-22T16:35:42.0499021Z [sync] [07-22|16:35:42.049] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AMe2kn79+/fv379/", "end": "ANcVJP379+/fv38="}
2023-07-22T16:35:42.0814905Z [sync] INFO [07-22|16:35:42.081] <C Chain> github.com/ava-labs/coreth/plugin/evm/syncervm_client.go:171: last accepted too close to most recent syncable block, skipping state sync lastAccepted=0 syncableHeight=0
2023-07-22T16:35:42.0816038Z [sync] INFO [07-22|16:35:42.081] <C Chain> github.com/ava-labs/coreth/core/blockchain.go:1728: Initializing snapshots async=false rebuild=true headHash=b81c22..0e6bb9 headRoot=3cbfcc..68c8b4
2023-07-22T16:35:42.0817134Z [sync] [07-22|16:35:42.081] INFO <C Chain> syncer/state_syncer.go:316 accepted state summary {"summaryID": "kvdtVofKwGTkgt3Pna4eqGv8obiXqCC719YzbR9nFL6F6YKjj", "syncMode": "Skipped", "numTotalSummaries": 1}
2023-07-22T16:35:42.0817714Z [sync] [07-22|16:35:42.081] INFO <C Chain> bootstrap/bootstrapper.go:115 starting bootstrapper
2023-07-22T16:35:42.0828617Z [sync] [07-22|16:35:42.082] INFO <C Chain> common/bootstrapper.go:254 bootstrapping started syncing {"numVerticesInFrontier": 1}
2023-07-22T16:35:42.0829124Z [sync] [07-22|16:35:42.082] INFO <C Chain> bootstrap/bootstrapper.go:554 executing blocks {"numPendingJobs": 0}
2023-07-22T16:35:42.0829557Z [sync] [07-22|16:35:42.082] INFO <C Chain> queue/jobs.go:224 executed operations {"numExecuted": 0}
2023-07-22T16:35:42.0830025Z [sync] [07-22|16:35:42.082] INFO <C Chain> bootstrap/bootstrapper.go:599 waiting for the remaining chains in this subnet to finish syncing
2023-07-22T16:35:42.0859856Z [sync] [07-22|16:35:42.085] INFO <X Chain> common/bootstrapper.go:254 bootstrapping started syncing {"numVerticesInFrontier": 1}
2023-07-22T16:35:42.0861055Z [sync] [07-22|16:35:42.085] INFO <X Chain> bootstrap/bootstrapper.go:554 executing blocks {"numPendingJobs": 0}
2023-07-22T16:35:42.0861569Z [sync] [07-22|16:35:42.085] INFO <X Chain> queue/jobs.go:224 executed operations {"numExecuted": 0}
2023-07-22T16:35:42.0862238Z [sync] [07-22|16:35:42.086] INFO <X Chain> snowman/transitive.go:400 consensus starting {"lastAcceptedBlock": "2o79tLyefpG4rKwecqqAX7MudkuPgrq1NqpTm8Yh1UoDQjmJ7t"}
2023-07-22T16:35:42.0863288Z [sync] [07-22|16:35:42.086] INFO <C Chain> snowman/transitive.go:400 consensus starting {"lastAcceptedBlock": "2Q5qkGvLuJyg7UAp1khitQ2WUScBzEjiUf68T8sQYjUm7U97xS"}
2023-07-22T16:35:42.0864001Z [sync] [07-22|16:35:42.086] INFO <P Chain> snowman/transitive.go:400 consensus starting {"lastAcceptedBlock": "QRdYMLzmJo7hVNfRVxjF1rNHgXwCA3fFyQ2PcmXfXNBR1Uw7p"}
2023-07-22T16:35:42.1839840Z [sync] [07-22|16:35:42.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:42.5033072Z [sync] [07-22|16:35:42.502] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-A5GNnGLY96XzzQfjKSFU2m67rDvoKh8c5", "requestID": 38, "responseLen": 18}
2023-07-22T16:35:43.1761113Z [sync] [07-22|16:35:43.175] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 39, "responseLen": 18}
2023-07-22T16:35:43.1834525Z [sync] [07-22|16:35:43.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:44.0113238Z [sync] [07-22|16:35:44.011] INFO health/worker.go:258 check started passing {"namespace": "readiness", "name": "bootstrapped", "tags": ["application"]}
2023-07-22T16:35:44.0113997Z [sync] [07-22|16:35:44.011] INFO health/worker.go:258 check started passing {"namespace": "health", "name": "bootstrapped", "tags": ["application"]}
2023-07-22T16:35:44.0114702Z [sync] [07-22|16:35:44.011] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:35:44.1386720Z [sync] [07-22|16:35:44.138] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 40, "responseLen": 18}
2023-07-22T16:35:44.1836871Z [sync] [07-22|16:35:44.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:45.1837880Z [sync] [07-22|16:35:45.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:45.2412028Z [sync] [07-22|16:35:45.240] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 41, "responseLen": 18}
2023-07-22T16:35:46.0107576Z [sync] [07-22|16:35:46.010] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:35:46.1833987Z [sync] [07-22|16:35:46.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:46.3431461Z [sync] [07-22|16:35:46.342] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 42, "responseLen": 18}
2023-07-22T16:35:47.1843955Z [sync] [07-22|16:35:47.184] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:47.4478433Z [sync] [07-22|16:35:47.445] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-7ahuhysKthMLShd8EJHA1YnY2xY1w3LCY", "requestID": 43, "responseLen": 18}
2023-07-22T16:35:48.0115909Z [sync] [07-22|16:35:48.011] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:35:48.1843132Z [sync] [07-22|16:35:48.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:48.5486748Z [sync] [07-22|16:35:48.548] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 44, "responseLen": 18}
2023-07-22T16:35:49.1837550Z [sync] [07-22|16:35:49.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:49.6223010Z [07-22|16:35:49.622] INFO client/client.go:206 health
2023-07-22T16:35:49.6225753Z [07-22|16:35:49.622] DEBUG server/server.go:817 Health
2023-07-22T16:35:49.6226422Z [07-22|16:35:49.622] INFO server/server.go:823 waiting for local cluster readiness
2023-07-22T16:35:49.6226853Z [07-22|16:35:49.622] INFO ux/output.go:13 waiting for all nodes to report healthy...
2023-07-22T16:35:49.6227279Z [07-22|16:35:49.622] INFO local/network.go:666 checking local network healthiness {"num-of-nodes": 12}
2023-07-22T16:35:49.6233861Z [07-22|16:35:49.623] DEBUG local/network.go:706 node became healthy {"name": "node5"}
2023-07-22T16:35:49.6234343Z [07-22|16:35:49.623] DEBUG local/network.go:706 node became healthy {"name": "node1"}
2023-07-22T16:35:49.6234808Z [07-22|16:35:49.623] DEBUG local/network.go:706 node became healthy {"name": "node3"}
2023-07-22T16:35:49.6235177Z [07-22|16:35:49.623] DEBUG local/network.go:706 node became healthy {"name": "node2"}
2023-07-22T16:35:49.6235893Z [07-22|16:35:49.623] DEBUG local/network.go:706 node became healthy {"name": "node4"}
2023-07-22T16:35:49.6236251Z [07-22|16:35:49.623] DEBUG local/network.go:706 node became healthy {"name": "node3-bls"}
2023-07-22T16:35:49.6236620Z [07-22|16:35:49.623] DEBUG local/network.go:706 node became healthy {"name": "bootstrap"}
2023-07-22T16:35:49.6236985Z [07-22|16:35:49.623] DEBUG local/network.go:706 node became healthy {"name": "node1-bls"}
2023-07-22T16:35:49.6237499Z [07-22|16:35:49.623] DEBUG local/network.go:706 node became healthy {"name": "node4-bls"}
2023-07-22T16:35:49.6237856Z [07-22|16:35:49.623] DEBUG local/network.go:706 node became healthy {"name": "node2-bls"}
2023-07-22T16:35:49.6238435Z [07-22|16:35:49.623] DEBUG local/network.go:706 node became healthy {"name": "node5-bls"}
2023-07-22T16:35:49.6241388Z [sync] [07-22|16:35:49.623] WARN health/health.go:111 failing check {"namespace": "health", "reason": {"C":{"message":{"engine":{"consensus":{"longestRunningBlock":"0s","outstandingBlocks":0},"vm":null},"networking":{"percentConnected":1}},"timestamp":"2023-07-22T16:35:48.011055273Z","duration":3486},"MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS":{"message":{"engine":{"consensus":{"longestRunningBlock":"0s","outstandingBlocks":0},"vm":null},"networking":{"percentConnected":1}},"error":"health check failed: rpc error: code = Unknown desc = not ready","timestamp":"2023-07-22T16:35:48.011334344Z","duration":278600,"contiguousFailures":4,"timeOfFirstFailure":"2023-07-22T16:35:42.010758291Z"},"P":{"message":{"engine":{"consensus":{"longestRunningBlock":"0s","outstandingBlocks":0},"vm":null},"networking":{"percentConnected":1}},"timestamp":"2023-07-22T16:35:48.011047609Z","duration":16300},"X":{"message":{"engine":{"consensus":{"longestRunningBlock":"0s","outstandingBlocks":0},"vm":null},"networking":{"percentConnected":1}},"timestamp":"2023-07-22T16:35:48.011061345Z","duration":6963},"bootstrapped":{"message":[],"timestamp":"2023-07-22T16:35:48.011051326Z","duration":3096},"database":{"timestamp":"2023-07-22T16:35:48.011064591Z","duration":2304},"diskspace":{"message":{"availableDiskBytes":1178045321216},"timestamp":"2023-07-22T16:35:48.011069119Z","duration":3967},"network":{"message":{"connectedPeers":10,"sendFailRate":0,"timeSinceLastMsgReceived":"1.011028774s","timeSinceLastMsgSent":"1.011028774s"},"timestamp":"2023-07-22T16:35:48.011030617Z","duration":6622},"router":{"message":{"longestRunningRequest":"0s","outstandingRequests":0},"timestamp":"2023-07-22T16:35:48.011052578Z","duration":8726}}}
2023-07-22T16:35:49.6508603Z [sync] [07-22|16:35:49.650] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 45, "responseLen": 18}
2023-07-22T16:35:50.0117705Z [sync] [07-22|16:35:50.011] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:35:50.1843993Z [sync] [07-22|16:35:50.184] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:50.7527823Z [sync] [07-22|16:35:50.752] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 46, "responseLen": 18}
2023-07-22T16:35:51.1835668Z [sync] [07-22|16:35:51.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:51.8550573Z [sync] [07-22|16:35:51.854] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-7ahuhysKthMLShd8EJHA1YnY2xY1w3LCY", "requestID": 47, "responseLen": 18}
2023-07-22T16:35:52.0109424Z [sync] [07-22|16:35:52.010] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:35:52.1835713Z [sync] [07-22|16:35:52.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:52.6259302Z [sync] [07-22|16:35:52.625] WARN health/health.go:111 failing check {"namespace": "health", "reason": {"C":{"message":{"engine":{"consensus":{"longestRunningBlock":"0s","outstandingBlocks":0},"vm":null},"networking":{"percentConnected":1}},"timestamp":"2023-07-22T16:35:52.010558711Z","duration":5911},"MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS":{"message":{"engine":{"consensus":{"longestRunningBlock":"0s","outstandingBlocks":0},"vm":null},"networking":{"percentConnected":1}},"error":"health check failed: rpc error: code = Unknown desc = not ready","timestamp":"2023-07-22T16:35:52.010815357Z","duration":233082,"contiguousFailures":6,"timeOfFirstFailure":"2023-07-22T16:35:42.010758291Z"},"P":{"message":{"engine":{"consensus":{"longestRunningBlock":"0s","outstandingBlocks":0},"vm":null},"networking":{"percentConnected":1}},"timestamp":"2023-07-22T16:35:52.010581583Z","duration":9397},"X":{"message":{"engine":{"consensus":{"longestRunningBlock":"0s","outstandingBlocks":0},"vm":null},"networking":{"percentConnected":1}},"timestamp":"2023-07-22T16:35:52.010571585Z","duration":12213},"bootstrapped":{"message":[],"timestamp":"2023-07-22T16:35:52.010578265Z","duration":7073},"database":{"timestamp":"2023-07-22T16:35:52.010588063Z","duration":2625},"diskspace":{"message":{"availableDiskBytes":1178045210624},"timestamp":"2023-07-22T16:35:52.010552189Z","duration":3647},"network":{"message":{"connectedPeers":10,"sendFailRate":0,"timeSinceLastMsgReceived":"1.010592611s","timeSinceLastMsgSent":"1.010592611s"},"timestamp":"2023-07-22T16:35:52.010594505Z","duration":4859},"router":{"message":{"longestRunningRequest":"0s","outstandingRequests":0},"timestamp":"2023-07-22T16:35:52.010584626Z","duration":4328}}}
2023-07-22T16:35:52.9570254Z [sync] [07-22|16:35:52.956] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 48, "responseLen": 18}
2023-07-22T16:35:53.1837276Z [sync] [07-22|16:35:53.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:54.0107558Z [sync] [07-22|16:35:54.010] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:35:54.0593590Z [sync] [07-22|16:35:54.059] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 49, "responseLen": 18}
2023-07-22T16:35:54.1842219Z [sync] [07-22|16:35:54.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:55.1625037Z [sync] [07-22|16:35:55.162] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 50, "responseLen": 18}
2023-07-22T16:35:55.1838131Z [sync] [07-22|16:35:55.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:55.5145095Z [bootstrap] [07-22|16:35:55.514] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:334 gossiping because past verify timeout
2023-07-22T16:35:55.6274576Z [sync] [07-22|16:35:55.626] WARN health/health.go:111 failing check {"namespace": "health", "reason": {"C":{"message":{"engine":{"consensus":{"longestRunningBlock":"0s","outstandingBlocks":0},"vm":null},"networking":{"percentConnected":1}},"timestamp":"2023-07-22T16:35:54.01028343Z","duration":15148},"MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS":{"message":{"engine":{"consensus":{"longestRunningBlock":"0s","outstandingBlocks":0},"vm":null},"networking":{"percentConnected":1}},"error":"health check failed: rpc error: code = Unknown desc = not ready","timestamp":"2023-07-22T16:35:54.010528141Z","duration":290787,"contiguousFailures":7,"timeOfFirstFailure":"2023-07-22T16:35:42.010758291Z"},"P":{"message":{"engine":{"consensus":{"longestRunningBlock":"0s","outstandingBlocks":0},"vm":null},"networking":{"percentConnected":1}},"timestamp":"2023-07-22T16:35:54.010232976Z","duration":13616},"X":{"message":{"engine":{"consensus":{"longestRunningBlock":"0s","outstandingBlocks":0},"vm":null},"networking":{"percentConnected":1}},"timestamp":"2023-07-22T16:35:54.01026512Z","duration":8506},"bootstrapped":{"message":[],"timestamp":"2023-07-22T16:35:54.010278275Z","duration":3857},"database":{"timestamp":"2023-07-22T16:35:54.01025413Z","duration":7734},"diskspace":{"message":{"availableDiskBytes":1178045194240},"timestamp":"2023-07-22T16:35:54.010236853Z","duration":3216},"network":{"message":{"connectedPeers":10,"sendFailRate":0,"timeSinceLastMsgReceived":"1.010271362s","timeSinceLastMsgSent":"1.010271362s"},"timestamp":"2023-07-22T16:35:54.010273436Z","duration":5881},"router":{"message":{"longestRunningRequest":"52.764903ms","outstandingRequests":1},"timestamp":"2023-07-22T16:35:54.010274964Z","duration":4398}}}
2023-07-22T16:35:56.0116295Z [sync] [07-22|16:35:56.011] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:35:56.1838648Z [sync] [07-22|16:35:56.183] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:334 gossiping because past verify timeout
2023-07-22T16:35:56.1839571Z [sync] [07-22|16:35:56.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:56.2643420Z [sync] [07-22|16:35:56.264] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 51, "responseLen": 18}
2023-07-22T16:35:56.5146850Z [bootstrap] [07-22|16:35:56.514] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:334 gossiping because past verify timeout
2023-07-22T16:35:57.1838087Z [sync] [07-22|16:35:57.183] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:334 gossiping because past verify timeout
2023-07-22T16:35:57.1839004Z [sync] [07-22|16:35:57.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:57.3667946Z [sync] [07-22|16:35:57.366] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 52, "responseLen": 18}
2023-07-22T16:35:57.5141557Z [bootstrap] [07-22|16:35:57.513] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:334 gossiping because past verify timeout
2023-07-22T16:35:58.0113414Z [sync] [07-22|16:35:58.011] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:35:58.1840594Z [sync] [07-22|16:35:58.183] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:334 gossiping because past verify timeout
2023-07-22T16:35:58.1841345Z [sync] [07-22|16:35:58.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:58.4692783Z [sync] [07-22|16:35:58.469] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 53, "responseLen": 18}
2023-07-22T16:35:58.5146283Z [bootstrap] [07-22|16:35:58.514] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:334 gossiping because past verify timeout
2023-07-22T16:35:58.6286165Z [sync] [07-22|16:35:58.628] WARN health/health.go:111 failing check {"namespace": "health", "reason": {"C":{"message":{"engine":{"consensus":{"longestRunningBlock":"0s","outstandingBlocks":0},"vm":null},"networking":{"percentConnected":1}},"timestamp":"2023-07-22T16:35:58.010950371Z","duration":3267},"MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS":{"message":{"engine":{"consensus":{"longestRunningBlock":"0s","outstandingBlocks":0},"vm":null},"networking":{"percentConnected":1}},"error":"health check failed: rpc error: code = Unknown desc = not ready","timestamp":"2023-07-22T16:35:58.011198033Z","duration":261392,"contiguousFailures":9,"timeOfFirstFailure":"2023-07-22T16:35:42.010758291Z"},"P":{"message":{"engine":{"consensus":{"longestRunningBlock":"0s","outstandingBlocks":0},"vm":null},"networking":{"percentConnected":1}},"timestamp":"2023-07-22T16:35:58.010934571Z","duration":16501},"X":{"message":{"engine":{"consensus":{"longestRunningBlock":"0s","outstandingBlocks":0},"vm":null},"networking":{"percentConnected":1}},"timestamp":"2023-07-22T16:35:58.010954378Z","duration":3106},"bootstrapped":{"message":[],"timestamp":"2023-07-22T16:35:58.010917429Z","duration":4208},"database":{"timestamp":"2023-07-22T16:35:58.010945912Z","duration":2014},"diskspace":{"message":{"availableDiskBytes":1178045083648},"timestamp":"2023-07-22T16:35:58.010912009Z","duration":6863},"network":{"message":{"connectedPeers":10,"sendFailRate":0,"timeSinceLastMsgReceived":"1.010938108s","timeSinceLastMsgSent":"1.010938108s"},"timestamp":"2023-07-22T16:35:58.010939751Z","duration":4378},"router":{"message":{"longestRunningRequest":"0s","outstandingRequests":0},"timestamp":"2023-07-22T16:35:58.010943127Z","duration":2655}}}
2023-07-22T16:35:59.1834957Z [sync] [07-22|16:35:59.183] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:334 gossiping because past verify timeout
2023-07-22T16:35:59.1836022Z [sync] [07-22|16:35:59.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:59.5141452Z [bootstrap] [07-22|16:35:59.513] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:334 gossiping because past verify timeout
2023-07-22T16:35:59.5715917Z [sync] [07-22|16:35:59.571] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 54, "responseLen": 18}
2023-07-22T16:35:59.6230504Z waiting for health check to pass...broadcasting tx while waiting: rpc error: code = Unknown desc = node "sync" failed to become healthy within timeout, or network stopped
2023-07-22T16:36:00.0116354Z [sync] [07-22|16:36:00.011] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:36:00.0292483Z [bootstrap] [07-22|16:36:00.027] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:579 parsed block {"id": "ggfYHbKfQWFvCaJwNdk8CP5jksEDerQU2DEpnNMG9Prxxcq8A", "height": 1428}
2023-07-22T16:36:00.0294280Z [sync] [07-22|16:36:00.027] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:579 parsed block {"id": "ggfYHbKfQWFvCaJwNdk8CP5jksEDerQU2DEpnNMG9Prxxcq8A", "height": 1428}
2023-07-22T16:36:00.0296368Z [bootstrap] [07-22|16:36:00.029] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> chain/block.go:439 verify context {"height": 1428, "unit price": 1}
2023-07-22T16:36:00.0298189Z [sync] [07-22|16:36:00.029] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> chain/block.go:317 skipping verification, state not ready {"height": 1428, "blkID": "ggfYHbKfQWFvCaJwNdk8CP5jksEDerQU2DEpnNMG9Prxxcq8A"}
2023-07-22T16:36:00.0300186Z [sync] [07-22|16:36:00.029] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/resolutions.go:113 verified block {"blkID": "ggfYHbKfQWFvCaJwNdk8CP5jksEDerQU2DEpnNMG9Prxxcq8A", "height": 1428, "txs": 1, "state ready": false}
2023-07-22T16:36:00.0302012Z [bootstrap] [07-22|16:36:00.029] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/resolutions.go:113 verified block {"blkID": "ggfYHbKfQWFvCaJwNdk8CP5jksEDerQU2DEpnNMG9Prxxcq8A", "height": 1428, "txs": 1, "state ready": true}
2023-07-22T16:36:00.0352585Z [sync] [07-22|16:36:00.035] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> chain/block.go:594 updated state sync target {"id": "ggfYHbKfQWFvCaJwNdk8CP5jksEDerQU2DEpnNMG9Prxxcq8A", "root": "21GGH4mPNSCTi6v8UPJHtKBFWxw3eJpeehpbmHgHuH2r58hvHh"}
2023-07-22T16:36:00.0354880Z [bootstrap] [07-22|16:36:00.035] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/resolutions.go:263 accepted block {"blkID": "ggfYHbKfQWFvCaJwNdk8CP5jksEDerQU2DEpnNMG9Prxxcq8A", "height": 1428, "txs": 1, "size": 378, "units": 440, "dropped mempool txs": 0, "state ready": true}
2023-07-22T16:36:00.0355956Z [bootstrap] [07-22|16:36:00.035] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/resolutions.go:200 block processed {"blkID": "ggfYHbKfQWFvCaJwNdk8CP5jksEDerQU2DEpnNMG9Prxxcq8A", "height": 1428}
2023-07-22T16:36:00.1369912Z [sync] [07-22|16:36:00.136] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 55, "responseLen": 4017}
2023-07-22T16:36:00.1376428Z [sync] [07-22|16:36:00.137] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "ABCH", "end": ""}
2023-07-22T16:36:00.1846113Z [sync] [07-22|16:36:00.184] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:00.5151149Z [bootstrap] [07-22|16:36:00.514] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/proposer_monitor.go:82 refreshed proposer monitor {"previous": 21, "new": 21, "t": "539.165µs"}
2023-07-22T16:36:00.6739198Z [sync] [07-22|16:36:00.673] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 56, "responseLen": 18}
2023-07-22T16:36:01.1838202Z [sync] [07-22|16:36:01.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:01.7761555Z [sync] [07-22|16:36:01.775] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 57, "responseLen": 18}
2023-07-22T16:36:02.0111262Z [sync] [07-22|16:36:02.010] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:36:02.1839237Z [sync] [07-22|16:36:02.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:02.8783431Z [sync] [07-22|16:36:02.878] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 58, "responseLen": 18}
2023-07-22T16:36:03.1841319Z [sync] [07-22|16:36:03.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:03.9804929Z [sync] [07-22|16:36:03.980] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 59, "responseLen": 18}
2023-07-22T16:36:04.0112295Z [sync] [07-22|16:36:04.010] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:36:04.1839084Z [sync] [07-22|16:36:04.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:05.0827006Z [sync] [07-22|16:36:05.082] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-7ahuhysKthMLShd8EJHA1YnY2xY1w3LCY", "requestID": 60, "responseLen": 18}
2023-07-22T16:36:05.1842359Z [sync] [07-22|16:36:05.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:06.0108042Z [sync] [07-22|16:36:06.010] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:36:06.1834768Z [sync] [07-22|16:36:06.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:06.1844049Z [sync] [07-22|16:36:06.184] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 61, "responseLen": 18}
2023-07-22T16:36:07.1840997Z [sync] [07-22|16:36:07.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:07.2869544Z [sync] [07-22|16:36:07.286] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 62, "responseLen": 18}
2023-07-22T16:36:08.0108274Z [sync] [07-22|16:36:08.010] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:36:08.1834246Z [sync] [07-22|16:36:08.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:08.3892926Z [sync] [07-22|16:36:08.389] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 63, "responseLen": 18}
2023-07-22T16:36:09.1836624Z [sync] [07-22|16:36:09.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:09.4916192Z [sync] [07-22|16:36:09.491] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 64, "responseLen": 18}
2023-07-22T16:36:09.6270446Z [07-22|16:36:09.626] INFO client/client.go:206 health
2023-07-22T16:36:09.6272377Z [07-22|16:36:09.627] DEBUG server/server.go:817 Health
2023-07-22T16:36:09.6272742Z [07-22|16:36:09.627] INFO server/server.go:823 waiting for local cluster readiness
2023-07-22T16:36:09.6273172Z [07-22|16:36:09.627] INFO ux/output.go:13 waiting for all nodes to report healthy...
2023-07-22T16:36:09.6273601Z [07-22|16:36:09.627] INFO local/network.go:666 checking local network healthiness {"num-of-nodes": 12}
2023-07-22T16:36:09.6282411Z [sync] [07-22|16:36:09.627] WARN health/health.go:111 failing check {"namespace": "health", "reason": {"C":{"message":{"engine":{"consensus":{"longestRunningBlock":"0s","outstandingBlocks":0},"vm":null},"networking":{"percentConnected":1}},"timestamp":"2023-07-22T16:36:08.010463246Z","duration":10941},"MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS":{"message":{"engine":{"consensus":{"longestRunningBlock":"0s","outstandingBlocks":0},"vm":null},"networking":{"percentConnected":1}},"error":"health check failed: rpc error: code = Unknown desc = not ready","timestamp":"2023-07-22T16:36:08.010745313Z","duration":299704,"contiguousFailures":14,"timeOfFirstFailure":"2023-07-22T16:35:42.010758291Z"},"P":{"message":{"engine":{"consensus":{"longestRunningBlock":"0s","outstandingBlocks":0},"vm":null},"networking":{"percentConnected":1}},"timestamp":"2023-07-22T16:36:08.01049205Z","duration":13525},"X":{"message":{"engine":{"consensus":{"longestRunningBlock":"0s","outstandingBlocks":0},"vm":null},"networking":{"percentConnected":1}},"timestamp":"2023-07-22T16:36:08.010485263Z","duration":4068},"bootstrapped":{"message":[],"timestamp":"2023-07-22T16:36:08.010476752Z","duration":3396},"database":{"timestamp":"2023-07-22T16:36:08.010468306Z","duration":2745},"diskspace":{"message":{"availableDiskBytes":1178043621376},"timestamp":"2023-07-22T16:36:08.010472714Z","duration":3416},"network":{"message":{"connectedPeers":10,"sendFailRate":0,"timeSinceLastMsgReceived":"1.010439578s","timeSinceLastMsgSent":"1.010439578s"},"timestamp":"2023-07-22T16:36:08.010441682Z","duration":5621},"router":{"message":{"longestRunningRequest":"0s","outstandingRequests":0},"timestamp":"2023-07-22T16:36:08.010445128Z","duration":2905}}}
2023-07-22T16:36:09.6284387Z [07-22|16:36:09.627] DEBUG local/network.go:706 node became healthy {"name": "node5"}
2023-07-22T16:36:09.6284764Z [07-22|16:36:09.627] DEBUG local/network.go:706 node became healthy {"name": "node4"}
2023-07-22T16:36:09.6285114Z [07-22|16:36:09.627] DEBUG local/network.go:706 node became healthy {"name": "node3"}
2023-07-22T16:36:09.6285519Z [07-22|16:36:09.627] DEBUG local/network.go:706 node became healthy {"name": "node1"}
2023-07-22T16:36:09.6285871Z [07-22|16:36:09.627] DEBUG local/network.go:706 node became healthy {"name": "node2"}
2023-07-22T16:36:09.6286222Z [07-22|16:36:09.628] DEBUG local/network.go:706 node became healthy {"name": "node2-bls"}
2023-07-22T16:36:09.6286583Z [07-22|16:36:09.628] DEBUG local/network.go:706 node became healthy {"name": "node3-bls"}
2023-07-22T16:36:09.6286932Z [07-22|16:36:09.628] DEBUG local/network.go:706 node became healthy {"name": "node1-bls"}
2023-07-22T16:36:09.6287276Z [07-22|16:36:09.628] DEBUG local/network.go:706 node became healthy {"name": "node5-bls"}
2023-07-22T16:36:09.6287618Z [07-22|16:36:09.628] DEBUG local/network.go:706 node became healthy {"name": "node4-bls"}
2023-07-22T16:36:09.6288041Z [07-22|16:36:09.628] DEBUG local/network.go:706 node became healthy {"name": "bootstrap"}
2023-07-22T16:36:10.0108423Z [sync] [07-22|16:36:10.010] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:36:10.1836412Z [sync] [07-22|16:36:10.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:10.5944832Z [sync] [07-22|16:36:10.594] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 65, "responseLen": 18}
2023-07-22T16:36:11.1836224Z [sync] [07-22|16:36:11.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:11.6968231Z [sync] [07-22|16:36:11.696] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 66, "responseLen": 18}
2023-07-22T16:36:12.0109746Z [sync] [07-22|16:36:12.010] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:36:12.1838586Z [sync] [07-22|16:36:12.183] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/proposer_monitor.go:82 refreshed proposer monitor {"previous": 21, "new": 21, "t": "452.396µs"}
2023-07-22T16:36:12.1839582Z [sync] [07-22|16:36:12.183] WARN <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
patrick-ogrady commented 1 year ago

Key issue seems to be that state is not considered ready:

2023-07-22T16:37:19.6693327Z [sync] [07-22|16:37:19.669] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/resolutions.go:113 verified block {"blkID": "mtTW6RRWwFkBpBwRXWyo8yr8m38rwtZRi5b2nnmipReBLTDdv", "height": 1432, "txs": 1, "state ready": false}
patrick-ogrady commented 1 year ago

Never emits "state sync done" on restart:

2023-07-22T16:33:23.2722831Z [sync] [07-22|16:33:23.272] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:524 completed {"new root": "RHxHMqfUeQvbyLN5hx8mia171LiBkCm6JUxiwe4Qe1ii8zJi9"}
2023-07-22T16:33:23.2723591Z [sync] [07-22|16:33:23.272] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/syncervm_client.go:178 state sync done
patrick-ogrady commented 1 year ago

Looks like this may (at least in some cases) be a panic: https://github.com/ava-labs/avalanchego/issues/1750

2023-07-22T21:39:11.7256452Z [sync_concurrent] fatal error: concurrent map writes
2023-07-22T21:39:11.7256844Z [sync_concurrent] fatal error: concurrent map writes
2023-07-22T21:39:11.7328777Z [sync_concurrent] 
2023-07-22T21:39:11.7329088Z [sync_concurrent] goroutine 27175 [running]:
2023-07-22T21:39:11.7329544Z [sync_concurrent] github.com/ava-labs/avalanchego/utils/math.(*averagerHeapBackend).Push(0xc0005314d0, {0xeceaa0?, 0xc009d03740})
2023-07-22T21:39:11.7330072Z [sync_concurrent]     /home/runner/go/pkg/mod/github.com/ava-labs/avalanchego@v1.10.5/utils/math/averager_heap.go:134 +0x54
2023-07-22T21:39:11.7330504Z [sync_concurrent] container/heap.Push({0x12238a0, 0xc0005314d0}, {0xeceaa0?, 0xc009d03740?})
2023-07-22T21:39:11.7331052Z [sync_concurrent]     /opt/hostedtoolcache/go/1.20.6/x64/src/container/heap/heap.go:52 +0x37
2023-07-22T21:39:11.7331569Z [sync_concurrent] github.com/ava-labs/avalanchego/utils/math.averagerHeap.Add({0x0?}, {0x1, 0x41, 0xaf, 0x5a, 0xea, 0xc4, 0xc8, 0xe3, 0xfb, ...}, ...)
2023-07-22T21:39:11.7332056Z [sync_concurrent]     /home/runner/go/pkg/mod/github.com/ava-labs/avalanchego@v1.10.5/utils/math/averager_heap.go:77 +0x125
2023-07-22T21:39:11.7332586Z [sync_concurrent] github.com/ava-labs/avalanchego/x/sync.(*peerTracker).TrackBandwidth(0xc000816320, {0x1, 0x41, 0xaf, 0x5a, 0xea, 0xc4, 0xc8, 0xe3, 0xfb, ...}, ...)
2023-07-22T21:39:11.7333079Z [sync_concurrent]     /home/runner/go/pkg/mod/github.com/ava-labs/avalanchego@v1.10.5/x/sync/peer_tracker.go:171 +0x1b1
2023-07-22T21:39:11.7333613Z [sync_concurrent] github.com/ava-labs/avalanchego/x/sync.(*networkClient).request(0xc0005caf00, {0x1222160, 0xc0012082d0}, {0x1, 0x41, 0xaf, 0x5a, 0xea, 0xc4, 0xc8, ...}, ...)
2023-07-22T21:39:11.7334114Z [sync_concurrent]     /home/runner/go/pkg/mod/github.com/ava-labs/avalanchego@v1.10.5/x/sync/network_client.go:263 +0x725
2023-07-22T21:39:11.7334623Z [sync_concurrent] github.com/ava-labs/avalanchego/x/sync.(*networkClient).RequestAny(0xc0005caf00, {0x1222160, 0xc0012082d0}, 0x0, {0xc009062780, 0x55, 0x55})
2023-07-22T21:39:11.7335090Z [sync_concurrent]     /home/runner/go/pkg/mod/github.com/ava-labs/avalanchego@v1.10.5/x/sync/network_client.go:192 +0x2d5
2023-07-22T21:39:11.7335594Z [sync_concurrent] github.com/ava-labs/avalanchego/x/sync.(*client).get(0xc0012123c0, {0x1222160, 0xc0012082d0}, {0xc009062780, 0x55, 0x55})
2023-07-22T21:39:11.7336037Z [sync_concurrent]     /home/runner/go/pkg/mod/github.com/ava-labs/avalanchego@v1.10.5/x/sync/client.go:252 +0x16c
2023-07-22T21:39:11.7336619Z [sync_concurrent] github.com/ava-labs/avalanchego/x/sync.getAndParse[...]({0x1222160?, 0xc0012082d0}, 0xc0012123c0, {0xc009062780, 0x55, 0x55}, 0xc008d17e98)
2023-07-22T21:39:11.7337074Z [sync_concurrent]     /home/runner/go/pkg/mod/github.com/ava-labs/avalanchego@v1.10.5/x/sync/client.go:200 +0xd5
2023-07-22T21:39:11.7337639Z [sync_concurrent] github.com/ava-labs/avalanchego/x/sync.(*client).GetChangeProof(0x6ff1e7fe4db623b8?, {0x1222160, 0xc0012082d0}, 0xc00903dc20, {0x7f7d40a20e98?, 0xc000147e60?})
2023-07-22T21:39:11.7338244Z [sync_concurrent]     /home/runner/go/pkg/mod/github.com/ava-labs/avalanchego@v1.10.5/x/sync/client.go:128 +0x133
2023-07-22T21:39:11.7338748Z [sync_concurrent] github.com/ava-labs/avalanchego/x/sync.(*Manager).getAndApplyChangeProof(0xc00123a300, {0x1222160, 0xc0012082d0}, 0xc007ee5c20)
2023-07-22T21:39:11.7339220Z [sync_concurrent]     /home/runner/go/pkg/mod/github.com/ava-labs/avalanchego@v1.10.5/x/sync/manager.go:256 +0x1d4
2023-07-22T21:39:11.7339714Z [sync_concurrent] github.com/ava-labs/avalanchego/x/sync.(*Manager).doWork(0xc00123a300, {0x1222160, 0xc0012082d0}, 0xc007ee5c20)
2023-07-22T21:39:11.7340216Z [sync_concurrent]     /home/runner/go/pkg/mod/github.com/ava-labs/avalanchego@v1.10.5/x/sync/manager.go:241 +0xb8
2023-07-22T21:39:11.7340620Z [sync_concurrent] created by github.com/ava-labs/avalanchego/x/sync.(*Manager).sync
2023-07-22T21:39:11.7341037Z [sync_concurrent]     /home/runner/go/pkg/mod/github.com/ava-labs/avalanchego@v1.10.5/x/sync/manager.go:192 +0x198
patrick-ogrady commented 1 year ago

Related: https://github.com/ava-labs/avalanchego/issues/1760

patrick-ogrady commented 1 year ago

This is still ongoing: https://github.com/ava-labs/hypersdk/actions/runs/5729792847/job/15527249821

patrick-ogrady commented 1 year ago

Found the bug: https://github.com/ava-labs/hypersdk/actions/runs/5731125182/job/15532018550?pr=317

2023-08-01T20:20:28.4872503Z [0;0m[1;34m[sync] [08-01|20:20:28.486] [1;34mDEBUG[0;0m <TadxUrWCyiiNaHSmi5K28YGv74ygU44BkfJhwnnjyprweusdg Chain> sync/client.go:207 request failed, retrying {"nodeID": "NodeID-CxXQeJhc8brPL2mbNH4zFtvV9PqZt89L4", "attempt": 1398, "error": "failed to verify range proof due to no end proof"}