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.

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

fix trie by asking peers #4312

Merged

Conversation

matkt
Copy link
Contributor

@matkt matkt commented Aug 25, 2022

Signed-off-by: Karim TAAM karim.t2am@gmail.com

PR description

we may have an inconsistency in the worldstate trie. If this happens even if the cases are very rare and complex to reproduce this PR can help resolve the issue. Indeed if we detect a problem in the trie we can fix it directly by asking our peers for the correct version of the node

We start by asking with the GetNodeData request (which will soon be deprecated but which is still compatible and more practical) and if the response is empty we try with GetTrieNode

Fixed Issue(s)

Documentation

  • I thought about documentation and added the doc-change-required label to this PR if
    updates are required.

Changelog

Signed-off-by: Karim TAAM <karim.t2am@gmail.com>
Signed-off-by: Karim TAAM <karim.t2am@gmail.com>
Signed-off-by: Karim TAAM <karim.t2am@gmail.com>
Signed-off-by: Karim TAAM <karim.t2am@gmail.com>
Signed-off-by: Karim TAAM <karim.t2am@gmail.com>
@jclapis
Copy link
Contributor

jclapis commented Sep 3, 2022

Hi folks, I'm using Besu v22.7.1 with Nimbus v22.8.1 on Goerli/Prater and ran into an issue that @garyschulte recommended I provide here, so you can gauge whether or not this PR would fix it.

Yesterday my Besu node ran into a critical error and it stopped importing new blocks:

