22.10.0-RC2 got "stuck" during snap sync

[yorickdowne]

Description

22.10.0-RC2 stopped importing blocks. Logs seen on 10-24 09:00:

eth-main-execution-1  | 2022-10-23 21:56:24.131+00:00 | EthScheduler-Services-28 (requestCompleteTask) | INFO  | SnapWorldDownloadState | Pausing world state download while waiting for sync to complete
eth-main-execution-1  | 2022-10-23 21:56:53.881+00:00 | EthScheduler-Services-33 (importBlock) | INFO  | FastImportBlocksStep | Completed importing chain segment 8756337 to 8762336 (6000 blocks in 10250ms), Peers: 25
eth-main-execution-1  | 2022-10-23 21:57:28.076+00:00 | EthScheduler-Services-33 (importBlock) | INFO  | FastImportBlocksStep | Completed importing chain segment 8762337 to 8768336 (6000 blocks in 10133ms), Peers: 25
eth-main-execution-1  | 2022-10-23 21:57:57.327+00:00 | EthScheduler-Services-33 (importBlock) | INFO  | FastImportBlocksStep | Completed importing chain segment 8768337 to 8774536 (6200 blocks in 10026ms), Peers: 25
eth-main-execution-1  | 2022-10-23 21:58:34.987+00:00 | EthScheduler-Services-33 (importBlock) | INFO  | FastImportBlocksStep | Completed importing chain segment 8774537 to 8781536 (7000 blocks in 10331ms), Peers: 25
eth-main-execution-1  | 2022-10-23 21:59:06.993+00:00 | EthScheduler-Services-33 (importBlock) | INFO  | FastImportBlocksStep | Completed importing chain segment 8781537 to 8787936 (6400 blocks in 10153ms), Peers: 25
eth-main-execution-1  | 2022-10-23 21:59:40.067+00:00 | EthScheduler-Services-33 (importBlock) | INFO  | FastImportBlocksStep | Completed importing chain segment 8787937 to 8793936 (6000 blocks in 10235ms), Peers: 25
eth-main-execution-1  | 2022-10-23 22:00:07.199+00:00 | EthScheduler-Services-33 (importBlock) | INFO  | FastImportBlocksStep | Completed importing chain segment 8793937 to 8799536 (5600 blocks in 10011ms), Peers: 24
eth-main-execution-1  | 2022-10-23 22:00:40.500+00:00 | EthScheduler-Services-33 (importBlock) | INFO  | FastImportBlocksStep | Completed importing chain segment 8799537 to 8805136 (5600 blocks in 10056ms), Peers: 25
eth-main-execution-1  | 2022-10-23 22:01:16.665+00:00 | EthScheduler-Services-33 (importBlock) | INFO  | FastImportBlocksStep | Completed importing chain segment 8805137 to 8810136 (5000 blocks in 10136ms), Peers: 25
eth-main-execution-1  | 2022-10-23 22:01:53.775+00:00 | EthScheduler-Services-33 (importBlock) | INFO  | FastImportBlocksStep | Completed importing chain segment 8810137 to 8814936 (4800 blocks in 10052ms), Peers: 25
eth-main-execution-1  | 2022-10-23 22:02:24.194+00:00 | EthScheduler-Services-33 (importBlock) | INFO  | FastImportBlocksStep | Completed importing chain segment 8814937 to 8821336 (6400 blocks in 10013ms), Peers: 25
eth-main-execution-1  | 2022-10-23 22:02:55.697+00:00 | EthScheduler-Services-33 (importBlock) | INFO  | FastImportBlocksStep | Completed importing chain segment 8821337 to 8826536 (5200 blocks in 10827ms), Peers: 25
eth-main-execution-1  | 2022-10-23 22:03:28.083+00:00 | EthScheduler-Services-33 (importBlock) | INFO  | FastImportBlocksStep | Completed importing chain segment 8826537 to 8832736 (6200 blocks in 10494ms), Peers: 25
eth-main-execution-1  | 2022-10-23 22:03:59.702+00:00 | EthScheduler-Services-33 (importBlock) | INFO  | FastImportBlocksStep | Completed importing chain segment 8832737 to 8838136 (5400 blocks in 10171ms), Peers: 25
eth-main-execution-1  | 2022-10-24 07:07:47.769+00:00 | Timer-0 | INFO  | DNSResolver | Resolved 2409 nodes

And nothing after. CPU looked "idle" at that time. That is 11 hours of no progress.

After restarting Besu, it resumed:

