besu icon indicating copy to clipboard operation
besu copied to clipboard

Published 20 hours ago • verified publisher icon hyperledger

Invalid block detected (BREACH_OF_PROTOCOL) | IBFT 2.0

Open avenbreaks opened this issue 11 months ago • 11 comments

Description

After the node stop and then tries to re-run it seems to get an invalid block detected error and then the peer disconnects. We build blockchain using besu for private networks.

Config

besu/bin/besu \
     --api-gas-price-max=1000000000000000 \
     --min-gas-price=1000000000 \
     --data-path=Node-1/data \
     --data-storage-format=BONSAI \
     --network-id=6666 \
     --rpc-http-enabled=true \
     --rpc-http-host=0.0.0.0 \
     --rpc-http-port=8545 \
     --rpc-http-cors-origins="*" \
     --rpc-http-api=NET,WEB3,ETH,IBFT,ENGINE,TXPOOL,TRACE \
     --rpc-http-authentication-jwt-algorithm=RS256 \
     --rpc-ws-enabled=true \
     --rpc-ws-api=NET,WEB3,ETH,IBFT,ENGINE,TXPOOL,TRACE \
     --rpc-ws-host=0.0.0.0 \
     --rpc-ws-port=8546 \
     --rpc-ws-max-active-connections=100 \
     --rpc-ws-max-frame-size=1048576 \
     --genesis-file=genesis.json \
     --host-allowlist="*" \
     --engine-rpc-enabled=true \
     --engine-host-allowlist="*" \
     --engine-jwt-secret=jwtsecret.hex \
     --engine-rpc-port=8551 \
     --node-private-key-file=/Node-1/data/key \
     --max-peers=4 \
     --Xp2p-peer-lower-bound=4 \
     --sync-mode=FULL \
     --p2p-enabled=true \
     --p2p-host=XXX.XXX.XXX.XXX \
     --p2p-port=30303 \
     --logging=INFO \
     --metrics-enabled=true \
     --metrics-host=0.0.0.0 \
     --metrics-port=9545 \
     --metrics-protocol=PROMETHEUS \
     --metrics-category=BLOCKCHAIN,ETHEREUM,EXECUTORS,NETWORK,PEERS,PERMISSIONING,PRUNER,RPC,SYNCHRONIZER,TRANSACTION_POOL,STRATUM,JVM,PROCESS

Logs (if a bug)

2024-03-05 02:05:41.425+00:00 | BftProcessorExecutor-IBFT-0 | ERROR | AbstractBlockProcessor | failed persisting block
org.hyperledger.besu.plugin.services.exception.StorageException: org.rocksdb.RocksDBException: Busy
	at org.hyperledger.besu.plugin.services.storage.rocksdb.RocksDBTransaction.commit(RocksDBTransaction.java:95)
	at org.hyperledger.besu.services.kvstore.SegmentedKeyValueStorageTransactionValidatorDecorator.commit(SegmentedKeyValueStorageTransactionValidatorDecorator.java:65)
	at org.hyperledger.besu.ethereum.bonsai.storage.BonsaiWorldStateKeyValueStorage$Updater.commit(BonsaiWorldStateKeyValueStorage.java:466)
	at org.hyperledger.besu.ethereum.bonsai.worldview.BonsaiWorldState.persist(BonsaiWorldState.java:432)
	at org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:194)
	at org.hyperledger.besu.ethereum.mainnet.BlockProcessor.processBlock(BlockProcessor.java:79)
	at org.hyperledger.besu.ethereum.MainnetBlockValidator.processBlock(MainnetBlockValidator.java:207)
	at org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:135)
	at org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:72)
	at org.hyperledger.besu.consensus.ibft.validation.MessageValidator.validateBlock(MessageValidator.java:97)
	at org.hyperledger.besu.consensus.ibft.validation.MessageValidator.validateProposal(MessageValidator.java:80)
	at org.hyperledger.besu.consensus.ibft.statemachine.RoundState.setProposedBlock(RoundState.java:88)
	at org.hyperledger.besu.consensus.ibft.statemachine.IbftRound.updateStateWithProposedBlock(IbftRound.java:228)
	at org.hyperledger.besu.consensus.ibft.statemachine.IbftRound.updateStateWithProposalAndTransmit(IbftRound.java:170)
	at org.hyperledger.besu.consensus.ibft.statemachine.IbftRound.createAndSendProposalMessage(IbftRound.java:123)
	at org.hyperledger.besu.consensus.ibft.statemachine.IbftBlockHeightManager.handleBlockTimerExpiry(IbftBlockHeightManager.java:127)
	at org.hyperledger.besu.consensus.common.bft.statemachine.BaseBftController.handleBlockTimerExpiry(BaseBftController.java:167)
	at org.hyperledger.besu.consensus.common.bft.EventMultiplexer.handleBftEvent(EventMultiplexer.java:65)
	at java.base/java.util.Optional.ifPresent(Optional.java:178)
	at org.hyperledger.besu.consensus.common.bft.BftProcessor.run(BftProcessor.java:65)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
	at java.base/java.lang.Thread.run(Thread.java:840)
