besu
besu copied to clipboard
Concurrency issue with Nimbus/Besu combination
Description
The nimbus behavior in 2.8.2 (asking for a proposal on each forkchoice) uncovered a concurrency issue with Besu block proposals:
Report from @jclapis:
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?
Originally posted by @jclapis in https://github.com/hyperledger/besu/issues/4312#issuecomment-1236054598
Versions (Add all that apply)
- Software version: 22.7.1+
- Java version: [
java -version
] - OS Name & Version: [
cat /etc/*release
] - Kernel Version: [
uname -a
] - Virtual Machine software & version: [
vmware -v
] - Docker Version: [
docker version
] - Cloud VM, type, size: [Amazon Web Services I3-large]
Another Discord user reporting this with besu 22.7.5 and Nimbus 22.10.0 https://discord.com/channels/905194001349627914/938504958909747250/1027420741509058691