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

Besu fails to sync after the merge with empty DB #3988

Closed
zilm13 opened this issue Jun 17, 2022 · 2 comments
Closed

Besu fails to sync after the merge with empty DB #3988

zilm13 opened this issue Jun 17, 2022 · 2 comments
Labels
bug Something isn't working mainnet TeamRevenant GH issues worked on by Revenant Team

Comments

@zilm13
Copy link

zilm13 commented Jun 17, 2022

Description

Besu fails to sync when I delete DB after the merge and start syncing again

Steps to Reproduce (Bug)

I have an issue in Teku acceptance test, could provide any level of logs.
Test flow:
Teku1 (all vals) -> Besu1 (mining)
Teku2 (no vals, connected to Teku1) -> Besu2 (connected to Besu1)
[..waiting for merge to happen..]
Right after Merge:
Besu2 - DB erased, restarted
Teku2 - wait for optimistic import, success
Besu2.addPeer(Besu1)
Now sync between Besu1 and Besu2 begins from empty DB. For 22.4.1 it failed on backward sync, I've upgraded to 22.4.3 where backward sync is fixed, now Besu2 fails with following logs:

2022-06-17 18:30:54.533+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:54.531+00:00 | main | INFO  | Besu | Using LibEthPairings native alt bn128
2022-06-17 18:30:54.534+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:54.533+00:00 | main | INFO  | Besu | Using the native implementation of the signature algorithm
2022-06-17 18:30:54.538+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:54.537+00:00 | main | INFO  | Besu | Starting Besu version: besu/v22.4.3/linux-x86_64/openjdk-java-11
2022-06-17 18:30:55.062+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:55.062+00:00 | main | INFO  | Besu | Static Nodes file = /opt/besu/static-nodes.json
2022-06-17 18:30:55.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:55.063+00:00 | main | INFO  | StaticNodesParser | StaticNodes file /opt/besu/static-nodes.json does not exist, no static connections will be created.
2022-06-17 18:30:55.064+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:55.063+00:00 | main | INFO  | Besu | Connecting to 0 static nodes.
2022-06-17 18:30:55.067+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:55.066+00:00 | main | INFO  | Besu | Security Module: localfile
2022-06-17 18:30:55.090+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:55.089+00:00 | main | INFO  | RocksDBKeyValueStorageFactory | No existing database detected at /opt/besu. Using version 1
2022-06-17 18:30:55.713+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:55.712+00:00 | main | INFO  | KeyPairUtil | Generated new secp256k1 public key 0x0823d1a9a0784ba8d0adaa802c64ce2c82b057f8804781a55f3854c1f69b2b41d669fad5357719a45119bf9b999b50aa4b4054f4e23a885fef35e73987db22ba and stored it to /opt/besu/key
2022-06-17 18:30:55.884+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:55.883+00:00 | main | INFO  | ProtocolScheduleBuilder | Protocol schedule created with milestones: [ParisFork: 0]
2022-06-17 18:30:55.909+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:55.909+00:00 | main | INFO  | ProtocolScheduleBuilder | Protocol schedule created with milestones: [ParisFork: 0]
2022-06-17 18:30:56.069+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:56.068+00:00 | main | INFO  | BesuControllerBuilder | TTD difficulty is present, creating initial sync phase with transition to PoS support
2022-06-17 18:30:56.114+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:56.114+00:00 | main | INFO  | RunnerBuilder | Detecting NAT service.
2022-06-17 18:30:56.300+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:56.299+00:00 | main | INFO  | Runner | Starting external services ...
2022-06-17 18:30:56.300+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:56.300+00:00 | main | INFO  | JsonRpcHttpService | Starting JSON-RPC service on 0.0.0.0:8545
2022-06-17 18:30:56.391+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:56.390+00:00 | main | INFO  | JsonRpcService | Starting JSON-RPC service on 0.0.0.0:8550
2022-06-17 18:30:56.391+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:56.390+00:00 | vert.x-eventloop-thread-1 | INFO  | JsonRpcHttpService | JSON-RPC service started and listening on 0.0.0.0:8545
2022-06-17 18:30:56.396+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:56.395+00:00 | vert.x-eventloop-thread-1 | INFO  | JsonRpcService | JSON-RPC service started and listening on 0.0.0.0:8550
2022-06-17 18:30:56.400+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:56.399+00:00 | main | INFO  | AutoTransactionLogBloomCachingService | Starting auto transaction log bloom caching service.
2022-06-17 18:30:56.401+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:56.400+00:00 | main | INFO  | LogBloomCacheMetadata | Lookup cache metadata file in data directory: /opt/besu/caches
2022-06-17 18:30:56.409+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:56.409+00:00 | main | INFO  | Runner | Starting Ethereum main loop ...
2022-06-17 18:30:56.410+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:56.409+00:00 | main | INFO  | NatService | No NAT environment detected so no service could be started
2022-06-17 18:30:56.410+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:56.409+00:00 | main | INFO  | NetworkRunner | Starting Network.
2022-06-17 18:30:56.425+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:56.425+00:00 | nioEventLoopGroup-2-1 | INFO  | RlpxAgent | P2P RLPx agent started and listening on /0.0.0.0:30303.
2022-06-17 18:30:56.427+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:56.427+00:00 | main | INFO  | DefaultP2PNetwork | Enode URL enode://0823d1a9a0784ba8d0adaa802c64ce2c82b057f8804781a55f3854c1f69b2b41d669fad5357719a45119bf9b999b50aa4b4054f4e23a885fef35e73987db22ba@127.0.0.1:30303?discport=0
2022-06-17 18:30:56.428+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:56.427+00:00 | main | INFO  | DefaultP2PNetwork | Node address 0xa55d2a563d44e5f8f6db2f1d3f3eac25f78d5375
2022-06-17 18:30:56.430+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:56.429+00:00 | main | INFO  | DefaultSynchronizer | Starting synchronizer.
2022-06-17 18:30:56.432+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:56.432+00:00 | main | INFO  | FullSyncDownloader | Starting full sync.
2022-06-17 18:30:56.433+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:56.433+00:00 | main | INFO  | FullSyncTargetManager | No sync target, waiting for peers. Current peers: 0
2022-06-17 18:30:56.439+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:30:56.439+00:00 | main | INFO  | Runner | Ethereum main loop is up.
2022-06-17 18:31:01.052+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:01.052+00:00 | vert.x-worker-thread-0 | INFO  | BackwardSyncContext | Starting new backward sync towards a pivot 0xd800900a714cf1062517e0e6022efbf4912162c9956be7cf0022b5b681991ae7
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:01.061+00:00 | EthScheduler-Workers-0 | WARN  | BackwardSyncContext | There was an uncaught exception during Backwards Sync... Retrying in few seconds...
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | java.util.concurrent.CompletionException: org.hyperledger.besu.ethereum.eth.manager.exceptions.NoAvailablePeersException: Task failed: NO_AVAILABLE_PEERS
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:331)
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:346)
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | at java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:632)
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088)
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | at org.hyperledger.besu.util.FutureUtils.propagateResult(FutureUtils.java:99)
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | at org.hyperledger.besu.ethereum.eth.manager.EthScheduler.lambda$scheduleSyncWorkerTask$0(EthScheduler.java:108)
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | at java.base/java.lang.Thread.run(Thread.java:829)
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | Caused by: org.hyperledger.besu.ethereum.eth.manager.exceptions.NoAvailablePeersException: Task failed: NO_AVAILABLE_PEERS
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | at java.base/java.util.Optional.orElseThrow(Optional.java:408)
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | at org.hyperledger.besu.ethereum.eth.manager.task.RetryingGetBlockFromPeersTask.selectNextPeer(RetryingGetBlockFromPeersTask.java:124)
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | at org.hyperledger.besu.ethereum.eth.manager.task.RetryingGetBlockFromPeersTask.lambda$executePeerTask$1(RetryingGetBlockFromPeersTask.java:99)
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | at java.base/java.util.Optional.orElseGet(Optional.java:369)
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | at org.hyperledger.besu.ethereum.eth.manager.task.RetryingGetBlockFromPeersTask.executePeerTask(RetryingGetBlockFromPeersTask.java:97)
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | at org.hyperledger.besu.ethereum.eth.manager.task.AbstractRetryingPeerTask.executeTask(AbstractRetryingPeerTask.java:90)
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | at org.hyperledger.besu.ethereum.eth.manager.task.AbstractEthTask.executeTaskTimed(AbstractEthTask.java:150)
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | at org.hyperledger.besu.ethereum.eth.manager.task.AbstractEthTask.run(AbstractEthTask.java:75)
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | at org.hyperledger.besu.util.FutureUtils.propagateResult(FutureUtils.java:97)
2022-06-17 18:31:01.063+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | ... 6 more
2022-06-17 18:31:01.444+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:01.443+00:00 | EthScheduler-Timer-0 | INFO  | FullSyncTargetManager | No sync target, waiting for peers. Current peers: 0
2022-06-17 18:31:03.522+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:03.522+00:00 | nioEventLoopGroup-3-1 | INFO  | FullSyncTargetManager | No sync target, waiting for peers. Current peers: 1
2022-06-17 18:31:06.068+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:06.067+00:00 | ForkJoinPool.commonPool-worker-3 | INFO  | BackwardsSyncAlgorithm | Waiting for preconditions...
2022-06-17 18:31:08.525+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.524+00:00 | EthScheduler-Timer-0 | INFO  | SyncTargetManager | Found common ancestor with peer Peer 0x0571b00b9d50096c0b... PeerReputation 100, validated? true, disconnected? false at block 0
2022-06-17 18:31:08.787+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.786+00:00 | EthScheduler-Services-5 (importBlock) | INFO  | PandaPrinter |

