besu icon indicating copy to clipboard operation
besu copied to clipboard

Published 20 hours ago • verified publisher icon hyperledger

Post merge exception: "AbstractBlockProcessor | failed persisting block"

Open ibhagwan opened this issue 2 years ago • 10 comments

Description

Besu version:

❯ besu --version
besu/v22.7.2/linux-x86_64/openjdk-java-17
2022-09-15 03:47:37.199-04:00 | main | INFO  | Besu | Using jemalloc

Using latest nimbus beacon node, raises the following exception:

2022-09-15 03:45:01.802-04:00 | vert.x-worker-thread-0 | ERROR | AbstractBlockProcessor | failed persisting block
org.hyperledger.besu.ethereum.trie.MerkleTrieException: Unable to load trie node value for hash 0x0d1196dd0827615376ffdc567f9246612f48b9d98679fa976b4b974256d6e64b location 0x
        at org.hyperledger.besu.ethereum.trie.StoredNode.lambda$load$0(StoredNode.java:133)
        at java.base/java.util.Optional.orElseThrow(Optional.java:403)
        at org.hyperledger.besu.ethereum.trie.StoredNode.load(StoredNode.java:131)
        at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:63)
        at org.hyperledger.besu.ethereum.trie.StoredMerklePatriciaTrie.put(StoredMerklePatriciaTrie.java:142)
        at org.hyperledger.besu.ethereum.bonsai.BonsaiPersistedWorldState.calculateRootHash(BonsaiPersistedWorldState.java:172)
        at org.hyperledger.besu.ethereum.bonsai.BonsaiInMemoryWorldState.rootHash(BonsaiInMemoryWorldState.java:43)
        at org.hyperledger.besu.ethereum.bonsai.BonsaiInMemoryWorldState.persist(BonsaiInMemoryWorldState.java:53)
        at org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:220)
        at org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:43)
        at org.hyperledger.besu.ethereum.mainnet.BlockProcessor.processBlock(BlockProcessor.java:80)
        at org.hyperledger.besu.ethereum.MainnetBlockValidator.processBlock(MainnetBlockValidator.java:175)
        at org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:112)
        at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.validateBlock(MergeCoordinator.java:268)
        at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.rememberBlock(MergeCoordinator.java:284)
        at org.hyperledger.besu.consensus.merge.blockcreation.TransitionCoordinator.rememberBlock(TransitionCoordinator.java:137)
        at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.engine.EngineNewPayload.syncResponse(EngineNewPayload.java:212)
        at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.lambda$response$0(ExecutionEngineJsonRpcMethod.java:67)
        at io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)
        at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
        at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)
        at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:833)
2022-09-15 03:45:01.804-04:00 | vert.x-worker-thread-0 | ERROR | MainnetBlockValidator | Error processing block. Block 15537692 (0xf4eff6cbe33d6159ea7709812d83d01195304ebf9bbfcd40d544128f0624c33a), caused by Optional[org.hyperledger.besu.ethereum.trie.MerkleTrieException: Unable to load trie node value for hash 0x0d1196dd0827615376ffdc567f9246612f48b9d98679fa976b4b974256d6e64b location 0x]
2022-09-15 03:45:01.807-04:00 | vert.x-worker-thread-0 | WARN  | EngineNewPayload | Invalid new payload: number: 15537692, hash: 0xf4eff6cbe33d6159ea7709812d83d01195304ebf9bbfcd40d544128f0624c33a, parentHash: 0xd6d9072f418415c87585db97f7f5c1bfd91d9bb69ac5e99d077e66d7819a8227, latestValidHash: 0xd6d9072f418415c87585db97f7f5c1bfd91d9bb69ac5e99d077e66d7819a8227, status: INVALID, validationError: Error processing block
2022-09-15 03:45:01.816-04:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head

ibhagwan avatar Sep 15 '22 07:09 ibhagwan

I also got this error immediately after the merge; restarting besu allowed me to sync the missed blocks and catch up with the merged head. Here are the logs of both my beacon (lighthouse) and EL (besu) nodes around the merge (03:42:52 GMT-3); notice the container restart at 03:50:26. beacon.log besu.log

andrevmatos avatar Sep 15 '22 11:09 andrevmatos

