Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix IBC upgrade: manually tested #8187

Merged
merged 5 commits into from
Dec 17, 2020
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 2 additions & 2 deletions x/ibc/light-clients/07-tendermint/types/upgrade.go
Original file line number Diff line number Diff line change
Expand Up @@ -83,7 +83,7 @@ func (cs ClientState) VerifyUpgradeAndUpdateState(
// construct clientState Merkle path
upgradeClientPath := constructUpgradeClientMerklePath(cs.UpgradePath, lastHeight)
if err := merkleProofClient.VerifyMembership(cs.ProofSpecs, consState.GetRoot(), upgradeClientPath, bz); err != nil {
return nil, nil, err
return nil, nil, sdkerrors.Wrapf(err, "client state proof failed. Path: %s", upgradeClientPath.Pretty())
}

// Verify consensus state proof
Expand All @@ -94,7 +94,7 @@ func (cs ClientState) VerifyUpgradeAndUpdateState(
// construct consensus state Merkle path
upgradeConsStatePath := constructUpgradeConsStateMerklePath(cs.UpgradePath, lastHeight)
if err := merkleProofConsState.VerifyMembership(cs.ProofSpecs, consState.GetRoot(), upgradeConsStatePath, bz); err != nil {
return nil, nil, err
return nil, nil, sdkerrors.Wrapf(err, "consensus state proof failed. Path: %s", upgradeConsStatePath.Pretty())
}

// Construct new client state and consensus state
Expand Down
2 changes: 1 addition & 1 deletion x/upgrade/abci.go
Original file line number Diff line number Diff line change
Expand Up @@ -41,7 +41,7 @@ func BeginBlocker(k keeper.Keeper, ctx sdk.Context, _ abci.RequestBeginBlock) {
Timestamp: ctx.BlockTime(),
NextValidatorsHash: ctx.BlockHeader().NextValidatorsHash,
}
k.SetUpgradedConsensusState(ctx, ctx.BlockHeight(), upgradedConsState)
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This used to save consensus state at plan.Height-1

k.SetUpgradedConsensusState(ctx, plan.Height, upgradedConsState)
}
// To make sure clear upgrade is executed at the same block
if plan.ShouldExecute(ctx) {
Expand Down
3 changes: 2 additions & 1 deletion x/upgrade/abci_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -131,7 +131,8 @@ func VerifyDoIBCLastBlock(t *testing.T) {
req := abci.RequestBeginBlock{Header: newCtx.BlockHeader()}
s.module.BeginBlock(newCtx, req)

consState, err := s.keeper.GetUpgradedConsensusState(newCtx, s.ctx.BlockHeight())
// plan Height is at ctx.BlockHeight+1
consState, err := s.keeper.GetUpgradedConsensusState(newCtx, s.ctx.BlockHeight()+1)
require.NoError(t, err)
require.Equal(t, &ibctmtypes.ConsensusState{Timestamp: newCtx.BlockTime(), NextValidatorsHash: nextValsHash}, consState)
}
Expand Down
12 changes: 6 additions & 6 deletions x/upgrade/keeper/keeper.go
Original file line number Diff line number Diff line change
Expand Up @@ -89,15 +89,15 @@ func (k Keeper) ScheduleUpgrade(ctx sdk.Context, plan types.Plan) error {
if err != nil {
return sdkerrors.Wrapf(sdkerrors.ErrInvalidRequest, "could not unpack clientstate: %v", err)
}
// sets the new upgraded client in last height committed on this chain is at plan.Height - 1,
// sets the new upgraded client in last height committed on this chain is at plan.Height,
// since the chain will panic at plan.Height and new chain will resume at plan.Height
return k.SetUpgradedClient(ctx, plan.Height-1, clientState)
return k.SetUpgradedClient(ctx, plan.Height, clientState)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmmm.... this raises my eyebrows.

was normal x/upgrade (swapping out binaries) was working on stargate until now (or was this not tested?).

Because just swapping this height by one to fix an ibc test may break some other test. It would be good to test this with a non-ibc upgrade. Or maybe x/upgrade in general was never tested in stargate?

Copy link
Contributor

@colin-axner colin-axner Dec 18, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

this falls under the if condition if plan.IsIBCPlan(). It should never be reached under a normal upgrade, all the code changes in this pr occur after an if plan.IsIBCPlan() so there should be no change to normal upgrades

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The plan.Height - 1 was initially used due to a misunderstanding of how upgrades worked. It was initially understood that if the upgrade height is 100, the block 100 is not committed and that this would be the first block committed after the upgrade is successful. Which is why plan.Height - 1 was used (last committed height)

During testing, we realized the last committed height is actually block 100, not 99. Therefore we needed to set the client and consensus states at block 100. Block 101 was the first committed block after the upgrade

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The normal x/upgrade feature was working just fine before this PR.

This is to fix the IBC relevant part of the code that was added to ensure that IBC light client would be able to successfully track upgrades using the upgrade feature. Which was not manually tested until now. This PR simply fixes the IBC relevant changes as @colin-axner says.

A non-ibc upgrade would not set an upgraded client at all

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@colin-axner we tested it with multiple validator devnet couple of times, only the proposer will commit 100th block and panic. Other node can never receive this block details and they will never confirm. @kaustubhkapatral do you any other state details we found?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

maybe this will help. Logs from our upgrade yesterday

Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]: 3:34PM INF Commit is for locked block. Set ProposalBlock=LockedBlock blockHash=CC4BCFED2D91B3996C707E34E9AA1A1B4D790843550989C68C019538B9F20BB1 commitRound=0 height=349 module=consensus
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]: 3:34PM INF Finalizing commit of block with N txs N=0 hash=CC4BCFED2D91B3996C707E34E9AA1A1B4D790843550989C68C019538B9F20BB1 height=349 module=consensus root=B8306CFECCB8394DB53EC5CC0649DFFDF51D09BB92656606B2335BD2F00D3162
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]: 3:34PM INF Block{
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:   Header{
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:     Version:        {11 0}
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:     ChainID:        cosmos-pub-1
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:     Height:         349
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:     Time:           2020-12-17 15:34:24.231376001 +0000 UTC
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:     LastBlockID:    71BCA28BB612D75B0ED3A76E868C83D6BC78959A585F15E02BA655F0F26E29CC:1:E0068B7C5732
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:     LastCommit:     E946D30B07F07A29FFC81178B82ED6F48C7EE5A3A7479F2F8CD58C70E927360B
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:     Data:           E3B0C44298FC1C149AFBF4C8996FB92427AE41E4649B934CA495991B7852B855
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:     Validators:     06DCEB0D7DBD4D0ABD268B711B1D2EDA5535B7A8C5724D3CACC9C7863ACD1B9B
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:     NextValidators: 06DCEB0D7DBD4D0ABD268B711B1D2EDA5535B7A8C5724D3CACC9C7863ACD1B9B
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:     App:            B8306CFECCB8394DB53EC5CC0649DFFDF51D09BB92656606B2335BD2F00D3162
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:     Consensus:      0F2908883A105C793B74495EB7D6DF2EEA479ED7FC9349206A65CB0F9987A0B8
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:     Results:        E3B0C44298FC1C149AFBF4C8996FB92427AE41E4649B934CA495991B7852B855
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:     Evidence:       E3B0C44298FC1C149AFBF4C8996FB92427AE41E4649B934CA495991B7852B855
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:     Proposer:       26283F0B13EC798052CAB80F53F12022E9FB9D48
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:   }#CC4BCFED2D91B3996C707E34E9AA1A1B4D790843550989C68C019538B9F20BB1
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:   Data{
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:     
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:   }#E3B0C44298FC1C149AFBF4C8996FB92427AE41E4649B934CA495991B7852B855
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:   EvidenceData{
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:     
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:   }#E3B0C44298FC1C149AFBF4C8996FB92427AE41E4649B934CA495991B7852B855
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:   Commit{
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:     Height:     348
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:     Round:      0
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:     BlockID:    71BCA28BB612D75B0ED3A76E868C83D6BC78959A585F15E02BA655F0F26E29CC:1:E0068B7C5732
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:     Signatures:
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:       CommitSig{13C8863D955D by 26283F0B13EC on 2 @ 2020-12-17T15:34:24.231376001Z}
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:       CommitSig{1B259340E0F1 by A0CF85AB0996 on 2 @ 2020-12-17T15:34:24.338185266Z}
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]:   }#E946D30B07F07A29FFC81178B82ED6F48C7EE5A3A7479F2F8CD58C70E927360B
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]: }#CC4BCFED2D91B3996C707E34E9AA1A1B4D790843550989C68C019538B9F20BB1 module=consensus
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]: 3:34PM INF minted coins from module account amount=406866047ubrews from=mint module=x/bank
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]: 3:34PM INF Executed block height=349 invalidTxs=0 module=state validTxs=0
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]: 3:34PM INF commit synced commit=436F6D6D697449447B5B31393120313037203133312031313920313935203232342032392031343320313936203636203139312032323720323535203820313020313820323330203130322031383720392033362032313120352031323220373>
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]: 3:34PM INF Committed state appHash=BF6B8377C3E01D8FC442BFE3FF080A12E666BB0924D3057A4F3C33BA9EC9B7DF height=349 module=state txs=0
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]: 3:34PM INF Updating evidence pool last_block_height=349 last_block_time=2020-12-17T15:34:24Z module=evidence
Dec 17 15:34:29 colin-ibc-testnet gaiad[85310]: 3:34PM INF Indexed block height=349 module=txindex
Dec 17 15:34:34 colin-ibc-testnet gaiad[85310]: 3:34PM INF Timed out dur=4985.986111 height=350 module=consensus round=0 step=1
Dec 17 15:34:34 colin-ibc-testnet gaiad[85310]: 3:34PM INF enterNewRound(350/0). Current: 350/0/RoundStepNewHeight height=350 module=consensus round=0
Dec 17 15:34:34 colin-ibc-testnet gaiad[85310]: 3:34PM INF enterPropose(350/0). Current: 350/0/RoundStepNewRound height=350 module=consensus round=0
Dec 17 15:34:34 colin-ibc-testnet gaiad[85310]: 3:34PM INF enterPropose: Not our turn to propose height=350 module=consensus privValidator={"Key":{"address":"26283F0B13EC798052CAB80F53F12022E9FB9D48","priv_key":"qGZzhvf91pu/Si+FFD/qvxRJhHo1TU1C1ZiNi8reAQQp8bUQ6/QmDFQz11lUj>
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM INF Added to prevote module=consensus prevotes="VoteSet{H:350 R:0 T:SIGNED_MSG_TYPE_PREVOTE +2/3:<nil>(0.5) BA{2:_x} map[]}" vote={"block_id":{"hash":"0C356CBF16FE8C4E22A07D02E09903558D14F8DAFB48422B6D1B41155515055C",">
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM INF Received proposal module=consensus proposal={"Type":32,"block_id":{"hash":"0C356CBF16FE8C4E22A07D02E09903558D14F8DAFB48422B6D1B41155515055C","parts":{"hash":"FC2E487E16B6368F8579025EFA58D4B974CF89180363A3F82666B1C9>
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM INF Received complete proposal block hash=0C356CBF16FE8C4E22A07D02E09903558D14F8DAFB48422B6D1B41155515055C height=350 module=consensus
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM INF enterPrevote(350/0). Current: 350/0/RoundStepPropose module=consensus
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM INF enterPrevote: ProposalBlock is valid height=350 module=consensus round=0
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM INF Signed and pushed vote err=null height=350 module=consensus round=0 vote={"block_id":{"hash":"0C356CBF16FE8C4E22A07D02E09903558D14F8DAFB48422B6D1B41155515055C","parts":{"hash":"FC2E487E16B6368F8579025EFA58D4B974CF8>
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM INF Added to prevote module=consensus prevotes="VoteSet{H:350 R:0 T:SIGNED_MSG_TYPE_PREVOTE +2/3:0C356CBF16FE8C4E22A07D02E09903558D14F8DAFB48422B6D1B41155515055C:1:FC2E487E16B6(1) BA{2:xx} map[]}" vote={"block_id":{"ha>
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM INF Updating ValidBlock because of POL. POLRound=0 module=consensus validRound=-1
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM INF enterPrecommit(350/0). Current: 350/0/RoundStepPrevote height=350 module=consensus round=0
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM INF enterPrecommit: +2/3 prevoted proposal block. Locking hash=0C356CBF16FE8C4E22A07D02E09903558D14F8DAFB48422B6D1B41155515055C height=350 module=consensus round=0
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM INF Signed and pushed vote err=null height=350 module=consensus round=0 vote={"block_id":{"hash":"0C356CBF16FE8C4E22A07D02E09903558D14F8DAFB48422B6D1B41155515055C","parts":{"hash":"FC2E487E16B6368F8579025EFA58D4B974CF8>
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM INF Added to precommit module=consensus precommits="VoteSet{H:350 R:0 T:SIGNED_MSG_TYPE_PRECOMMIT +2/3:<nil>(0.5) BA{2:x_} map[]}" vote={"block_id":{"hash":"0C356CBF16FE8C4E22A07D02E09903558D14F8DAFB48422B6D1B411555150>
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM INF Added to precommit module=consensus precommits="VoteSet{H:350 R:0 T:SIGNED_MSG_TYPE_PRECOMMIT +2/3:0C356CBF16FE8C4E22A07D02E09903558D14F8DAFB48422B6D1B41155515055C:1:FC2E487E16B6(1) BA{2:xx} map[]}" vote={"block_id>
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM INF enterCommit(350/0). Current: 350/0/RoundStepPrecommit commitRound=0 height=350 module=consensus
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM INF Commit is for locked block. Set ProposalBlock=LockedBlock blockHash=0C356CBF16FE8C4E22A07D02E09903558D14F8DAFB48422B6D1B41155515055C commitRound=0 height=350 module=consensus
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM INF Finalizing commit of block with N txs N=0 hash=0C356CBF16FE8C4E22A07D02E09903558D14F8DAFB48422B6D1B41155515055C height=350 module=consensus root=BF6B8377C3E01D8FC442BFE3FF080A12E666BB0924D3057A4F3C33BA9EC9B7DF
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM INF Block{
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:   Header{
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:     Version:        {11 0}
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:     ChainID:        cosmos-pub-1
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:     Height:         350
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:     Time:           2020-12-17 15:34:29.72366291 +0000 UTC
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:     LastBlockID:    CC4BCFED2D91B3996C707E34E9AA1A1B4D790843550989C68C019538B9F20BB1:1:C574D66536CA
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:     LastCommit:     A723DFFB370668B3D5467A924C0C77311DE737459E1D8D7710FAB3D22E0EE1BE
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:     Data:           E3B0C44298FC1C149AFBF4C8996FB92427AE41E4649B934CA495991B7852B855
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:     Validators:     06DCEB0D7DBD4D0ABD268B711B1D2EDA5535B7A8C5724D3CACC9C7863ACD1B9B
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:     NextValidators: 06DCEB0D7DBD4D0ABD268B711B1D2EDA5535B7A8C5724D3CACC9C7863ACD1B9B
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:     App:            BF6B8377C3E01D8FC442BFE3FF080A12E666BB0924D3057A4F3C33BA9EC9B7DF
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:     Consensus:      0F2908883A105C793B74495EB7D6DF2EEA479ED7FC9349206A65CB0F9987A0B8
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:     Results:        E3B0C44298FC1C149AFBF4C8996FB92427AE41E4649B934CA495991B7852B855
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:     Evidence:       E3B0C44298FC1C149AFBF4C8996FB92427AE41E4649B934CA495991B7852B855
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:     Proposer:       A0CF85AB09965116FC2B195DA9AB6A54A03D54F2
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:   }#0C356CBF16FE8C4E22A07D02E09903558D14F8DAFB48422B6D1B41155515055C
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:   Data{
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:     
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:   }#E3B0C44298FC1C149AFBF4C8996FB92427AE41E4649B934CA495991B7852B855
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:   EvidenceData{
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:     
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:   }#E3B0C44298FC1C149AFBF4C8996FB92427AE41E4649B934CA495991B7852B855
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:   Commit{
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:     Height:     349
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:     Round:      0
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:     BlockID:    CC4BCFED2D91B3996C707E34E9AA1A1B4D790843550989C68C019538B9F20BB1:1:C574D66536CA
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:     Signatures:
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:       CommitSig{D54A751D3453 by 26283F0B13EC on 2 @ 2020-12-17T15:34:29.82472918Z}
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:       CommitSig{9141894B82F4 by A0CF85AB0996 on 2 @ 2020-12-17T15:34:29.72366291Z}
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]:   }#A723DFFB370668B3D5467A924C0C77311DE737459E1D8D7710FAB3D22E0EE1BE
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: }#0C356CBF16FE8C4E22A07D02E09903558D14F8DAFB48422B6D1B41155515055C module=consensus
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM ERR UPGRADE "ibc-test" NEEDED at height: 350: upgrading ibc!
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM ERR CONSENSUS FAILURE!!! err="UPGRADE \"ibc-test\" NEEDED at height: 350: upgrading ibc!" module=consensus stack="goroutine 145 [running]:\nruntime/debug.Stack(0xc000ec3c28, 0x1941700, 0xc00454e0a0)\n\truntime/debug/st>
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM INF Stopping baseWAL service impl={"Logger":{}} module=consensus wal=/root/.gaia/data/cs.wal/wal
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM INF Stopping Group service impl={"Dir":"/root/.gaia/data/cs.wal","Head":{"ID":"lXQdd1kqFnD1:/root/.gaia/data/cs.wal/wal","Path":"/root/.gaia/data/cs.wal/wal"},"ID":"group:lXQdd1kqFnD1:/root/.gaia/data/cs.wal/wal","Logg>
Dec 17 15:34:36 colin-ibc-testnet gaiad[85310]: 3:34PM INF HTTPJSONRPC args=[{}] method=status module=rpc-server returns=[{},{}]
Dec 17 15:34:36 colin-ibc-testnet gaiad[85310]: 3:34PM INF Served RPC HTTP response duration=0 method=POST module=rpc-server remoteAddr=127.0.0.1:38568 status=200 url={"ForceQuery":false,"Fragment":"","Host":"","Opaque":"","Path":"/","RawFragment":"","RawPath":"","RawQuery>
Dec 17 15:34:37 colin-ibc-testnet gaiad[85310]: 3:34PM INF Timed out dur=3000 height=350 module=consensus round=0 step=3
Dec 17 15:34:38 colin-ibc-testnet gaiad[85310]: 3:34PM INF Saving AddrBook to file book=/root/.gaia/config/addrbook.json module=p2p size=1
Dec 17 15:34:38 colin-ibc-testnet gaiad[85310]: 3:34PM INF Ensure peers module=pex numDialing=0 numInPeers=0 numOutPeers=1 numToDial=9
Dec 17 15:34:38 colin-ibc-testnet gaiad[85310]: 3:34PM INF We need more addresses. Sending pexRequest to random peer module=pex peer={"Data":{},"Logger":{}}
Dec 17 15:34:38 colin-ibc-testnet gaiad[85310]: 3:34PM INF No addresses to dial. Falling back to seeds module=pex

Note some important details here.

Dec 17 15:34:34 colin-ibc-testnet gaiad[85310]: 3:34PM INF enterPropose: Not our turn to propose height=350 module=consensus privValidator={"Key":{"address":"26283F0B13EC798052CAB80F53F12022E9FB9D48","priv_key":"qGZzhvf91pu/Si+FFD/qvxRJhHo1TU1C1ZiNi8reAQQp8bUQ6/QmDFQz11lUj>
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM INF Commit is for locked block. Set ProposalBlock=LockedBlock blockHash=0C356CBF16FE8C4E22A07D02E09903558D14F8DAFB48422B6D1B41155515055C commitRound=0 height=350 module=consensus
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM INF Finalizing commit of block with N txs N=0 hash=0C356CBF16FE8C4E22A07D02E09903558D14F8DAFB48422B6D1B41155515055C height=350 module=consensus root=BF6B8377C3E01D8FC442BFE3FF080A12E666BB0924D3057A4F3C33BA9EC9B7DF
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM ERR UPGRADE "ibc-test" NEEDED at height: 350: upgrading ibc!
Dec 17 15:34:35 colin-ibc-testnet gaiad[85310]: 3:34PM ERR CONSENSUS FAILURE!!! err="UPGRADE \"ibc-test\" NEEDED at height: 350: upgrading ibc!" module=consensus stack="goroutine 145 [running]:\nruntime/debug.Stack(0xc000ec3c28, 0x1941700, 0xc00454e0a0)\n\truntime/debug/st>

This shows

  1. my validator was not the proposer
  2. the block was committed for the plan height before the plan was executed
  3. The block is executed after the commit and then panics
  4. I did a successful RPC call locally after the application process panic'd

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Since my validator and @AdityaSripal's validator panic'd, it looks like we lost connection with each other, therefore preventing block 351 from being committed (which will contain the upgrade handler changes once the binaries are swapped)

Copy link
Contributor

@colin-axner colin-axner Dec 18, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Here are some logs of me doing queries after the panic

Dec 17 15:34:42 colin-ibc-testnet gaiad[85310]: 3:34PM INF ABCIQuery data= module=rpc path=/cosmos.upgrade.v1beta1.Query/CurrentPlan result={"code":0,"codespace":"","height":"349","index":"0","info":"","key":null,"log":"","proofOps":null,"value":"CtEBCghpYmMtdGVzdBILCICSuM>
Dec 17 15:34:42 colin-ibc-testnet gaiad[85310]: 3:34PM INF HTTPJSONRPC args=[{},{},{},{},{}] method=abci_query module=rpc-server returns=[{},{}]
Dec 17 15:34:42 colin-ibc-testnet gaiad[85310]: 3:34PM INF Served RPC HTTP response duration=0 method=POST module=rpc-server remoteAddr=127.0.0.1:38574 status=200 url={"ForceQuery":false,"Fragment":"","Host":"","Opaque":"","Path":"/","RawFragment":"","RawPath":"","RawQuery>
Dec 17 15:34:42 colin-ibc-testnet gaiad[85310]: 3:34PM INF ABCIQuery data=757067726164656449424353746174652F3335302F7570677261646564436C69656E74 module=rpc path=store/upgrade/key result={"code":0,"codespace":"","height":"349","index":"0","info":"","key":"dXBncmFkZWRJQkNTdG>
Dec 17 15:34:42 colin-ibc-testnet gaiad[85310]: 3:34PM INF HTTPJSONRPC args=[{},{},{},{},{}] method=abci_query module=rpc-server returns=[{},{}]
Dec 17 15:34:42 colin-ibc-testnet gaiad[85310]: 3:34PM INF Served RPC HTTP response duration=0 method=POST module=rpc-server remoteAddr=127.0.0.1:38574 status=200 url={"ForceQuery":false,"Fragment":"","Host":"","Opaque":"","Path":"/","RawFragment":"","RawPath":"","RawQuery>
Dec 17 15:34:42 colin-ibc-testnet gaiad[85310]: 3:34PM INF ABCIQuery data=08DE02 module=rpc path=/cosmos.upgrade.v1beta1.Query/UpgradedConsensusState result={"code":0,"codespace":"","height":"349","index":"0","info":"","key":null,"log":"","proofOps":null,"value":"CmMKLi9pY>
Dec 17 15:34:42 colin-ibc-testnet gaiad[85310]: 3:34PM INF HTTPJSONRPC args=[{},{},{},{},{}] method=abci_query module=rpc-server returns=[{},{}]
Dec 17 15:34:42 colin-ibc-testnet gaiad[85310]: 3:34PM INF Served RPC HTTP response duration=0 method=POST module=rpc-server remoteAddr=127.0.0.1:38574 status=200 url={"ForceQuery":false,"Fragment":"","Host":"","Opaque":"","Path":"/","RawFragment":"","RawPath":"","RawQuery>
Dec 17 15:34:42 colin-ibc-testnet gaiad[85310]: 3:34PM INF ABCIQuery data=757067726164656449424353746174652F3335302F7570677261646564436F6E735374617465 module=rpc path=store/upgrade/key result={"code":0,"codespace":"","height":"349","index":"0","info":"","key":"dXBncmFkZWRJ>
Dec 17 15:34:42 colin-ibc-testnet gaiad[85310]: 3:34PM INF HTTPJSONRPC args=[{},{},{},{},{}] method=abci_query module=rpc-server returns=[{},{}]

Note that you can see the query for things like upgraded consensus state at height 349 (iavl version height)

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

And after switching binaries

Dec 18 14:01:55 colin-ibc-testnet gaiad[89348]: 2:01PM INF starting ABCI with Tendermint
Dec 18 14:01:55 colin-ibc-testnet gaiad[89348]: 2:01PM INF Starting multiAppConn service impl={"Logger":{}} module=proxy
Dec 18 14:01:55 colin-ibc-testnet gaiad[89348]: 2:01PM INF Starting localClient service connection=query impl="marshaling error: json: unsupported type: abcicli.Callback" module=abci-client
Dec 18 14:01:55 colin-ibc-testnet gaiad[89348]: 2:01PM INF Starting localClient service connection=snapshot impl="marshaling error: json: unsupported type: abcicli.Callback" module=abci-client
Dec 18 14:01:55 colin-ibc-testnet gaiad[89348]: 2:01PM INF Starting localClient service connection=mempool impl="marshaling error: json: unsupported type: abcicli.Callback" module=abci-client
Dec 18 14:01:55 colin-ibc-testnet gaiad[89348]: 2:01PM INF Starting localClient service connection=consensus impl="marshaling error: json: unsupported type: abcicli.Callback" module=abci-client
Dec 18 14:01:55 colin-ibc-testnet gaiad[89348]: 2:01PM INF Starting EventBus service impl={"Logger":{}} module=events
Dec 18 14:01:55 colin-ibc-testnet gaiad[89348]: 2:01PM INF Starting PubSub service impl={"Logger":{}} module=pubsub
Dec 18 14:01:55 colin-ibc-testnet gaiad[89348]: 2:01PM INF Starting IndexerService service impl={"Logger":{}} module=txindex
Dec 18 14:01:55 colin-ibc-testnet gaiad[89348]: 2:01PM INF ABCI Handshake App Info hash=BF6B8377C3E01D8FC442BFE3FF080A12E666BB0924D3057A4F3C33BA9EC9B7DF height=349 module=consensus protocol-version=0 software-version=
Dec 18 14:01:55 colin-ibc-testnet gaiad[89348]: 2:01PM INF ABCI Replay Blocks appHeight=349 module=consensus stateHeight=349 storeHeight=350
Dec 18 14:01:55 colin-ibc-testnet gaiad[89348]: 2:01PM INF Replay last block using real app module=consensus
Dec 18 14:01:55 colin-ibc-testnet gaiad[89348]: 2:01PM INF applying upgrade "ibc-test" at height: 350
Dec 18 14:01:55 colin-ibc-testnet gaiad[89348]: CLEARED IBC STATE ON APPLY UPGRADE!!!!!
Dec 18 14:01:55 colin-ibc-testnet gaiad[89348]: 2:01PM INF minted coins from module account amount=406866055ubrews from=mint module=x/bank
Dec 18 14:01:55 colin-ibc-testnet gaiad[89348]: 2:01PM INF Executed block height=350 invalidTxs=0 module=consensus validTxs=0
Dec 18 14:01:55 colin-ibc-testnet gaiad[89348]: 2:01PM INF commit synced commit=436F6D6D697449447B5B32392031353120353420313638203231362032303120313920363920313037203439203231352032303720313637203136372034322039372031333620343620323535203339203130392031333820333920313038203>
Dec 18 14:01:55 colin-ibc-testnet gaiad[89348]: 2:01PM INF Committed state appHash=1D9736A8D8C913456B31D7CFA7A72A61882EFF276D8A276C572F8D2D674C4CB9 height=350 module=consensus txs=0

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is there any part of the above logs that differ?

}
return nil
}

// SetUpgradedClient sets the expected upgraded client for the next version of this chain at the last height the current chain will commit.
func (k Keeper) SetUpgradedClient(ctx sdk.Context, lastHeight int64, cs ibcexported.ClientState) error {
func (k Keeper) SetUpgradedClient(ctx sdk.Context, planHeight int64, cs ibcexported.ClientState) error {
store := ctx.KVStore(k.storeKey)

// zero out any custom fields before setting
Expand All @@ -107,7 +107,7 @@ func (k Keeper) SetUpgradedClient(ctx sdk.Context, lastHeight int64, cs ibcexpor
return sdkerrors.Wrapf(sdkerrors.ErrInvalidRequest, "could not marshal clientstate: %v", err)
}

store.Set(types.UpgradedClientKey(lastHeight), bz)
store.Set(types.UpgradedClientKey(planHeight), bz)
return nil
}

Expand All @@ -129,14 +129,14 @@ func (k Keeper) GetUpgradedClient(ctx sdk.Context, height int64) (ibcexported.Cl

// SetUpgradedConsensusState set the expected upgraded consensus state for the next version of this chain
// using the last height committed on this chain.
func (k Keeper) SetUpgradedConsensusState(ctx sdk.Context, lastHeight int64, cs ibcexported.ConsensusState) error {
func (k Keeper) SetUpgradedConsensusState(ctx sdk.Context, planHeight int64, cs ibcexported.ConsensusState) error {
store := ctx.KVStore(k.storeKey)
bz, err := clienttypes.MarshalConsensusState(k.cdc, cs)
if err != nil {
return sdkerrors.Wrapf(sdkerrors.ErrInvalidRequest, "could not marshal consensus state: %v", err)
}

store.Set(types.UpgradedConsStateKey(lastHeight), bz)
store.Set(types.UpgradedConsStateKey(planHeight), bz)
return nil
}

Expand Down
5 changes: 2 additions & 3 deletions x/upgrade/keeper/keeper_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -161,7 +161,6 @@ func (s *KeeperTestSuite) TestScheduleUpgrade() {
},
expPass: true,
},

{
name: "unsuccessful schedule: invalid plan",
plan: types.Plan{
Expand Down Expand Up @@ -235,12 +234,12 @@ func (s *KeeperTestSuite) TestScheduleUpgrade() {
if tc.expPass {
s.Require().NoError(err, "valid test case failed")
if tc.plan.UpgradedClientState != nil {
got, err := s.app.UpgradeKeeper.GetUpgradedClient(s.ctx, tc.plan.Height-1)
got, err := s.app.UpgradeKeeper.GetUpgradedClient(s.ctx, tc.plan.Height)
s.Require().NoError(err)
s.Require().Equal(clientState, got, "upgradedClient not equal to expected value")
} else {
// check that upgraded client is empty if latest plan does not specify an upgraded client
got, err := s.app.UpgradeKeeper.GetUpgradedClient(s.ctx, tc.plan.Height-1)
got, err := s.app.UpgradeKeeper.GetUpgradedClient(s.ctx, tc.plan.Height)
s.Require().Error(err)
s.Require().Nil(got)
}
Expand Down