Caused by: org.rocksdb.RocksDBException: Busy
	at org.rocksdb.Transaction.commit(Native Method)
	at org.rocksdb.Transaction.commit(Transaction.java:208)
	at org.hyperledger.besu.plugin.services.storage.rocksdb.RocksDBTransaction.commit(RocksDBTransaction.java:89)
	... 22 more
2024-03-05 02:05:41.428+00:00 | BftProcessorExecutor-IBFT-0 | INFO  | MainnetBlockValidator | Invalid block 2704803 (0x0743edf2e2fd0a61c11ff76cdc1dd82d09e675fc1c4c7c78235af506a2178d3b): Optional[org.rocksdb.RocksDBException: Busy], caused by org.hyperledger.besu.plugin.services.exception.StorageException: org.rocksdb.RocksDBException: Busy
2024-03-05 02:05:41.428+00:00 | BftProcessorExecutor-IBFT-0 | INFO  | MessageValidator | Invalid Proposal message, block did not pass validation. Reason Optional[org.rocksdb.RocksDBException: Busy]
2024-03-05 02:05:41.601+00:00 | BftProcessorExecutor-IBFT-0 | ERROR | AbstractBlockProcessor | failed persisting block

2024-03-05 02:05:41.602+00:00 | BftProcessorExecutor-IBFT-0 | INFO  | MainnetBlockValidator | Invalid block 2704878 (0xf8f7026f524b33db9bb0115c4053e5b3f4141de166617f6e51c6c5ff47731cc5): Optional[org.rocksdb.RocksDBException: Busy], caused by org.hyperledger.besu.plugin.services.exception.StorageException: org.rocksdb.RocksDBException: Busy
2024-03-05 02:05:41.602+00:00 | BftProcessorExecutor-IBFT-0 | INFO  | MessageValidator | Invalid Proposal message, block did not pass validation. Reason Optional[org.rocksdb.RocksDBException: Busy]
2024-03-05 02:05:41.663+00:00 | EthScheduler-Services-5 (importBlock) | INFO  | MainnetBlockValidator | Invalid block 2704921 (0x5758b561fa7b427883ed71e4975cbe72836fa21d52b6196f8262d048f86c51e8): Optional[Unable to process block because parent world state 0x964e562dbcd2113159cda36946fac806e5ef48e3f10a7289d3c34b84a6635501 is not available]
2024-03-05 02:05:41.666+00:00 | EthScheduler-Services-5 (importBlock) | INFO  | Pipeline | Unexpected exception in pipeline. Aborting.
org.hyperledger.besu.ethereum.eth.sync.tasks.exceptions.InvalidBlockException: Failed to import block: Invalid block at #2704921 (0x5758b561fa7b427883ed71e4975cbe72836fa21d52b6196f8262d048f86c51e8)


2024-03-05 02:05:41.668+00:00 | EthScheduler-Services-5 (importBlock) | WARN  | PipelineChainDownloader | Invalid block detected (BREACH_OF_PROTOCOL). Disconnecting from sync target. Failed to import block: Invalid block at #2704921 (0x5758b561fa7b427883ed71e4975cbe72836fa21d52b6196f8262d048f86c51e8)
2024-03-05 02:05:41.675+00:00 | EthScheduler-Services-5 (importBlock) | WARN  | PipelineChainDownloader | Chain download failed. Restarting after short delay.
java.util.concurrent.CompletionException: org.hyperledger.besu.ethereum.eth.sync.tasks.exceptions.InvalidBlockException: Failed to import block: Invalid block at #2704921 (0x5758b561fa7b427883ed71e4975cbe72836fa21d52b6196f8262d048f86c51e8)

