core: abundant QBFT logging (#4381)

* core: abundant QBFT logging (#4380)

Abundant QBFT debug logging as an attempt to diagnose failing attestations.

category: misc
ticket: none

* Remove empty file

Author: KaloyanTanev

core/consensus/qbft/qbft.go

@@ -115,6 +115,17 @@ func newDefinition(nodes int, subs func() []subscriber, roundTimer timer.RoundTi
 			)
 		},
 
+		LogDebug: func(ctx context.Context, _ core.Duty, _ int64, msg qbft.Msg[core.Duty, [32]byte], logMsg string) {
+			if msg != nil {
+				log.Debug(ctx, logMsg,
+					z.Any("type", msg.Type()),
+					z.I64("peer", msg.Source()),
+				)
+			} else {
+				log.Debug(ctx, logMsg)
+			}
+		},
+
 		// Nodes is the number of nodes.
 		Nodes: nodes,
 
@@ -480,6 +491,12 @@ func (c *Consensus) runInstance(parent context.Context, duty core.Duty) (err err
 		Receive:   t.RecvBuffer(),
 	}
 
+	log.Debug(ctx, "QBFT run",
+		z.Any("peer", p2p.PeerName(c.p2pNode.ID())),
+		z.Any("peers", c.peerLabels),
+		z.Any("timer", string(roundTimer.Type())),
+	)
+
 	// Run the algo, blocking until the context is cancelled.
 	err = qbft.Run(ctx, def, qt, duty, peerIdx, inst.HashCh)
 	if err != nil && !isContextErr(err) {

core/consensus/qbft/strategysim_internal_test.go

@@ -497,6 +497,7 @@ func newSimDefinition(nodes int, roundTimer timer.RoundTimer,
 		},
 		NewTimer:  roundTimer.Timer,
 		LogUnjust: func(context.Context, core.Duty, int64, qbft.Msg[core.Duty, [32]byte]) {},
+		LogDebug:  func(context.Context, core.Duty, int64, qbft.Msg[core.Duty, [32]byte], string) {},
 		LogRoundChange: func(ctx context.Context, duty core.Duty, process,
 			round, newRound int64, uponRule qbft.UponRule, msgs []qbft.Msg[core.Duty, [32]byte],
 		) {

core/qbft/qbft.go

@@ -43,6 +43,8 @@ type Definition[I any, V comparable] struct {
 	LogRoundChange func(ctx context.Context, instance I, process, round, newRound int64, uponRule UponRule, msgs []Msg[I, V])
 	// LogUnjust allows debug logging of unjust messages.
 	LogUnjust func(ctx context.Context, instance I, process int64, msg Msg[I, V])
+	// LogDebug allows arbitrary debug logging.
+	LogDebug func(ctx context.Context, instance I, process int64, msg Msg[I, V], logMsg string)
 
 	// Nodes is the total number of nodes/processes participating in consensus.
 	Nodes int
@@ -265,52 +267,71 @@ func Run[I any, V comparable](ctx context.Context, d Definition[I, V], t Transpo
 	// === Algorithm ===
 
 	{ // Algorithm 1:11
+		d.LogDebug(ctx, instance, process, nil, "QBFT check if leader")
 		if d.IsLeader(instance, round, process) { // Note round==1 at this point.
+			d.LogDebug(ctx, instance, process, nil, "QBFT leader, broadcast own pre-prepare")
 			err := broadcastOwnPrePrepare([]Msg[I, V]{}) // Empty justification since round==1
+			d.LogDebug(ctx, instance, process, nil, "QBFT leader, broadcast own pre-prepare finished")
 			if err != nil {
 				return err
 			}
 		}
 
+		d.LogDebug(ctx, instance, process, nil, "QBFT new timer")
 		timerChan, stopTimer = d.NewTimer(round)
 	}
 
+	d.LogDebug(ctx, instance, process, nil, "QBFT start handling events")
 	// Handle events until cancelled.
 	for {
 		var err error
 
 		select {
 		case inputValue = <-inputValueCh:
+			d.LogDebug(ctx, instance, process, nil, "QBFT new inputValue - step 1 received")
+
 			if isZeroVal(inputValue) {
 				return errors.New("zero input value not supported")
 			}
 
 			if ppjCache != nil {
 				// Broadcast the pre-prepare now that we have a input value using the cached justification.
+				d.LogDebug(ctx, instance, process, nil, "QBFT new inputValue - step 2 broadcast")
 				err = broadcastMsg(MsgPrePrepare, inputValue, ppjCache)
+				d.LogDebug(ctx, instance, process, nil, "QBFT new inputValue - step 3 broadcast finished")
 			}
 
 			inputValueCh = nil // Don't read from this channel again.
+			d.LogDebug(ctx, instance, process, nil, "QBFT new inputValue - step 2-4 finished")
 
 		case msg := <-t.Receive:
+			d.LogDebug(ctx, instance, process, msg, "new QBFT message - received")
 			// Just send Qcommit if consensus already decided
 			if len(qCommit) > 0 {
+				d.LogDebug(ctx, instance, process, msg, "new QBFT message - qCommits greater than 0")
 				if msg.Source() != process && msg.Type() == MsgRoundChange { // Algorithm 3:17
+					d.LogDebug(ctx, instance, process, msg, "new QBFT message - consensus already decided, broadcast")
 					err = broadcastMsg(MsgDecided, qCommit[0].Value(), qCommit)
+					d.LogDebug(ctx, instance, process, msg, "new QBFT message - consensus already decided, broadcast finished")
 				}
 
 				break
 			}
 
 			if !isJustified(d, instance, msg) { // Drop unjust messages
+				d.LogDebug(ctx, instance, process, msg, "new QBFT message - unjustified, dropping")
 				d.LogUnjust(ctx, instance, process, msg)
 				break
 			}
 
+			d.LogDebug(ctx, instance, process, msg, "new QBFT message - buffering")
 			bufferMsg(msg)
+			d.LogDebug(ctx, instance, process, msg, "new QBFT message - buffered")
 
+			d.LogDebug(ctx, instance, process, msg, "new QBFT message - classifying")
 			rule, justification := classify(d, instance, round, process, buffer, msg)
 			if rule == UponNothing || isDuplicatedRule(rule, msg.Round()) {
+				d.LogDebug(ctx, instance, process, msg, "new QBFT message - classified as duplicate")
 				// Do nothing more if no rule or duplicate rule was triggered
 				break
 			}
@@ -319,72 +340,98 @@ func Run[I any, V comparable](ctx context.Context, d Definition[I, V], t Transpo
 
 			switch rule {
 			case UponJustifiedPrePrepare: // Algorithm 2:1
+				d.LogDebug(ctx, instance, process, msg, "UponJustifiedPrePrepare QBFT step 1 - starting procedure")
 				// Applicable to current or future rounds (since justified)
 				changeRound(msg.Round(), rule)
 
+				d.LogDebug(ctx, instance, process, msg, "UponJustifiedPrePrepare QBFT step 2 - stop timer")
 				stopTimer()
 				timerChan, stopTimer = d.NewTimer(round)
 
+				d.LogDebug(ctx, instance, process, msg, "UponJustifiedPrePrepare QBFT step 3 - broadcast")
 				err = broadcastMsg(MsgPrepare, msg.Value(), nil)
+				d.LogDebug(ctx, instance, process, msg, "UponJustifiedPrePrepare QBFT step 3 - broadcast finished")
 
 			case UponQuorumPrepares: // Algorithm 2:4
+				d.LogDebug(ctx, instance, process, msg, "UponQuorumPrepares QBFT step 1 - starting procedure")
 				// Only applicable to current round
 				preparedRound = round /* == msg.Round*/
 				preparedValue = msg.Value()
 				preparedJustification = justification
 
+				d.LogDebug(ctx, instance, process, msg, "UponQuorumPrepares QBFT step 2 - broadcast")
 				err = broadcastMsg(MsgCommit, preparedValue, nil)
+				d.LogDebug(ctx, instance, process, msg, "UponQuorumPrepares QBFT step 3 - broadcast finished")
 
 			case UponQuorumCommits, UponJustifiedDecided: // Algorithm 2:8
+				d.LogDebug(ctx, instance, process, msg, "UponQuorumCommits, UponJustifiedDecided QBFT step 1 - starting procedure")
 				// Applicable to any round (since can be justified)
 				changeRound(msg.Round(), rule)
 
 				qCommit = justification
 
+				d.LogDebug(ctx, instance, process, msg, "UponQuorumCommits, UponJustifiedDecided QBFT step 2 - stop timer")
 				stopTimer()
 
 				timerChan = nil
 
+				d.LogDebug(ctx, instance, process, msg, "UponQuorumCommits, UponJustifiedDecided QBFT step 3 - decide")
 				d.Decide(ctx, instance, msg.Value(), justification)
+				d.LogDebug(ctx, instance, process, msg, "UponQuorumCommits, UponJustifiedDecided QBFT step 4 - decided")
 
 			case UponFPlus1RoundChanges: // Algorithm 3:5
+				d.LogDebug(ctx, instance, process, msg, "UponFPlus1RoundChanges QBFT step 1 - starting procedure")
 				// Only applicable to future rounds
 				changeRound(nextMinRound(d, justification, round /* < msg.Round */), rule)
 
+				d.LogDebug(ctx, instance, process, msg, "UponFPlus1RoundChanges QBFT step 2 - stop timer")
 				stopTimer()
 				timerChan, stopTimer = d.NewTimer(round)
 
+				d.LogDebug(ctx, instance, process, msg, "UponFPlus1RoundChanges QBFT step 3 - broadcast round change")
 				err = broadcastRoundChange()
+				d.LogDebug(ctx, instance, process, msg, "UponFPlus1RoundChanges QBFT step 4 - broadcasted round change")
 
 			case UponQuorumRoundChanges: // Algorithm 3:11
+				d.LogDebug(ctx, instance, process, msg, "UponQuorumRoundChanges QBFT step 1 - starting procedure")
 				// Only applicable to current round (round > 1)
 				if _, pv, ok := getSingleJustifiedPrPv(d, justification); ok {
 					// Send pre-prepare using prepared value (not our own input value)
+					d.LogDebug(ctx, instance, process, msg, "UponQuorumRoundChanges QBFT step 2 - broadcast pre-prepare with prepared value")
 					err = broadcastMsg(MsgPrePrepare, pv, justification)
 				} else {
 					// Send pre-prepare using our own input value
+					d.LogDebug(ctx, instance, process, msg, "UponQuorumRoundChanges QBFT step 2 - broadcast pre-prepare with own input value")
 					err = broadcastOwnPrePrepare(justification)
 				}
+				d.LogDebug(ctx, instance, process, msg, "UponQuorumRoundChanges QBFT step 3 - broadcasted pre-prepare")
 			case UponUnjustQuorumRoundChanges:
+				d.LogDebug(ctx, instance, process, msg, "UponUnjustQuorumRoundChanges QBFT step 1 - starting procedure")
 				// Ignore bug or byzantine
 
 			default:
 				panic("bug: invalid rule")
 			}
 
 		case <-timerChan: // Algorithm 3:1
+			d.LogDebug(ctx, instance, process, nil, "RoundTimeout QBFT - step 1 starting procedure")
 			changeRound(round+1, UponRoundTimeout)
 
+			d.LogDebug(ctx, instance, process, nil, "RoundTimeout QBFT - step 2 stop timer")
 			stopTimer()
 			timerChan, stopTimer = d.NewTimer(round)
 
+			d.LogDebug(ctx, instance, process, nil, "RoundTimeout QBFT - step 3 broadcast round change")
 			err = broadcastRoundChange()
+			d.LogDebug(ctx, instance, process, nil, "RoundTimeout QBFT - step 4 broadcast finished")
 
 		case <-ctx.Done(): // Cancelled
+			d.LogDebug(ctx, instance, process, nil, "QBFT event handling context done")
 			return ctx.Err()
 		}
 
 		if err != nil { // Errors are considered fatal.
+			d.LogDebug(ctx, instance, process, nil, "QBFT fatal error")
 			return err
 		}
 	}

core/qbft/qbft_internal_test.go

@@ -332,6 +332,13 @@ func testQBFT(t *testing.T, test test) {
 			t.Logf("Unjust: %#v", msg)
 			cancel()
 		},
+		LogDebug: func(_ context.Context, instance int64, process int64, msg Msg[int64, int64], logMsg string) {
+			if test.Fuzz {
+				return // Ignore debug messages when fuzzing.
+			}
+
+			t.Logf("Debug: %s - %#v", logMsg, msg)
+		},
 		Nodes:     n,
 		FIFOLimit: fifoLimit,
 	}
@@ -747,4 +754,5 @@ var noopDef = Definition[int64, int64]{
 	LogUponRule:    func(context.Context, int64, int64, int64, Msg[int64, int64], UponRule) {},
 	LogRoundChange: func(context.Context, int64, int64, int64, int64, UponRule, []Msg[int64, int64]) {},
 	LogUnjust:      func(context.Context, int64, int64, Msg[int64, int64]) {},
+	LogDebug:       func(context.Context, int64, int64, Msg[int64, int64], string) {},
 }