eth-main-execution-1  | 2022-10-24 09:06:56.520+00:00 | main | INFO  | Runner | Ethereum main loop is up.
eth-main-execution-1  | 2022-10-24 09:07:01.730+00:00 | Timer-0 | INFO  | DNSResolver | Resolved 2409 nodes
eth-main-execution-1  | 2022-10-24 09:07:56.950+00:00 | EthScheduler-Services-3 (batchPersistAccountData) | INFO  | SnapsyncMetricsManager | Worldstate download in progress synced=0.00%, accounts=0, slots=0, codes=0, nodes=0
eth-main-execution-1  | 2022-10-24 09:09:39.959+00:00 | EthScheduler-Services-3 (batchPersistAccountData) | INFO  | SnapsyncMetricsManager | Worldstate download in progress synced=0.07%, accounts=131426, slots=797644, codes=17406, nodes=772916
eth-main-execution-1  | 2022-10-24 09:10:55.399+00:00 | EthScheduler-Services-31 (importBlock) | INFO  | FastImportBlocksStep | Completed importing chain segment 8841937 to 8846536 (4600 blocks in 10146ms), Peers: 9
eth-main-execution-1  | 2022-10-24 09:11:21.875+00:00 | EthScheduler-Services-31 (importBlock) | INFO  | FastImportBlocksStep | Completed importing chain segment 8846537 to 8851936 (5400 blocks in 10398ms), Peers: 9
eth-main-execution-1  | 2022-10-24 09:12:27.031+00:00 | EthScheduler-Services-31 (importBlock) | INFO  | FastImportBlocksStep | Completed importing chain segment 8851937 to 8857536 (5600 blocks in 10339ms), Peers: 19
eth-main-execution-1  | 2022-10-24 09:12:53.063+00:00 | EthScheduler-Services-31 (importBlock) | INFO  | FastImportBlocksStep | Completed importing chain segment 8857537 to 8863336 (5800 blocks in 10270ms), Peers: 14
eth-main-execution-1  | 2022-10-24 09:16:22.032+00:00 | EthScheduler-Services-29 (importBlock) | INFO  | FastImportBlocksStep | Completed importing chain segment 8872923 to 8877722 (4800 blocks in 10135ms), Peers: 21
eth-main-execution-1  | 2022-10-24 09:18:37.323+00:00 | EthScheduler-Services-33 (importBlock) | INFO  | FastImportBlocksStep | Completed importing chain segment 8885286 to 8889885 (4600 blocks in 10131ms), Peers: 23
eth-main-execution-1  | 2022-10-24 09:19:02.521+00:00 | EthScheduler-Services-3 (batchPersistAccountData) | INFO  | SnapsyncMetricsManager | Worldstate download in progress synced=0.20%, accounts=361788, slots=7468984, codes=48134, nodes=9089979

I don't have debug logs, unfortunately. This issue is meant to just note that Besu can stall during sync.

Sync is on a dedicated server, 6 cores, 32 GiB RAM, Samsung PM9A3 NVMe SSD, Debian 11 OS and docker-ce.

[yorickdowne]

Once it got through snap sync after restart, it's quite unhappy:

