Recover geth and story clients when geth client is upgraded after the upgrade height

[limengformal]

Description and context

In the event of a geth hard fork upgrade, if a node is not upgraded after the upgrade block height, the story client may panic since it may not reach consensus with the rest of the nodes that already have their geth clients upgraded.

Only upgrading the geth client at this point doesn't help since the story client already verified/proposed a block that is in conflict. Node at this point can only remove data folder and sync from genesis block which takes a long time.

Suggested solution

One suggested solution is to roll back the block with incorrect proposal so the node can sync the correct block.

Definition of done

Node can roll back incorrect block and restart with correct block in the event of a late geth upgrade.

[limengformal]

How to reproduce:

• versions
  • before upgrade: story client version / geth version
    • story: v0.10.0
    • geth: v0.9.2
  • after upgrade, normal node: story client version / geth version
    • story: v0.10.0
    • geth: v0.9.3
  • after upgrade, not-upgrading node: story client version / geth version
    • story: v0.10.0
    • geth: v0.9.2
• upgrade procedure
  • Before the upgrade height (you may specify height by using --override.nostoi ${BLOCK_NUMBER})
  • Stop story
  • Stop old geth
  • Start new geth with upgrade height by using --override.nostoi ${BLOCK_NUMBER}
  • Start story
• Trigger the issue
  • Leave some nodes not upgraded to geth v0.9.3 after specified ${BLOCK_NUMBER}
  • Send a tx to call EIP-7212 precompile as follows:

Install Cast (if not installed yet):

curl -L https://foundry.paradigm.xyz/ | bash
source /home/ec2-user/.zshenv
foundryup

cast call 0x0000000000000000000000000000000000000100  "0x4cee90eb86eaa050036147a12d49004b6b9c72bd725d39d4785011fe190f0b4da73bd4903f0ce3b639bbbf6e8e80d16931ff4bcf5993d58468e8fb19086e8cac36dbcd03009df8c59286b162af3bd7fcc0450c9aa81be5d10d312af6c66b1d604aebd3099c618202fcfe16ae7770b0c49ab5eadf74b754204a3bb6060e44eff37618b065f9832de4ca6ca971a7a1adc826d0f7c00181a5fb2ddf79ae00b4e10e" --rpc-url <node url to 8545 port, e.g. http://localhost:8545/>

[zsystm]

@limengformal
I have successfully reproduced the stuck scenario.

• Note: Nodes N0 through N4 have equal voting power.
  

Currently, I'm working on integrating the CometBFT rollback command into the Story codebase to test if this rollback feature can resolve the issue.

• Since the Story codebase has some differences from a standard Cosmos SDK chain, I'm unable to directly apply the existing rollback command.
• Integration is working on in zsystm/rollback branch

geth logs at stuck

INFO [10-01|10:48:13.945] Starting work on payload                 id=0x0386ee442fe919a1
INFO [10-01|10:48:13.945] Updated payload                          id=0x0386ee442fe919a1 number=51 hash=5c4047..d3232d txs=0 withdrawals=0 gas=0 fees=0 root=11c9c2..f205fb elapsed="181.167µs"
INFO [10-01|10:48:14.546] Stopping work on payload                 id=0x0386ee442fe919a1 reason=delivery
INFO [10-01|10:48:14.567] newPayload                               hash=5c4047..d3232d parentHash=e65703..a5b4ff number=51
INFO [10-01|10:48:14.571] Imported new potential chain segment     number=51 hash=5c4047..d3232d blocks=1 txs=0 mgas=0.000 elapsed=4.595ms     mgasps=0.000  snapdiffs=4.76KiB triediffs=46.78KiB triedirty=0.00B
WARN [10-01|10:48:14.899] Ignoring already known beacon payload    number=51 hash=5c4047..d3232d age=2s
INFO [10-01|10:48:14.913] Chain head was updated                   number=51 hash=5c4047..d3232d root=11c9c2..f205fb elapsed=13.492583ms
INFO [10-01|10:48:16.596] newPayload                               hash=db88bc..1fcecd parentHash=5c4047..d3232d number=52
INFO [10-01|10:48:16.604] Imported new potential chain segment     number=52 hash=db88bc..1fcecd blocks=1 txs=0 mgas=0.000 elapsed=7.734ms     mgasps=0.000  snapdiffs=4.94KiB triediffs=48.54KiB triedirty=0.00B
WARN [10-01|10:48:16.920] Ignoring already known beacon payload    number=52 hash=db88bc..1fcecd age=2s
INFO [10-01|10:48:16.936] Chain head was updated                   number=52 hash=db88bc..1fcecd root=13bac8..e530b4 elapsed=15.623125ms
INFO [10-01|10:48:18.631] newPayload                               hash=7ed2d6..283377 parentHash=db88bc..1fcecd number=53
WARN [10-01|10:48:18.631] Failed to load old bad blocks            error="pebble: not found"
ERROR[10-01|10:48:18.641]
########## BAD BLOCK #########
Block: 53 (0x7ed2d670db226de90dca3f3b707ac530626360b499390158b8612800b8283377)
Error: invalid gas used (remote: 31469 local: 30450)
Platform: geth (devel) go1.21.6 arm64 darwin
VCS: 34869b5f-20240926
Chain config: &params.ChainConfig{ChainID:2513, HomesteadBlock:0, DAOForkBlock:<nil>, DAOForkSupport:false, EIP150Block:0, EIP155Block:0, EIP158Block:0, ByzantiumBlock:0, ConstantinopleBlock:0, PetersburgBlock:0, IstanbulBlock:0, MuirGlacierBlock:<nil>, BerlinBlock:0, LondonBlock:0, ArrowGlacierBlock:0, GrayGlacierBlock:0, MergeNetsplitBlock:<nil>, ShanghaiTime:(*uint64)(0x14000814be0), CancunTime:(*uint64)(0x14000814be8), PragueTime:(*uint64)(nil), VerkleTime:(*uint64)(nil), TerminalTotalDifficulty:0, TerminalTotalDifficultyPassed:true, Ethash:(*params.EthashConfig)(nil), Clique:(*params.CliqueConfig)(nil)}
Receipts:
  0: cumulative: 30450 gas: 30450 contract: 0x0000000000000000000000000000000000000000 status: 1 tx: 0x68717093b59520656f315cb734182f486dad1e1a33bb194ed40c849ee42ba812 logs: [] bloom: 00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000 state:
