Merge remote-tracking branch 'origin/v0.34.x' into priority_mempool_backport

test/e2e/node/main.go

@@ -111,7 +111,7 @@ func startApp(cfg *Config) error {
 	if err != nil {
 		return err
 	}
-	logger.Info(fmt.Sprintf("Server listening on %v (%v protocol)", cfg.Listen, cfg.Protocol))
+	logger.Info("start app", "msg", log.NewLazySprintf("Server listening on %v (%v protocol)", cfg.Listen, cfg.Protocol))
 	return nil
 }
 
@@ -261,7 +261,7 @@ func startSigner(cfg *Config) error {
 	if err != nil {
 		return err
 	}
-	logger.Info(fmt.Sprintf("Remote signer connecting to %v", cfg.PrivValServer))
+	logger.Info("start signer", "msg", log.NewLazySprintf("Remote signer connecting to %v", cfg.PrivValServer))
 	return nil
 }
 

test/e2e/runner/cleanup.go

@@ -6,6 +6,7 @@ import (
 	"os"
 	"path/filepath"
 
+	"github.com/tendermint/tendermint/libs/log"
 	e2e "github.com/tendermint/tendermint/test/e2e/pkg"
 )
 
@@ -59,7 +60,7 @@ func cleanupDir(dir string) error {
 		return err
 	}
 
-	logger.Info(fmt.Sprintf("Removing testnet directory %q", dir))
+	logger.Info("cleanup dir", "msg", log.NewLazySprintf("Removing testnet directory %q", dir))
 
 	// On Linux, some local files in the volume will be owned by root since Tendermint
 	// runs as root inside the container, so we need to clean them up from within a

test/e2e/runner/load.go

