Merge #31876

31876: storage: log(spy) incoming raft messages r=bdarnell a=tschottdorf

Being able to look at the outgoing Raft messages has been quite helpful
in lots of investigations. Unfortunately there wasn't ever a
corresponding log for the incoming messages. In principle these can be
observed by logspying into the origin nodes, but that's far from
ergonomic.

Release note: None

Co-authored-by: Tobias Schottdorf <tobias.schottdorf@gmail.com>

pkg/storage/raft.go

@@ -105,34 +105,40 @@ func (r *raftLogger) Panicf(format string, v ...interface{}) {
 	panic(fmt.Sprintf(format, v...))
 }
 
+func verboseRaftLoggingEnabled() bool {
+	return log.V(5)
+}
+
 func logRaftReady(ctx context.Context, ready raft.Ready) {
-	if log.V(5) {
-		var buf bytes.Buffer
-		if ready.SoftState != nil {
-			fmt.Fprintf(&buf, "  SoftState updated: %+v\n", *ready.SoftState)
-		}
-		if !raft.IsEmptyHardState(ready.HardState) {
-			fmt.Fprintf(&buf, "  HardState updated: %+v\n", ready.HardState)
-		}
-		for i, e := range ready.Entries {
-			fmt.Fprintf(&buf, "  New Entry[%d]: %.200s\n",
-				i, raft.DescribeEntry(e, raftEntryFormatter))
-		}
-		for i, e := range ready.CommittedEntries {
-			fmt.Fprintf(&buf, "  Committed Entry[%d]: %.200s\n",
-				i, raft.DescribeEntry(e, raftEntryFormatter))
-		}
-		if !raft.IsEmptySnap(ready.Snapshot) {
-			snap := ready.Snapshot
-			snap.Data = nil
-			fmt.Fprintf(&buf, "  Snapshot updated: %v\n", snap)
-		}
-		for i, m := range ready.Messages {
-			fmt.Fprintf(&buf, "  Outgoing Message[%d]: %.200s\n",
-				i, raftDescribeMessage(m, raftEntryFormatter))
-		}
-		log.Infof(ctx, "raft ready (must-sync=%t)\n%s", ready.MustSync, buf.String())
+	if !verboseRaftLoggingEnabled() {
+		return
+	}
+
+	var buf bytes.Buffer
+	if ready.SoftState != nil {
+		fmt.Fprintf(&buf, "  SoftState updated: %+v\n", *ready.SoftState)
+	}
+	if !raft.IsEmptyHardState(ready.HardState) {
+		fmt.Fprintf(&buf, "  HardState updated: %+v\n", ready.HardState)
+	}
+	for i, e := range ready.Entries {
+		fmt.Fprintf(&buf, "  New Entry[%d]: %.200s\n",
+			i, raft.DescribeEntry(e, raftEntryFormatter))
+	}
+	for i, e := range ready.CommittedEntries {
+		fmt.Fprintf(&buf, "  Committed Entry[%d]: %.200s\n",
+			i, raft.DescribeEntry(e, raftEntryFormatter))
+	}
+	if !raft.IsEmptySnap(ready.Snapshot) {
+		snap := ready.Snapshot
+		snap.Data = nil
+		fmt.Fprintf(&buf, "  Snapshot updated: %v\n", snap)
+	}
+	for i, m := range ready.Messages {
+		fmt.Fprintf(&buf, "  Outgoing Message[%d]: %.200s\n",
+			i, raftDescribeMessage(m, raftEntryFormatter))
 	}
+	log.Infof(ctx, "raft ready (must-sync=%t)\n%s", ready.MustSync, buf.String())
 }
 
 // This is a fork of raft.DescribeMessage with a tweak to avoid logging

pkg/storage/store.go

@@ -3330,6 +3330,10 @@ func (s *Store) withReplicaForRequest(
 func (s *Store) processRaftRequestWithReplica(
 	ctx context.Context, r *Replica, req *RaftMessageRequest,
 ) *roachpb.Error {
+	if verboseRaftLoggingEnabled() {
+		log.Infof(ctx, "incoming raft message:\n%s", raftDescribeMessage(req.Message, raftEntryFormatter))
+	}
+
 	if req.Message.Type == raftpb.MsgSnap {
 		log.Fatalf(ctx, "unexpected snapshot: %+v", req)
 	}