{"log":"2022-09-02 19:04:01.036+00:00 | nioEventLoopGroup-3-5 | INFO  | BackwardSyncContext | Backward sync failed (Did not receive a headers for hash 0xc33bdbbe21f95dad81361ffba139b39d983dff362e591f744aadce9540b7eb29). Current Peers: 66. Retrying in 5000 milliseconds...\n","stream":"stdout","time":"2022-09-02T19:04:01.036719219Z"}
{"log":"2022-09-02 19:04:06.149+00:00 | nioEventLoopGroup-3-10 | INFO  | BackwardSyncContext | Backward sync failed (Did not receive a headers for hash 0x7e086e87786bf4ad5da6398a939a98e417ebf4fc8acfdd3ebfe875771124d145). Current Peers: 66. Retrying in 5000 milliseconds...\n","stream":"stdout","time":"2022-09-02T19:04:06.149689208Z"}
{"log":"2022-09-02 19:04:07.245+00:00 | vert.x-eventloop-thread-7 | WARN  | EngineExchangeTransitionConfiguration | not called in 120 seconds, consensus client may not be connected\n","stream":"stdout","time":"2022-09-02T19:04:07.246771771Z"}
{"log":"2022-09-02 19:04:11.248+00:00 | nioEventLoopGroup-3-10 | INFO  | BackwardSyncContext | Backward sync failed (Did not receive a headers for hash 0x7e086e87786bf4ad5da6398a939a98e417ebf4fc8acfdd3ebfe875771124d145). Current Peers: 66. Retrying in 5000 milliseconds...\n","stream":"stdout","time":"2022-09-02T19:04:11.249239501Z"}
{"log":"2022-09-02 19:04:16.456+00:00 | nioEventLoopGroup-3-10 | INFO  | BackwardSyncContext | Backward sync failed (Did not receive a headers for hash 0x7e086e87786bf4ad5da6398a939a98e417ebf4fc8acfdd3ebfe875771124d145). Current Peers: 66. Retrying in 5000 milliseconds...\n","stream":"stdout","time":"2022-09-02T19:04:16.456577848Z"}
{"log":"2022-09-02 19:04:21.713+00:00 | nioEventLoopGroup-3-4 | INFO  | BackwardSyncContext | Backward sync failed (Did not receive a headers for hash 0x7e086e87786bf4ad5da6398a939a98e417ebf4fc8acfdd3ebfe875771124d145). Current Peers: 66. Retrying in 5000 milliseconds...\n","stream":"stdout","time":"2022-09-02T19:04:21.714220699Z"}
{"log":"2022-09-02 19:04:27.314+00:00 | nioEventLoopGroup-3-6 | INFO  | BackwardSyncStep | Saved headers 7515250 -\u003e 7515051 (head: 7507622)\n","stream":"stdout","time":"2022-09-02T19:04:27.314871222Z"}
{"log":"2022-09-02 19:04:27.344+00:00 | ForkJoinPool.commonPool-worker-460 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync\n","stream":"stdout","time":"2022-09-02T19:04:27.34537908Z"}
{"log":"java.lang.RuntimeException: java.lang.IllegalStateException: Address=0xa29d95a19a22492b45a0cb506b93b1345443d662 Prior Value in Rolling Change: nonces differ\n","stream":"stdout","time":"2022-09-02T19:04:30.587171911Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateArchive.getMutable(BonsaiWorldStateArchive.java:206)\n","stream":"stdout","time":"2022-09-02T19:04:30.587267002Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:100)\n","stream":"stdout","time":"2022-09-02T19:04:30.587276044Z"}
{"log":"\u0009at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.validateBlock(MergeCoordinator.java:268)\n","stream":"stdout","time":"2022-09-02T19:04:30.587281294Z"}
{"log":"\u0009at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.rememberBlock(MergeCoordinator.java:284)\n","stream":"stdout","time":"2022-09-02T19:04:30.587285961Z"}
{"log":"\u0009at org.hyperledger.besu.consensus.merge.blockcreation.TransitionCoordinator.rememberBlock(TransitionCoordinator.java:137)\n","stream":"stdout","time":"2022-09-02T19:04:30.587290628Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.engine.EngineNewPayload.syncResponse(EngineNewPayload.java:203)\n","stream":"stdout","time":"2022-09-02T19:04:30.587295003Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.lambda$response$0(ExecutionEngineJsonRpcMethod.java:67)\n","stream":"stdout","time":"2022-09-02T19:04:30.58729967Z"}
{"log":"\u0009at io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)\n","stream":"stdout","time":"2022-09-02T19:04:30.587304629Z"}
{"log":"\u0009at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)\n","stream":"stdout","time":"2022-09-02T19:04:30.587309296Z"}
{"log":"\u0009at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)\n","stream":"stdout","time":"2022-09-02T19:04:30.587313671Z"}
{"log":"\u0009at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)\n","stream":"stdout","time":"2022-09-02T19:04:30.587353049Z"}
{"log":"\u0009at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)\n","stream":"stdout","time":"2022-09-02T19:04:30.587357716Z"}
{"log":"\u0009at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)\n","stream":"stdout","time":"2022-09-02T19:04:30.5873618Z"}
{"log":"\u0009at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n","stream":"stdout","time":"2022-09-02T19:04:30.587365592Z"}
{"log":"\u0009at java.base/java.lang.Thread.run(Thread.java:833)\n","stream":"stdout","time":"2022-09-02T19:04:30.587372009Z"}
{"log":"Caused by: java.lang.IllegalStateException: Address=0xa29d95a19a22492b45a0cb506b93b1345443d662 Prior Value in Rolling Change: nonces differ\n","stream":"stdout","time":"2022-09-02T19:04:30.587462724Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.bonsai.BonsaiAccount.assertCloseEnoughForDiffing(BonsaiAccount.java:303)\n","stream":"stdout","time":"2022-09-02T19:04:30.587504727Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.rollAccountChange(BonsaiWorldStateUpdater.java:497)\n","stream":"stdout","time":"2022-09-02T19:04:30.58752252Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.lambda$rollForward$9(BonsaiWorldStateUpdater.java:422)\n","stream":"stdout","time":"2022-09-02T19:04:30.587539146Z"}
{"log":"\u0009at java.base/java.util.HashMap$EntrySpliterator.forEachRemaining(HashMap.java:1850)\n","stream":"stdout","time":"2022-09-02T19:04:30.587555188Z"}
{"log":"\u0009at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:762)\n","stream":"stdout","time":"2022-09-02T19:04:30.58757094Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.rollForward(BonsaiWorldStateUpdater.java:420)\n","stream":"stdout","time":"2022-09-02T19:04:30.587588441Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateArchive.getMutable(BonsaiWorldStateArchive.java:195)\n","stream":"stdout","time":"2022-09-02T19:04:30.587604484Z"}
{"log":"\u0009... 14 more\n","stream":"stdout","time":"2022-09-02T19:04:30.587620235Z"}
{"log":"2022-09-02 19:04:30.587+00:00 | vert.x-worker-thread-0 | ERROR | MainnetBlockValidator | Unable to process block because parent world state 0xd88b673dffc35d7035e69ecbf77548279c35c1910522190f8dbdc7562e7c48c1 is not available. Block 7515241 (0xe2107822f04ed1033f53f93cb88e3ee70120d16a0aa5f03d3be314c92d760d40)\n","stream":"stdout","time":"2022-09-02T19:04:30.5>
{"log":"2022-09-02 19:04:30.587+00:00 | vert.x-worker-thread-0 | WARN  | EngineNewPayload | Invalid new payload: number: 7515241, hash: 0xe2107822f04ed1033f53f93cb88e3ee70120d16a0aa5f03d3be314c92d760d40, parentHash: 0xfbf75cff95e19b14b30644e3896e7084b01342aa8dc85460494d8e4ebf243a9d, latestValidHash: 0xfbf75cff95e19b14b30644e3896e7084b01342aa8dc85460494d8e4ebf243a9>
{"log":"2022-09-02 19:04:31.141+00:00 | nioEventLoopGroup-3-9 | ERROR | AbstractBlockProcessor | failed persisting block\n","stream":"stdout","time":"2022-09-02T19:04:31.142477295Z"}
{"log":"java.lang.RuntimeException: World State Root does not match expected value, header 0xd88b673dffc35d7035e69ecbf77548279c35c1910522190f8dbdc7562e7c48c1 calculated 0x332ed84d258dd6260d9fca6f35ed5f9206394e01eadc42da3c6c07e01045ff3b\n","stream":"stdout","time":"2022-09-02T19:04:31.142568885Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.bonsai.BonsaiPersistedWorldState.persist(BonsaiPersistedWorldState.java:255)\n","stream":"stdout","time":"2022-09-02T19:04:31.14258872Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:201)\n","stream":"stdout","time":"2022-09-02T19:04:31.142605637Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:42)\n","stream":"stdout","time":"2022-09-02T19:04:31.142667475Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.mainnet.BlockProcessor.processBlock(BlockProcessor.java:75)\n","stream":"stdout","time":"2022-09-02T19:04:31.142685268Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.MainnetBlockValidator.processBlock(MainnetBlockValidator.java:158)\n","stream":"stdout","time":"2022-09-02T19:04:31.142701019Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:112)\n","stream":"stdout","time":"2022-09-02T19:04:31.14271677Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:71)\n","stream":"stdout","time":"2022-09-02T19:04:31.14273223Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.sync.backwardsync.BackwardSyncContext.saveBlock(BackwardSyncContext.java:307)\n","stream":"stdout","time":"2022-09-02T19:04:31.142747981Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.sync.backwardsync.ForwardSyncStep.saveBlocks(ForwardSyncStep.java:104)\n","stream":"stdout","time":"2022-09-02T19:04:31.142764315Z"}
{"log":"\u0009at java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:646)\n","stream":"stdout","time":"2022-09-02T19:04:31.142779775Z"}
{"log":"\u0009at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)\n","stream":"stdout","time":"2022-09-02T19:04:31.142795234Z"}
{"log":"\u0009at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)\n","stream":"stdout","time":"2022-09-02T19:04:31.142810985Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.task.AbstractPeerRequestTask.lambda$executeTask$2(AbstractPeerRequestTask.java:83)\n","stream":"stdout","time":"2022-09-02T19:04:31.142826153Z"}
{"log":"\u0009at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)\n","stream":"stdout","time":"2022-09-02T19:04:31.142841904Z"}
{"log":"\u0009at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)\n","stream":"stdout","time":"2022-09-02T19:04:31.142857072Z"}
{"log":"\u0009at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)\n","stream":"stdout","time":"2022-09-02T19:04:31.142878073Z"}
{"log":"\u0009at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)\n","stream":"stdout","time":"2022-09-02T19:04:31.142896741Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.task.AbstractPeerRequestTask.lambda$handleMessage$3(AbstractPeerRequestTask.java:110)\n","stream":"stdout","time":"2022-09-02T19:04:31.142912492Z"}
{"log":"\u0009at java.base/java.util.Optional.ifPresent(Optional.java:178)\n","stream":"stdout","time":"2022-09-02T19:04:31.142928535Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.task.AbstractPeerRequestTask.handleMessage(AbstractPeerRequestTask.java:108)\n","stream":"stdout","time":"2022-09-02T19:04:31.142943995Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.task.AbstractPeerRequestTask.lambda$executeTask$0(AbstractPeerRequestTask.java:67)\n","stream":"stdout","time":"2022-09-02T19:04:31.142959454Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.RequestManager$ResponseStream.dispatchBufferedResponses(RequestManager.java:191)\n","stream":"stdout","time":"2022-09-02T19:04:31.142975205Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.RequestManager$ResponseStream.processMessage(RequestManager.java:182)\n","stream":"stdout","time":"2022-09-02T19:04:31.142990956Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.RequestManager.lambda$dispatchResponse$0(RequestManager.java:74)\n","stream":"stdout","time":"2022-09-02T19:04:31.143006416Z"}
{"log":"\u0009at java.base/java.util.Optional.ifPresentOrElse(Optional.java:196)\n","stream":"stdout","time":"2022-09-02T19:04:31.143043168Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.RequestManager.dispatchResponse(RequestManager.java:73)\n","stream":"stdout","time":"2022-09-02T19:04:31.143060086Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.EthPeer.lambda$dispatch$7(EthPeer.java:386)\n","stream":"stdout","time":"2022-09-02T19:04:31.143075837Z"}
{"log":"\u0009at java.base/java.util.Optional.ifPresentOrElse(Optional.java:196)\n","stream":"stdout","time":"2022-09-02T19:04:31.143091005Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.EthPeer.dispatch(EthPeer.java:385)\n","stream":"stdout","time":"2022-09-02T19:04:31.143106173Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.EthPeers.dispatchMessage(EthPeers.java:158)\n","stream":"stdout","time":"2022-09-02T19:04:31.14312134Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.EthProtocolManager.processMessage(EthProtocolManager.java:294)\n","stream":"stdout","time":"2022-09-02T19:04:31.1431368Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.p2p.network.NetworkRunner.lambda$setupHandlers$0(NetworkRunner.java:135)\n","stream":"stdout","time":"2022-09-02T19:04:31.143152551Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.p2p.rlpx.connections.PeerConnectionEvents.lambda$dispatchMessage$1(PeerConnectionEvents.java:64)\n","stream":"stdout","time":"2022-09-02T19:04:31.143168302Z"}
{"log":"\u0009at org.hyperledger.besu.util.Subscribers.lambda$forEach$0(Subscribers.java:112)\n","stream":"stdout","time":"2022-09-02T19:04:31.143184053Z"}
{"log":"\u0009at java.base/java.lang.Iterable.forEach(Iterable.java:75)\n","stream":"stdout","time":"2022-09-02T19:04:31.143199804Z"}
{"log":"\u0009at org.hyperledger.besu.util.Subscribers.forEach(Subscribers.java:109)\n","stream":"stdout","time":"2022-09-02T19:04:31.143215264Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.p2p.rlpx.connections.PeerConnectionEvents.dispatchMessage(PeerConnectionEvents.java:64)\n","stream":"stdout","time":"2022-09-02T19:04:31.14323014Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.p2p.rlpx.connections.netty.ApiHandler.channelRead0(ApiHandler.java:99)\n","stream":"stdout","time":"2022-09-02T19:04:31.143247349Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.p2p.rlpx.connections.netty.ApiHandler.channelRead0(ApiHandler.java:33)\n","stream":"stdout","time":"2022-09-02T19:04:31.1432631Z"}
{"log":"\u0009at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99)\n","stream":"stdout","time":"2022-09-02T19:04:31.14327856Z"}
{"log":"\u0009at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)\n","stream":"stdout","time":"2022-09-02T19:04:31.143294311Z"}
{"log":"\u0009at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)\n","stream":"stdout","time":"2022-09-02T19:04:31.14330977Z"}
{"log":"\u0009at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)\n","stream":"stdout","time":"2022-09-02T19:04:31.14332523Z"}
{"log":"\u0009at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286)\n","stream":"stdout","time":"2022-09-02T19:04:31.143340981Z"}
{"log":"\u0009at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)\n","stream":"stdout","time":"2022-09-02T19:04:31.143356149Z"}
{"log":"\u0009at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)\n","stream":"stdout","time":"2022-09-02T19:04:31.143371608Z"}
{"log":"\u0009at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)\n","stream":"stdout","time":"2022-09-02T19:04:31.143387359Z"}
{"log":"\u0009at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:327)\n","stream":"stdout","time":"2022-09-02T19:04:31.14340311Z"}
{"log":"\u0009at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:299)\n","stream":"stdout","time":"2022-09-02T19:04:31.143437529Z"}
{"log":"\u0009at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)\n","stream":"stdout","time":"2022-09-02T19:04:31.143454739Z"}
{"log":"\u0009at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)\n","stream":"stdout","time":"2022-09-02T19:04:31.143470198Z"}
{"log":"\u0009at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)\n","stream":"stdout","time":"2022-09-02T19:04:31.143485949Z"}
{"log":"\u0009at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)\n","stream":"stdout","time":"2022-09-02T19:04:31.143501701Z"}
{"log":"\u0009at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)\n","stream":"stdout","time":"2022-09-02T19:04:31.143517452Z"}
{"log":"\u0009at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)\n","stream":"stdout","time":"2022-09-02T19:04:31.143532911Z"}
{"log":"\u0009at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)\n","stream":"stdout","time":"2022-09-02T19:04:31.143548371Z"}
{"log":"\u0009at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)\n","stream":"stdout","time":"2022-09-02T19:04:31.14356558Z"}
{"log":"\u0009at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:722)\n","stream":"stdout","time":"2022-09-02T19:04:31.14358454Z"}
{"log":"\u0009at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658)\n","stream":"stdout","time":"2022-09-02T19:04:31.143599999Z"}
{"log":"\u0009at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584)\n","stream":"stdout","time":"2022-09-02T19:04:31.143615459Z"}
{"log":"\u0009at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496)\n","stream":"stdout","time":"2022-09-02T19:04:31.143630918Z"}
{"log":"\u0009at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)\n","stream":"stdout","time":"2022-09-02T19:04:31.143646086Z"}
{"log":"\u0009at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)\n","stream":"stdout","time":"2022-09-02T19:04:31.143661545Z"}
{"log":"\u0009at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n","stream":"stdout","time":"2022-09-02T19:04:31.143676421Z"}
{"log":"\u0009at java.base/java.lang.Thread.run(Thread.java:833)\n","stream":"stdout","time":"2022-09-02T19:04:31.143692172Z"}
{"log":"2022-09-02 19:04:31.142+00:00 | nioEventLoopGroup-3-9 | ERROR | MainnetBlockValidator | Error processing block. Block 7515240 (0xfbf75cff95e19b14b30644e3896e7084b01342aa8dc85460494d8e4ebf243a9d)\n","stream":"stdout","time":"2022-09-02T19:04:31.14370734Z"}
{"log":"2022-09-02 19:04:31.143+00:00 | nioEventLoopGroup-3-9 | WARN  | EngineNewPayload | Sync to block 7515278 (0x508f5c9c63cc63a7808158091f4d41629fa1c89e79d82d7a912e1c81e7436437) failed\n","stream":"stdout","time":"2022-09-02T19:04:31.143723383Z"}
{"log":"2022-09-02 19:04:31.143+00:00 | nioEventLoopGroup-3-9 | WARN  | EngineNewPayload | Sync to block 7515251 (0x571781474a096227f22d4f53b0e8e698c35339dd2be5ad400b21beffd8771dfe) failed\n","stream":"stdout","time":"2022-09-02T19:04:31.143739426Z"}
{"log":"2022-09-02 19:06:07.248+00:00 | vert.x-eventloop-thread-7 | WARN  | EngineExchangeTransitionConfiguration | not called in 120 seconds, consensus client may not be connected\n","stream":"stdout","time":"2022-09-02T19:06:07.249973489Z"}
{"log":"2022-09-02 19:08:07.302+00:00 | vert.x-eventloop-thread-7 | WARN  | EngineExchangeTransitionConfiguration | not called in 120 seconds, consensus client may not be connected\n","stream":"stdout","time":"2022-09-02T19:08:07.303532006Z"}
...

At which point, Nimbus started printing the following over and over again and stopped syncing:

{"log":"NOT 2022-09-03 03:11:48.933+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35976 peer=16U*dkZxtG direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:11:48.934579698Z"}
{"log":"NOT 2022-09-03 03:11:50.414+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35977 peer=16U*5WRyPT direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:11:50.415324575Z"}
{"log":"NOT 2022-09-03 03:11:51.977+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35978 peer=16U*5WRyPT direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:11:51.977682686Z"}
{"log":"NOT 2022-09-03 03:11:53.824+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35979 peer=16U*DiWMtw direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:11:53.824608262Z"}
{"log":"NOT 2022-09-03 03:11:55.149+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35980 peer=16U*DiWMtw direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:11:55.149763396Z"}
{"log":"NOT 2022-09-03 03:11:57.180+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35981 peer=16U*FsPSND direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:11:57.181073686Z"}
{"log":"NOT 2022-09-03 03:11:58.940+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35982 peer=16U*FsPSND direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:11:58.941103437Z"}
{"log":"INF 2022-09-03 03:12:00.000+00:00 Slot start                                 topics=\"beacnde\" slot=3805560 epoch=118923 sync=\"08h43m (87.14%) 0.1750slots/s (QQQQQQQQQD:3800063)\" peers=11 head=3f20d883:3791806 finalized=118491:607dd28f delay=217us912ns\n","stream":"stdout","time":"2022-09-03T03:12:00.000984176Z"}
{"log":"INF 2022-09-03 03:12:00.023+00:00 Syncing in progress; skipping validator duties for now topics=\"beacval\" slot=3805560 headSlot=3791806\n","stream":"stdout","time":"2022-09-03T03:12:00.023552069Z"}
{"log":"INF 2022-09-03 03:12:00.058+00:00 Slot end                                   topics=\"beacnde\" slot=3805560 nextActionWait=n/a nextAttestationSlot=-1 nextProposalSlot=-1 syncCommitteeDuties=none head=3f20d883:3791806\n","stream":"stdout","time":"2022-09-03T03:12:00.059035277Z"}
{"log":"NOT 2022-09-03 03:12:01.086+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35983 peer=16U*NeZjdV direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:01.086858683Z"}
{"log":"NOT 2022-09-03 03:12:02.638+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35984 peer=16U*NeZjdV direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:02.639406288Z"}
{"log":"NOT 2022-09-03 03:12:04.615+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35985 peer=16U*S3i4gQ direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:04.616105644Z"}
{"log":"NOT 2022-09-03 03:12:07.296+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35986 peer=16U*C7uogE direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:07.296970845Z"}
{"log":"NOT 2022-09-03 03:12:09.696+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35987 peer=16U*C7uogE direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:09.696694497Z"}
{"log":"NOT 2022-09-03 03:12:11.366+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35988 peer=16U*ePxmtV direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:11.366538432Z"}
{"log":"INF 2022-09-03 03:12:12.001+00:00 Slot start                                 topics=\"beacnde\" slot=3805561 epoch=118923 sync=\"08h43m (87.14%) 0.1750slots/s (QQQQQQQQQP:3800063)\" peers=11 head=3f20d883:3791806 finalized=118491:607dd28f delay=1ms11us995ns\n","stream":"stdout","time":"2022-09-03T03:12:12.00146907Z"}
{"log":"INF 2022-09-03 03:12:12.009+00:00 Syncing in progress; skipping validator duties for now topics=\"beacval\" slot=3805561 headSlot=3791806\n","stream":"stdout","time":"2022-09-03T03:12:12.009305557Z"}
{"log":"INF 2022-09-03 03:12:12.034+00:00 Slot end                                   topics=\"beacnde\" slot=3805561 nextActionWait=n/a nextAttestationSlot=-1 nextProposalSlot=-1 syncCommitteeDuties=none head=3f20d883:3791806\n","stream":"stdout","time":"2022-09-03T03:12:12.034470931Z"}
{"log":"NOT 2022-09-03 03:12:12.389+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35989 peer=16U*ePxmtV direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:12.389941641Z"}
{"log":"NOT 2022-09-03 03:12:16.291+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35990 peer=16U*3Lzriz direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:16.292725545Z"}
{"log":"NOT 2022-09-03 03:12:18.118+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35991 peer=16U*41mTKW direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:18.11935131Z"}
{"log":"NOT 2022-09-03 03:12:19.461+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35992 peer=16U*41mTKW direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:19.461671985Z"}
{"log":"NOT 2022-09-03 03:12:21.341+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35993 peer=16U*oaDETv direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:21.341835356Z"}
{"log":"NOT 2022-09-03 03:12:22.832+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35994 peer=16U*oaDETv direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:22.833512029Z"}

This was on one of my arm64 machines.

Does this look like it would be caught by this PR and resolved autonomously, or is there something else to do here?

@macfarla macfarla added the 22.7.2 label Sep 4, 2022
@matkt
Copy link
Contributor Author

matkt commented Sep 5, 2022

Hi folks, I'm using Besu v22.7.1 with Nimbus v22.8.1 on Goerli/Prater and ran into an issue that @garyschulte recommended I provide here, so you can gauge whether or not this PR would fix it.

Yesterday my Besu node ran into a critical error and it stopped importing new blocks:

{"log":"2022-09-02 19:04:01.036+00:00 | nioEventLoopGroup-3-5 | INFO  | BackwardSyncContext | Backward sync failed (Did not receive a headers for hash 0xc33bdbbe21f95dad81361ffba139b39d983dff362e591f744aadce9540b7eb29). Current Peers: 66. Retrying in 5000 milliseconds...\n","stream":"stdout","time":"2022-09-02T19:04:01.036719219Z"}
{"log":"2022-09-02 19:04:06.149+00:00 | nioEventLoopGroup-3-10 | INFO  | BackwardSyncContext | Backward sync failed (Did not receive a headers for hash 0x7e086e87786bf4ad5da6398a939a98e417ebf4fc8acfdd3ebfe875771124d145). Current Peers: 66. Retrying in 5000 milliseconds...\n","stream":"stdout","time":"2022-09-02T19:04:06.149689208Z"}
{"log":"2022-09-02 19:04:07.245+00:00 | vert.x-eventloop-thread-7 | WARN  | EngineExchangeTransitionConfiguration | not called in 120 seconds, consensus client may not be connected\n","stream":"stdout","time":"2022-09-02T19:04:07.246771771Z"}
{"log":"2022-09-02 19:04:11.248+00:00 | nioEventLoopGroup-3-10 | INFO  | BackwardSyncContext | Backward sync failed (Did not receive a headers for hash 0x7e086e87786bf4ad5da6398a939a98e417ebf4fc8acfdd3ebfe875771124d145). Current Peers: 66. Retrying in 5000 milliseconds...\n","stream":"stdout","time":"2022-09-02T19:04:11.249239501Z"}
{"log":"2022-09-02 19:04:16.456+00:00 | nioEventLoopGroup-3-10 | INFO  | BackwardSyncContext | Backward sync failed (Did not receive a headers for hash 0x7e086e87786bf4ad5da6398a939a98e417ebf4fc8acfdd3ebfe875771124d145). Current Peers: 66. Retrying in 5000 milliseconds...\n","stream":"stdout","time":"2022-09-02T19:04:16.456577848Z"}
{"log":"2022-09-02 19:04:21.713+00:00 | nioEventLoopGroup-3-4 | INFO  | BackwardSyncContext | Backward sync failed (Did not receive a headers for hash 0x7e086e87786bf4ad5da6398a939a98e417ebf4fc8acfdd3ebfe875771124d145). Current Peers: 66. Retrying in 5000 milliseconds...\n","stream":"stdout","time":"2022-09-02T19:04:21.714220699Z"}
{"log":"2022-09-02 19:04:27.314+00:00 | nioEventLoopGroup-3-6 | INFO  | BackwardSyncStep | Saved headers 7515250 -\u003e 7515051 (head: 7507622)\n","stream":"stdout","time":"2022-09-02T19:04:27.314871222Z"}
{"log":"2022-09-02 19:04:27.344+00:00 | ForkJoinPool.commonPool-worker-460 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync\n","stream":"stdout","time":"2022-09-02T19:04:27.34537908Z"}
{"log":"java.lang.RuntimeException: java.lang.IllegalStateException: Address=0xa29d95a19a22492b45a0cb506b93b1345443d662 Prior Value in Rolling Change: nonces differ\n","stream":"stdout","time":"2022-09-02T19:04:30.587171911Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateArchive.getMutable(BonsaiWorldStateArchive.java:206)\n","stream":"stdout","time":"2022-09-02T19:04:30.587267002Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:100)\n","stream":"stdout","time":"2022-09-02T19:04:30.587276044Z"}
{"log":"\u0009at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.validateBlock(MergeCoordinator.java:268)\n","stream":"stdout","time":"2022-09-02T19:04:30.587281294Z"}
{"log":"\u0009at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.rememberBlock(MergeCoordinator.java:284)\n","stream":"stdout","time":"2022-09-02T19:04:30.587285961Z"}
{"log":"\u0009at org.hyperledger.besu.consensus.merge.blockcreation.TransitionCoordinator.rememberBlock(TransitionCoordinator.java:137)\n","stream":"stdout","time":"2022-09-02T19:04:30.587290628Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.engine.EngineNewPayload.syncResponse(EngineNewPayload.java:203)\n","stream":"stdout","time":"2022-09-02T19:04:30.587295003Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.lambda$response$0(ExecutionEngineJsonRpcMethod.java:67)\n","stream":"stdout","time":"2022-09-02T19:04:30.58729967Z"}
{"log":"\u0009at io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)\n","stream":"stdout","time":"2022-09-02T19:04:30.587304629Z"}
{"log":"\u0009at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)\n","stream":"stdout","time":"2022-09-02T19:04:30.587309296Z"}
{"log":"\u0009at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)\n","stream":"stdout","time":"2022-09-02T19:04:30.587313671Z"}
{"log":"\u0009at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)\n","stream":"stdout","time":"2022-09-02T19:04:30.587353049Z"}
{"log":"\u0009at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)\n","stream":"stdout","time":"2022-09-02T19:04:30.587357716Z"}
{"log":"\u0009at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)\n","stream":"stdout","time":"2022-09-02T19:04:30.5873618Z"}
{"log":"\u0009at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n","stream":"stdout","time":"2022-09-02T19:04:30.587365592Z"}
{"log":"\u0009at java.base/java.lang.Thread.run(Thread.java:833)\n","stream":"stdout","time":"2022-09-02T19:04:30.587372009Z"}
{"log":"Caused by: java.lang.IllegalStateException: Address=0xa29d95a19a22492b45a0cb506b93b1345443d662 Prior Value in Rolling Change: nonces differ\n","stream":"stdout","time":"2022-09-02T19:04:30.587462724Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.bonsai.BonsaiAccount.assertCloseEnoughForDiffing(BonsaiAccount.java:303)\n","stream":"stdout","time":"2022-09-02T19:04:30.587504727Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.rollAccountChange(BonsaiWorldStateUpdater.java:497)\n","stream":"stdout","time":"2022-09-02T19:04:30.58752252Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.lambda$rollForward$9(BonsaiWorldStateUpdater.java:422)\n","stream":"stdout","time":"2022-09-02T19:04:30.587539146Z"}
{"log":"\u0009at java.base/java.util.HashMap$EntrySpliterator.forEachRemaining(HashMap.java:1850)\n","stream":"stdout","time":"2022-09-02T19:04:30.587555188Z"}
{"log":"\u0009at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:762)\n","stream":"stdout","time":"2022-09-02T19:04:30.58757094Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.rollForward(BonsaiWorldStateUpdater.java:420)\n","stream":"stdout","time":"2022-09-02T19:04:30.587588441Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateArchive.getMutable(BonsaiWorldStateArchive.java:195)\n","stream":"stdout","time":"2022-09-02T19:04:30.587604484Z"}
{"log":"\u0009... 14 more\n","stream":"stdout","time":"2022-09-02T19:04:30.587620235Z"}
{"log":"2022-09-02 19:04:30.587+00:00 | vert.x-worker-thread-0 | ERROR | MainnetBlockValidator | Unable to process block because parent world state 0xd88b673dffc35d7035e69ecbf77548279c35c1910522190f8dbdc7562e7c48c1 is not available. Block 7515241 (0xe2107822f04ed1033f53f93cb88e3ee70120d16a0aa5f03d3be314c92d760d40)\n","stream":"stdout","time":"2022-09-02T19:04:30.5>
{"log":"2022-09-02 19:04:30.587+00:00 | vert.x-worker-thread-0 | WARN  | EngineNewPayload | Invalid new payload: number: 7515241, hash: 0xe2107822f04ed1033f53f93cb88e3ee70120d16a0aa5f03d3be314c92d760d40, parentHash: 0xfbf75cff95e19b14b30644e3896e7084b01342aa8dc85460494d8e4ebf243a9d, latestValidHash: 0xfbf75cff95e19b14b30644e3896e7084b01342aa8dc85460494d8e4ebf243a9>
{"log":"2022-09-02 19:04:31.141+00:00 | nioEventLoopGroup-3-9 | ERROR | AbstractBlockProcessor | failed persisting block\n","stream":"stdout","time":"2022-09-02T19:04:31.142477295Z"}
{"log":"java.lang.RuntimeException: World State Root does not match expected value, header 0xd88b673dffc35d7035e69ecbf77548279c35c1910522190f8dbdc7562e7c48c1 calculated 0x332ed84d258dd6260d9fca6f35ed5f9206394e01eadc42da3c6c07e01045ff3b\n","stream":"stdout","time":"2022-09-02T19:04:31.142568885Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.bonsai.BonsaiPersistedWorldState.persist(BonsaiPersistedWorldState.java:255)\n","stream":"stdout","time":"2022-09-02T19:04:31.14258872Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:201)\n","stream":"stdout","time":"2022-09-02T19:04:31.142605637Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:42)\n","stream":"stdout","time":"2022-09-02T19:04:31.142667475Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.mainnet.BlockProcessor.processBlock(BlockProcessor.java:75)\n","stream":"stdout","time":"2022-09-02T19:04:31.142685268Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.MainnetBlockValidator.processBlock(MainnetBlockValidator.java:158)\n","stream":"stdout","time":"2022-09-02T19:04:31.142701019Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:112)\n","stream":"stdout","time":"2022-09-02T19:04:31.14271677Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:71)\n","stream":"stdout","time":"2022-09-02T19:04:31.14273223Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.sync.backwardsync.BackwardSyncContext.saveBlock(BackwardSyncContext.java:307)\n","stream":"stdout","time":"2022-09-02T19:04:31.142747981Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.sync.backwardsync.ForwardSyncStep.saveBlocks(ForwardSyncStep.java:104)\n","stream":"stdout","time":"2022-09-02T19:04:31.142764315Z"}
{"log":"\u0009at java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:646)\n","stream":"stdout","time":"2022-09-02T19:04:31.142779775Z"}
{"log":"\u0009at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)\n","stream":"stdout","time":"2022-09-02T19:04:31.142795234Z"}
{"log":"\u0009at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)\n","stream":"stdout","time":"2022-09-02T19:04:31.142810985Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.task.AbstractPeerRequestTask.lambda$executeTask$2(AbstractPeerRequestTask.java:83)\n","stream":"stdout","time":"2022-09-02T19:04:31.142826153Z"}
{"log":"\u0009at java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)\n","stream":"stdout","time":"2022-09-02T19:04:31.142841904Z"}
{"log":"\u0009at java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)\n","stream":"stdout","time":"2022-09-02T19:04:31.142857072Z"}
{"log":"\u0009at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)\n","stream":"stdout","time":"2022-09-02T19:04:31.142878073Z"}
{"log":"\u0009at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)\n","stream":"stdout","time":"2022-09-02T19:04:31.142896741Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.task.AbstractPeerRequestTask.lambda$handleMessage$3(AbstractPeerRequestTask.java:110)\n","stream":"stdout","time":"2022-09-02T19:04:31.142912492Z"}
{"log":"\u0009at java.base/java.util.Optional.ifPresent(Optional.java:178)\n","stream":"stdout","time":"2022-09-02T19:04:31.142928535Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.task.AbstractPeerRequestTask.handleMessage(AbstractPeerRequestTask.java:108)\n","stream":"stdout","time":"2022-09-02T19:04:31.142943995Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.task.AbstractPeerRequestTask.lambda$executeTask$0(AbstractPeerRequestTask.java:67)\n","stream":"stdout","time":"2022-09-02T19:04:31.142959454Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.RequestManager$ResponseStream.dispatchBufferedResponses(RequestManager.java:191)\n","stream":"stdout","time":"2022-09-02T19:04:31.142975205Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.RequestManager$ResponseStream.processMessage(RequestManager.java:182)\n","stream":"stdout","time":"2022-09-02T19:04:31.142990956Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.RequestManager.lambda$dispatchResponse$0(RequestManager.java:74)\n","stream":"stdout","time":"2022-09-02T19:04:31.143006416Z"}
{"log":"\u0009at java.base/java.util.Optional.ifPresentOrElse(Optional.java:196)\n","stream":"stdout","time":"2022-09-02T19:04:31.143043168Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.RequestManager.dispatchResponse(RequestManager.java:73)\n","stream":"stdout","time":"2022-09-02T19:04:31.143060086Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.EthPeer.lambda$dispatch$7(EthPeer.java:386)\n","stream":"stdout","time":"2022-09-02T19:04:31.143075837Z"}
{"log":"\u0009at java.base/java.util.Optional.ifPresentOrElse(Optional.java:196)\n","stream":"stdout","time":"2022-09-02T19:04:31.143091005Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.EthPeer.dispatch(EthPeer.java:385)\n","stream":"stdout","time":"2022-09-02T19:04:31.143106173Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.EthPeers.dispatchMessage(EthPeers.java:158)\n","stream":"stdout","time":"2022-09-02T19:04:31.14312134Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.eth.manager.EthProtocolManager.processMessage(EthProtocolManager.java:294)\n","stream":"stdout","time":"2022-09-02T19:04:31.1431368Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.p2p.network.NetworkRunner.lambda$setupHandlers$0(NetworkRunner.java:135)\n","stream":"stdout","time":"2022-09-02T19:04:31.143152551Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.p2p.rlpx.connections.PeerConnectionEvents.lambda$dispatchMessage$1(PeerConnectionEvents.java:64)\n","stream":"stdout","time":"2022-09-02T19:04:31.143168302Z"}
{"log":"\u0009at org.hyperledger.besu.util.Subscribers.lambda$forEach$0(Subscribers.java:112)\n","stream":"stdout","time":"2022-09-02T19:04:31.143184053Z"}
{"log":"\u0009at java.base/java.lang.Iterable.forEach(Iterable.java:75)\n","stream":"stdout","time":"2022-09-02T19:04:31.143199804Z"}
{"log":"\u0009at org.hyperledger.besu.util.Subscribers.forEach(Subscribers.java:109)\n","stream":"stdout","time":"2022-09-02T19:04:31.143215264Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.p2p.rlpx.connections.PeerConnectionEvents.dispatchMessage(PeerConnectionEvents.java:64)\n","stream":"stdout","time":"2022-09-02T19:04:31.14323014Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.p2p.rlpx.connections.netty.ApiHandler.channelRead0(ApiHandler.java:99)\n","stream":"stdout","time":"2022-09-02T19:04:31.143247349Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.p2p.rlpx.connections.netty.ApiHandler.channelRead0(ApiHandler.java:33)\n","stream":"stdout","time":"2022-09-02T19:04:31.1432631Z"}
{"log":"\u0009at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99)\n","stream":"stdout","time":"2022-09-02T19:04:31.14327856Z"}
{"log":"\u0009at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)\n","stream":"stdout","time":"2022-09-02T19:04:31.143294311Z"}
{"log":"\u0009at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)\n","stream":"stdout","time":"2022-09-02T19:04:31.14330977Z"}
{"log":"\u0009at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)\n","stream":"stdout","time":"2022-09-02T19:04:31.14332523Z"}
{"log":"\u0009at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286)\n","stream":"stdout","time":"2022-09-02T19:04:31.143340981Z"}
{"log":"\u0009at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)\n","stream":"stdout","time":"2022-09-02T19:04:31.143356149Z"}
{"log":"\u0009at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)\n","stream":"stdout","time":"2022-09-02T19:04:31.143371608Z"}
{"log":"\u0009at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)\n","stream":"stdout","time":"2022-09-02T19:04:31.143387359Z"}
{"log":"\u0009at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:327)\n","stream":"stdout","time":"2022-09-02T19:04:31.14340311Z"}
{"log":"\u0009at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:299)\n","stream":"stdout","time":"2022-09-02T19:04:31.143437529Z"}
{"log":"\u0009at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)\n","stream":"stdout","time":"2022-09-02T19:04:31.143454739Z"}
{"log":"\u0009at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)\n","stream":"stdout","time":"2022-09-02T19:04:31.143470198Z"}
{"log":"\u0009at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)\n","stream":"stdout","time":"2022-09-02T19:04:31.143485949Z"}
{"log":"\u0009at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)\n","stream":"stdout","time":"2022-09-02T19:04:31.143501701Z"}
{"log":"\u0009at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)\n","stream":"stdout","time":"2022-09-02T19:04:31.143517452Z"}
{"log":"\u0009at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)\n","stream":"stdout","time":"2022-09-02T19:04:31.143532911Z"}
{"log":"\u0009at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)\n","stream":"stdout","time":"2022-09-02T19:04:31.143548371Z"}
{"log":"\u0009at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)\n","stream":"stdout","time":"2022-09-02T19:04:31.14356558Z"}
{"log":"\u0009at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:722)\n","stream":"stdout","time":"2022-09-02T19:04:31.14358454Z"}
{"log":"\u0009at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658)\n","stream":"stdout","time":"2022-09-02T19:04:31.143599999Z"}
{"log":"\u0009at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584)\n","stream":"stdout","time":"2022-09-02T19:04:31.143615459Z"}
{"log":"\u0009at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496)\n","stream":"stdout","time":"2022-09-02T19:04:31.143630918Z"}
{"log":"\u0009at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)\n","stream":"stdout","time":"2022-09-02T19:04:31.143646086Z"}
{"log":"\u0009at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)\n","stream":"stdout","time":"2022-09-02T19:04:31.143661545Z"}
{"log":"\u0009at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n","stream":"stdout","time":"2022-09-02T19:04:31.143676421Z"}
{"log":"\u0009at java.base/java.lang.Thread.run(Thread.java:833)\n","stream":"stdout","time":"2022-09-02T19:04:31.143692172Z"}
{"log":"2022-09-02 19:04:31.142+00:00 | nioEventLoopGroup-3-9 | ERROR | MainnetBlockValidator | Error processing block. Block 7515240 (0xfbf75cff95e19b14b30644e3896e7084b01342aa8dc85460494d8e4ebf243a9d)\n","stream":"stdout","time":"2022-09-02T19:04:31.14370734Z"}
{"log":"2022-09-02 19:04:31.143+00:00 | nioEventLoopGroup-3-9 | WARN  | EngineNewPayload | Sync to block 7515278 (0x508f5c9c63cc63a7808158091f4d41629fa1c89e79d82d7a912e1c81e7436437) failed\n","stream":"stdout","time":"2022-09-02T19:04:31.143723383Z"}
{"log":"2022-09-02 19:04:31.143+00:00 | nioEventLoopGroup-3-9 | WARN  | EngineNewPayload | Sync to block 7515251 (0x571781474a096227f22d4f53b0e8e698c35339dd2be5ad400b21beffd8771dfe) failed\n","stream":"stdout","time":"2022-09-02T19:04:31.143739426Z"}
{"log":"2022-09-02 19:06:07.248+00:00 | vert.x-eventloop-thread-7 | WARN  | EngineExchangeTransitionConfiguration | not called in 120 seconds, consensus client may not be connected\n","stream":"stdout","time":"2022-09-02T19:06:07.249973489Z"}
{"log":"2022-09-02 19:08:07.302+00:00 | vert.x-eventloop-thread-7 | WARN  | EngineExchangeTransitionConfiguration | not called in 120 seconds, consensus client may not be connected\n","stream":"stdout","time":"2022-09-02T19:08:07.303532006Z"}
...

At which point, Nimbus started printing the following over and over again and stopped syncing:

{"log":"NOT 2022-09-03 03:11:48.933+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35976 peer=16U*dkZxtG direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:11:48.934579698Z"}
{"log":"NOT 2022-09-03 03:11:50.414+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35977 peer=16U*5WRyPT direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:11:50.415324575Z"}
{"log":"NOT 2022-09-03 03:11:51.977+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35978 peer=16U*5WRyPT direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:11:51.977682686Z"}
{"log":"NOT 2022-09-03 03:11:53.824+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35979 peer=16U*DiWMtw direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:11:53.824608262Z"}
{"log":"NOT 2022-09-03 03:11:55.149+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35980 peer=16U*DiWMtw direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:11:55.149763396Z"}
{"log":"NOT 2022-09-03 03:11:57.180+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35981 peer=16U*FsPSND direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:11:57.181073686Z"}
{"log":"NOT 2022-09-03 03:11:58.940+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35982 peer=16U*FsPSND direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:11:58.941103437Z"}
{"log":"INF 2022-09-03 03:12:00.000+00:00 Slot start                                 topics=\"beacnde\" slot=3805560 epoch=118923 sync=\"08h43m (87.14%) 0.1750slots/s (QQQQQQQQQD:3800063)\" peers=11 head=3f20d883:3791806 finalized=118491:607dd28f delay=217us912ns\n","stream":"stdout","time":"2022-09-03T03:12:00.000984176Z"}
{"log":"INF 2022-09-03 03:12:00.023+00:00 Syncing in progress; skipping validator duties for now topics=\"beacval\" slot=3805560 headSlot=3791806\n","stream":"stdout","time":"2022-09-03T03:12:00.023552069Z"}
{"log":"INF 2022-09-03 03:12:00.058+00:00 Slot end                                   topics=\"beacnde\" slot=3805560 nextActionWait=n/a nextAttestationSlot=-1 nextProposalSlot=-1 syncCommitteeDuties=none head=3f20d883:3791806\n","stream":"stdout","time":"2022-09-03T03:12:00.059035277Z"}
{"log":"NOT 2022-09-03 03:12:01.086+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35983 peer=16U*NeZjdV direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:01.086858683Z"}
{"log":"NOT 2022-09-03 03:12:02.638+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35984 peer=16U*NeZjdV direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:02.639406288Z"}
{"log":"NOT 2022-09-03 03:12:04.615+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35985 peer=16U*S3i4gQ direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:04.616105644Z"}
{"log":"NOT 2022-09-03 03:12:07.296+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35986 peer=16U*C7uogE direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:07.296970845Z"}
{"log":"NOT 2022-09-03 03:12:09.696+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35987 peer=16U*C7uogE direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:09.696694497Z"}
{"log":"NOT 2022-09-03 03:12:11.366+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35988 peer=16U*ePxmtV direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:11.366538432Z"}
{"log":"INF 2022-09-03 03:12:12.001+00:00 Slot start                                 topics=\"beacnde\" slot=3805561 epoch=118923 sync=\"08h43m (87.14%) 0.1750slots/s (QQQQQQQQQP:3800063)\" peers=11 head=3f20d883:3791806 finalized=118491:607dd28f delay=1ms11us995ns\n","stream":"stdout","time":"2022-09-03T03:12:12.00146907Z"}
{"log":"INF 2022-09-03 03:12:12.009+00:00 Syncing in progress; skipping validator duties for now topics=\"beacval\" slot=3805561 headSlot=3791806\n","stream":"stdout","time":"2022-09-03T03:12:12.009305557Z"}
{"log":"INF 2022-09-03 03:12:12.034+00:00 Slot end                                   topics=\"beacnde\" slot=3805561 nextActionWait=n/a nextAttestationSlot=-1 nextProposalSlot=-1 syncCommitteeDuties=none head=3f20d883:3791806\n","stream":"stdout","time":"2022-09-03T03:12:12.034470931Z"}
{"log":"NOT 2022-09-03 03:12:12.389+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35989 peer=16U*ePxmtV direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:12.389941641Z"}
{"log":"NOT 2022-09-03 03:12:16.291+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35990 peer=16U*3Lzriz direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:16.292725545Z"}
{"log":"NOT 2022-09-03 03:12:18.118+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35991 peer=16U*41mTKW direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:18.11935131Z"}
{"log":"NOT 2022-09-03 03:12:19.461+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35992 peer=16U*41mTKW direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:19.461671985Z"}
{"log":"NOT 2022-09-03 03:12:21.341+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35993 peer=16U*oaDETv direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:21.341835356Z"}
{"log":"NOT 2022-09-03 03:12:22.832+00:00 Received blocks from an unviable fork      topics=\"syncman\" request=3800064:32@35994 peer=16U*oaDETv direction=forward blockRoot=8934e70b blockSlot=3800064 blocks_count=26 blocks_map=xxx.xxxxxxxx..xxxxxxxxx.xxxx..xx sync_ident=main\n","stream":"stdout","time":"2022-09-03T03:12:22.833512029Z"}

This was on one of my arm64 machines.

Does this look like it would be caught by this PR and resolved autonomously, or is there something else to do here?

do you still have the error? if so could you run this PR to see if it fixes the problem ?

Signed-off-by: Karim TAAM <karim.t2am@gmail.com>
@matkt matkt marked this pull request as ready for review September 5, 2022 08:04
Signed-off-by: Karim TAAM <karim.t2am@gmail.com>
Signed-off-by: Karim TAAM <karim.t2am@gmail.com>
Signed-off-by: Karim TAAM <karim.t2am@gmail.com>
Copy link
Contributor

@jflo jflo left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Logger name needs to be corrected, and I think we can do better than ifPresent for that Optional. Other than that, just comments.

return maybeFallbackNodeFinder;
}

public void addFallbackNodeFinder(final Optional<PeerTrieNodeFinder> maybeFallbackNodeFinder) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

When I saw this was called addFallbackNodeFinder, I expected it to be adding to a collection. This is not the case as there is only a single member to use for fallback. perhaps setFallbackNodeFiner or useFallbackNodeFinder would be more intuitive.

msg.capability, new DefaultMessage(peerConnection, response));
} else
snapProtocolManager.ifPresent(
protocolManager ->
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could also wrap this in a capability check to make sure snap manager can handle it.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

not sure to understand this one ? modifying this test class or another part ?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

For this test class. It will exercise the capabilities collection checking.

if (response.containsKey(nodeHash)) {
LOG.trace("Found node {} with getNodeData request", nodeHash);
return Optional.of(response.get(nodeHash));
}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

else case isn't handled, I think it might warrant a TRACE statement just like the if case.

if (nodeValue != null && Hash.hash(nodeValue).equals(nodeHash)) {
LOG.trace("Found node {} with getTrieNode request", nodeHash);
return Optional.of(nodeValue);
}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

same suggestion here, to better track our assumptions.

Signed-off-by: Karim TAAM <karim.t2am@gmail.com>
@@ -101,6 +101,8 @@ private DefaultBlockchain(
chainHeadTransactionCount = chainHeadBody.getTransactions().size();
chainHeadOmmerCount = chainHeadBody.getOmmers().size();

System.out.println("head " + getChainHead().getHeight() + " " + getChainHead().getHash());
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

probably meant to use a Logger or remove?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

for test forgot to remove it

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

good catch

Signed-off-by: Karim TAAM <karim.t2am@gmail.com>
@jclapis
Copy link
Contributor

jclapis commented Sep 6, 2022

do you still have the error? if so could you run this PR to see if it fixes the problem ?

Yes, I've actually had pretty consistent failures on Prater using 22.7.1 (and later a 22.7.2 snapshot from a few days ago). It's always related to a nonce mismatch; Besu thinks a block is invalid due to miscounting nonces when the other clients seem to think the block is fine.

Here's another example:

{"log":"2022-09-06 13:00:29.248+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | INVALID for fork-choice-update: head: 0x81d576d6d6ddabf296f4cc6500beb15b28d4c717ac3931dd98be076a5cbe24d2, finalized: 0xe4cb541214ad20ef803c668118acd1558a1eeaa07ca873d32c573eecdb02dfd1, safeBlockHash: 0x1dcb07708f28fb93c730bae85500f440bd612fa58bc7fbf929f4ed86453cbea4\n","stream":"stdout","time":"2022-09-06T13:00:29.248953405Z"}
{"log":"2022-09-06 13:00:29.267+00:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head\n","stream":"stdout","time":"2022-09-06T13:00:29.2678988Z"}
{"log":"2022-09-06 13:00:30.404+00:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head\n","stream":"stdout","time":"2022-09-06T13:00:30.405151309Z"}
{"log":"2022-09-06 13:00:30.424+00:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head\n","stream":"stdout","time":"2022-09-06T13:00:30.424980517Z"}
{"log":"2022-09-06 13:00:31.631+00:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head\n","stream":"stdout","time":"2022-09-06T13:00:31.63167011Z"}
{"log":"2022-09-06 13:00:31.639+00:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head\n","stream":"stdout","time":"2022-09-06T13:00:31.639535464Z"}
{"log":"2022-09-06 13:00:33.775+00:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head\n","stream":"stdout","time":"2022-09-06T13:00:33.775686102Z"}
{"log":"2022-09-06 13:00:33.785+00:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head\n","stream":"stdout","time":"2022-09-06T13:00:33.78597917Z"}
{"log":"2022-09-06 13:00:34.949+00:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head\n","stream":"stdout","time":"2022-09-06T13:00:34.949660609Z"}
{"log":"2022-09-06 13:00:34.969+00:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head\n","stream":"stdout","time":"2022-09-06T13:00:34.96979813Z"}
{"log":"java.lang.RuntimeException: java.lang.IllegalStateException: Expected to create account, but the account exists.  Address=0x11361f33b72646a343d0084a2d75c1866e29bd4d\n","stream":"stdout","time":"2022-09-06T13:00:36.403494394Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateArchive.getMutable(BonsaiWorldStateArchive.java:206)\n","stream":"stdout","time":"2022-09-06T13:00:36.403617486Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:100)\n","stream":"stdout","time":"2022-09-06T13:00:36.403638488Z"}
{"log":"\u0009at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.validateBlock(MergeCoordinator.java:269)\n","stream":"stdout","time":"2022-09-06T13:00:36.403657156Z"}
{"log":"\u0009at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.rememberBlock(MergeCoordinator.java:285)\n","stream":"stdout","time":"2022-09-06T13:00:36.40367524Z"}
{"log":"\u0009at org.hyperledger.besu.consensus.merge.blockcreation.TransitionCoordinator.rememberBlock(TransitionCoordinator.java:137)\n","stream":"stdout","time":"2022-09-06T13:00:36.403693617Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.engine.EngineNewPayload.syncResponse(EngineNewPayload.java:209)\n","stream":"stdout","time":"2022-09-06T13:00:36.403777331Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.lambda$response$0(ExecutionEngineJsonRpcMethod.java:67)\n","stream":"stdout","time":"2022-09-06T13:00:36.403795707Z"}
{"log":"\u0009at io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)\n","stream":"stdout","time":"2022-09-06T13:00:36.403812042Z"}
{"log":"\u0009at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)\n","stream":"stdout","time":"2022-09-06T13:00:36.403828085Z"}
{"log":"\u0009at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)\n","stream":"stdout","time":"2022-09-06T13:00:36.403843544Z"}
{"log":"\u0009at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)\n","stream":"stdout","time":"2022-09-06T13:00:36.403859295Z"}
{"log":"\u0009at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)\n","stream":"stdout","time":"2022-09-06T13:00:36.403874755Z"}
{"log":"\u0009at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)\n","stream":"stdout","time":"2022-09-06T13:00:36.403890797Z"}
{"log":"\u0009at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n","stream":"stdout","time":"2022-09-06T13:00:36.403906549Z"}
{"log":"\u0009at java.base/java.lang.Thread.run(Thread.java:833)\n","stream":"stdout","time":"2022-09-06T13:00:36.403922008Z"}
{"log":"Caused by: java.lang.IllegalStateException: Expected to create account, but the account exists.  Address=0x11361f33b72646a343d0084a2d75c1866e29bd4d\n","stream":"stdout","time":"2022-09-06T13:00:36.40395176Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.rollAccountChange(BonsaiWorldStateUpdater.java:493)\n","stream":"stdout","time":"2022-09-06T13:00:36.403969845Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.lambda$rollForward$9(BonsaiWorldStateUpdater.java:422)\n","stream":"stdout","time":"2022-09-06T13:00:36.403986179Z"}
{"log":"\u0009at java.base/java.util.HashMap$EntrySpliterator.forEachRemaining(HashMap.java:1850)\n","stream":"stdout","time":"2022-09-06T13:00:36.404002222Z"}
{"log":"\u0009at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:762)\n","stream":"stdout","time":"2022-09-06T13:00:36.404017681Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.rollForward(BonsaiWorldStateUpdater.java:420)\n","stream":"stdout","time":"2022-09-06T13:00:36.404033433Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateArchive.getMutable(BonsaiWorldStateArchive.java:195)\n","stream":"stdout","time":"2022-09-06T13:00:36.404049184Z"}
{"log":"\u0009... 14 more\n","stream":"stdout","time":"2022-09-06T13:00:36.404064935Z"}
{"log":"2022-09-06 13:00:36.403+00:00 | vert.x-worker-thread-0 | ERROR | MainnetBlockValidator | Unable to process block because parent world state 0x2e0e6aac7d547931e0bb7af9b9aec476c3c40e79be37c3f8ee1aad7b8f45f0ac is not available. Block 7541211 (0x9a244ce2271fe94ed16fc2dd885624291b9b95fd66f02eca3b251af2755514d5)\n","stream":"stdout","time":"2022-09-06T13:00:36.404081561Z"}
{"log":"2022-09-06 13:00:36.403+00:00 | vert.x-worker-thread-0 | WARN  | EngineNewPayload | Invalid new payload: number: 7541211, hash: 0x9a244ce2271fe94ed16fc2dd885624291b9b95fd66f02eca3b251af2755514d5, parentHash: 0xa5cf8669714f5ec91eaea5e882f1eff3e0f4dc6e10e29cc7d9a1790b28f091a6, latestValidHash: 0xa5cf8669714f5ec91eaea5e882f1eff3e0f4dc6e10e29cc7d9a1790b28f091a6, status: INVALID, validationError: Unable to process block because parent world state 0x2e0e6aac7d547931e0bb7af9b9aec476c3c40e79be37c3f8ee1aad7b8f45f0ac is not available\n","stream":"stdout","time":"2022-09-06T13:00:36.404100521Z"}
{"log":"2022-09-06 13:00:36.609+00:00 | vert.x-worker-thread-0 | WARN  | MainnetBlockBodyValidator | Invalid block: state root mismatch (expected=0x9b96a52c67ad075ac1b69d737917cf23472d089730451bee99537cdea92bcd3b, actual=0x2e0e6aac7d547931e0bb7af9b9aec476c3c40e79be37c3f8ee1aad7b8f45f0ac)\n","stream":"stdout","time":"2022-09-06T13:00:36.609860674Z"}
{"log":"2022-09-06 13:00:36.609+00:00 | vert.x-worker-thread-0 | WARN  | MainnetBlockBodyValidator | Invalid block RLP : 0xf90200f901fba0a5cf8669714f5ec91eaea5e882f1eff3e0f4dc6e10e29cc7d9a1790b28f091a6a01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d4934794d4e96ef8eee8678dbff4d535e033ed1a4f7605b7a09b96a52c67ad075ac1b69d737917cf23472d089730451bee99537cdea92bcd3ba056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421b901000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000080837311db8401c9c38080846317435480a0d857b00ffba384e85be65627900e3303b7fb0484ae6b3a9455f2c95c6e0e760988000000000000000082beb6c0c0\n","stream":"stdout","time":"2022-09-06T13:00:36.609977057Z"}
{"log":"2022-09-06 13:00:36.609+00:00 | vert.x-worker-thread-0 | ERROR | MainnetBlockValidator | Block body not valid. Block 7541211 (0xe2addaf1297a9639c066d4c954ec2acc149c6d3fefce7337417029ab5ec0c413)\n","stream":"stdout","time":"2022-09-06T13:00:36.610005934Z"}
{"log":"2022-09-06 13:00:36.609+00:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | failed to execute empty block proposal 0xe2addaf1297a9639c066d4c954ec2acc149c6d3fefce7337417029ab5ec0c413, reason Optional[Block body not valid]\n","stream":"stdout","time":"2022-09-06T13:00:36.610023144Z"}
{"log":"2022-09-06 13:00:38.745+00:00 | nioEventLoopGroup-3-6 | INFO  | AbstractBlockProcessor | Block processing error: transaction invalid 'NONCE_TOO_LOW'. Block 0xa5cf8669714f5ec91eaea5e882f1eff3e0f4dc6e10e29cc7d9a1790b28f091a6 Transaction 0xee6451818db82efe0c4f5c9fc19697c5603727cae62fd535ff360e3ea0aaa79e\n","stream":"stdout","time":"2022-09-06T13:00:38.746115153Z"}
{"log":"2022-09-06 13:00:38.745+00:00 | nioEventLoopGroup-3-6 | ERROR | MainnetBlockValidator | Error processing block. Block 7541210 (0xa5cf8669714f5ec91eaea5e882f1eff3e0f4dc6e10e29cc7d9a1790b28f091a6)\n","stream":"stdout","time":"2022-09-06T13:00:38.746211118Z"}

I will build an image with this PR and try it out.

@jclapis
Copy link
Contributor

jclapis commented Sep 7, 2022

Unfortunately, this PR didn't seem to fix my problem - it seems to have made it considerably worse; I can barely keep Besu synced for an hour before it breaks with constant log messages such as:

{"log":"2022-09-07 02:28:46.339+00:00 | ForkJoinPool.commonPool-worker-3 | WARN  | MergeCoordinator | something went wrong creating block\n","stream":"stdout","time":"2022-09-07T02:28:46.340656873Z"}
{"log":"java.util.concurrent.CompletionException: java.lang.IllegalStateException: Block creation failed unexpectedly. Will restart on next block added to chain.\n","stream":"stdout","time":"2022-09-07T02:28:46.340813217Z"}
{"log":"\u0009at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:315)\n","stream":"stdout","time":"2022-09-07T02:28:46.340892264Z"}
{"log":"\u0009at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:320)\n","stream":"stdout","time":"2022-09-07T02:28:46.340914724Z"}
{"log":"\u0009at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1770)\n","stream":"stdout","time":"2022-09-07T02:28:46.340933684Z"}
{"log":"\u0009at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.exec(CompletableFuture.java:1760)\n","stream":"stdout","time":"2022-09-07T02:28:46.340953227Z"}
{"log":"\u0009at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:373)\n","stream":"stdout","time":"2022-09-07T02:28:46.340971895Z"}
{"log":"\u0009at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1182)\n","stream":"stdout","time":"2022-09-07T02:28:46.340991146Z"}
{"log":"\u0009at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1655)\n","stream":"stdout","time":"2022-09-07T02:28:46.341010106Z"}
{"log":"\u0009at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1622)\n","stream":"stdout","time":"2022-09-07T02:28:46.341029066Z"}
{"log":"\u0009at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:165)\n","stream":"stdout","time":"2022-09-07T02:28:46.341047734Z"}
{"log":"Caused by: java.lang.IllegalStateException: Block creation failed unexpectedly. Will restart on next block added to chain.\n","stream":"stdout","time":"2022-09-07T02:28:46.341066402Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.blockcreation.AbstractBlockCreator.createBlock(AbstractBlockCreator.java:211)\n","stream":"stdout","time":"2022-09-07T02:28:46.341085653Z"}
{"log":"\u0009at org.hyperledger.besu.consensus.merge.blockcreation.MergeBlockCreator.createBlock(MergeBlockCreator.java:67)\n","stream":"stdout","time":"2022-09-07T02:28:46.341105196Z"}
{"log":"\u0009at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.lambda$preparePayload$3(MergeCoordinator.java:193)\n","stream":"stdout","time":"2022-09-07T02:28:46.341124156Z"}
{"log":"\u0009at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1768)\n","stream":"stdout","time":"2022-09-07T02:28:46.34114399Z"}
{"log":"\u0009... 6 more\n","stream":"stdout","time":"2022-09-07T02:28:46.34116295Z"}
{"log":"Caused by: org.hyperledger.besu.plugin.services.exception.StorageException: org.rocksdb.RocksDBException: TimedOut(LockTimeout)\n","stream":"stdout","time":"2022-09-07T02:28:46.341181326Z"}
{"log":"\u0009at org.hyperledger.besu.plugin.services.storage.rocksdb.segmented.RocksDBColumnarKeyValueStorage$RocksDbTransaction.put(RocksDBColumnarKeyValueStorage.java:266)\n","stream":"stdout","time":"2022-09-07T02:28:46.341200286Z"}
{"log":"\u0009at org.hyperledger.besu.plugin.services.storage.rocksdb.segmented.RocksDBColumnarKeyValueStorage$RocksDbTransaction.put(RocksDBColumnarKeyValueStorage.java:247)\n","stream":"stdout","time":"2022-09-07T02:28:46.341222454Z"}
{"log":"\u0009at org.hyperledger.besu.services.kvstore.SegmentedKeyValueStorageTransactionTransitionValidatorDecorator.put(SegmentedKeyValueStorageTransactionTransitionValidatorDecorator.java:36)\n","stream":"stdout","time":"2022-09-07T02:28:46.341242581Z"}
{"log":"\u0009at org.hyperledger.besu.services.kvstore.SegmentedKeyValueStorageAdapter$1.put(SegmentedKeyValueStorageAdapter.java:80)\n","stream":"stdout","time":"2022-09-07T02:28:46.341262416Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateKeyValueStorage$Updater.putStorageValueBySlotHash(BonsaiWorldStateKeyValueStorage.java:362)\n","stream":"stdout","time":"2022-09-07T02:28:46.341281375Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.bonsai.BonsaiPersistedWorldState.calculateRootHash(BonsaiPersistedWorldState.java:171)\n","stream":"stdout","time":"2022-09-07T02:28:46.341301502Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.bonsai.BonsaiInMemoryWorldState.rootHash(BonsaiInMemoryWorldState.java:43)\n","stream":"stdout","time":"2022-09-07T02:28:46.341339129Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.bonsai.BonsaiInMemoryWorldState.rootHash(BonsaiInMemoryWorldState.java:37)\n","stream":"stdout","time":"2022-09-07T02:28:46.341359547Z"}
{"log":"\u0009at org.hyperledger.besu.ethereum.blockcreation.AbstractBlockCreator.createBlock(AbstractBlockCreator.java:193)\n","stream":"stdout","time":"2022-09-07T02:28:46.341378799Z"}
{"log":"\u0009... 9 more\n","stream":"stdout","time":"2022-09-07T02:28:46.341397758Z"}
{"log":"Caused by: org.rocksdb.RocksDBException: TimedOut(LockTimeout)\n","stream":"stdout","time":"2022-09-07T02:28:46.341415843Z"}
{"log":"\u0009at org.rocksdb.Transaction.put(Native Method)\n","stream":"stdout","time":"2022-09-07T02:28:46.341434219Z"}
{"log":"\u0009at org.rocksdb.Transaction.put(Transaction.java:705)\n","stream":"stdout","time":"2022-09-07T02:28:46.341452596Z"}
{"log":"\u0009at org.hyperledger.besu.plugin.services.storage.rocksdb.segmented.RocksDBColumnarKeyValueStorage$RocksDbTransaction.put(RocksDBColumnarKeyValueStorage.java:260)\n","stream":"stdout","time":"2022-09-07T02:28:46.341471847Z"}
{"log":"\u0009... 17 more\n","stream":"stdout","time":"2022-09-07T02:28:46.341491098Z"}

It looks like RocksDB is constantly timing out. Perhaps there's a setting somewhere that is just overly aggressively tuned? CC @garyschulte, did that change between 22.7.1 and this PR?

I've attached a full log file here for reference so you can see the stream of errors... hopefully there is some insight to be gleaned:

besu-3.log

@garyschulte garyschulte enabled auto-merge (squash) September 7, 2022 17:44
@garyschulte garyschulte merged commit c57dcd9 into hyperledger:main Sep 7, 2022
garyschulte pushed a commit to garyschulte/besu that referenced this pull request Sep 7, 2022
* fix trie by asking peers

Signed-off-by: Karim TAAM <karim.t2am@gmail.com>
garyschulte pushed a commit to garyschulte/besu that referenced this pull request Sep 7, 2022
* fix trie by asking peers

Signed-off-by: Karim TAAM <karim.t2am@gmail.com>
garyschulte pushed a commit to garyschulte/besu that referenced this pull request Sep 7, 2022
* fix trie by asking peers

Signed-off-by: Karim TAAM <karim.t2am@gmail.com>
Signed-off-by: garyschulte <garyschulte@gmail.com>
@matkt matkt deleted the feature/fallback-mechanism-to-fix-trie branch August 17, 2023 07:27
eum602 pushed a commit to lacchain/besu that referenced this pull request Nov 3, 2023
* fix trie by asking peers

Signed-off-by: Karim TAAM <karim.t2am@gmail.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants