Test heartbeat service, restrict free heartbeats

Author: jannotti

agreement/gossip/networkFull_test.go

@@ -103,7 +103,7 @@ func spinNetwork(t *testing.T, nodesCount int, cfg config.Local) ([]*networkImpl
 			break
 		}
 	}
-	log.Infof("network established, %d nodes connected in %s", nodesCount, time.Now().Sub(start).String())
+	log.Infof("network established, %d nodes connected in %s", nodesCount, time.Since(start).String())
 	return networkImpls, msgCounters
 }
 

catchup/universalFetcher.go

@@ -88,7 +88,7 @@ func (uf *universalBlockFetcher) fetchBlock(ctx context.Context, round basics.Ro
 	} else {
 		return nil, nil, time.Duration(0), fmt.Errorf("fetchBlock: UniversalFetcher only supports HTTPPeer and UnicastPeer")
 	}
-	downloadDuration = time.Now().Sub(blockDownloadStartTime)
+	downloadDuration = time.Since(blockDownloadStartTime)
 	block, cert, err := processBlockBytes(fetchedBuf, round, address)
 	if err != nil {
 		return nil, nil, time.Duration(0), err

cmd/goal/clerk.go

@@ -221,8 +221,7 @@ func waitForCommit(client libgoal.Client, txid string, transactionLastValidRound
 		}
 
 		reportInfof(infoTxPending, txid, stat.LastRound)
-		// WaitForRound waits until round "stat.LastRound+1" is committed
-		stat, err = client.WaitForRound(stat.LastRound)
+		stat, err = client.WaitForRound(stat.LastRound + 1)
 		if err != nil {
 			return model.PendingTransactionResponse{}, fmt.Errorf(errorRequestFail, err)
 		}

cmd/loadgenerator/main.go

@@ -200,22 +200,23 @@ func waitForRound(restClient client.RestClient, cfg config, spendingRound bool)
 			time.Sleep(1 * time.Second)
 			continue
 		}
