search

hyperledger / besu

An enterprise-grade Java-based, Apache 2.0 licensed Ethereum client https://wiki.hyperledger.org/display/besu
https://www.hyperledger.org/projects/besu
Apache License 2.0
1.52k stars 839 forks source link

Critical Exception Processing Transaction #4079

Closed SeaMonkey82 closed 2 years ago

SeaMonkey82 commented 2 years ago

v22.4.4 on Ropsten

2022-07-10 02:47:56.033-04:00 | ForkJoinPool.commonPool-worker-59 | INFO  | AbstractBlockProcessor | Block processing error: transaction invalid 'INTERNAL_ERROR'. Block 0xe63111e889a4127ff441498ac5d79883184c6de6ab0fad6db71e67931db32453 Transaction 0x06d93ad334328ee21228f5cc6443b5bbadb0781d16421ff3e7c8bc3fd2874247
2022-07-10 02:47:56.033-04:00 | ForkJoinPool.commonPool-worker-59 | ERROR | MainnetBlockValidator | Error processing block. Block 12560518 (0xe63111e889a4127ff441498ac5d79883184c6de6ab0fad6db71e67931db32453)
2022-07-10 02:47:56.035-04:00 | ForkJoinPool.commonPool-worker-59 | ERROR | MainnetTransactionProcessor | Critical Exception Processing Transaction
org.hyperledger.besu.ethereum.trie.MerkleTrieException: Unable to load trie node value for hash 0x2858e905a4fad439ec3eb36652b76843ff8e171f97f589f976a41b9a26d2ffcf location 0x
        at org.hyperledger.besu.ethereum.trie.StoredNode.lambda$load$0(StoredNode.java:133)
        at java.base/java.util.Optional.orElseThrow(Optional.java:408)
        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.get(StoredMerklePatriciaTrie.java:119)
        at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateKeyValueStorage.getStorageValueBySlotHash(BonsaiWorldStateKeyValueStorage.java:159)
        at org.hyperledger.besu.ethereum.bonsai.BonsaiPersistedWorldState.getStorageValueBySlotHash(BonsaiPersistedWorldState.java:422)
        at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.getStorageValueBySlotHash(BonsaiWorldStateUpdater.java:320)
        at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.getStorageValue(BonsaiWorldStateUpdater.java:307)
        at org.hyperledger.besu.ethereum.bonsai.BonsaiAccount.getStorageValue(BonsaiAccount.java:208)
        at org.hyperledger.besu.evm.worldstate.UpdateTrackingAccount.getStorageValue(UpdateTrackingAccount.java:213)
        at org.hyperledger.besu.evm.worldstate.UpdateTrackingAccount.getStorageValue(UpdateTrackingAccount.java:213)
        at org.hyperledger.besu.evm.worldstate.UpdateTrackingAccount.getStorageValue(UpdateTrackingAccount.java:213)
        at org.hyperledger.besu.evm.worldstate.UpdateTrackingAccount.getStorageValue(UpdateTrackingAccount.java:213)
        at org.hyperledger.besu.evm.operation.SLoadOperation.execute(SLoadOperation.java:61)
        at org.hyperledger.besu.evm.EVM.lambda$executeNextOperation$0(EVM.java:87)
        at org.hyperledger.besu.evm.tracing.OperationTracer.lambda$static$0(OperationTracer.java:27)
        at org.hyperledger.besu.evm.EVM.executeNextOperation(EVM.java:81)
        at org.hyperledger.besu.evm.EVM.runToHalt(EVM.java:74)
        at org.hyperledger.besu.evm.processor.AbstractMessageProcessor.codeExecute(AbstractMessageProcessor.java:161)
        at org.hyperledger.besu.evm.processor.AbstractMessageProcessor.process(AbstractMessageProcessor.java:173)
        at org.hyperledger.besu.ethereum.mainnet.MainnetTransactionProcessor.process(MainnetTransactionProcessor.java:485)
        at org.hyperledger.besu.ethereum.mainnet.MainnetTransactionProcessor.processTransaction(MainnetTransactionProcessor.java:397)
        at org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:161)
        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:158)
        at org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:112)
        at org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:71)
        at org.hyperledger.besu.ethereum.eth.sync.backwardsync.BackwardSyncContext.saveBlock(BackwardSyncContext.java:242)
        at org.hyperledger.besu.ethereum.eth.sync.backwardsync.ProcessKnownAncestorsStep.processKnownAncestors(ProcessKnownAncestorsStep.java:59)
        at java.base/java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1736)
        at java.base/java.util.concurrent.CompletableFuture$AsyncRun.exec(CompletableFuture.java:1728)
        at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:290)
        at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1020)
        at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1656)
        at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1594)
        at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:183)
