fix: "Lazy" Stringers to defer Sprintf and Hash until logs print (#8845)

blockchain/v2/routine.go

@@ -58,7 +58,7 @@ func (rt *Routine) setMetrics(metrics *Metrics) {
 }
 
 func (rt *Routine) start() {
-	rt.logger.Info(fmt.Sprintf("%s: run", rt.name))
+	rt.logger.Info("routine start", "msg", log.NewLazySprintf("%s: run", rt.name))
 	running := atomic.CompareAndSwapUint32(rt.running, uint32(0), uint32(1))
 	if !running {
 		panic(fmt.Sprintf("%s is already running", rt.name))
@@ -98,7 +98,7 @@ func (rt *Routine) start() {
 			return
 		}
 		rt.metrics.EventsOut.With("routine", rt.name).Add(1)
-		rt.logger.Debug(fmt.Sprintf("%s: produced %T %+v", rt.name, oEvent, oEvent))
+		rt.logger.Debug("routine start", "msg", log.NewLazySprintf("%s: produced %T %+v", rt.name, oEvent, oEvent))
 
 		// Skip rTrySchedule and rProcessBlock events as they clutter the history
 		// due to their frequency.
@@ -118,7 +118,7 @@ func (rt *Routine) start() {
 
 // XXX: look into returning OpError in the net package
 func (rt *Routine) send(event Event) bool {
-	rt.logger.Debug(fmt.Sprintf("%s: received %T %+v", rt.name, event, event))
+	rt.logger.Debug("routine send", "msg", log.NewLazySprintf("%s: received %T %+v", rt.name, event, event))
 	if !rt.isRunning() {
 		return false
 	}
@@ -150,7 +150,7 @@ func (rt *Routine) stop() {
 		return
 	}
 
-	rt.logger.Info(fmt.Sprintf("%s: stop", rt.name))
+	rt.logger.Info("routine stop", "msg", log.NewLazySprintf("%s: stop", rt.name))
 	rt.queue.Dispose() // this should block until all queue items are free?
 }
 

consensus/reactor.go

@@ -1265,12 +1265,12 @@ func (ps *PeerState) SetHasVote(vote *types.Vote) {
 }
 
 func (ps *PeerState) setHasVote(height int64, round int32, voteType tmproto.SignedMsgType, index int32) {
-	logger := ps.logger.With(
+	ps.logger.Debug("setHasVote",
 		"peerH/R",
-		fmt.Sprintf("%d/%d", ps.PRS.Height, ps.PRS.Round),
+		log.NewLazySprintf("%d/%d", ps.PRS.Height, ps.PRS.Round),
 		"H/R",
-		fmt.Sprintf("%d/%d", height, round))
-	logger.Debug("setHasVote", "type", voteType, "index", index)
+		log.NewLazySprintf("%d/%d", height, round),
+		"type", voteType, "index", index)
 
 	// NOTE: some may be nil BitArrays -> no side effects.
 	psVotes := ps.getVoteBitArray(height, round, voteType)

consensus/state.go

@@ -981,7 +981,7 @@ func (cs *State) enterNewRound(height int64, round int32) {
 	if cs.Height != height || round < cs.Round || (cs.Round == round && cs.Step != cstypes.RoundStepNewHeight) {
 		logger.Debug(
 			"entering new round with invalid args",
-			"current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step),
+			"current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step),
 		)
 		return
 	}
@@ -990,7 +990,7 @@ func (cs *State) enterNewRound(height int64, round int32) {
 		logger.Debug("need to set a buffer and log message here for sanity", "start_time", cs.StartTime, "now", now)
 	}
 
-	logger.Debug("entering new round", "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step))
+	logger.Debug("entering new round", "current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step))
 
 	// increment validators if necessary
 	validators := cs.Validators
@@ -1063,12 +1063,12 @@ func (cs *State) enterPropose(height int64, round int32) {
 	if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPropose <= cs.Step) {
 		logger.Debug(
 			"entering propose step with invalid args",
-			"current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step),
+			"current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step),
 		)
 		return
 	}
 
-	logger.Debug("entering propose step", "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step))
+	logger.Debug("entering propose step", "current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step))
 
 	defer func() {
 		// Done enterPropose:
@@ -1230,7 +1230,7 @@ func (cs *State) enterPrevote(height int64, round int32) {
 	if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPrevote <= cs.Step) {
 		logger.Debug(
 			"entering prevote step with invalid args",
-			"current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step),
+			"current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step),
 		)
 		return
 	}
@@ -1241,7 +1241,7 @@ func (cs *State) enterPrevote(height int64, round int32) {
 		cs.newStep()
 	}()
 
-	logger.Debug("entering prevote step", "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step))
+	logger.Debug("entering prevote step", "current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step))
 
 	// Sign and broadcast vote as necessary
 	cs.doPrevote(height, round)
@@ -1290,7 +1290,7 @@ func (cs *State) enterPrevoteWait(height int64, round int32) {
 	if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPrevoteWait <= cs.Step) {
 		logger.Debug(
 			"entering prevote wait step with invalid args",
-			"current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step),
+			"current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step),
 		)
 		return
 	}
@@ -1302,7 +1302,7 @@ func (cs *State) enterPrevoteWait(height int64, round int32) {
 		))
 	}
 
-	logger.Debug("entering prevote wait step", "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step))
+	logger.Debug("entering prevote wait step", "current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step))
 
 	defer func() {
 		// Done enterPrevoteWait:
@@ -1326,12 +1326,12 @@ func (cs *State) enterPrecommit(height int64, round int32) {
 	if cs.Height != height || round < cs.Round || (cs.Round == round && cstypes.RoundStepPrecommit <= cs.Step) {
 		logger.Debug(
 			"entering precommit step with invalid args",
-			"current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step),
+			"current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step),
 		)
 		return
 	}
 
-	logger.Debug("entering precommit step", "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step))
+	logger.Debug("entering precommit step", "current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step))
 
 	defer func() {
 		// Done enterPrecommit:
@@ -1449,7 +1449,7 @@ func (cs *State) enterPrecommitWait(height int64, round int32) {
 		logger.Debug(
 			"entering precommit wait step with invalid args",
 			"triggered_timeout", cs.TriggeredTimeoutPrecommit,
-			"current", fmt.Sprintf("%v/%v", cs.Height, cs.Round),
+			"current", log.NewLazySprintf("%v/%v", cs.Height, cs.Round),
 		)
 		return
 	}
@@ -1461,7 +1461,7 @@ func (cs *State) enterPrecommitWait(height int64, round int32) {
 		))
 	}
 
-	logger.Debug("entering precommit wait step", "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step))
+	logger.Debug("entering precommit wait step", "current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step))
 
 	defer func() {
 		// Done enterPrecommitWait:
@@ -1480,12 +1480,12 @@ func (cs *State) enterCommit(height int64, commitRound int32) {
 	if cs.Height != height || cstypes.RoundStepCommit <= cs.Step {
 		logger.Debug(
 			"entering commit step with invalid args",
-			"current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step),
+			"current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step),
 		)
 		return
 	}
 
-	logger.Debug("entering commit step", "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step))
+	logger.Debug("entering commit step", "current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step))
 
 	defer func() {
 		// Done enterCommit:
@@ -1518,7 +1518,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,
 			)
 
@@ -1555,7 +1555,7 @@ func (cs *State) tryFinalizeCommit(height int64) {
 		// TODO: ^^ wait, why does it matter that we're a validator?
 		logger.Debug(
 			"failed attempt to finalize commit; we do not have the commit block",
-			"proposal_block", cs.ProposalBlock.Hash(),
+			"proposal_block", log.NewLazyBlockHash(cs.ProposalBlock),
 			"commit_block", blockID.Hash,
 		)
 		return
@@ -1571,7 +1571,7 @@ func (cs *State) finalizeCommit(height int64) {
 	if cs.Height != height || cs.Step != cstypes.RoundStepCommit {
 		logger.Debug(
 			"entering finalize commit step",
-			"current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step),
+			"current", log.NewLazySprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step),
 		)
 		return
 	}
@@ -1597,11 +1597,11 @@ func (cs *State) finalizeCommit(height int64) {
 
 	logger.Info(
 		"finalizing commit of block",
-		"hash", block.Hash(),
+		"hash", log.NewLazyBlockHash(block),
 		"root", block.AppHash,
 		"num_txs", len(block.Txs),
 	)
-	logger.Debug(fmt.Sprintf("%v", block))
+	logger.Debug("committed block", "block", log.NewLazySprintf("%v", block))
 
 	fail.Fail() // XXX
 
@@ -1918,7 +1918,7 @@ func (cs *State) handleCompleteProposal(blockHeight int64) {
 			cs.Logger.Debug(
 				"updating valid block to new proposal block",
 				"valid_round", cs.Round,
-				"valid_block_hash", cs.ProposalBlock.Hash(),
+				"valid_block_hash", log.NewLazyBlockHash(cs.ProposalBlock),
 			)
 
 			cs.ValidRound = cs.Round
@@ -2092,7 +2092,7 @@ func (cs *State) addVote(vote *types.Vote, peerID p2p.ID) (added bool, err error
 				} else {
 					cs.Logger.Debug(
 						"valid block we do not know about; set ProposalBlock=nil",
-						"proposal", cs.ProposalBlock.Hash(),
+						"proposal", log.NewLazyBlockHash(cs.ProposalBlock),
 						"block_id", blockID.Hash,
 					)
 

libs/log/lazy.go

@@ -0,0 +1,42 @@
+package log
+
+import (
+	"fmt"
+
+	tmbytes "github.com/tendermint/tendermint/libs/bytes"
+)
+
+type LazySprintf struct {
+	format string
+	args   []interface{}
+}
+
+// NewLazySprintf defers fmt.Sprintf until the Stringer interface is invoked.
+// This is particularly useful for avoiding calling Sprintf when debugging is not
+// active.
+func NewLazySprintf(format string, args ...interface{}) *LazySprintf {
+	return &LazySprintf{format, args}
+}
+
+func (l *LazySprintf) String() string {
+	return fmt.Sprintf(l.format, l.args...)
+}
+
+type LazyBlockHash struct {
+	block hashable
+}
+
+type hashable interface {
+	Hash() tmbytes.HexBytes
+}
+
+// NewLazyBlockHash defers block Hash until the Stringer interface is invoked.
+// This is particularly useful for avoiding calling Sprintf when debugging is not
+// active.
+func NewLazyBlockHash(block hashable) *LazyBlockHash {
+	return &LazyBlockHash{block}
+}
+
+func (l *LazyBlockHash) String() string {
+	return l.block.Hash().String()
+}

libs/log/tmfmt_logger.go

@@ -87,6 +87,12 @@ func (l tmfmtLogger) Log(keyvals ...interface{}) error {
 		if b, ok := keyvals[i+1].([]byte); ok {
 			keyvals[i+1] = strings.ToUpper(hex.EncodeToString(b))
 		}
+
+		// Realize stringers
+		if s, ok := keyvals[i+1].(fmt.Stringer); ok {
+			keyvals[i+1] = s.String()
+		}
+
 	}
 
 	// Form a custom Tendermint line

libs/os/os.go

@@ -8,6 +8,8 @@ import (
 	"os"
 	"os/signal"
 	"syscall"
+
+	"github.com/tendermint/tendermint/libs/log"
 )
 
 type logger interface {
@@ -21,7 +23,7 @@ func TrapSignal(logger logger, cb func()) {
 	signal.Notify(c, os.Interrupt, syscall.SIGTERM)
 	go func() {
 		for sig := range c {
-			logger.Info(fmt.Sprintf("captured %v, exiting...", sig))
+			logger.Info("signal trapped", "msg", log.NewLazySprintf("captured %v, exiting...", sig))
 			if cb != nil {
 				cb()
 			}

libs/service/service.go

@@ -136,7 +136,11 @@ func (bs *BaseService) Start() error {
 			atomic.StoreUint32(&bs.started, 0)
 			return ErrAlreadyStopped
 		}
-		bs.Logger.Info(fmt.Sprintf("Starting %v service", bs.name), "impl", bs.impl.String())
+		bs.Logger.Info("service start",
+			"msg",
+			log.NewLazySprintf("Starting %v service", bs.name),
+			"impl",
+			bs.impl.String())
 		err := bs.impl.OnStart()
 		if err != nil {
 			// revert flag
@@ -145,7 +149,11 @@ func (bs *BaseService) Start() error {
 		}
 		return nil
 	}
-	bs.Logger.Debug(fmt.Sprintf("Not starting %v service -- already started", bs.name), "impl", bs.impl)
+	bs.Logger.Debug("service start",
+		"msg",
+		log.NewLazySprintf("Not starting %v service -- already started", bs.name),
+		"impl",
+		bs.impl)
 	return ErrAlreadyStarted
 }
 
@@ -165,12 +173,20 @@ func (bs *BaseService) Stop() error {
 			atomic.StoreUint32(&bs.stopped, 0)
 			return ErrNotStarted
 		}
-		bs.Logger.Info(fmt.Sprintf("Stopping %v service", bs.name), "impl", bs.impl)
+		bs.Logger.Info("service stop",
+			"msg",
+			log.NewLazySprintf("Stopping %v service", bs.name),
+			"impl",
+			bs.impl)
 		bs.impl.OnStop()
 		close(bs.quit)
 		return nil
 	}
-	bs.Logger.Debug(fmt.Sprintf("Stopping %v service (already stopped)", bs.name), "impl", bs.impl)
+	bs.Logger.Debug("service stop",
+		"msg",
+		log.NewLazySprintf("Stopping %v service (already stopped)", bs.name),
+		"impl",
+		bs.impl)
 	return ErrAlreadyStopped
 }
 
@@ -183,7 +199,11 @@ func (bs *BaseService) OnStop() {}
 // will be returned if the service is running.
 func (bs *BaseService) Reset() error {
 	if !atomic.CompareAndSwapUint32(&bs.stopped, 1, 0) {
-		bs.Logger.Debug(fmt.Sprintf("Can't reset %v service. Not stopped", bs.name), "impl", bs.impl)
+		bs.Logger.Debug("service reset",
+			"msg",
+			log.NewLazySprintf("Can't reset %v service. Not stopped", bs.name),
+			"impl",
+			bs.impl)
 		return fmt.Errorf("can't reset running %s", bs.name)
 	}
 

p2p/conn/connection.go

@@ -352,7 +352,7 @@ func (c *MConnection) Send(chID byte, msgBytes []byte) bool {
 		return false
 	}
 
-	c.Logger.Debug("Send", "channel", chID, "conn", c, "msgBytes", fmt.Sprintf("%X", msgBytes))
+	c.Logger.Debug("Send", "channel", chID, "conn", c, "msgBytes", log.NewLazySprintf("%X", msgBytes))
 
 	// Send message to channel.
 	channel, ok := c.channelsIdx[chID]
@@ -369,7 +369,7 @@ func (c *MConnection) Send(chID byte, msgBytes []byte) bool {
 		default:
 		}
 	} else {
-		c.Logger.Debug("Send failed", "channel", chID, "conn", c, "msgBytes", fmt.Sprintf("%X", msgBytes))
+		c.Logger.Debug("Send failed", "channel", chID, "conn", c, "msgBytes", log.NewLazySprintf("%X", msgBytes))
 	}
 	return success
 }
@@ -381,7 +381,7 @@ func (c *MConnection) TrySend(chID byte, msgBytes []byte) bool {
 		return false
 	}
 
-	c.Logger.Debug("TrySend", "channel", chID, "conn", c, "msgBytes", fmt.Sprintf("%X", msgBytes))
+	c.Logger.Debug("TrySend", "channel", chID, "conn", c, "msgBytes", log.NewLazySprintf("%X", msgBytes))
 
 	// Send message to channel.
 	channel, ok := c.channelsIdx[chID]