From 64fec908d6e3193a51bf6faf4a03afc386f5a216 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Andr=C3=A9=20Patta?= Date: Thu, 7 Nov 2024 06:31:02 -0300 Subject: [PATCH] ibft: more log messages --- consensus/istanbul/core/commit.go | 15 +++---- consensus/istanbul/core/core.go | 7 ++-- consensus/istanbul/core/handler.go | 4 +- consensus/istanbul/core/prepare.go | 17 ++++---- consensus/istanbul/core/preprepare.go | 12 +++--- consensus/istanbul/core/roundchange.go | 29 ++++++++------ consensus/istanbul/types/roundchange.go | 52 ++++++++++++------------- 7 files changed, 73 insertions(+), 63 deletions(-) diff --git a/consensus/istanbul/core/commit.go b/consensus/istanbul/core/commit.go index 874fae85a..a939c5682 100644 --- a/consensus/istanbul/core/commit.go +++ b/consensus/istanbul/core/commit.go @@ -42,7 +42,7 @@ func (c *core) broadcastCommit() { // Create Commit Seal commitSeal, err := c.backend.SignWithoutHashing(PrepareCommittedSeal(header, uint32(c.currentView().Round.Uint64()))) if err != nil { - logger.Error("IBFT: failed to create COMMIT seal", "sub", sub, "err", err) + logger.Error("[Consensus]: Failed to create COMMIT seal", "sub", sub, "err", err) return } @@ -52,13 +52,13 @@ func (c *core) broadcastCommit() { // Sign Message encodedPayload, err := commit.EncodePayloadForSigning() if err != nil { - withMsg(logger, commit).Error("IBFT: failed to encode payload of COMMIT message", "err", err) + withMsg(logger, commit).Error("[Consensus]: Failed to encode payload of COMMIT message", "err", err) return } signature, err := c.backend.Sign(encodedPayload) if err != nil { - withMsg(logger, commit).Error("IBFT: failed to sign COMMIT message", "err", err) + withMsg(logger, commit).Error("[Consensus]: Failed to sign COMMIT message", "err", err) return } commit.SetSignature(signature) @@ -66,15 +66,16 @@ func (c *core) broadcastCommit() { // RLP-encode message payload, err := rlp.EncodeToBytes(&commit) if err != nil { - withMsg(logger, commit).Error("IBFT: failed to encode COMMIT message", "err", err) + withMsg(logger, commit).Error("[Consensus]: Failed to encode COMMIT message", "err", err) return } withMsg(logger, commit).Trace("IBFT: broadcast COMMIT message", "payload", hexutil.Encode(payload)) + c.cleanLogger.Info("[Consensus]: -> Broadcasting COMMIT message to validators") // Broadcast RLP-encoded message if err = c.backend.Broadcast(c.valSet, commit.Code(), payload); err != nil { - withMsg(logger, commit).Error("IBFT: failed to broadcast COMMIT message", "err", err) + withMsg(logger, commit).Error("[Consensus]: Failed to broadcast COMMIT message", "err", err) return } } @@ -106,7 +107,8 @@ func (c *core) handleCommitMsg(commit *qbfttypes.Commit) error { // If we reached thresho if c.current.QBFTCommits.Size() >= c.QuorumSize() { - logger.Trace("Consensus: Received quorum of COMMIT messages") + logger.Trace("[Consensus]: Received quorum of COMMIT messages") + c.cleanLogger.Info("[Consensus]: <- Received quorum of COMMIT messages", "count", c.current.QBFTCommits.Size(), "quorum", c.QuorumSize()) c.commitQBFT() } else { logger.Debug("IBFT: accepted new COMMIT messages") @@ -139,5 +141,4 @@ func (c *core) commitQBFT() { return } } - c.cleanLogger.Info("Consensus: Block proposal COMMITTED") } diff --git a/consensus/istanbul/core/core.go b/consensus/istanbul/core/core.go index 7c95f5905..5b323acb3 100644 --- a/consensus/istanbul/core/core.go +++ b/consensus/istanbul/core/core.go @@ -133,7 +133,7 @@ func (c *core) startNewRound(round *big.Int) { c.cleanLogger.Info("=====================================================") - logger.Info("Consensus: Initializing new round") + logger.Info("[Consensus]: Initializing new round") if c.current == nil { logger.Debug("IBFT: start at the initial round") @@ -190,7 +190,7 @@ func (c *core) startNewRound(round *big.Int) { c.valSet.CalcProposer(lastProposer, newView.Round.Uint64()) c.setState(StateAcceptRequest) - c.cleanLogger.Info("Consensus: Proposer selected", "proposer", c.valSet.GetProposer().Address()) + c.cleanLogger.Info("[Consensus]: Proposer selected", "proposer", c.valSet.GetProposer().Address()) if c.current != nil && round.Cmp(c.current.Round()) > 0 { roundMeter.Mark(new(big.Int).Sub(round, c.current.Round()).Int64()) @@ -226,7 +226,7 @@ func (c *core) setState(state State) { if c.state != state { oldState := c.state c.state = state - c.currentLogger(false, nil).Trace("Consensus: State changed", "from", oldState.String(), "to", state.String()) + c.currentLogger(false, nil).Trace("[Consensus]: State changed", "from", oldState.String(), "to", state.String()) } if state == StateAcceptRequest { @@ -290,6 +290,7 @@ func (c *core) newRoundChangeTimer() { } c.currentLogger(true, nil).Trace("IBFT: start new ROUND-CHANGE timer", "timeout", timeout.Seconds()) + c.cleanLogger.Info("[Consensus]: Start new ROUND-CHANGE timer", "timeout", timeout.Seconds()) c.roundChangeTimer = time.AfterFunc(timeout, func() { c.sendEvent(timeoutEvent{}) }) diff --git a/consensus/istanbul/core/handler.go b/consensus/istanbul/core/handler.go index 5fb95cfd0..95495567f 100644 --- a/consensus/istanbul/core/handler.go +++ b/consensus/istanbul/core/handler.go @@ -228,9 +228,9 @@ func (c *core) handleTimeoutMsg() { round := c.current.Round() nextRound := new(big.Int).Add(round, common.Big1) - logger.Warn("IBFT: TIMER CHANGING ROUND", "pr", c.current.preparedRound) + logger.Warn("[Consensus]: Round reached timeout", "pr", c.current.preparedRound) c.startNewRound(nextRound) - logger.Warn("IBFT: TIMER CHANGED ROUND", "pr", c.current.preparedRound) + logger.Trace("IBFT: TIMER CHANGED ROUND", "pr", c.current.preparedRound) // Send Round Change c.broadcastRoundChange(nextRound) diff --git a/consensus/istanbul/core/prepare.go b/consensus/istanbul/core/prepare.go index 570911d41..32fbc9fbd 100644 --- a/consensus/istanbul/core/prepare.go +++ b/consensus/istanbul/core/prepare.go @@ -38,12 +38,12 @@ func (c *core) broadcastPrepare() { // Sign Message encodedPayload, err := prepare.EncodePayloadForSigning() if err != nil { - withMsg(logger, prepare).Error("IBFT: failed to encode payload of PREPARE message", "err", err) + withMsg(logger, prepare).Error("[Consensus]: Failed to encode payload of PREPARE message", "err", err) return } signature, err := c.backend.Sign(encodedPayload) if err != nil { - withMsg(logger, prepare).Error("IBFT: failed to sign PREPARE message", "err", err) + withMsg(logger, prepare).Error("[Consensus]: Failed to sign PREPARE message", "err", err) return } prepare.SetSignature(signature) @@ -51,15 +51,16 @@ func (c *core) broadcastPrepare() { // RLP-encode message payload, err := rlp.EncodeToBytes(&prepare) if err != nil { - withMsg(logger, prepare).Error("IBFT: failed to encode PREPARE message", "err", err) + withMsg(logger, prepare).Error("[Consensus]: Failed to encode PREPARE message", "err", err) return } withMsg(logger, prepare).Trace("IBFT: broadcast PREPARE message", "payload", hexutil.Encode(payload)) + c.cleanLogger.Info("[Consensus]: -> Broadcasting PREPARE message to validators") // Broadcast RLP-encoded message if err = c.backend.Broadcast(c.valSet, prepare.Code(), payload); err != nil { - withMsg(logger, prepare).Error("IBFT: failed to broadcast PREPARE message", "err", err) + withMsg(logger, prepare).Error("[Consensus]: Failed to broadcast PREPARE message", "err", err) return } } @@ -77,13 +78,13 @@ func (c *core) handlePrepare(prepare *qbfttypes.Prepare) error { // Check digest if prepare.Digest != c.current.Proposal().Hash() { - logger.Error("IBFT: invalid PREPARE message digest") + logger.Error("[Consensus]: Invalid PREPARE message digest") return errInvalidMessage } // Save PREPARE messages if err := c.current.QBFTPrepares.Add(prepare); err != nil { - logger.Error("IBFT: failed to save PREPARE message", "err", err) + logger.Error("[Consensus]: Failed to save PREPARE message", "err", err) return err } @@ -92,7 +93,8 @@ func (c *core) handlePrepare(prepare *qbfttypes.Prepare) error { // Change to "Prepared" state if we've received quorum of PREPARE messages // and we are in earlier state than "Prepared" if (c.current.QBFTPrepares.Size() >= c.QuorumSize()) && c.state.Cmp(StatePrepared) < 0 { - logger.Trace("Consensus: Received quorum of PREPARE messages") + logger.Trace("[Consensus]: Received quorum of PREPARE messages") + c.cleanLogger.Info("[Consensus]: <- Received quorum of PREPARED messages", "count", c.current.QBFTPrepares.Size(), "quorum", c.QuorumSize()) // Accumulates PREPARE messages c.current.preparedRound = c.currentView().Round @@ -110,7 +112,6 @@ func (c *core) handlePrepare(prepare *qbfttypes.Prepare) error { } c.setState(StatePrepared) - c.cleanLogger.Info("Consensus: Block proposal PREPARED") c.broadcastCommit() } else { logger.Debug("IBFT: accepted PREPARE messages") diff --git a/consensus/istanbul/core/preprepare.go b/consensus/istanbul/core/preprepare.go index 3d81b23f3..f02cbceeb 100644 --- a/consensus/istanbul/core/preprepare.go +++ b/consensus/istanbul/core/preprepare.go @@ -44,7 +44,7 @@ func (c *core) sendPreprepareMsg(request *Request) { preprepare := qbfttypes.NewPreprepare(curView.Sequence, curView.Round, request.Proposal) preprepare.SetSource(c.Address()) - c.logger.Info("Consensus: Proposing new block", "sequence", curView.Sequence.Uint64()) + c.logger.Info("[Consensus]: Proposing new block", "sequence", curView.Sequence.Uint64()) // Sign payload encodedPayload, err := preprepare.EncodePayloadForSigning() @@ -116,14 +116,14 @@ func (c *core) handlePreprepareMsg(preprepare *qbfttypes.Preprepare) error { // Validates PRE-PREPARE message comes from current proposer if !c.valSet.IsProposer(preprepare.Source()) { - logger.Warn("IBFT: ignore PRE-PREPARE message from non proposer", "proposer", c.valSet.GetProposer().Address()) + logger.Warn("[Consensus]: Ignore PRE-PREPARE message from non proposer", "proposer", c.valSet.GetProposer().Address()) return errNotFromProposer } // Validates PRE-PREPARE message justification if preprepare.Round.Uint64() > 0 { if err := isJustified(preprepare.Proposal, preprepare.JustificationRoundChanges, preprepare.JustificationPrepares, c.QuorumSize()); err != nil { - logger.Warn("IBFT: invalid PRE-PREPARE message justification", "err", err) + logger.Warn("[Consensus]: Invalid PRE-PREPARE message justification", "err", err) return errInvalidPreparedBlock } } @@ -132,7 +132,7 @@ func (c *core) handlePreprepareMsg(preprepare *qbfttypes.Preprepare) error { if duration, err := c.backend.Verify(preprepare.Proposal); err != nil { // if it's a future block, we will handle it again after the duration if err == consensus.ErrFutureBlock { - logger.Warn("IBFT: PRE-PREPARE block proposal is in the future (will be treated again later)", "duration", duration) + logger.Warn("[Consensus]: PRE-PREPARE block proposal is in the future (will be treated again later)", "duration", duration) // start a timer to re-input PRE-PREPARE message as a backlog event c.stopFuturePreprepareTimer() @@ -144,7 +144,7 @@ func (c *core) handlePreprepareMsg(preprepare *qbfttypes.Preprepare) error { }) }) } else { - logger.Warn("IBFT: invalid PRE-PREPARE block proposal", "err", err) + logger.Warn("[Consensus]: Invalid PRE-PREPARE block proposal", "err", err) } return err @@ -162,7 +162,7 @@ func (c *core) handlePreprepareMsg(preprepare *qbfttypes.Preprepare) error { c.current.SetPreprepare(preprepare) c.setState(StatePreprepared) - c.cleanLogger.Info("Consensus: Block proposal PRE-PREPARED") + c.cleanLogger.Info("[Consensus]: <- Received PRE-PREPARE message from proposer", "author", preprepare.Source()) // Broadcast prepare message to other validators c.broadcastPrepare() diff --git a/consensus/istanbul/core/roundchange.go b/consensus/istanbul/core/roundchange.go index 00507e256..8691f2b99 100644 --- a/consensus/istanbul/core/roundchange.go +++ b/consensus/istanbul/core/roundchange.go @@ -50,7 +50,7 @@ func (c *core) broadcastRoundChange(round *big.Int) { // Validates new round corresponds to current view cv := c.currentView() if cv.Round.Cmp(round) > 0 { - logger.Error("IBFT: invalid past target round", "target", round) + logger.Error("[Consensus]: Invalid past target round", "target", round) return } @@ -65,12 +65,12 @@ func (c *core) broadcastRoundChange(round *big.Int) { // Sign message encodedPayload, err := roundChange.EncodePayloadForSigning() if err != nil { - withMsg(logger, roundChange).Error("IBFT: failed to encode ROUND-CHANGE message", "err", err) + withMsg(logger, roundChange).Error("[Consensus]: Failed to encode ROUND-CHANGE message", "err", err) return } signature, err := c.backend.Sign(encodedPayload) if err != nil { - withMsg(logger, roundChange).Error("IBFT: failed to sign ROUND-CHANGE message", "err", err) + withMsg(logger, roundChange).Error("[Consensus]: Failed to sign ROUND-CHANGE message", "err", err) return } roundChange.SetSignature(signature) @@ -78,21 +78,22 @@ func (c *core) broadcastRoundChange(round *big.Int) { // Extend ROUND-CHANGE message with PREPARE justification if c.QBFTPreparedPrepares != nil { roundChange.Justification = c.QBFTPreparedPrepares - withMsg(logger, roundChange).Debug("IBFT: extended ROUND-CHANGE message with PREPARE justification", "justification", roundChange.Justification) + withMsg(logger, roundChange).Debug("[Consensus]: Extended ROUND-CHANGE message with PREPARE justification", "justification", roundChange.Justification) } // RLP-encode message data, err := rlp.EncodeToBytes(roundChange) if err != nil { - withMsg(logger, roundChange).Error("IBFT: failed to encode ROUND-CHANGE message", "err", err) + withMsg(logger, roundChange).Error("[Consensus]: Failed to encode ROUND-CHANGE message", "err", err) return } - withMsg(logger, roundChange).Trace("IBFT: broadcast ROUND-CHANGE message", "payload", hexutil.Encode(data)) + withMsg(logger, roundChange).Trace("[Consensus]: Broadcast ROUND-CHANGE message", "payload", hexutil.Encode(data)) + c.cleanLogger.Info("[Consensus]: -> Broadcasting ROUND-CHANGE message to validators") // Broadcast RLP-encoded message if err = c.backend.Broadcast(c.valSet, roundChange.Code(), data); err != nil { - withMsg(logger, roundChange).Error("IBFT: failed to broadcast ROUND-CHANGE message", "err", err) + withMsg(logger, roundChange).Error("[Consensus]: Failed to broadcast ROUND-CHANGE message", "err", err) return } } @@ -126,7 +127,7 @@ func (c *core) handleRoundChange(roundChange *qbfttypes.RoundChange) error { } err := c.roundChangeSet.Add(view.Round, roundChange, pr, pb, prepareMessages, c.QuorumSize()) if err != nil { - logger.Warn("IBFT: failed to add ROUND-CHANGE message", "err", err) + logger.Warn("[Consensus]: Failed to add ROUND-CHANGE message", "err", err) return err } } @@ -144,12 +145,14 @@ func (c *core) handleRoundChange(roundChange *qbfttypes.RoundChange) error { // we start new round and broadcast ROUND-CHANGE message newRound := c.roundChangeSet.getMinRoundChange(currentRound) - logger.Trace("Consensus: Received F+1 ROUND-CHANGE messages", "F", c.valSet.F()) + logger.Trace("[Consensus]: Received F+1 ROUND-CHANGE messages", "F", c.valSet.F()) + c.cleanLogger.Info("[Consensus]: <- Received F+1 ROUND-CHANGE messages", "F", c.valSet.F()) c.startNewRound(newRound) c.broadcastRoundChange(newRound) } else if currentRoundMessages >= c.QuorumSize() && c.IsProposer() && c.current.preprepareSent.Cmp(currentRound) < 0 { - logger.Trace("Consensus: Received quorum of ROUND-CHANGE messages") + logger.Trace("[Consensus]: Received quorum of ROUND-CHANGE messages") + c.cleanLogger.Info("[Consensus]: <- Received quorum of ROUND-CHANGE messages", "count", currentRoundMessages, "quorum", c.QuorumSize()) // We received quorum of ROUND-CHANGE for current round and we are proposer @@ -190,7 +193,11 @@ func (c *core) handleRoundChange(roundChange *qbfttypes.RoundChange) error { } c.sendPreprepareMsg(r) } else { - logger.Debug("IBFT: accepted ROUND-CHANGE messages") + logger.Trace("IBFT: accepted ROUND-CHANGE messages") + } + + if currentRoundMessages >= c.QuorumSize() { + c.cleanLogger.Info("[Consensus]: <- Received quorum of ROUND-CHANGE messages", "count", currentRoundMessages, "quorum", c.QuorumSize()) } return nil } diff --git a/consensus/istanbul/types/roundchange.go b/consensus/istanbul/types/roundchange.go index a442a14c8..529795379 100644 --- a/consensus/istanbul/types/roundchange.go +++ b/consensus/istanbul/types/roundchange.go @@ -70,50 +70,50 @@ func (p *SignedRoundChangePayload) EncodeRLP(w io.Writer) error { func (p *SignedRoundChangePayload) DecodeRLP(stream *rlp.Stream) error { // Signed Payload if _, err := stream.List(); err != nil { - log.Error("IBFT: Error List() Signed Payload", "err", err) + log.Trace("[Consensus]: Error List() Signed Payload", "err", err) return err } // Payload encodedPayload, err := stream.Raw() if err != nil { - log.Error("IBFT: Error Raw()", "err", err) + log.Error("[Consensus]: Error Raw()", "err", err) return err } payloadStream := rlp.NewStream(bytes.NewReader(encodedPayload), 0) if _, err = payloadStream.List(); err != nil { - log.Error("IBFT: Error List() Payload", "err", err) + log.Error("[Consensus]: Error List() Payload", "err", err) return err } if err = payloadStream.Decode(&p.Sequence); err != nil { - log.Error("IBFT: Error Decode(&m.Sequence)", "err", err) + log.Error("[Consensus]: Error Decode(&m.Sequence)", "err", err) return err } if err = payloadStream.Decode(&p.Round); err != nil { - log.Error("IBFT: Error Decode(&m.Round)", "err", err) + log.Error("[Consensus]: Error Decode(&m.Round)", "err", err) return err } // Prepared var size uint64 if size, err = payloadStream.List(); err != nil { - log.Error("IBFT: Error List() Prepared", "err", err) + log.Error("[Consensus]: Error List() Prepared", "err", err) return err } if size > 0 { if err = payloadStream.Decode(&p.PreparedRound); err != nil { - log.Error("IBFT: Error Decode(&m.PreparedRound)", "err", err) + log.Error("[Consensus]: Error Decode(&m.PreparedRound)", "err", err) return err } if err = payloadStream.Decode(&p.PreparedDigest); err != nil { - log.Error("IBFT: Error Decode(&p.PreparedDigest)", "err", err) + log.Error("[Consensus]: Error Decode(&p.PreparedDigest)", "err", err) return err } if err = payloadStream.Decode(&p.HasBadProposal); err != nil { - log.Error("IBFT: Error Decode(&p.HasBadProposal)", "err", err) + log.Error("[Consensus]: Error Decode(&p.HasBadProposal)", "err", err) return err } } @@ -137,7 +137,7 @@ func (p *SignedRoundChangePayload) DecodeRLP(stream *rlp.Stream) error { p.code = RoundChangeCode - log.Trace("IBFT: Correctly decoded SignedRoundChangePayload", "p", p) + log.Trace("[Consensus]: Correctly decoded SignedRoundChangePayload", "p", p) return nil } @@ -197,50 +197,50 @@ func (m *RoundChange) DecodeRLP(stream *rlp.Stream) error { // Signed Payload if _, err = stream.List(); err != nil { - log.Error("IBFT: Error List() Signed Payload", "err", err) + log.Trace("[Consensus]: Error List() Signed Payload", "err", err) return err } // Payload encodedPayload, err := stream.Raw() if err != nil { - log.Error("IBFT: Error Raw()", "err", err) + log.Error("[Consensus]: Error Raw()", "err", err) return err } payloadStream := rlp.NewStream(bytes.NewReader(encodedPayload), 0) if _, err = payloadStream.List(); err != nil { - log.Error("IBFT: Error List() Payload", "err", err) + log.Error("[Consensus]: Error List() Payload", "err", err) return err } if err = payloadStream.Decode(&m.Sequence); err != nil { - log.Error("IBFT: Error Decode(&m.Sequence)", "err", err) + log.Error("[Consensus]: Error Decode(&m.Sequence)", "err", err) return err } if err = payloadStream.Decode(&m.Round); err != nil { - log.Error("IBFT: Error Decode(&m.Round)", "err", err) + log.Error("[Consensus]: Error Decode(&m.Round)", "err", err) return err } // Prepared var size uint64 if size, err = payloadStream.List(); err != nil { - log.Error("IBFT: Error List() Prepared", "err", err) + log.Error("[Consensus]: Error List() Prepared", "err", err) return err } if size > 0 { if err = payloadStream.Decode(&m.PreparedRound); err != nil { - log.Error("IBFT: Error Decode(&m.PreparedRound)", "err", err) + log.Error("[Consensus]: Error Decode(&m.PreparedRound)", "err", err) return err } if err = payloadStream.Decode(&m.PreparedDigest); err != nil { - log.Error("IBFT: Error Decode(&m.PreparedDigest)", "err", err) + log.Error("[Consensus]: Error Decode(&m.PreparedDigest)", "err", err) return err } if err = payloadStream.Decode(&m.HasBadProposal); err != nil { - log.Error("IBFT: Error Decode(&m.HasBadProposal)", "err", err) + log.Error("[Consensus]: Error Decode(&m.HasBadProposal)", "err", err) return err } } @@ -263,37 +263,37 @@ func (m *RoundChange) DecodeRLP(stream *rlp.Stream) error { } if _, size, err = stream.Kind(); err != nil { - log.Error("IBFT: Error Kind()", "err", err) + log.Error("[Consensus]: Error Kind()", "err", err) return err } if size == 0 { if _, err = stream.Raw(); err != nil { - log.Error("IBFT: Error Raw()", "err", err) + log.Error("[Consensus]: Error Raw()", "err", err) return err } } else { if err = stream.Decode(&m.PreparedBlock); err != nil { - log.Error("IBFT: Error Decode(&m.PreparedDigest)", "err", err) + log.Error("[Consensus]: Error Decode(&m.PreparedDigest)", "err", err) return err } if m.PreparedBlock.Hash() != m.PreparedDigest { - log.Error("IBFT: Error m.PreparedDigest.Hash() != digest") + log.Error("[Consensus]: Error m.PreparedDigest.Hash() != digest") return istanbulcommon.ErrFailedDecodePreprepare } } if _, size, err = stream.Kind(); err != nil { - log.Error("IBFT: Error Kind()", "err", err) + log.Error("[Consensus]: Error Kind()", "err", err) return err } if size == 0 { if _, err = stream.Raw(); err != nil { - log.Error("IBFT: Error Raw()", "err", err) + log.Error("[Consensus]: Error Raw()", "err", err) return err } } else { if err = stream.Decode(&m.Justification); err != nil { - log.Error("IBFT: Error Decode(&m.Justification)", "err", err) + log.Error("[Consensus]: Error Decode(&m.Justification)", "err", err) return err } }