I implemented a PR that could fix the issue . Just not sure yet if it will fix everything we are still investgating

https://github.com/hyperledger/besu/pull/4397

https://output.circle-artifacts.com/output/job/dfd43b58-7ef6-4eaa-af40-e3f577efc55c/artifacts/0/distributions/besu-22.7.3-SNAPSHOT.tar.gz

But yes restarting the node can help you fixing the issue

matkt avatar Sep 15 '22 13:09 matkt

Same thing but in "EthScheduler-Transactions-4"


Sep 15 13:47:49 eth-execution besu[138643]: 2022-09-15 13:47:49.654+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,539,488 / 163 tx / base fee 11.95 gwe>
Sep 15 13:47:44 eth-execution besu[138643]:         at java.base/java.lang.Thread.run(Thread.java:833)
Sep 15 13:47:44 eth-execution besu[138643]:         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
Sep 15 13:47:44 eth-execution besu[138643]:         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
Sep 15 13:47:44 eth-execution besu[138643]:         at org.hyperledger.besu.ethereum.eth.transactions.TransactionsMessageHandler.lambda$exec$0(TransactionsMessageHandler.java:48)
Sep 15 13:47:44 eth-execution besu[138643]:         at org.hyperledger.besu.ethereum.eth.transactions.TransactionsMessageProcessor.processTransactionsMessage(TransactionsMessageP>
Sep 15 13:47:44 eth-execution besu[138643]:         at org.hyperledger.besu.ethereum.eth.transactions.TransactionsMessageProcessor.processTransactionsMessage(TransactionsMessageP>
Sep 15 13:47:44 eth-execution besu[138643]:         at org.hyperledger.besu.ethereum.eth.transactions.TransactionPool.addRemoteTransactions(TransactionPool.java:153)
Sep 15 13:47:44 eth-execution besu[138643]:         at org.hyperledger.besu.ethereum.eth.transactions.TransactionPool.validateRemoteTransaction(TransactionPool.java:213)
Sep 15 13:47:44 eth-execution besu[138643]:         at org.hyperledger.besu.ethereum.eth.transactions.TransactionPool.validateTransaction(TransactionPool.java:280)
Sep 15 13:47:44 eth-execution besu[138643]:         at java.base/java.util.Optional.map(Optional.java:260)
Sep 15 13:47:44 eth-execution besu[138643]:         at org.hyperledger.besu.ethereum.eth.transactions.TransactionPool.lambda$validateTransaction$2(TransactionPool.java:282)
Sep 15 13:47:44 eth-execution besu[138643]:         at org.hyperledger.besu.ethereum.bonsai.BonsaiLayeredWorldState.get(BonsaiLayeredWorldState.java:232)
Sep 15 13:47:44 eth-execution besu[138643]:         at org.hyperledger.besu.ethereum.bonsai.BonsaiPersistedWorldState.get(BonsaiPersistedWorldState.java:340)
Sep 15 13:47:44 eth-execution besu[138643]:         at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateKeyValueStorage.getAccount(BonsaiWorldStateKeyValueStorage.java:110)
Sep 15 13:47:44 eth-execution besu[138643]:         at org.hyperledger.besu.ethereum.trie.StoredMerklePatriciaTrie.get(StoredMerklePatriciaTrie.java:119)
Sep 15 13:47:44 eth-execution besu[138643]:         at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:64)
Sep 15 13:47:44 eth-execution besu[138643]:         at org.hyperledger.besu.ethereum.trie.BranchNode.accept(BranchNode.java:80)
Sep 15 13:47:44 eth-execution besu[138643]:         at org.hyperledger.besu.ethereum.trie.GetVisitor.visit(GetVisitor.java:46)
Sep 15 13:47:44 eth-execution besu[138643]:         at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:64)
Sep 15 13:47:44 eth-execution besu[138643]:         at org.hyperledger.besu.ethereum.trie.BranchNode.accept(BranchNode.java:80)
Sep 15 13:47:44 eth-execution besu[138643]:         at org.hyperledger.besu.ethereum.trie.GetVisitor.visit(GetVisitor.java:46)
Sep 15 13:47:44 eth-execution besu[138643]:         at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:64)
Sep 15 13:47:44 eth-execution besu[138643]:         at org.hyperledger.besu.ethereum.trie.BranchNode.accept(BranchNode.java:80)
Sep 15 13:47:44 eth-execution besu[138643]:         at org.hyperledger.besu.ethereum.trie.GetVisitor.visit(GetVisitor.java:46)
Sep 15 13:47:44 eth-execution besu[138643]:         at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:63)
Sep 15 13:47:44 eth-execution besu[138643]:         at org.hyperledger.besu.ethereum.trie.StoredNode.load(StoredNode.java:131)
Sep 15 13:47:44 eth-execution besu[138643]:         at java.base/java.util.Optional.orElseThrow(Optional.java:403)
Sep 15 13:47:44 eth-execution besu[138643]:         at org.hyperledger.besu.ethereum.trie.StoredNode.lambda$load$0(StoredNode.java:133)
Sep 15 13:47:44 eth-execution besu[138643]: org.hyperledger.besu.ethereum.trie.MerkleTrieException: Unable to load trie node value for hash 0xfed5095b11a61ff06d2489bb5fce729f0a82>
Sep 15 13:47:44 eth-execution besu[138643]: 2022-09-15 13:47:44.047+00:00 | EthScheduler-Transactions-4 | ERROR | Besu | Uncaught exception in thread "EthScheduler-Transactions-4"
Sep 15 13:47:42 eth-execution besu[138643]: 2022-09-15 13:47:42.047+00:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | VALID for fork-choice-update: head: 0x28c25>
Sep 15 13:47:41 eth-execution besu[138643]: 2022-09-15 13:47:41.662+00:00 | vert.x-worker-thread-0 | INFO  | EngineNewPayload | Imported #15,539,487 / 264 tx / base fee 10.69 gwe>

