From bedb00d25229639793e86d741db4e2f6f576ab63 Mon Sep 17 00:00:00 2001 From: Aleksandr Bezobchuk Date: Wed, 27 Jan 2021 15:53:24 -0500 Subject: [PATCH] consensus: Groom Logs (#5917) Executed a local network using simapp and looked for logs that seemed superfluous. This isn't by any means an exhaustive grooming, but should drastically help legibility of logs. ref: #5912 --- cmd/tendermint/commands/root.go | 7 +- config/config.go | 16 ++--- consensus/state.go | 93 +++++++++++++------------- test/e2e/app/main.go | 19 ++++-- test/maverick/consensus/misbehavior.go | 52 +++++++------- test/maverick/consensus/state.go | 39 +++++------ test/maverick/main.go | 7 +- 7 files changed, 124 insertions(+), 109 deletions(-) diff --git a/cmd/tendermint/commands/root.go b/cmd/tendermint/commands/root.go index b0e446c4c..2478f95a5 100644 --- a/cmd/tendermint/commands/root.go +++ b/cmd/tendermint/commands/root.go @@ -51,20 +51,25 @@ var RootCmd = &cobra.Command{ if cmd.Name() == VersionCmd.Name() { return nil } + config, err = ParseConfig() if err != nil { return err } + if config.LogFormat == cfg.LogFormatJSON { logger = log.NewTMJSONLogger(log.NewSyncWriter(os.Stdout)) } - logger, err = tmflags.ParseLogLevel(config.LogLevel, logger, cfg.DefaultLogLevel()) + + logger, err = tmflags.ParseLogLevel(config.LogLevel, logger, cfg.DefaultLogLevel) if err != nil { return err } + if viper.GetBool(cli.TraceFlag) { logger = log.NewTracingLogger(logger) } + logger = logger.With("module", "main") return nil }, diff --git a/config/config.go b/config/config.go index 44876af48..15b3ab092 100644 --- a/config/config.go +++ b/config/config.go @@ -20,6 +20,9 @@ const ( LogFormatPlain = "plain" // LogFormatJSON is a format for json output LogFormatJSON = "json" + + // DefaultLogLevel defines a default log level as INFO. + DefaultLogLevel = "info" ) // NOTE: Most of the structs & relevant comments + the @@ -225,7 +228,7 @@ func DefaultBaseConfig() BaseConfig { Moniker: defaultMoniker, ProxyApp: "tcp://127.0.0.1:26658", ABCI: "socket", - LogLevel: DefaultPackageLogLevels(), + LogLevel: DefaultLogLevel, LogFormat: LogFormatPlain, FastSyncMode: true, FilterPeers: false, @@ -284,17 +287,6 @@ func (cfg BaseConfig) ValidateBasic() error { return nil } -// DefaultLogLevel returns a default log level of "error" -func DefaultLogLevel() string { - return "error" -} - -// DefaultPackageLogLevels returns a default log level setting so all packages -// log at "error", while the `state` and `main` packages log at "info" -func DefaultPackageLogLevels() string { - return fmt.Sprintf("main:info,state:info,statesync:info,*:%s", DefaultLogLevel()) -} - //----------------------------------------------------------------------------- // RPCConfig diff --git a/consensus/state.go b/consensus/state.go index f263293df..004d0d2a6 100644 --- a/consensus/state.go +++ b/consensus/state.go @@ -920,7 +920,7 @@ func (cs *State) enterNewRound(height int64, round int32) { } if now := tmtime.Now(); cs.StartTime.After(now) { - logger.Info("Need to set a buffer and log message here for sanity.", "startTime", cs.StartTime, "now", now) + 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)) @@ -1040,18 +1040,16 @@ func (cs *State) enterPropose(height int64, round int32) { } if cs.isProposer(address) { - logger.Info("enterPropose: Our turn to propose", - "proposer", - address, - "privValidator", - cs.privValidator) + logger.Debug("enterPropose: our turn to propose", + "proposer", address, + "privValidator", cs.privValidator, + ) cs.decideProposal(height, round) } else { - logger.Info("enterPropose: Not our turn to propose", - "proposer", - cs.Validators.GetProposer().Address, - "privValidator", - cs.privValidator) + logger.Debug("enterPropose: not our turn to propose", + "proposer", cs.Validators.GetProposer().Address, + "privValidator", cs.privValidator, + ) } } @@ -1176,7 +1174,7 @@ func (cs *State) enterPrevote(height int64, round int32) { cs.newStep() }() - cs.Logger.Info(fmt.Sprintf("enterPrevote(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step)) + cs.Logger.Debug(fmt.Sprintf("enterPrevote(%v/%v); current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step)) // Sign and broadcast vote as necessary cs.doPrevote(height, round) @@ -1190,14 +1188,14 @@ func (cs *State) defaultDoPrevote(height int64, round int32) { // If a block is locked, prevote that. if cs.LockedBlock != nil { - logger.Info("enterPrevote: Already locked on a block, prevoting locked block") + logger.Debug("enterPrevote: already locked on a block; prevoting locked block") cs.signAddVote(tmproto.PrevoteType, cs.LockedBlock.Hash(), cs.LockedBlockParts.Header()) return } // If ProposalBlock is nil, prevote nil. if cs.ProposalBlock == nil { - logger.Info("enterPrevote: ProposalBlock is nil") + logger.Debug("enterPrevote: ProposalBlock is nil") cs.signAddVote(tmproto.PrevoteType, nil, types.PartSetHeader{}) return } @@ -1214,7 +1212,7 @@ func (cs *State) defaultDoPrevote(height int64, round int32) { // Prevote cs.ProposalBlock // NOTE: the proposal signature is validated when it is received, // and the proposal block parts are validated as they are received (against the merkle hash in the proposal) - logger.Info("enterPrevote: ProposalBlock is valid") + logger.Debug("enterPrevote: ProposalBlock is valid") cs.signAddVote(tmproto.PrevoteType, cs.ProposalBlock.Hash(), cs.ProposalBlockParts.Header()) } @@ -1235,7 +1233,8 @@ func (cs *State) enterPrevoteWait(height int64, round int32) { if !cs.Votes.Prevotes(round).HasTwoThirdsAny() { panic(fmt.Sprintf("enterPrevoteWait(%v/%v), but Prevotes does not have any +2/3 votes", height, round)) } - logger.Info(fmt.Sprintf("enterPrevoteWait(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step)) + + logger.Debug(fmt.Sprintf("enterPrevoteWait(%v/%v); current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step)) defer func() { // Done enterPrevoteWait: @@ -1267,7 +1266,7 @@ func (cs *State) enterPrecommit(height int64, round int32) { return } - logger.Info(fmt.Sprintf("enterPrecommit(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step)) + logger.Debug(fmt.Sprintf("enterPrecommit(%v/%v); current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step)) defer func() { // Done enterPrecommit: @@ -1281,9 +1280,9 @@ func (cs *State) enterPrecommit(height int64, round int32) { // If we don't have a polka, we must precommit nil. if !ok { if cs.LockedBlock != nil { - logger.Info("enterPrecommit: No +2/3 prevotes during enterPrecommit while we're locked. Precommitting nil") + logger.Debug("enterPrecommit: no +2/3 prevotes during enterPrecommit while we're locked. Precommitting nil") } else { - logger.Info("enterPrecommit: No +2/3 prevotes during enterPrecommit. Precommitting nil.") + logger.Debug("enterPrecommit: no +2/3 prevotes during enterPrecommit. Precommitting nil.") } cs.signAddVote(tmproto.PrecommitType, nil, types.PartSetHeader{}) return @@ -1303,9 +1302,9 @@ func (cs *State) enterPrecommit(height int64, round int32) { // +2/3 prevoted nil. Unlock and precommit nil. if len(blockID.Hash) == 0 { if cs.LockedBlock == nil { - logger.Info("enterPrecommit: +2/3 prevoted for nil.") + logger.Debug("enterPrecommit: +2/3 prevoted for nil") } else { - logger.Info("enterPrecommit: +2/3 prevoted for nil. Unlocking") + logger.Debug("enterPrecommit: +2/3 prevoted for nil; unlocking") cs.LockedRound = -1 cs.LockedBlock = nil cs.LockedBlockParts = nil @@ -1321,7 +1320,7 @@ func (cs *State) enterPrecommit(height int64, round int32) { // If we're already locked on that block, precommit it, and update the LockedRound if cs.LockedBlock.HashesTo(blockID.Hash) { - logger.Info("enterPrecommit: +2/3 prevoted locked block. Relocking") + logger.Debug("enterPrecommit: +2/3 prevoted locked block; relocking") cs.LockedRound = round if err := cs.eventBus.PublishEventRelock(cs.RoundStateEvent()); err != nil { cs.Logger.Error("Error publishing event relock", "err", err) @@ -1332,7 +1331,7 @@ func (cs *State) enterPrecommit(height int64, round int32) { // If +2/3 prevoted for proposal block, stage and precommit it if cs.ProposalBlock.HashesTo(blockID.Hash) { - logger.Info("enterPrecommit: +2/3 prevoted proposal block. Locking", "hash", blockID.Hash) + logger.Debug("enterPrecommit: +2/3 prevoted proposal block; locking", "hash", blockID.Hash) // Validate the block. if err := cs.blockExec.ValidateBlock(cs.state, cs.ProposalBlock); err != nil { panic(fmt.Sprintf("enterPrecommit: +2/3 prevoted for an invalid block: %v", err)) @@ -1350,7 +1349,7 @@ func (cs *State) enterPrecommit(height int64, round int32) { // There was a polka in this round for a block we don't have. // Fetch that block, unlock, and precommit nil. // The +2/3 prevotes for this round is the POL for our unlock. - logger.Info("enterPrecommit: +2/3 prevotes for a block we don't have. Voting nil", "blockID", blockID) + logger.Debug("enterPrecommit: +2/3 prevotes for a block we do not have; voting nil", "blockID", blockID) cs.LockedRound = -1 cs.LockedBlock = nil cs.LockedBlockParts = nil @@ -1379,7 +1378,7 @@ 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.Debug(fmt.Sprintf("enterPrecommitWait(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step)) defer func() { // Done enterPrecommitWait: @@ -1428,7 +1427,7 @@ func (cs *State) enterCommit(height int64, commitRound int32) { // Move them over to ProposalBlock if they match the commit hash, // otherwise they'll be cleared in updateToState. if cs.LockedBlock.HashesTo(blockID.Hash) { - logger.Info("Commit is for locked block. Set ProposalBlock=LockedBlock", "blockHash", blockID.Hash) + logger.Debug("commit is for a locked block; set ProposalBlock=LockedBlock", "blockHash", blockID.Hash) cs.ProposalBlock = cs.LockedBlock cs.ProposalBlockParts = cs.LockedBlockParts } @@ -1437,11 +1436,11 @@ func (cs *State) enterCommit(height int64, commitRound int32) { if !cs.ProposalBlock.HashesTo(blockID.Hash) { if !cs.ProposalBlockParts.HasHeader(blockID.PartSetHeader) { logger.Info( - "Commit is for a block we don't know about. Set ProposalBlock=nil", - "proposal", - cs.ProposalBlock.Hash(), - "commit", - blockID.Hash) + "commit is for a block we do not know about; set ProposalBlock=nil", + "proposal", cs.ProposalBlock.Hash(), + "commit", blockID.Hash, + ) + // We're getting the wrong block. // Set up ProposalBlockParts and keep waiting. cs.ProposalBlock = nil @@ -1473,12 +1472,11 @@ func (cs *State) tryFinalizeCommit(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.Info( - "Attempt to finalize failed. We don't have the commit block.", - "proposal-block", - cs.ProposalBlock.Hash(), - "commit-block", - blockID.Hash) + logger.Debug( + "attempt to finalize failed; we do not have the commit block", + "proposal-block", cs.ProposalBlock.Hash(), + "commit-block", blockID.Hash, + ) return } @@ -1514,12 +1512,13 @@ func (cs *State) finalizeCommit(height int64) { panic(fmt.Errorf("+2/3 committed an invalid block: %w", err)) } - cs.Logger.Info("Finalizing commit of block with N txs", + cs.Logger.Info("finalizing commit of block with N txs", "height", block.Height, "hash", block.Hash(), "root", block.AppHash, - "N", len(block.Txs)) - cs.Logger.Info(fmt.Sprintf("%v", block)) + "N", len(block.Txs), + ) + cs.Logger.Debug(fmt.Sprintf("%v", block)) fail.Fail() // XXX @@ -1532,7 +1531,7 @@ func (cs *State) finalizeCommit(height int64) { cs.blockStore.SaveBlock(block, blockParts, seenCommit) } else { // Happens during replay if we already saved the block but didn't commit - cs.Logger.Info("Calling finalizeCommit on already stored block", "height", block.Height) + cs.Logger.Debug("calling finalizeCommit on already stored block", "height", block.Height) } fail.Fail() // XXX @@ -1749,7 +1748,8 @@ func (cs *State) defaultSetProposal(proposal *types.Proposal) error { if cs.ProposalBlockParts == nil { cs.ProposalBlockParts = types.NewPartSetFromHeader(proposal.BlockID.PartSetHeader) } - cs.Logger.Info("Received proposal", "proposal", proposal) + + cs.Logger.Info("received proposal", "proposal", proposal) return nil } @@ -1935,7 +1935,7 @@ func (cs *State) addVote( // Height mismatch is ignored. // Not necessarily a bad peer, but not favourable behaviour. if vote.Height != cs.Height { - cs.Logger.Info("Vote ignored and not added", "voteHeight", vote.Height, "csHeight", cs.Height, "peerID", peerID) + cs.Logger.Debug("vote ignored and not added", "voteHeight", vote.Height, "csHeight", cs.Height, "peerID", peerID) return } @@ -1991,8 +1991,11 @@ func (cs *State) addVote( cs.ValidBlockParts = cs.ProposalBlockParts } else { cs.Logger.Info( - "Valid block we don't know about. Set ProposalBlock=nil", - "proposal", cs.ProposalBlock.Hash(), "blockID", blockID.Hash) + "valid block we do not know about; set ProposalBlock=nil", + "proposal", cs.ProposalBlock.Hash(), + "blockID", blockID.Hash, + ) + // We're getting the wrong block. cs.ProposalBlock = nil } diff --git a/test/e2e/app/main.go b/test/e2e/app/main.go index 215c00d78..d309a0289 100644 --- a/test/e2e/app/main.go +++ b/test/e2e/app/main.go @@ -200,28 +200,35 @@ func setupNode() (*config.Config, log.Logger, *p2p.NodeKey, error) { if home == "" { return nil, nil, nil, errors.New("TMHOME not set") } + viper.AddConfigPath(filepath.Join(home, "config")) viper.SetConfigName("config") - err := viper.ReadInConfig() - if err != nil { + + if err := viper.ReadInConfig(); err != nil { return nil, nil, nil, err } + tmcfg = config.DefaultConfig() - err = viper.Unmarshal(tmcfg) - if err != nil { + + if err := viper.Unmarshal(tmcfg); err != nil { return nil, nil, nil, err } + tmcfg.SetRoot(home) - if err = tmcfg.ValidateBasic(); err != nil { + + if err := tmcfg.ValidateBasic(); err != nil { return nil, nil, nil, fmt.Errorf("error in config file: %w", err) } + if tmcfg.LogFormat == config.LogFormatJSON { logger = log.NewTMJSONLogger(log.NewSyncWriter(os.Stdout)) } - nodeLogger, err := tmflags.ParseLogLevel(tmcfg.LogLevel, logger, config.DefaultLogLevel()) + + nodeLogger, err := tmflags.ParseLogLevel(tmcfg.LogLevel, logger, config.DefaultLogLevel) if err != nil { return nil, nil, nil, err } + nodeLogger = nodeLogger.With("module", "main") nodeKey, err := p2p.LoadOrGenNodeKey(tmcfg.NodeKeyFile()) diff --git a/test/maverick/consensus/misbehavior.go b/test/maverick/consensus/misbehavior.go index ce78173a9..5ef3f27d9 100644 --- a/test/maverick/consensus/misbehavior.go +++ b/test/maverick/consensus/misbehavior.go @@ -53,14 +53,14 @@ func DoublePrevoteMisbehavior() Misbehavior { // If a block is locked, prevote that. if cs.LockedBlock != nil { - cs.Logger.Info("enterPrevote: Already locked on a block, prevoting locked block") + cs.Logger.Debug("enterPrevote: already locked on a block, prevoting locked block") cs.signAddVote(tmproto.PrevoteType, cs.LockedBlock.Hash(), cs.LockedBlockParts.Header()) return } // If ProposalBlock is nil, prevote nil. if cs.ProposalBlock == nil { - cs.Logger.Info("enterPrevote: ProposalBlock is nil") + cs.Logger.Debug("enterPrevote: ProposalBlock is nil") cs.signAddVote(tmproto.PrevoteType, nil, types.PartSetHeader{}) return } @@ -136,18 +136,16 @@ func defaultEnterPropose(cs *State, height int64, round int32) { } if cs.isProposer(address) { - logger.Info("enterPropose: Our turn to propose", - "proposer", - address, - "privValidator", - cs.privValidator) + logger.Debug("enterPropose: our turn to propose", + "proposer", address, + "privValidator", cs.privValidator, + ) cs.decideProposal(height, round) } else { - logger.Info("enterPropose: Not our turn to propose", - "proposer", - cs.Validators.GetProposer().Address, - "privValidator", - cs.privValidator) + logger.Debug("enterPropose: not our turn to propose", + "proposer", cs.Validators.GetProposer().Address, + "privValidator", cs.privValidator, + ) } } @@ -156,14 +154,14 @@ func defaultEnterPrevote(cs *State, height int64, round int32) { // If a block is locked, prevote that. if cs.LockedBlock != nil { - logger.Info("enterPrevote: Already locked on a block, prevoting locked block") + logger.Debug("enterPrevote: already locked on a block, prevoting locked block") cs.signAddVote(tmproto.PrevoteType, cs.LockedBlock.Hash(), cs.LockedBlockParts.Header()) return } // If ProposalBlock is nil, prevote nil. if cs.ProposalBlock == nil { - logger.Info("enterPrevote: ProposalBlock is nil") + logger.Debug("enterPrevote: ProposalBlock is nil") cs.signAddVote(tmproto.PrevoteType, nil, types.PartSetHeader{}) return } @@ -180,7 +178,7 @@ func defaultEnterPrevote(cs *State, height int64, round int32) { // Prevote cs.ProposalBlock // NOTE: the proposal signature is validated when it is received, // and the proposal block parts are validated as they are received (against the merkle hash in the proposal) - logger.Info("enterPrevote: ProposalBlock is valid") + logger.Debug("enterPrevote: ProposalBlock is valid") cs.signAddVote(tmproto.PrevoteType, cs.ProposalBlock.Hash(), cs.ProposalBlockParts.Header()) } @@ -193,9 +191,9 @@ func defaultEnterPrecommit(cs *State, height int64, round int32) { // If we don't have a polka, we must precommit nil. if !ok { if cs.LockedBlock != nil { - logger.Info("enterPrecommit: No +2/3 prevotes during enterPrecommit while we're locked. Precommitting nil") + logger.Debug("enterPrecommit: no +2/3 prevotes during enterPrecommit while we're locked; precommitting nil") } else { - logger.Info("enterPrecommit: No +2/3 prevotes during enterPrecommit. Precommitting nil.") + logger.Debug("enterPrecommit: no +2/3 prevotes during enterPrecommit; precommitting nil.") } cs.signAddVote(tmproto.PrecommitType, nil, types.PartSetHeader{}) return @@ -213,9 +211,9 @@ func defaultEnterPrecommit(cs *State, height int64, round int32) { // +2/3 prevoted nil. Unlock and precommit nil. if len(blockID.Hash) == 0 { if cs.LockedBlock == nil { - logger.Info("enterPrecommit: +2/3 prevoted for nil.") + logger.Debug("enterPrecommit: +2/3 prevoted for nil") } else { - logger.Info("enterPrecommit: +2/3 prevoted for nil. Unlocking") + logger.Debug("enterPrecommit: +2/3 prevoted for nil; unlocking") cs.LockedRound = -1 cs.LockedBlock = nil cs.LockedBlockParts = nil @@ -229,7 +227,7 @@ func defaultEnterPrecommit(cs *State, height int64, round int32) { // If we're already locked on that block, precommit it, and update the LockedRound if cs.LockedBlock.HashesTo(blockID.Hash) { - logger.Info("enterPrecommit: +2/3 prevoted locked block. Relocking") + logger.Debug("enterPrecommit: +2/3 prevoted locked block; relocking") cs.LockedRound = round _ = cs.eventBus.PublishEventRelock(cs.RoundStateEvent()) cs.signAddVote(tmproto.PrecommitType, blockID.Hash, blockID.PartSetHeader) @@ -238,7 +236,7 @@ func defaultEnterPrecommit(cs *State, height int64, round int32) { // If +2/3 prevoted for proposal block, stage and precommit it if cs.ProposalBlock.HashesTo(blockID.Hash) { - logger.Info("enterPrecommit: +2/3 prevoted proposal block. Locking", "hash", blockID.Hash) + logger.Debug("enterPrecommit: +2/3 prevoted proposal block; locking", "hash", blockID.Hash) // Validate the block. if err := cs.blockExec.ValidateBlock(cs.state, cs.ProposalBlock); err != nil { panic(fmt.Sprintf("enterPrecommit: +2/3 prevoted for an invalid block: %v", err)) @@ -254,7 +252,7 @@ func defaultEnterPrecommit(cs *State, height int64, round int32) { // There was a polka in this round for a block we don't have. // Fetch that block, unlock, and precommit nil. // The +2/3 prevotes for this round is the POL for our unlock. - logger.Info("enterPrecommit: +2/3 prevotes for a block we don't have. Voting nil", "blockID", blockID) + logger.Debug("enterPrecommit: +2/3 prevotes for a block we don't have; voting nil", "blockID", blockID) cs.LockedRound = -1 cs.LockedBlock = nil cs.LockedBlockParts = nil @@ -303,8 +301,11 @@ func defaultReceivePrevote(cs *State, vote *types.Vote) { cs.ValidBlockParts = cs.ProposalBlockParts } else { cs.Logger.Info( - "Valid block we don't know about. Set ProposalBlock=nil", - "proposal", cs.ProposalBlock.Hash(), "blockID", blockID.Hash) + "valid block we do not know about; set ProposalBlock=nil", + "proposal", cs.ProposalBlock.Hash(), + "blockID", blockID.Hash, + ) + // We're getting the wrong block. cs.ProposalBlock = nil } @@ -394,6 +395,7 @@ func defaultReceiveProposal(cs *State, proposal *types.Proposal) error { if cs.ProposalBlockParts == nil { cs.ProposalBlockParts = types.NewPartSetFromHeader(proposal.BlockID.PartSetHeader) } - cs.Logger.Info("Received proposal", "proposal", proposal) + + cs.Logger.Info("received proposal", "proposal", proposal) return nil } diff --git a/test/maverick/consensus/state.go b/test/maverick/consensus/state.go index f83dc56c6..e4ff82793 100644 --- a/test/maverick/consensus/state.go +++ b/test/maverick/consensus/state.go @@ -295,7 +295,7 @@ func (cs *State) enterPrevote(height int64, round int32) { cs.newStep() }() - cs.Logger.Info(fmt.Sprintf("enterPrevote(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step)) + cs.Logger.Debug(fmt.Sprintf("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 { @@ -389,7 +389,7 @@ func (cs *State) addVote( // Height mismatch is ignored. // Not necessarily a bad peer, but not favourable behaviour. if vote.Height != cs.Height { - cs.Logger.Info("Vote ignored and not added", "voteHeight", vote.Height, "csHeight", cs.Height, "peerID", peerID) + cs.Logger.Debug("vote ignored and not added", "voteHeight", vote.Height, "csHeight", cs.Height, "peerID", peerID) return } @@ -1114,7 +1114,7 @@ func (cs *State) enterNewRound(height int64, round int32) { } if now := tmtime.Now(); cs.StartTime.After(now) { - logger.Info("Need to set a buffer and log message here for sanity.", "startTime", cs.StartTime, "now", now) + 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)) @@ -1293,7 +1293,8 @@ func (cs *State) enterPrevoteWait(height int64, round int32) { if !cs.Votes.Prevotes(round).HasTwoThirdsAny() { panic(fmt.Sprintf("enterPrevoteWait(%v/%v), but Prevotes does not have any +2/3 votes", height, round)) } - logger.Info(fmt.Sprintf("enterPrevoteWait(%v/%v). Current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step)) + + logger.Debug(fmt.Sprintf("enterPrevoteWait(%v/%v); current: %v/%v/%v", height, round, cs.Height, cs.Round, cs.Step)) defer func() { // Done enterPrevoteWait: @@ -1378,11 +1379,11 @@ func (cs *State) enterCommit(height int64, commitRound int32) { if !cs.ProposalBlock.HashesTo(blockID.Hash) { if !cs.ProposalBlockParts.HasHeader(blockID.PartSetHeader) { logger.Info( - "Commit is for a block we don't know about. Set ProposalBlock=nil", - "proposal", - cs.ProposalBlock.Hash(), - "commit", - blockID.Hash) + "commit is for a block we do not know about; set ProposalBlock=nil", + "proposal", cs.ProposalBlock.Hash(), + "commit", blockID.Hash, + ) + // We're getting the wrong block. // Set up ProposalBlockParts and keep waiting. cs.ProposalBlock = nil @@ -1414,12 +1415,11 @@ func (cs *State) tryFinalizeCommit(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.Info( - "Attempt to finalize failed. We don't have the commit block.", - "proposal-block", - cs.ProposalBlock.Hash(), - "commit-block", - blockID.Hash) + logger.Debug( + "attempt to finalize failed; we do not have the commit block", + "proposal-block", cs.ProposalBlock.Hash(), + "commit-block", blockID.Hash, + ) return } @@ -1455,12 +1455,13 @@ func (cs *State) finalizeCommit(height int64) { panic(fmt.Errorf("+2/3 committed an invalid block: %w", err)) } - cs.Logger.Info("Finalizing commit of block with N txs", + cs.Logger.Info("finalizing commit of block with N txs", "height", block.Height, "hash", block.Hash(), "root", block.AppHash, - "N", len(block.Txs)) - cs.Logger.Info(fmt.Sprintf("%v", block)) + "N", len(block.Txs), + ) + cs.Logger.Debug(fmt.Sprintf("%v", block)) fail.Fail() // XXX @@ -1473,7 +1474,7 @@ func (cs *State) finalizeCommit(height int64) { cs.blockStore.SaveBlock(block, blockParts, seenCommit) } else { // Happens during replay if we already saved the block but didn't commit - cs.Logger.Info("Calling finalizeCommit on already stored block", "height", block.Height) + cs.Logger.Debug("calling finalizeCommit on already stored block", "height", block.Height) } fail.Fail() // XXX diff --git a/test/maverick/main.go b/test/maverick/main.go index 6a337b3fd..a3c42e28f 100644 --- a/test/maverick/main.go +++ b/test/maverick/main.go @@ -60,20 +60,25 @@ var RootCmd = &cobra.Command{ "through a flag. See maverick node --help for how the misbehavior flag is constructured", PersistentPreRunE: func(cmd *cobra.Command, args []string) (err error) { fmt.Printf("use: %v, args: %v", cmd.Use, cmd.Args) + config, err = ParseConfig() if err != nil { return err } + if config.LogFormat == cfg.LogFormatJSON { logger = log.NewTMJSONLogger(log.NewSyncWriter(os.Stdout)) } - logger, err = tmflags.ParseLogLevel(config.LogLevel, logger, cfg.DefaultLogLevel()) + + logger, err = tmflags.ParseLogLevel(config.LogLevel, logger, cfg.DefaultLogLevel) if err != nil { return err } + if viper.GetBool(cli.TraceFlag) { logger = log.NewTracingLogger(logger) } + logger = logger.With("module", "main") return nil },