From 2f136d7c86083b4454cee62b304bc0e8218d028a Mon Sep 17 00:00:00 2001 From: Lukasz Klimek <842586+lklimek@users.noreply.github.com> Date: Tue, 12 Sep 2023 16:42:22 +0200 Subject: [PATCH] chore: improve logs --- internal/consensus/block_executor.go | 2 +- internal/consensus/event_publisher.go | 2 +- internal/consensus/gossip_peer_worker.go | 8 ++--- internal/consensus/gossiper.go | 4 +-- internal/consensus/msg_handlers.go | 2 +- internal/consensus/peer_state.go | 4 +-- internal/consensus/proposal_updater.go | 2 +- internal/consensus/reactor.go | 19 ++++++------ internal/consensus/replay.go | 10 +++--- internal/consensus/replayer.go | 6 ++-- internal/consensus/round_scheduler.go | 1 - internal/consensus/state.go | 6 ++-- internal/consensus/state_add_prop_block.go | 31 +++++++++---------- internal/consensus/state_add_vote.go | 10 +++--- internal/consensus/state_data.go | 14 ++++----- internal/consensus/state_enter_commit.go | 3 +- internal/consensus/state_enter_new_round.go | 7 +++-- internal/consensus/state_enter_precommit.go | 12 ++++--- internal/consensus/state_enter_prevote.go | 2 +- internal/consensus/state_enter_propose.go | 19 ++++++------ internal/consensus/state_enter_wait.go | 2 +- internal/consensus/state_prevoter.go | 2 +- internal/consensus/state_proposaler.go | 8 ++--- internal/consensus/state_try_add_commit.go | 2 +- .../consensus/state_try_finalize_commit.go | 3 +- internal/consensus/ticker.go | 4 +-- internal/consensus/vote_signer.go | 2 +- 27 files changed, 95 insertions(+), 92 deletions(-) diff --git a/internal/consensus/block_executor.go b/internal/consensus/block_executor.go index 69783a3c8a..c2beffcb46 100644 --- a/internal/consensus/block_executor.go +++ b/internal/consensus/block_executor.go @@ -65,7 +65,7 @@ func (c *blockExecutor) ensureProcess(ctx context.Context, rs *cstypes.RoundStat block := rs.ProposalBlock crs := rs.CurrentRoundState if crs.Params.Source != sm.ProcessProposalSource || !crs.MatchesBlock(block.Header, round) { - c.logger.Debug("CurrentRoundState is outdated", "crs", crs) + c.logger.Debug("CurrentRoundState is outdated, executing ProcessProposal", "crs", crs) uncommittedState, err := c.blockExec.ProcessProposal(ctx, block, round, c.committedState, true) if err != nil { return fmt.Errorf("ProcessProposal abci method: %w", err) diff --git a/internal/consensus/event_publisher.go b/internal/consensus/event_publisher.go index 411ddd5824..01984346c7 100644 --- a/internal/consensus/event_publisher.go +++ b/internal/consensus/event_publisher.go @@ -34,7 +34,7 @@ func (p *EventPublisher) PublishValidBlockEvent(rs cstypes.RoundState) { // PublishCommitEvent ... func (p *EventPublisher) PublishCommitEvent(commit *types.Commit) error { - p.logger.Debug("publish commit event", "commit", commit) + p.logger.Trace("publish commit event", "commit", commit) if err := p.eventBus.PublishEventCommit(types.EventDataCommit{Commit: commit}); err != nil { return err } diff --git a/internal/consensus/gossip_peer_worker.go b/internal/consensus/gossip_peer_worker.go index f4c12d177d..ca9e8c79cd 100644 --- a/internal/consensus/gossip_peer_worker.go +++ b/internal/consensus/gossip_peer_worker.go @@ -86,7 +86,7 @@ func (g *peerGossipWorker) Stop() { if !g.running.Swap(false) { return } - g.logger.Debug("peer gossip worker stopping") + g.logger.Trace("peer gossip worker stopping") close(g.stopCh) g.Wait() } @@ -94,7 +94,7 @@ func (g *peerGossipWorker) Stop() { func (g *peerGossipWorker) Wait() { for _, hd := range g.handlers { <-hd.stoppedCh - g.logger.Debug("peer gossip worker stopped") + g.logger.Trace("peer gossip worker stopped") } } @@ -107,11 +107,11 @@ func (g *peerGossipWorker) runHandler(ctx context.Context, hd gossipHandler) { select { case <-timer.Chan(): case <-g.stopCh: - g.logger.Debug("peer gossip worker got stop signal") + g.logger.Trace("peer gossip worker got stop signal") close(hd.stoppedCh) return case <-ctx.Done(): - g.logger.Debug("peer gossip worker got stop signal via context.Done") + g.logger.Trace("peer gossip worker got stop signal via context.Done") close(hd.stoppedCh) return } diff --git a/internal/consensus/gossiper.go b/internal/consensus/gossiper.go index f65d0b59e3..4a3dc5991c 100644 --- a/internal/consensus/gossiper.go +++ b/internal/consensus/gossiper.go @@ -121,7 +121,7 @@ func (g *msgGossiper) GossipProposalBlockParts( "round", prs.Round, "part_index", index, }) - logger.Debug("syncing proposal block part to the peer") + logger.Trace("syncing proposal block part to the peer") part := rs.ProposalBlockParts.GetPart(index) // NOTE: A peer might have received a different proposal message, so this Proposal msg will be rejected! err := g.syncProposalBlockPart(ctx, part, rs.Height, rs.Round) @@ -137,7 +137,7 @@ func (g *msgGossiper) GossipProposal(ctx context.Context, rs cstypes.RoundState, "round", prs.Round, }) // Proposal: share the proposal metadata with peer. - logger.Debug("syncing proposal") + logger.Trace("syncing proposal") err := g.sync(ctx, rs.Proposal.ToProto(), updatePeerProposal(g.ps, rs.Proposal)) if err != nil { logger.Error("failed to sync proposal to the peer", "error", err) diff --git a/internal/consensus/msg_handlers.go b/internal/consensus/msg_handlers.go index c9986b583a..8477e812b1 100644 --- a/internal/consensus/msg_handlers.go +++ b/internal/consensus/msg_handlers.go @@ -90,7 +90,7 @@ func blockPartMessageHandler(ctrl *Controller) msgHandlerFunc { FromReplay: envelope.fromReplay, }, stateData) if err != nil && msg.Round != stateData.Round { - logger.Debug("received block part from wrong round") + logger.Trace("received block part from wrong round") return nil } return err diff --git a/internal/consensus/peer_state.go b/internal/consensus/peer_state.go index ffcb697ca5..607fc3be86 100644 --- a/internal/consensus/peer_state.go +++ b/internal/consensus/peer_state.go @@ -427,7 +427,7 @@ func (ps *PeerState) SetHasVote(vote *types.Vote) error { // setHasVote will return an error when the index exceeds the bitArray length func (ps *PeerState) setHasVote(height int64, round int32, voteType tmproto.SignedMsgType, index int32) error { - ps.logger.Debug( + ps.logger.Trace( "peerState setHasVote", "peer", ps.peerID, "height", height, @@ -466,7 +466,7 @@ func (ps *PeerState) SetHasCommit(commit *types.Commit) { } func (ps *PeerState) setHasCommit(height int64, round int32) { - ps.logger.Debug( + ps.logger.Trace( "setHasCommit", "height", height, "round", round, diff --git a/internal/consensus/proposal_updater.go b/internal/consensus/proposal_updater.go index 727a125f90..d2c376453c 100644 --- a/internal/consensus/proposal_updater.go +++ b/internal/consensus/proposal_updater.go @@ -16,7 +16,7 @@ func (u *proposalUpdater) updateStateData(stateData *StateData, blockID types.Bl return nil } // If we don't have the block being committed, set up to get it. - u.logger.Info( + u.logger.Debug( "commit is for a block we do not know about; set ProposalBlock=nil", "proposal", stateData.ProposalBlock.Hash(), "commit", blockID.Hash, diff --git a/internal/consensus/reactor.go b/internal/consensus/reactor.go index 10e63f8de7..bd789bfeec 100644 --- a/internal/consensus/reactor.go +++ b/internal/consensus/reactor.go @@ -166,7 +166,7 @@ type channelBundle struct { // messages on that p2p channel accordingly. The caller must be sure to execute // OnStop to ensure the outbound p2p Channels are closed. func (r *Reactor) OnStart(ctx context.Context) error { - r.logger.Debug("consensus wait sync", "wait_sync", r.WaitSync()) + r.logger.Trace("consensus wait sync", "wait_sync", r.WaitSync()) peerUpdates := r.peerEvents(ctx, "consensus") @@ -406,7 +406,7 @@ func (r *Reactor) logResult(err error, logger log.Logger, message string, keyval // the peer. During peer removal, we remove the peer for our set of peers and // signal to all spawned goroutines to gracefully exit in a non-blocking manner. func (r *Reactor) processPeerUpdate(ctx context.Context, peerUpdate p2p.PeerUpdate, chans channelBundle) { - r.logger.Debug("received peer update", "peer", peerUpdate.NodeID, "status", peerUpdate.Status, + r.logger.Trace("received peer update", "peer", peerUpdate.NodeID, "status", peerUpdate.Status, "peer_proTxHash", peerUpdate.ProTxHash.ShortString()) switch peerUpdate.Status { @@ -547,7 +547,7 @@ func (r *Reactor) handleStateMessage(ctx context.Context, envelope *p2p.Envelope case *tmcons.HasVote: if err := ps.ApplyHasVoteMessage(msgI.(*HasVoteMessage)); err != nil { - r.logger.Error("applying HasVote message", "msg", msg, "err", err) + r.logger.Error("applying HasVote message failed", "msg", msg, "err", err) return err } case *tmcons.VoteSetMaj23: @@ -619,7 +619,7 @@ func (r *Reactor) handleDataMessage(ctx context.Context, envelope *p2p.Envelope, } if r.WaitSync() { - logger.Info("ignoring message received during sync", "msg", tmstrings.LazySprintf("%T", msgI)) + logger.Debug("ignoring message received during sync", "msg", tmstrings.LazySprintf("%T", msgI)) return nil } @@ -660,7 +660,7 @@ func (r *Reactor) handleVoteMessage(ctx context.Context, envelope *p2p.Envelope, } if r.WaitSync() { - logger.Info("ignoring message received during sync", "msg", msgI) + logger.Debug("ignoring message received during sync", "msg", msgI) return nil } @@ -715,7 +715,7 @@ func (r *Reactor) handleVoteSetBitsMessage(ctx context.Context, envelope *p2p.En } if r.WaitSync() { - logger.Info("ignoring message received during sync", "msg", msgI) + logger.Debug("ignoring message received during sync", "msg", msgI) return nil } @@ -779,8 +779,6 @@ func (r *Reactor) handleMessage(ctx context.Context, envelope *p2p.Envelope, cha return err } - //r.logger.Debug("received message", "ch_id", envelope.ChannelID, "message", msgI, "peer", envelope.From) - switch envelope.ChannelID { case StateChannel: err = r.handleStateMessage(ctx, envelope, msg, chans.voteSet) @@ -835,7 +833,7 @@ func (r *Reactor) processPeerUpdates(ctx context.Context, peerUpdates *p2p.PeerU func (r *Reactor) peerStatsRoutine(ctx context.Context, peerUpdates *p2p.PeerUpdates) { for { if !r.IsRunning() { - r.logger.Info("stopping peerStatsRoutine") + r.logger.Trace("stopping peerStatsRoutine") return } @@ -843,7 +841,8 @@ func (r *Reactor) peerStatsRoutine(ctx context.Context, peerUpdates *p2p.PeerUpd case msg := <-r.state.statsMsgQueue.ch: ps, ok := r.GetPeerState(msg.PeerID) if !ok || ps == nil { - r.logger.Debug("attempt to update stats for non-existent peer", "peer", msg.PeerID) + // it's quite common to happen when a peer is removed + r.logger.Trace("attempt to update stats for non-existent peer", "peer", msg.PeerID) continue } diff --git a/internal/consensus/replay.go b/internal/consensus/replay.go index f905500d95..d0b769b428 100644 --- a/internal/consensus/replay.go +++ b/internal/consensus/replay.go @@ -49,7 +49,7 @@ func (cs *State) readReplayMessage(ctx context.Context, msg *TimedWALMessage, ne // for logging switch m := msg.Msg.(type) { case types.EventDataRoundState: - cs.logger.Info("Replay: New Step", "height", m.Height, "round", m.Round, "step", m.Step) + cs.logger.Trace("Replay: New Step", "height", m.Height, "round", m.Round, "step", m.Step) // these are playback checks if newStepSub != nil { ctxto, cancel := context.WithTimeout(ctx, 2*time.Second) @@ -78,18 +78,18 @@ func (cs *State) readReplayMessage(ctx context.Context, msg *TimedWALMessage, ne stateData.Votes.SetRound(p.Round) stateData.Round = p.Round } - cs.logger.Info("Replay: Proposal", "height", p.Height, "round", p.Round, "cs.Round", stateData.Round, + cs.logger.Trace("Replay: Proposal", "height", p.Height, "round", p.Round, "cs.Round", stateData.Round, "header", p.BlockID.PartSetHeader, "pol", p.POLRound, "peer", peerID) case *BlockPartMessage: - cs.logger.Info("Replay: BlockPart", "height", msg.Height, "round", msg.Round, "peer", peerID) + cs.logger.Trace("Replay: BlockPart", "height", msg.Height, "round", msg.Round, "peer", peerID) case *VoteMessage: v := msg.Vote - cs.logger.Info("Replay: Vote", "height", v.Height, "round", v.Round, "type", v.Type, + cs.logger.Trace("Replay: Vote", "height", v.Height, "round", v.Round, "type", v.Type, "blockID", v.BlockID, "peer", peerID) } _ = cs.msgDispatcher.dispatch(ctx, &stateData, m, msgFromReplay()) case timeoutInfo: - cs.logger.Info("Replay: Timeout", "height", m.Height, "round", m.Round, "step", m.Step, "dur", m.Duration) + cs.logger.Trace("Replay: Timeout", "height", m.Height, "round", m.Round, "step", m.Step, "dur", m.Duration) cs.handleTimeout(ctx, m, &stateData) default: return fmt.Errorf("replay: Unknown TimedWALMessage type: %v", reflect.TypeOf(msg.Msg)) diff --git a/internal/consensus/replayer.go b/internal/consensus/replayer.go index 1ccdad0e0d..6cb6e3c646 100644 --- a/internal/consensus/replayer.go +++ b/internal/consensus/replayer.go @@ -272,7 +272,7 @@ func (r *BlockReplayer) replayBlock( state sm.State, height int64, ) (sm.CurrentRoundState, *abci.ResponseFinalizeBlock, error) { - r.logger.Info("Applying block", "height", height) + r.logger.Info("Replay: applying block", "height", height) // Extra check to ensure the app was not changed in a way it shouldn't have. ucState, err := r.blockExec.ProcessProposal(ctx, block, commit.Round, state, false) if err != nil { @@ -337,8 +337,8 @@ func (r *BlockReplayer) execInitChain(ctx context.Context, rs *replayState, stat } quorumType := state.Validators.QuorumType - if quorumType.Validate() != nil { - r.logger.Debug("state quorum type: %w", err) + if err := quorumType.Validate(); err != nil { + r.logger.Error("state quorum type validation failed: %w", err) quorumType = r.genDoc.QuorumType } diff --git a/internal/consensus/round_scheduler.go b/internal/consensus/round_scheduler.go index f26732abb2..a6df0c9369 100644 --- a/internal/consensus/round_scheduler.go +++ b/internal/consensus/round_scheduler.go @@ -15,7 +15,6 @@ type roundScheduler struct { // ScheduleRound0 enterNewRoundCommand(height, 0) at StartTime func (b *roundScheduler) ScheduleRound0(rs cstypes.RoundState) { - // b.logger.Info("scheduleRound0", "now", tmtime.Now(), "startTime", b.StartTime) sleepDuration := rs.StartTime.Sub(tmtime.Now()) b.ScheduleTimeout(sleepDuration, rs.Height, 0, cstypes.RoundStepNewHeight) } diff --git a/internal/consensus/state.go b/internal/consensus/state.go index 81e1036756..91af6fac30 100644 --- a/internal/consensus/state.go +++ b/internal/consensus/state.go @@ -459,7 +459,7 @@ func (cs *State) OnStart(ctx context.Context) error { return err } - cs.logger.Debug("backed up WAL file", "src", cs.config.WalFile(), "dst", corruptedFile) + cs.logger.Info("backed up WAL file", "src", cs.config.WalFile(), "dst", corruptedFile) // 3) try to repair (WAL file will be overwritten!) if err := repairWalFile(corruptedFile, cs.config.WalFile()); err != nil { @@ -722,7 +722,7 @@ func (cs *State) handleTimeout( ti timeoutInfo, stateData *StateData, ) { - cs.logger.Debug("received tock", "timeout", ti.Duration, "height", ti.Height, "round", ti.Round, "step", ti.Step) + cs.logger.Trace("received tock", "timeout", ti.Duration, "height", ti.Height, "round", ti.Round, "step", ti.Step) // timeouts must be for current height, round, step if ti.Height != stateData.Height || ti.Round < stateData.Round || (ti.Round == stateData.Round && ti.Step < stateData.Step) { @@ -801,7 +801,7 @@ func (cs *State) CreateProposalBlock(ctx context.Context) (*types.Block, error) // PublishCommitEvent ... func (cs *State) PublishCommitEvent(commit *types.Commit) error { - cs.logger.Debug("publish commit event", "commit", commit) + cs.logger.Trace("publish commit event", "commit", commit) if err := cs.eventBus.PublishEventCommit(types.EventDataCommit{Commit: commit}); err != nil { return err } diff --git a/internal/consensus/state_add_prop_block.go b/internal/consensus/state_add_prop_block.go index fd5a914c86..bf2b5d4376 100644 --- a/internal/consensus/state_add_prop_block.go +++ b/internal/consensus/state_add_prop_block.go @@ -75,7 +75,7 @@ func (c *AddProposalBlockPartAction) addProposalBlockPart( peerID types.NodeID, ) (bool, error) { height, round, part := msg.Height, msg.Round, msg.Part - c.logger.Info( + c.logger.Trace( "addProposalBlockPart", "height", stateData.Height, "round", stateData.Round, @@ -158,6 +158,20 @@ func (c *AddProposalBlockPartAction) addProposalBlockPart( } // NOTE: it's possible to receive complete proposal blocks for future rounds without having the proposal + + if stateData.Commit != nil { + c.logger.Info("received complete proposal block and commit", + "proposal", stateData.ProposalBlock, + "commit", stateData.Commit, + "height", stateData.RoundState.Height, + "round", stateData.RoundState.Round, + "hash", stateData.ProposalBlock.Hash(), + ) + // We received a commit before the block + // Transit to AddCommit + return added, ctrl.Dispatch(ctx, &AddCommitEvent{Commit: stateData.Commit}, stateData) + } + c.logger.Info( "received complete proposal block", "height", stateData.RoundState.Height, @@ -168,20 +182,6 @@ func (c *AddProposalBlockPartAction) addProposalBlockPart( ) c.eventPublisher.PublishCompleteProposalEvent(stateData.CompleteProposalEvent()) - - if stateData.Commit != nil { - c.logger.Info("Proposal block fully received", "proposal", stateData.ProposalBlock) - c.logger.Info("Commit already present", "commit", stateData.Commit) - c.logger.Debug("adding commit after complete proposal", - "height", stateData.ProposalBlock.Height, - "hash", stateData.ProposalBlock.Hash(), - ) - // We received a commit before the block - // Transit to AddCommit - return added, ctrl.Dispatch(ctx, &AddCommitEvent{Commit: stateData.Commit}, stateData) - } - - return added, nil } return added, nil @@ -236,7 +236,6 @@ func (c *ProposalCompletedAction) Execute(ctx context.Context, stateEvent StateE "height", stateData.RoundState.Height, "round", stateData.RoundState.Round, "proposal_height", stateData.ProposalBlock.Height, - "hash", stateData.ProposalBlock.Hash(), ) err := stateEvent.Ctrl.Dispatch(ctx, &EnterPrevoteEvent{ diff --git a/internal/consensus/state_add_vote.go b/internal/consensus/state_add_vote.go index a1d24d63e2..0644beb518 100644 --- a/internal/consensus/state_add_vote.go +++ b/internal/consensus/state_add_vote.go @@ -110,7 +110,7 @@ func addVoteToLastPrecommitMw(ep *EventPublisher, ctrl *Controller) AddVoteMiddl logger := log.FromCtxOrNop(ctx) if stateData.Step != cstypes.RoundStepNewHeight { // Late precommit at prior height is ignored - logger.Debug("precommit vote came in after commit timeout and has been ignored") + logger.Trace("precommit vote came in after commit timeout and has been ignored") return false, nil } if stateData.LastPrecommits == nil { @@ -122,7 +122,7 @@ func addVoteToLastPrecommitMw(ep *EventPublisher, ctrl *Controller) AddVoteMiddl logger.Debug("vote not added to last precommits", logKeyValsWithError(nil, err)...) return false, nil } - logger.Debug("added vote to last precommits", "last_precommits", stateData.LastPrecommits) + logger.Trace("added vote to last precommits", "last_precommits", stateData.LastPrecommits) err = ep.PublishVoteEvent(vote) if err != nil { @@ -341,7 +341,7 @@ func addVoteErrorMw(evpool evidencePool, logger log.Logger, privVal privValidato return added, err } if errors.Is(err, types.ErrVoteNonDeterministicSignature) { - logger.Debug("vote has non-deterministic signature", "err", err) + logger.Error("vote has non-deterministic signature", "err", err) return added, err } // If the vote height is off, we'll just ignore it, @@ -365,7 +365,7 @@ func addVoteErrorMw(evpool evidencePool, logger log.Logger, privVal privValidato // report conflicting votes to the evidence pool evpool.ReportConflictingVotes(voteErr.VoteA, voteErr.VoteB) - logger.Debug("found and sent conflicting votes to the evidence pool", + logger.Error("found and sent conflicting votes to the evidence pool", "vote_a", voteErr.VoteA, "vote_b", voteErr.VoteB) return added, err @@ -395,7 +395,7 @@ func addVoteLoggingMw() AddVoteMiddlewareFunc { return added, err } votes := stateData.Votes.GetVoteSet(vote.Round, vote.Type) - logger.Debug("vote added", "data", votes) + logger.Trace("vote added", "data", votes) return added, err } } diff --git a/internal/consensus/state_data.go b/internal/consensus/state_data.go index 589f1bec37..519d60175a 100644 --- a/internal/consensus/state_data.go +++ b/internal/consensus/state_data.go @@ -258,7 +258,7 @@ func (s *StateData) updateToState(state sm.State, commit *types.Commit) { height = state.InitialHeight } - s.logger.Debug("updating state height", "newHeight", height) + s.logger.Trace("updating state height", "newHeight", height) // RoundState fields s.updateHeight(height) @@ -350,11 +350,11 @@ func (s *StateData) verifyCommit(commit *types.Commit, peerID types.NodeID, igno // A commit for the previous height? // These come in while we wait timeoutCommit if commit.Height+1 == stateHeight { - s.logger.Debug("old commit ignored", "commit", commit) + s.logger.Trace("old commit ignored", "commit", commit) return false, nil } - s.logger.Debug( + s.logger.Trace( "verifying commit from remote", "commit_height", commit.Height, "cs_height", s.Height, @@ -377,9 +377,9 @@ func (s *StateData) verifyCommit(commit *types.Commit, peerID types.NodeID, igno if rs.Proposal == nil || ignoreProposalBlock { if ignoreProposalBlock { - s.logger.Info("Commit verified for future round", "height", commit.Height, "round", commit.Round) + s.logger.Debug("Commit verified for future round", "height", commit.Height, "round", commit.Round) } else { - s.logger.Info("Commit came in before proposal", "height", commit.Height, "round", commit.Round) + s.logger.Debug("Commit came in before proposal", "height", commit.Height, "round", commit.Round) } // We need to verify that it was properly signed @@ -389,7 +389,7 @@ func (s *StateData) verifyCommit(commit *types.Commit, peerID types.NodeID, igno } if !s.ProposalBlockParts.HasHeader(commit.BlockID.PartSetHeader) { - s.logger.Info("setting proposal block parts from commit", "partSetHeader", commit.BlockID.PartSetHeader) + s.logger.Debug("setting proposal block parts from commit", "partSetHeader", commit.BlockID.PartSetHeader) s.ProposalBlockParts = types.NewPartSetFromHeader(commit.BlockID.PartSetHeader) } @@ -426,7 +426,7 @@ func (s *StateData) replaceProposalBlockOnLockedBlock(blockID types.BlockID) { } s.ProposalBlock = s.LockedBlock s.ProposalBlockParts = s.LockedBlockParts - s.logger.Debug("commit is for a locked block; set ProposalBlock=LockedBlock", "block_hash", blockID.Hash) + s.logger.Trace("commit is for a locked block; set ProposalBlock=LockedBlock", "block_hash", blockID.Hash) } func (s *StateData) proposeTimeout(round int32) time.Duration { diff --git a/internal/consensus/state_enter_commit.go b/internal/consensus/state_enter_commit.go index d210b6377e..723f3ba710 100644 --- a/internal/consensus/state_enter_commit.go +++ b/internal/consensus/state_enter_commit.go @@ -36,7 +36,8 @@ func (c *EnterCommitAction) Execute(ctx context.Context, stateEvent StateEvent) logger := c.logger.With("new_height", height, "commit_round", commitRound) if stateData.Height != height || cstypes.RoundStepApplyCommit <= stateData.Step { - logger.Debug("entering commit step with invalid args", + // this is quite common event + logger.Trace("entering commit step with invalid args", "height", stateData.Height, "round", stateData.Round, "step", stateData.Step) diff --git a/internal/consensus/state_enter_new_round.go b/internal/consensus/state_enter_new_round.go index dcc23afeb8..d38bed9e90 100644 --- a/internal/consensus/state_enter_new_round.go +++ b/internal/consensus/state_enter_new_round.go @@ -49,7 +49,8 @@ func (c *EnterNewRoundAction) Execute(ctx context.Context, stateEvent StateEvent logger := c.logger.With("height", height, "round", round) if stateData.Height != height || round < stateData.Round || (stateData.Round == round && stateData.Step != cstypes.RoundStepNewHeight) { - logger.Debug("entering new round with invalid args", + // this is quite common event + logger.Trace("entering new round with invalid args", "height", stateData.Height, "round", stateData.Round, "step", stateData.Step) @@ -57,7 +58,7 @@ func (c *EnterNewRoundAction) Execute(ctx context.Context, stateEvent StateEvent } if now := tmtime.Now(); stateData.StartTime.After(now) { - logger.Debug("need to set a buffer and log message here for sanity", "start_time", stateData.StartTime, "now", now) + logger.Trace("need to set a buffer and log message here for sanity", "start_time", stateData.StartTime, "now", now) } logger.Debug("entering new round", @@ -82,7 +83,7 @@ func (c *EnterNewRoundAction) Execute(ctx context.Context, stateEvent StateEvent // and meanwhile we might have received a proposal // for round 0. } else { - logger.Debug("resetting proposal info") + logger.Trace("resetting proposal info") stateData.Proposal = nil stateData.ProposalReceiveTime = time.Time{} stateData.ProposalBlock = nil diff --git a/internal/consensus/state_enter_precommit.go b/internal/consensus/state_enter_precommit.go index 8834850666..41e53b1075 100644 --- a/internal/consensus/state_enter_precommit.go +++ b/internal/consensus/state_enter_precommit.go @@ -47,7 +47,7 @@ func (c *EnterPrecommitAction) Execute(ctx context.Context, stateEvent StateEven logger := c.logger.With("new_height", height, "new_round", round) if stateData.Height != height || round < stateData.Round || (stateData.Round == round && cstypes.RoundStepPrecommit <= stateData.Step) { - logger.Debug("entering precommit step with invalid args", + logger.Trace("entering precommit step with invalid args", "height", stateData.Height, "round", stateData.Round, "step", stateData.Step) @@ -68,11 +68,12 @@ func (c *EnterPrecommitAction) Execute(ctx context.Context, stateEvent StateEven blockID, ok := stateData.Votes.Prevotes(round).TwoThirdsMajority() // If we don't have a polka, we must precommit nil. + // From protocol perspective it's an error condition, so we log it on Error level. if !ok { if stateData.LockedBlock != nil { - logger.Debug("precommit step; no +2/3 prevotes during enterPrecommit while we are locked; precommitting nil") + logger.Error("precommit step; no +2/3 prevotes during enterPrecommit while we are locked; precommitting nil") } else { - logger.Debug("precommit step; no +2/3 prevotes during enterPrecommit; precommitting nil") + logger.Error("precommit step; no +2/3 prevotes during enterPrecommit; precommitting nil") } c.voteSigner.signAddVote(ctx, stateData, tmproto.PrecommitType, types.BlockID{}) @@ -90,7 +91,8 @@ func (c *EnterPrecommitAction) Execute(ctx context.Context, stateEvent StateEven // +2/3 prevoted nil. Precommit nil. if blockID.IsNil() { - logger.Debug("precommit step: +2/3 prevoted for nil; precommitting nil") + // From protocol perspective it's an error condition, so we log it on Error level. + logger.Error("precommit step: +2/3 prevoted for nil; precommitting nil") c.voteSigner.signAddVote(ctx, stateData, tmproto.PrecommitType, types.BlockID{}) return nil } @@ -105,7 +107,7 @@ func (c *EnterPrecommitAction) Execute(ctx context.Context, stateEvent StateEven // If the proposal time does not match the block time, precommit nil. if !stateData.Proposal.Timestamp.Equal(stateData.ProposalBlock.Header.Time) { - logger.Debug("precommit step: proposal timestamp not equal; precommitting nil") + logger.Error("precommit step: proposal timestamp not equal; precommitting nil") c.voteSigner.signAddVote(ctx, stateData, tmproto.PrecommitType, types.BlockID{}) return nil } diff --git a/internal/consensus/state_enter_prevote.go b/internal/consensus/state_enter_prevote.go index e57559e093..7e32071b93 100644 --- a/internal/consensus/state_enter_prevote.go +++ b/internal/consensus/state_enter_prevote.go @@ -42,7 +42,7 @@ func (c *EnterPrevoteAction) Execute(ctx context.Context, statEvent StateEvent) logger := c.logger.With("height", height, "round", round) if stateData.Height != height || round < stateData.Round || (stateData.Round == round && cstypes.RoundStepPrevote <= stateData.Step) { - logger.Debug("entering prevote step with invalid args", + logger.Trace("entering prevote step with invalid args", "height", stateData.Height, "round", stateData.Round, "step", stateData.Step) diff --git a/internal/consensus/state_enter_propose.go b/internal/consensus/state_enter_propose.go index ee41820493..e9ae2075c8 100644 --- a/internal/consensus/state_enter_propose.go +++ b/internal/consensus/state_enter_propose.go @@ -45,7 +45,7 @@ func (c *EnterProposeAction) Execute(ctx context.Context, stateEvent StateEvent) if stateData.Height != height || round < stateData.Round || (stateData.Round == round && cstypes.RoundStepPropose <= stateData.Step) { - logger.Debug("entering propose step with invalid args", "step", stateData.Step) + logger.Trace("entering propose step with invalid args", "step", stateData.Step) return nil } @@ -67,11 +67,6 @@ func (c *EnterProposeAction) Execute(ctx context.Context, stateEvent StateEvent) } } - logger.Debug("entering propose step", - "height", stateData.Height, - "round", stateData.Round, - "step", stateData.Step) - defer func() { // Done enterPropose: stateData.updateRoundStep(round, cstypes.RoundStepPropose) @@ -89,9 +84,12 @@ func (c *EnterProposeAction) Execute(ctx context.Context, stateEvent StateEvent) c.scheduler.ScheduleTimeout(stateData.proposeTimeout(round), height, round, cstypes.RoundStepPropose) if !isProposer { - logger.Debug("propose step; not our turn to propose", + logger.Info("propose step; not our turn to propose", "proposer_proTxHash", stateData.Validators.GetProposer().ProTxHash, - "node_proTxHash", proTxHash.String()) + "node_proTxHash", proTxHash.String(), + "height", stateData.Height, + "round", stateData.Round, + "step", stateData.Step) return nil } // In replay mode, we don't propose blocks. @@ -100,8 +98,11 @@ func (c *EnterProposeAction) Execute(ctx context.Context, stateEvent StateEvent) return nil } - logger.Debug("propose step; our turn to propose", + logger.Info("propose step; our turn to propose", "proposer_proTxHash", proTxHash.ShortString(), + "height", stateData.Height, + "round", stateData.Round, + "step", stateData.Step, ) // Flush the WAL. Otherwise, we may not recompute the same proposal to sign, // and the privVal will refuse to sign anything. diff --git a/internal/consensus/state_enter_wait.go b/internal/consensus/state_enter_wait.go index 0df6dfd38f..875d0bb928 100644 --- a/internal/consensus/state_enter_wait.go +++ b/internal/consensus/state_enter_wait.go @@ -35,7 +35,7 @@ func (c *EnterPrecommitWaitAction) Execute(ctx context.Context, stateEvent State logger := c.logger.With("new_height", height, "new_round", round) if stateData.Height != height || round < stateData.Round || (stateData.Round == round && stateData.TriggeredTimeoutPrecommit) { - logger.Debug("entering precommit wait step with invalid args", + logger.Trace("entering precommit wait step with invalid args", "triggered_timeout", stateData.TriggeredTimeoutPrecommit, "height", stateData.Height, "round", stateData.Round) diff --git a/internal/consensus/state_prevoter.go b/internal/consensus/state_prevoter.go index 8988a0c1a7..fdc7913603 100644 --- a/internal/consensus/state_prevoter.go +++ b/internal/consensus/state_prevoter.go @@ -39,7 +39,7 @@ func (p *prevoter) Do(ctx context.Context, stateData *StateData) error { err := stateData.isValidForPrevote() if err != nil { keyVals := append(prevoteKeyVals(stateData), "error", err) - p.logger.Debug("prevote is invalid", keyVals...) + p.logger.Error("prevote is invalid", keyVals...) p.signAndAddNilVote(ctx, stateData) return nil } diff --git a/internal/consensus/state_proposaler.go b/internal/consensus/state_proposaler.go index 69db2a01b3..48848927b7 100644 --- a/internal/consensus/state_proposaler.go +++ b/internal/consensus/state_proposaler.go @@ -103,7 +103,7 @@ func (p *Proposaler) Create(ctx context.Context, height int64, round int32, rs * logger.Error("propose step; failed signing proposal", "error", err) return err } - p.logger.Debug("replay; failed signing proposal", "proposal", proposal, "error", err) + p.logger.Error("replay; failed signing proposal", "proposal", proposal, "error", err) return err } p.logger.Debug("signed proposal", "proposal", proposal) @@ -160,7 +160,7 @@ func (p *Proposaler) checkValidBlock(rs *cstypes.RoundState) bool { return rs.ValidBlock.Time.Equal(p.committedState.LastBlockTime) } if !rs.ValidBlock.IsTimely(rs.ValidBlockRecvTime, sp, rs.ValidRound) { - p.logger.Debug( + p.logger.Error( "proposal block is outdated", "height", rs.Height, "round", rs.ValidRound, @@ -209,7 +209,7 @@ func (p *Proposaler) verifyProposal(proposal *types.Proposal, rs *cstypes.RoundS if proposer.PubKey.VerifySignatureDigest(proposalBlockSignID, proposal.Signature) { return nil } - p.logger.Debug( + p.logger.Error( "error verifying signature", "height", rs.Height, "proposal_height", proposal.Height, @@ -234,7 +234,7 @@ func (p *Proposaler) verifyProposalForNonValidatorSet(proposal *types.Proposal, // We need to verify that the commit block id is equal to the proposal block id if !proposal.BlockID.Equals(commit.BlockID) { proposer := rs.Validators.GetProposer() - p.logger.Debug("proposal blockID isn't the same as the commit blockID", + p.logger.Error("proposal blockID isn't the same as the commit blockID", "height", proposal.Height, "round", proposal.Round, "proposer_proTxHash", proposer.ProTxHash.ShortString()) diff --git a/internal/consensus/state_try_add_commit.go b/internal/consensus/state_try_add_commit.go index b141c78dd6..4537d37a2d 100644 --- a/internal/consensus/state_try_add_commit.go +++ b/internal/consensus/state_try_add_commit.go @@ -46,7 +46,7 @@ func (cs *TryAddCommitAction) Execute(ctx context.Context, stateEvent StateEvent // We need to first verify that the commit received wasn't for a future round, // If it was then we must go to next round if commit.Height == rs.Height && commit.Round > rs.Round { - cs.logger.Debug("Commit received for a later round", "height", commit.Height, "our round", + cs.logger.Trace("Commit received for a later round", "height", commit.Height, "our round", rs.Round, "commit round", commit.Round) verified, err := cs.verifyCommit(ctx, stateData, commit, peerID, true) if err != nil { diff --git a/internal/consensus/state_try_finalize_commit.go b/internal/consensus/state_try_finalize_commit.go index ea449d6b20..dacdd443f6 100644 --- a/internal/consensus/state_try_finalize_commit.go +++ b/internal/consensus/state_try_finalize_commit.go @@ -47,7 +47,7 @@ func (cs *TryFinalizeCommitAction) Execute(ctx context.Context, stateEvent State if !stateData.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", + logger.Trace("failed attempt to finalize commit; we do not have the commit block", "proposal_block", tmstrings.LazyBlockHash(stateData.ProposalBlock), "commit_block", blockID.Hash, ) @@ -88,6 +88,7 @@ func (cs *TryFinalizeCommitAction) finalizeCommit(ctx context.Context, ctrl *Con "hash", tmstrings.LazyBlockHash(block), "root", block.AppHash, "num_txs", len(block.Txs), + "block", block, ) precommits := stateData.Votes.Precommits(stateData.CommitRound) diff --git a/internal/consensus/ticker.go b/internal/consensus/ticker.go index 3e8f5eb9a9..a768854c6f 100644 --- a/internal/consensus/ticker.go +++ b/internal/consensus/ticker.go @@ -93,7 +93,7 @@ func (t *timeoutTicker) timeoutRoutine(ctx context.Context) { for { select { case newti := <-t.tickChan: - t.logger.Debug("Received tick", "old_ti", ti, "new_ti", newti) + t.logger.Trace("Received tick", "old_ti", ti, "new_ti", newti) // ignore tickers for old height/round/step if newti.Height < ti.Height { @@ -115,7 +115,7 @@ func (t *timeoutTicker) timeoutRoutine(ctx context.Context) { // NOTE time.Timer allows duration to be non-positive ti = newti t.timer.Reset(ti.Duration) - t.logger.Debug("Internal state machine timeout scheduled", "duration", ti.Duration, "height", ti.Height, "round", ti.Round, "step", ti.Step.String()) + t.logger.Trace("Internal state machine timeout scheduled", "duration", ti.Duration, "height", ti.Height, "round", ti.Round, "step", ti.Step.String()) case <-t.timer.C: t.logger.Debug("Internal state machine timeout elapsed", "duration", ti.Duration, "height", ti.Height, "round", ti.Round, "step", ti.Step.String()) // go routine here guarantees timeoutRoutine doesn't block. diff --git a/internal/consensus/vote_signer.go b/internal/consensus/vote_signer.go index bdfa7758d8..62ef6cee30 100644 --- a/internal/consensus/vote_signer.go +++ b/internal/consensus/vote_signer.go @@ -34,7 +34,7 @@ func (s *voteSigner) signAddVote( } // If the node not in the validator set, do nothing. if !stateData.Validators.HasProTxHash(s.privValidator.ProTxHash) { - s.logger.Debug("do nothing, node is not a part of validator set") + s.logger.Error("do nothing, node is not a part of validator set") return nil } keyVals := []any{"height", stateData.Height, "round", stateData.Round, "quorum_hash", stateData.Validators.QuorumHash}