[.. Panda skipped ..]

2022-06-17 18:31:08.792+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.787+00:00 | ForkJoinPool.commonPool-worker-3 | INFO  | BackwardsSyncAlgorithm | Preconditions meet...
2022-06-17 18:31:08.792+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.789+00:00 | EthScheduler-Services-5 (importBlock) | INFO  | PipelineChainDownloader | PipelineChain download complete
2022-06-17 18:31:08.792+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.790+00:00 | EthScheduler-Services-5 (importBlock) | WARN  | BlockPropagationManager | Attempted to stop when we are not even running...
2022-06-17 18:31:08.792+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.790+00:00 | EthScheduler-Services-5 (importBlock) | INFO  | DefaultSynchronizer | Stopping block propagation.
2022-06-17 18:31:08.792+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.791+00:00 | EthScheduler-Services-5 (importBlock) | WARN  | BlockPropagationManager | Attempted to stop when we are not even running...
2022-06-17 18:31:08.792+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.791+00:00 | EthScheduler-Services-5 (importBlock) | INFO  | DefaultSynchronizer | Stopping the pruner.
2022-06-17 18:31:08.818+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.817+00:00 | nioEventLoopGroup-3-1 | INFO  | BackwardSyncStep | Saved headers 101 -> 0 (head: 100)
2022-06-17 18:31:08.829+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.829+00:00 | ForkJoinPool.commonPool-worker-3 | INFO  | BackwardsSyncAlgorithm | Backward sync reached final header, starting Forward sync
2022-06-17 18:31:08.837+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.836+00:00 | nioEventLoopGroup-3-1 | WARN  | MainnetBlockBodyValidator | Invalid block: state root mismatch (expected=0xa3602d68ddcd93f34c6998c86612aca302e914b6ea03951f4d0e09a8bb266b8b, actual=0x6c35b61329c076879a468373160c9dacdbb542c7158899f19eed9de4bbf8e99a)
2022-06-17 18:31:08.837+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.836+00:00 | nioEventLoopGroup-3-1 | WARN  | MainnetBlockBodyValidator | Invalid block RLP : 0xf901fef901f9a0245becf4bd277b78011439dfb5e5a6e1c3438088624c9faac0653279dda64338a01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d4934794fe3b557e8fb62b89f4916b721be55ceb828dbd73a0a3602d68ddcd93f34c6998c86612aca302e914b6ea03951f4d0e09a8bb266b8ba056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421b90100000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000008065871f
2022-06-17 18:31:08.837+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | fffffffffbff808462ac901980a07cc7cf82ca716fe00fba24e709dec8a747398092b24f5b92989fffc8ebf4f57588000000000000000001c0c0
2022-06-17 18:31:08.840+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.839+00:00 | nioEventLoopGroup-3-1 | ERROR | MainnetBlockValidator | Block body not valid. Block 101 (0xd800900a714cf1062517e0e6022efbf4912162c9956be7cf0022b5b681991ae7)
2022-06-17 18:31:08.840+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.840+00:00 | nioEventLoopGroup-3-1 | INFO  | BackwardsSyncAlgorithm | Backward sync reached final header, starting Forward sync
2022-06-17 18:31:08.844+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.844+00:00 | nioEventLoopGroup-3-1 | WARN  | MainnetBlockBodyValidator | Invalid block: state root mismatch (expected=0xa3602d68ddcd93f34c6998c86612aca302e914b6ea03951f4d0e09a8bb266b8b, actual=0x6c35b61329c076879a468373160c9dacdbb542c7158899f19eed9de4bbf8e99a)
2022-06-17 18:31:08.844+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.844+00:00 | nioEventLoopGroup-3-1 | WARN  | MainnetBlockBodyValidator | Invalid block RLP : 0xf901fef901f9a0245becf4bd277b78011439dfb5e5a6e1c3438088624c9faac0653279dda64338a01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d4934794fe3b557e8fb62b89f4916b721be55ceb828dbd73a0a3602d68ddcd93f34c6998c86612aca302e914b6ea03951f4d0e09a8bb266b8ba056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421b90100000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000008065871f
2022-06-17 18:31:08.844+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | fffffffffbff808462ac901980a07cc7cf82ca716fe00fba24e709dec8a747398092b24f5b92989fffc8ebf4f57588000000000000000001c0c0
2022-06-17 18:31:08.844+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.844+00:00 | nioEventLoopGroup-3-1 | ERROR | MainnetBlockValidator | Block body not valid. Block 101 (0xd800900a714cf1062517e0e6022efbf4912162c9956be7cf0022b5b681991ae7)
2022-06-17 18:31:08.845+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.844+00:00 | nioEventLoopGroup-3-1 | INFO  | BackwardsSyncAlgorithm | Backward sync reached final header, starting Forward sync
2022-06-17 18:31:08.848+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.848+00:00 | nioEventLoopGroup-3-1 | WARN  | MainnetBlockBodyValidator | Invalid block: state root mismatch (expected=0xa3602d68ddcd93f34c6998c86612aca302e914b6ea03951f4d0e09a8bb266b8b, actual=0x6c35b61329c076879a468373160c9dacdbb542c7158899f19eed9de4bbf8e99a)
2022-06-17 18:31:08.848+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.848+00:00 | nioEventLoopGroup-3-1 | WARN  | MainnetBlockBodyValidator | Invalid block RLP : 0xf901fef901f9a0245becf4bd277b78011439dfb5e5a6e1c3438088624c9faac0653279dda64338a01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d4934794fe3b557e8fb62b89f4916b721be55ceb828dbd73a0a3602d68ddcd93f34c6998c86612aca302e914b6ea03951f4d0e09a8bb266b8ba056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421b90100000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000008065871f
2022-06-17 18:31:08.848+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | fffffffffbff808462ac901980a07cc7cf82ca716fe00fba24e709dec8a747398092b24f5b92989fffc8ebf4f57588000000000000000001c0c0
2022-06-17 18:31:08.849+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.848+00:00 | nioEventLoopGroup-3-1 | ERROR | MainnetBlockValidator | Block body not valid. Block 101 (0xd800900a714cf1062517e0e6022efbf4912162c9956be7cf0022b5b681991ae7)
2022-06-17 18:31:08.849+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.849+00:00 | nioEventLoopGroup-3-1 | INFO  | BackwardsSyncAlgorithm | Backward sync reached final header, starting Forward sync
2022-06-17 18:31:08.852+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.852+00:00 | nioEventLoopGroup-3-1 | WARN  | MainnetBlockBodyValidator | Invalid block: state root mismatch (expected=0xa3602d68ddcd93f34c6998c86612aca302e914b6ea03951f4d0e09a8bb266b8b, actual=0x6c35b61329c076879a468373160c9dacdbb542c7158899f19eed9de4bbf8e99a)
2022-06-17 18:31:08.852+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.852+00:00 | nioEventLoopGroup-3-1 | WARN  | MainnetBlockBodyValidator | Invalid block RLP : 0xf901fef901f9a0245becf4bd277b78011439dfb5e5a6e1c3438088624c9faac0653279dda64338a01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d4934794fe3b557e8fb62b89f4916b721be55ceb828dbd73a0a3602d68ddcd93f34c6998c86612aca302e914b6ea03951f4d0e09a8bb266b8ba056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421b90100000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000008065871f
2022-06-17 18:31:08.852+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | fffffffffbff808462ac901980a07cc7cf82ca716fe00fba24e709dec8a747398092b24f5b92989fffc8ebf4f57588000000000000000001c0c0
2022-06-17 18:31:08.852+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.852+00:00 | nioEventLoopGroup-3-1 | ERROR | MainnetBlockValidator | Block body not valid. Block 101 (0xd800900a714cf1062517e0e6022efbf4912162c9956be7cf0022b5b681991ae7)
2022-06-17 18:31:08.853+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.852+00:00 | nioEventLoopGroup-3-1 | INFO  | BackwardsSyncAlgorithm | Backward sync reached final header, starting Forward sync
2022-06-17 18:31:08.856+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.856+00:00 | nioEventLoopGroup-3-1 | WARN  | MainnetBlockBodyValidator | Invalid block: state root mismatch (expected=0xa3602d68ddcd93f34c6998c86612aca302e914b6ea03951f4d0e09a8bb266b8b, actual=0x6c35b61329c076879a468373160c9dacdbb542c7158899f19eed9de4bbf8e99a)
2022-06-17 18:31:08.857+04:00 | docker-java-stream-1295795497 | DEBUG | BesuNode | 2022-06-17 14:31:08.856+00:00 | nioEventLoopGroup-3-1 | WARN  | MainnetBlockBodyValidator | Invalid block RLP : 0xf901fef901f9a0245becf4bd277b78011439dfb5e5a6e1c3438088624c9faac0653279dda64338a01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d4934794fe3b557e8fb62b89f4916b721be55ceb828dbd73a0a3602d68ddcd93f34c6998c86612aca302e914b6ea03951f4d0e09a8bb266b8ba056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421b90100000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000008065871f

