besu: Besu bonsai trie mainnet sync fails

Description

Fresh bonsai trie mainnet sync fails with “World state root does not match expected value”

execution_1  | 2021-10-12 10:43:11.730+02:00 | nioEventLoopGroup-3-4 | INFO  | SyncTargetManager | Found common ancestor with peer Peer 0x7bb206354dd02618aa... at block 13387913
execution_1  | 2021-10-12 10:43:21.968+02:00 | EthScheduler-Services-101 (importBlock) | ERROR | PipelineChainDownloader | Chain download failed. Restarting after short delay.
execution_1  | java.util.concurrent.CompletionException: java.lang.RuntimeException: World State Root does not match expected value, header 0x47f8ae0d9dc85b86fa2ecb4111d49a5ef9b575d79b69b75267706e8ba3af24e2 calculated 0xfb65b3878aac74cef5d561338cf2562840b54c619a1a0c5f3f7904a583377ea5
execution_1  |  at java.base/java.util.concurrent.CompletableFuture.encodeRelay(Unknown Source)
execution_1  |  at java.base/java.util.concurrent.CompletableFuture.completeRelay(Unknown Source)
execution_1  |  at java.base/java.util.concurrent.CompletableFuture$UniRelay.tryFire(Unknown Source)
execution_1  |  at java.base/java.util.concurrent.CompletableFuture.postComplete(Unknown Source)
execution_1  |  at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(Unknown Source)
execution_1  |  at org.hyperledger.besu.services.pipeline.Pipeline.abort(Pipeline.java:180)
execution_1  |  at org.hyperledger.besu.services.pipeline.Pipeline.lambda$runWithErrorHandling$3(Pipeline.java:159)
execution_1  |  at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
execution_1  |  at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
execution_1  |  at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
execution_1  |  at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
execution_1  |  at java.base/java.lang.Thread.run(Unknown Source)
execution_1  | Caused by: java.lang.RuntimeException: World State Root does not match expected value, header 0x47f8ae0d9dc85b86fa2ecb4111d49a5ef9b575d79b69b75267706e8ba3af24e2 calculated 0xfb65b3878aac74cef5d561338cf2562840b54c619a1a0c5f3f7904a583377ea5
execution_1  |  at org.hyperledger.besu.ethereum.bonsai.BonsaiPersistedWorldState.persist(BonsaiPersistedWorldState.java:264)
execution_1  |  at org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:202)
execution_1  |  at org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:42)
execution_1  |  at org.hyperledger.besu.ethereum.mainnet.BlockProcessor.processBlock(BlockProcessor.java:75)
execution_1  |  at org.hyperledger.besu.ethereum.MainnetBlockValidator.processBlock(MainnetBlockValidator.java:150)
execution_1  |  at org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:108)
execution_1  |  at org.hyperledger.besu.ethereum.mainnet.MainnetBlockImporter.importBlock(MainnetBlockImporter.java:45)
execution_1  |  at org.hyperledger.besu.ethereum.core.BlockImporter.importBlock(BlockImporter.java:44)
execution_1  |  at org.hyperledger.besu.ethereum.eth.sync.fullsync.FullImportBlockStep.accept(FullImportBlockStep.java:54)
execution_1  |  at org.hyperledger.besu.ethereum.eth.sync.fullsync.FullImportBlockStep.accept(FullImportBlockStep.java:31)
execution_1  |  at org.hyperledger.besu.services.pipeline.CompleterStage.run(CompleterStage.java:37)
execution_1  |  at org.hyperledger.besu.services.pipeline.Pipeline.lambda$runWithErrorHandling$3(Pipeline.java:152)

Versions (Add all that apply)

  • Software version: besu/v21.10.0-RC1/linux-x86_64/adoptopenjdk-java-11
  • OS Name & Version: Ubuntu 20.04
  • Docker Version: 20.10.7

About this issue

  • Original URL
  • State: closed
  • Created 3 years ago
  • Comments: 16 (6 by maintainers)

Most upvoted comments

We are testing a potential fix : https://github.com/hyperledger/besu/pull/2934

ok I think the problem comes from the fastsync and in particular the fact that there are several retry of the fastsync. I think in the database there must be the old fasstync data which are not completely flushed. I’ll try to reproduce it locally to investigate.

Side note: In that test build, --rpc-ws-apis WEB3,ETH,NET works but --rpc-ws-apis web3,eth,net fails with Invalid value for option '--rpc-ws-apis'

I started a fresh sync with that test build.

I’m having the same problem with besu/v21.10.0-RC2/linux-x86_64/adoptopenjdk-java-11.

2021-10-14 14:54:30.042+00:00 | nioEventLoopGroup-3-2 | INFO  | PivotBlockConfirmer | Confirmed pivot block at 13416909: 0xc1b11e9a611ea827c5a40df96fcb1941ce00e5a68319f42ec8d484fdf2f67906

