Merge #144257

144257: logstore: add basic datadriven test r=tbg a=pav-kv

This PR adds a basic datadriven test to the `logstore` package. Captures setting the `HardState`, appending entries to the log with/out overlaps, log truncation, and log size stats maintenance.

Epic: CRDB-46488

Co-authored-by: Pavel Kalinnikov <[email protected]>

Author: craig[bot]

pkg/BUILD.bazel

@@ -273,6 +273,7 @@ ALL_TESTS = [
     "//pkg/kv/kvserver/loqrecovery/loqrecoverypb:loqrecoverypb_test",
     "//pkg/kv/kvserver/loqrecovery:loqrecovery_test",
     "//pkg/kv/kvserver/multiqueue:multiqueue_test",
+    "//pkg/kv/kvserver/print:print_test",
     "//pkg/kv/kvserver/protectedts/ptcache:ptcache_test",
     "//pkg/kv/kvserver/protectedts/ptreconcile:ptreconcile_test",
     "//pkg/kv/kvserver/protectedts/ptstorage:ptstorage_test",
@@ -1552,6 +1553,8 @@ GO_TARGETS = [
     "//pkg/kv/kvserver/loqrecovery:loqrecovery_test",
     "//pkg/kv/kvserver/multiqueue:multiqueue",
     "//pkg/kv/kvserver/multiqueue:multiqueue_test",
+    "//pkg/kv/kvserver/print:print",
+    "//pkg/kv/kvserver/print:print_test",
     "//pkg/kv/kvserver/protectedts/ptcache:ptcache",
     "//pkg/kv/kvserver/protectedts/ptcache:ptcache_test",
     "//pkg/kv/kvserver/protectedts/ptpb:ptpb",

pkg/cli/BUILD.bazel

@@ -135,6 +135,7 @@ go_library(
         "//pkg/kv/kvserver/liveness/livenesspb",
         "//pkg/kv/kvserver/loqrecovery",
         "//pkg/kv/kvserver/loqrecovery/loqrecoverypb",
+        "//pkg/kv/kvserver/print",
         "//pkg/kv/kvserver/rditer",
         "//pkg/kv/kvserver/stateloader",
         "//pkg/multitenant/mtinfopb",

pkg/cli/debug.go

@@ -31,9 +31,9 @@ import (
 	"github.com/cockroachdb/cockroach/pkg/cloud"
 	"github.com/cockroachdb/cockroach/pkg/gossip"
 	"github.com/cockroachdb/cockroach/pkg/keys"
-	"github.com/cockroachdb/cockroach/pkg/kv/kvserver"
 	"github.com/cockroachdb/cockroach/pkg/kv/kvserver/gc"
 	"github.com/cockroachdb/cockroach/pkg/kv/kvserver/liveness/livenesspb"
+	"github.com/cockroachdb/cockroach/pkg/kv/kvserver/print"
 	"github.com/cockroachdb/cockroach/pkg/kv/kvserver/rditer"
 	"github.com/cockroachdb/cockroach/pkg/roachpb"
 	"github.com/cockroachdb/cockroach/pkg/security/username"
@@ -312,13 +312,13 @@ func runDebugKeys(cmd *cobra.Command, args []string) error {
 			}
 			return strings.Join(pairs, ", "), nil
 		}
-		kvserver.DebugSprintMVCCKeyValueDecoders = append(kvserver.DebugSprintMVCCKeyValueDecoders, fn)
+		print.DebugSprintMVCCKeyValueDecoders = append(print.DebugSprintMVCCKeyValueDecoders, fn)
 	}
 	printer := printKey
 	rangeKeyPrinter := printRangeKey
 	if debugCtx.values {
-		printer = kvserver.PrintMVCCKeyValue
-		rangeKeyPrinter = kvserver.PrintMVCCRangeKeyValue
+		printer = print.PrintMVCCKeyValue
+		rangeKeyPrinter = print.PrintMVCCRangeKeyValue
 	}
 
 	keyTypeOptions := keyTypeParams[debugCtx.keyTypes]
@@ -509,7 +509,7 @@ func runDebugRangeData(cmd *cobra.Command, args []string) error {
 					if err != nil {
 						return err
 					}
-					kvserver.PrintEngineKeyValue(key, v)
+					print.PrintEngineKeyValue(key, v)
 					results++
 					if results == debugCtx.maxResults {
 						return iterutil.StopIteration()
@@ -522,7 +522,7 @@ func runDebugRangeData(cmd *cobra.Command, args []string) error {
 						return err
 					}
 					for _, v := range iter.EngineRangeKeys() {
-						kvserver.PrintEngineRangeKeyValue(bounds, v)
+						print.PrintEngineRangeKeyValue(bounds, v)
 						results++
 						if results == debugCtx.maxResults {
 							return iterutil.StopIteration()
@@ -553,7 +553,7 @@ func loadRangeDescriptor(
 			// We only want values, not MVCCMetadata.
 			return nil
 		}
-		if err := kvserver.IsRangeDescriptorKey(kv.Key); err != nil {
+		if err := print.IsRangeDescriptorKey(kv.Key); err != nil {
 			// Range descriptor keys are interleaved with others, so if it
 			// doesn't parse as a range descriptor just skip it.
 			return nil //nolint:returnerrcheck
@@ -609,10 +609,10 @@ func runDebugRangeDescriptors(cmd *cobra.Command, args []string) error {
 	return db.MVCCIterate(cmd.Context(), start, end, storage.MVCCKeyAndIntentsIterKind,
 		storage.IterKeyTypePointsOnly, fs.UnknownReadCategory,
 		func(kv storage.MVCCKeyValue, _ storage.MVCCRangeKeyStack) error {
-			if kvserver.IsRangeDescriptorKey(kv.Key) != nil {
+			if print.IsRangeDescriptorKey(kv.Key) != nil {
 				return nil
 			}
-			kvserver.PrintMVCCKeyValue(kv)
+			print.PrintMVCCKeyValue(kv)
 			return nil
 		})
 }
@@ -693,7 +693,7 @@ Decode and print a hexadecimal-encoded key-value pair.
 			//   is already a roachpb.Key, so make a half-assed attempt to support both.
 			if !isTS {
 				if k, ok := storage.DecodeEngineKey(bs[0]); ok {
-					kvserver.PrintEngineKeyValue(k, bs[1])
+					print.PrintEngineKeyValue(k, bs[1])
 					return nil
 				}
 				fmt.Printf("unable to decode key: %v, assuming it's a roachpb.Key with fake timestamp;\n"+
@@ -705,7 +705,7 @@ Decode and print a hexadecimal-encoded key-value pair.
 			}
 		}
 
-		kvserver.PrintMVCCKeyValue(storage.MVCCKeyValue{
+		print.PrintMVCCKeyValue(storage.MVCCKeyValue{
 			Key:   k,
 			Value: bs[1],
 		})
@@ -787,7 +787,7 @@ func runDebugRaftLog(cmd *cobra.Command, args []string) error {
 	return db.MVCCIterate(cmd.Context(), start, end, storage.MVCCKeyIterKind,
 		storage.IterKeyTypePointsOnly, fs.UnknownReadCategory,
 		func(kv storage.MVCCKeyValue, _ storage.MVCCRangeKeyStack) error {
-			kvserver.PrintMVCCKeyValue(kv)
+			print.PrintMVCCKeyValue(kv)
 			return nil
 		})
 }
@@ -1381,7 +1381,7 @@ func (m mvccValueFormatter) Format(f fmt.State, c rune) {
 		errors.FormatError(m.err, f, c)
 		return
 	}
-	fmt.Fprint(f, kvserver.SprintMVCCKeyValue(m.kv, false /* printKey */))
+	fmt.Fprint(f, print.SprintMVCCKeyValue(m.kv, false /* printKey */))
 }
 
 // lockValueFormatter is a fmt.Formatter for lock values.
@@ -1391,7 +1391,7 @@ type lockValueFormatter struct {
 
 // Format implements the fmt.Formatter interface.
 func (m lockValueFormatter) Format(f fmt.State, c rune) {
-	fmt.Fprint(f, kvserver.SprintIntent(m.value))
+	fmt.Fprint(f, print.SprintIntent(m.value))
 }
 
 // pebbleToolFS is the vfs.FS that the pebble tool should use.

pkg/kv/kvserver/BUILD.bazel

@@ -9,7 +9,6 @@ go_library(
         "addressing.go",
         "app_batch.go",
         "consistency_queue.go",
-        "debug_print.go",
         "doc.go",
         "flow_control_integration.go",
         "flow_control_raft_transport.go",
@@ -170,6 +169,7 @@ go_library(
         "//pkg/kv/kvserver/lockspanset",
         "//pkg/kv/kvserver/logstore",
         "//pkg/kv/kvserver/multiqueue",
+        "//pkg/kv/kvserver/print",
         "//pkg/kv/kvserver/raftentry",
         "//pkg/kv/kvserver/raftlog",
         "//pkg/kv/kvserver/rafttrace",
@@ -307,7 +307,6 @@ go_test(
         "client_test.go",
         "closed_timestamp_test.go",
         "consistency_queue_test.go",
-        "debug_print_test.go",
         "deleted_external_sstable_test.go",
         "errors_test.go",
         "flow_control_integration_test.go",

pkg/kv/kvserver/logstore/BUILD.bazel

@@ -51,14 +51,18 @@ go_test(
     srcs = [
         "bytes_tracker_test.go",
         "logstore_bench_test.go",
+        "logstore_test.go",
         "sideload_test.go",
         "sync_waiter_test.go",
     ],
+    data = glob(["testdata/**"]),
     embed = [":logstore"],
     deps = [
+        "//pkg/keys",
         "//pkg/kv/kvpb",
         "//pkg/kv/kvserver/kvserverbase",
         "//pkg/kv/kvserver/kvserverpb",
+        "//pkg/kv/kvserver/print",
         "//pkg/kv/kvserver/raftentry",
         "//pkg/kv/kvserver/raftlog",
         "//pkg/raft",
@@ -68,6 +72,7 @@ go_test(
         "//pkg/storage",
         "//pkg/storage/fs",
         "//pkg/testutils",
+        "//pkg/testutils/echotest",
         "//pkg/util/humanizeutil",
         "//pkg/util/leaktest",
         "//pkg/util/log",

pkg/kv/kvserver/logstore/logstore.go

@@ -84,15 +84,28 @@ type RaftState struct {
 	ByteSize  int64
 }
 
+// EntryStats contains stats about the appended log slice.
+type EntryStats struct {
+	RegularEntries    int
+	RegularBytes      int64
+	SideloadedEntries int
+	SideloadedBytes   int64
+}
+
+// Add increments the stats with the given delta.
+func (e *EntryStats) Add(delta EntryStats) {
+	e.RegularEntries += delta.RegularEntries
+	e.RegularBytes += delta.RegularBytes
+	e.SideloadedEntries += delta.SideloadedEntries
+	e.SideloadedBytes += delta.SideloadedBytes
+}
+
 // AppendStats describes a completed log storage append operation.
 type AppendStats struct {
 	Begin crtime.Mono
 	End   crtime.Mono
 
-	RegularEntries    int
-	RegularBytes      int64
-	SideloadedEntries int
-	SideloadedBytes   int64
+	EntryStats
 
 	PebbleBegin crtime.Mono
 	PebbleEnd   crtime.Mono
@@ -186,39 +199,26 @@ func (s *LogStore) storeEntriesAndCommitBatch(
 		stats.Begin = crtime.NowMono()
 		// All of the entries are appended to distinct keys, returning a new
 		// last index.
-		thinEntries, numSideloaded, sideLoadedEntriesSize, otherEntriesSize, err := MaybeSideloadEntries(ctx, m.Entries, s.Sideload)
+		thinEntries, entryStats, err := MaybeSideloadEntries(ctx, m.Entries, s.Sideload)
 		if err != nil {
 			const expl = "during sideloading"
 			return RaftState{}, errors.Wrap(err, expl)
 		}
-		state.ByteSize += sideLoadedEntriesSize
+		stats.EntryStats.Add(entryStats) // TODO(pav-kv): just return the stats.
+		state.ByteSize += entryStats.SideloadedBytes
 		if state, err = logAppend(
 			ctx, s.StateLoader.RaftLogPrefix(), batch, state, thinEntries,
 		); err != nil {
 			const expl = "during append"
 			return RaftState{}, errors.Wrap(err, expl)
 		}
-		stats.RegularEntries += len(thinEntries) - numSideloaded
-		stats.RegularBytes += otherEntriesSize
-		stats.SideloadedEntries += numSideloaded
-		stats.SideloadedBytes += sideLoadedEntriesSize
 		stats.End = crtime.NowMono()
 	}
 
-	if hs := m.HardState; !raft.IsEmptyHardState(hs) {
-		// NB: Note that without additional safeguards, it's incorrect to write
-		// the HardState before appending m.Entries. When catching up, a follower
-		// will receive Entries that are immediately Committed in the same
-		// Ready. If we persist the HardState but happen to lose the Entries,
-		// assertions can be tripped.
-		//
-		// We have both in the same batch, so there's no problem. If that ever
-		// changes, we must write and sync the Entries before the HardState.
-		if err := s.StateLoader.SetHardState(ctx, batch, hs); err != nil {
-			const expl = "during setHardState"
-			return RaftState{}, errors.Wrap(err, expl)
-		}
+	if err := storeHardState(ctx, batch, s.StateLoader, m.HardState); err != nil {
+		return RaftState{}, err
 	}
+
 	// Synchronously commit the batch with the Raft log entries and Raft hard
 	// state as we're promising not to lose this data.
 	//
@@ -376,6 +376,26 @@ var logAppendPool = sync.Pool{
 	},
 }
 
+func storeHardState(
+	ctx context.Context, w storage.Writer, sl StateLoader, hs raftpb.HardState,
+) error {
+	if raft.IsEmptyHardState(hs) {
+		return nil
+	}
+	// NB: Note that without additional safeguards, it's incorrect to write the
+	// HardState before appending m.Entries. When catching up, a follower will
+	// receive Entries that are immediately Committed in the same Ready. If we
+	// persist the HardState but happen to lose the Entries, assertions can be
+	// tripped.
+	//
+	// We have both in the same batch, so there's no problem. If that ever
+	// changes, we must write and sync the Entries before the HardState.
+	if err := sl.SetHardState(ctx, w, hs); err != nil {
+		return errors.Wrap(err, "during SetHardState")
+	}
+	return nil
+}
+
 // logAppend adds the given entries to the raft log. Takes the previous log
 // state, and returns the updated state. It's the caller's responsibility to
 // maintain exclusive access to the raft log for the duration of the method