silkworm: wrong state root at block 21072002

[canepat]

Running standalone Silkworm at commit b0ce84b using Prism as Consensus Layer client, the Execution stage stumbled upon an invalid block failure due to wrong block gas error at block 21099525:

...
  INFO [12-31|20:44:03.457 UTC] PoSSync: new_payload block_hash=ac49f15fd77604e834dbb1949673b2351bd439f39d18049179f2d999951f2529 block_num: 21'495'630 <- reply SYNCING
  INFO [12-31|20:44:03.463 UTC] [5/13 Execution]                         block=21099525 blocks/s=36 txns/s=5645 Mgas/s=559
  INFO [12-31|20:44:03.628 UTC] PoSSync: fork_choice_update head_block_hash=ac49f15fd77604e834dbb1949673b2351bd439f39d18049179f2d999951f2529 safe_block_hash=5f7ee85f7be8e81187c7054d55dbd7e6780d54982f5ab0d306a3f237b8eaac7b finalized_block_hash=da920d7b9edcfa4aafe460bc665c30447f8d879e61744608839410bf60e4fde3
...
  INFO [12-31|20:44:16.124 UTC] Flushed state                            size=301.45 MB in=15.250s
  WARN [12-31|20:44:16.140 UTC] [5/13 Execution]                         block=21099525 hash=0xf47efd5411ae2c21430ff662155ee0bb8ba27b36083c44ff76d09bb93b50a4d0 error=kWrongBlockGas
  INFO [12-31|20:44:19.005 UTC] PoSSync: new_payload block_hash=765e667f093d766f98e38ff37e5dd1966b1e6ab252a1ae7a19328c83efbce96b block_num: 21'495'631 <- reply SYNCING
...
  INFO [12-31|20:44:19.968 UTC] PoSSync: fork_choice_update head_block_hash=ea20eb203c2be7ec82dc05e5be58dad3317801e3f85fda783cf1df3474a7b795 safe_block_hash=4e61981a8039d4b539da00e519b74a52f95ff8781811eb2d08b2c41a69f47498 finalized_block_hash=765e667f093d766f98e38ff37e5dd1966b1e6ab252a1ae7a19328c83efbce96b
  INFO [12-31|20:44:20.099 UTC] [5/13 Execution] commit                  batch time=3.917s
 ERROR [12-31|20:44:20.109 UTC] [5/13 Execution]                         op=Forward failure=kInvalidBlock
  INFO [12-31|20:44:20.109 UTC] MainChain::verify_chain forward_result=kInvalidBlock
  INFO [12-31|20:44:20.109 UTC] MainChain::collect_bad_headers bad_count=387'643 skip=1

The last known valid state can be found looking at the block span applied by the last staged sync or reading the progress of stages from the database. It turned out that the last valid state root was computed at block 21049761.

Applying the bisect command in staged_pipeline utility:

./cmd/dev/staged_pipeline --datadir ~/.local/share/silkworm/ bisect --from 21049762 --to 21099524

you get the first block that breaks the state root computation:

...
  INFO [01-04|02:05:40.140 UTC] [7/13 IntermediateHashes]                op=kForward mode=full op=building merkle tree key=0xfd05c9fee26045c766...
  INFO [01-04|02:06:10.140 UTC] [7/13 IntermediateHashes]                op=kForward mode=full op=building merkle tree key=0xfdf580df66b644757f...
 ERROR [01-04|02:06:28.379 UTC] [7/13 IntermediateHashes]                function=regenerate_intermediate_hashes exception=expected 0x0cc0db0367272cf732cadbf7ff0975e06679b6d91cc45c08e5479073ea9520a2 got 0xbd02257d7e054c423bac16885ffca857dcb22ba6c18c572061c25f5ed5a6cbfb
 ERROR [01-04|02:06:28.379 UTC] [7/13 IntermediateHashes]                function=forward exception=kWrongStateRoot
 ERROR [01-04|02:06:28.379 UTC] [7/13 IntermediateHashes]                op=Forward failure=kWrongStateRoot
  INFO [01-04|02:06:28.379 UTC] Bisect: forward from=21'072'001 to=21'072'002 END
  INFO [01-04|02:06:28.379 UTC] Bisect: left=21'072'001 median=21'072'001 unwind=21'072'001
  INFO [01-04|02:06:28.379 UTC] Bisect: unwind down to block=21'072'001 START
  INFO [01-04|02:06:28.379 UTC] ExecutionPipeline                        Unwind start
  INFO [01-04|02:06:28.379 UTC] [7/13 HashState]                         op=kUnwind from=21072002 to=21072001 span=1
  INFO [01-04|02:06:28.381 UTC] [9/13 Execution]                         op=kUnwind from=21072002 to=21072001 span=1
  INFO [01-04|02:06:28.382 UTC] Erased 2 records from AccountChangeSet
  INFO [01-04|02:06:28.382 UTC] Erased 2 records from StorageChangeSet
  INFO [01-04|02:06:28.382 UTC] Erased 1 records from Receipt
  INFO [01-04|02:06:28.382 UTC] Erased 0 records from TransactionLog
  INFO [01-04|02:06:28.382 UTC] Erased 3 records from CallTraceSet
  INFO [01-04|02:06:28.383 UTC] [10/13 Senders]                          op=kUnwind from=21072002 to=21072001 span=1
  INFO [01-04|02:06:28.383 UTC] [11/13 Bodies]                           op=kUnwind from=21072002 to=21072001 span=1
  INFO [01-04|02:06:28.383 UTC] [12/13 BlockHashes]                      op=kUnwind from=21072002 to=21072001 span=1
  INFO [01-04|02:06:28.383 UTC] [13/13 Headers]                          op=kUnwind from=21072002 to=21072001 span=1
  INFO [01-04|02:06:28.384 UTC] ExecutionPipeline                        Unwind done
  INFO [01-04|02:06:28.384 UTC] Bisect: unwind down to block=21'072'001 END
  INFO [01-04|02:06:28.384 UTC] Bisect: failed at block=21'072'002

Using the blocks command in db_toolbox to inspect such a block saved on the database:

./cmd/dev/db_toolbox --datadir ~/.local/share/silkworm/ blocks --from 21072002 --to 21072002

this is what you get:

Block number=21072002

Header:
hash=2b94af10b95520e5dae83d8e7bc7bf62c55f1a66fa0d7032d7a7e3f963a4b21d
parent_hash=e0a4eac8dd2fe1271a8a7d4eab99dfe456e97c63904c3d26d74de0bce6929d3f
number=21072002
beneficiary=0xafedf06777839d59eed3163cc3e0a5057b514399
ommers_hash=1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347
state_root=0cc0db0367272cf732cadbf7ff0975e06679b6d91cc45c08e5479073ea9520a2
transactions_root=56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421
receipts_root=56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421
withdrawals_root=c18745982077dc6d0ad193a0142a55f5239d7c4f757a6b9bfaad89fcfa02886a
beneficiary=0xafedf06777839d59eed3163cc3e0a5057b514399
timestamp=1730213483
nonce=0000000000000000
prev_randao=d99996d768137199d2e7df9b78ca5523e688fdc43b3a0a9cfd2478ca243b052f
base_fee_per_gas=12867580497
difficulty=0
gas_limit=30000000
gas_used=0
blob_gas_used=0
excess_blob_gas=78643200
logs_bloom=00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
extra_data=d883010d0c846765746888676f312e32312e36856c696e7578
rlp=f90260a0e0a4eac8dd2fe1271a8a7d4eab99dfe456e97c63904c3d26d74de0bce6929d3fa01dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d4934794afedf06777839d59eed3163cc3e0a5057b514399a00cc0db0367272cf732cadbf7ff0975e06679b6d91cc45c08e5479073ea9520a2a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421b90100000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000008084014188828401c9c38080846720f66b99d883010d0c846765746888676f312e32312e36856c696e7578a0d99996d768137199d2e7df9b78ca5523e688fdc43b3a0a9cfd2478ca243b052f8800000000000000008502fef7b251a0c18745982077dc6d0ad193a0142a55f5239d7c4f757a6b9bfaad89fcfa02886a808404b00000a045269c7f581f0bcbdb33f1209a82545194134960c55ccb5286fffa31219f36aa