avenbreaks avatar Mar 05 '24 02:03 avenbreaks

This looks like improper error handling in Besu. Need an exception for rocksDB exception (or wrap with storage exception). We do not have retry logic for a storage exception in IBFT, can be added in the block validator (we can mirror mainnet).

non-fungible-nelson avatar Mar 12 '24 15:03 non-fungible-nelson

Hi there @avenbreaks - can you provide your hardware specs here and machine configuration?

non-fungible-nelson avatar Mar 12 '24 15:03 non-fungible-nelson

There have been various issues & discussions about the RocksDBException: Busy errors:

  • https://github.com/hyperledger/besu/pull/5976
  • https://github.com/hyperledger/besu/pull/6004
  • https://discord.com/channels/905194001349627914/1204343645847687199/1205121949337133098

I'm not an expert on the DB layer in Besu but retrying operations seems to be the preferred way to resolve these. It would seem to make most sense for it to be handled down in the RocksDB layer so individual places in the codebase don't need to handle it themselves. However for now I've raised a draft PR to use retries for BFT block validation paths:

  • https://github.com/hyperledger/besu/pull/6715

I'll try running with it in the scenarios I've hit the Busy error to see if it resolves them. If anyone else is able to give it a try (@avenbreaks are you able to see if it resolves your errors?) that would help validate the fix.

matthew1001 avatar Mar 12 '24 16:03 matthew1001

Sorry @matthew1001, I erroneously tagged you. However, if you want to work on it with @daniellehrner, we can collaborate on discord !

non-fungible-nelson avatar Mar 12 '24 19:03 non-fungible-nelson

This looks like improper error handling in Besu. Need an exception for rocksDB exception (or wrap with storage exception). We do not have retry logic for a storage exception in IBFT, can be added in the block validator (we can mirror mainnet).

Hi, this is a private blockchain and I have tried to add a new validator but it only synchronizes the old block, to add a new block it does not work at all. for specifications

Digital Ocean VM
16GB RAM 
4 vCPU
1TB SSD

avenbreaks avatar Mar 12 '24 20:03 avenbreaks

Sorry @matthew1001, I erroneously tagged you. However, if you want to work on it with @daniellehrner, we can collaborate on discord !

No problem - it's something I've been involved in various chats about, so thought I might at least try to prove out a fix for another of the code paths. I'll leave my PR in draft for a while until I have time to test it for a longer period of time. I don't mind at all if someone else picks this issue up.

matthew1001 avatar Mar 13 '24 10:03 matthew1001

Good morning sir, its already solved?

avenbreaks avatar Mar 25 '24 23:03 avenbreaks

I faced same issues with QBFT, rollback to version 24.1.0, issue resolved.

sereyvathanatum avatar Mar 28 '24 03:03 sereyvathanatum

@daniellehrner - can we status this please?

non-fungible-nelson avatar Apr 15 '24 21:04 non-fungible-nelson

I was sidetracked by another issue. I have starting working on this one again.

daniellehrner avatar Apr 17 '24 12:04 daniellehrner

Facing similar Invalid block error here

Last week, I had an issue with Holesky running 24.3.0. I resynced and upgraded to 24.3.3, which fixed it until today, but now I am facing a similar error again

here are our logs

