diff --git a/abci/client/grpc_client.go b/abci/client/grpc_client.go index 1e163056d..bd255bebe 100644 --- a/abci/client/grpc_client.go +++ b/abci/client/grpc_client.go @@ -3,7 +3,6 @@ package abciclient import ( "context" "errors" - "fmt" "net" "sync" "time" @@ -65,7 +64,7 @@ RETRY_LOOP: if cli.mustConnect { return err } - cli.logger.Error(fmt.Sprintf("abci.grpcClient failed to connect to %v. Retrying...\n", cli.addr), "err", err) + cli.logger.Error("abci.grpcClient failed to connect, Retrying...", "addr", cli.addr, "err", err) timer.Reset(time.Second * dialRetryIntervalSeconds) select { case <-ctx.Done(): diff --git a/abci/client/socket_client.go b/abci/client/socket_client.go index 7dfcf76cc..d023e7074 100644 --- a/abci/client/socket_client.go +++ b/abci/client/socket_client.go @@ -67,8 +67,11 @@ func (cli *socketClient) OnStart(ctx context.Context) error { if cli.mustConnect { return err } - cli.logger.Error(fmt.Sprintf("abci.socketClient failed to connect to %v. Retrying after %vs...", - cli.addr, dialRetryIntervalSeconds), "err", err) + + cli.logger.Error("abci.socketClient failed to connect, retrying after", + "retry_after", dialRetryIntervalSeconds, + "target", cli.addr, + "err", err) timer.Reset(time.Second * dialRetryIntervalSeconds) select { @@ -77,7 +80,6 @@ func (cli *socketClient) OnStart(ctx context.Context) error { case <-timer.C: continue } - } cli.conn = conn diff --git a/internal/blocksync/reactor.go b/internal/blocksync/reactor.go index c1b032b03..9f0a76089 100644 --- a/internal/blocksync/reactor.go +++ b/internal/blocksync/reactor.go @@ -469,12 +469,10 @@ func (r *Reactor) poolRoutine(ctx context.Context, stateSynced bool, blockSyncCh lastAdvance = r.pool.LastAdvance() ) - r.logger.Debug( - "consensus ticker", + r.logger.Debug("consensus ticker", "num_pending", numPending, "total", lenRequesters, - "height", height, - ) + "height", height) switch { diff --git a/internal/consensus/reactor.go b/internal/consensus/reactor.go index 3ba95c836..12317a9b4 100644 --- a/internal/consensus/reactor.go +++ b/internal/consensus/reactor.go @@ -10,6 +10,7 @@ import ( cstypes "github.com/tendermint/tendermint/internal/consensus/types" "github.com/tendermint/tendermint/internal/eventbus" + tmstrings "github.com/tendermint/tendermint/internal/libs/strings" "github.com/tendermint/tendermint/internal/p2p" sm "github.com/tendermint/tendermint/internal/state" "github.com/tendermint/tendermint/libs/bits" @@ -1113,7 +1114,7 @@ func (r *Reactor) handleDataMessage(ctx context.Context, envelope *p2p.Envelope, } if r.WaitSync() { - logger.Info("ignoring message received during sync", "msg", fmt.Sprintf("%T", msgI)) + logger.Info("ignoring message received during sync", "msg", tmstrings.LazySprintf("%T", msgI)) return nil } diff --git a/internal/consensus/state.go b/internal/consensus/state.go index a7a0b8fed..5b10d4b50 100644 --- a/internal/consensus/state.go +++ b/internal/consensus/state.go @@ -21,6 +21,7 @@ import ( "github.com/tendermint/tendermint/internal/eventbus" "github.com/tendermint/tendermint/internal/jsontypes" "github.com/tendermint/tendermint/internal/libs/autofile" + tmstrings "github.com/tendermint/tendermint/internal/libs/strings" sm "github.com/tendermint/tendermint/internal/state" tmevents "github.com/tendermint/tendermint/libs/events" "github.com/tendermint/tendermint/libs/log" @@ -778,11 +779,9 @@ func (cs *State) updateToState(state sm.State) { // signal the new round step, because other services (eg. txNotifier) // depend on having an up-to-date peer state! if state.LastBlockHeight <= cs.state.LastBlockHeight { - cs.logger.Debug( - "ignoring updateToState()", + cs.logger.Debug("ignoring updateToState()", "new_height", state.LastBlockHeight+1, - "old_height", cs.state.LastBlockHeight+1, - ) + "old_height", cs.state.LastBlockHeight+1) cs.newStep() return } @@ -1038,12 +1037,10 @@ func (cs *State) handleMsg(ctx context.Context, mi msgInfo) { } if err != nil && msg.Round != cs.Round { - cs.logger.Debug( - "received block part from wrong round", + cs.logger.Debug("received block part from wrong round", "height", cs.Height, "cs_round", cs.Round, - "block_round", msg.Round, - ) + "block_round", msg.Round) err = nil } @@ -1073,7 +1070,7 @@ func (cs *State) handleMsg(ctx context.Context, mi msgInfo) { // We could make note of this and help filter in broadcastHasVoteMessage(). default: - cs.logger.Error("unknown msg type", "type", fmt.Sprintf("%T", msg)) + cs.logger.Error("unknown msg type", "type", tmstrings.LazySprintf("%T", msg)) return } @@ -1184,10 +1181,10 @@ func (cs *State) enterNewRound(ctx context.Context, 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( - "entering new round with invalid args", - "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step), - ) + logger.Debug("entering new round with invalid args", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) return } @@ -1195,7 +1192,10 @@ func (cs *State) enterNewRound(ctx context.Context, 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", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) // increment validators if necessary validators := cs.Validators @@ -1274,10 +1274,10 @@ func (cs *State) enterPropose(ctx context.Context, 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( - "entering propose step with invalid args", - "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step), - ) + logger.Debug("entering propose step with invalid args", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) return } @@ -1291,7 +1291,10 @@ func (cs *State) enterPropose(ctx context.Context, height int64, round int32) { } } - logger.Debug("entering propose step", "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step)) + logger.Debug("entering propose step", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) defer func() { // Done enterPropose: @@ -1333,17 +1336,13 @@ func (cs *State) enterPropose(ctx context.Context, height int64, round int32) { } if cs.isProposer(addr) { - logger.Debug( - "propose step; our turn to propose", - "proposer", addr, - ) + logger.Debug("propose step; our turn to propose", + "proposer", addr) cs.decideProposal(ctx, height, round) } else { - logger.Debug( - "propose step; not our turn to propose", - "proposer", cs.Validators.GetProposer().Address, - ) + logger.Debug("propose step; not our turn to propose", + "proposer", cs.Validators.GetProposer().Address) } } @@ -1480,10 +1479,10 @@ func (cs *State) enterPrevote(ctx context.Context, height int64, round int32) { logger := cs.logger.With("height", height, "round", round) 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), - ) + logger.Debug("entering prevote step with invalid args", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) return } @@ -1493,7 +1492,10 @@ func (cs *State) enterPrevote(ctx context.Context, 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", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) // Sign and broadcast vote as necessary cs.doPrevote(ctx, height, round) @@ -1533,14 +1535,10 @@ func (cs *State) defaultDoPrevote(ctx context.Context, height int64, round int32 //TODO: Remove this temporary fix when the complete solution is ready. See #8739 if !cs.replayMode && cs.Proposal.POLRound == -1 && cs.LockedRound == -1 && !cs.proposalIsTimely() { logger.Debug("prevote step: Proposal is not timely; prevoting nil", - "proposed", - tmtime.Canonical(cs.Proposal.Timestamp).Format(time.RFC3339Nano), - "received", - tmtime.Canonical(cs.ProposalReceiveTime).Format(time.RFC3339Nano), - "msg_delay", - sp.MessageDelay, - "precision", - sp.Precision) + "proposed", tmtime.Canonical(cs.Proposal.Timestamp).Format(time.RFC3339Nano), + "received", tmtime.Canonical(cs.ProposalReceiveTime).Format(time.RFC3339Nano), + "msg_delay", sp.MessageDelay, + "precision", sp.Precision) cs.signAddVote(ctx, tmproto.PrevoteType, nil, types.PartSetHeader{}) return } @@ -1625,8 +1623,8 @@ func (cs *State) defaultDoPrevote(ctx context.Context, height int64, round int32 blockID, ok := cs.Votes.Prevotes(cs.Proposal.POLRound).TwoThirdsMajority() if ok && cs.ProposalBlock.HashesTo(blockID.Hash) && cs.Proposal.POLRound >= 0 && cs.Proposal.POLRound < cs.Round { if cs.LockedRound <= cs.Proposal.POLRound { - logger.Debug("prevote step: ProposalBlock is valid and received a 2/3" + - "majority in a round later than the locked round; prevoting the proposal") + logger.Debug("prevote step: ProposalBlock is valid and received a 2/3 majority in a round later than the locked round", + "outcome", "prevoting the proposal") cs.signAddVote(ctx, tmproto.PrevoteType, cs.ProposalBlock.Hash(), cs.ProposalBlockParts.Header()) return } @@ -1637,8 +1635,8 @@ func (cs *State) defaultDoPrevote(ctx context.Context, height int64, round int32 } } - logger.Debug("prevote step: ProposalBlock is valid but was not our locked block or " + - "did not receive a more recent majority; prevoting nil") + logger.Debug("prevote step: ProposalBlock is valid but was not our locked block or did not receive a more recent majority", + "outcome", "prevoting nil") cs.signAddVote(ctx, tmproto.PrevoteType, nil, types.PartSetHeader{}) } @@ -1647,10 +1645,10 @@ 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( - "entering prevote wait step with invalid args", - "current", fmt.Sprintf("%v/%v/%v", cs.Height, cs.Round, cs.Step), - ) + logger.Debug("entering prevote wait step with invalid args", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) return } @@ -1661,7 +1659,10 @@ 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", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) defer func() { // Done enterPrevoteWait: @@ -1679,17 +1680,21 @@ func (cs *State) enterPrevoteWait(height int64, round int32) { // Lock & precommit the ProposalBlock if we have enough prevotes for it (a POL in this round) // else, precommit nil otherwise. func (cs *State) enterPrecommit(ctx context.Context, height int64, round int32) { - logger := cs.logger.With("height", height, "round", round) + logger := cs.logger.With("new_height", height, "new_round", round) 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), - ) + logger.Debug("entering precommit step with invalid args", + "height", cs.Height, + "round", cs.Round, + "step", 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", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) defer func() { // Done enterPrecommit: @@ -1796,14 +1801,13 @@ func (cs *State) enterPrecommit(ctx context.Context, height int64, round int32) // Enter: any +2/3 precommits for next round. func (cs *State) enterPrecommitWait(height int64, round int32) { - logger := cs.logger.With("height", height, "round", round) + logger := cs.logger.With("new_height", height, "new_round", round) if cs.Height != height || round < cs.Round || (cs.Round == round && cs.TriggeredTimeoutPrecommit) { - logger.Debug( - "entering precommit wait step with invalid args", + logger.Debug("entering precommit wait step with invalid args", "triggered_timeout", cs.TriggeredTimeoutPrecommit, - "current", fmt.Sprintf("%v/%v", cs.Height, cs.Round), - ) + "height", cs.Height, + "round", cs.Round) return } @@ -1814,7 +1818,10 @@ 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", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) defer func() { // Done enterPrecommitWait: @@ -1828,17 +1835,20 @@ func (cs *State) enterPrecommitWait(height int64, round int32) { // Enter: +2/3 precommits for block func (cs *State) enterCommit(ctx context.Context, height int64, commitRound int32) { - logger := cs.logger.With("height", height, "commit_round", commitRound) + logger := cs.logger.With("new_height", height, "commit_round", commitRound) 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), - ) + logger.Debug("entering commit step with invalid args", + "height", cs.Height, + "round", cs.Round, + "step", 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", + "height", cs.Height, + "round", cs.Round, + "step", cs.Step) defer func() { // Done enterCommit: @@ -1892,12 +1902,12 @@ func (cs *State) enterCommit(ctx context.Context, height int64, commitRound int3 // If we have the block AND +2/3 commits for it, finalize. func (cs *State) tryFinalizeCommit(ctx context.Context, height int64) { - logger := cs.logger.With("height", height) - if cs.Height != height { panic(fmt.Sprintf("tryFinalizeCommit() cs.Height: %v vs height: %v", cs.Height, height)) } + logger := cs.logger.With("height", height) + blockID, ok := cs.Votes.Precommits(cs.CommitRound).TwoThirdsMajority() if !ok || blockID.IsNil() { logger.Error("failed attempt to finalize commit; there was no +2/3 majority or +2/3 was for nil") @@ -1907,9 +1917,8 @@ func (cs *State) tryFinalizeCommit(ctx context.Context, height int64) { if !cs.ProposalBlock.HashesTo(blockID.Hash) { // TODO: this happens every time if we're not a validator (ugly logs) // 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(), + logger.Debug("failed attempt to finalize commit; we do not have the commit block", + "proposal_block", tmstrings.LazyBlockHash(cs.ProposalBlock), "commit_block", blockID.Hash, ) return @@ -1951,11 +1960,10 @@ func (cs *State) finalizeCommit(ctx context.Context, height int64) { logger.Info( "finalizing commit of block", - "hash", block.Hash(), + "hash", tmstrings.LazyBlockHash(block), "root", block.AppHash, "num_txs", len(block.Txs), ) - logger.Debug(fmt.Sprintf("%v", block)) // Save to blockStore. if cs.blockStore.Height() < block.Height { @@ -2052,8 +2060,11 @@ func (cs *State) RecordMetrics(height int64, block *types.Block) { address types.Address ) if commitSize != valSetLen { - cs.logger.Error(fmt.Sprintf("commit size (%d) doesn't match valset length (%d) at height %d\n\n%v\n\n%v", - commitSize, valSetLen, block.Height, block.LastCommit.Signatures, cs.LastValidators.Validators)) + cs.logger.Error("commit size doesn't match valset", + "size", commitSize, + "valset_len", valSetLen, + "height", block.Height, + "extra", tmstrings.LazySprintf("\n%v\n\n%v", block.LastCommit.Signatures, cs.LastValidators.Validators)) return } @@ -2187,8 +2198,7 @@ func (cs *State) addProposalBlockPart( cs.metrics.BlockGossipPartsReceived.With("matches_current", "false").Add(1) // NOTE: this can happen when we've gone to a higher round and // then receive parts from the previous round - not necessarily a bad peer. - cs.logger.Debug( - "received a block part when we are not expecting any", + cs.logger.Debug("received a block part when we are not expecting any", "height", height, "round", round, "index", part.Index, @@ -2248,11 +2258,9 @@ func (cs *State) handleCompleteProposal(ctx context.Context, height int64) { blockID, hasTwoThirds := prevotes.TwoThirdsMajority() if hasTwoThirds && !blockID.IsNil() && (cs.ValidRound < cs.Round) { if cs.ProposalBlock.HashesTo(blockID.Hash) { - cs.logger.Debug( - "updating valid block to new proposal block", + cs.logger.Debug("updating valid block to new proposal block", "valid_round", cs.Round, - "valid_block_hash", cs.ProposalBlock.Hash(), - ) + "valid_block_hash", tmstrings.LazyBlockHash(cs.ProposalBlock)) cs.ValidRound = cs.Round cs.ValidBlock = cs.ProposalBlock @@ -2291,23 +2299,19 @@ func (cs *State) tryAddVote(ctx context.Context, vote *types.Vote, peerID types. } if bytes.Equal(vote.ValidatorAddress, cs.privValidatorPubKey.Address()) { - cs.logger.Error( - "found conflicting vote from ourselves; did you unsafe_reset a validator?", + cs.logger.Error("found conflicting vote from ourselves; did you unsafe_reset a validator?", "height", vote.Height, "round", vote.Round, - "type", vote.Type, - ) + "type", vote.Type) return added, err } // report conflicting votes to the evidence pool cs.evpool.ReportConflictingVotes(voteErr.VoteA, voteErr.VoteB) - cs.logger.Debug( - "found and sent conflicting votes to the evidence pool", + cs.logger.Debug("found and sent conflicting votes to the evidence pool", "vote_a", voteErr.VoteA, - "vote_b", voteErr.VoteB, - ) + "vote_b", voteErr.VoteB) return added, err } else if errors.Is(err, types.ErrVoteNonDeterministicSignature) { @@ -2331,13 +2335,11 @@ func (cs *State) addVote( vote *types.Vote, peerID types.NodeID, ) (added bool, err error) { - cs.logger.Debug( - "adding vote", + cs.logger.Debug("adding vote", "vote_height", vote.Height, "vote_type", vote.Type, "val_index", vote.ValidatorIndex, - "cs_height", cs.Height, - ) + "cs_height", cs.Height) if vote.Height < cs.Height || (vote.Height == cs.Height && vote.Round < cs.Round) { cs.metrics.MarkLateVote(vote.Type) @@ -2458,11 +2460,9 @@ func (cs *State) addVote( cs.ValidBlock = cs.ProposalBlock cs.ValidBlockParts = cs.ProposalBlockParts } else { - cs.logger.Debug( - "valid block we do not know about; set ProposalBlock=nil", - "proposal", cs.ProposalBlock.Hash(), - "block_id", blockID.Hash, - ) + cs.logger.Debug("valid block we do not know about; set ProposalBlock=nil", + "proposal", tmstrings.LazyBlockHash(cs.ProposalBlock), + "block_id", blockID.Hash) // we're getting the wrong block cs.ProposalBlock = nil diff --git a/internal/libs/strings/string.go b/internal/libs/strings/string.go index 95ea03b5a..067f31ffc 100644 --- a/internal/libs/strings/string.go +++ b/internal/libs/strings/string.go @@ -3,8 +3,94 @@ package strings import ( "fmt" "strings" + + tmbytes "github.com/tendermint/tendermint/libs/bytes" ) +type lazyStringf struct { + tmpl string + args []interface{} + out string +} + +func (s *lazyStringf) String() string { + if s.out == "" && s.tmpl != "" { + s.out = fmt.Sprintf(s.tmpl, s.args) + s.args = nil + s.tmpl = "" + } + return s.out +} + +// LazySprintf creates a fmt.Stringer implementation with similar +// semantics as fmt.Sprintf, *except* that the string is built when +// String() is called on the object. This means that format arguments +// are resolved/captured into string format when String() is called, +// and not, as in fmt.Sprintf when that function returns. +// +// As a result, if you use this type in go routines or defer +// statements it's possible to pass an argument to LazySprintf which +// has one value at the call site and a different value when the +// String() is evaluated, which may lead to unexpected outcomes. In +// these situations, either be *extremely* careful about the arguments +// passed to this function or use fmt.Sprintf. +// +// The implementation also caches the output of the underlying +// fmt.Sprintf statement when String() is called, so subsequent calls +// will produce the same result. +func LazySprintf(t string, args ...interface{}) fmt.Stringer { + return &lazyStringf{tmpl: t, args: args} +} + +type lazyStringer struct { + val fmt.Stringer + out string +} + +func (l *lazyStringer) String() string { + if l.out == "" && l.val != nil { + l.out = l.val.String() + l.val = nil + } + return l.out +} + +// LazyStringer captures a fmt.Stringer implementation resolving the +// underlying string *only* when the String() method is called and +// caching the result for future use. +func LazyStringer(v fmt.Stringer) fmt.Stringer { return &lazyStringer{val: v} } + +type lazyBlockHash struct { + block interface{ Hash() tmbytes.HexBytes } + out string +} + +// LazyBlockHash defers block Hash until the Stringer interface is invoked. +// This is particularly useful for avoiding calling Sprintf when debugging is not +// active. +// +// As a result, if you use this type in go routines or defer +// statements it's possible to pass an argument to LazyBlockHash that +// has one value at the call site and a different value when the +// String() is evaluated, which may lead to unexpected outcomes. In +// these situations, either be *extremely* careful about the arguments +// passed to this function or use fmt.Sprintf. +// +// The implementation also caches the output of the string form of the +// block hash when String() is called, so subsequent calls will +// produce the same result. +func LazyBlockHash(block interface{ Hash() tmbytes.HexBytes }) fmt.Stringer { + return &lazyBlockHash{block: block} +} + +func (l *lazyBlockHash) String() string { + if l.out == "" && l.block != nil { + l.out = l.block.Hash().String() + l.block = nil + } + return l.out +} + // SplitAndTrimEmpty slices s into all subslices separated by sep and returns a // slice of the string s with all leading and trailing Unicode code points // contained in cutset removed. If sep is empty, SplitAndTrim splits after each diff --git a/internal/mempool/mempool.go b/internal/mempool/mempool.go index 0354eb28a..c0da7cef2 100644 --- a/internal/mempool/mempool.go +++ b/internal/mempool/mempool.go @@ -14,6 +14,7 @@ import ( abci "github.com/tendermint/tendermint/abci/types" "github.com/tendermint/tendermint/config" "github.com/tendermint/tendermint/internal/libs/clist" + tmstrings "github.com/tendermint/tendermint/internal/libs/strings" "github.com/tendermint/tendermint/libs/log" "github.com/tendermint/tendermint/types" ) @@ -540,7 +541,7 @@ func (txmp *TxMempool) addNewTransaction(wtx *WrappedTx, checkTxRes *abci.Respon } txmp.logger.Debug("evicting lower-priority transactions", - "new_tx", fmt.Sprintf("%X", wtx.tx.Hash()), + "new_tx", tmstrings.LazySprintf("%X", wtx.tx.Hash()), "new_priority", priority, ) @@ -562,7 +563,7 @@ func (txmp *TxMempool) addNewTransaction(wtx *WrappedTx, checkTxRes *abci.Respon txmp.logger.Debug( "evicted valid existing transaction; mempool full", - "old_tx", fmt.Sprintf("%X", w.tx.Hash()), + "old_tx", tmstrings.LazySprintf("%X", w.tx.Hash()), "old_priority", w.priority, ) txmp.removeTxByElement(vic) @@ -588,7 +589,7 @@ func (txmp *TxMempool) addNewTransaction(wtx *WrappedTx, checkTxRes *abci.Respon txmp.logger.Debug( "inserted new valid transaction", "priority", wtx.Priority(), - "tx", fmt.Sprintf("%X", wtx.tx.Hash()), + "tx", tmstrings.LazySprintf("%X", wtx.tx.Hash()), "height", txmp.height, "num_txs", txmp.Size(), ) diff --git a/internal/mempool/reactor.go b/internal/mempool/reactor.go index 1f4b3f78a..18124f82b 100644 --- a/internal/mempool/reactor.go +++ b/internal/mempool/reactor.go @@ -9,6 +9,7 @@ import ( "github.com/tendermint/tendermint/config" "github.com/tendermint/tendermint/internal/libs/clist" + tmstrings "github.com/tendermint/tendermint/internal/libs/strings" "github.com/tendermint/tendermint/internal/p2p" "github.com/tendermint/tendermint/libs/log" "github.com/tendermint/tendermint/libs/service" @@ -330,9 +331,8 @@ func (r *Reactor) broadcastTxRoutine(ctx context.Context, peerID types.NodeID, m return } - r.logger.Debug( - "gossiped tx to peer", - "tx", fmt.Sprintf("%X", memTx.tx.Hash()), + r.logger.Debug("gossiped tx to peer", + "tx", tmstrings.LazySprintf("%X", memTx.tx.Hash()), "peer", peerID, ) } diff --git a/internal/p2p/conn/connection.go b/internal/p2p/conn/connection.go index 8f8453e71..adc287328 100644 --- a/internal/p2p/conn/connection.go +++ b/internal/p2p/conn/connection.go @@ -313,7 +313,7 @@ func (c *MConnection) Send(chID ChannelID, msgBytes []byte) bool { // Send message to channel. channel, ok := c.channelsIdx[chID] if !ok { - c.logger.Error(fmt.Sprintf("Cannot send bytes, unknown channel %X", chID)) + c.logger.Error("Cannot send bytes to unknown channel", "channel", chID) return false } diff --git a/internal/p2p/pex/reactor.go b/internal/p2p/pex/reactor.go index 87677799d..9618433f4 100644 --- a/internal/p2p/pex/reactor.go +++ b/internal/p2p/pex/reactor.go @@ -358,7 +358,8 @@ func (r *Reactor) calculateNextRequestTime(added int) time.Duration { // If the peer store is nearly full, wait the maximum interval. if ratio := r.peerManager.PeerRatio(); ratio >= 0.95 { r.logger.Debug("Peer manager is nearly full", - "sleep_period", fullCapacityInterval, "ratio", ratio) + "sleep_period", fullCapacityInterval, + "ratio", ratio) return fullCapacityInterval } diff --git a/internal/p2p/pqueue.go b/internal/p2p/pqueue.go index 3cd1c897a..f53c988a6 100644 --- a/internal/p2p/pqueue.go +++ b/internal/p2p/pqueue.go @@ -208,13 +208,11 @@ func (s *pqScheduler) process(ctx context.Context) { } else { pqEnvTmpChIDStr := strconv.Itoa(int(pqEnvTmp.envelope.ChannelID)) s.metrics.PeerQueueDroppedMsgs.With("ch_id", pqEnvTmpChIDStr).Add(1) - s.logger.Debug( - "dropped envelope", + s.logger.Debug("dropped envelope", "ch_id", pqEnvTmpChIDStr, "priority", pqEnvTmp.priority, "msg_size", pqEnvTmp.size, - "capacity", s.capacity, - ) + "capacity", s.capacity) s.metrics.PeerPendingSendBytes.With("peer_id", string(pqEnvTmp.envelope.To)).Add(float64(-pqEnvTmp.size)) @@ -238,13 +236,11 @@ func (s *pqScheduler) process(ctx context.Context) { // There is not sufficient capacity to drop lower priority Envelopes, // so we drop the incoming Envelope. s.metrics.PeerQueueDroppedMsgs.With("ch_id", chIDStr).Add(1) - s.logger.Debug( - "dropped envelope", + s.logger.Debug("dropped envelope", "ch_id", chIDStr, "priority", pqEnv.priority, "msg_size", pqEnv.size, - "capacity", s.capacity, - ) + "capacity", s.capacity) } } diff --git a/internal/p2p/router.go b/internal/p2p/router.go index 4f3af1346..f10691715 100644 --- a/internal/p2p/router.go +++ b/internal/p2p/router.go @@ -13,6 +13,7 @@ import ( "github.com/gogo/protobuf/proto" "github.com/tendermint/tendermint/crypto" + tmstrings "github.com/tendermint/tendermint/internal/libs/strings" "github.com/tendermint/tendermint/libs/log" "github.com/tendermint/tendermint/libs/service" "github.com/tendermint/tendermint/types" @@ -461,7 +462,7 @@ func (r *Router) acceptPeers(ctx context.Context, transport Transport) { closeErr := conn.Close() r.logger.Debug("rate limiting incoming peer", "err", err, - "ip", incomingIP.String(), + "ip", tmstrings.LazyStringer(incomingIP), "close_err", closeErr, ) diff --git a/internal/statesync/reactor.go b/internal/statesync/reactor.go index deed8d0d3..ffd863dda 100644 --- a/internal/statesync/reactor.go +++ b/internal/statesync/reactor.go @@ -686,37 +686,31 @@ func (r *Reactor) handleSnapshotMessage(ctx context.Context, envelope *p2p.Envel func (r *Reactor) handleChunkMessage(ctx context.Context, envelope *p2p.Envelope, chunkCh p2p.Channel) error { switch msg := envelope.Message.(type) { case *ssproto.ChunkRequest: - r.logger.Debug( - "received chunk request", + r.logger.Debug("received chunk request", "height", msg.Height, "format", msg.Format, "chunk", msg.Index, - "peer", envelope.From, - ) + "peer", envelope.From) resp, err := r.conn.LoadSnapshotChunk(ctx, &abci.RequestLoadSnapshotChunk{ Height: msg.Height, Format: msg.Format, Chunk: msg.Index, }) if err != nil { - r.logger.Error( - "failed to load chunk", + r.logger.Error("failed to load chunk", "height", msg.Height, "format", msg.Format, "chunk", msg.Index, "err", err, - "peer", envelope.From, - ) + "peer", envelope.From) return nil } - r.logger.Debug( - "sending chunk", + r.logger.Debug("sending chunk", "height", msg.Height, "format", msg.Format, "chunk", msg.Index, - "peer", envelope.From, - ) + "peer", envelope.From) if err := chunkCh.Send(ctx, p2p.Envelope{ To: envelope.From, Message: &ssproto.ChunkResponse{ @@ -739,13 +733,11 @@ func (r *Reactor) handleChunkMessage(ctx context.Context, envelope *p2p.Envelope return nil } - r.logger.Debug( - "received chunk; adding to sync", + r.logger.Debug("received chunk; adding to sync", "height", msg.Height, "format", msg.Format, "chunk", msg.Index, - "peer", envelope.From, - ) + "peer", envelope.From) _, err := r.syncer.AddChunk(&chunk{ Height: msg.Height, Format: msg.Format, @@ -754,14 +746,12 @@ func (r *Reactor) handleChunkMessage(ctx context.Context, envelope *p2p.Envelope Sender: envelope.From, }) if err != nil { - r.logger.Error( - "failed to add chunk", + r.logger.Error("failed to add chunk", "height", msg.Height, "format", msg.Format, "chunk", msg.Index, "err", err, - "peer", envelope.From, - ) + "peer", envelope.From) return nil } diff --git a/internal/statesync/syncer.go b/internal/statesync/syncer.go index a09b55892..591639fcd 100644 --- a/internal/statesync/syncer.go +++ b/internal/statesync/syncer.go @@ -84,11 +84,9 @@ func (s *syncer) AddChunk(chunk *chunk) (bool, error) { return false, err } if added { - s.logger.Debug("Added chunk to queue", "height", chunk.Height, "format", chunk.Format, - "chunk", chunk.Index) + s.logger.Debug("Added chunk to queue", "height", chunk.Height, "format", chunk.Format, "chunk", chunk.Index) } else { - s.logger.Debug("Ignoring duplicate chunk in queue", "height", chunk.Height, "format", chunk.Format, - "chunk", chunk.Index) + s.logger.Debug("Ignoring duplicate chunk in queue", "height", chunk.Height, "format", chunk.Format, "chunk", chunk.Index) } return added, nil } @@ -137,12 +135,20 @@ func (s *syncer) SyncAny( discoveryTime = minimumDiscoveryTime } + timer := time.NewTimer(discoveryTime) + defer timer.Stop() + if discoveryTime > 0 { if err := requestSnapshots(); err != nil { return sm.State{}, nil, err } - s.logger.Info(fmt.Sprintf("Discovering snapshots for %v", discoveryTime)) - time.Sleep(discoveryTime) + s.logger.Info("discovering snapshots", + "interval", discoveryTime) + select { + case <-ctx.Done(): + return sm.State{}, nil, ctx.Err() + case <-timer.C: + } } // The app may ask us to retry a snapshot restoration, in which case we need to reuse @@ -151,8 +157,11 @@ func (s *syncer) SyncAny( snapshot *snapshot chunks *chunkQueue err error + iters int ) + for { + iters++ // If not nil, we're going to retry restoration of the same snapshot. if snapshot == nil { snapshot = s.snapshots.Best() @@ -162,9 +171,16 @@ func (s *syncer) SyncAny( if discoveryTime == 0 { return sm.State{}, nil, errNoSnapshots } - s.logger.Info(fmt.Sprintf("Discovering snapshots for %v", discoveryTime)) - time.Sleep(discoveryTime) - continue + s.logger.Info("discovering snapshots", + "iterations", iters, + "interval", discoveryTime) + timer.Reset(discoveryTime) + select { + case <-ctx.Done(): + return sm.State{}, nil, ctx.Err() + case <-timer.C: + continue + } } if chunks == nil { chunks, err = newChunkQueue(snapshot, s.tempDir) @@ -494,13 +510,11 @@ func (s *syncer) requestChunk(ctx context.Context, snapshot *snapshot, chunk uin return nil } - s.logger.Debug( - "Requesting snapshot chunk", + s.logger.Debug("Requesting snapshot chunk", "height", snapshot.Height, "format", snapshot.Format, "chunk", chunk, - "peer", peer, - ) + "peer", peer) msg := p2p.Envelope{ To: peer, diff --git a/libs/log/default.go b/libs/log/default.go index 557ba6551..a6e829639 100644 --- a/libs/log/default.go +++ b/libs/log/default.go @@ -55,9 +55,7 @@ func NewDefaultLogger(format, level string) (Logger, error) { // make the writer thread-safe logWriter = newSyncWriter(logWriter) - return &defaultLogger{ - Logger: zerolog.New(logWriter).Level(logLevel).With().Timestamp().Logger(), - }, nil + return &defaultLogger{Logger: zerolog.New(logWriter).Level(logLevel).With().Timestamp().Logger()}, nil } func (l defaultLogger) Info(msg string, keyVals ...interface{}) { @@ -73,9 +71,7 @@ func (l defaultLogger) Debug(msg string, keyVals ...interface{}) { } func (l defaultLogger) With(keyVals ...interface{}) Logger { - return &defaultLogger{ - Logger: l.Logger.With().Fields(keyVals).Logger(), - } + return &defaultLogger{Logger: l.Logger.With().Fields(keyVals).Logger()} } // OverrideWithNewLogger replaces an existing logger's internal with diff --git a/light/client.go b/light/client.go index f38e9d59d..3c32f5c69 100644 --- a/light/client.go +++ b/light/client.go @@ -9,6 +9,7 @@ import ( "sync" "time" + tmstrings "github.com/tendermint/tendermint/internal/libs/strings" "github.com/tendermint/tendermint/libs/log" tmmath "github.com/tendermint/tendermint/libs/math" "github.com/tendermint/tendermint/light/provider" @@ -475,7 +476,8 @@ func (c *Client) VerifyHeader(ctx context.Context, newHeader *types.Header, now return fmt.Errorf("existing trusted header %X does not match newHeader %X", l.Hash(), newHeader.Hash()) } c.logger.Debug("header has already been verified", - "height", newHeader.Height, "hash", newHeader.Hash()) + "height", newHeader.Height, + "hash", tmstrings.LazyBlockHash(newHeader)) return nil } @@ -576,7 +578,7 @@ func (c *Client) verifySequential( // 2) Verify them c.logger.Debug("verify adjacent newLightBlock against verifiedBlock", "trustedHeight", verifiedBlock.Height, - "trustedHash", verifiedBlock.Hash(), + "trustedHash", tmstrings.LazyBlockHash(verifiedBlock), "newHeight", interimBlock.Height, "newHash", interimBlock.Hash()) @@ -663,9 +665,9 @@ func (c *Client) verifySkipping( for { c.logger.Debug("verify non-adjacent newHeader against verifiedBlock", "trustedHeight", verifiedBlock.Height, - "trustedHash", verifiedBlock.Hash(), + "trustedHash", tmstrings.LazyBlockHash(verifiedBlock), "newHeight", blockCache[depth].Height, - "newHash", blockCache[depth].Hash()) + "newHash", tmstrings.LazyBlockHash(blockCache[depth])) // Verify the untrusted header. This function is equivalent to // ValidAndVerified in the spec @@ -897,9 +899,9 @@ func (c *Client) backwards( interimHeader = interimBlock.Header c.logger.Debug("verify newHeader against verifiedHeader", "trustedHeight", verifiedHeader.Height, - "trustedHash", verifiedHeader.Hash(), + "trustedHash", tmstrings.LazyBlockHash(verifiedHeader), "newHeight", interimHeader.Height, - "newHash", interimHeader.Hash()) + "newHash", tmstrings.LazyBlockHash(interimHeader)) if err := VerifyBackwards(interimHeader, verifiedHeader); err != nil { // verification has failed c.logger.Info("backwards verification failed, replacing primary...", "err", err, "primary", c.primary) diff --git a/light/detector.go b/light/detector.go index a5ac35a02..a0afdca89 100644 --- a/light/detector.go +++ b/light/detector.go @@ -39,8 +39,10 @@ func (c *Client) detectDivergence(ctx context.Context, primaryTrace []*types.Lig lastVerifiedHeader = primaryTrace[len(primaryTrace)-1].SignedHeader witnessesToRemove = make([]int, 0) ) - c.logger.Debug("running detector against trace", "finalizeBlockHeight", lastVerifiedHeader.Height, - "finalizeBlockHash", lastVerifiedHeader.Hash, "length", len(primaryTrace)) + c.logger.Debug("running detector against trace", + "finalizeBlockHeight", lastVerifiedHeader.Height, + "finalizeBlockHash", lastVerifiedHeader.Hash, + "length", len(primaryTrace)) // launch one goroutine per witness to retrieve the light block of the target height // and compare it with the header from the primary diff --git a/rpc/jsonrpc/server/http_server.go b/rpc/jsonrpc/server/http_server.go index 50a37158e..fffc002f3 100644 --- a/rpc/jsonrpc/server/http_server.go +++ b/rpc/jsonrpc/server/http_server.go @@ -58,7 +58,7 @@ func DefaultConfig() *Config { // Serve creates a http.Server and calls Serve with the given listener. It // wraps handler to recover panics and limit the request body size. func Serve(ctx context.Context, listener net.Listener, handler http.Handler, logger log.Logger, config *Config) error { - logger.Info(fmt.Sprintf("Starting RPC HTTP server on %s", listener.Addr())) + logger.Info("Starting RPC HTTP server on", "addr", listener.Addr()) h := recoverAndLogHandler(MaxBytesHandler(handler, config.MaxBodyBytes), logger) s := &http.Server{ Handler: h, diff --git a/test/e2e/app/app.go b/test/e2e/app/app.go index 1f66e95cc..4a18a54a4 100644 --- a/test/e2e/app/app.go +++ b/test/e2e/app/app.go @@ -18,6 +18,7 @@ import ( "github.com/tendermint/tendermint/abci/example/code" abci "github.com/tendermint/tendermint/abci/types" "github.com/tendermint/tendermint/crypto" + tmstrings "github.com/tendermint/tendermint/internal/libs/strings" "github.com/tendermint/tendermint/libs/log" "github.com/tendermint/tendermint/proto/tendermint/types" "github.com/tendermint/tendermint/version" @@ -484,7 +485,10 @@ func (app *Application) ExtendVote(_ context.Context, req *abci.RequestExtendVot time.Sleep(time.Duration(app.cfg.VoteExtensionDelayMS) * time.Millisecond) } - app.logger.Info("generated vote extension", "num", num, "ext", fmt.Sprintf("%x", ext[:extLen]), "state.Height", app.state.Height) + app.logger.Info("generated vote extension", + "num", num, + "ext", tmstrings.LazySprintf("%x", ext[:extLen]), + "state.Height", app.state.Height) return &abci.ResponseExtendVote{ VoteExtension: ext[:extLen], }, nil diff --git a/test/e2e/runner/cleanup.go b/test/e2e/runner/cleanup.go index 25a1008e6..5332af29c 100644 --- a/test/e2e/runner/cleanup.go +++ b/test/e2e/runner/cleanup.go @@ -3,7 +3,6 @@ package main import ( "context" "errors" - "fmt" "os" "github.com/tendermint/tendermint/libs/log" @@ -27,6 +26,6 @@ func Cleanup(ctx context.Context, logger log.Logger, testnetDir string, ti infra return err } - logger.Info(fmt.Sprintf("Removing testnet directory %q", testnetDir)) + logger.Info("Removing testnet", "directory", testnetDir) return os.RemoveAll(testnetDir) }