Marking block as invalid because of temporary world state root mismatch

[daniellehrner]

Description

I happened already two time that my node has a temporary World State Root mismatch. Temporary, because once the CL has recovered after Besu has sent an erroneous invalid block message, the same block can be imported without any changes in the running Besu instance.

The config file:

data-path="/var/lib/besu"
engine-jwt-secret="/var/lib/jwtsecret/jwt.hex"
rpc-http-enabled=true
metrics-enabled=true
logging="INFO"
rpc-http-api=["ETH","NET","WEB3", "DEBUG"]
Xsnapsync-server-enabled=true
Xsnapsync-synchronizer-flat-db-healing-enabled=true
Xbonsai-trie-log-pruning-enabled=true
Xbonsai-code-using-code-hash-enabled=true
Xbonsai-parallel-tx-processing-enabled=true

The error message:

2024-10-30 12:52:25.114+00:00 | vert.x-worker-thread-0 | ERROR | AbstractBlockProcessor | failed persisting block
java.lang.RuntimeException: World State Root does not match expected value, header 0x0787bd3cdf97a5ac4bf602e2404a07adee62838abad8a8ba22e3d4d963944b54 calculated 0x7483bd3302935cd3cd9e10d1db634fc0a04174d9aea4c8c1e0b00e515ea611a3
        at org.hyperledger.besu.ethereum.trie.diffbased.common.worldview.DiffBasedWorldState.verifyWorldStateRoot(DiffBasedWorldState.java:226)
        at org.hyperledger.besu.ethereum.trie.diffbased.common.worldview.DiffBasedWorldState.persist(DiffBasedWorldState.java:184)
        at org.hyperledger.besu.ethereum.mainnet.AbstractBlockProcessor.processBlock(AbstractBlockProcessor.java:233)
        at org.hyperledger.besu.ethereum.mainnet.BlockProcessor.processBlock(BlockProcessor.java:78)
        at org.hyperledger.besu.ethereum.MainnetBlockValidator.processBlock(MainnetBlockValidator.java:247)
        at org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:164)
        at org.hyperledger.besu.ethereum.MainnetBlockValidator.validateAndProcessBlock(MainnetBlockValidator.java:108)
        at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.validateBlock(MergeCoordinator.java:557)
        at org.hyperledger.besu.consensus.merge.blockcreation.MergeCoordinator.rememberBlock(MergeCoordinator.java:587)
        at org.hyperledger.besu.consensus.merge.blockcreation.TransitionCoordinator.rememberBlock(TransitionCoordinator.java:157)
        at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.engine.AbstractEngineNewPayload.syncResponse(AbstractEngineNewPayload.java:374)
        at org.hyperledger.besu.ethereum.api.jsonrpc.internal.methods.ExecutionEngineJsonRpcMethod.lambda$response$0(ExecutionEngineJsonRpcMethod.java:90)
        at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:191)
        at io.vertx.core.impl.ContextInternal.dispatch(ContextInternal.java:279)
        at io.vertx.core.impl.ContextImpl.lambda$internalExecuteBlocking$2(ContextImpl.java:210)
        at io.vertx.core.impl.TaskQueue.run(TaskQueue.java:76)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.base/java.lang.Thread.run(Thread.java:1583)
2024-10-30 12:52:25.150+00:00 | vert.x-worker-thread-0 | INFO  | MainnetBlockValidator | Failed to process block 21078577 (0x22572bcd031b872c2f84ade258fa15dfd82deb3ad60e52bb5e83b02c35882974): Optional[World State Root does not match expected value, header 0x0787bd3cdf97a5ac4bf602e2404a07adee62838abad8a8ba22e3d4d963944b54 calculated 0x7483bd3302935cd3cd9e10d1db634fc0a04174d9aea4c8c1e0b00e515ea611a3], caused by java.lang.RuntimeException: World State Root does not match expected value, header 0x0787bd3cdf97a5ac4bf602e2404a07adee62838abad8a8ba22e3d4d963944b54 calculated 0x7483bd3302935cd3cd9e10d1db634fc0a04174d9aea4c8c1e0b00e515ea611a3
2024-10-30 12:52:25.153+00:00 | vert.x-worker-thread-0 | WARN  | AbstractEngineNewPayload | Invalid new payload: number: 21078577, hash: 0x22572bcd031b872c2f84ade258fa15dfd82deb3ad60e52bb5e83b02c35882974, parentHash: 0x6a24b47ea1288b302368281eb3134b19455e57a4083724561355e85275304689, latestValidHash: 0x6a24b47ea1288b302368281eb3134b19455e57a4083724561355e85275304689, status: INVALID, validationError: World State Root does not match expected value, header 0x0787bd3cdf97a5ac4bf602e2404a07adee62838abad8a8ba22e3d4d963944b54 calculated 0x7483bd3302935cd3cd9e10d1db634fc0a04174d9aea4c8c1e0b00e515ea611a3
2024-10-30 12:53:27.072+00:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineForkchoiceUpdated | VALID for fork-choice-update: head: 0x6a24b47ea1288b302368281eb3134b19455e57a4083724561355e85275304689, finalized: 0x284dc25665922634656360afbef4fc1bc4123844a37caa4d07cdc6eb2f3d4de9, safeBlockHash: 0x824fe222e9f33c744f0777443fd8d307a1884e841dc52386a89548ee6aa652f3

