rac2: add test-only vmod(3) handle raft event logging

In certain occasions, such as testing, it is useful to view a summary of
inputs to every `HandleRaftEventRaftMuLocked` invocation. Previously,
the debugger would need to manually add instrumentation for this, which
could be tedious.

Add a set of `debugFmt(...)` functions which verbosely print the
`RaftEvent` and fields within `RaftEvent` separately.

Note, there is no behavior change on non-test builds. The logging cannot
be enabled.

Epic: none
Release note: None

pkg/kv/kvserver/kvflowcontrol/rac2/BUILD.bazel

@@ -3,6 +3,7 @@ load("@io_bazel_rules_go//go:def.bzl", "go_library", "go_test")
 go_library(
     name = "rac2",
     srcs = [
+        "debug_util.go",
         "log_tracker.go",
         "metrics.go",
         "priority.go",

pkg/kv/kvserver/kvflowcontrol/rac2/debug_util.go

@@ -0,0 +1,93 @@
+// Copyright 2024 The Cockroach Authors.
+//
+// Use of this software is governed by the CockroachDB Software License
+// included in the /LICENSE file.
+
+package rac2
+
+import (
+	"github.com/cockroachdb/cockroach/pkg/raft/raftpb"
+	"github.com/cockroachdb/cockroach/pkg/roachpb"
+	"github.com/cockroachdb/redact"
+)
+
+// NOTE: These functions are currently only used for debugging and testing
+// RaftEvent. They are verbose and not optimized for performance, so should not
+// be used unless behind a vmodule filter, or in testing, or on a terminating
+// condition.
+//
+// An example output from `HandleRaftEventRaftMuLocked` of the RaftEvent:
+//
+// TODO(kvoli): Consider moving relevant functions closer to raft, for shared
+// use.
+
+func debugFmtRaftEvent(re RaftEvent) redact.StringBuilder {
+	var buf redact.StringBuilder
+	buf.Printf("mode=%v term=%d snap=%v", re.MsgAppMode, re.Term, re.Snap)
+	buf.Printf("\n[")
+	buf.Printf("\n  replicas_state_info(%d)=", len(re.ReplicasStateInfo))
+	debugFmtReplicaStateInfos(&buf, re.ReplicasStateInfo)
+	buf.Printf("\n  entries(%d)=", len(re.Entries))
+	debugFmtEntries(&buf, re.Entries)
+	buf.Printf("\n  msg_apps=")
+	debugFmtMsgApps(&buf, re.MsgApps)
+	buf.Printf("\n]")
+	return buf
+}
+
+func debugFmtEntry(buf *redact.StringBuilder, entry raftpb.Entry) {
+	buf.Printf("(%v/%v %v)", entry.Term, entry.Index, entry.Type)
+}
+
+func debugFmtEntries(buf *redact.StringBuilder, entries []raftpb.Entry) {
+	for _, entry := range entries {
+		debugFmtEntry(buf, entry)
+	}
+}
+
+func debugFmtMsg(buf *redact.StringBuilder, msg raftpb.Message) {
+	buf.Printf(
+		"%v->%v %v/%v log_term=%v match=%v commit=%v lead=%v vote=%v "+
+			"reject=%v reject_hint=%v",
+		msg.From, msg.To, msg.Term, msg.Index, msg.LogTerm,
+		msg.Match, msg.Commit, msg.Lead, msg.Vote,
+		msg.Reject, msg.RejectHint)
+	buf.Printf("\n        entries=")
+	debugFmtEntries(buf, msg.Entries)
+	if len(msg.Responses) > 0 {
+		buf.Printf("\n        responses=")
+		debugFmtMsgs(buf, msg.Responses)
+	}
+}
+
+func debugFmtMsgs(buf *redact.StringBuilder, msgs []raftpb.Message) {
+	for _, msg := range msgs {
+		buf.Printf("\n      ")
+		debugFmtMsg(buf, msg)
+	}
+}
+
+func debugFmtMsgApps(buf *redact.StringBuilder, msgApps map[roachpb.ReplicaID][]raftpb.Message) {
+	for replicaID, msgs := range msgApps {
+		if len(msgs) == 0 {
+			continue
+		}
+		buf.Printf("\n    /%v:", replicaID)
+		debugFmtMsgs(buf, msgs)
+	}
+}
+
+func debugFmtReplicaStateInfos(
+	buf *redact.StringBuilder, replicaStateInfos map[roachpb.ReplicaID]ReplicaStateInfo,
+) {
+	buf.Printf("[")
+	i := 0
+	for replicaID, rsi := range replicaStateInfos {
+		if i > 0 {
+			buf.Printf(" ")
+		}
+		buf.Printf("%v=%v", replicaID, rsi)
+		i++
+	}
+	buf.Printf("]")
+}

pkg/kv/kvserver/kvflowcontrol/rac2/range_controller.go

@@ -194,6 +194,17 @@ type ReplicaStateInfo struct {
 	InflightBytes uint64
 }
 
+func (rsi ReplicaStateInfo) String() string {
+	return redact.StringWithoutMarkers(rsi)
+}
+
+var _ redact.SafeFormatter = ReplicaStateInfo{}
+
+// SafeFormat implements the redact.SafeFormatter interface.
+func (rsi ReplicaStateInfo) SafeFormat(w redact.SafePrinter, _ rune) {
+	w.Printf("state=%v match=%v next=%v", rsi.State, rsi.Match, rsi.Next)
+}
+
 // sendQueueStatRefreshInterval is the interval at which the send queue stats
 // are refreshed by the range controller, as part of
 // HandleRaftEventRaftMuLocked. One should expect the stats to be at most this
@@ -1067,6 +1078,12 @@ func constructRaftEventForReplica(
 //
 // Requires replica.raftMu to be held.
 func (rc *rangeController) HandleRaftEventRaftMuLocked(ctx context.Context, e RaftEvent) error {
+	if buildutil.CrdbTestBuild {
+		// NB: This logging is incredibly verbose, and should not be enabled on
+		// real clusters. It is only enabled in test builds as such.
+		log.VInfof(ctx, 3, "r%v/%v handle raft event: %v",
+			rc.opts.RangeID, rc.opts.LocalReplicaID, debugFmtRaftEvent(e))
+	}
 	// NB: e.Term can be empty when the RaftEvent was not constructed using a
 	// MsgStorageAppend. Hence, the assertion is gated on the conditions that
 	// ensure e.Term was initialized.