Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

Concurrency issue with Nimbus/Besu combination #4372

Closed
garyschulte opened this issue Sep 8, 2022 · 1 comment
Closed

Concurrency issue with Nimbus/Besu combination #4372

garyschulte opened this issue Sep 8, 2022 · 1 comment
Assignees
@garyschulte

Comments

@garyschulte
Copy link
Contributor

garyschulte commented Sep 8, 2022 •
edited
Loading

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 #4312 (comment)

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]
@garyschulte garyschulte changed the title 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. Concurrency issue discovered with Nimbus/Besu combination Sep 8, 2022
@garyschulte garyschulte changed the title Concurrency issue discovered with Nimbus/Besu combination Concurrency issue with Nimbus/Besu combination Sep 8, 2022
@garyschulte garyschulte mentioned this issue Sep 8, 2022
Closed
2 tasks
@siladu siladu mentioned this issue Sep 16, 2022
Closed
@matkt matkt mentioned this issue Sep 16, 2022
Closed
@garyschulte garyschulte mentioned this issue Sep 16, 2022
Merged
2 tasks
@macfarla
Copy link
Contributor

macfarla commented Oct 6, 2022

Another Discord user reporting this with besu 22.7.5 and Nimbus 22.10.0 https://discord.com/channels/905194001349627914/938504958909747250/1027420741509058691

@garyschulte garyschulte mentioned this issue Oct 13, 2022
Merged
2 tasks
@garyschulte garyschulte self-assigned this Oct 31, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@garyschulte garyschulte

Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

bugfix: BlockValidator should pass shouldPersist flag when getting worldstate garyschulte/besu
2 participants
@garyschulte @macfarla