Apphash mismatch (IAVL 1.2.0, been able to reproduce it once)

[Pitasi]

Hey everyone, I'm asking for help investigating an apphash mismatch we have seen in one of our internal testnet.

We are using:

• Cosmos SDK: v0.50.9 (Evmos fork)
• IAVL: v1.2.0

Our testnet was composed of two nodes, sharing the same Horcrux remote signer (i.e. there was only one validator).

One of the two nodes halted due to a apphash mismatch, the chain didn't halt because the other node continued acting as the validator. By the time we noticed, the pruning settings already wiped the interested block from the node that continued running, hence I wasn't able to do some proper investigation.

The interesting this I noticed from the application.db of the node that halted, is that it completely wiped an entire module storage. The previous block height was there, the next it doesn't have any keys:

go run . data ~/Downloads/chiado-1-dump.db "s/k:act/" 17698
Got version: 19520
Printing all keys with hashed values (to detect diff)
  000000000000000001
    1F878D20753082B2905FCFE18F98D3B7D4E8C866EF7A1781D7BC9D455767A11E
... [omitted for brevity]
  action/count
    7A42E3892368F826928202014A6CA95A3D8D846DF25088DA80018663EDF96B1C
Hash: 389087F05766BD6552DF3FC40AACD8A1B5A9FC16927CBCFFAA5EC73D79128A35
Size: 34

❯ go run . data ~/Downloads/chiado-1-dump.db "s/k:act/" 17699
Got version: 19520
Printing all keys with hashed values (to detect diff)
Hash: E3B0C44298FC1C149AFBF4C8996FB92427AE41E4649B934CA495991B7852B855
Size: 0

Both nodes had an interesting line in the logs, just before this error occured.

12:09PM ERR iavl set error error="Value missing for key [0 0 0 0 0 0 0 1 0 0 0 1] corresponding to nodeKey 73000000000000000100000001" module=server

At this point, one thing I noticed is that the node wasn't shutting down properly on SIGTERM/SIGINT, it was panicking right before closing the databases. So my initial thought was that the db got corrupted because of that.

We fixed the bug causing the panic and restarted a new chain from scratch using the fixed version, with the same setup.

The issue happened again, and the same module data was gone, just like the first time. (weird coincidence?)

And an identical log entry for both nodes appeared before the apphash mismatch:

2024-10-07T01:09:22.79390127Z stdout F 1:09AM ERR iavl set error error=“Value missing for key [0 0 0 0 0 0 0 1 0 0 0 1] corresponding to nodeKey 73000000000000000100000001” module=server”

We disabled pruning and ran yet another chain from scratch, but the issue haven't happened yet and it's been a week now. Could the issue be related to pruning?
FWIW we've been using the same IAVL version for months in our public testnet, with the exact same pruning parameters, without any issues.

If anyone has any idea on how to investigate further the root cause, I'd be more than happy. Thanks!

[julienrbrt]

cc @cool-develope

[cool-develope]

Please check whether this act module is committed per block. I am thinking for some reasons, the act module is skipped in SaveVersion (store.Commit) and then the entire tree is deleted when this version is pruned later.

[cool-develope]

@Pitasi , could you please share the chiado-1-dump.db file?

[Thomasvdam]

@cool-develope thanks for looking into this!

The first time it happened we saw the error on validator 2, and no error on validator 1 (resulting in a chain halt). When we tried to query some state for the module of which we knew it should be present we only got a result on validator 1. The same input gave a "not found" error on validator 2.

After executing the rollback and restarting the chain validator 1 and validator 2 both returned the expected data for the query. After resubmitting the transaction we observed the error on both validators (no chain halt) but now both validators returned the "not found" error for the query that worked before the error.

[mmsqe]

seems can constantly reproduced with iavl 1.2.x, there's pruning store trigger traverseOrphans before recursiveSet for [0 0 0 0 0 0 0 1 0 0 0 1]

[yihuang]

seems can constantly reproduced with iavl 1.2.x, there's pruning store trigger traverseOrphans before recursiveSet for [0 0 0 0 0 0 0 1 0 0 0 1]

cosmos/iavl#1006

[cool-develope]

Good catch, thanks for this report @mmsqe @yihuang, I've created the fixing PR cosmos/iavl#1007

[yihuang]

We experienced chain halting when upgrading testnet, after generated a dozen blocks beyond the upgrade point. The validator nodes with pruning=everything hanged, the last log is executed block .... We recovered it by setting pruning=nothing and restart. there seems indeed some serious issue with the pruning of iavl v1 (this is because default sync pruning takes a long time, see: #22253 (reply in thread)).
we are using iavl commit hash 594b181f427e (the latest commit in release/v1.2.x branch)

[yihuang]

older version is iavl v0 with sdk 0.47, new version is a forked sdk based on sdk 0.50, and we've updated iavl to the latest release/v1.2.x branch (commit hash 594b181f427e), because we see it includes a prune fix.

[cool-develope]

if you do not set AsyncPruning, the pruning will block for a long time (experienced in Osmosis)

[cool-develope]

cosmos-sdk/store/iavl/store.go

Line 58 in 96a1c1c

tree := iavl.NewMutableTree(db, cacheSize, disableFastNode, logger, iavl.InitialVersionOption(initialVersion), iavl.AsyncPruningOption(true))

[yihuang]

I see, that explains the validator hangs, because the async-pruning is not enabled in sdk 0.50

https://github.com/cosmos/cosmos-sdk/blob/release/v0.50.x/store/iavl/store.go#L55

[alienc0der]

I've switched to memiavl and it fixed the issue @yihuang