##############################

WARN [10-01|10:48:18.641] NewPayloadV1: inserting block failed     error="invalid gas used (remote: 31469 local: 30450)"

story logs at stuck

24-10-01 10:48:12.612 INFO 👾 ABCI call: ProcessProposal            height=51 proposer=cda29a3
24-10-01 10:48:12.741 INFO 👾 ABCI call: ExtendVote                 height=51
24-10-01 10:48:12.839 INFO 👾 ABCI call: VerifyVoteExtension        height=51
24-10-01 10:48:12.937 INFO 👾 ABCI call: VerifyVoteExtension        height=51
24-10-01 10:48:12.937 INFO 👾 ABCI call: VerifyVoteExtension        height=51
24-10-01 10:48:12.975 INFO 👾 ABCI response: FinalizeBlock          val_updates=0 height=51
24-10-01 10:48:12.984 INFO 👾 ABCI call: Commit
24-10-01 10:48:13.937 INFO 👾 ABCI call: PrepareProposal            height=52 proposer=e4eb3df
24-10-01 10:48:13.937 INFO Submit new EVM payload                   timestamp="2024-10-01 01:48:12.7474 +0000 UTC" withdrawals=0 app_hash=0xb57fbe684ecd70a98091c31d9068bf5afa939672d9bac4de11fd736a82ea2ab4
24-10-01 10:48:14.547 INFO Proposing new block                      height=52 execution_block_hash=5c40471 evm_events=0
24-10-01 10:48:14.566 INFO 👾 ABCI call: ProcessProposal            height=52 proposer=e4eb3df
24-10-01 10:48:14.794 INFO 👾 ABCI call: ExtendVote                 height=52
24-10-01 10:48:14.877 INFO 👾 ABCI call: VerifyVoteExtension        height=52
24-10-01 10:48:14.878 INFO 👾 ABCI call: VerifyVoteExtension        height=52
24-10-01 10:48:14.929 INFO 👾 ABCI response: FinalizeBlock          val_updates=0 height=52
24-10-01 10:48:14.948 INFO 👾 ABCI call: Commit
24-10-01 10:48:16.595 INFO 👾 ABCI call: ProcessProposal            height=53 proposer=25fabef
24-10-01 10:48:16.726 INFO 👾 ABCI call: ExtendVote                 height=53
24-10-01 10:48:16.815 INFO 👾 ABCI call: VerifyVoteExtension        height=53
24-10-01 10:48:16.910 INFO 👾 ABCI call: VerifyVoteExtension        height=53
24-10-01 10:48:16.953 INFO 👾 ABCI response: FinalizeBlock          val_updates=0 height=53
24-10-01 10:48:16.973 INFO 👾 ABCI call: Commit
24-10-01 10:48:18.630 INFO 👾 ABCI call: ProcessProposal            height=54 proposer=c8eb2bd
24-10-01 10:48:18.641 ERRO Rejecting process proposal               err="execute message: invalid payload, rejecting proposal: payload invalid" validation_err="invalid gas used (remote: 31469 local: 30450)" last_valid_hash=0xdb88bcfe79e898ca12ccc7c282d064a1c7b37038fff90e833b1a81fe951fcecd stacktrace="[errors.go:14 msg_server.go:204 proposal_server.go:40 helpers.go:22 proposal_server.go:32 tx.pb.go:290 msg_service_router.go:175 tx.pb.go:292 msg_service_router.go:198 prouter.go:74 abci.go:520 cmt_abci.go:40 abci.go:85 local_client.go:164 app_conn.go:89 execution.go:166 state.go:1381 state.go:1338 state.go:2055 state.go:910 state.go:836 asm_arm64.s:1223]"
24-10-01 10:48:18.641 ERRO prevote step: state machine rejected a proposed block; this should not happen:the proposer may be misbehaving; prevoting nil module=consensus height=54 round=0 err=<nil>
24-10-01 10:48:18.944 INFO 👾 ABCI call: ExtendVote                 height=54
24-10-01 10:48:18.954 INFO 👾 ABCI call: VerifyVoteExtension        height=54
24-10-01 10:48:19.051 INFO 👾 ABCI call: VerifyVoteExtension        height=54
24-10-01 10:48:19.084 ERRO Processing finalized payload failed; payload invalid [BUG] err="payload invalid" validation_err="links to previously rejected block" last_valid_hash=0xdb88bcfe79e898ca12ccc7c282d064a1c7b37038fff90e833b1a81fe951fcecd stacktrace="[errors.go:14 msg_server.go:204 msg_server.go:63 helpers.go:22 msg_server.go:55 tx.pb.go:290 msg_service_router.go:175 tx.pb.go:292 msg_service_router.go:198 baseapp.go:1015 baseapp.go:953 baseapp.go:762 abci.go:790 abci.go:884 cmt_abci.go:44 abci.go:95 local_client.go:185 app_conn.go:104 execution.go:224 execution.go:202 state.go:1772 state.go:1682 state.go:1617 state.go:1655 state.go:2335 state.go:2067 state.go:929 state.go:836 asm_arm64.s:1223]"
24-10-01 10:48:19.084 INFO 👾 ABCI response: FinalizeBlock          val_updates=0 height=54
24-10-01 10:48:19.085 ERRO FinalizeBlock contains unexpected failed transaction [BUG] info="" code=1 log="failed to execute message; message index: 0: payload invalid" code_space=undefined index=0 height=54
24-10-01 10:48:19.095 INFO 👾 ABCI call: Commit
24-10-01 10:48:20.749 ERRO prevote step: consensus deems this block invalid; prevoting nil module=consensus height=55 round=0 err="wrong Block.Header.AppHash.  Expected 92019BBA0AB4CDF329F2D52D7763C8FC5C2387D88982B2714541A84DFA4C0977, got 052D3982DBA6D23422FD4CDA5DD5B6B0C5A186B02BED645B0BEBAD65D1F3A4F0"
24-10-01 10:48:20.876 ERRO CONSENSUS FAILURE!!!                     module=consensus err="precommit step; +2/3 prevoted for an invalid block: wrong Block.Header.AppHash.  Expected 92019BBA0AB4CDF329F2D52D7763C8FC5C2387D88982B2714541A84DFA4C0977, got 052D3982DBA6D23422FD4CDA5DD5B6B0C5A186B02BED645B0BEBAD65D1F3A4F0"
  stack=
  │ goroutine 189 [running]:
  │ runtime/debug.Stack()
  │ \t/Users/denver/.gvm/pkgsets/go1.22.4/global/pkg/mod/golang.org/[email protected]/src/runtime/debug/stack.go:26 +0x64
  │ github.com/cometbft/cometbft/consensus.(*State).receiveRoutine.func2()
  │ \t/Users/denver/.gvm/pkgsets/go1.21/global/pkg/mod/github.com/cometbft/[email protected]/consensus/state.go:801 +0x44
  │ panic({0x106ca36e0?, 0x140010c0cd0?})
  │ \t/Users/denver/.gvm/pkgsets/go1.22.4/global/pkg/mod/golang.org/[email protected]/src/runtime/panic.go:785 +0x124
  │ github.com/cometbft/cometbft/consensus.(*State).enterPrecommit(0x14000c6b188, 0x37, 0x0)
  │ \t/Users/denver/.gvm/pkgsets/go1.21/global/pkg/mod/github.com/cometbft/[email protected]/consensus/state.go:1526 +0x1300
  │ github.com/cometbft/cometbft/consensus.(*State).addVote(0x14000c6b188, 0x140015c5e10, {0x1400123a210, 0x28})
  │ \t/Users/denver/.gvm/pkgsets/go1.21/global/pkg/mod/github.com/cometbft/[email protected]/consensus/state.go:2307 +0x1494
  │ github.com/cometbft/cometbft/consensus.(*State).tryAddVote(0x14000c6b188, 0x140015c5e10, {0x1400123a210?, 0x1054c4a84?})
  │ \t/Users/denver/.gvm/pkgsets/go1.21/global/pkg/mod/github.com/cometbft/[email protected]/consensus/state.go:2067 +0x28
  │ github.com/cometbft/cometbft/consensus.(*State).handleMsg(0x14000c6b188, {{0x10724c320, 0x140001b5028}, {0x1400123a210, 0x28}})
  │ \t/Users/denver/.gvm/pkgsets/go1.21/global/pkg/mod/github.com/cometbft/[email protected]/consensus/state.go:929 +0x2fc
  │ github.com/cometbft/cometbft/consensus.(*State).receiveRoutine(0x14000c6b188, 0x0)
  │ \t/Users/denver/.gvm/pkgsets/go1.21/global/pkg/mod/github.com/cometbft/[email protected]/consensus/state.go:836 +0x2b8
  │ created by github.com/cometbft/cometbft/consensus.(*State).OnStart in goroutine 122
  │ \t/Users/denver/.gvm/pkgsets/go1.21/global/pkg/mod/github.com/cometbft/[email protected]/consensus/state.go:398 +0xf0