@@ -8,6 +8,7 @@ import (
 	"math"
 	"time"
 
+	"github.com/tendermint/tendermint/libs/log"
 	rpchttp "github.com/tendermint/tendermint/rpc/client/http"
 	e2e "github.com/tendermint/tendermint/test/e2e/pkg"
 	"github.com/tendermint/tendermint/types"
@@ -35,7 +36,7 @@ func Load(ctx context.Context, testnet *e2e.Testnet, multiplier int) error {
 	defer cancel()
 
 	// Spawn job generator and processors.
-	logger.Info(fmt.Sprintf("Starting transaction load (%v workers)...", concurrency))
+	logger.Info("load", "msg", log.NewLazySprintf("Starting transaction load (%v workers)...", concurrency))
 	started := time.Now()
 
 	go loadGenerate(ctx, chTx, multiplier)
@@ -58,7 +59,7 @@ func Load(ctx context.Context, testnet *e2e.Testnet, multiplier int) error {
 			if success == 0 {
 				return errors.New("failed to submit any transactions")
 			}
-			logger.Info(fmt.Sprintf("Ending transaction load after %v txs (%.1f tx/s)...",
+			logger.Info("load", "msg", log.NewLazySprintf("Ending transaction load after %v txs (%.1f tx/s)...",
 				success, float64(success)/time.Since(started).Seconds()))
 			return nil
 		}

test/e2e/runner/perturb.go

@@ -4,6 +4,7 @@ import (
 	"fmt"
 	"time"
 
+	"github.com/tendermint/tendermint/libs/log"
 	rpctypes "github.com/tendermint/tendermint/rpc/core/types"
 	e2e "github.com/tendermint/tendermint/test/e2e/pkg"
 )
@@ -28,7 +29,7 @@ func PerturbNode(node *e2e.Node, perturbation e2e.Perturbation) (*rpctypes.Resul
 	testnet := node.Testnet
 	switch perturbation {
 	case e2e.PerturbationDisconnect:
-		logger.Info(fmt.Sprintf("Disconnecting node %v...", node.Name))
+		logger.Info("perturb node", "msg", log.NewLazySprintf("Disconnecting node %v...", node.Name))
 		if err := execDocker("network", "disconnect", testnet.Name+"_"+testnet.Name, node.Name); err != nil {
 			return nil, err
 		}
@@ -38,7 +39,7 @@ func PerturbNode(node *e2e.Node, perturbation e2e.Perturbation) (*rpctypes.Resul
 		}
 
 	case e2e.PerturbationKill:
-		logger.Info(fmt.Sprintf("Killing node %v...", node.Name))
+		logger.Info("perturb node", "msg", log.NewLazySprintf("Killing node %v...", node.Name))
 		if err := execCompose(testnet.Dir, "kill", "-s", "SIGKILL", node.Name); err != nil {
 			return nil, err
 		}
@@ -47,7 +48,7 @@ func PerturbNode(node *e2e.Node, perturbation e2e.Perturbation) (*rpctypes.Resul
 		}
 
 	case e2e.PerturbationPause:
-		logger.Info(fmt.Sprintf("Pausing node %v...", node.Name))
+		logger.Info("perturb node", "msg", log.NewLazySprintf("Pausing node %v...", node.Name))
 		if err := execCompose(testnet.Dir, "pause", node.Name); err != nil {
 			return nil, err
 		}
@@ -57,7 +58,7 @@ func PerturbNode(node *e2e.Node, perturbation e2e.Perturbation) (*rpctypes.Resul
 		}
 
 	case e2e.PerturbationRestart:
-		logger.Info(fmt.Sprintf("Restarting node %v...", node.Name))
+		logger.Info("perturb node", "msg", log.NewLazySprintf("Restarting node %v...", node.Name))
 		if err := execCompose(testnet.Dir, "restart", node.Name); err != nil {
 			return nil, err
 		}
@@ -70,6 +71,8 @@ func PerturbNode(node *e2e.Node, perturbation e2e.Perturbation) (*rpctypes.Resul
 	if err != nil {
 		return nil, err
 	}
-	logger.Info(fmt.Sprintf("Node %v recovered at height %v", node.Name, status.SyncInfo.LatestBlockHeight))
+	logger.Info("perturb node",
+		"msg",
+		log.NewLazySprintf("Node %v recovered at height %v", node.Name, status.SyncInfo.LatestBlockHeight))
 	return status, nil
 }

test/e2e/runner/setup.go

@@ -21,6 +21,7 @@ import (
 
 	"github.com/tendermint/tendermint/config"
 	"github.com/tendermint/tendermint/crypto/ed25519"
+	"github.com/tendermint/tendermint/libs/log"
 	"github.com/tendermint/tendermint/p2p"
 	"github.com/tendermint/tendermint/privval"
 	e2e "github.com/tendermint/tendermint/test/e2e/pkg"
@@ -41,7 +42,7 @@ const (
 
 // Setup sets up the testnet configuration.
 func Setup(testnet *e2e.Testnet) error {
-	logger.Info(fmt.Sprintf("Generating testnet files in %q", testnet.Dir))
+	logger.Info("setup", "msg", log.NewLazySprintf("Generating testnet files in %q", testnet.Dir))
 
 	err := os.MkdirAll(testnet.Dir, os.ModePerm)
 	if err != nil {

test/e2e/runner/start.go

@@ -5,6 +5,7 @@ import (
 	"sort"
 	"time"
 
+	"github.com/tendermint/tendermint/libs/log"
 	e2e "github.com/tendermint/tendermint/test/e2e/pkg"
 )
 
@@ -48,7 +49,7 @@ func Start(testnet *e2e.Testnet) error {
 		if _, err := waitForNode(node, 0, 15*time.Second); err != nil {
 			return err
 		}
-		logger.Info(fmt.Sprintf("Node %v up on http://127.0.0.1:%v", node.Name, node.ProxyPort))
+		logger.Info("start", "msg", log.NewLazySprintf("Node %v up on http://127.0.0.1:%v", node.Name, node.ProxyPort))
 	}
 
 	networkHeight := testnet.InitialHeight
@@ -103,7 +104,7 @@ func Start(testnet *e2e.Testnet) error {
 		if err != nil {
 			return err
 		}
-		logger.Info(fmt.Sprintf("Node %v up on http://127.0.0.1:%v at height %v",
+		logger.Info("start", "msg", log.NewLazySprintf("Node %v up on http://127.0.0.1:%v at height %v",
 			node.Name, node.ProxyPort, status.SyncInfo.LatestBlockHeight))
 	}
 

test/e2e/runner/wait.go

@@ -1,9 +1,9 @@
 package main
 
 import (
-	"fmt"
 	"time"
 
+	"github.com/tendermint/tendermint/libs/log"
 	e2e "github.com/tendermint/tendermint/test/e2e/pkg"
 )
 
@@ -19,7 +19,7 @@ func Wait(testnet *e2e.Testnet, blocks int64) error {
 
 // WaitUntil waits until a given height has been reached.
 func WaitUntil(testnet *e2e.Testnet, height int64) error {
-	logger.Info(fmt.Sprintf("Waiting for all nodes to reach height %v...", height))
+	logger.Info("wait until", "msg", log.NewLazySprintf("Waiting for all nodes to reach height %v...", height))
 	_, err := waitForAllNodes(testnet, height, waitingTime(len(testnet.Nodes)))
 	if err != nil {
 		return err

test/maverick/consensus/misbehavior.go

@@ -5,6 +5,7 @@ import (
 
 	tmcon "github.com/tendermint/tendermint/consensus"
 	cstypes "github.com/tendermint/tendermint/consensus/types"
+	"github.com/tendermint/tendermint/libs/log"
 	tmproto "github.com/tendermint/tendermint/proto/tendermint/types"
 	"github.com/tendermint/tendermint/types"
 )
@@ -300,7 +301,7 @@ func defaultReceivePrevote(cs *State, vote *types.Vote) {
 			} else {
 				cs.Logger.Info(
 					"valid block we do not know about; set ProposalBlock=nil",
-					"proposal", cs.ProposalBlock.Hash(),
+					"proposal", log.NewLazyBlockHash(cs.ProposalBlock),
 					"blockID", blockID.Hash,
 				)
 

test/maverick/consensus/state.go

@@ -242,7 +242,7 @@ func (cs *State) enterPropose(height int64, round int32) {
 	logger := cs.Logger.With("height", height, "round", round)
 
 	if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPropose <= cs.Step) {
-		logger.Debug(fmt.Sprintf(
+		logger.Debug("enter propose", "msg", log.NewLazySprintf(
 			"enterPropose(%v/%v): Invalid args. Current step: %v/%v/%v",
 			height,
 			round,
@@ -251,7 +251,9 @@ func (cs *State) enterPropose(height int64, round int32) {
 			cs.Step))
 		return
 	}
-	logger.Info(fmt.Sprintf("enterPropose(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
+	logger.Info("enter propose",
+		"msg",
+		log.NewLazySprintf("enterPropose(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
 
 	defer func() {
 		// Done enterPropose:
@@ -279,7 +281,7 @@ func (cs *State) enterPropose(height int64, round int32) {
 // Otherwise vote nil.
 func (cs *State) enterPrevote(height int64, round int32) {
 	if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPrevote <= cs.Step) {
-		cs.Logger.Debug(fmt.Sprintf(
+		cs.Logger.Debug("enter prevote", "msg", log.NewLazySprintf(
 			"enterPrevote(%v/%v): Invalid args. Current step: %v/%v/%v",
 			height,
 			round,
@@ -295,7 +297,9 @@ func (cs *State) enterPrevote(height int64, round int32) {
 		cs.newStep()
 	}()
 
-	cs.Logger.Debug(fmt.Sprintf("enterPrevote(%v/%v); current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
+	cs.Logger.Debug("enter prevote",
+		"msg",
+		log.NewLazySprintf("enterPrevote(%v/%v); current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
 
 	// Sign and broadcast vote as necessary
 	if b, ok := cs.misbehaviors[cs.Height]; ok {
@@ -318,17 +322,20 @@ func (cs *State) enterPrecommit(height int64, round int32) {
 	logger := cs.Logger.With("height", height, "round", round)
 
 	if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPrecommit <= cs.Step) {
-		logger.Debug(fmt.Sprintf(
-			"enterPrecommit(%v/%v): Invalid args. Current step: %v/%v/%v",
-			height,
-			round,
-			cs.Height,
-			cs.Round,
-			cs.Step))
+		logger.Debug("enter precommit",
+			"msg",
+			log.NewLazySprintf("enterPrecommit(%v/%v): Invalid args. Current step: %v/%v/%v",
+				height,
+				round,
+				cs.Height,
+				cs.Round,
+				cs.Step))
 		return
 	}
 
-	logger.Info(fmt.Sprintf("enterPrecommit(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
+	logger.Info("enter precommit",
+		"msg",
+		log.NewLazySprintf("enterPrecommit(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
 
 	defer func() {
 		// Done enterPrecommit:
@@ -372,7 +379,9 @@ func (cs *State) addVote(
 			return
 		}
 
-		cs.Logger.Info(fmt.Sprintf("Added to lastPrecommits: %v", cs.LastCommit.StringShort()))
+		cs.Logger.Info("add vote",
+			"msg",
+			log.NewLazySprintf("Added to lastPrecommits: %v", cs.LastCommit.StringShort()))
 		_ = cs.eventBus.PublishEventVote(types.EventDataVote{Vote: vote})
 		cs.evsw.FireEvent(types.EventVote, vote)
 
@@ -1103,7 +1112,7 @@ func (cs *State) enterNewRound(height int64, round int32) {
 	logger := cs.Logger.With("height", height, "round", round)
 
 	if cs.Height != height || round < cs.Round || (cs.Round == round && cs.Step != cstypes.RoundStepNewHeight) {
-		logger.Debug(fmt.Sprintf(
+		logger.Debug("enter new round", "msg", log.NewLazySprintf(
 			"enterNewRound(%v/%v): Invalid args. Current step: %v/%v/%v",
 			height,
 			round,
@@ -1117,7 +1126,9 @@ func (cs *State) enterNewRound(height int64, round int32) {
 		logger.Debug("need to set a buffer and log message here for sanity", "startTime", cs.StartTime, "now", now)
 	}
 
-	logger.Info(fmt.Sprintf("enterNewRound(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
+	logger.Info("enter new round",
+		"msg",
+		log.NewLazySprintf("enterNewRound(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
 
 	// Increment validators if necessary
 	validators := cs.Validators
@@ -1217,7 +1228,9 @@ func (cs *State) defaultDecideProposal(height int64, round int32) {
 			cs.sendInternalMessage(msgInfo{&tmcon.BlockPartMessage{Height: cs.Height, Round: cs.Round, Part: part}, ""})
 		}
 		cs.Logger.Info("Signed proposal", "height", height, "round", round, "proposal", proposal)
-		cs.Logger.Debug(fmt.Sprintf("Signed proposal block: %v", block))
+		cs.Logger.Debug("default decide proposal",
+			"msg",
+			log.NewLazySprintf("Signed proposal block: %v", block))
 	} else if !cs.replayMode {
 		cs.Logger.Error("enterPropose: Error signing proposal", "height", height, "round", round, "err", err)
 	}
@@ -1281,20 +1294,24 @@ func (cs *State) enterPrevoteWait(height int64, round int32) {
 	logger := cs.Logger.With("height", height, "round", round)
 
 	if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPrevoteWait <= cs.Step) {
-		logger.Debug(fmt.Sprintf(
-			"enterPrevoteWait(%v/%v): Invalid args. Current step: %v/%v/%v",
-			height,
-			round,
-			cs.Height,
-			cs.Round,
-			cs.Step))
+		logger.Debug("enter prevote wait",
+			"msg",
+			log.NewLazySprintf(
+				"enterPrevoteWait(%v/%v): Invalid args. Current step: %v/%v/%v",
+				height,
+				round,
+				cs.Height,
+				cs.Round,
+				cs.Step))
 		return
 	}
 	if !cs.Votes.Prevotes(round).HasTwoThirdsAny() {
 		panic(fmt.Sprintf("enterPrevoteWait(%v/%v), but Prevotes does not have any +2/3 votes", height, round))
 	}
 
-	logger.Debug(fmt.Sprintf("enterPrevoteWait(%v/%v); current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
+	logger.Debug("enter prevote wait",
+		"msg",
+		log.NewLazySprintf("enterPrevoteWait(%v/%v); current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
 
 	defer func() {
 		// Done enterPrevoteWait:
@@ -1311,8 +1328,9 @@ func (cs *State) enterPrecommitWait(height int64, round int32) {
 	logger := cs.Logger.With("height", height, "round", round)
 
 	if cs.Height != height || round < cs.Round || (cs.Round == round && cs.TriggeredTimeoutPrecommit) {
-		logger.Debug(
-			fmt.Sprintf(
+		logger.Debug("state enter precommit wait",
+			"msg",
+			log.NewLazySprintf(
 				"enterPrecommitWait(%v/%v): Invalid args. "+
 					"Current state is Height/Round: %v/%v/, TriggeredTimeoutPrecommit:%v",
 				height, round, cs.Height, cs.Round, cs.TriggeredTimeoutPrecommit))
@@ -1321,7 +1339,9 @@ func (cs *State) enterPrecommitWait(height int64, round int32) {
 	if !cs.Votes.Precommits(round).HasTwoThirdsAny() {
 		panic(fmt.Sprintf("enterPrecommitWait(%v/%v), but Precommits does not have any +2/3 votes", height, round))
 	}
-	logger.Info(fmt.Sprintf("enterPrecommitWait(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
+	logger.Info("enter precommit wait",
+		"msg",
+		log.NewLazySprintf("enterPrecommitWait(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step))
 
 	defer func() {
 		// Done enterPrecommitWait:
@@ -1338,16 +1358,19 @@ func (cs *State) enterCommit(height int64, commitRound int32) {
 	logger := cs.Logger.With("height", height, "commitRound", commitRound)
 
 	if cs.Height != height || cstypes.RoundStepCommit <= cs.Step {
-		logger.Debug(fmt.Sprintf(
-			"enterCommit(%v/%v): Invalid args. Current step: %v/%v/%v",
-			height,
-			commitRound,
-			cs.Height,
-			cs.Round,
-			cs.Step))
+		logger.Debug("enter commit",
+			"msg",
+			log.NewLazySprintf("enterCommit(%v/%v): Invalid args. Current step: %v/%v/%v",
+				height,
+				commitRound,
+				cs.Height,
+				cs.Round,
+				cs.Step))
 		return
 	}
-	logger.Info(fmt.Sprintf("enterCommit(%v/%v). Current: %v/%v/%v", height, commitRound, cs.Height, cs.Round, cs.Step))
+	logger.Info("enter commit",
+		"msg",
+		log.NewLazySprintf("enterCommit(%v/%v). Current: %v/%v/%v", height, commitRound, cs.Height, cs.Round, cs.Step))
 
 	defer func() {
 		// Done enterCommit:
@@ -1380,7 +1403,7 @@ func (cs *State) enterCommit(height int64, commitRound int32) {
 		if !cs.ProposalBlockParts.HasHeader(blockID.PartSetHeader) {
 			logger.Info(
 				"commit is for a block we do not know about; set ProposalBlock=nil",
-				"proposal", cs.ProposalBlock.Hash(),
+				"proposal", log.NewLazyBlockHash(cs.ProposalBlock),
 				"commit", blockID.Hash,
 			)
 
@@ -1417,7 +1440,7 @@ func (cs *State) tryFinalizeCommit(height int64) {
 		// TODO: ^^ wait, why does it matter that we're a validator?
 		logger.Debug(
 			"attempt to finalize failed; we do not have the commit block",
-			"proposal-block", cs.ProposalBlock.Hash(),
+			"proposal-block", log.NewLazyBlockHash(cs.ProposalBlock),
 			"commit-block", blockID.Hash,
 		)
 		return
@@ -1430,12 +1453,13 @@ func (cs *State) tryFinalizeCommit(height int64) {
 // Increment height and goto cstypes.RoundStepNewHeight
 func (cs *State) finalizeCommit(height int64) {
 	if cs.Height != height || cs.Step != cstypes.RoundStepCommit {
-		cs.Logger.Debug(fmt.Sprintf(
-			"finalizeCommit(%v): Invalid args. Current step: %v/%v/%v",
-			height,
-			cs.Height,
-			cs.Round,
-			cs.Step))
+		cs.Logger.Debug("finalize commit",
+			"msg",
+			log.NewLazySprintf("finalizeCommit(%v): Invalid args. Current step: %v/%v/%v",
+				height,
+				cs.Height,
+				cs.Round,
+				cs.Step))
 		return
 	}
 
@@ -1461,7 +1485,7 @@ func (cs *State) finalizeCommit(height int64) {
 		"root", block.AppHash,
 		"N", len(block.Txs),
 	)
-	cs.Logger.Debug(fmt.Sprintf("%v", block))
+	cs.Logger.Debug("finalize commit", "msg", log.NewLazySprintf("%v", block))
 
 	fail.Fail() // XXX