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

Incorrectly returned INVALID for ropsten block #4512

Closed
ajsutton opened this issue Oct 10, 2022 · 9 comments · Fixed by #4524
Closed

Incorrectly returned INVALID for ropsten block #4512

ajsutton opened this issue Oct 10, 2022 · 9 comments · Fixed by #4524
Assignees
@jflo @macfarla
Labels
bug Something isn't working

Comments

@ajsutton
Copy link
Contributor

Description

On one of our ropsten nodes, besu incorrectly returned INVALID with a 0x0000 latestValidHash for beacon block 957088 (root 0x1cfaadb29cab42bb951aca0d068f624cbf4ae68fe5117c8c133114a84b96fb6f)

Execution payload header:

        "execution_payload": {
          "parent_hash": "0x9abbfb6c82d7c0b9639333acd2d648205c12c16db0e304877ec765a822323803",
          "fee_recipient": "0x965b7a773e3632b259108d246a7cfdcdff118999",
          "state_root": "0x93489b3724363a97c28808016d360e630ffe99d3449c8f275163dcb1120652ab",
          "receipts_root": "0xc97efdeae4ddcbb597099852fe158644f86a6411c8db862c4f698526474980dd",
          "logs_bloom": "0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000",
          "prev_randao": "0xcf371ca53a22567031cb5c909a1c9f27f417240b795a718c9bcb269efdea8325",
          "block_number": "13125902",
          "gas_limit": "30000000",
          "gas_used": "346036",
          "timestamp": "1665407856",
          "extra_data": "0x",
          "base_fee_per_gas": "7",
          "block_hash": "0x56128e3165fa54e3644b2de9493972741a029666f128b9b2595a0df47be61d5f",

This caused the node to be unable to follow the canonical chain. The block was correctly imported after restarting besu and then teku.

Relevant teku logs:


{"@timestamp":"2022-10-10T13:17:36,270","level":"INFO","thread":"beaconchain-async-0","class":"teku-status-log","message":"Sync committee performance: epoch 29908, expected 768, produced 768, correct 768, included 672 (88%)","throwable":""}
{"@timestamp":"2022-10-10T13:17:37,124","level":"ERROR","thread":"pool-4-thread-417","class":"teku-event-log","message":"Execution Client request failed. Make sure the Execution Client is online and in sync.","throwable":" java.io.IOException: -32603: Internal error\n\tat tech.pegasys.teku.ethereum.executionclient.web3j.Web3JClient.lambda$doRequest$0(Web3JClient.java:85)\n\tat java.base/java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:934)\n\tat java.base/java.util.concurrent.CompletableFuture$UniHandle.tryFire(CompletableFuture.java:911)\n\tat java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)\n\tat java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)\n\tat tech.pegasys.teku.infrastructure.async.SafeFuture.lambda$propagateResult$3(SafeFuture.java:148)\n\tat java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)\n\tat java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)\n\tat java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)\n\tat java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)\n\tat org.web3j.utils.Async.lambda$run$1(Async.java:38)\n\tat java.base/java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1804)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)\n\tat java.base/java.lang.Thread.run(Thread.java:833)\n"}
{"@timestamp":"2022-10-10T13:17:37,134","level":"ERROR","thread":"forkchoice-async-0","class":"BlockManager","message":"Unable to import block: Execution Client returned an error: tech.pegasys.teku.ethereum.executionlayer.InvalidRemoteResponseException: Invalid remote response from the execution client: -32603: Internal error","throwable":""}
{"@timestamp":"2022-10-10T13:17:37,136","level":"ERROR","thread":"beaconchain-async-4","class":"teku-validator-log","message":"Failed to import proposed block due to FAILED_EXECUTION_PAYLOAD_EXECUTION: 1cfaadb29cab42bb951aca0d068f624cbf4ae68fe5117c8c133114a84b96fb6f (957088)","throwable":" java.util.concurrent.CompletionException: tech.pegasys.teku.ethereum.executionlayer.InvalidRemoteResponseException: Invalid remote response from the execution client: -32603: Internal error\n\tat java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:315)\n\tat java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:320)\n\tat java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:649)\n\tat java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)\n\tat java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)\n\tat tech.pegasys.teku.infrastructure.async.SafeFuture.lambda$propagateResult$3(SafeFuture.java:148)\n\tat java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)\n\tat java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)\n\tat java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)\n\tat java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)\n\tat tech.pegasys.teku.infrastructure.async.SafeFuture.lambda$propagateResult$3(SafeFuture.java:148)\n\tat java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)\n\tat java.base/java.util.concurrent.CompletableFuture.uniWhenCompleteStage(CompletableFuture.java:887)\n\tat java.base/java.util.concurrent.CompletableFuture.whenComplete(CompletableFuture.java:2325)\n\tat tech.pegasys.teku.infrastructure.async.SafeFuture.whenComplete(SafeFuture.java:603)\n\tat tech.pegasys.teku.infrastructure.async.SafeFuture.whenComplete(SafeFuture.java:33)\n\tat tech.pegasys.teku.infrastructure.async.SafeFuture.propagateResult(SafeFuture.java:143)\n\tat tech.pegasys.teku.infrastructure.async.SafeFuture.lambda$exceptionallyCompose$33(SafeFuture.java:422)\n\tat java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)\n\tat java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)\n\tat java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)\n\tat java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)\n\tat tech.pegasys.teku.infrastructure.async.SafeFuture.lambda$propagateResult$3(SafeFuture.java:148)\n\tat java.base/java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:863)\n\tat java.base/java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:841)\n\tat java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)\n\tat java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2147)\n\tat org.web3j.utils.Async.lambda$run$1(Async.java:38)\n\tat java.base/java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java:1804)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)\n\tat java.base/java.lang.Thread.run(Thread.java:833)\nCaused by: tech.pegasys.teku.ethereum.executionlayer.InvalidRemoteResponseException: Invalid remote response from the execution client: -32603: Internal error\n\tat tech.pegasys.teku.ethereum.executionlayer.ExecutionLayerManagerImpl.unwrapResponseOrThrow(ExecutionLayerManagerImpl.java:518)\n\tat tech.pegasys.teku.ethereum.executionlayer.ExecutionLayerManagerImpl.unwrapExecutionClientResponseOrThrow(ExecutionLayerManagerImpl.java:504)\n\tat java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:646)\n\t... 29 more\n"}
{"@timestamp":"2022-10-10T13:17:37,647","level":"INFO","thread":"validator-async-2","class":"teku-validator-log","message":"Validator   *** Published block              Count: 1, Slot: 957088, Root: 1cfaadb29cab42bb951aca0d068f624cbf4ae68fe5117c8c133114a84b96fb6f, 346036 (1%) gas, EL block:  56128e3165fa54e3644b2de9493972741a029666f128b9b2595a0df47be61d5f (13125902)","throwable":""}
{"@timestamp":"2022-10-10T13:17:39,135","level":"INFO","thread":"beaconchain-async-1","class":"FailedExecutionPool","message":"Retrying execution of block 1cfaadb29cab42bb951aca0d068f624cbf4ae68fe5117c8c133114a84b96fb6f (957088)","throwable":""}
{"@timestamp":"2022-10-10T13:17:39,139","level":"INFO","thread":"pool-4-thread-417","class":"teku-event-log","message":"Execution Client request succeeded after a previous failure","throwable":""}
{"@timestamp":"2022-10-10T13:17:39,169","level":"WARN","thread":"forkchoice-async-0","class":"ForkChoiceStrategy","message":"Payload for child of block root 0xd85399eb10de6804a2d8d5d749a457b350a6c2bbedc3858dc24be275072d3c63 marked as invalid by Execution Client","throwable":""}
{"@timestamp":"2022-10-10T13:17:39,170","level":"ERROR","thread":"forkchoice-async-0","class":"teku-status-log","message":"Could not find latest valid execution payload hash (0x0000000000000000000000000000000000000000000000000000000000000000) in the non-finalized chain. Optimistic sync may have finalized an invalid transition block.","throwable":""}

Besu logs:

{"@timestamp":"2022-10-10T13:17:24,224","level":"INFO","thread":"vert.x-worker-thread-0","class":"EngineNewPayload","message":"Imported #13,125,901 / 0 tx / base fee 7 wei / 0 (0.0%) gas / (0x9abbfb6c82d7c0b9639333
acd2d648205c12c16db0e304877ec765a822323803) in 0.001s. Peers: 25","throwable":""}
{"@timestamp":"2022-10-10T13:17:24,910","level":"INFO","thread":"EthScheduler-Computation-534","class":"MergeCoordinator","message":"Successfully built block 13125902 (0x56128e3165fa54e3644b2de9493972741a029666f128
b9b2595a0df47be61d5f) for proposal identified by 0x0035eb5652a22a90, with 5 transactions, in 108ms","throwable":""}
{"@timestamp":"2022-10-10T13:17:24,999","level":"INFO","thread":"EthScheduler-Computation-534","class":"MergeCoordinator","message":"Successfully built block 13125902 (0x56128e3165fa54e3644b2de9493972741a029666f128
b9b2595a0df47be61d5f) for proposal identified by 0x0035eb5652a22a90, with 5 transactions, in 188ms","throwable":""}
{"@timestamp":"2022-10-10T13:17:36,043","level":"INFO","thread":"vert.x-worker-thread-0","class":"EngineGetPayload","message":"Fetch block proposal by identifier: 0x0035eb5652a22a90, hash: 0x56128e3165fa54e3644b2de
9493972741a029666f128b9b2595a0df47be61d5f, number: 13125902, coinbase: 0x965b7a773e3632b259108d246a7cfdcdff118999, transaction count: 5","throwable":""}
{"@timestamp":"2022-10-10T13:17:37,092","level":"ERROR","thread":"vert.x-worker-thread-0","class":"AbstractBlockProcessor","message":"failed persisting block","throwable":" org.hyperledger.besu.plugin.services.exce
ption.StorageException: org.rocksdb.RocksDBException: TimedOut(LockTimeout)\n\tat org.hyperledger.besu.plugin.services.storage.rocksdb.segmented.RocksDBColumnarKeyValueStorage$RocksDbTransaction.put(RocksDBColumnar
KeyValueStorage.java:299)\n\tat org.hyperledger.besu.plugin.services.storage.rocksdb.segmented.RocksDBColumnarKeyValueStorage$RocksDbTransaction.put(RocksDBColumnarKeyValueStorage.java:280)\n\tat org.hyperledger.be
su.services.kvstore.SegmentedKeyValueStorageTransactionTransitionValidatorDecorator.put(SegmentedKeyValueStorageTransactionTransitionValidatorDecorator.java:36)\n\tat org.hyperledger.besu.services.kvstore.Segmented
KeyValueStorageAdapter$1.put(SegmentedKeyValueStorageAdapter.java:80)\n\tat org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateKeyValueStorage$Updater.putAccountInfoState(BonsaiWorldStateKeyValueStorage.java:318)
\n\tat org.hyperledger.besu.ethereum.bonsai.BonsaiPersistedWorldState.calculateRootHash(BonsaiPersistedWorldState.java:223)\n\tat org.hyperledger.besu.ethereum.bonsai.BonsaiInMemoryWorldState.rootHash(BonsaiInMemor
yWorldState.java:43)\n\tat org.hyperledger.besu.ethereum.bonsai.BonsaiInMemoryWorldState.persist(BonsaiInMemoryWorldState.java:53)\n\tat org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(Abs
tractBlockProcessor.java:220)\n\tat org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:43)\n\tat org.hyperledger.besu.ethereum.mainnet.BlockProcessor.processBlock(
BlockProcessor.java:80)\n\tat org.hyperledger.besu.ethereum.MainnetBlockValidator.processBlock(MainnetBlockValidator.java:175)\n\tat org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(Mainn
etBlockValidator.java:112)\n\tat org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.validateBlock(MergeCoordinator.java:343)\n\tat org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.rememberBlock(MergeCoordinator.java:359)\n\tat org.hyperledger.besu.consensus.merge.blockcreation.TransitionCoordinator.rememberBlock(TransitionCoordinator.java:137)\n\tat org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.engine.EngineNewPayload.syncResponse(EngineNewPayload.java:215)\n\tat org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.lambda$response$0(ExecutionEngineJsonRpcMethod.java:73)\n\tat io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)\n\tat io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)\n\tat io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:157)\n\tat io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)\n\tat io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat java.base/java.lang.Thread.run(Thread.java:833)\nCaused by: org.rocksdb.RocksDBException: TimedOut(LockTimeout)\n\tat org.rocksdb.Transaction.put(Native Method)\n\tat org.rocksdb.Transaction.put(Transaction.java:705)\n\tat org.hyperledger.besu.plugin.services.storage.rocksdb.segmented.RocksDBColumnarKeyValueStorage$RocksDbTransaction.put(RocksDBColumnarKeyValueStorage.java:293)\n\t... 25 more\n"}
{"@timestamp":"2022-10-10T13:17:37,115","level":"ERROR","thread":"vert.x-worker-thread-0","class":"MainnetBlockValidator","message":"Error processing block. Block 13125902 (0x56128e3165fa54e3644b2de9493972741a029666f128b9b2595a0df47be61d5f), caused by Optional[org.hyperledger.besu.plugin.services.exception.StorageException: org.rocksdb.RocksDBException: TimedOut(LockTimeout)]","throwable":""}
{"@timestamp":"2022-10-10T13:17:37,178","level":"INFO","thread":"EthScheduler-Computation-535","class":"MergeCoordinator","message":"Successfully built block 13125902 (0x56128e3165fa54e3644b2de9493972741a029666f128b9b2595a0df47be61d5f) for proposal identified by 0x0035eb5652a22a90, with 5 transactions, in 1146ms","throwable":""}
{"@timestamp":"2022-10-10T13:17:40,024","level":"INFO","thread":"vert.x-worker-thread-0","class":"EngineForkchoiceUpdated","message":"VALID for fork-choice-update: head: 0x9abbfb6c82d7c0b9639333acd2d648205c12c16db0e304877ec765a822323803, finalized: 0x8ba9bc3f1eae2be2dd6f72d0fca0b92539a8d9df918f12c237a0270111aae8b3, safeBlockHash: 0xe6e2279003ab00660ab571b64dee3d82f8550078af727f0b29db0eb1134bc71c","throwable":""}
{"@timestamp":"2022-10-10T13:17:40,092","level":"INFO","thread":"EthScheduler-Computation-536","class":"MergeCoordinator","message":"Successfully built block 13125902 (0x8f679c1cc8e936bb60706a6437df2cc9492613e7f92a98f5036130c962c93580) for proposal identified by 0x0035eb5652a22a84, with 5 transactions, in 68ms","throwable":""}
{"@timestamp":"2022-10-10T13:17:48,028","level":"INFO","thread":"vert.x-worker-thread-0","class":"EngineGetPayload","message":"Fetch block proposal by identifier: 0x0035eb5652a22a84, hash: 0x8f679c1cc8e936bb60706a6437df2cc9492613e7f92a98f5036130c962c93580, number: 13125902, coinbase: 0x965b7a773e3632b259108d246a7cfdcdff118999, transaction count: 5","throwable":""}
{"@timestamp":"2022-10-10T13:17:48,057","level":"INFO","thread":"vert.x-worker-thread-0","class":"EngineNewPayload","message":"Imported #13,125,902 / 5 tx / base fee 7 wei / 346,036 (1.2%) gas / (0x8f679c1cc8e936bb60706a6437df2cc9492613e7f92a98f5036130c962c93580) in 0.004s. Peers: 25","throwable":""}
{"@timestamp":"2022-10-10T13:19:04,015","level":"INFO","thread":"vert.x-worker-thread-0","class":"EngineForkchoiceUpdated","message":"VALID for fork-choice-update: head: 0x8f679c1cc8e936bb60706a6437df2cc9492613e7f92a98f5036130c962c93580, finalized: 0x8ba9bc3f1eae2be2dd6f72d0fca0b92539a8d9df918f12c237a0270111aae8b3, safeBlockHash: 0xe6e2279003ab00660ab571b64dee3d82f8550078af727f0b29db0eb1134bc71c","throwable":""}
{"@timestamp":"2022-10-10T13:20:16,019","level":"INFO","thread":"vert.x-worker-thread-0","class":"EngineForkchoiceUpdated","message":"VALID for fork-choice-update: head: 0x8f679c1cc8e936bb60706a6437df2cc9492613e7f92a98f5036130c962c93580, finalized: 0x8ba9bc3f1eae2be2dd6f72d0fca0b92539a8d9df918f12c237a0270111aae8b3, safeBlockHash: 0xe6e2279003ab00660ab571b64dee3d82f8550078af727f0b29db0eb1134bc71c","throwable":""}
{"@timestamp":"2022-10-10T13:20:16,091","level":"INFO","thread":"EthScheduler-Computation-537","class":"MergeCoordinator","message":"Successfully built block 13125903 (0x3c93b52ee42013c33f3f8a2dfb4e9e7350dd3a099864a3ffdb284c1ca86f6b94) for proposal identified by 0x0035e5100fe7b1e8, with 3 transactions, in 72ms","throwable":""}