totoCZ avatar Sep 15 '22 14:09 totoCZ

Working on that https://github.com/hyperledger/besu/issues/4372

matkt avatar Sep 16 '22 18:09 matkt

FYI this still happens with the newest releases of both besu (22.7.3) & nimbus (22.9.1):

2022-09-23 14:23:08.095-04:00 | ForkJoinPool.commonPool-worker-1 | INFO  | BackwardsSyncAlgorithm | The Backward sync is done...
2022-09-23 14:23:10.337-04:00 | vert.x-worker-thread-0 | ERROR | AbstractBlockProcessor | failed persisting block
org.hyperledger.besu.ethereum.trie.MerkleTrieException: Unable to load trie node value for hash 0xc46befb4259e43a6ae1f13996615563feaea546702615ad68ad87288ddd694c9 location 0x0d0c
        at org.hyperledger.besu.ethereum.trie.StoredNode.lambda$load$0(StoredNode.java:133)
        at java.base/java.util.Optional.orElseThrow(Optional.java:403)
        at org.hyperledger.besu.ethereum.trie.StoredNode.load(StoredNode.java:131)
        at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:63)
        at org.hyperledger.besu.ethereum.trie.PutVisitor.visit(PutVisitor.java:68)
        at org.hyperledger.besu.ethereum.trie.BranchNode.accept(BranchNode.java:80)
        at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:64)
        at org.hyperledger.besu.ethereum.trie.PutVisitor.visit(PutVisitor.java:68)
        at org.hyperledger.besu.ethereum.trie.BranchNode.accept(BranchNode.java:80)
        at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:64)
        at org.hyperledger.besu.ethereum.trie.StoredMerklePatriciaTrie.put(StoredMerklePatriciaTrie.java:142)
        at org.hyperledger.besu.ethereum.bonsai.BonsaiPersistedWorldState.calculateRootHash(BonsaiPersistedWorldState.java:172)
        at org.hyperledger.besu.ethereum.bonsai.BonsaiInMemoryWorldState.rootHash(BonsaiInMemoryWorldState.java:43)
        at org.hyperledger.besu.ethereum.bonsai.BonsaiInMemoryWorldState.persist(BonsaiInMemoryWorldState.java:53)
        at org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:220)
        at org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:43)
        at org.hyperledger.besu.ethereum.mainnet.BlockProcessor.processBlock(BlockProcessor.java:80)
        at org.hyperledger.besu.ethereum.MainnetBlockValidator.processBlock(MainnetBlockValidator.java:175)
        at org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:112)
        at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.validateBlock(MergeCoordinator.java:342)
        at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.rememberBlock(MergeCoordinator.java:358)
        at org.hyperledger.besu.consensus.merge.blockcreation.TransitionCoordinator.rememberBlock(TransitionCoordinator.java:137)
        at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.engine.EngineNewPayload.syncResponse(EngineNewPayload.java:215)
        at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.lambda$response$0(ExecutionEngineJsonRpcMethod.java:73)
        at io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)
        at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
        at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)
        at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:833)