...

2021-10-15 09:09:03.297+00:00 | nioEventLoopGroup-3-9 | INFO  | FastSyncDownloader | Re-pivoting to newer block.

...

2021-10-15 09:09:04.893+00:00 | nioEventLoopGroup-3-9 | INFO  | PivotBlockConfirmer | Confirmed pivot block at 13421708: 0x18859a99aafebccfbb31e7220442d53833bd9c7bdba5696c05a42cac32dea9df
2021-10-15 09:09:04.897+00:00 | nioEventLoopGroup-3-9 | INFO  | WorldStateDownloader | Begin downloading world state from peers for block 13421708 (0x18859a99aafebccfbb31e7220442d53833bd9c7bdba5696c05a42cac32dea9df). State root 0x01a4e5961f712cc29be8bb9c5957d876345daa0e91b79254e54bf45c510488d3

...

2021-10-15 22:27:59.953+00:00 | EthScheduler-Services-10 (requestCompleteTask) | INFO  | CompleteTaskStep | Downloaded 1086700000 world state nodes. At least 17726 nodes remaining.
2021-10-15 22:28:07.284+00:00 | EthScheduler-Services-10 (requestCompleteTask) | INFO  | DefaultSynchronizer | Fast sync completed successfully with pivot block 13421708
2021-10-15 22:28:07.286+00:00 | EthScheduler-Services-10 (requestCompleteTask) | INFO  | FullSyncDownloader | Starting full sync.
2021-10-15 22:28:07.286+00:00 | EthScheduler-Services-10 (requestCompleteTask) | INFO  | WorldDownloadState | Finished downloading world state from peers
2021-10-15 22:28:07.306+00:00 | nioEventLoopGroup-3-3 | INFO  | SyncTargetManager | Found common ancestor with peer Peer 0xf359075eddb93bd90c... at block 13421708
2021-10-15 22:28:13.280+00:00 | EthScheduler-Services-18 (importBlock) | ERROR | PipelineChainDownloader | Chain download failed. Restarting after short delay.
java.util.concurrent.CompletionException: java.lang.RuntimeException: World State Root does not match expected value, header 0x29fbc32a5cb6c688510b26e53294de0b8ea6900813104a04f3a109dea96f06a1 calculated 0x7caae49b6d2e5fb47b206b49c138d136cd2607bfa58a3df076ba67d21f6f1481
        at java.base/java.util.concurrent.CompletableFuture.encodeRelay(Unknown Source)
        at java.base/java.util.concurrent.CompletableFuture.completeRelay(Unknown Source)
        at java.base/java.util.concurrent.CompletableFuture$UniRelay.tryFire(Unknown Source)
        at java.base/java.util.concurrent.CompletableFuture.postComplete(Unknown Source)
        at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(Unknown Source)
        at org.hyperledger.besu.services.pipeline.Pipeline.abort(Pipeline.java:180)
        at org.hyperledger.besu.services.pipeline.Pipeline.lambda$runWithErrorHandling$3(Pipeline.java:159)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
        at java.base/java.util.concurrent.FutureTask.run(Unknown Source)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
        at java.base/java.lang.Thread.run(Unknown Source)
Caused by: java.lang.RuntimeException: World State Root does not match expected value, header 0x29fbc32a5cb6c688510b26e53294de0b8ea6900813104a04f3a109dea96f06a1 calculated 0x7caae49b6d2e5fb47b206b49c138d136cd2607bfa58a3df076ba67d21f6f1481
        at org.hyperledger.besu.ethereum.bonsai.BonsaiPersistedWorldState.persist(BonsaiPersistedWorldState.java:264)
        at org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:202)
        at org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:42)
        at org.hyperledger.besu.ethereum.mainnet.BlockProcessor.processBlock(BlockProcessor.java:75)
        at org.hyperledger.besu.ethereum.MainnetBlockValidator.processBlock(MainnetBlockValidator.java:150)
        at org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:108)
        at org.hyperledger.besu.ethereum.mainnet.MainnetBlockImporter.importBlock(MainnetBlockImporter.java:45)
        at org.hyperledger.besu.ethereum.core.BlockImporter.importBlock(BlockImporter.java:44)
        at org.hyperledger.besu.ethereum.eth.sync.fullsync.FullImportBlockStep.accept(FullImportBlockStep.java:54)
        at org.hyperledger.besu.ethereum.eth.sync.fullsync.FullImportBlockStep.accept(FullImportBlockStep.java:31)
        at org.hyperledger.besu.services.pipeline.CompleterStage.run(CompleterStage.java:37)
        at org.hyperledger.besu.services.pipeline.Pipeline.lambda$runWithErrorHandling$3(Pipeline.java:152)
        ... 5 more

besu.log.txt