Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Sync Readiness Not Triggering after State Sync Reboot #262

Closed
patrick-ogrady opened this issue Jul 22, 2023 · 7 comments · Fixed by #258, #278 or #333
Closed

Sync Readiness Not Triggering after State Sync Reboot #262

patrick-ogrady opened this issue Jul 22, 2023 · 7 comments · Fixed by #258, #278 or #333
Assignees
@patrick-ogrady
Labels
bug Something isn't working
Milestone
v0.0.11 (Mempool....

Comments

@patrick-ogrady
Copy link
Contributor

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 patrick-ogrady added the bug Something isn't working label Jul 22, 2023
@patrick-ogrady
Copy link
Contributor Author

This occurs on node restart:

2023-07-22T16:35:40.1871895Z �[0;0m�[1;34m[sync] [07-22|16:35:40.187] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> syncer/state_syncer.go:389 starting state sync
2023-07-22T16:35:40.1873937Z �[0;0m�[1;34m[sync] [07-22|16:35:40.187] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:382 state sync started
2023-07-22T16:35:40.1883461Z �[0;0m�[1;34m[sync] [07-22|16:35:40.188] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> syncer/state_syncer.go:415 starting state sync
2023-07-22T16:35:40.1898897Z �[0;0m�[1;34m[sync] [07-22|16:35:40.189] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/syncervm_server.go:47 parsed state summary {"summary": "1426:YVPjDeS6bLFWxbNdtjSeTRJowH6benoic5C12kLGNNiGKDTLA root=2JneVzxCQpc8bi8qG2ZXmLeV5RyXmyEU5pEGPVwZFfJPPUiGRb"}
2023-07-22T16:35:40.1902424Z �[0;0m�[1;34m[sync] [07-22|16:35:40.190] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:579 parsed block {"id": "YVPjDeS6bLFWxbNdtjSeTRJowH6benoic5C12kLGNNiGKDTLA", "height": 1426}
2023-07-22T16:35:40.1905646Z �[0;0m�[1;34m[sync] [07-22|16:35:40.190] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/syncervm_server.go:47 parsed state summary {"summary": "1426:YVPjDeS6bLFWxbNdtjSeTRJowH6benoic5C12kLGNNiGKDTLA root=2JneVzxCQpc8bi8qG2ZXmLeV5RyXmyEU5pEGPVwZFfJPPUiGRb"}
2023-07-22T16:35:40.1908352Z �[0;0m�[1;34m[sync] [07-22|16:35:40.190] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/syncervm_server.go:47 parsed state summary {"summary": "1426:YVPjDeS6bLFWxbNdtjSeTRJowH6benoic5C12kLGNNiGKDTLA root=2JneVzxCQpc8bi8qG2ZXmLeV5RyXmyEU5pEGPVwZFfJPPUiGRb"}
2023-07-22T16:35:40.1911422Z �[0;0m�[1;34m[sync] [07-22|16:35:40.190] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/syncervm_server.go:47 parsed state summary {"summary": "1426:YVPjDeS6bLFWxbNdtjSeTRJowH6benoic5C12kLGNNiGKDTLA root=2JneVzxCQpc8bi8qG2ZXmLeV5RyXmyEU5pEGPVwZFfJPPUiGRb"}
2023-07-22T16:35:40.1915056Z �[0;0m�[1;34m[sync] [07-22|16:35:40.191] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/syncervm_server.go:47 parsed state summary {"summary": "1426:YVPjDeS6bLFWxbNdtjSeTRJowH6benoic5C12kLGNNiGKDTLA root=2JneVzxCQpc8bi8qG2ZXmLeV5RyXmyEU5pEGPVwZFfJPPUiGRb"}
2023-07-22T16:35:40.1928148Z �[0;0m�[1;34m[sync] [07-22|16:35:40.192] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/syncervm_server.go:47 parsed state summary {"summary": "1426:YVPjDeS6bLFWxbNdtjSeTRJowH6benoic5C12kLGNNiGKDTLA root=2JneVzxCQpc8bi8qG2ZXmLeV5RyXmyEU5pEGPVwZFfJPPUiGRb"}
2023-07-22T16:35:40.1929351Z �[0;0m�[1;34m[sync] [07-22|16:35:40.192] �[0;0mINFO�[0;0m <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 �[0;0m�[1;34m[sync] [07-22|16:35:40.192] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:35:40.1931059Z �[0;0m�[1;34m[sync] [07-22|16:35:40.192] �[0;0mINFO�[0;0m <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 �[0;0m�[1;34m[sync] [07-22|16:35:40.192] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/resolutions.go:153 skipping unprocessed block {"height": 1426}
2023-07-22T16:35:40.1932930Z �[0;0m�[1;34m[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 �[0;0m�[1;34m[sync] [07-22|16:35:40.192] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> bootstrap/bootstrapper.go:115 starting bootstrapper
2023-07-22T16:35:40.1934403Z �[0;0m�[1;34m[sync] [07-22|16:35:40.193] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:405 bootstrapping started {"state sync started": true}
2023-07-22T16:35:40.1942977Z �[0;0m�[1;34m[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 �[0;0m�[1;34m[sync] [07-22|16:35:40.194] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> bootstrap/bootstrapper.go:554 executing blocks {"numPendingJobs": 0}
2023-07-22T16:35:40.1944188Z �[0;0m�[1;34m[sync] [07-22|16:35:40.194] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> queue/jobs.go:224 executed operations {"numExecuted": 0}
2023-07-22T16:35:40.1947919Z �[0;0m�[1;34m[sync] [07-22|16:35:40.194] INFO <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> snowman/transitive.go:400 consensus starting {"lastAcceptedBlock": "2L38nK1cHQvTrEUhWQMp52aSvEayG876KwhJtC2TRfjm38J2Bd"}
2023-07-22T16:35:40.1948842Z �[0;0m�[1;34m[sync] [07-22|16:35:40.194] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:409 normal operation started {"state sync started": true}
2023-07-22T16:35:40.3003376Z �[0;0m�[1;34m[sync] [07-22|16:35:40.300] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 0, "responseLen": 98478}
2023-07-22T16:35:40.3385911Z �[0;0m�[1;34m[sync] [07-22|16:35:40.338] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "", "end": "ABCH"}
2023-07-22T16:35:40.3805731Z �[0;0m�[1;33m[bootstrap] [07-22|16:35:40.380] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:579 parsed block {"id": "2eKg5a8CB2WJGTCkbH7QLYWUJkmkGRXJborhS6ti8yLx11cqnY", "height": 1427}
2023-07-22T16:35:40.3807175Z �[0;0m�[1;34m[sync] [07-22|16:35:40.380] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:579 parsed block {"id": "2eKg5a8CB2WJGTCkbH7QLYWUJkmkGRXJborhS6ti8yLx11cqnY", "height": 1427}
2023-07-22T16:35:40.3820185Z �[0;0m�[1;33m[bootstrap] [07-22|16:35:40.381] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> chain/block.go:439 verify context {"height": 1427, "unit price": 1}
2023-07-22T16:35:40.3823127Z �[0;0m�[1;34m[sync] [07-22|16:35:40.382] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> chain/block.go:317 skipping verification, state not ready {"height": 1427, "blkID": "2eKg5a8CB2WJGTCkbH7QLYWUJkmkGRXJborhS6ti8yLx11cqnY"}
2023-07-22T16:35:40.3824112Z �[0;0m�[1;34m[sync] [07-22|16:35:40.382] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/resolutions.go:113 verified block {"blkID": "2eKg5a8CB2WJGTCkbH7QLYWUJkmkGRXJborhS6ti8yLx11cqnY", "height": 1427, "txs": 4, "state ready": false}
2023-07-22T16:35:40.3825143Z �[0;0m�[1;33m[bootstrap] [07-22|16:35:40.382] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/resolutions.go:113 verified block {"blkID": "2eKg5a8CB2WJGTCkbH7QLYWUJkmkGRXJborhS6ti8yLx11cqnY", "height": 1427, "txs": 4, "state ready": true}
2023-07-22T16:35:40.3880137Z �[0;0m�[1;33m[bootstrap] [07-22|16:35:40.387] �[0;0mINFO�[0;0m <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 �[0;0m�[1;33m[bootstrap] [07-22|16:35:40.387] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/resolutions.go:200 block processed {"blkID": "2eKg5a8CB2WJGTCkbH7QLYWUJkmkGRXJborhS6ti8yLx11cqnY", "height": 1427}
2023-07-22T16:35:40.3885780Z �[0;0m�[1;34m[sync] [07-22|16:35:40.388] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> chain/block.go:594 updated state sync target {"id": "2eKg5a8CB2WJGTCkbH7QLYWUJkmkGRXJborhS6ti8yLx11cqnY", "root": "25brDB1cyAAdELwG1PAgw37mQFqsw4gpq3k9e7Rag4PAeakqjj"}
2023-07-22T16:35:40.4401034Z �[0;0m�[1;34m[sync] [07-22|16:35:40.439] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-A5GNnGLY96XzzQfjKSFU2m67rDvoKh8c5", "requestID": 1, "responseLen": 54}
2023-07-22T16:35:40.4402491Z �[0;0m�[1;34m[sync] [07-22|16:35:40.440] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "gAhD", "end": ""}
2023-07-22T16:35:40.4461060Z �[0;0m�[1;34m[sync] [07-22|16:35:40.445] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 2, "responseLen": 100147}
2023-07-22T16:35:40.4788312Z �[0;0m�[1;34m[sync] [07-22|16:35:40.478] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "ABCH", "end": "ACGn"}
2023-07-22T16:35:40.4902585Z �[0;0m�[1;34m[sync] [07-22|16:35:40.489] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-FZ4uKBNjztHA1zt2PQ7BdtXCyxdzynnda", "requestID": 3, "responseLen": 18}
2023-07-22T16:35:40.5421937Z �[0;0m�[1;34m[sync] [07-22|16:35:40.541] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-7ahuhysKthMLShd8EJHA1YnY2xY1w3LCY", "requestID": 4, "responseLen": 58}
2023-07-22T16:35:40.5422898Z �[0;0m�[1;34m[sync] [07-22|16:35:40.541] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "wAQh", "end": ""}
2023-07-22T16:35:40.5423878Z �[0;0m�[1;34m[sync] [07-22|16:35:40.542] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 5, "responseLen": 58}
2023-07-22T16:35:40.5424751Z �[0;0m�[1;34m[sync] [07-22|16:35:40.542] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "gAhD", "end": "wAQh"}
2023-07-22T16:35:40.5857049Z �[0;0m�[1;34m[sync] [07-22|16:35:40.585] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 6, "responseLen": 100071}
2023-07-22T16:35:40.6022916Z �[0;0m�[1;34m[sync] [07-22|16:35:40.602] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-A5GNnGLY96XzzQfjKSFU2m67rDvoKh8c5", "requestID": 7, "responseLen": 18}
2023-07-22T16:35:40.6196963Z �[0;0m�[1;34m[sync] [07-22|16:35:40.619] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "ACGn", "end": "ADIg"}
2023-07-22T16:35:40.6440953Z �[0;0m�[1;34m[sync] [07-22|16:35:40.643] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-7ahuhysKthMLShd8EJHA1YnY2xY1w3LCY", "requestID": 8, "responseLen": 3053}
2023-07-22T16:35:40.6442486Z �[0;0m�[1;34m[sync] [07-22|16:35:40.643] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 9, "responseLen": 3155}
2023-07-22T16:35:40.6443557Z �[0;0m�[1;34m[sync] [07-22|16:35:40.644] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "ABCH", "end": "ABkX"}
2023-07-22T16:35:40.6445668Z �[0;0m�[1;34m[sync] [07-22|16:35:40.644] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "ABkX", "end": "ACGn"}
2023-07-22T16:35:40.7246798Z �[0;0m�[1;34m[sync] [07-22|16:35:40.724] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-A5GNnGLY96XzzQfjKSFU2m67rDvoKh8c5", "requestID": 11, "responseLen": 18}
2023-07-22T16:35:40.7302879Z �[0;0m�[1;34m[sync] [07-22|16:35:40.729] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 10, "responseLen": 100110}
2023-07-22T16:35:40.7460455Z �[0;0m�[1;34m[sync] [07-22|16:35:40.745] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 12, "responseLen": 54}
2023-07-22T16:35:40.7461446Z �[0;0m�[1;34m[sync] [07-22|16:35:40.745] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "ICOKfw==", "end": "QBT1"}
2023-07-22T16:35:40.7462622Z �[0;0m�[1;34m[sync] [07-22|16:35:40.745] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-7ahuhysKthMLShd8EJHA1YnY2xY1w3LCY", "requestID": 13, "responseLen": 54}
2023-07-22T16:35:40.7463457Z �[0;0m�[1;34m[sync] [07-22|16:35:40.746] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "QBT1", "end": "gAhD"}
2023-07-22T16:35:40.7616697Z �[0;0m�[1;34m[sync] [07-22|16:35:40.761] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "ADIg", "end": "AEJw"}
2023-07-22T16:35:40.8579810Z �[0;0m�[1;34m[sync] [07-22|16:35:40.857] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-7ahuhysKthMLShd8EJHA1YnY2xY1w3LCY", "requestID": 14, "responseLen": 18}
2023-07-22T16:35:40.8632145Z �[0;0m�[1;34m[sync] [07-22|16:35:40.862] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 15, "responseLen": 54}
2023-07-22T16:35:40.8637164Z �[0;0m�[1;34m[sync] [07-22|16:35:40.863] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "EDL9P38=", "end": "ICOKfw=="}
2023-07-22T16:35:40.8688541Z �[0;0m�[1;34m[sync] [07-22|16:35:40.868] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 16, "responseLen": 100208}
2023-07-22T16:35:40.9023661Z �[0;0m�[1;34m[sync] [07-22|16:35:40.902] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AEJw", "end": "AFOs"}
2023-07-22T16:35:41.0040735Z �[0;0m�[1;34m[sync] [07-22|16:35:41.003] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 17, "responseLen": 676}
2023-07-22T16:35:41.0041548Z �[0;0m�[1;34m[sync] [07-22|16:35:41.003] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "CENUn79/", "end": "EDL9P38="}
2023-07-22T16:35:41.0092072Z �[0;0m�[1;34m[sync] [07-22|16:35:41.009] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 19, "responseLen": 18}
2023-07-22T16:35:41.0093179Z �[0;0m�[1;34m[sync] [07-22|16:35:41.009] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 18, "responseLen": 100208}
2023-07-22T16:35:41.0469912Z �[0;0m�[1;34m[sync] [07-22|16:35:41.046] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AFOs", "end": "AGSY"}
2023-07-22T16:35:41.1486267Z �[0;0m�[1;34m[sync] [07-22|16:35:41.148] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 20, "responseLen": 676}
2023-07-22T16:35:41.1487081Z �[0;0m�[1;34m[sync] [07-22|16:35:41.148] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "BFP2T9+/fw==", "end": "CENUn79/"}
2023-07-22T16:35:41.1533466Z �[0;0m�[1;34m[sync] [07-22|16:35:41.153] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 21, "responseLen": 100094}
2023-07-22T16:35:41.1821636Z �[0;0m�[1;34m[sync] [07-22|16:35:41.181] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-7ahuhysKthMLShd8EJHA1YnY2xY1w3LCY", "requestID": 22, "responseLen": 18}
2023-07-22T16:35:41.1839782Z �[0;0m�[1;34m[sync] [07-22|16:35:41.183] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/proposer_monitor.go:82 refreshed proposer monitor {"previous": 0, "new": 21, "t": "721.874µs"}
2023-07-22T16:35:41.1843745Z �[0;0m�[1;34m[sync] [07-22|16:35:41.184] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:41.1896239Z �[0;0m�[1;34m[sync] [07-22|16:35:41.189] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AGSY", "end": "AHWQ"}
2023-07-22T16:35:41.2915669Z �[0;0m�[1;34m[sync] [07-22|16:35:41.291] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 23, "responseLen": 676}
2023-07-22T16:35:41.2918477Z �[0;0m�[1;34m[sync] [07-22|16:35:41.291] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AmTDJ+/fv38=", "end": "BFP2T9+/fw=="}
2023-07-22T16:35:41.2955438Z �[0;0m�[1;34m[sync] [07-22|16:35:41.295] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 24, "responseLen": 100132}
2023-07-22T16:35:41.3304245Z �[0;0m�[1;34m[sync] [07-22|16:35:41.330] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AHWQ", "end": "AIZg"}
2023-07-22T16:35:41.3952367Z �[0;0m�[1;34m[sync] [07-22|16:35:41.394] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 25, "responseLen": 18}
2023-07-22T16:35:41.4324521Z �[0;0m�[1;34m[sync] [07-22|16:35:41.432] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 26, "responseLen": 676}
2023-07-22T16:35:41.4325783Z �[0;0m�[1;34m[sync] [07-22|16:35:41.432] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AXWRk/fv379/", "end": "AmTDJ+/fv38="}
2023-07-22T16:35:41.4371906Z �[0;0m�[1;34m[sync] [07-22|16:35:41.436] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-A5GNnGLY96XzzQfjKSFU2m67rDvoKh8c5", "requestID": 27, "responseLen": 100079}
2023-07-22T16:35:41.4663574Z �[0;0m�[1;34m[sync] [07-22|16:35:41.466] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AIZg", "end": "AJcD"}
2023-07-22T16:35:41.5679587Z �[0;0m�[1;34m[sync] [07-22|16:35:41.567] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 28, "responseLen": 676}
2023-07-22T16:35:41.5681384Z �[0;0m�[1;34m[sync] [07-22|16:35:41.567] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AQZKSfv379+/fw==", "end": "AXWRk/fv379/"}
2023-07-22T16:35:41.5730400Z �[0;0m�[1;34m[sync] [07-22|16:35:41.572] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-7ahuhysKthMLShd8EJHA1YnY2xY1w3LCY", "requestID": 29, "responseLen": 100170}
2023-07-22T16:35:41.6109072Z �[0;0m�[1;34m[sync] [07-22|16:35:41.610] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AJcD", "end": "AKfg"}
2023-07-22T16:35:41.6681286Z �[0;0m�[1;34m[sync] [07-22|16:35:41.667] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 30, "responseLen": 18}
2023-07-22T16:35:41.7395658Z �[0;0m�[1;34m[sync] [07-22|16:35:41.739] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 31, "responseLen": 99889}
2023-07-22T16:35:41.7679296Z �[0;0m�[1;34m[sync] [07-22|16:35:41.767] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 32, "responseLen": 99980}
2023-07-22T16:35:41.7787115Z �[0;0m�[1;34m[sync] [07-22|16:35:41.778] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "ANcVJP379+/fv38=", "end": "AOfc"}
2023-07-22T16:35:41.8034484Z �[0;0m�[1;34m[sync] [07-22|16:35:41.803] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AKfg", "end": "ALhY"}
2023-07-22T16:35:41.8832442Z �[0;0m�[1;34m[sync] [07-22|16:35:41.883] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 33, "responseLen": 53678}
2023-07-22T16:35:41.8847850Z �[0;0m�[1;34m[sync] [07-22|16:35:41.884] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-7ahuhysKthMLShd8EJHA1YnY2xY1w3LCY", "requestID": 34, "responseLen": 89369}
2023-07-22T16:35:41.9098000Z �[0;0m�[1;34m[sync] [07-22|16:35:41.909] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 35, "responseLen": 91764}
2023-07-22T16:35:41.9134874Z �[0;0m�[1;34m[sync] [07-22|16:35:41.913] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "APcTJP379+/fv38=", "end": "AQZKSfv379+/fw=="}
2023-07-22T16:35:41.9347727Z �[0;0m�[1;34m[sync] [07-22|16:35:41.934] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AOfc", "end": "APcTJP379+/fv38="}
2023-07-22T16:35:41.9633586Z �[0;0m�[1;34m[sync] [07-22|16:35:41.963] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "ALhY", "end": "AMe2kn79+/fv379/"}
2023-07-22T16:35:42.0106721Z �[0;0m�[1;34m[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 �[0;0m�[1;34m[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 �[0;0m�[1;34m[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 �[0;0m�[1;34m[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 �[0;0m�[1;34m[sync] [07-22|16:35:42.010] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:35:42.0194149Z �[0;0m�[1;34m[sync] [07-22|16:35:42.019] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 36, "responseLen": 94969}
2023-07-22T16:35:42.0202745Z �[0;0m�[1;34m[sync] [07-22|16:35:42.020] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 37, "responseLen": 18}
2023-07-22T16:35:42.0499021Z �[0;0m�[1;34m[sync] [07-22|16:35:42.049] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "AMe2kn79+/fv379/", "end": "ANcVJP379+/fv38="}
2023-07-22T16:35:42.0814905Z �[0;0m�[1;34m[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 �[0;0m�[1;34m[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 �[0;0m�[1;34m[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 �[0;0m�[1;34m[sync] [07-22|16:35:42.081] INFO <C Chain> bootstrap/bootstrapper.go:115 starting bootstrapper
2023-07-22T16:35:42.0828617Z �[0;0m�[1;34m[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 �[0;0m�[1;34m[sync] [07-22|16:35:42.082] INFO <C Chain> bootstrap/bootstrapper.go:554 executing blocks {"numPendingJobs": 0}
2023-07-22T16:35:42.0829557Z �[0;0m�[1;34m[sync] [07-22|16:35:42.082] INFO <C Chain> queue/jobs.go:224 executed operations {"numExecuted": 0}
2023-07-22T16:35:42.0830025Z �[0;0m�[1;34m[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 �[0;0m�[1;34m[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 �[0;0m�[1;34m[sync] [07-22|16:35:42.085] INFO <X Chain> bootstrap/bootstrapper.go:554 executing blocks {"numPendingJobs": 0}
2023-07-22T16:35:42.0861569Z �[0;0m�[1;34m[sync] [07-22|16:35:42.085] INFO <X Chain> queue/jobs.go:224 executed operations {"numExecuted": 0}
2023-07-22T16:35:42.0862238Z �[0;0m�[1;34m[sync] [07-22|16:35:42.086] INFO <X Chain> snowman/transitive.go:400 consensus starting {"lastAcceptedBlock": "2o79tLyefpG4rKwecqqAX7MudkuPgrq1NqpTm8Yh1UoDQjmJ7t"}
2023-07-22T16:35:42.0863288Z �[0;0m�[1;34m[sync] [07-22|16:35:42.086] INFO <C Chain> snowman/transitive.go:400 consensus starting {"lastAcceptedBlock": "2Q5qkGvLuJyg7UAp1khitQ2WUScBzEjiUf68T8sQYjUm7U97xS"}
2023-07-22T16:35:42.0864001Z �[0;0m�[1;34m[sync] [07-22|16:35:42.086] INFO <P Chain> snowman/transitive.go:400 consensus starting {"lastAcceptedBlock": "QRdYMLzmJo7hVNfRVxjF1rNHgXwCA3fFyQ2PcmXfXNBR1Uw7p"}
2023-07-22T16:35:42.1839840Z �[0;0m�[1;34m[sync] [07-22|16:35:42.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:42.5033072Z �[0;0m�[1;34m[sync] [07-22|16:35:42.502] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-A5GNnGLY96XzzQfjKSFU2m67rDvoKh8c5", "requestID": 38, "responseLen": 18}
2023-07-22T16:35:43.1761113Z �[0;0m�[1;34m[sync] [07-22|16:35:43.175] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 39, "responseLen": 18}
2023-07-22T16:35:43.1834525Z �[0;0m�[1;34m[sync] [07-22|16:35:43.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:44.0113238Z �[0;0m�[1;34m[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 �[0;0m�[1;34m[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 �[0;0m�[1;34m[sync] [07-22|16:35:44.011] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:35:44.1386720Z �[0;0m�[1;34m[sync] [07-22|16:35:44.138] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 40, "responseLen": 18}
2023-07-22T16:35:44.1836871Z �[0;0m�[1;34m[sync] [07-22|16:35:44.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:45.1837880Z �[0;0m�[1;34m[sync] [07-22|16:35:45.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:45.2412028Z �[0;0m�[1;34m[sync] [07-22|16:35:45.240] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 41, "responseLen": 18}
2023-07-22T16:35:46.0107576Z �[0;0m�[1;34m[sync] [07-22|16:35:46.010] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:35:46.1833987Z �[0;0m�[1;34m[sync] [07-22|16:35:46.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:46.3431461Z �[0;0m�[1;34m[sync] [07-22|16:35:46.342] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 42, "responseLen": 18}
2023-07-22T16:35:47.1843955Z �[0;0m�[1;34m[sync] [07-22|16:35:47.184] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:47.4478433Z �[0;0m�[1;34m[sync] [07-22|16:35:47.445] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-7ahuhysKthMLShd8EJHA1YnY2xY1w3LCY", "requestID": 43, "responseLen": 18}
2023-07-22T16:35:48.0115909Z �[0;0m�[1;34m[sync] [07-22|16:35:48.011] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:35:48.1843132Z �[0;0m�[1;34m[sync] [07-22|16:35:48.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:48.5486748Z �[0;0m�[1;34m[sync] [07-22|16:35:48.548] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 44, "responseLen": 18}
2023-07-22T16:35:49.1837550Z �[0;0m�[1;34m[sync] [07-22|16:35:49.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:49.6223010Z �[0;0m[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 �[0;34m�[;1mwaiting for all nodes to report healthy...�[0;0m�[0;0m
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 �[1;34m[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 �[0;0m�[1;34m[sync] [07-22|16:35:49.650] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 45, "responseLen": 18}
2023-07-22T16:35:50.0117705Z �[0;0m�[1;34m[sync] [07-22|16:35:50.011] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:35:50.1843993Z �[0;0m�[1;34m[sync] [07-22|16:35:50.184] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:50.7527823Z �[0;0m�[1;34m[sync] [07-22|16:35:50.752] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 46, "responseLen": 18}
2023-07-22T16:35:51.1835668Z �[0;0m�[1;34m[sync] [07-22|16:35:51.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:51.8550573Z �[0;0m�[1;34m[sync] [07-22|16:35:51.854] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-7ahuhysKthMLShd8EJHA1YnY2xY1w3LCY", "requestID": 47, "responseLen": 18}
2023-07-22T16:35:52.0109424Z �[0;0m�[1;34m[sync] [07-22|16:35:52.010] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:35:52.1835713Z �[0;0m�[1;34m[sync] [07-22|16:35:52.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:52.6259302Z �[0;0m�[1;34m[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 �[0;0m�[1;34m[sync] [07-22|16:35:52.956] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 48, "responseLen": 18}
2023-07-22T16:35:53.1837276Z �[0;0m�[1;34m[sync] [07-22|16:35:53.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:54.0107558Z �[0;0m�[1;34m[sync] [07-22|16:35:54.010] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:35:54.0593590Z �[0;0m�[1;34m[sync] [07-22|16:35:54.059] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 49, "responseLen": 18}
2023-07-22T16:35:54.1842219Z �[0;0m�[1;34m[sync] [07-22|16:35:54.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:55.1625037Z �[0;0m�[1;34m[sync] [07-22|16:35:55.162] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 50, "responseLen": 18}
2023-07-22T16:35:55.1838131Z �[0;0m�[1;34m[sync] [07-22|16:35:55.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:55.5145095Z �[0;0m�[1;33m[bootstrap] [07-22|16:35:55.514] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:334 gossiping because past verify timeout
2023-07-22T16:35:55.6274576Z �[0;0m�[1;34m[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 �[0;0m�[1;34m[sync] [07-22|16:35:56.011] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:35:56.1838648Z �[0;0m�[1;34m[sync] [07-22|16:35:56.183] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:334 gossiping because past verify timeout
2023-07-22T16:35:56.1839571Z �[0;0m�[1;34m[sync] [07-22|16:35:56.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:56.2643420Z �[0;0m�[1;34m[sync] [07-22|16:35:56.264] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 51, "responseLen": 18}
2023-07-22T16:35:56.5146850Z �[0;0m�[1;33m[bootstrap] [07-22|16:35:56.514] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:334 gossiping because past verify timeout
2023-07-22T16:35:57.1838087Z �[0;0m�[1;34m[sync] [07-22|16:35:57.183] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:334 gossiping because past verify timeout
2023-07-22T16:35:57.1839004Z �[0;0m�[1;34m[sync] [07-22|16:35:57.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:57.3667946Z �[0;0m�[1;34m[sync] [07-22|16:35:57.366] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 52, "responseLen": 18}
2023-07-22T16:35:57.5141557Z �[0;0m�[1;33m[bootstrap] [07-22|16:35:57.513] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:334 gossiping because past verify timeout
2023-07-22T16:35:58.0113414Z �[0;0m�[1;34m[sync] [07-22|16:35:58.011] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:35:58.1840594Z �[0;0m�[1;34m[sync] [07-22|16:35:58.183] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:334 gossiping because past verify timeout
2023-07-22T16:35:58.1841345Z �[0;0m�[1;34m[sync] [07-22|16:35:58.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:58.4692783Z �[0;0m�[1;34m[sync] [07-22|16:35:58.469] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 53, "responseLen": 18}
2023-07-22T16:35:58.5146283Z �[0;0m�[1;33m[bootstrap] [07-22|16:35:58.514] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:334 gossiping because past verify timeout
2023-07-22T16:35:58.6286165Z �[0;0m�[1;34m[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 �[0;0m�[1;34m[sync] [07-22|16:35:59.183] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:334 gossiping because past verify timeout
2023-07-22T16:35:59.1836022Z �[0;0m�[1;34m[sync] [07-22|16:35:59.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:35:59.5141452Z �[0;0m�[1;33m[bootstrap] [07-22|16:35:59.513] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:334 gossiping because past verify timeout
2023-07-22T16:35:59.5715917Z �[0;0m�[1;34m[sync] [07-22|16:35:59.571] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 54, "responseLen": 18}
2023-07-22T16:35:59.6230504Z �[0;0m�[38;5;11mwaiting for health check to pass...broadcasting tx while waiting:�[0m rpc error: code = Unknown desc = node "sync" failed to become healthy within timeout, or network stopped
2023-07-22T16:36:00.0116354Z �[1;34m[sync] [07-22|16:36:00.011] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:36:00.0292483Z �[0;0m�[1;33m[bootstrap] [07-22|16:36:00.027] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:579 parsed block {"id": "ggfYHbKfQWFvCaJwNdk8CP5jksEDerQU2DEpnNMG9Prxxcq8A", "height": 1428}
2023-07-22T16:36:00.0294280Z �[0;0m�[1;34m[sync] [07-22|16:36:00.027] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:579 parsed block {"id": "ggfYHbKfQWFvCaJwNdk8CP5jksEDerQU2DEpnNMG9Prxxcq8A", "height": 1428}
2023-07-22T16:36:00.0296368Z �[0;0m�[1;33m[bootstrap] [07-22|16:36:00.029] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> chain/block.go:439 verify context {"height": 1428, "unit price": 1}
2023-07-22T16:36:00.0298189Z �[0;0m�[1;34m[sync] [07-22|16:36:00.029] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> chain/block.go:317 skipping verification, state not ready {"height": 1428, "blkID": "ggfYHbKfQWFvCaJwNdk8CP5jksEDerQU2DEpnNMG9Prxxcq8A"}
2023-07-22T16:36:00.0300186Z �[0;0m�[1;34m[sync] [07-22|16:36:00.029] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/resolutions.go:113 verified block {"blkID": "ggfYHbKfQWFvCaJwNdk8CP5jksEDerQU2DEpnNMG9Prxxcq8A", "height": 1428, "txs": 1, "state ready": false}
2023-07-22T16:36:00.0302012Z �[0;0m�[1;33m[bootstrap] [07-22|16:36:00.029] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/resolutions.go:113 verified block {"blkID": "ggfYHbKfQWFvCaJwNdk8CP5jksEDerQU2DEpnNMG9Prxxcq8A", "height": 1428, "txs": 1, "state ready": true}
2023-07-22T16:36:00.0352585Z �[0;0m�[1;34m[sync] [07-22|16:36:00.035] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> chain/block.go:594 updated state sync target {"id": "ggfYHbKfQWFvCaJwNdk8CP5jksEDerQU2DEpnNMG9Prxxcq8A", "root": "21GGH4mPNSCTi6v8UPJHtKBFWxw3eJpeehpbmHgHuH2r58hvHh"}
2023-07-22T16:36:00.0354880Z �[0;0m�[1;33m[bootstrap] [07-22|16:36:00.035] �[0;0mINFO�[0;0m <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 �[0;0m�[1;33m[bootstrap] [07-22|16:36:00.035] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/resolutions.go:200 block processed {"blkID": "ggfYHbKfQWFvCaJwNdk8CP5jksEDerQU2DEpnNMG9Prxxcq8A", "height": 1428}
2023-07-22T16:36:00.1369912Z �[0;0m�[1;34m[sync] [07-22|16:36:00.136] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 55, "responseLen": 4017}
2023-07-22T16:36:00.1376428Z �[0;0m�[1;34m[sync] [07-22|16:36:00.137] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:608 completed range {"start": "ABCH", "end": ""}
2023-07-22T16:36:00.1846113Z �[0;0m�[1;34m[sync] [07-22|16:36:00.184] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:00.5151149Z �[0;0m�[1;33m[bootstrap] [07-22|16:36:00.514] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/proposer_monitor.go:82 refreshed proposer monitor {"previous": 21, "new": 21, "t": "539.165µs"}
2023-07-22T16:36:00.6739198Z �[0;0m�[1;34m[sync] [07-22|16:36:00.673] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 56, "responseLen": 18}
2023-07-22T16:36:01.1838202Z �[0;0m�[1;34m[sync] [07-22|16:36:01.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:01.7761555Z �[0;0m�[1;34m[sync] [07-22|16:36:01.775] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 57, "responseLen": 18}
2023-07-22T16:36:02.0111262Z �[0;0m�[1;34m[sync] [07-22|16:36:02.010] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:36:02.1839237Z �[0;0m�[1;34m[sync] [07-22|16:36:02.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:02.8783431Z �[0;0m�[1;34m[sync] [07-22|16:36:02.878] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 58, "responseLen": 18}
2023-07-22T16:36:03.1841319Z �[0;0m�[1;34m[sync] [07-22|16:36:03.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:03.9804929Z �[0;0m�[1;34m[sync] [07-22|16:36:03.980] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 59, "responseLen": 18}
2023-07-22T16:36:04.0112295Z �[0;0m�[1;34m[sync] [07-22|16:36:04.010] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:36:04.1839084Z �[0;0m�[1;34m[sync] [07-22|16:36:04.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:05.0827006Z �[0;0m�[1;34m[sync] [07-22|16:36:05.082] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-7ahuhysKthMLShd8EJHA1YnY2xY1w3LCY", "requestID": 60, "responseLen": 18}
2023-07-22T16:36:05.1842359Z �[0;0m�[1;34m[sync] [07-22|16:36:05.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:06.0108042Z �[0;0m�[1;34m[sync] [07-22|16:36:06.010] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:36:06.1834768Z �[0;0m�[1;34m[sync] [07-22|16:36:06.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:06.1844049Z �[0;0m�[1;34m[sync] [07-22|16:36:06.184] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 61, "responseLen": 18}
2023-07-22T16:36:07.1840997Z �[0;0m�[1;34m[sync] [07-22|16:36:07.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:07.2869544Z �[0;0m�[1;34m[sync] [07-22|16:36:07.286] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 62, "responseLen": 18}
2023-07-22T16:36:08.0108274Z �[0;0m�[1;34m[sync] [07-22|16:36:08.010] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:36:08.1834246Z �[0;0m�[1;34m[sync] [07-22|16:36:08.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:08.3892926Z �[0;0m�[1;34m[sync] [07-22|16:36:08.389] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 63, "responseLen": 18}
2023-07-22T16:36:09.1836624Z �[0;0m�[1;34m[sync] [07-22|16:36:09.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:09.4916192Z �[0;0m�[1;34m[sync] [07-22|16:36:09.491] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 64, "responseLen": 18}
2023-07-22T16:36:09.6270446Z �[0;0m[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 �[0;34m�[;1mwaiting for all nodes to report healthy...�[0;0m�[0;0m
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 �[1;34m[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 �[0;0m[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 �[1;34m[sync] [07-22|16:36:10.010] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:36:10.1836412Z �[0;0m�[1;34m[sync] [07-22|16:36:10.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:10.5944832Z �[0;0m�[1;34m[sync] [07-22|16:36:10.594] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-LhyzUPJYJ8yjF8ZRmJAzmGAXCvr7LKcSw", "requestID": 65, "responseLen": 18}
2023-07-22T16:36:11.1836224Z �[0;0m�[1;34m[sync] [07-22|16:36:11.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}
2023-07-22T16:36:11.6968231Z �[0;0m�[1;34m[sync] [07-22|16:36:11.696] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/network_client.go:98 received AppResponse from peer {"nodeID": "NodeID-AuoksrQHXMH6YeYPZHVdnnCBRsXHdJhZ4", "requestID": 66, "responseLen": 18}
2023-07-22T16:36:12.0109746Z �[0;0m�[1;34m[sync] [07-22|16:36:12.010] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/vm.go:362 node is not ready yet
2023-07-22T16:36:12.1838586Z �[0;0m�[1;34m[sync] [07-22|16:36:12.183] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/proposer_monitor.go:82 refreshed proposer monitor {"previous": 21, "new": 21, "t": "452.396µs"}
2023-07-22T16:36:12.1839582Z �[0;0m�[1;34m[sync] [07-22|16:36:12.183] �[1;33mWARN�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> gossiper/proposer.go:339 gossip txs failed {"error": "block is not processed"}

@patrick-ogrady
Copy link
Contributor Author

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

2023-07-22T16:37:19.6693327Z �[0;0m�[1;34m[sync] [07-22|16:37:19.669] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/resolutions.go:113 verified block {"blkID": "mtTW6RRWwFkBpBwRXWyo8yr8m38rwtZRi5b2nnmipReBLTDdv", "height": 1432, "txs": 1, "state ready": false}

@patrick-ogrady patrick-ogrady changed the title Sync Readiness Not Triggering Sync Readiness Not Triggering after State Sync Reboot Jul 22, 2023
@patrick-ogrady patrick-ogrady self-assigned this Jul 22, 2023
@patrick-ogrady
Copy link
Contributor Author

patrick-ogrady commented Jul 22, 2023 •
edited
Loading

Never emits "state sync done" on restart:

2023-07-22T16:33:23.2722831Z �[0;0m�[0;36m[sync] [07-22|16:33:23.272] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> sync/manager.go:524 completed {"new root": "RHxHMqfUeQvbyLN5hx8mia171LiBkCm6JUxiwe4Qe1ii8zJi9"}
2023-07-22T16:33:23.2723591Z �[0;0m�[0;36m[sync] [07-22|16:33:23.272] �[0;0mINFO�[0;0m <MWbQa78z716X82tr3eeM9TNH9PALrn6GgQJMVucL463gf4euS Chain> vm/syncervm_client.go:178 state sync done

@patrick-ogrady patrick-ogrady mentioned this issue Jul 22, 2023
Merged
11 tasks
@patrick-ogrady
Copy link
Contributor Author

patrick-ogrady commented Jul 24, 2023 •
edited
Loading

Looks like this may (at least in some cases) be a panic: ava-labs/avalanchego#1750

2023-07-22T21:39:11.7256452Z �[0;0m�[0;37m[sync_concurrent] fatal error: concurrent map writes
2023-07-22T21:39:11.7256844Z �[0;0m�[0;37m[sync_concurrent] fatal error: concurrent map writes
2023-07-22T21:39:11.7328777Z �[0;0m�[0;37m[sync_concurrent] 
2023-07-22T21:39:11.7329088Z �[0;0m�[0;37m[sync_concurrent] goroutine 27175 [running]:
2023-07-22T21:39:11.7329544Z �[0;0m�[0;37m[sync_concurrent] github.com/ava-labs/avalanchego/utils/math.(*averagerHeapBackend).Push(0xc0005314d0, {0xeceaa0?, 0xc009d03740})
2023-07-22T21:39:11.7330072Z �[0;0m�[0;37m[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 �[0;0m�[0;37m[sync_concurrent] container/heap.Push({0x12238a0, 0xc0005314d0}, {0xeceaa0?, 0xc009d03740?})
2023-07-22T21:39:11.7331052Z �[0;0m�[0;37m[sync_concurrent] 	/opt/hostedtoolcache/go/1.20.6/x64/src/container/heap/heap.go:52 +0x37
2023-07-22T21:39:11.7331569Z �[0;0m�[0;37m[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 �[0;0m�[0;37m[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 �[0;0m�[0;37m[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 �[0;0m�[0;37m[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 �[0;0m�[0;37m[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 �[0;0m�[0;37m[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 �[0;0m�[0;37m[sync_concurrent] github.com/ava-labs/avalanchego/x/sync.(*networkClient).RequestAny(0xc0005caf00, {0x1222160, 0xc0012082d0}, 0x0, {0xc009062780, 0x55, 0x55})
2023-07-22T21:39:11.7335090Z �[0;0m�[0;37m[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 �[0;0m�[0;37m[sync_concurrent] github.com/ava-labs/avalanchego/x/sync.(*client).get(0xc0012123c0, {0x1222160, 0xc0012082d0}, {0xc009062780, 0x55, 0x55})
2023-07-22T21:39:11.7336037Z �[0;0m�[0;37m[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 �[0;0m�[0;37m[sync_concurrent] github.com/ava-labs/avalanchego/x/sync.getAndParse[...]({0x1222160?, 0xc0012082d0}, 0xc0012123c0, {0xc009062780, 0x55, 0x55}, 0xc008d17e98)
2023-07-22T21:39:11.7337074Z �[0;0m�[0;37m[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 �[0;0m�[0;37m[sync_concurrent] github.com/ava-labs/avalanchego/x/sync.(*client).GetChangeProof(0x6ff1e7fe4db623b8?, {0x1222160, 0xc0012082d0}, 0xc00903dc20, {0x7f7d40a20e98?, 0xc000147e60?})
2023-07-22T21:39:11.7338244Z �[0;0m�[0;37m[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 �[0;0m�[0;37m[sync_concurrent] github.com/ava-labs/avalanchego/x/sync.(*Manager).getAndApplyChangeProof(0xc00123a300, {0x1222160, 0xc0012082d0}, 0xc007ee5c20)
2023-07-22T21:39:11.7339220Z �[0;0m�[0;37m[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 �[0;0m�[0;37m[sync_concurrent] github.com/ava-labs/avalanchego/x/sync.(*Manager).doWork(0xc00123a300, {0x1222160, 0xc0012082d0}, 0xc007ee5c20)
2023-07-22T21:39:11.7340216Z �[0;0m�[0;37m[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 �[0;0m�[0;37m[sync_concurrent] created by github.com/ava-labs/avalanchego/x/sync.(*Manager).sync
2023-07-22T21:39:11.7341037Z �[0;0m�[0;37m[sync_concurrent] 	/home/runner/go/pkg/mod/github.com/ava-labs/avalanchego@v1.10.5/x/sync/manager.go:192 +0x198

@patrick-ogrady patrick-ogrady mentioned this issue Jul 24, 2023
Merged
@patrick-ogrady
Copy link
Contributor Author

Related: ava-labs/avalanchego#1760

@patrick-ogrady patrick-ogrady linked a pull request Jul 26, 2023 that will close this issue
Update to AvalancheGo dev #278
Merged
@patrick-ogrady
Copy link
Contributor Author

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

@patrick-ogrady patrick-ogrady reopened this Aug 1, 2023
@patrick-ogrady patrick-ogrady mentioned this issue Aug 1, 2023
Merged
3 tasks
@patrick-ogrady
Copy link
Contributor Author

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"}

This was referenced Aug 1, 2023
Closed
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@patrick-ogrady patrick-ogrady

Labels
bug Something isn't working
Projects
None yet
Milestone
v0.0.11 (Mempool.Build Replacement + ...
1 participant
@patrick-ogrady