-		if isSpendRound(cfg, nodeStatus.LastRound) == spendingRound {
+		lastRound := nodeStatus.LastRound
+		if isSpendRound(cfg, lastRound) == spendingRound {
 			// time to send transactions.
 			return
 		}
 		if spendingRound {
-			fmt.Printf("Last round %d, waiting for spending round %d\n", nodeStatus.LastRound, nextSpendRound(cfg, nodeStatus.LastRound))
+			fmt.Printf("Last round %d, waiting for spending round %d\n", lastRound, nextSpendRound(cfg, nodeStatus.LastRound))
 		}
 		for {
 			// wait for the next round.
-			nodeStatus, err = restClient.WaitForBlock(basics.Round(nodeStatus.LastRound))
+			err = restClient.WaitForRoundWithTimeout(lastRound + 1)
 			if err != nil {
 				fmt.Fprintf(os.Stderr, "unable to wait for next round node status : %v", err)
-				time.Sleep(1 * time.Second)
 				break
 			}
-			if isSpendRound(cfg, nodeStatus.LastRound) == spendingRound {
+			lastRound++
+			if isSpendRound(cfg, lastRound) == spendingRound {
 				// time to send transactions.
 				return
 			}

daemon/algod/api/client/restClient.go

@@ -26,6 +26,7 @@ import (
 	"net/http"
 	"net/url"
 	"strings"
+	"time"
 
 	"github.com/google/go-querystring/query"
 
@@ -39,6 +40,8 @@ import (
 	"github.com/algorand/go-algorand/ledger/eval"
 	"github.com/algorand/go-algorand/ledger/ledgercore"
 	"github.com/algorand/go-algorand/protocol"
+	"github.com/algorand/go-algorand/rpcs"
+	"github.com/algorand/go-algorand/test/e2e-go/globals"
 )
 
 const (
@@ -283,12 +286,77 @@ func (client RestClient) Status() (response model.NodeStatusResponse, err error)
 	return
 }
 
-// WaitForBlock returns the node status after waiting for the given round.
-func (client RestClient) WaitForBlock(round basics.Round) (response model.NodeStatusResponse, err error) {
+// WaitForBlockAfter returns the node status after trying to wait for the given
+// round+1. This REST API has the documented misfeatures of returning after 1
+// minute, regardless of whether the given block has been reached.
+func (client RestClient) WaitForBlockAfter(round basics.Round) (response model.NodeStatusResponse, err error) {
 	err = client.get(&response, fmt.Sprintf("/v2/status/wait-for-block-after/%d/", round), nil)
 	return
 }
 
+// WaitForRound returns the node status after waiting for the given round.
+func (client RestClient) WaitForRound(round uint64, waitTime time.Duration) (status model.NodeStatusResponse, err error) {
+	timeout := time.NewTimer(waitTime)
+	for {
+		status, err = client.Status()
+		if err != nil {
+			return
+		}
+
+		if status.LastRound >= round {
+			return
+		}
+		select {
+		case <-timeout.C:
+			return model.NodeStatusResponse{}, fmt.Errorf("timeout waiting for round %v with last round = %v", round, status.LastRound)
+		case <-time.After(200 * time.Millisecond):
+		}
+	}
+}
+
+const singleRoundMaxTime = globals.MaxTimePerRound * 40
+
+// WaitForRoundWithTimeout waits for a given round to be reached. As it
+// waits, it returns early with an error if the wait time for any round exceeds
+// globals.MaxTimePerRound so we can alert when we're getting "hung" waiting.
+func (client RestClient) WaitForRoundWithTimeout(roundToWaitFor uint64) error {
+	status, err := client.Status()
+	if err != nil {
+		return err
+	}
+	lastRound := status.LastRound
+
+	// If node is already at or past target round, we're done
+	if lastRound >= roundToWaitFor {
+		return nil
+	}
+
+	roundComplete := make(chan error, 2)
+
+	for nextRound := lastRound + 1; lastRound < roundToWaitFor; nextRound++ {
+		roundStarted := time.Now()
+
+		go func(done chan error) {
+			stat, err := client.WaitForRound(nextRound, singleRoundMaxTime)
+			lastRound = stat.LastRound
+			done <- err
+		}(roundComplete)
+
+		select {
+		case lastError := <-roundComplete:
+			if lastError != nil {
+				close(roundComplete)
+				return lastError
+			}
+		case <-time.After(singleRoundMaxTime):
+			// we've timed out.
+			time := time.Since(roundStarted)
+			return fmt.Errorf("fixture.WaitForRound took %3.2f seconds between round %d and %d", time.Seconds(), lastRound, nextRound)
+		}
+	}
+	return nil
+}
+
 // HealthCheck does a health check on the potentially running node,
 // returning an error if the API is down
 func (client RestClient) HealthCheck() error {
@@ -301,14 +369,6 @@ func (client RestClient) ReadyCheck() error {
 	return client.get(nil, "/ready", nil)
 }
 
-// StatusAfterBlock waits for a block to occur then returns the StatusResponse after that block
-// blocks on the node end
-// Not supported
-func (client RestClient) StatusAfterBlock(blockNum uint64) (response model.NodeStatusResponse, err error) {
-	err = client.get(&response, fmt.Sprintf("/v2/status/wait-for-block-after/%d", blockNum), nil)
-	return
-}
-
 type pendingTransactionsParams struct {
 	Max    uint64 `url:"max"`
 	Format string `url:"format"`
@@ -557,6 +617,16 @@ func (client RestClient) RawBlock(round uint64) (response []byte, err error) {
 	return
 }
 
+// EncodedBlockCert takes a round and returns its parsed block and certificate
+func (client RestClient) EncodedBlockCert(round uint64) (blockCert rpcs.EncodedBlockCert, err error) {
+	resp, err := client.RawBlock(round)
+	if err != nil {
+		return
+	}
+	err = protocol.Decode(resp, &blockCert)
+	return
+}
+
 // Shutdown requests the node to shut itself down
 func (client RestClient) Shutdown() (err error) {
 	response := 1

data/transactions/verify/txn.go

@@ -224,8 +224,8 @@ func txnGroupBatchPrep(stxs []transactions.SignedTxn, contextHdr *bookkeeping.Bl
 		if stxn.Txn.Type == protocol.StateProofTx {
 			continue
 		}
-		if stxn.Txn.Type == protocol.HeartbeatTx && len(stxs) == 1 {
-			// TODO: Only allow free HB if the HbAddress is challenged
+		if stxn.Txn.Type == protocol.HeartbeatTx && stxn.Txn.Group.IsZero() {
+			// in apply.Heartbeat, we further confirm that the heartbeat is for a challenged node
 			continue
 		}
 		minFeeCount++

data/transactions/verify/txn_test.go

@@ -575,7 +575,7 @@ func TestPaysetGroups(t *testing.T) {
 	startPaysetGroupsTime := time.Now()
 	err := PaysetGroups(context.Background(), txnGroups, blkHdr, verificationPool, MakeVerifiedTransactionCache(50000), nil)
 	require.NoError(t, err)
-	paysetGroupDuration := time.Now().Sub(startPaysetGroupsTime)
+	paysetGroupDuration := time.Since(startPaysetGroupsTime)
 
 	// break the signature and see if it fails.
 	txnGroups[0][0].Sig[0] = txnGroups[0][0].Sig[0] + 1
@@ -609,7 +609,7 @@ func TestPaysetGroups(t *testing.T) {
 			// channel is closed without a return
 			require.Failf(t, "Channel got closed ?!", "")
 		} else {
-			actualDuration := time.Now().Sub(startPaysetGroupsTime)
+			actualDuration := time.Since(startPaysetGroupsTime)
 			if err == nil {
 				if actualDuration > 4*time.Second {
 					// it took at least 2.5 seconds more than it should have had!

data/transactions/verify/verifiedTxnCache_test.go

@@ -127,7 +127,7 @@ func BenchmarkGetUnverifiedTransactionGroups50(b *testing.B) {
 	for i := 0; i < measuringMultipler; i++ {
 		impl.GetUnverifiedTransactionGroups(queryTxnGroups, spec, protocol.ConsensusCurrentVersion)
 	}
-	duration := time.Now().Sub(startTime)
+	duration := time.Since(startTime)
 	// calculate time per 10K verified entries:
 	t := int(duration*10000) / (measuringMultipler * b.N)
 	b.ReportMetric(float64(t)/float64(time.Millisecond), "ms/10K_cache_compares")

heartbeat/service.go

@@ -26,7 +26,7 @@ import (
 	"github.com/algorand/go-algorand/data/bookkeeping"
 	"github.com/algorand/go-algorand/data/transactions"
 	"github.com/algorand/go-algorand/data/transactions/logic"
-	"github.com/algorand/go-algorand/ledger/eval"
+	"github.com/algorand/go-algorand/ledger/apply"
 	"github.com/algorand/go-algorand/logging"
 	"github.com/algorand/go-algorand/protocol"
 )
@@ -80,7 +80,7 @@ func (s *Service) Stop() {
 func (s *Service) findChallenged(rules config.ProposerPayoutRules) []account.ParticipationRecordForRound {
 	current := s.ledger.LastRound()
 
-	ch := eval.FindChallenge(rules, current, s.ledger, eval.ChRisky)
+	ch := apply.FindChallenge(rules, current, s.ledger, apply.ChRisky)
 	if ch.IsZero() {
 		return nil
 	}
@@ -93,8 +93,7 @@ func (s *Service) findChallenged(rules config.ProposerPayoutRules) []account.Par
 			continue
 		}
 		if acct.Status == basics.Online {
-			lastSeen := max(acct.LastProposed, acct.LastHeartbeat)
-			if ch.Failed(pr.Account, lastSeen) {
+			if ch.Failed(pr.Account, acct.LastSeen()) {
 				s.log.Infof(" %v needs a heartbeat\n", pr.Account)
 				found = append(found, pr)
 			}
@@ -135,6 +134,7 @@ func (s *Service) loop() {
 
 		for _, pr := range s.findChallenged(proto.Payouts) {
 			stxn := s.prepareHeartbeat(pr, lastHdr)
+			s.log.Infof("sending heartbeat %v for %v\n", stxn.Txn.HeartbeatTxnFields, pr.Account)
 			err = s.bcast.BroadcastInternalSignedTxGroup([]transactions.SignedTxn{stxn})
 			if err != nil {
 				s.log.Errorf("error broadcasting heartbeat %v for %v: %v", stxn, pr.Account, err)

heartbeat/service_test.go

@@ -210,7 +210,7 @@ func makeBlock(r basics.Round) bookkeeping.Block {
 	}
 }
 
-func TestHeartBeatOnlyWhenChallenged(t *testing.T) {
+func TestHeartbeatOnlyWhenChallenged(t *testing.T) {
 	partitiontest.PartitionTest(t)
 	t.Parallel()
 
@@ -234,9 +234,9 @@ func TestHeartBeatOnlyWhenChallenged(t *testing.T) {
 	// now they are online, but not challenged, so no heartbeat
 	acct.Status = basics.Online
 	acct.VoteKeyDilution = 100
-	otss := crypto.GenerateOneTimeSignatureSecrets(
-		basics.OneTimeIDForRound(ledger.LastRound(), acct.VoteKeyDilution).Batch,
-		5)
+	startBatch := basics.OneTimeIDForRound(ledger.LastRound(), acct.VoteKeyDilution).Batch
+	const batches = 50 // gives 50 * kd rounds = 5000
+	otss := crypto.GenerateOneTimeSignatureSecrets(startBatch, batches)
 	acct.VoteID = otss.OneTimeSignatureVerifier
 	ledger.addParticipant(joe, otss)
 	ledger.addParticipant(mary, otss)