matkt commented 2 years ago

Hi thanks for the ticket. do you know if you used fastync or snapsync for this one ?

SeaMonkey82 commented 2 years ago

I can't say for certain, but as checkpoint sync has been failing to do much besides refresh DNS records and receive new payloads from an already-synced CL, I think this was with fast sync.

ahamlat commented 2 years ago

Another discord user had the same error with Fast Sync and Bonsai as a database, here're the logs 

Aug 31 19:54:41 validateur2 besu[3598]: 2022-08-31 19:54:41.386+00:00 | EthScheduler-Workers-0 | INFO  | PersistBlockTask | Imported #15,448,544 / 154 tx / 0 om / 13,057,730 (43.5%) gas / (0xe7d26bab682f7d76e30f8ce9f86fc37104a35da888a30a>
Aug 31 19:54:46 validateur2 besu[3598]: 2022-08-31 19:54:46.713+00:00 | EthScheduler-Workers-1 | INFO  | PersistBlockTask | Imported #15,448,545 / 85 tx / 0 om / 9,775,765 (32.6%) gas / (0xe97c015be3aeaccc57f89b8a2366efb01824604458540506>
Aug 31 19:55:00 validateur2 besu[3598]: 2022-08-31 19:55:00.856+00:00 | EthScheduler-Workers-0 | ERROR | MainnetTransactionProcessor | Critical Exception Processing Transaction
Aug 31 19:55:00 validateur2 besu[3598]: org.hyperledger.besu.ethereum.trie.MerkleTrieException: Unable to load trie node value for hash 0xf5794f7eae54fa32f3d93c33c38915a3dce29129e477ac635e0d1261763e3d00 location 0x0f0e0e090e
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.trie.StoredNode.lambda$load$0(StoredNode.java:133)
Aug 31 19:55:00 validateur2 besu[3598]:         at java.base/java.util.Optional.orElseThrow(Optional.java:408)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.trie.StoredNode.load(StoredNode.java:131)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:63)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.trie.GetVisitor.visit(GetVisitor.java:46)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.trie.BranchNode.accept(BranchNode.java:80)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:64)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.trie.GetVisitor.visit(GetVisitor.java:46)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.trie.BranchNode.accept(BranchNode.java:80)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:64)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.trie.GetVisitor.visit(GetVisitor.java:46)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.trie.BranchNode.accept(BranchNode.java:80)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:64)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.trie.GetVisitor.visit(GetVisitor.java:46)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.trie.BranchNode.accept(BranchNode.java:80)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:64)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.trie.GetVisitor.visit(GetVisitor.java:46)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.trie.BranchNode.accept(BranchNode.java:80)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:64)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.trie.StoredMerklePatriciaTrie.get(StoredMerklePatriciaTrie.java:119)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateKeyValueStorage.getStorageValueBySlotHash(BonsaiWorldStateKeyValueStorage.java:159)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.bonsai.BonsaiPersistedWorldState.getStorageValueBySlotHash(BonsaiPersistedWorldState.java:379)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.getStorageValueBySlotHash(BonsaiWorldStateUpdater.java:320)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.getStorageValue(BonsaiWorldStateUpdater.java:307)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.ethereum.bonsai.BonsaiAccount.getStorageValue(BonsaiAccount.java:208)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.evm.worldstate.UpdateTrackingAccount.getStorageValue(UpdateTrackingAccount.java:213)
Aug 31 19:55:00 validateur2 besu[3598]:         at org.hyperledger.besu.evm.worldstate.UpdateTrackingAccount.getStorageValue(Upd

The node wasn't able to recover after this error.

matkt commented 2 years ago

I'm working on a fix for this issue https://github.com/hyperledger/besu/pull/4312

felix-halim commented 2 years ago

I'm also having the same issue, from here on, besu cannot continue syncing and stuck forever.

Is there any workaround for this?

Here is the detail:

besu/v22.7.6/osx-x86_64/oracle-java-13

2022-10-14 02:58:39.791-07:00 | vert.x-worker-thread-0 | ERROR | MainnetTransactionProcessor | Critical Exception Processing Transaction
org.hyperledger.besu.ethereum.trie.MerkleTrieException: Unable to load trie node value for hash 0x9c3e293bec7396fe66663bc8fd3c209f3db3b2eaf57ca0d6eed1e7df3f339f51 location 0x040005
  at org.hyperledger.besu.ethereum.trie.StoredNode.lambda$load$0(StoredNode.java:133)
  at java.base/java.util.Optional.orElseThrow(Optional.java:401)
  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.GetVisitor.visit(GetVisitor.java:34)
  at org.hyperledger.besu.ethereum.trie.ExtensionNode.accept(ExtensionNode.java:68)
  at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:64)
  at org.hyperledger.besu.ethereum.trie.GetVisitor.visit(GetVisitor.java:46)
  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.GetVisitor.visit(GetVisitor.java:46)
  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.get(StoredMerklePatriciaTrie.java:119)
  at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateKeyValueStorage.getStorageValueBySlotHash(BonsaiWorldStateKeyValueStorage.java:200)
  at org.hyperledger.besu.ethereum.bonsai.BonsaiPersistedWorldState.getStorageValueBySlotHash(BonsaiPersistedWorldState.java:381)
  at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.getStorageValueBySlotHash(BonsaiWorldStateUpdater.java:320)
  at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.getStorageValue(BonsaiWorldStateUpdater.java:307)
  at org.hyperledger.besu.ethereum.bonsai.BonsaiAccount.getStorageValue(BonsaiAccount.java:208)
  at org.hyperledger.besu.evm.worldstate.UpdateTrackingAccount.getStorageValue(UpdateTrackingAccount.java:213)
  at org.hyperledger.besu.evm.worldstate.UpdateTrackingAccount.getStorageValue(UpdateTrackingAccount.java:213)
  at org.hyperledger.besu.evm.worldstate.UpdateTrackingAccount.getStorageValue(UpdateTrackingAccount.java:213)
  at org.hyperledger.besu.evm.worldstate.UpdateTrackingAccount.getStorageValue(UpdateTrackingAccount.java:213)
  at org.hyperledger.besu.evm.operation.SLoadOperation.execute(SLoadOperation.java:61)
  at org.hyperledger.besu.evm.EVM.lambda$executeNextOperation$0(EVM.java:87)
  at org.hyperledger.besu.evm.tracing.OperationTracer.lambda$static$0(OperationTracer.java:27)
  at org.hyperledger.besu.evm.EVM.executeNextOperation(EVM.java:81)
  at org.hyperledger.besu.evm.EVM.runToHalt(EVM.java:74)
  at org.hyperledger.besu.evm.processor.AbstractMessageProcessor.codeExecute(AbstractMessageProcessor.java:161)
  at org.hyperledger.besu.evm.processor.AbstractMessageProcessor.process(AbstractMessageProcessor.java:173)
  at org.hyperledger.besu.ethereum.mainnet.MainnetTransactionProcessor.process(MainnetTransactionProcessor.java:485)
  at org.hyperledger.besu.ethereum.mainnet.MainnetTransactionProcessor.processTransaction(MainnetTransactionProcessor.java:397)
  at org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:180)
  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:343)
  at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.rememberBlock(MergeCoordinator.java:359)
  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:1128)
  at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
  at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
  at java.base/java.lang.Thread.run(Thread.java:830)
