Insufficient Outstanding Rewards Simulation Edge Case #3735

jaekwon · 2019-02-25T20:55:29Z

Rige edit:
the situation which causes this bug has been narrowed down within the (#3737) branch testing with make test_sim_gaia_fast

Just making a record... after merging the latest PRs from the weekend (see my branch jae/launch-rc-jae branch), I got a sim failure:

=== RUN   TestFullGaiaSimulation
Starting SimulateFromSeed with randomness created with seed 30
Randomized simulation params: {PastEvidenceFraction:0.7774658682560324 NumKeys:16 EvidenceFraction:0.19648335462094776 InitialLivenessWeightings:[78 7 1] LivenessTransitionMatrix:{weights:[[90 20 1] [10 50 5] [0 10 1000]] totals:[100 80 1006] n:3} BlockSizeTransitionMatrix:{weights:[[85 5 0] [15 92 1] [0 3 99]] totals:[100 100 100] n:3}}
Starting the simulation from time Sun May 11 02:28:48 UTC 3130, unixtime 36617279328
Selected randomly generated parameters for simulated genesis:
	{amount of steak per account: 593263161587, initially bonded validators: 16}
Selected randomly generated auth parameters:
	{CollectedFees: Params:Params: 
MaxMemoCharacters: 195
TxSigLimit: 7
TxSizeCostPerByte: 14
SigVerifyCostED25519: 877
SigVerifyCostSecp256k1: 607
}
Selected randomly generated bank parameters:
	{SendEnabled:true}
Selected randomly generated governance parameters:
	{StartingProposalID:1 Deposits:[] Votes:[] Proposals:[] DepositParams:Deposit Params:
  Min Deposit:        664stake
  Max Deposit Period: 22h14m41s VotingParams:Voting Params:
  Voting Period:      22h14m41s TallyParams:Tally Params:
  Quorum:             %!s(PANIC=runtime error: invalid memory address or nil pointer dereference)
  Threshold:          0.500000000000000000
  Veto:               0.334000000000000000
  Governance Penalty: 0.010000000000000000}
Selected randomly generated staking parameters:
	{Pool:Pool:
  Loose Tokens:  0
  Bonded Tokens: 0
  Token Supply:  0
  Bonded Ratio:  0.000000000000000000 Params:Params:
  Unbonding Time:    45h52m29s
  Max Validators:    98
  Max Entries:       0
  Bonded Coin Denom: stake LastTotalPower:<nil> LastValidatorPowers:[] Validators: Delegations: UnbondingDelegations:[] Redelegations:[] Exported:false}
Selected randomly generated slashing parameters:
	{Params:Slashing Params:
  MaxEvidenceAge:          45h52m29s
  SignedBlocksWindow:      394
  MinSignedPerWindow:      0.500000000000000000
  DowntimeJailDuration:    22h41m53s
  SlashFractionDoubleSign: 0.166666666666666667
  SlashFractionDowntime:   0.012345679012345679 SigningInfos:map[] MissedBlocks:map[]}
Selected randomly generated minting parameters:
	{Minter:{Inflation:0.500000000000000000 AnnualProvisions:0.000000000000000000} Params:{MintDenom:stake InflationRateChange:0.270000000000000000 InflationMax:0.200000000000000000 InflationMin:0.070000000000000000 GoalBonded:0.670000000000000000 BlocksPerYear:6311520}}
Selected randomly generated distribution parameters:
	{FeePool:{CommunityPool:} CommunityTax:0.050000000000000000 BaseProposerReward:0.180000000000000000 BonusProposerReward:0.290000000000000000 WithdrawAddrEnabled:false DelegatorWithdrawInfos:[] PreviousProposer: OutstandingRewards: ValidatorAccumulatedCommissions:[] ValidatorHistoricalRewards:[] ValidatorCurrentRewards:[] DelegatorStartingInfos:[] ValidatorSlashEvents:[]}
Simulating... block 53/400, operation 200/245. Panic with err
 negative coin amount
goroutine 12 [running]:
runtime/debug.Stack(0xc0009664f8, 0x2, 0x2)
	/usr/local/go/src/runtime/debug/stack.go:24 +0xa7
github.com/cosmos/cosmos-sdk/x/mock/simulation.SimulateFromSeed.func2(0xc000f72020, 0xc000f6c000, 0xc0005752e0)
	/Users/jae/gocode/src/github.com/cosmos/cosmos-sdk/x/mock/simulation/simulate.go:131 +0xb6
panic(0x1873be0, 0x1bd8e10)
	/usr/local/go/src/runtime/panic.go:513 +0x1b9
github.com/cosmos/cosmos-sdk/types.DecCoins.Sub(0xc0047d3360, 0x1, 0x1, 0xc0047d2fc0, 0x1, 0x1, 0x1be0780, 0xc000574fb0, 0xc0004f5000)
	/Users/jae/gocode/src/github.com/cosmos/cosmos-sdk/types/dec_coin.go:268 +0xbe
github.com/cosmos/cosmos-sdk/x/distribution/keeper.Keeper.withdrawDelegationRewards(0x1be0740, 0xc000574f50, 0xc0000ee230, 0xc0000ee230, 0x1be0740, 0xc000574fa0, 0x1be0780, 0xc000574fb0, 0xc0004f5000, 0x5, ...)
	/Users/jae/gocode/src/github.com/cosmos/cosmos-sdk/x/distribution/keeper/delegation.go:104 +0x5c7
github.com/cosmos/cosmos-sdk/x/distribution/keeper.Keeper.WithdrawDelegationRewards(0x1be0740, 0xc000574f50, 0xc0000ee230, 0xc0000ee230, 0x1be0740, 0xc000574fa0, 0x1be0780, 0xc000574fb0, 0xc0004f5000, 0x5, ...)
	/Users/jae/gocode/src/github.com/cosmos/cosmos-sdk/x/distribution/keeper/keeper.go:62 +0x20c
github.com/cosmos/cosmos-sdk/x/distribution/simulation.CanWithdrawInvariant.func1(0x1be7580, 0xc003ed9590, 0xc0047ad340, 0xc, 0x1be0740, 0xc000574fa0)
	/Users/jae/gocode/src/github.com/cosmos/cosmos-sdk/x/distribution/simulation/invariants.go:57 +0x329
github.com/cosmos/cosmos-sdk/x/distribution/simulation.AllInvariants.func1(0x1be7580, 0xc003ed9590, 0xc0047ad340, 0xc, 0x36, 0x0)
	/Users/jae/gocode/src/github.com/cosmos/cosmos-sdk/x/distribution/simulation/invariants.go:14 +0xbf
github.com/cosmos/cosmos-sdk/x/mock/simulation.PeriodicInvariant.func1(0x1be7580, 0xc003ed9590, 0xc0047ad340, 0xc, 0x0, 0x0)
	/Users/jae/gocode/src/github.com/cosmos/cosmos-sdk/x/mock/simulation/util.go:135 +0xc8
github.com/cosmos/cosmos-sdk/x/mock/simulation.assertAllInvariants(0xc000580e00, 0xc000580f00, 0xc000013680, 0x5, 0x5, 0x19b770d, 0xa, 0xc000f72020)
	/Users/jae/gocode/src/github.com/cosmos/cosmos-sdk/x/mock/simulation/util.go:23 +0x15c
github.com/cosmos/cosmos-sdk/x/mock/simulation.SimulateFromSeed(0x1bef4c0, 0xc000580e00, 0xc000580f00, 0x1b12b90, 0x1e, 0xc0000f02a0, 0xe, 0xe, 0xc000013680, 0x5, ...)
	/Users/jae/gocode/src/github.com/cosmos/cosmos-sdk/x/mock/simulation/simulate.go:156 +0x1962
github.com/cosmos/cosmos-sdk/cmd/gaia/app.TestFullGaiaSimulation(0xc000580e00)
	/Users/jae/gocode/src/github.com/cosmos/cosmos-sdk/cmd/gaia/app/sim_test.go:359 +0x339
testing.tRunner(0xc000580e00, 0x1b12b20)
	/usr/local/go/src/testing/testing.go:827 +0xbf
created by testing.(*T).Run
	/usr/local/go/src/testing/testing.go:878 +0x35c

Too many logs to display, instead writing to simulation_log_2019-02-25 09:49:44.txt

The text was updated successfully, but these errors were encountered:

rigelrozanski · 2019-02-25T21:31:27Z

reference command:
go test ./cmd/gaia/app -run TestFullGaiaSimulation -SimulationEnabled=true -SimulationNumBlocks=400 -SimulationVerbose=false -SimulationCommit=true -SimulationSeed=30 -v -timeout 24h

jackzampolin · 2019-02-25T21:38:20Z

Is there a copy of the logs?

rigelrozanski · 2019-02-25T21:40:52Z

jaekwon [21 minutes ago]
debug output of outstanding/rewards from around that function shows that it's way off.... here's the last few debug lines...

>>>> outstanding 454560506.432460236240670503stake rewards 
>>>> outstanding 454560506.432460236240670503stake rewards 
>>>> outstanding 454560506.432460236240670503stake rewards 
>>>> outstanding 454560506.432460236240670503stake rewards 482536446.922005148438991902stake```

rigelrozanski · 2019-02-25T22:55:36Z

Update the test
go test ./cmd/gaia/app -run TestFullGaiaSimulation -SimulationEnabled=true -SimulationNumBlocks=400 -SimulationVerbose=false -SimulationCommit=true -SimulationSeed=30 -v -timeout 24h

is failing on jae/undelegate_more (#3717) and is due to the bias introduced in x/mock/simulation/rand_util.go

guess it's not a part of CI because CI is passing? I'm going to re-trigger the CI

additionally - develop fails if we simply include the new updates to x/mock/simulation/rand_util.go

rigelrozanski · 2019-02-26T00:39:44Z

More specifically - I believe this bug is caused by the large presence of "undelegate max share" transactions (with this non-fixing change, the tests don't fail https://github.com/cosmos/cosmos-sdk/pull/3737/files#diff-5b2524ac49f8371d55e5d76aeef9b618R158).

I think that somehow an edge case within the distribution PR has come about through this test introduction - I suspect maybe a bug in the distr-hooks being called in distribution by the staking undelegate function

edit:

yeah the problem goes away if you eliminate the high probability of max-share undelegations… so it may have to do with the distribution hooks called during undelegations - but I’m thinking that your suggestion about it causing a totally new scenario (and the rarity of this bug - meaning vast majority of other scenarios don’t have this… so far we only know 1) - so I’m doubtful of my original opinion, I think if it does have to do with undelegations it may just be due to luck

cwgoes · 2019-02-26T13:43:41Z

Debugging more in #3746...

Tried merging the truncation fix (R4R: Alternative negative coins fix (floor multiplication) #3728), no luck
Isolated last operation with onOperation = true (BeginBlock)
Figured out which delegation the invariant fails on:

delegation 247 of 248
outstanding: 454560506.432459005262762026stake, rewards: 482536446.922005148438991902stake

cwgoes · 2019-02-26T18:39:24Z

Well this is possibly interesting:

rewards for final period (startingPeriod 177, endingPeriod 198) with stake 245062318940.226838227693785761: 9862.295748815299289701stake
D[2019-02-26|19:35:00.363] Commit synced                                commit=436F6D6D697449447B5B32303120313834203139332032303920323237203132382034322034312032353220313730203135342032353120313737203631203133352031353520323136203436203232352032313220313431203135392031333420343720313620323235203137352031383520393920313338203334203230375D3A33357D
allocating tokens: sumPrecommitPower 2425321, totalPower 3437104, previousProposer FEBDC6079DE334E695E3673F3391C18AC6E4E31A, votes [{{[107 109 87 172 245 246 64 66 112 217 111 242 215 216 81 239 217 106 201 140] 593263 {} [] 0} true {} [] 0} {{[51 53 198 104 78 148 62 99 166 114 226 114 57 213 213 243 189 198 136 161] 593263 {} [] 0} true {} [] 0} {{[67 156 141 101 153 123 176 233 186 71 233 134 151 110 191 4 255 255 85 98] 140574 {} [] 0} true {} [] 0} {{[57 178 135 219 182 202 201 227 198 148 87 150 23 11 149 23 241 126 39 25] 1011783 {} [] 0} false {} [] 0} {{[32 136 51 194 44 138 21 169 0 70 89 189 24 13 233 206 138 113 138 217] 1098221 {} [] 0} true {} [] 0}]
allocate to validator: val Validator
  Operator Address:           cosmosvaloper1l67uvpuauv6wd90rvuln8ywp3trwfcc6csx0hn
  Validator Consensus Pubkey: cosmosvalconspub1zcjduepqt2gf45pv33fls7c4n5ukzugj3r68z8jqpzhha0rd0qfepnetyxgs3ltmn7
  Jailed:                     true
  Status:                     Unbonding
  Tokens:                     978435872116
  Delegator Shares:           1074040715314.427507160608908083
  Description:                {mtKhGaArLP LZpHzksjbf iStyxpeFQq bZAnuFTQvl}
  Unbonding Height:           52
  Unbonding Completion Time:  3130-05-17 08:19:00 +0000 UTC
  Minimum Self Delegation:    1
  Commission:                 rate: 0.000000000000000000, maxRate: 0.000000000000000000, maxChangeRate: 0.000000000000000000, updateTime: 3130-05-13 20:58:16 +0000 UTC, tokens 1926535755.026056324633364950stake
remaining after: 250438521.500000008495388462stake
I[2019-02-26|19:35:00.364] Absent validator 39B287DBB6CAC9E3C6945796170B9517F17E2719 (PubKeySecp256k1{02012C55A53D783C97F0206807C05D1376887FEAED896CE536CB045E5E680F33EE}) at height 54, 19 missed, threshold 197 module=x/slashing 
I[2019-02-26|19:35:00.364] Confirmed double sign from 439C8D65997BB0E9BA47E986976EBF04FFFF5562 at height 39, age of 103385000000000 module=x/slashing 
I[2019-02-26|19:35:00.367] validator cosmosvaloper1gwwg6eve0wcwnwj8axrfwm4lqnll74tz43my0d slashed by slash factor of 0.166666666666666667; burned 0 tokens module=x/staking 
I[2019-02-26|19:35:00.367] validator cosmosvalcons1gwwg6eve0wcwnwj8axrfwm4lqnll74tzpzgcrv jailed module=x/staking 
rewards for final period (startingPeriod 177, endingPeriod 198) with stake 245062318940.226838227693785761: 482536446.922005148438991902stake

Did the validator get tokens on just the most recent block - could those be calculated incorrectly?

It seems like we should be iterating over a slash, for this final block on which we just allocated rewards, since those rewards would have been allocated after this validator was slashed.

cwgoes · 2019-02-26T19:15:08Z

The validator withdrew their self-delegation rewards at block 52, just after being slashed, so we now start iterating over slashes in block 53 (as intended)...

cwgoes · 2019-02-26T19:18:06Z

I wonder if there's an off-by-one bug somewhere.

cwgoes · 2019-02-26T20:42:33Z

For one, this situation is really weird, a validator was tombstoned and then keeps receiving rewards for two blocks after (LastCommit + 1 for the validator update delay), although that alone isn't a bug.

cwgoes · 2019-02-26T21:17:13Z

Some progress in #3750 (comment)

jackzampolin · 2019-03-01T20:12:56Z

Fixed by #3750

cwgoes · 2019-03-06T11:36:36Z

Fixed by #3750

Not then but it is now!

rigelrozanski mentioned this issue Feb 25, 2019

WIP: fixes for biased simulation RandomAmount #3737

Closed

5 tasks

rigelrozanski added T:Bug critical C:x/distribution distribution module related labels Feb 26, 2019

rigelrozanski changed the title ~~Simulation failure on Jae's local branch~~ Insufficient Outstanding Rewards Simulation Edge Case Feb 26, 2019

cwgoes added this to the v0.33.0 (Launch) milestone Feb 26, 2019

cwgoes mentioned this issue Feb 26, 2019

DNM: Debugging simulation failure #3746

Closed

cwgoes mentioned this issue Feb 26, 2019

R4R: Outstanding per-validator rewards; correctly handle same-BeginBlock redelegation-double-slash #3750

Merged

cwgoes mentioned this issue Feb 27, 2019

DNM: Adhoc invariant checks {LATEST debugging branch} #3759

Closed

cwgoes closed this as completed in #3750 Mar 6, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Insufficient Outstanding Rewards Simulation Edge Case #3735

Insufficient Outstanding Rewards Simulation Edge Case #3735

jaekwon commented Feb 25, 2019 •

edited by rigelrozanski

Loading

rigelrozanski commented Feb 25, 2019

jackzampolin commented Feb 25, 2019

rigelrozanski commented Feb 25, 2019

rigelrozanski commented Feb 25, 2019 •

edited

Loading

rigelrozanski commented Feb 26, 2019 •

edited

Loading

cwgoes commented Feb 26, 2019 •

edited

Loading

cwgoes commented Feb 26, 2019 •

edited

Loading

cwgoes commented Feb 26, 2019 •

edited

Loading

cwgoes commented Feb 26, 2019 •

edited

Loading

cwgoes commented Feb 26, 2019

cwgoes commented Feb 26, 2019

jackzampolin commented Mar 1, 2019

cwgoes commented Mar 6, 2019

Insufficient Outstanding Rewards Simulation Edge Case #3735

Insufficient Outstanding Rewards Simulation Edge Case #3735

Comments

jaekwon commented Feb 25, 2019 • edited by rigelrozanski Loading

rigelrozanski commented Feb 25, 2019

jackzampolin commented Feb 25, 2019

rigelrozanski commented Feb 25, 2019

rigelrozanski commented Feb 25, 2019 • edited Loading

rigelrozanski commented Feb 26, 2019 • edited Loading

cwgoes commented Feb 26, 2019 • edited Loading

cwgoes commented Feb 26, 2019 • edited Loading

cwgoes commented Feb 26, 2019 • edited Loading

cwgoes commented Feb 26, 2019 • edited Loading

cwgoes commented Feb 26, 2019

cwgoes commented Feb 26, 2019

jackzampolin commented Mar 1, 2019

cwgoes commented Mar 6, 2019

jaekwon commented Feb 25, 2019 •

edited by rigelrozanski

Loading

rigelrozanski commented Feb 25, 2019 •

edited

Loading

rigelrozanski commented Feb 26, 2019 •

edited

Loading

cwgoes commented Feb 26, 2019 •

edited

Loading

cwgoes commented Feb 26, 2019 •

edited

Loading

cwgoes commented Feb 26, 2019 •

edited

Loading

cwgoes commented Feb 26, 2019 •

edited

Loading