[.. 5 lines above are repeated forever ..]

Besu1 after the merge (just to clarify correct block hashes):

[.. skipped Panda ..]

2022-06-17 18:30:29.482+04:00 | docker-java-stream-398692030 | DEBUG | BesuNode | 2022-06-17 14:30:29.477+00:00 | pool-7-thread-2 | INFO  | BlockMiner | Produced #100 / 0 tx / 0 om / 0 (0.0%) gas / (0x245becf4bd277b78011439dfb5e5a6e1c3438088624c9faac0653279dda64338) in 0.476s
2022-06-17 18:30:45.391+04:00 | docker-java-stream-398692030 | DEBUG | BesuNode | 2022-06-17 14:30:45.391+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | Consensus fork-choice-update: head: 0x245becf4bd277b78011439dfb5e5a6e1c3438088624c9faac0653279dda64338, finalized: 0x0000000000000000000000000000000000000000000000000000000000000000, safeBlockHash: 0x0000000000000000000000000000000000000000000000000000000000000000
2022-06-17 18:30:45.401+04:00 | docker-java-stream-398692030 | DEBUG | BesuNode | 2022-06-17 14:30:45.401+00:00 | vert.x-worker-thread-0 | WARN  | BlockPropagationManager | Attempted to stop when we are not even running...
2022-06-17 18:30:49.011+04:00 | docker-java-stream-398692030 | DEBUG | BesuNode | 2022-06-17 14:30:49.010+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | Consensus fork-choice-update: head: 0x245becf4bd277b78011439dfb5e5a6e1c3438088624c9faac0653279dda64338, finalized: 0x0000000000000000000000000000000000000000000000000000000000000000, safeBlockHash: 0x0000000000000000000000000000000000000000000000000000000000000000
2022-06-17 18:30:49.017+04:00 | docker-java-stream-398692030 | DEBUG | BesuNode | 2022-06-17 14:30:49.017+00:00 | vert.x-worker-thread-0 | WARN  | BlockPropagationManager | Attempted to stop when we are not even running...
2022-06-17 18:30:49.400+04:00 | docker-java-stream-398692030 | DEBUG | BesuNode | 2022-06-17 14:30:49.400+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | Consensus fork-choice-update: head: 0xd800900a714cf1062517e0e6022efbf4912162c9956be7cf0022b5b681991ae7, finalized: 0x0000000000000000000000000000000000000000000000000000000000000000, safeBlockHash: 0x0000000000000000000000000000000000000000000000000000000000000000
2022-06-17 18:30:49.404+04:00 | docker-java-stream-398692030 | DEBUG | BesuNode | 2022-06-17 14:30:49.403+00:00 | vert.x-worker-thread-0 | WARN  | MergeCoordinator | checking ancestor 100 (0x245becf4bd277b78011439dfb5e5a6e1c3438088624c9faac0653279dda64338) is valid terminal PoW for 101 (0xd800900a714cf1062517e0e6022efbf4912162c9956be7cf0022b5b681991ae7)
2022-06-17 18:30:49.404+04:00 | docker-java-stream-398692030 | DEBUG | BesuNode | true
2022-06-17 18:30:49.406+04:00 | docker-java-stream-398692030 | DEBUG | BesuNode | 2022-06-17 14:30:49.405+00:00 | vert.x-worker-thread-0 | WARN  | BlockPropagationManager | Attempted to stop when we are not even running...
2022-06-17 18:30:54.876+04:00 | docker-java-stream-398692030 | DEBUG | BesuNode | 2022-06-17 14:30:54.875+00:00 | EthScheduler-Timer-0 | INFO  | FullSyncTargetManager | No sync target, waiting for peers. Current peers: 0
2022-06-17 18:30:55.388+04:00 | docker-java-stream-398692030 | DEBUG | BesuNode | 2022-06-17 14:30:55.387+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | Consensus fork-choice-update: head: 0xb27c2ed60d755157b4a6903b26a28a86e22ace72373dbffa84206cdb1844f17f, finalized: 0x0000000000000000000000000000000000000000000000000000000000000000, safeBlockHash: 0x0000000000000000000000000000000000000000000000000000000000000000
2022-06-17 18:30:55.390+04:00 | docker-java-stream-398692030 | DEBUG | BesuNode | 2022-06-17 14:30:55.390+00:00 | vert.x-worker-thread-0 | WARN  | BlockPropagationManager | Attempted to stop when we are not even running...
2022-06-17 18:30:59.877+04:00 | docker-java-stream-398692030 | DEBUG | BesuNode | 2022-06-17 14:30:59.876+00:00 | EthScheduler-Timer-0 | INFO  | FullSyncTargetManager | No sync target, waiting for peers. Current peers: 0
2022-06-17 18:31:01.379+04:00 | docker-java-stream-398692030 | DEBUG | BesuNode | 2022-06-17 14:31:01.378+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | Consensus fork-choice-update: head: 0x59346c55c9216b92a3979242f900111fe416a7999416b6bd34e15144b1bc86a3, finalized: 0x0000000000000000000000000000000000000000000000000000000000000000, safeBlockHash: 0x0000000000000000000000000000000000000000000000000000000000000000
2022-06-17 18:31:01.381+04:00 | docker-java-stream-398692030 | DEBUG | BesuNode | 2022-06-17 14:31:01.380+00:00 | vert.x-worker-thread-0 | WARN  | BlockPropagationManager | Attempted to stop when we are not even running...
2022-06-17 18:31:03.507+04:00 | docker-java-stream-398692030 | DEBUG | BesuNode | 2022-06-17 14:31:03.506+00:00 | nioEventLoopGroup-3-2 | INFO  | FullSyncTargetManager | No sync target, waiting for peers. Current peers: 1
2022-06-17 18:31:07.409+04:00 | docker-java-stream-398692030 | DEBUG | BesuNode | 2022-06-17 14:31:07.408+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | Consensus fork-choice-update: head: 0xe6b042eb4649257442a8c31721ac4a5553528e1a23dcbd1c1a42454b1e72afb7, finalized: 0x0000000000000000000000000000000000000000000000000000000000000000, safeBlockHash: 0x0000000000000000000000000000000000000000000000000000000000000000
2022-06-17 18:31:07.414+04:00 | docker-java-stream-398692030 | DEBUG | BesuNode | 2022-06-17 14:31:07.414+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | Consensus fork-choice-update: head: 0xe6b042eb4649257442a8c31721ac4a5553528e1a23dcbd1c1a42454b1e72afb7, finalized: 0x0000000000000000000000000000000000000000000000000000000000000000, safeBlockHash: 0x0000000000000000000000000000000000000000000000000000000000000000
2022-06-17 18:31:07.417+04:00 | docker-java-stream-398692030 | DEBUG | BesuNode | 2022-06-17 14:31:07.416+00:00 | vert.x-worker-thread-0 | WARN  | BlockPropagationManager | Attempted to stop when we are not even running...
2022-06-17 18:31:08.508+04:00 | docker-java-stream-398692030 | DEBUG | BesuNode | 2022-06-17 14:31:08.507+00:00 | EthScheduler-Timer-0 | INFO  | FullSyncTargetManager | No sync target, waiting for peers. Current peers: 1

Expected behavior: [What you expect to happen]
Besu syncs successfully

Actual behavior: [What actually happens]
Besu fails to sync and repeats to fail on the same block

Frequency: [What percentage of the time does it occur?]
Always, 100% in this kind of test

Versions (Add all that apply)

Besu 22.4.3
@zilm13 zilm13 mentioned this issue Jun 17, 2022
Closed
2 tasks
@non-fungible-nelson non-fungible-nelson added bug Something isn't working mainnet labels Jun 21, 2022
@iamhsk iamhsk added the TeamRevenant GH issues worked on by Revenant Team label Jun 22, 2022
@zilm13 zilm13 mentioned this issue Jul 11, 2022
Closed
@non-fungible-nelson
Copy link
Contributor

This issue should be fixed by #4116 ! If you are still experiencing this on the latest releases, please let us know.

@zilm13
Copy link
Author

zilm13 commented Aug 4, 2022

It works, cool, thank you!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working mainnet TeamRevenant GH issues worked on by Revenant Team
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@gezero @iamhsk @zilm13 @non-fungible-nelson and others