2022-10-14 02:58:39.792-07:00 | vert.x-worker-thread-0 | INFO  | AbstractBlockProcessor | Block processing error: transaction invalid 'INTERNAL_ERROR'. Block 0x43b31dfd08fd7c9bc84800de57c688a6f06257c765cafad8f936c50eb69d3a44 Transaction 0x76b5eb30e3080e341e024fcd7870804c245cd43683d9fe4f99a48fc878451ef1
2022-10-14 02:58:39.793-07:00 | vert.x-worker-thread-0 | ERROR | MainnetBlockValidator | Error processing block. Block 15745602 (0x43b31dfd08fd7c9bc84800de57c688a6f06257c765cafad8f936c50eb69d3a44)
2022-10-14 02:58:39.794-07:00 | vert.x-worker-thread-0 | WARN  | EngineNewPayload | Invalid new payload: number: 15745602, hash: 0x43b31dfd08fd7c9bc84800de57c688a6f06257c765cafad8f936c50eb69d3a44, parentHash: 0xffe76145e90fd25733ad76011877acb562047954aa54fc83c89a425a41c1d1b8, latestValidHash: 0xffe76145e90fd25733ad76011877acb562047954aa54fc83c89a425a41c1d1b8, status: INVALID, validationError: Error processing block
2022-10-14 03:00:37.118-07:00 | vert.x-eventloop-thread-2 | WARN  | EngineQosTimer | Execution engine not called in 120 seconds, consensus client may not be connected
sJJdGG commented 2 years ago