2022-09-23 14:23:10.340-04:00 | vert.x-worker-thread-0 | ERROR | MainnetBlockValidator | Error processing block. Block 15597793 (0x3fefccf68e4fa3820c3e7a7c7b1a27398af3bef2c80c7d3cde000c9da7c11e5b), caused by Optional[org.hyperledger.besu.ethereum.trie.MerkleTrieException: Unable to load trie node value for hash 0xc46befb4259e43a6ae1f13996615563feaea546702615ad68ad87288ddd694c9 location 0x0d0c]
2022-09-23 14:23:10.342-04:00 | vert.x-worker-thread-0 | WARN  | EngineNewPayload | Invalid new payload: number: 15597793, hash: 0x3fefccf68e4fa3820c3e7a7c7b1a27398af3bef2c80c7d3cde000c9da7c11e5b, parentHash: 0xd0d5b6f68a3820f1e38ec1e06116aa97acbf7f97c0a7ea73eb7b6a0051c4d5df, latestValidHash: 0xd0d5b6f68a3820f1e38ec1e06116aa97acbf7f97c0a7ea73eb7b6a0051c4d5df, status: INVALID, validationError: Error processing block
2022-09-23 14:26:25.848-04:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | INVALID for fork-choice-update: head: 0x3fefccf68e4fa3820c3e7a7c7b1a27398af3bef2c80c7d3cde000c9da7c11e5b, finalized: 0x9b362e56e6d1fd2f39cf4d9253ad0026d67a38701e3eaa4816c4f0ccb4455bab, safeBlockHash: 0x91c204e40b98b7da2d1177ff6b6773578c0308b1c02f13faad4d9e9d611911eb

Important to note that after this besu fails to sync and goes into a loop of Backward sync failed followed by INVALID for fork-choice-update and Ignoring update to old head errors, the only remedy seems to be a besu restart:

