Skip to content

Commit

Permalink
ibft: more log messages
Browse files Browse the repository at this point in the history
  • Loading branch information
@andrepatta
andrepatta committed Nov 7, 2024
1 parent 41237d2 commit 64fec90
Show file tree
Hide file tree
Showing 7 changed files with 73 additions and 63 deletions.
15 changes: 8 additions & 7 deletions consensus/istanbul/core/commit.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
}

Expand All @@ -52,29 +52,30 @@ 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)

// 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
}
}
Expand Down Expand Up @@ -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")
Expand Down Expand Up @@ -139,5 +141,4 @@ func (c *core) commitQBFT() {
return
}
}
c.cleanLogger.Info("Consensus: Block proposal COMMITTED")
}
7 changes: 4 additions & 3 deletions consensus/istanbul/core/core.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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")
Expand Down Expand Up @@ -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())
Expand Down Expand Up @@ -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 {
Expand Down Expand Up @@ -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{})
})
Expand Down
4 changes: 2 additions & 2 deletions consensus/istanbul/core/handler.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down
17 changes: 9 additions & 8 deletions consensus/istanbul/core/prepare.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -38,28 +38,29 @@ 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)

// 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
}
}
Expand All @@ -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
}

Expand All @@ -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
Expand All @@ -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")
Expand Down
12 changes: 6 additions & 6 deletions consensus/istanbul/core/preprepare.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Expand Down Expand Up @@ -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
}
}
Expand All @@ -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()
Expand All @@ -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
Expand All @@ -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()
Expand Down
29 changes: 18 additions & 11 deletions consensus/istanbul/core/roundchange.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
}

Expand All @@ -65,34 +65,35 @@ 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)

// 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
}
}
Expand Down Expand Up @@ -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
}
}
Expand All @@ -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

Expand Down Expand Up @@ -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
}
Expand Down
Loading

0 comments on commit 64fec90

Please sign in to comment.