Initially Besu hit an error and correctly returned an error response (not invalid). Then Teku retried executing the block and got the incorrect INVALID response and from there it went off creating its own fork.
@jflo jflo self-assigned this Oct 10, 2022
@macfarla macfarla self-assigned this Oct 11, 2022
@macfarla
Copy link
Contributor

from the above logs I can't tell what the exception was the second time ie why besu is returning Invalid

spotted this TODO which may be related?

besu/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/EngineNewPayload.java

Line 222 in e179b86

// TODO; would prefer to invert the logic so we rpc error on anything that isn't a

does it make sense to only log one invalid block per minute? or do we need a different timing mechanism for this?
I don't see this Invalid new payload at all in the besu logs (and it was not started up within a minute of the issue) ->

besu/ethereum/api/src/main/java/org/hyperledger/besu/ethereum/api/jsonrpc/internal/methods/engine/EngineNewPayload.java

Line 261 in e179b86

if (lastInvalidWarn + ENGINE_API_LOGGING_THRESHOLD < System.currentTimeMillis()) {

@macfarla macfarla removed their assignment Oct 11, 2022
@jflo
Copy link
Contributor

jflo commented Oct 11, 2022

Yeah, agree with what Sally found. Even if we were suppressing invalid block messages to one per minute, we don't see any at all. I was going to add more logging on INVALID, but its already there.

@macfarla macfarla self-assigned this Oct 11, 2022
@macfarla
Copy link
Contributor

adjustment to logging #4520

@ajsutton
Copy link
Contributor Author

I'm pretty sure the problem is that Besu is failing to import on the first try because of an internal error and incorrectly adding the block to the bad block list. So when Teku retries it responds INVALID because it's already in the known bad block list. Why do I think this, because someone helpfully added a TODO that pointed out exactly how this is broken. :)

