World State Root does not match during Nimbus Backwards Sync

[siladu]

Split out from #5411

Doesn't happen everytime, but easiest way to recreate is by simply restarting both clients together for an in-sync besu and nimbus pair.

Once the error is hit, it sometimes requires a restart to recover (in this case because it was cached in the bad block manager and re-requested).

"@timestamp":"2023-06-13T23:13:55,006","level":"INFO","thread":"nioEventLoopGroup-3-1","class":"BackwardSyncStep","message":"Backward sync phase 1 of 2 completed, downloaded a total of 200 headers. Peers: 14","throwable":""}
{"@timestamp":"2023-06-13T23:13:55,768","level":"INFO","thread":"vert.x-worker-thread-0","class":"AbstractEngineNewPayload","message":"Imported #3,686,276 / 100 tx / 16 ws / base fee 452.80 kwei / 29,686,316 (99.0%) gas / (0x61a9ef505d8665ff3adda131a4ebb5783afd630d770b45fcc43a46c94fc1a32b) in 0.650s. Peers: 14","throwable":""}
{"@timestamp":"2023-06-13T23:13:55,882","level":"ERROR","thread":"vert.x-worker-thread-0","class":"MergeCoordinator","message":
"Could not persist world for root hash 0xe92db83af4c3badf1afacbf17ee713f41e6e42e35d008ad3bc7317491e95ed6e and block hash 0x61a9ef505d8665ff3adda131a4ebb5783afd630d770b45fcc43a46c94fc1a32b","throwable":""}
{"@timestamp":"2023-06-13T23:13:55,883","level":"INFO","thread":"vert.x-worker-thread-0","class":"AbstractEngineForkchoiceUpdated","message":"VALID for fork-choice-update: head: 0x61a9ef505d8665ff3adda131a4ebb5783afd630d770b45fcc43a46c94fc1a32b, finalized: 0x70e44d0d34c34bf28340e86df44886ed36ee6ce2d480a2d99a0afccfdc36355d, safeBlockHash: 0xde41dab225d2994e1dbbc6a32e0c60cb20cc270e1c3b270ab166f0e41ccbbbfc","throwable":""}
{"@timestamp":"2023-06-13T23:13:56,051","level":"INFO","thread":"vert.x-worker-thread-0","class":"AbstractEngineNewPayload","message":"Imported #3,686,277 / 0 tx / 16 ws / base fee 508.21 kwei / 0 (0.0%) gas / (0xbca5dee4a01b741fcef49b436e1fc5a3dffcf2a22ee98e3ef10fb5a16e98569a) in 0.112s. Peers: 14","throwable":""}
{"@timestamp":"2023-06-13T23:13:56,210","level":"ERROR","thread":"nioEventLoopGroup-3-1","class":"AbstractBlockProcessor","message":"failed persisting block","throwable":" 
java.lang.RuntimeException: World State Root does not match expected value, header 0xe92db83af4c3badf1afacbf17ee713f41e6e42e35d008ad3bc7317491e95ed6e calculated 0x86636a550e660e588556606a5a5aac13fa07e8672dec7e744b6c4bbe40099372\n\tat org.hyperledger.besu.ethereum.bonsai.worldview.BonsaiWorldState.persist(BonsaiWorldState.java:381)\n\tat org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:181)\n\tat org.hyperledger.besu.ethereum.mainnet.BlockProcessor.processBlock(BlockProcessor.java:79)\n\tat org.hyperledger.besu.ethereum.MainnetBlockValidator.processBlock(MainnetBlockValidator.java:207)\n\tat org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:135)\n\tat org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:72)\n\tat org.hyperledger.besu.ethereum.eth.sync.backwardsync.BackwardSyncContext.saveBlock(BackwardSyncContext.java:307)\n\tat org.hyperledger.besu.ethereum.eth.sync.backwardsync.ForwardSyncStep.saveBlocks(ForwardSyncStep.java:124)\n\tat java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:646)\n\tat java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFutu
{"@timestamp":"2023-06-13T23:13:56,213","level":"INFO","thread":"nioEventLoopGroup-3-1","class":"MainnetBlockValidator","message":"Invalid block 3686276 (0x61a9ef505d8665ff3adda131a4ebb5783afd630d770b45fcc43are.java:510)\n\tat java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)\n\tat org.hyperledger.besu.ethereum.eth.manager.task.RetryingGetBlocksFromPeersTask.lambda$executeTaskOnCurrentPeer$0(RetryingGetBlocksFromPeersTask.java:86)\n\tat java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:646)\n\tat java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)\n\tat java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)\n\tat org.hyperledger.besu.ethereum.eth.manager.task.AbstractPeerRequestTask.lambda$executeTask$2(AbstractPeerRequestTask.java:83)\n\tat java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)\n\tat java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)\n\tat java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)\n\tat java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)\n\tat org.hyperledger.besu.ethereum.eth.manager.task.AbstractPeerRequestTask.lambda$handleMessage$3(AbstractPeerRequestTask.java:106)\n\tat java.base/java.util.Optional.ifPresent(Optional.java:178)\n\tat org.hyperledger.besu.ethereum.eth.manager.task.AbstractPeerRequestTask.handleMessage(AbstractPeerRequestTask.java:104)\n\tat org.hyperledger.besu.ethereum.eth.manager.task.AbstractPeerRequestTask.lambda$executeTask$0(AbstractPeerRequestTask.java:67)\n\tat org.hyperledger.besu.ethereum.eth.manager.RequestManager$ResponseStream.dispatchBufferedResponses(RequestManager.java:211)\n\tat org.hyperledger.besu.ethereum.eth.manager.RequestManager$ResponseStream.processMessage(RequestManager.java:202)\n\tat org.hyperledger.besu.ethereum.eth.manager.RequestManager.lambda$dispatchResponse$0(RequestManager.java:82)\n\tat java.base/java.util.Optional.ifPresentOrElse(Optional.java:196)\n\tat org.hyperledger.besu.ethereum.eth.manager.RequestManager.dispatchResponse(RequestManager.java:81)\n\tat org.hyperledger.besu.ethereum.eth.manager.EthPeer.lambda$dispatch$7(EthPeer.java:411)\n\tat java.base/java.util.Optional.ifPresentOrElse(Optional.java:196)\n\tat org.hyperledger.besu.ethereum.eth.manager.EthPeer.dispatch(EthPeer.java:410)\n\tat org.hyperledger.besu.ethereum.eth.manager.EthPeers.dispatchMessage(EthPeers.java:256)\n\tat org.hyperledger.besu.ethereum.eth.manager.EthProtocolManager.processMessage(EthProtocolManager.java:320)\n\tat org.hyperledger.besu.ethereum.p2p.network.NetworkRunner.lambda$setupHandlers$1(NetworkRunner.java:142)\n\tat org.hyperledger.besu.ethereum.p2p.rlpx.connections.PeerConnectionEvents.lambda$dispatchMessage$1(PeerConnectionEvents.java:64)\n\tat org.hyperledger.besu.util.Subscribers.lambda$forEach$0(Subscribers.java:131)\n\tat java.base/java.lang.Iterable.forEach(Iterable.java:75)\n\tat org.hyperledger.besu.util.Subscribers.forEach(Subscribers.java:128)\n\tat org.hyperledger.besu.ethereum.p2p.rlpx.connections.PeerConnectionEvents.dispatchMessage(PeerConnectionEvents.java:64)\n\tat org.hyperledger.besu.ethereum.p2p.rlpx.connections.netty.ApiHandler.channelRead0(ApiHandler.java:99)\n\tat org.hyperledger.besu.ethereum.p2p.rlpx.connections.netty.ApiHandler.channelRead0(ApiHandler.java:33)\n\tat io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)\n\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)\n\tat io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)\n\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)\n\tat io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:346)\n\tat io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:318)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)\n\tat io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)\n\tat io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)\n\tat io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)\n\tat io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)\n\tat io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)\n\tat io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)\n\tat io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)\n\tat io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)\n\tat io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)\n\tat io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat java.base/java.lang.Thread.run(Thread.java:833)\n"}
{"@timestamp":"2023-06-13T23:13:56,213","level":"INFO","thread":"nioEventLoopGroup-3-1","class":"MainnetBlockValidator","message":
"Invalid block 3686276 (0x61a9ef505d8665ff3adda131a4ebb5783afd630d770b45fcc43a46
c94fc1a32b): Optional[World State Root does not match expected value, header 0xe92db83af4c3badf1afacbf17ee713f41e6e42e35d008ad3bc7317491e95ed6e calculated 0x86636a550e660e588556606a5a5aac13fa07e8672dec7e744b6c4bbe40099372], caused by java.lang.RuntimeException: World State Root does not match expected value, header 0xe92db83af4c3badf1afacbf17ee713f41e6e42e35d008ad3bc7317491e95ed6e calculated 0x86636a550e660e588556606a5a5aac13fa07e8672dec7e744b6c4bbe40099372","throwable":""}
{"@timestamp":"2023-06-13T23:13:56,268","level":"WARN","thread":"vert.x-worker-thread-0","class":"AbstractEngineNewPayload","message":"Invalid new payload: number: 3686278, hash: 0x8f959d15022c55311be0b11a028d2b72cd336a1c69fb4e5718c6865bde1a41a0, parentHash: 0xbca5dee4a01b741fcef49b436e1fc5a3dffcf2a22ee98e3ef10fb5a16e98569a, latestValidHash: 0x720cdda03c8d0e851c5436cafbf079a829feae064bfc3bee488dbbd1a378ccf8, status: INVALID, validationError: Block already present in bad block manager.","throwable":""}
{"@timestamp":"2023-06-13T23:13:56,615","level":"INFO","thread":"nioEventLoopGroup-3-1","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 9.38% completed, imported 3 blocks of at least 32 (current head 3686278, target head 3686307). Peers: 14","throwable":""}

besu7-restart.log
nimbus-engine7-restart.log
nimbus7-restart.log

[non-fungible-nelson]

@siladu do you have a status here?

[siladu]

@siladu do you have a status here?

@non-fungible-nelson No, it's just in the backlog. Suspect it's less of an issue on mainnet compared to Sepolia. Also suspect playing this will make this a non-issue: #5687

[non-fungible-nelson]

@siladu when you have a moment - please revisit all these related issues and close