Frequency: Has happened 2 times in as many weeks.

[siladu]

@daniellehrner Have you seen this any more frequently? Which CL did you see it with? I suspect some CLs may not recover without a restart, which might make this a P2.

[kinsi55]

I've encountered the same issue (~2x in 2 Months), with Nimbus it does indeed not recover automatically.

2024-11-27 04:11:25.258+00:00 | vert.x-worker-thread-0 | ERROR | AbstractBlockProcessor | failed persisting block
java.lang.RuntimeException: World State Root does not match expected value, header 0x53c25a6330b5eae480447eaa78d79966bd8f2c8d6aad6acaf97b374ec6625fc0 calculated 0xef1970dca41727dbcbe15f9c42146e55fde410968b3c5d56df5dfb2330a3e2a4
[...]
2024-11-27 04:11:25.268+00:00 | vert.x-worker-thread-0 | INFO  | MainnetBlockValidator | Failed to process block 21276616 (0x9545fc70fcbf61d44921d27ad2d1964e13d3ffd600de0d31ce3f45bf648d3974): Optional[World State Root does not match expected value, header 0x5
3c25a6330b5eae480447eaa78d79966bd8f2c8d6aad6acaf97b374ec6625fc0 calculated 0xef1970dca41727dbcbe15f9c42146e55fde410968b3c5d56df5dfb2330a3e2a4], caused by java.lang.RuntimeException: World State Root does not match expected value, header 0x53c25a6330b5eae480447eaa78d79966
bd8f2c8d6aad6acaf97b374ec6625fc0 calculated 0xef1970dca41727dbcbe15f9c42146e55fde410968b3c5d56df5dfb2330a3e2a4
2024-11-27 04:11:25.269+00:00 | vert.x-worker-thread-0 | WARN  | AbstractEngineNewPayload | Invalid new payload: number: 21276616, hash: 0x9545fc70fcbf61d44921d27ad2d1964e13d3ffd600de0d31ce3f45bf648d3974, parentHash: 0x2e0b5deabbf4c819cd76fff58a8438e2a2269c74
f3f97206ec193f76d35278c4, latestValidHash: 0x2e0b5deabbf4c819cd76fff58a8438e2a2269c74f3f97206ec193f76d35278c4, status: INVALID, validationError: World State Root does not match expected value, header 0x53c25a6330b5eae480447eaa78d79966bd8f2c8d6aad6acaf97b374ec6625fc0 calc
ulated 0xef1970dca41727dbcbe15f9c42146e55fde410968b3c5d56df5dfb2330a3e2a

Notably after restarting, the first block that was imported is +1 of the one that was deemed invalid / where it broke

2024-11-27 05:00:03.060+00:00 | main | INFO  | Runner | Ethereum main loop is up.
2024-11-27 05:00:42.692+00:00 | vert.x-worker-thread-0 | INFO  | AbstractEngineNewPayload | Imported #21,276,617 / 613 tx / 16 ws / 0 blobs / base fee 5.70 gwei / 21,978,196 (73.3%) gas / (0x12cb2b909665ec7731de3a0ffeba784039c666e1d59a1c24d9453a76e7fc25e9) in 3.066s. Peers: 6
2024-11-27 05:00:46.170+00:00 | vert.x-worker-thread-0 | INFO  | TransactionPoolFactory | Node out of sync, disabling transaction handling
2024-11-27 05:01:52.309+00:00 | vert.x-worker-thread-0 | INFO  | BackwardSyncContext | Starting a new backward sync session
2024-11-27 05:01:52.494+00:00 | nioEventLoopGroup-3-4 | INFO  | BackwardSyncStep | Backward sync phase 1 of 2 completed, downloaded a total of 200 headers. Peers: 6
2024-11-27 05:01:55.483+00:00 | nioEventLoopGroup-3-4 | INFO  | BackwardSyncContext | Backward sync phase 2 of 2, 0.62% completed, imported 1 blocks of at least 162 (current head 21276618, target head 21276779). Peers: 6

Nothing special in my config really (Besides parallel processing ofc)

"--sync-mode=CHECKPOINT",
"--data-storage-format=BONSAI",
"--Xsnapsync-synchronizer-flat-db-healing-enabled=true",
"--Xbonsai-parallel-tx-processing-enabled=true",

[daniellehrner]

It didn't happen to me in a while, but I think the parallel tx processing is most likely the culprit here. The feature is still improved, but from time to time it marks valid blocks invalid. You could simple deactivate it until it not experimental anymore and we have hardened it enough that it isn't happening anymore.