Body:
base_txn_id=2602809979
txn_count=2
#ommers=0
#withdrawals=16
rlp=f9024a849b23ba7b02c0f90240e38403d933eb830d7ae894b9d7934878b5fb9610b3fe8a5e441e8fad7e293f840127a3f1e38403d933ec830d7ae994b9d7934878b5fb9610b3fe8a5e441e8fad7e293f840126fa82e38403d933ed830d7aea94b9d7934878b5fb9610b3fe8a5e441e8fad7e293f84012650fee38403d933ee830d7aeb94b9d7934878b5fb9610b3fe8a5e441e8fad7e293f840126192ce38403d933ef830d7aec94b9d7934878b5fb9610b3fe8a5e441e8fad7e293f840124ce1fe38403d933f0830d7aed94b9d7934878b5fb9610b3fe8a5e441e8fad7e293f840125293ce38403d933f1830d7aee94b9d7934878b5fb9610b3fe8a5e441e8fad7e293f840127ac27e38403d933f2830d7aef94b9d7934878b5fb9610b3fe8a5e441e8fad7e293f840128315ee38403d933f3830d7af094b9d7934878b5fb9610b3fe8a5e441e8fad7e293f8401280443e38403d933f4830d7af194b9d7934878b5fb9610b3fe8a5e441e8fad7e293f840127e8bae38403d933f5830d7af294b9d7934878b5fb9610b3fe8a5e441e8fad7e293f840126e7aee38403d933f6830d7af394b9d7934878b5fb9610b3fe8a5e441e8fad7e293f84012762d0e38403d933f7830d7af494b9d7934878b5fb9610b3fe8a5e441e8fad7e293f8401271437e38403d933f8830d7af594b9d7934878b5fb9610b3fe8a5e441e8fad7e293f840126aa33e38403d933f9830d7af694b9d7934878b5fb9610b3fe8a5e441e8fad7e293f840127809ae38403d933fa830d7af794b9d7934878b5fb9610b3fe8a5e441e8fad7e293f840127eb60

This output reveals that the saved copy of block 21072002 is invalid because computing the withdrawals root from the withdrawals data you get a mismatch. Moreover, if you decode the RLP storage-encoded data for the body and print the content of the the withdrawals you get:

w[0].address=b9d7934878b5fb9610b3fe8a5e441e8fad7e293f
w[0].index=64566251
w[0].validator_index=883432
w[0].amount=19375089
w[1].address=b9d7934878b5fb9610b3fe8a5e441e8fad7e293f
w[1].index=64566252
w[1].validator_index=883433
w[1].amount=19331714
w[2].address=b9d7934878b5fb9610b3fe8a5e441e8fad7e293f
w[2].index=64566253
w[2].validator_index=883434
w[2].amount=19288318
w[3].address=b9d7934878b5fb9610b3fe8a5e441e8fad7e293f
w[3].index=64566254
w[3].validator_index=883435
w[3].amount=19274028
w[4].address=b9d7934878b5fb9610b3fe8a5e441e8fad7e293f
w[4].index=64566255
w[4].validator_index=883436
w[4].amount=19189279
w[5].address=b9d7934878b5fb9610b3fe8a5e441e8fad7e293f
w[5].index=64566256
w[5].validator_index=883437
w[5].amount=19212604
w[6].address=b9d7934878b5fb9610b3fe8a5e441e8fad7e293f
w[6].index=64566257
w[6].validator_index=883438
w[6].amount=19377191
w[7].address=b9d7934878b5fb9610b3fe8a5e441e8fad7e293f
w[7].index=64566258
w[7].validator_index=883439
w[7].amount=19411294
w[8].address=b9d7934878b5fb9610b3fe8a5e441e8fad7e293f
w[8].index=64566259
w[8].validator_index=883440
w[8].amount=19399747
w[9].address=b9d7934878b5fb9610b3fe8a5e441e8fad7e293f
w[9].index=64566260
w[9].validator_index=883441
w[9].amount=19392698
w[10].address=b9d7934878b5fb9610b3fe8a5e441e8fad7e293f
w[10].index=64566261
w[10].validator_index=883442
w[10].amount=19326894
w[11].address=b9d7934878b5fb9610b3fe8a5e441e8fad7e293f
w[11].index=64566262
w[11].validator_index=883443
w[11].amount=19358416
w[12].address=b9d7934878b5fb9610b3fe8a5e441e8fad7e293f
w[12].index=64566263
w[12].validator_index=883444
w[12].amount=19338295
w[13].address=b9d7934878b5fb9610b3fe8a5e441e8fad7e293f
w[13].index=64566264
w[13].validator_index=883445
w[13].amount=19311155
w[14].address=b9d7934878b5fb9610b3fe8a5e441e8fad7e293f
w[14].index=64566265
w[14].validator_index=883446
w[14].amount=19366042
w[15].address=b9d7934878b5fb9610b3fe8a5e441e8fad7e293f
w[15].index=64566266
w[15].validator_index=883447
w[15].amount=19393376

Surprisingly or not, this shows that the invalid content of the withdrawals is indeed well-formed and you can even deduce from the validator_index values that these withdrawals are indeed the ones from block 21070352, which is kind of weird.