Note: Geth did not insert the invalid block, so it remains at the last valid block. This means that once the app hash issue in the story is resolved and re-executed, the chain would function correctly again.

[zsystm]

@limengformal
The rollback command has been successfully integrated (#157) and is functioning as expected! Below is a brief summary of the steps taken, along with a video demonstration showing it in action.

rollback-test.mp4

Video Explanation

Background Info

1. The terminal sessions on the left represent Geth sessions, listed from top to bottom as N0, N1, N2, and N3. Note that N1 has not been upgraded and is currently using version story-geth-v0.9.2.
2. The terminal sessions on the right represent Story sessions, also listed from top to bottom as N0, N1, N2, and N3.

Stuck Resolution Flow in the Video

1. N1, which has not been upgraded, has a different app hash from the other nodes, causing it to get stuck and preventing further block progress. Meanwhile, the blocks on N0, N2, and N3 are continuing to increase without issues.
2. To resolve the stuck issue on N1, I attempted a rollback on the story client for N1 using the command: ./story rollback --home val1 --hard.
3. The message Rolled back state to ... confirms that a rollback of one block was successfully performed.
4. After the rollback, I upgraded N1’s Geth from version v0.9.2 to v0.9.3 and restarted it.
5. I also restarted the story client for N1.
6. As seen in the second terminal sessions, the stuck issue is resolved, and N1 successfully syncs to the latest block.

[zsystm]

@limengformal I have successfully reproduced the stuck scenario.

• Note: Nodes N0 through N4 have equal voting power.
  

Currently, I'm working on integrating the CometBFT rollback command into the Story codebase to test if this rollback feature can resolve the issue.

• Since the Story codebase has some differences from a standard Cosmos SDK chain, I'm unable to directly apply the existing rollback command.
• Integration is working on in zsystm/rollback branch

geth logs at stuck
story logs at stuck
Note: Geth did not insert the invalid block, so it remains at the last valid block. This means that once the app hash issue in the story is resolved and re-executed, the chain would function correctly again.

What happens if a non-upgraded node proposes a block? No need to worry—other nodes will reject the proposal, and Geth will not insert the incorrect block into the database.

In this case, the non-upgraded node should stop both the Story client and Geth, upgrade Geth, and then restart everything.
If the node was in a stuck, it can perform a rollback first. If there is no stuck state, simply upgrading and restarting should allow the node to sync blocks without any issues.

[limengformal]

@zsystm Thank you for the work. This solution rollback a block on the CL side. Do we also need to rollback blocks on the EL side as well?

[zsystm]

@limengformal
No, we don’t need to roll back blocks on the EL side in this case. Some nodes didn’t upgrade Geth in time meaning the hard fork is already active. Any non-upgraded node will stop processing blocks containing state-breaking transactions (i.e., transactions that result in different states due to the hard fork).

Case 1: Non-upgraded node is the proposer

• The EVM payload created by the non-upgraded node will be rejected by the other nodes. This means the payload will never be finalized on the CL side, and the non-upgraded node will not insert the block on EL since it hasn’t been finalized by the CL.

Case 2: Non-upgraded node is not the proposer

• The non-upgraded node will reject the EVM payload created by upgraded nodes because it will differ from its own state.

In other scenarios, there may be a need for rollback on EL. For example, if there were an attempt by a hacker to steal a large sum of funds on the EL side and the community, along with the majority of validators, deemed the action unjust, a rollback might be necessary. However, in the current situation where we are dealing with some nodes (less than 1/3 of total voting power) missing their upgrades, there is no need for a rollback on the EL side.