eth-main-execution-1  | 2022-10-25 11:23:25.914+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,824,776 / 254 tx / base fee 8.67 gwei / 29,916,367 (99.7%) gas / (0x36d41e286ca668ba611e0aa3e6b8f76e629fd403d4569b185494d0d08c58afc4) in 1.089s. Peers: 25
eth-main-execution-1  | java.lang.RuntimeException: java.lang.IllegalStateException: Expected to create code, but the code exists.  Address=0x007933790a4f00000099e9001629d9fe7775b800
eth-main-execution-1  |         at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateArchive.rollMutableStateToBlockHash(BonsaiWorldStateArchive.java:229)
eth-main-execution-1  |         at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateArchive.getMutable(BonsaiWorldStateArchive.java:156)
eth-main-execution-1  |         at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.forwardWorldStateTo(MergeCoordinator.java:505)
eth-main-execution-1  |         at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.setNewHead(MergeCoordinator.java:494)
eth-main-execution-1  |         at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.updateForkChoice(MergeCoordinator.java:457)
eth-main-execution-1  |         at org.hyperledger.besu.consensus.merge.blockcreation.TransitionCoordinator.updateForkChoice(TransitionCoordinator.java:155)
eth-main-execution-1  |         at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.engine.EngineForkchoiceUpdated.syncResponse(EngineForkchoiceUpdated.java:131)
eth-main-execution-1  |         at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.lambda$response$0(ExecutionEngineJsonRpcMethod.java:73)
eth-main-execution-1  |         at io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)
eth-main-execution-1  |         at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
eth-main-execution-1  |         at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)
eth-main-execution-1  |         at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
eth-main-execution-1  |         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
eth-main-execution-1  |         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
eth-main-execution-1  |         at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
eth-main-execution-1  |         at java.base/java.lang.Thread.run(Thread.java:833)
eth-main-execution-1  | Caused by: java.lang.IllegalStateException: Expected to create code, but the code exists.  Address=0x007933790a4f00000099e9001629d9fe7775b800
eth-main-execution-1  |         at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.rollCodeChange(BonsaiWorldStateUpdater.java:558)
eth-main-execution-1  |         at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.lambda$rollForward$10(BonsaiWorldStateUpdater.java:428)
eth-main-execution-1  |         at java.base/java.util.HashMap$EntrySpliterator.forEachRemaining(HashMap.java:1850)
eth-main-execution-1  |         at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:762)
eth-main-execution-1  |         at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.rollForward(BonsaiWorldStateUpdater.java:426)
eth-main-execution-1  |         at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateArchive.rollMutableStateToBlockHash(BonsaiWorldStateArchive.java:218)
eth-main-execution-1  |         ... 15 more
eth-main-execution-1  | 2022-10-25 11:23:25.955+00:00 | vert.x-worker-thread-0 | ERROR | MergeCoordinator | Could not persist world for root hash 0x9d3a748c02f26f0186677f47ddc7c10cf0e01b16defbc631b7de7c8a90b2c57a and block hash 0x36d41e286ca668ba611e0aa3e6b8f76e629fd403d4569b185494d0d08c58afc4
eth-main-execution-1  | 2022-10-25 11:23:25.981+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0x36d41e286ca668ba611e0aa3e6b8f76e629fd403d4569b185494d0d08c58afc4, finalized: 0x5726103d6029c4a4c9f88c00e1f0cfa5c1960fa8a00092c9230e4b507f7f65f5, safeBlockHash: 0x5afea2b6334a3c67cd412a6def1fd5ee978c862cc2ffbad476f88aca490fc693
eth-main-execution-1  | java.lang.RuntimeException: java.lang.IllegalStateException: Expected to create code, but the code exists.  Address=0x007933790a4f00000099e9001629d9fe7775b800
eth-main-execution-1  |         at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateArchive.rollMutableStateToBlockHash(BonsaiWorldStateArchive.java:229)
eth-main-execution-1  |         at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateArchive.getMutable(BonsaiWorldStateArchive.java:156)
eth-main-execution-1  |         at org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:100)
eth-main-execution-1  |         at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.validateBlock(MergeCoordinator.java:411)
eth-main-execution-1  |         at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.rememberBlock(MergeCoordinator.java:427)
eth-main-execution-1  |         at org.hyperledger.besu.consensus.merge.blockcreation.TransitionCoordinator.rememberBlock(TransitionCoordinator.java:141)
eth-main-execution-1  |         at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.engine.EngineNewPayload.syncResponse(EngineNewPayload.java:220)
eth-main-execution-1  |         at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.lambda$response$0(ExecutionEngineJsonRpcMethod.java:73)
eth-main-execution-1  |         at io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)
eth-main-execution-1  |         at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
eth-main-execution-1  |         at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)
eth-main-execution-1  |         at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
eth-main-execution-1  |         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
eth-main-execution-1  |         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
eth-main-execution-1  |         at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
eth-main-execution-1  |         at java.base/java.lang.Thread.run(Thread.java:833)
eth-main-execution-1  | Caused by: java.lang.IllegalStateException: Expected to create code, but the code exists.  Address=0x007933790a4f00000099e9001629d9fe7775b800
eth-main-execution-1  |         at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.rollCodeChange(BonsaiWorldStateUpdater.java:558)
eth-main-execution-1  |         at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.lambda$rollForward$10(BonsaiWorldStateUpdater.java:428)
eth-main-execution-1  |         at java.base/java.util.HashMap$EntrySpliterator.forEachRemaining(HashMap.java:1850)
eth-main-execution-1  |         at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:762)
eth-main-execution-1  |         at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.rollForward(BonsaiWorldStateUpdater.java:426)
eth-main-execution-1  |         at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateArchive.rollMutableStateToBlockHash(BonsaiWorldStateArchive.java:218)
eth-main-execution-1  |         ... 15 more
eth-main-execution-1  | 2022-10-25 11:23:36.273+00:00 | vert.x-worker-thread-0 | INFO  | MainnetBlockValidator | Unable to process block because parent world state 0x9d3a748c02f26f0186677f47ddc7c10cf0e01b16defbc631b7de7c8a90b2c57a is not available. Block 15824777 (0xf299f4f2fdd7dab3df01d0f47b506cf44b584af61c972e350bb3fe852955a3bf)
eth-main-execution-1  | 2022-10-25 11:23:36.273+00:00 | vert.x-worker-thread-0 | WARN  | EngineNewPayload | Invalid new payload: number: 15824777, hash: 0xf299f4f2fdd7dab3df01d0f47b506cf44b584af61c972e350bb3fe852955a3bf, parentHash: 0x36d41e286ca668ba611e0aa3e6b8f76e629fd403d4569b185494d0d08c58afc4, latestValidHash: 0x36d41e286ca668ba611e0aa3e6b8f76e629fd403d4569b185494d0d08c58afc4, status: INVALID, validationError: Unable to process block because parent world state 0x9d3a748c02f26f0186677f47ddc7c10cf0e01b16defbc631b7de7c8a90b2c57a is not available

[yorickdowne]

Starting over, this time with debug logs

[garyschulte]

I strongly suspect this is a bonsai consistency issue and will be resolved by using bonsai snapshots #4531

[yorickdowne]

The good news is I can reproduce this. I'll get you (extensive 😅 ) debug logs. Do you expect 4531 to help with a sync that has stalled, or is that "fresh sync only" territory?

[yorickdowne]

Closing this, as bonsai snapshots may have solved it.