mirrors/tendermint
1
0
Fork 0
mirror of https://github.com/tendermint/tendermint.git synced 2026-04-20 15:50:31 +00:00
Code Issues Packages Projects Releases Wiki Activity

logging: implement lazy sprinting (#8898)

Browse Source 
shout out to @joeabbey for the inspiration. This makes the lazy
functions internal by default to prevent potential misuse by external
callers.

Should backport cleanly into 0.36 and I'll handle a messy merge into 0.35
This commit is contained in:
Sam Kleinman
2022-07-27 15:16:51 -04:00
committed by GitHub
parent b9d6bb4cd1
commit 48147e1fb9
20 changed files with 269 additions and 177 deletions
Download Patch File Download Diff File Expand all files Collapse all files

3
abci/client/grpc_client.go
View File

@@ -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():

8
abci/client/socket_client.go
View File

@@ -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

6
internal/blocksync/reactor.go
View File

@@ -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 {

3
internal/consensus/reactor.go
View File

@@ -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
}

198
internal/consensus/state.go
View File

@@ -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

86
internal/libs/strings/string.go
View File

@@ -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

7
internal/mempool/mempool.go
View File

@@ -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(),
)

6
internal/mempool/reactor.go
View File

@@ -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,
)
}

2
internal/p2p/conn/connection.go
View File

@@ -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
}

3
internal/p2p/pex/reactor.go
View File

@@ -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
}

12
internal/p2p/pqueue.go
View File

@@ -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)
}
}

3
internal/p2p/router.go
View File

@@ -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,
)

30
internal/statesync/reactor.go
View File

@@ -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
}

40
internal/statesync/syncer.go
View File

@@ -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,

8
libs/log/default.go
View File

@@ -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

14
light/client.go
View File

@@ -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)

6
light/detector.go
View File

@@ -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

2
rpc/jsonrpc/server/http_server.go
View File

@@ -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,

6
test/e2e/app/app.go
View File

@@ -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

3
test/e2e/runner/cleanup.go
View File

@@ -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)
}