diff --git a/consensus/reactor.go b/consensus/reactor.go index 902ed76f7..f8a6dfae1 100644 --- a/consensus/reactor.go +++ b/consensus/reactor.go @@ -388,7 +388,6 @@ OUTER_LOOP: // Send proposal Block parts? if rs.ProposalBlockParts.HasHeader(prs.ProposalBlockPartsHeader) { - //logger.Info("ProposalBlockParts matched", "blockParts", prs.ProposalBlockParts) if index, ok := rs.ProposalBlockParts.BitArray().Sub(prs.ProposalBlockParts.Copy()).PickRandom(); ok { part := rs.ProposalBlockParts.GetPart(index) msg := &BlockPartMessage{ @@ -396,6 +395,7 @@ OUTER_LOOP: Round: rs.Round, // This tells peer that this part applies to us. Part: part, } + logger.Debug("Sending block part", "height", prs.Height, "round", prs.Round) if peer.Send(DataChannel, struct{ ConsensusMessage }{msg}) { ps.SetHasProposalBlockPart(prs.Height, prs.Round, index) } @@ -405,7 +405,6 @@ OUTER_LOOP: // If the peer is on a previous height, help catch up. if (0 < prs.Height) && (prs.Height < rs.Height) { - //logger.Info("Data catchup", "height", rs.Height, "peerHeight", prs.Height, "peerProposalBlockParts", prs.ProposalBlockParts) if index, ok := prs.ProposalBlockParts.Not().PickRandom(); ok { // Ensure that the peer's PartSetHeader is correct blockMeta := conR.conS.blockStore.LoadBlockMeta(prs.Height) @@ -433,6 +432,7 @@ OUTER_LOOP: Round: prs.Round, // Not our height, so it doesn't matter. Part: part, } + logger.Debug("Sending block part for catchup", "height", prs.Height, "round", prs.Round) if peer.Send(DataChannel, struct{ ConsensusMessage }{msg}) { ps.SetHasProposalBlockPart(prs.Height, prs.Round, index) } @@ -461,6 +461,7 @@ OUTER_LOOP: // Proposal: share the proposal metadata with peer. { msg := &ProposalMessage{Proposal: rs.Proposal} + logger.Debug("Sending proposal", "height", prs.Height, "round", prs.Round) if peer.Send(DataChannel, struct{ ConsensusMessage }{msg}) { ps.SetHasProposal(rs.Proposal) } @@ -475,6 +476,7 @@ OUTER_LOOP: ProposalPOLRound: rs.Proposal.POLRound, ProposalPOL: rs.Votes.Prevotes(rs.Proposal.POLRound).BitArray(), } + logger.Debug("Sending POL", "height", prs.Height, "round", prs.Round) peer.Send(DataChannel, struct{ ConsensusMessage }{msg}) } continue OUTER_LOOP @@ -517,21 +519,21 @@ OUTER_LOOP: // If there are lastCommits to send... if prs.Step == RoundStepNewHeight { if ps.PickSendVote(rs.LastCommit) { - logger.Debug("Picked rs.LastCommit to send") + logger.Debug("Picked rs.LastCommit to send", "height", prs.Height) continue OUTER_LOOP } } // If there are prevotes to send... if prs.Step <= RoundStepPrevote && prs.Round != -1 && prs.Round <= rs.Round { if ps.PickSendVote(rs.Votes.Prevotes(prs.Round)) { - logger.Debug("Picked rs.Prevotes(prs.Round) to send") + logger.Debug("Picked rs.Prevotes(prs.Round) to send", "height", prs.Height, "round", prs.Round) continue OUTER_LOOP } } // If there are precommits to send... if prs.Step <= RoundStepPrecommit && prs.Round != -1 && prs.Round <= rs.Round { if ps.PickSendVote(rs.Votes.Precommits(prs.Round)) { - logger.Debug("Picked rs.Precommits(prs.Round) to send") + logger.Debug("Picked rs.Precommits(prs.Round) to send", "height", prs.Height, "round", prs.Round) continue OUTER_LOOP } } @@ -539,7 +541,7 @@ OUTER_LOOP: if prs.ProposalPOLRound != -1 { if polPrevotes := rs.Votes.Prevotes(prs.ProposalPOLRound); polPrevotes != nil { if ps.PickSendVote(polPrevotes) { - logger.Debug("Picked rs.Prevotes(prs.ProposalPOLRound) to send") + logger.Debug("Picked rs.Prevotes(prs.ProposalPOLRound) to send", "height", prs.Height, "round", prs.ProposalPOLRound) continue OUTER_LOOP } } @@ -550,7 +552,7 @@ OUTER_LOOP: // If peer is lagging by height 1, send LastCommit. if prs.Height != 0 && rs.Height == prs.Height+1 { if ps.PickSendVote(rs.LastCommit) { - logger.Debug("Picked rs.LastCommit to send") + logger.Debug("Picked rs.LastCommit to send", "height", prs.Height) continue OUTER_LOOP } } @@ -563,7 +565,7 @@ OUTER_LOOP: commit := conR.conS.blockStore.LoadBlockCommit(prs.Height) logger.Info("Loaded BlockCommit for catch-up", "height", prs.Height, "commit", commit) if ps.PickSendVote(commit) { - logger.Debug("Picked Catchup commit to send") + logger.Debug("Picked Catchup commit to send", "height", prs.Height) continue OUTER_LOOP } } @@ -571,7 +573,7 @@ OUTER_LOOP: if sleeping == 0 { // We sent nothing. Sleep... sleeping = 1 - logger.Debug("No votes to send, sleeping", + logger.Debug("No votes to send, sleeping", "rs.Height", rs.Height, "prs.Height", prs.Height, "localPV", rs.Votes.Prevotes(rs.Round).BitArray(), "peerPV", prs.Prevotes, "localPC", rs.Votes.Precommits(rs.Round).BitArray(), "peerPC", prs.Precommits) } else if sleeping == 2 { diff --git a/consensus/state.go b/consensus/state.go index fe98e854a..75da2a08d 100644 --- a/consensus/state.go +++ b/consensus/state.go @@ -912,16 +912,17 @@ func (cs *ConsensusState) enterPrevote(height int, round int) { } func (cs *ConsensusState) defaultDoPrevote(height int, round int) { + logger := cs.Logger.With("height", height, "round", round) // If a block is locked, prevote that. if cs.LockedBlock != nil { - cs.Logger.Info("enterPrevote: Block was locked") + logger.Info("enterPrevote: Block was locked") cs.signAddVote(types.VoteTypePrevote, cs.LockedBlock.Hash(), cs.LockedBlockParts.Header()) return } // If ProposalBlock is nil, prevote nil. if cs.ProposalBlock == nil { - cs.Logger.Info("enterPrevote: ProposalBlock is nil") + logger.Info("enterPrevote: ProposalBlock is nil") cs.signAddVote(types.VoteTypePrevote, nil, types.PartSetHeader{}) return } @@ -930,7 +931,7 @@ func (cs *ConsensusState) defaultDoPrevote(height int, round int) { err := cs.state.ValidateBlock(cs.ProposalBlock) if err != nil { // ProposalBlock is invalid, prevote nil. - cs.Logger.Error("enterPrevote: ProposalBlock is invalid", "err", err) + logger.Error("enterPrevote: ProposalBlock is invalid", "err", err) cs.signAddVote(types.VoteTypePrevote, nil, types.PartSetHeader{}) return }