Apr 22 17:42:39 ethereum-holesky-02 besu[263501]: 2024-04-22 17:42:39.776+02:00 | vert.x-worker-thread-0 | ERROR | AbstractBlockProcessor | failed persisting block
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]: org.hyperledger.besu.plugin.services.exception.StorageException: org.rocksdb.RocksDBException: block checksum mismatch: stored = 2102455641, computed = 1576578973, type = 1  in /home/ethereum/var/lib/besu/database/012104.sst offset 8254017 size 32665
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at org.hyperledger.besu.plugin.services.storage.rocksdb.RocksDBTransaction.commit(RocksDBTransaction.java:95)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at org.hyperledger.besu.services.kvstore.SegmentedKeyValueStorageTransactionValidatorDecorator.commit(SegmentedKeyValueStorageTransactionValidatorDecorator.java:65)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at org.hyperledger.besu.services.kvstore.SegmentedKeyValueStorageAdapter$KeyValueStorageTransactionAdapter.commit(SegmentedKeyValueStorageAdapter.java:168)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at org.hyperledger.besu.ethereum.trie.bonsai.storage.BonsaiWorldStateKeyValueStorage$Updater.commit(BonsaiWorldStateKeyValueStorage.java:462)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at org.hyperledger.besu.ethereum.trie.bonsai.worldview.BonsaiWorldState.persist(BonsaiWorldState.java:460)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:209)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at org.hyperledger.besu.ethereum.mainnet.BlockProcessor.processBlock(BlockProcessor.java:79)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at org.hyperledger.besu.ethereum.MainnetBlockValidator.processBlock(MainnetBlockValidator.java:207)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:135)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:83)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.validateBlock(MergeCoordinator.java:551)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.rememberBlock(MergeCoordinator.java:581)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at org.hyperledger.besu.consensus.merge.blockcreation.TransitionCoordinator.rememberBlock(TransitionCoordinator.java:164)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.engine.AbstractEngineNewPayload.syncResponse(AbstractEngineNewPayload.java:319)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.lambda$response$0(ExecutionEngineJsonRpcMethod.java:90)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at io.vertx.core.impl.ContextBase.lambda$null$0(ContextBase.java:137)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:264)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at io.vertx.core.impl.ContextBase.lambda$executeBlocking$1(ContextBase.java:135)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at java.base/java.lang.Thread.run(Thread.java:840)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]: Caused by: org.rocksdb.RocksDBException: block checksum mismatch: stored = 2102455641, computed = 1576578973, type = 1  in /home/ethereum/var/lib/besu/database/012104.sst offset 8254017 size 32665
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at org.rocksdb.Transaction.commit(Native Method)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at org.rocksdb.Transaction.commit(Transaction.java:207)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         at org.hyperledger.besu.plugin.services.storage.rocksdb.RocksDBTransaction.commit(RocksDBTransaction.java:89)
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]:         ... 22 more
Apr 22 17:42:39 ethereum-holesky-02 besu[263501]: 2024-04-22 17:42:39.776+02:00 | vert.x-worker-thread-0 | INFO  | MainnetBlockValidator | Invalid block 1397638 (0xd81f964406264f7a7c4cfa0b9eef957aee1eae2e3499dfec35583038b443ad9b): Optional[org.rocksdb.RocksDBException] block checksum mismatch: stored = 2102455641, computed = 1576578973, type = 1  in /home/ethereum/var/lib/besu/database/012104.sst offset 8254017 size 32665], caused by org.hyperledger.besu.plugin.services.exception.StorageException: org.rocksdb.RocksDBException: block checksum mismatch: stored = 2102455641, computed = 1576578973, type = 1  in /home/ethereum/var/lib/besu/database/012104.sst offset 8254017 size 32665
Apr 22 17:42:45 ethereum-holesky-02 besu[263501]: 2024-04-22 17:42:45.041+02:00 | vert.x-worker-thread-0 | ERROR | AbstractBlockProcessor | failed persisting block
Apr 22 17:42:45 ethereum-holesky-02 besu[263501]: org.hyperledger.besu.plugin.services.exception.StorageException: org.rocksdb.RocksDBException: block checksum mismatch: stored = 2102455641, computed = 1576578973, type = 1  in /home/ethereum/var/lib/besu/database/012104.sst offset 8254017 size 32665

Server specs:

64Go RAM
6 CPU
1.9T NVME (1.7T free)

binary configuration:

besu \
  --network=holesky \
  --logging=INFO \
  --host-allowlist=localhost,127.0.0.1 \
  --metrics-enabled=true \
  --metrics-port=6061 \
  --metrics-host=0.0.0.0 \
  --rpc-http-enabled=true \
  --rpc-http-port=8545 \
  --rpc-ws-enabled=True \
  --rpc-ws-host=0.0.0.0 \
  --rpc-ws-port=8554 \
  --max-peers=10 \
  --sync-mode=X_CHECKPOINT \
  --data-storage-format=BONSAI \
  --data-path=/home/ethereum/var/lib/besu \
  --Xplugin-rocksdb-high-spec-enabled \
  --engine-jwt-secret=/home/ethereum/secrets/jwtsecret

jmc000 avatar Apr 22 '24 16:04 jmc000

@matthew1001 any workaround with this issue? we are facing this issue in our blockchain. image

ex-shubham-koli avatar May 08 '24 10:05 ex-shubham-koli

@avenbreaks were you able to resolve this issue?

ex-shubham-koli avatar May 08 '24 11:05 ex-shubham-koli