2022-09-23 14:34:45.444-04:00 | nioEventLoopGroup-3-2 | INFO  | BackwardSyncStep | Saved headers 15597852 -> 15597653 (head: 15597848)
2022-09-23 14:34:45.462-04:00 | ForkJoinPool.commonPool-worker-4 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
2022-09-23 14:35:01.715-04:00 | nioEventLoopGroup-3-5 | INFO  | ForwardSyncStep | Saved blocks 15597849 -> 15597854 (target: 15597854)
2022-09-23 14:35:01.718-04:00 | ForkJoinPool.commonPool-worker-4 | INFO  | BackwardsSyncAlgorithm | The Backward sync is done...
2022-09-23 14:35:03.713-04:00 | nioEventLoopGroup-3-2 | INFO  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.sync.backwardsync.BackwardSyncException: Did not receive a headers for hash 0xe244a5e00c5b7f1036cb5a23913a28c69d4d1498675b12ec838c6be5ad69b7b6). Current Peers: 31. Retrying in 5000 milliseconds...
2022-09-23 14:35:08.930-04:00 | nioEventLoopGroup-3-3 | INFO  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.sync.backwardsync.BackwardSyncException: Did not receive a headers for hash 0xe244a5e00c5b7f1036cb5a23913a28c69d4d1498675b12ec838c6be5ad69b7b6). Current Peers: 31. Retrying in 5000 milliseconds...
2022-09-23 14:35:14.062-04:00 | nioEventLoopGroup-3-3 | INFO  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.sync.backwardsync.BackwardSyncException: Did not receive a headers for hash 0xe244a5e00c5b7f1036cb5a23913a28c69d4d1498675b12ec838c6be5ad69b7b6). Current Peers: 31. Retrying in 5000 milliseconds...
2022-09-23 14:35:19.102-04:00 | nioEventLoopGroup-3-9 | INFO  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.sync.backwardsync.BackwardSyncException: Did not receive a headers for hash 0xe244a5e00c5b7f1036cb5a23913a28c69d4d1498675b12ec838c6be5ad69b7b6). Current Peers: 31. Retrying in 5000 milliseconds...
2022-09-23 14:35:24.211-04:00 | nioEventLoopGroup-3-1 | INFO  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.sync.backwardsync.BackwardSyncException: Did not receive a headers for hash 0xe244a5e00c5b7f1036cb5a23913a28c69d4d1498675b12ec838c6be5ad69b7b6). Current Peers: 31. Retrying in 5000 milliseconds...
2022-09-23 14:35:29.359-04:00 | nioEventLoopGroup-3-7 | INFO  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.sync.backwardsync.BackwardSyncException: Did not receive a headers for hash 0xe244a5e00c5b7f1036cb5a23913a28c69d4d1498675b12ec838c6be5ad69b7b6). Current Peers: 31. Retrying in 5000 milliseconds...
2022-09-23 14:35:34.675-04:00 | nioEventLoopGroup-3-10 | INFO  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.sync.backwardsync.BackwardSyncException: Did not receive a headers for hash 0xe244a5e00c5b7f1036cb5a23913a28c69d4d1498675b12ec838c6be5ad69b7b6). Current Peers: 31. Retrying in 5000 milliseconds...
2022-09-23 14:35:39.837-04:00 | nioEventLoopGroup-3-1 | INFO  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.sync.backwardsync.BackwardSyncException: Did not receive a headers for hash 0xe244a5e00c5b7f1036cb5a23913a28c69d4d1498675b12ec838c6be5ad69b7b6). Current Peers: 31. Retrying in 5000 milliseconds...
2022-09-23 14:35:45.278-04:00 | nioEventLoopGroup-3-1 | INFO  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.sync.backwardsync.BackwardSyncException: Did not receive a headers for hash 0xe244a5e00c5b7f1036cb5a23913a28c69d4d1498675b12ec838c6be5ad69b7b6). Current Peers: 31. Retrying in 5000 milliseconds...
2022-09-23 14:35:50.345-04:00 | nioEventLoopGroup-3-9 | INFO  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.sync.backwardsync.BackwardSyncException: Did not receive a headers for hash 0xe244a5e00c5b7f1036cb5a23913a28c69d4d1498675b12ec838c6be5ad69b7b6). Current Peers: 31. Retrying in 5000 milliseconds...
2022-09-23 14:35:56.422-04:00 | nioEventLoopGroup-3-9 | INFO  | BackwardSyncStep | Saved headers 15597867 -> 15597867 (head: 15597854)
2022-09-23 14:35:57.644-04:00 | nioEventLoopGroup-3-6 | INFO  | BackwardSyncStep | Saved headers 15597866 -> 15597866 (head: 15597854)
2022-09-23 14:35:57.733-04:00 | nioEventLoopGroup-3-5 | INFO  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.sync.backwardsync.BackwardSyncException: Did not receive a headers for hash 0xf5586586f2258cd837c04b8a965e814c65d5eb4958ceacf24cfdec7f23ca37fb). Current Peers: 31. Retrying in 5000 milliseconds...
2022-09-23 14:36:02.807-04:00 | nioEventLoopGroup-3-10 | INFO  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.sync.backwardsync.BackwardSyncException: Did not receive a headers for hash 0xf5586586f2258cd837c04b8a965e814c65d5eb4958ceacf24cfdec7f23ca37fb). Current Peers: 31. Retrying in 5000 milliseconds...
2022-09-23 14:36:08.061-04:00 | nioEventLoopGroup-3-2 | INFO  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.sync.backwardsync.BackwardSyncException: Did not receive a headers for hash 0xf5586586f2258cd837c04b8a965e814c65d5eb4958ceacf24cfdec7f23ca37fb). Current Peers: 31. Retrying in 5000 milliseconds...
2022-09-23 14:36:14.811-04:00 | nioEventLoopGroup-3-6 | INFO  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.sync.backwardsync.BackwardSyncException: Did not receive a headers for hash 0xf5586586f2258cd837c04b8a965e814c65d5eb4958ceacf24cfdec7f23ca37fb). Current Peers: 31. Retrying in 5000 milliseconds...
2022-09-23 14:36:19.838-04:00 | nioEventLoopGroup-3-8 | INFO  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.sync.backwardsync.BackwardSyncException: Did not receive a headers for hash 0xf5586586f2258cd837c04b8a965e814c65d5eb4958ceacf24cfdec7f23ca37fb). Current Peers: 31. Retrying in 5000 milliseconds...
2022-09-23 14:36:25.042-04:00 | nioEventLoopGroup-3-10 | INFO  | BackwardSyncContext | Backward sync failed (org.hyperledger.besu.ethereum.eth.sync.backwardsync.BackwardSyncException: Did not receive a headers for hash 0xf5586586f2258cd837c04b8a965e814c65d5eb4958ceacf24cfdec7f23ca37fb). Current Peers: 31. Retrying in 5000 milliseconds...
2022-09-23 14:36:31.322-04:00 | nioEventLoopGroup-3-2 | INFO  | BackwardSyncStep | Saved headers 15597865 -> 15597666 (head: 15597854)
2022-09-23 14:36:31.342-04:00 | ForkJoinPool.commonPool-worker-4 | INFO  | BackwardsSyncAlgorithm | Backward sync reached ancestor header, starting Forward sync
2022-09-23 14:36:58.715-04:00 | nioEventLoopGroup-3-5 | INFO  | ForwardSyncStep | Saved blocks 15597855 -> 15597868 (target: 15597868)
2022-09-23 14:36:58.717-04:00 | ForkJoinPool.commonPool-worker-4 | INFO  | BackwardsSyncAlgorithm | The Backward sync is done...
2022-09-23 14:37:38.494-04:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head
2022-09-23 14:37:38.495-04:00 | vert.x-worker-thread-0 | INFO  | EngineForkchoiceUpdated | INVALID for fork-choice-update: head: 0x62f386f697e4f057747c04f76b6809c47750697e743ecefb3aff9b2ad83046fc, finalized: 0x5b9f384f38a027534bddd0a8aada596fa8ff66cf740b9cf9586aa383d9d70d4c, safeBlockHash: 0x1cf673abb78f8dca745a07c2ee398f563337f74be516fb691304ac3567570585
2022-09-23 14:37:39.458-04:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head
2022-09-23 14:37:40.376-04:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head
2022-09-23 14:37:41.390-04:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head
2022-09-23 14:37:42.305-04:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head
2022-09-23 14:37:43.220-04:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head
2022-09-23 14:37:45.065-04:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head
2022-09-23 14:37:45.984-04:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head
2022-09-23 14:37:46.894-04:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head
2022-09-23 14:37:47.699-04:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head
2022-09-23 14:37:48.584-04:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head
2022-09-23 14:37:49.450-04:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head
2022-09-23 14:37:50.327-04:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head
2022-09-23 14:37:51.146-04:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head
2022-09-23 14:37:51.922-04:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head
2022-09-23 14:37:52.652-04:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head
2022-09-23 14:37:53.425-04:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head
2022-09-23 14:37:54.197-04:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head
2022-09-23 14:37:55.000-04:00 | vert.x-worker-thread-0 | INFO  | MergeCoordinator | Ignoring update to old head

ibhagwan avatar Sep 23 '22 18:09 ibhagwan

Hi there - are you still experiencing this on Nimbus 22.10? Besu 22.7.5 wouldn't necessarily have addressed this.

non-fungible-nelson avatar Oct 05 '22 23:10 non-fungible-nelson

Hi there - are you still experiencing this on Nimbus 22.10? Besu 22.7.5 wouldn't necessarily have addressed this.

Unfortuntely I've since migrated to Nethermind so I can't tell :/

ibhagwan avatar Oct 05 '22 23:10 ibhagwan

No problem, thank you for the report!

non-fungible-nelson avatar Oct 05 '22 23:10 non-fungible-nelson

No problem, thank you for the report!

I'm currently resyncing besu on Goerli with Nimbus 22.10/Besu 22.7.5 and not seeing any errors (aside from backward sync being extremley slow with NO_AVAILABLE_PEERS alerts), will report if this comes up again.

ibhagwan avatar Oct 05 '22 23:10 ibhagwan

You're a saint 🙏🏻 And Goerli always takes a moment to heat up with peers.

non-fungible-nelson avatar Oct 05 '22 23:10 non-fungible-nelson