besu/ethereum/core/src/main/java/org/hyperledger/besu/ethereum/MainnetBlockValidator.java

Line 153 in 016016d

// TODO: if it's an internal error, don't add it 

    if (result.causedBy().isPresent()) {
      LOG.info("{}. Block {}, caused by {}", reason, invalidBlock.toLogString(), result.causedBy());
      // TODO: if it's an internal error, don't add it
      badBlockManager.addBadBlock(invalidBlock);
      return new Result(reason, result.causedBy().get());

@jflo jflo mentioned this issue Oct 12, 2022
Merged
2 tasks
@non-fungible-nelson
Copy link
Contributor

ROUGH To-Do lol

@ajsutton
Copy link
Contributor Author

Reopening this one. It's recurred with 22.7.7 on goerli:

{"@timestamp":"2022-10-21T08:08:14,250","level":"INFO","thread":"vert.x-worker-thread-0","class":"EngineNewPayload","message":"Imported #7,807,240 / 115 tx / base fee 52.74 gwei / 29,997,769 (100.0%) gas / (0xc8a33
0188690e6a0f8dc96e7980de612b152a9c944ee5155b44e928eaea286e4) in 0.643s. Peers: 25","throwable":""}
{"@timestamp":"2022-10-21T08:08:15,160","level":"INFO","thread":"EthScheduler-Computation-0","class":"MergeCoordinator","message":"Successfully built block 7807241 (0xc1fac2b70275bcde2cdea44086b53d376bdd1a213ca136d
34dacf752360b935a) for proposal identified by 0x002cea8de1f80288, with 40 transactions, in 748ms","throwable":""}
{"@timestamp":"2022-10-21T08:08:24,082","level":"INFO","thread":"vert.x-worker-thread-0","class":"EngineGetPayload","message":"Fetch block proposal by identifier: 0x002cea8de1f80288, hash: 0xc1fac2b70275bcde2cdea44
086b53d376bdd1a213ca136d34dacf752360b935a, number: 7807241, coinbase: 0x000095e79eac4d76aab57cb2c1f091d553b36ca0, transaction count: 40","throwable":""}
{"@timestamp":"2022-10-21T08:08:25,336","level":"ERROR","thread":"vert.x-worker-thread-0","class":"AbstractBlockProcessor","message":"failed persisting block","throwable":" org.hyperledger.besu.plugin.services.exce
ption.StorageException: org.rocksdb.RocksDBException: TimedOut(LockTimeout)\n\tat org.hyperledger.besu.plugin.services.storage.rocksdb.segmented.RocksDBColumnarKeyValueStorage$RocksDbTransaction.put(RocksDBColumnar
KeyValueStorage.java:299)\n\tat org.hyperledger.besu.plugin.services.storage.rocksdb.segmented.RocksDBColumnarKeyValueStorage$RocksDbTransaction.put(RocksDBColumnarKeyValueStorage.java:280)\n\tat org.hyperledger.be
su.services.kvstore.SegmentedKeyValueStorageTransactionTransitionValidatorDecorator.put(SegmentedKeyValueStorageTransactionTransitionValidatorDecorator.java:36)\n\tat org.hyperledger.besu.services.kvstore.Segmented
KeyValueStorageAdapter$1.put(SegmentedKeyValueStorageAdapter.java:80)\n\tat org.hyperledger.besu.ethereum.bonsai.BonsaiWorldStateKeyValueStorage$Updater.putStorageValueBySlotHash(BonsaiWorldStateKeyValueStorage.jav
a:362)\n\tat org.hyperledger.besu.ethereum.bonsai.BonsaiPersistedWorldState.calculateRootHash(BonsaiPersistedWorldState.java:171)\n\tat org.hyperledger.besu.ethereum.bonsai.BonsaiInMemoryWorldState.rootHash(BonsaiI
nMemoryWorldState.java:43)\n\tat org.hyperledger.besu.ethereum.bonsai.BonsaiInMemoryWorldState.persist(BonsaiInMemoryWorldState.java:53)\n\tat org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlo
ck(AbstractBlockProcessor.java:220)\n\tat org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:43)\n\tat org.hyperledger.besu.ethereum.mainnet.BlockProcessor.process
Block(BlockProcessor.java:92)\n\tat org.hyperledger.besu.ethereum.MainnetBlockValidator.processBlock(MainnetBlockValidator.java:175)\n\tat org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock
(MainnetBlockValidator.java:112)\n\tat org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.validateBlock(MergeCoordinator.java:343)\n\tat org.hyperledger.besu.consensus.merge.blockcreation.MergeCoor
dinator.rememberBlock(MergeCoordinator.java:359)\n\tat org.hyperledger.besu.consensus.merge.blockcreation.TransitionCoordinator.rememberBlock(TransitionCoordinator.java:137)\n\tat org.hyperledger.besu.ethereum.api.
jsonrpc.internal.methods.engine.EngineNewPayload.syncResponse(EngineNewPayload.java:220)\n\tat org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.lambda$response$0(ExecutionEngi
neJsonRpcMethod.java:73)\n\tat io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:159)\n\tat io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100)\n\tat io.vertx.core.impl.ContextImpl.lam
bda$executeBlocking$1(ContextImpl.java:157)\n\tat io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)\n\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)\n\tat java.base/
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)\n\tat io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)\n\tat java.base/java.lang.Thread.run(Threa
d.java:833)\nCaused by: org.rocksdb.RocksDBException: TimedOut(LockTimeout)\n\tat org.rocksdb.Transaction.put(Native Method)\n\tat org.rocksdb.Transaction.put(Transaction.java:705)\n\tat org.hyperledger.besu.plugin
.services.storage.rocksdb.segmented.RocksDBColumnarKeyValueStorage$RocksDbTransaction.put(RocksDBColumnarKeyValueStorage.java:293)\n\t... 25 more\n"}
{"@timestamp":"2022-10-21T08:08:25,339","level":"INFO","thread":"vert.x-worker-thread-0","class":"MainnetBlockValidator","message":"Error processing block. Block 7807241 (0xc1fac2b70275bcde2cdea44086b53d376bdd1a213
ca136d34dacf752360b935a), caused by Optional[org.hyperledger.besu.plugin.services.exception.StorageException: org.rocksdb.RocksDBException: TimedOut(LockTimeout)]","throwable":""}
{"@timestamp":"2022-10-21T08:08:25,764","level":"INFO","thread":"EthScheduler-Computation-0","class":"MergeCoordinator","message":"Successfully built block 7807241 (0x7de5c3b86efb25792b820d74a7d763fe685a4b8fa69e755
6c77b4b8c4fe91460) for proposal identified by 0x002cea8de1f8027c, with 75 transactions, in 1708ms","throwable":""}
{"@timestamp":"2022-10-21T08:08:26,482","level":"INFO","thread":"EthScheduler-Computation-0","class":"MergeCoordinator","message":"Successfully built block 7807241 (0xee31984909c687f92cc1cb9a376f8854331f3f61efad29c
8beeb2bc7fd91471a) for proposal identified by 0x002cea8de1f80288, with 87 transactions, in 2423ms","throwable":""}
{"@timestamp":"2022-10-21T08:08:27,354","level":"WARN","thread":"vert.x-worker-thread-0","class":"EngineNewPayload","message":"Invalid new payload: number: 7807241, hash: 0xc1fac2b70275bcde2cdea44086b53d376bdd1a213
ca136d34dacf752360b935a, parentHash: 0xc8a330188690e6a0f8dc96e7980de612b152a9c944ee5155b44e928eaea286e4, latestValidHash: 0x0000000000000000000000000000000000000000000000000000000000000000, status: INVALID, validat
ionError: Block already present in bad block manager.","throwable":""}
{"@timestamp":"2022-10-21T08:08:29,894","level":"INFO","thread":"EthScheduler-Computation-0","class":"MergeCoordinator","message":"Successfully built block 7807241 (0x0a887d2a7a9abf3acf9fff7ae91a695b257aece9da9e284
f5597fbe1f0c0b09f) for proposal identified by 0x002cea8de1f8027c, with 96 transactions, in 1859ms","throwable":""}
{"@timestamp":"2022-10-21T08:08:36,069","level":"INFO","thread":"vert.x-worker-thread-0","class":"EngineGetPayload","message":"Fetch block proposal by identifier: 0x002cea8de1f8027c, hash: 0x0a887d2a7a9abf3acf9fff7
ae91a695b257aece9da9e284f5597fbe1f0c0b09f, number: 7807241, coinbase: 0x000095e79eac4d76aab57cb2c1f091d553b36ca0, transaction count: 96","throwable":""}
{"@timestamp":"2022-10-21T08:08:36,627","level":"INFO","thread":"vert.x-worker-thread-0","class":"EngineNewPayload","message":"Imported #7,807,241 / 96 tx / base fee 59.33 gwei / 22,170,408 (73.9%) gas / (0x0a887d2
a7a9abf3acf9fff7ae91a695b257aece9da9e284f5597fbe1f0c0b09f) in 0.396s. Peers: 24","throwable":""}
{"@timestamp":"2022-10-21T08:09:16,031","level":"INFO","thread":"vert.x-worker-thread-0","class":"EngineForkchoiceUpdated","message":"VALID for fork-choice-update: head: 0x0a887d2a7a9abf3acf9fff7ae91a695b257aece9da
9e284f5597fbe1f0c0b09f, finalized: 0x143ece4e2b06ef971121488683728fda6c53ae0d3584ebdef6cbce02d93f9193, safeBlockHash: 0xb46cfb90dbb6f9c9ac36980e024c05f18402c7a551e3908ad10d6fb069b70dd1","throwable":""}
{"@timestamp":"2022-10-21T08:10:28,036","level":"INFO","thread":"vert.x-worker-thread-0","class":"EngineForkchoiceUpdated","message":"VALID for fork-choice-update: head: 0x0a887d2a7a9abf3acf9fff7ae91a695b257aece9da
9e284f5597fbe1f0c0b09f, finalized: 0x143ece4e2b06ef971121488683728fda6c53ae0d3584ebdef6cbce02d93f9193, safeBlockHash: 0xb46cfb90dbb6f9c9ac36980e024c05f18402c7a551e3908ad10d6fb069b70dd1","throwable":""}
{"@timestamp":"2022-10-21T08:11:40,035","level":"INFO","thread":"vert.x-worker-thread-0","class":"EngineForkchoiceUpdated","message":"VALID for fork-choice-update: head: 0x0a887d2a7a9abf3acf9fff7ae91a695b257aece9da
9e284f5597fbe1f0c0b09f, finalized: 0x143ece4e2b06ef971121488683728fda6c53ae0d3584ebdef6cbce02d93f9193, safeBlockHash: 0xb46cfb90dbb6f9c9ac36980e024c05f18402c7a551e3908ad10d6fb069b70dd1","throwable":""}

@ajsutton ajsutton reopened this Oct 21, 2022
@macfarla macfarla added the bug Something isn't working label Oct 21, 2022
@jflo
Copy link
Contributor

jflo commented Oct 22, 2022

Reformatted logging output.
4512logs_teku_repoened.json.zip

@jflo
Copy link
Contributor

jflo commented Oct 22, 2022

The block was being added to badblock manager due to an exception during validation, as opposed to execution.

besu/consensus/merge/src/main/java/org/hyperledger/besu/consensus/merge/blockcreation/MergeCoordinator.java

Line 350 in 33a0188

validationResult.errorMessage.ifPresent(errMsg -> addBadBlock(block));

The results classes are different, and are handled differently. Will reafactor to have execution results extend validation results, and handle them in one place.

@siladu
Copy link
Contributor

siladu commented Oct 31, 2022

Report from Sea Monkey https://discord.com/channels/905194001349627914/938504958909747250/1036727707293196359

All of my goerli-besu client pairs are hitting Invalid new payload at 7861134.
2022-10-31 15:44:39.978-04:00 | vert.x-worker-thread-0 | WARN | EngineNewPayload | Invalid new payload: number: 7861134, hash: 0x1dd53b7be3e97262011376c2f1e8da4535785270db6a46659d6e1670e83c53af, parentHash: 0x6cf6b9f42cb3d995cad4871645e8165039df13a684a3aa2b15d6dc3e456186e2, latestValidHash: 0x0000000000000000000000000000000000000000000000000000000000000000, status: INVALID, validationError: Block already present in bad block manager.

@jflo jflo closed this as completed Nov 14, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@jflo jflo

@macfarla macfarla

Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

don't add to bad blocks manager on StorageException jflo/besu
5 participants
@ajsutton @jflo @macfarla @siladu @non-fungible-nelson