celestia-appd status reports app version 3 prematurely

[rootulp]

Context

On main, I added a log line to print the current version in EndBlocker and ran

make install
./scripts/single-node.sh

Problem

The app thinks it is on app version 3 from the beginning even though I think it should start on app version 1, upgrade to app version 2 at block height 3.

Also there are log lines for an upgrade from app version 1 -> 2 at block height 3 which doesn't make sense if the app version is already 3.

Note the genesis doesn't have an app version specified.

$ ./scripts/single-node.sh
celestia-app home: /Users/rootulp/.celestia-app
celestia-app version: 3.0.0-alpha-5-ga7476c6c7

Do you want to delete existing /Users/rootulp/.celestia-app and start a new local testnet? [y/n]
y
Deleting /Users/rootulp/.celestia-app...
Initializing validator and node config files...
Adding a new key to the keyring...
Adding genesis account...
Creating a genesis tx...
Collecting genesis txs...
Tracing is set up with the ability to pull traced data from the node on the address http://127.0.0.1:26661
Starting celestia-app...
10:55AM INF starting node with ABCI Tendermint in-process
10:55AM INF service start impl=multiAppConn module=proxy msg={}
10:55AM INF service start connection=query impl=localClient module=abci-client msg={}
10:55AM INF service start connection=snapshot impl=localClient module=abci-client msg={}
10:55AM INF service start connection=mempool impl=localClient module=abci-client msg={}
10:55AM INF service start connection=consensus impl=localClient module=abci-client msg={}
10:55AM INF service start impl=EventBus module=events msg={}
10:55AM INF service start impl=PubSub module=pubsub msg={}
10:55AM INF service start impl=IndexerService module=txindex msg={}
10:55AM INF ABCI Replay Blocks appHeight=0 module=consensus stateHeight=0 storeHeight=0
10:55AM INF mounting KV stores for app version 3
10:55AM INF initializing blockchain state from genesis.json
10:55AM INF asserting crisis invariants inv=1/11 module=x/crisis name=bank/nonnegative-outstanding
10:55AM INF asserting crisis invariants inv=2/11 module=x/crisis name=bank/total-supply
10:55AM INF asserting crisis invariants inv=3/11 module=x/crisis name=gov/module-account
10:55AM INF asserting crisis invariants inv=4/11 module=x/crisis name=distribution/nonnegative-outstanding
10:55AM INF asserting crisis invariants inv=5/11 module=x/crisis name=distribution/can-withdraw
10:55AM INF asserting crisis invariants inv=6/11 module=x/crisis name=distribution/reference-count
10:55AM INF asserting crisis invariants inv=7/11 module=x/crisis name=distribution/module-account
10:55AM INF asserting crisis invariants inv=8/11 module=x/crisis name=staking/module-accounts
10:55AM INF asserting crisis invariants inv=9/11 module=x/crisis name=staking/nonnegative-power
10:55AM INF asserting crisis invariants inv=10/11 module=x/crisis name=staking/positive-delegation
10:55AM INF asserting crisis invariants inv=11/11 module=x/crisis name=staking/delegator-shares
10:55AM INF asserted all invariants duration=0.314 height=0 module=x/crisis
10:55AM INF created new capability module=ibc name=ports/transfer
10:55AM INF port binded module=x/ibc/port port=transfer
10:55AM INF claimed capability capability=1 module=transfer name=ports/transfer
10:55AM INF created new capability module=ibc name=ports/icahost
10:55AM INF port binded module=x/ibc/port port=icahost
10:55AM INF claimed capability capability=2 module=icahost name=ports/icahost
10:55AM INF Completed ABCI Handshake - CometBFT and App are synced appHash="���B��\x1c\x14���șo�$'�A�d��L���\x1bxR�U" appHeight=0 appVersion=3 module=consensus
10:55AM INF Version info abci=0.17.0 block=11 cmtbft_version=0.34.35 commit_hash= p2p=8
10:55AM INF This node is a validator addr=8805596DC2B0D96F5079F6712D20005BED656856 module=consensus pubKey=UNediq3wVuwJD+NRViz8cP1kisSfHvIaBv+2pkyoTqA=
10:55AM INF starting pull server address=:26661
10:55AM INF P2P Node ID ID=1c8a2dc1aee035bed85e94df3bf2f44359522d1d file=/Users/rootulp/.celestia-app/config/node_key.json module=p2p
10:55AM INF Adding persistent peers addrs=[] module=p2p
10:55AM INF Adding unconditional peer ids ids=[] module=p2p
10:55AM INF Add our address to book addr={"id":"1c8a2dc1aee035bed85e94df3bf2f44359522d1d","ip":"0.0.0.0","port":26656} book=/Users/rootulp/.celestia-app/config/addrbook.json module=p2p
10:55AM INF service start impl=Node msg={}
10:55AM INF Starting pprof server laddr=localhost:6060
10:55AM INF service start impl="P2P Switch" module=p2p msg={}
10:55AM INF serve module=rpc-server msg={}
10:55AM INF service start impl=Mempool msg={}
10:55AM INF service start impl=BlockchainReactor module=blockchain msg={}
10:55AM INF service start impl=ConsensusReactor module=consensus msg={}
10:55AM INF Reactor  module=consensus waitSync=false
10:55AM INF service start impl=ConsensusState module=consensus msg={}
10:55AM INF service start impl=baseWAL module=consensus msg={} wal=/Users/rootulp/.celestia-app/data/cs.wal/wal
10:55AM INF service start impl=Group module=consensus msg={} wal=/Users/rootulp/.celestia-app/data/cs.wal/wal
10:55AM INF service start impl=TimeoutTicker module=consensus msg={}
10:55AM INF Searching for height height=1 max=0 min=0 module=consensus wal=/Users/rootulp/.celestia-app/data/cs.wal/wal
10:55AM INF Searching for height height=0 max=0 min=0 module=consensus wal=/Users/rootulp/.celestia-app/data/cs.wal/wal
10:55AM INF Found height=0 index=0 module=consensus wal=/Users/rootulp/.celestia-app/data/cs.wal/wal
10:55AM INF Catchup by replaying consensus messages height=1 module=consensus
10:55AM INF Replay: Done module=consensus
10:55AM INF service start impl=Evidence module=evidence msg={}
10:55AM INF service start impl=StateSync module=statesync msg={}
10:55AM INF service start impl=PEX module=pex msg={}
10:55AM INF service start book=/Users/rootulp/.celestia-app/config/addrbook.json impl=AddrBook module=p2p msg={}
10:55AM INF Saving AddrBook to file book=/Users/rootulp/.celestia-app/config/addrbook.json module=p2p size=0
10:55AM INF Ensure peers module=pex numDialing=0 numInPeers=0 numOutPeers=0 numToDial=10
10:55AM INF No addresses to dial. Falling back to seeds module=pex
10:55AM INF starting API server... module=api-server
10:55AM INF serve module=api-server msg={}
10:55AM INF Timed out dur=10995.051 height=1 module=consensus round=0 step=1
10:55AM INF received proposal module=consensus proposal={"Type":32,"block_id":{"hash":"7290B6AD6B9D42FF1239083C4AF768A0CDC2C850D518E2550A14F332A9E5789D","parts":{"hash":"253BF3F8582ABACE4E89E9551F7F8234A3EF1106E28BC21B62F9D589AEB66B4E","total":1}},"height":1,"pol_round":-1,"round":0,"signature":"dNt1Ay+iPy0rURGXLu7DMjNldkLRDrt2+LmKY62IxK0zFf+rHiYsofLWUL2U3O5vjVDjlvlfahY3VyjUBbZoCw==","timestamp":"2024-10-15T14:55:44.282065Z"} proposer=8805596DC2B0D96F5079F6712D20005BED656856
10:55AM INF received complete proposal block hash=7290B6AD6B9D42FF1239083C4AF768A0CDC2C850D518E2550A14F332A9E5789D height=1 module=consensus
10:55AM INF finalizing commit of block hash={} height=1 module=consensus num_txs=0 root=E3B0C44298FC1C149AFBF4C8996FB92427AE41E4649B934CA495991B7852B855
10:55AM INF current version: 3
10:55AM INF executed block height=1 module=state num_invalid_txs=0 num_valid_txs=0
10:55AM INF commit synced commit=436F6D6D697449447B5B313735203231372034302031373720333020313837203137372031362031393420323030203132332038312034342032302031343820313235203232382031323220353220362031343720313335203234362035382034332031343820313536203138302033382037203632203131375D3A317D
10:55AM INF committed state app_hash=AFD928B11EBBB110C2C87B512C14947DE47A34069387F63A2B949CB426073E75 height=1 module=state num_txs=0
10:55AM INF indexed block events height=1 module=txindex
10:55AM INF Timed out dur=10976.968 height=2 module=consensus round=0 step=1
10:55AM INF received proposal module=consensus proposal={"Type":32,"block_id":{"hash":"0518E752AD738753F5C93B031227799B9A88F284E1BA469BF8E95B59C48AEAD4","parts":{"hash":"E6E95DBFE89639CD196AF0A8DE8F0453A3D7777AAE3F91A1CA1C7A90B60C6409","total":1}},"height":2,"pol_round":-1,"round":0,"signature":"cHqwjbZtajfPIMYLDw9AIkZWoEgp+v3slx3bETfVWtxSu0Dg3eICAxxcE2MzaiYJ1pBSEMmt3dITdKtwtO0RDA==","timestamp":"2024-10-15T14:55:55.307865Z"} proposer=8805596DC2B0D96F5079F6712D20005BED656856
10:55AM INF received complete proposal block hash=0518E752AD738753F5C93B031227799B9A88F284E1BA469BF8E95B59C48AEAD4 height=2 module=consensus
10:55AM INF finalizing commit of block hash={} height=2 module=consensus num_txs=0 root=AFD928B11EBBB110C2C87B512C14947DE47A34069387F63A2B949CB426073E75
10:55AM INF minted coins from module account amount=28988802utia from=mint module=x/bank
10:55AM INF current version: 3
10:55AM INF executed block height=2 module=state num_invalid_txs=0 num_valid_txs=0
10:55AM INF commit synced commit=436F6D6D697449447B5B31392032333320313032203231203233203130382031313720313431203138332031363620373420313420313334203130203336203230352032303920313830203137382031343720323220383620313537203735203338203232352036332032343320313936203530203230302031335D3A327D
10:55AM INF committed state app_hash=13E96615176C758DB7A64A0E860A24CDD1B4B29316569D4B26E13FF3C432C80D height=2 module=state num_txs=0
10:55AM INF indexed block events height=2 module=txindex
10:56AM INF Ensure peers module=pex numDialing=0 numInPeers=0 numOutPeers=0 numToDial=10
10:56AM INF No addresses to dial. Falling back to seeds module=pex
10:56AM INF Timed out dur=10974.009 height=3 module=consensus round=0 step=1
10:56AM INF received proposal module=consensus proposal={"Type":32,"block_id":{"hash":"B416DAF11D647060CE78EBB90D2051DAD408ABE134EAA69C53DFC52AD23BDBB5","parts":{"hash":"1AE17224AE9E79C7EA29D708F4086BD69E245591F5C557D4E19B9F024E341D1D","total":1}},"height":3,"pol_round":-1,"round":0,"signature":"6X20gZqBq7VMDybK5Knug3W0fYKINdjCnSmeMBhhLyn1nk4TESXmG+pjRKIBeJSp5XfnmYmIbKsq53BNInYmBA==","timestamp":"2024-10-15T14:56:06.351236Z"} proposer=8805596DC2B0D96F5079F6712D20005BED656856
10:56AM INF received complete proposal block hash=B416DAF11D647060CE78EBB90D2051DAD408ABE134EAA69C53DFC52AD23BDBB5 height=3 module=consensus
10:56AM INF finalizing commit of block hash={} height=3 module=consensus num_txs=0 root=13E96615176C758DB7A64A0E860A24CDD1B4B29316569D4B26E13FF3C432C80D
10:56AM INF upgraded from app version 1 to 2
10:56AM INF minted coins from module account amount=27991291utia from=mint module=x/bank
10:56AM INF current version: 3
10:56AM INF executed block height=3 module=state num_invalid_txs=0 num_valid_txs=0
10:56AM INF commit synced commit=436F6D6D697449447B5B363620323532203532203933203137312031323620373420313631203132392031303020333820333220313834203332203337203134362033362031373220383620343620313032203137372037302031353020363420313436203130203135322031313520353220323134203136375D3A337D
10:56AM INF committed state app_hash=42FC345DAB7E4AA181642620B820259224AC562E66B1469640920A987334D6A7 height=3 module=state num_txs=0
10:56AM INF indexed block events height=3 module=txindex

Proposal

Investigate the issue.

[rootulp]

FWIW the log line I added:

$ git diff
diff --git a/app/app.go b/app/app.go
index ecba66102..f8cad1079 100644
--- a/app/app.go
+++ b/app/app.go
@@ -458,6 +458,7 @@ func (app *App) BeginBlocker(ctx sdk.Context, req abci.RequestBeginBlock) abci.R
 func (app *App) EndBlocker(ctx sdk.Context, req abci.RequestEndBlock) abci.ResponseEndBlock {
        res := app.manager.EndBlock(ctx, req)
        currentVersion := app.AppVersion()
+       app.BaseApp.Logger().Info(fmt.Sprintf("current version: %v", currentVersion))
        // For v1 only we upgrade using a agreed upon height known ahead of time
        if currentVersion == v1 {
                // check that we are at the height before the upgrade