Getting the same error in a new besu/lighthouse setup starting from fresh. here's the error:

sudo journalctl -fu besu
Oct 14 21:51:01 Starship besu[717887]: 2022-10-14 21:51:01.729+00:00 | main | INFO  | Besu | Using LibEthPairings native alt bn128
Oct 14 21:51:01 Starship besu[717887]: 2022-10-14 21:51:01.731+00:00 | main | INFO  | Besu | Using the native implementation of the signature algorithm
Oct 14 21:51:01 Starship besu[717887]: 2022-10-14 21:51:01.734+00:00 | main | INFO  | Besu | Using the native implementation of the blake2bf algorithm
Oct 14 21:51:01 Starship besu[717887]: 2022-10-14 21:51:01.736+00:00 | main | INFO  | Besu | Starting Besu version: besu/v22.7.6/linux-x86_64/openjdk-java-11
Oct 14 21:51:01 Starship besu[717887]: 2022-10-14 21:51:01.903+00:00 | main | INFO  | Besu | Static Nodes file = /var/lib/besu/static-nodes.json
Oct 14 21:51:01 Starship besu[717887]: 2022-10-14 21:51:01.904+00:00 | main | INFO  | StaticNodesParser | StaticNodes file /var/lib/besu/static-nodes.json does not exist, no static connections will be created.
Oct 14 21:51:01 Starship besu[717887]: 2022-10-14 21:51:01.904+00:00 | main | INFO  | Besu | Connecting to 0 static nodes.
Oct 14 21:51:01 Starship besu[717887]: 2022-10-14 21:51:01.906+00:00 | main | INFO  | Besu | Security Module: localfile
Oct 14 21:51:01 Starship besu[717887]: 2022-10-14 21:51:01.915+00:00 | main | INFO  | DatabaseMetadata | Lookup database metadata file in data directory: /var/lib/besu
Oct 14 21:51:01 Starship besu[717887]: 2022-10-14 21:51:01.944+00:00 | main | INFO  | RocksDBKeyValueStorageFactory | Existing database detected at /var/lib/besu. Version 2
Oct 14 21:51:19 Starship besu[717887]: 2022-10-14 21:51:19.736+00:00 | main | WARN  | Besu | --tx-pool-future-max-by-account has been deprecated, use --tx-pool-limit-by-account-percentage instead.
Oct 14 21:51:19 Starship besu[717887]: 2022-10-14 21:51:19.748+00:00 | main | INFO  | KeyPairUtil | Loaded public key 0x037e8c2b7fabb415ec8042d3066993a8e25e51c2b7a9fb729b5d9c763970bfbb76053d871e70ccf1f800ecb6e4639d43ba3a528fa7ac69f19d66e4df32fa3092 from /var/lib/besu/key
Oct 14 21:51:19 Starship besu[717887]: 2022-10-14 21:51:19.841+00:00 | main | INFO  | ProtocolScheduleBuilder | Protocol schedule created with milestones: [Frontier: 0, Homestead: 1150000, DaoRecoveryInit: 1920000, DaoRecoveryTransition: 1920001, Homestead: 1920010, TangerineWhistle: 2463000, SpuriousDragon: 2675000, Byzantium: 4370000, Petersburg: 7280000, Istanbul: 9069000, MuirGlacier: 9200000, Berlin: 12244000, London: 12965000, ArrowGlacier: 13773000, GrayGlacier: 15050000]
Oct 14 21:51:19 Starship besu[717887]: 2022-10-14 21:51:19.857+00:00 | main | INFO  | ProtocolScheduleBuilder | Protocol schedule created with milestones: [Frontier: 0, Homestead: 1150000, DaoRecoveryInit: 1920000, DaoRecoveryTransition: 1920001, Homestead: 1920010, TangerineWhistle: 2463000, SpuriousDragon: 2675000, Byzantium: 4370000, Petersburg: 7280000, Istanbul: 9069000, MuirGlacier: 9200000, Berlin: 12244000, London: 12965000, ArrowGlacier: 13773000, GrayGlacier: 15050000]
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.185+00:00 | main | INFO  | EthPeers | Updating the default best peer comparator
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.198+00:00 | main | INFO  | BesuControllerBuilder | TTD difficulty is present, creating initial sync phase with transition to PoS support
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.203+00:00 | main | INFO  | SnapDownloaderFactory | Snap sync was requested, but cannot be enabled because the local blockchain is not empty.
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.204+00:00 | main | INFO  | TransitionBesuControllerBuilder | TTD present, creating DefaultSynchronizer that stops propagating after finalization
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.217+00:00 | main | INFO  | RunnerBuilder | Detecting NAT service.
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.378+00:00 | main | INFO  | Runner | Starting external services ...
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.379+00:00 | main | INFO  | JsonRpcService | Starting JSON-RPC service on 127.0.0.1:8551
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.431+00:00 | vert.x-eventloop-thread-1 | INFO  | JsonRpcService | JSON-RPC service started and listening on 127.0.0.1:8551
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.433+00:00 | main | INFO  | AutoTransactionLogBloomCachingService | Starting auto transaction log bloom caching service.
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.434+00:00 | main | INFO  | LogBloomCacheMetadata | Lookup cache metadata file in data directory: /var/lib/besu/caches
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.438+00:00 | main | INFO  | Runner | Starting Ethereum main loop ...
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.438+00:00 | main | INFO  | NatService | No NAT environment detected so no service could be started
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.438+00:00 | main | INFO  | NetworkRunner | Starting Network.
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.440+00:00 | main | INFO  | DefaultP2PNetwork | Starting DNS discovery with URL enrtree://AKA3AM6LPBYEUDMVNU3BSVQJ5AD45Y7YPOHJLEF6W26QOE4VTUDPE@all.mainnet.ethdisco.net
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.477+00:00 | nioEventLoopGroup-2-1 | INFO  | RlpxAgent | P2P RLPx agent started and listening on /0:0:0:0:0:0:0:0:30303.
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.478+00:00 | main | INFO  | PeerDiscoveryAgent | Starting peer discovery agent on host=0.0.0.0, port=30303
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.516+00:00 | vert.x-eventloop-thread-1 | INFO  | VertxPeerDiscoveryAgent | Started peer discovery agent successfully, on effective host=0:0:0:0:0:0:0:0%0 and port=30303
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.518+00:00 | vert.x-eventloop-thread-1 | INFO  | PeerDiscoveryAgent | P2P peer discovery agent started and listening on /0:0:0:0:0:0:0:0%0:30303
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.558+00:00 | vert.x-eventloop-thread-1 | INFO  | PeerDiscoveryAgent | Writing node record to disk. NodeRecord{seq=16, publicKey=0x02037e8c2b7fabb415ec8042d3066993a8e25e51c2b7a9fb729b5d9c763970bfbb, udpAddress=Optional[/127.0.0.1:30303], tcpAddress=Optional[/127.0.0.1:30303], asBase64=-Je4QJYWUqMeo2xKDY72w2m_2Lz_C0VMX8YWN-29xBURp8PEQd_YaEnvV1WikjukNIwN9ZG3jrLeUWOG0qX16dzT-kkQg2V0aMfGhPCv0OOAgmlkgnY0gmlwhH8AAAGJc2VjcDI1NmsxoQIDfowrf6u0FeyAQtMGaZOo4l5Rwrep-3KbXZx2OXC_u4N0Y3CCdl-DdWRwgnZf, nodeId=0xbcff8021312ef362c058515d723f2d36e5214f179fbdc7312349b583edb35784, customFields={tcp=30303, udp=30303, ip=0x7f000001, eth=[[0xf0afd0e3, 0x]], id=V4, secp256k1=0x02037e8c2b7fabb415ec8042d3066993a8e25e51c2b7a9fb729b5d9c763970bfbb}}
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.595+00:00 | main | INFO  | DefaultP2PNetwork | Enode URL enode://037e8c2b7fabb415ec8042d3066993a8e25e51c2b7a9fb729b5d9c763970bfbb76053d871e70ccf1f800ecb6e4639d43ba3a528fa7ac69f19d66e4df32fa3092@127.0.0.1:30303
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.596+00:00 | main | INFO  | DefaultP2PNetwork | Node address 0x723f2d36e5214f179fbdc7312349b583edb35784
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.597+00:00 | main | INFO  | DefaultSynchronizer | Starting synchronizer.
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.599+00:00 | main | INFO  | TransactionPoolFactory | Enabling transaction pool
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.601+00:00 | main | INFO  | DefaultSynchronizer | Stopping block propagation.
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.602+00:00 | main | INFO  | DefaultSynchronizer | Stopping the pruner.
Oct 14 21:51:20 Starship besu[717887]: 2022-10-14 21:51:20.602+00:00 | main | INFO  | Runner | Ethereum main loop is up.
Oct 14 21:51:28 Starship besu[717887]: 2022-10-14 21:51:28.823+00:00 | Timer-0 | INFO  | DNSResolver | Resolved 2409 nodes
Oct 14 21:51:31 Starship besu[717887]: 2022-10-14 21:51:31.681+00:00 | vert.x-worker-thread-0 | ERROR | MainnetTransactionProcessor | Critical Exception Processing Transaction
Oct 14 21:51:31 Starship besu[717887]: org.hyperledger.besu.ethereum.trie.MerkleTrieException: Unable to load trie node value for hash 0x9c3e293bec7396fe66663bc8fd3c209f3db3b2eaf57ca0d6eed1e7df3f339f51 location 0x040005
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.trie.StoredNode.lambda$load$0(StoredNode.java:133)
Oct 14 21:51:31 Starship besu[717887]:         at java.base/java.util.Optional.orElseThrow(Optional.java:408)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.trie.StoredNode.load(StoredNode.java:131)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:63)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.trie.GetVisitor.visit(GetVisitor.java:34)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.trie.ExtensionNode.accept(ExtensionNode.java:68)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:64)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.trie.GetVisitor.visit(GetVisitor.java:46)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.trie.BranchNode.accept(BranchNode.java:80)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:64)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.trie.GetVisitor.visit(GetVisitor.java:46)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.trie.BranchNode.accept(BranchNode.java:80)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.trie.StoredNode.accept(StoredNode.java:64)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.trie.StoredMerklePatriciaTrie.get(StoredMerklePatriciaTrie.java:119)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateKeyValueStorage.getStorageValueBySlotHash(BonsaiWorldStateKeyValueStorage.java:200)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.bonsai.BonsaiPersistedWorldState.getStorageValueBySlotHash(BonsaiPersistedWorldState.java:381)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.getStorageValueBySlotHash(BonsaiWorldStateUpdater.java:320)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateUpdater.getStorageValue(BonsaiWorldStateUpdater.java:307)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.bonsai.BonsaiAccount.getStorageValue(BonsaiAccount.java:208)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.evm.worldstate.UpdateTrackingAccount.getStorageValue(UpdateTrackingAccount.java:213)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.evm.worldstate.UpdateTrackingAccount.getStorageValue(UpdateTrackingAccount.java:213)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.evm.worldstate.UpdateTrackingAccount.getStorageValue(UpdateTrackingAccount.java:213)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.evm.worldstate.UpdateTrackingAccount.getStorageValue(UpdateTrackingAccount.java:213)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.evm.operation.SLoadOperation.execute(SLoadOperation.java:61)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.evm.EVM.lambda$executeNextOperation$0(EVM.java:87)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.evm.tracing.OperationTracer.lambda$static$0(OperationTracer.java:27)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.evm.EVM.executeNextOperation(EVM.java:81)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.evm.EVM.runToHalt(EVM.java:74)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.evm.processor.AbstractMessageProcessor.codeExecute(AbstractMessageProcessor.java:161)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.evm.processor.AbstractMessageProcessor.process(AbstractMessageProcessor.java:173)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.mainnet.MainnetTransactionProcessor.process(MainnetTransactionProcessor.java:485)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.mainnet.MainnetTransactionProcessor.processTransaction(MainnetTransactionProcessor.java:397)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:180)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:43)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.mainnet.BlockProcessor.processBlock(BlockProcessor.java:80)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.MainnetBlockValidator.processBlock(MainnetBlockValidator.java:175)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:112)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.validateBlock(MergeCoordinator.java:343)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.rememberBlock(MergeCoordinator.java:359)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.consensus.merge.blockcreation.TransitionCoordinator.rememberBlock(TransitionCoordinator.java:137)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.engine.EngineNewPayload.syncResponse(EngineNewPayload.java:215)
Oct 14 21:51:31 Starship besu[717887]:         at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.lambda$response$0(ExecutionEngineJsonRpcMethod.java:73)
Oct 14 21:51:31 Starship besu[717887]:         at io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)
Oct 14 21:51:31 Starship besu[717887]:         at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)
Oct 14 21:51:31 Starship besu[717887]:         at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)
Oct 14 21:51:31 Starship besu[717887]:         at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
Oct 14 21:51:31 Starship besu[717887]:         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
Oct 14 21:51:31 Starship besu[717887]:         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
Oct 14 21:51:31 Starship besu[717887]:         at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
Oct 14 21:51:31 Starship besu[717887]:         at java.base/java.lang.Thread.run(Thread.java:829)
Oct 14 21:51:31 Starship besu[717887]: 2022-10-14 21:51:31.689+00:00 | vert.x-worker-thread-0 | INFO  | AbstractBlockProcessor | Block processing error: transaction invalid 'INTERNAL_ERROR'. Block 0x43b31dfd08fd7c9bc84800de57c688a6f06257c765cafad8f936c50eb69d3a44 Transaction 0x76b5eb30e3080e341e024fcd7870804c245cd43683d9fe4f99a48fc878451ef1
Oct 14 21:51:31 Starship besu[717887]: 2022-10-14 21:51:31.698+00:00 | vert.x-worker-thread-0 | ERROR | MainnetBlockValidator | Error processing block. Block 15745602 (0x43b31dfd08fd7c9bc84800de57c688a6f06257c765cafad8f936c50eb69d3a44)

Here's systemd sample:

[Unit]
Description=Besu Execution Client (Mainnet)
Wants=network-online.target
After=network-online.target

[Service]
User=besu
Group=besu
Type=simple
Restart=always
RestartSec=5
Environment="JAVA_OPTS=-Xmx6g"
ExecStart=/usr/local/bin/besu/bin/besu \
  --network=mainnet \
  --sync-mode=X_SNAP \
  --data-path=/var/lib/besu \
  --data-storage-format=BONSAI \
  --Xplugin-rocksdb-high-spec-enabled \
  --engine-jwt-secret=/var/lib/jwtsecret/jwt.hex

[Install]
WantedBy=multi-user.target

besu version: v22.7.6 lighthouse version: v3.1.2

@macfarla @garyschulte @matkt Is there any repair/fix option?

garyschulte commented 2 years ago

closing as fixed by #4409