Minimize flakiness in TestBasicPayouts

Flakiness seemed to come from one of two places

1) Testing balances after a proposal as sometimes wrong, if the
proposer proposed AGAIN before we performed the checks.

2) An off by one error such that if account01 (which proposed rarely)
proposed in exactly the lookback'th round after burning algos, we
thought it should not get paid, but it should.

Author: jannotti

test/e2e-go/features/incentives/payouts_test.go

@@ -49,21 +49,22 @@ func TestBasicPayouts(t *testing.T) {
 	// Make the seed lookback shorter, otherwise we need to wait 320 rounds to become IncentiveEligible.
 	const lookback = 32
 	fixture.FasterConsensus(protocol.ConsensusFuture, time.Second, lookback)
-	fmt.Printf("lookback is %d\n", lookback)
+	t.Logf("lookback is %d\n", lookback)
 	fixture.Setup(t, filepath.Join("nettemplates", "Payouts.json"))
 	defer fixture.Shutdown()
 
 	// Overview of this test:
 	// rereg to become eligible (must pay extra fee)
 	// show payouts are paid (from fees and bonuses)
 	// deplete feesink to ensure it's graceful
-
+	addressToNode := make(map[string]string)
 	clientAndAccount := func(name string) (libgoal.Client, model.Account) {
 		c := fixture.GetLibGoalClientForNamedNode(name)
 		accounts, err := fixture.GetNodeWalletsSortedByBalance(c)
 		a.NoError(err)
 		a.Len(accounts, 1)
-		fmt.Printf("Client %s is %v\n", name, accounts[0].Address)
+		t.Logf("Client %s is %v\n", name, accounts[0].Address)
+		addressToNode[accounts[0].Address] = name
 		return c, accounts[0]
 	}
 
@@ -74,31 +75,42 @@ func TestBasicPayouts(t *testing.T) {
 	data01 := rekeyreg(&fixture, a, c01, account01.Address, true)
 	data15 := rekeyreg(&fixture, a, c15, account15.Address, true)
 
+	// Wait a few rounds after rekeyreg, this means that `lookback` rounds after
+	// those rekeyregs, the nodes will be IncentiveEligible, but both will have
+	// too much stake to earn rewards.  Then we'll burn from account01, so
+	// lookback rounds after _that_ account01 will start earning.
+	client := fixture.LibGoalClient
+	status, err := client.Status()
+	a.NoError(err)
+	fixture.WaitForRoundWithTimeout(status.LastRound + 10)
+
 	// have account01 burn some money to get below the eligibility cap
 	// Starts with 100M, so burn 60M and get under 70M cap.
 	txn, err := c01.SendPaymentFromUnencryptedWallet(account01.Address, basics.Address{}.String(),
 		1000, 60_000_000_000_000, nil)
 	a.NoError(err)
 	burn, err := fixture.WaitForConfirmedTxn(uint64(txn.LastValid), txn.ID().String())
 	a.NoError(err)
+	burnRound := *burn.ConfirmedRound
+	t.Logf("burn round is %d", burnRound)
 	// sync up with the network
-	_, err = c01.WaitForRound(*burn.ConfirmedRound)
+	_, err = c01.WaitForRound(burnRound)
 	a.NoError(err)
 	data01, err = c01.AccountData(account01.Address)
 	a.NoError(err)
 
-	// Go 31 rounds after the burn happened. During this time, incentive
-	// eligibility is not in effect yet, so regardless of who proposes, they
-	// won't earn anything.
-	client := fixture.LibGoalClient
-	status, err := client.Status()
+	// Start advancing. IncentiveEligibile will come into effect 32 rounds after
+	// the rekeregs but earning will only happen 32 rounds after burnRound, and
+	// only for account01 (the one that burned to get under the cap).
+	status, err = client.Status()
 	a.NoError(err)
-	for status.LastRound < *burn.ConfirmedRound+lookback-1 {
+	account1earned := false
+	for !account1earned {
 		block, err := client.BookkeepingBlock(status.LastRound)
 		a.NoError(err)
 
-		fmt.Printf("block %d proposed by %v\n", status.LastRound, block.Proposer())
-		a.Zero(block.ProposerPayout()) // nobody is eligible yet (hasn't worked back to balance round)
+		t.Logf("block %d proposed by %s %v\n",
+			status.LastRound, addressToNode[block.Proposer().String()], block.Proposer())
 		a.EqualValues(bonus1, block.Bonus.Raw)
 
 		// all nodes agree the proposer proposed. The paranoia here is
@@ -109,7 +121,7 @@ func TestBasicPayouts(t *testing.T) {
 		// optimization, and it would cause failures here.  Interface changes
 		// made since they should make such a problem impossible, but...
 		for i, c := range []libgoal.Client{c15, c01, relay} {
-			fmt.Printf("checking block %v\n", block.Round())
+			t.Logf("checking block %v\n", block.Round())
 			bb, err := getblock(c, status.LastRound)
 			a.NoError(err)
 			a.Equal(block.Proposer(), bb.Proposer())
@@ -125,12 +137,26 @@ func TestBasicPayouts(t *testing.T) {
 		next, err := client.AccountData(block.Proposer().String())
 		a.NoError(err)
 		a.LessOrEqual(int(status.LastRound), int(next.LastProposed))
-		// regardless of proposer, nobody gets paid
 		switch block.Proposer().String() {
 		case account01.Address:
-			a.Equal(data01.MicroAlgos, next.MicroAlgos)
+			if uint64(block.Round()) < burnRound+lookback {
+				// until the burn is lookback rounds old, account01 can't earn
+				a.Zero(block.ProposerPayout())
+				a.Equal(data01.MicroAlgos, next.MicroAlgos)
+			} else {
+				a.EqualValues(bonus1, block.ProposerPayout().Raw)
+				// We'd like to do test if account one got paid the bonus:
+				// a.EqualValues(data01.MicroAlgos.Raw+bonus1, next.MicroAlgos.Raw)
+
+				// But we can't because it might have already proposed again. So
+				// let's check if it has received one OR two bonuses.
+				earned := int(next.MicroAlgos.Raw - data01.MicroAlgos.Raw)
+				a.True(earned == bonus1 || earned == 2*bonus1, "earned %d", earned)
+				account1earned = true
+			}
 			data01 = next
 		case account15.Address:
+			a.Zero(block.ProposerPayout())
 			a.Equal(data15.MicroAlgos, next.MicroAlgos)
 			data15 = next
 		default:
@@ -141,54 +167,6 @@ func TestBasicPayouts(t *testing.T) {
 		a.NoError(err)
 	}
 
-	// all nodes are in sync
-	for _, c := range []libgoal.Client{c15, c01, relay} {
-		_, err := c.WaitForRound(status.LastRound)
-		a.NoError(err)
-	}
-
-	// Wait until each have proposed, so we can see that 01 gets paid and 15 does not (too much balance)
-	proposed01 := false
-	proposed15 := false
-	for i := 0; !proposed01 || !proposed15; i++ {
-		status, err := client.Status()
-		a.NoError(err)
-		block, err := client.BookkeepingBlock(status.LastRound)
-		a.NoError(err)
-		a.EqualValues(bonus1, block.Bonus.Raw)
-
-		next, err := client.AccountData(block.Proposer().String())
-		a.NoError(err)
-		fmt.Printf(" proposer %v has %d after proposing round %d\n", block.Proposer(), next.MicroAlgos.Raw, status.LastRound)
-
-		// all nodes agree the proposer proposed
-		for i, c := range []libgoal.Client{c15, c01, relay} {
-			_, err := c.WaitForRound(status.LastRound)
-			a.NoError(err)
-			data, err := c.AccountData(block.Proposer().String())
-			a.NoError(err)
-			// <= in case one node is behind, and the others have already advanced
-			a.LessOrEqual(block.Round(), data.LastProposed, i)
-		}
-
-		// 01 would get paid (because under balance cap) 15 would not
-		switch block.Proposer().String() {
-		case account01.Address:
-			a.EqualValues(bonus1, block.ProposerPayout().Raw)
-			a.EqualValues(data01.MicroAlgos.Raw+bonus1, next.MicroAlgos.Raw) // 01 earns
-			proposed01 = true
-			data01 = next
-		case account15.Address:
-			a.Zero(block.ProposerPayout())
-			a.Equal(data15.MicroAlgos, next.MicroAlgos) // didn't earn
-			data15 = next
-			proposed15 = true
-		default:
-			a.Fail("bad proposer", "%v proposed", block.Proposer)
-		}
-		fixture.WaitForRoundWithTimeout(status.LastRound + 1)
-	}
-
 	// Now that we've proven incentives get paid, let's drain the FeeSink and
 	// ensure it happens gracefully.  Have account15 go offline so that (after
 	// 32 rounds) only account01 (who is eligible) is proposing, so drainage
@@ -203,7 +181,8 @@ func TestBasicPayouts(t *testing.T) {
 	offTxn, err := fixture.WaitForConfirmedTxn(uint64(offline.LastValid), offlineTxID)
 	a.NoError(err)
 
-	fmt.Printf(" c15 (%s) will be truly offline (not proposing) after round %d\n", account15.Address, *offTxn.ConfirmedRound+lookback)
+	t.Logf(" c15 (%s) will be truly offline (not proposing) after round %d\n",
+		account15.Address, *offTxn.ConfirmedRound+lookback)
 
 	var feesink basics.Address
 	for i := 0; i < 100; i++ {