Merge #153946

153946: kvserver: move off Dev logging channel in subpackages r=tbg a=tbg

First two commits are from #153945.

----

Starting from `rg -l 'log.Dev' pkg/kv/kvserver/ | sed -E 's/[^/]+$//g' | sort | uniq -c | sort -r -n`, I went through each package and wholesale replaced `log.Dev.*` either with the KvDistribution or KvExec log channel.

As of this PR, the only `log.Dev` logging in the `kvserver` tree is in the `kvserver` package itself:

```
$ rg -l 'log.Dev' pkg/kv/kvserver/ | sed -E 's/[^/]+$//g' | sort | uniq -c | sort -r -n
  81 pkg/kv/kvserver/
```

This will be addressed separately.

Epic: none

Co-authored-by: Tobias Grieger <tobias.b.grieger@gmail.com>

Author: craig[bot]

pkg/kv/kvserver/allocator/allocatorimpl/allocator.go

@@ -986,9 +986,9 @@ func (a *Allocator) ComputeAction(
 	// to be processed with the correct priority.
 	if priority == -1 {
 		if buildutil.CrdbTestBuild {
-			log.Dev.Fatalf(ctx, "allocator returned -1 priority for range %s: %v", desc, action)
+			log.KvDistribution.Fatalf(ctx, "allocator returned -1 priority for range %s: %v", desc, action)
 		} else {
-			log.Dev.Warningf(ctx, "allocator returned -1 priority for range %s: %v", desc, action)
+			log.KvDistribution.Warningf(ctx, "allocator returned -1 priority for range %s: %v", desc, action)
 		}
 	}
 	return action, priority

pkg/kv/kvserver/allocator/allocatorimpl/allocator_test.go

@@ -2852,7 +2852,7 @@ func TestAllocatorRebalanceDifferentLocalitySizes(t *testing.T) {
 	}
 
 	for i, tc := range testCases2 {
-		log.Dev.Infof(ctx, "case #%d", i)
+		log.KvDistribution.Infof(ctx, "case #%d", i)
 		var rangeUsageInfo allocator.RangeUsageInfo
 		result, _, details, ok := a.RebalanceVoter(
 			ctx,
@@ -8764,13 +8764,13 @@ func (ts *testStore) rebalance(ots *testStore, bytes int64, qps float64, do Disk
 	// almost out of disk. (In a real allocator this is, for example, in
 	// rankedCandidateListFor{Allocation,Rebalancing}).
 	if !do.maxCapacityCheck(ots.StoreDescriptor) {
-		log.Dev.Infof(
+		log.KvDistribution.Infof(
 			context.Background(),
 			"s%d too full to accept snapshot from s%d: %v", ots.StoreID, ts.StoreID, ots.Capacity,
 		)
 		return
 	}
-	log.Dev.Infof(context.Background(), "s%d accepting snapshot from s%d", ots.StoreID, ts.StoreID)
+	log.KvDistribution.Infof(context.Background(), "s%d accepting snapshot from s%d", ots.StoreID, ts.StoreID)
 	ts.Capacity.RangeCount--
 	ts.Capacity.QueriesPerSecond -= qps
 	if ts.immediateCompaction {
@@ -8801,7 +8801,7 @@ func Example_rangeCountRebalancing() {
 			alloc.ScorerOptions(ctx),
 		)
 		if ok {
-			log.Dev.Infof(ctx, "rebalancing to %v; details: %s", target, details)
+			log.KvDistribution.Infof(ctx, "rebalancing to %v; details: %s", target, details)
 			ts.rebalance(
 				&testStores[int(target.StoreID)],
 				alloc.randGen.Int63n(1<<20),
@@ -8916,7 +8916,7 @@ func qpsBasedRebalanceFn(
 		opts,
 	)
 	if ok {
-		log.Dev.Infof(ctx, "rebalancing from %v to %v; details: %s", remove, add, details)
+		log.KvDistribution.Infof(ctx, "rebalancing from %v to %v; details: %s", remove, add, details)
 		candidate.rebalance(&testStores[int(add.StoreID)], alloc.randGen.Int63n(1<<20), jitteredQPS, opts.BaseScorerOptions.DiskCapacity)
 	}
 }

pkg/kv/kvserver/allocator/mmaprototype/allocator_state.go

@@ -353,7 +353,7 @@ func makeRebalanceReplicaChanges(
 		}
 	}
 	if remove == (StoreIDAndReplicaState{}) {
-		log.Dev.Fatalf(context.Background(), "remove target %s not in existing replicas", removeTarget)
+		log.KvDistribution.Fatalf(context.Background(), "remove target %s not in existing replicas", removeTarget)
 	}
 
 	addState := ReplicaState{
@@ -1169,7 +1169,7 @@ func (cs *clusterState) processStoreLoadMsg(ctx context.Context, storeMsg *Store
 	// corresponding delta adjustment as the reported load already contains the
 	// effect.
 	for _, change := range ss.computePendingChangesReflectedInLatestLoad(storeMsg.LoadTime) {
-		log.Dev.VInfof(ctx, 2, "s%d not-pending %v", storeMsg.StoreID, change)
+		log.KvDistribution.VInfof(ctx, 2, "s%d not-pending %v", storeMsg.StoreID, change)
 		delete(ss.adjusted.loadPendingChanges, change.ChangeID)
 	}
 
@@ -1179,7 +1179,7 @@ func (cs *clusterState) processStoreLoadMsg(ctx context.Context, storeMsg *Store
 		// replicas.
 		cs.applyChangeLoadDelta(change.ReplicaChange)
 	}
-	log.Dev.VInfof(ctx, 2, "processStoreLoadMsg for store s%v: %v",
+	log.KvDistribution.VInfof(ctx, 2, "processStoreLoadMsg for store s%v: %v",
 		storeMsg.StoreID, ss.adjusted.load)
 }
 
@@ -1279,7 +1279,7 @@ func (cs *clusterState) processStoreLeaseholderMsgInternal(
 		// rs.pendingChanges is the union of remainingChanges and enactedChanges.
 		// These changes are also in cs.pendingChanges.
 		if len(enactedChanges) > 0 {
-			log.Dev.Infof(ctx, "enactedChanges %v", enactedChanges)
+			log.KvDistribution.Infof(ctx, "enactedChanges %v", enactedChanges)
 		}
 		for _, change := range enactedChanges {
 			// Mark the change as enacted. Enacting a change does not remove the
@@ -1301,7 +1301,7 @@ func (cs *clusterState) processStoreLeaseholderMsgInternal(
 		// effect is also incorporated into the storeStates, but not in the range
 		// membership (since we undid that above).
 		if len(remainingChanges) > 0 {
-			log.Dev.Infof(ctx, "remainingChanges %v", remainingChanges)
+			log.KvDistribution.Infof(ctx, "remainingChanges %v", remainingChanges)
 			// Temporarily set the rs.pendingChanges to nil, since
 			// preCheckOnApplyReplicaChanges returns false if there are any pending
 			// changes, and these are the changes that are pending. This is hacky
@@ -1324,7 +1324,7 @@ func (cs *clusterState) processStoreLeaseholderMsgInternal(
 				// changes, so we need to drop them. This should be rare, but can happen
 				// if the leaseholder executed a change that MMA was completely unaware
 				// of.
-				log.Dev.Infof(ctx, "remainingChanges %v are no longer valid due to %v",
+				log.KvDistribution.Infof(ctx, "remainingChanges %v are no longer valid due to %v",
 					remainingChanges, reason)
 				if metrics != nil {
 					metrics.DroppedDueToStateInconsistency.Inc(1)
@@ -1556,7 +1556,7 @@ func (cs *clusterState) gcPendingChanges(now time.Time) {
 	}
 	if len(replicaChanges) > 0 {
 		if valid, reason := cs.preCheckOnUndoReplicaChanges(replicaChanges); !valid {
-			log.Dev.Infof(context.Background(), "did not undo change %v: due to %v", removeChangeIds, reason)
+			log.KvDistribution.Infof(context.Background(), "did not undo change %v: due to %v", removeChangeIds, reason)
 			return
 		}
 		for _, rmChange := range removeChangeIds {
@@ -1664,7 +1664,7 @@ func (cs *clusterState) createPendingChanges(changes ...ReplicaChange) []*pendin
 		cs.pendingChanges[cid] = pendingChange
 		storeState.adjusted.loadPendingChanges[cid] = pendingChange
 		rangeState.pendingChanges = append(rangeState.pendingChanges, pendingChange)
-		log.Dev.VInfof(context.Background(), 3, "createPendingChanges: change_id=%v, range_id=%v, change=%v", cid, change.rangeID, change)
+		log.KvDistribution.VInfof(context.Background(), 3, "createPendingChanges: change_id=%v, range_id=%v, change=%v", cid, change.rangeID, change)
 		pendingChanges = append(pendingChanges, pendingChange)
 	}
 	return pendingChanges
@@ -1691,7 +1691,7 @@ func (cs *clusterState) preCheckOnApplyReplicaChanges(
 		return false, "range does not exist in cluster state"
 	}
 	if len(curr.pendingChanges) > 0 {
-		log.Dev.VInfof(context.Background(), 2, "range %d has pending changes: %v",
+		log.KvDistribution.VInfof(context.Background(), 2, "range %d has pending changes: %v",
 			rangeID, curr.pendingChanges)
 		return false, "range has pending changes"
 	}
@@ -1792,7 +1792,7 @@ func (cs *clusterState) applyReplicaChange(change ReplicaChange, applyLoadChange
 		panic(fmt.Sprintf("range %v not found in cluster state", change.rangeID))
 	}
 
-	log.Dev.VInfof(context.Background(), 2, "applying replica change %v to range %d on store %d",
+	log.KvDistribution.VInfof(context.Background(), 2, "applying replica change %v to range %d on store %d",
 		change, change.rangeID, change.target.StoreID)
 	if change.isRemoval() {
 		delete(storeState.adjusted.replicas, change.rangeID)
@@ -1823,7 +1823,7 @@ func (cs *clusterState) applyReplicaChange(change ReplicaChange, applyLoadChange
 }
 
 func (cs *clusterState) undoReplicaChange(change ReplicaChange) {
-	log.Dev.Infof(context.Background(), "undoing replica change %v to range %d on store %d",
+	log.KvDistribution.Infof(context.Background(), "undoing replica change %v to range %d on store %d",
 		change, change.rangeID, change.target.StoreID)
 	rangeState := cs.ranges[change.rangeID]
 	storeState := cs.stores[change.target.StoreID]
@@ -1987,11 +1987,11 @@ func (cs *clusterState) canShedAndAddLoad(
 	var reason strings.Builder
 	defer func() {
 		if canAddLoad {
-			log.Dev.VInfof(ctx, 3, "can add load to n%vs%v: %v targetSLS[%v] srcSLS[%v]",
+			log.KvDistribution.VInfof(ctx, 3, "can add load to n%vs%v: %v targetSLS[%v] srcSLS[%v]",
 				targetNS.NodeID, targetSS.StoreID, canAddLoad, targetSLS, srcSLS)
 		} else {
-			log.Dev.VInfof(ctx, 2, "cannot add load to n%vs%v: due to %s", targetNS.NodeID, targetSS.StoreID, reason.String())
-			log.Dev.VInfof(ctx, 2, "[target_sls:%v,src_sls:%v]", targetSLS, srcSLS)
+			log.KvDistribution.VInfof(ctx, 2, "cannot add load to n%vs%v: due to %s", targetNS.NodeID, targetSS.StoreID, reason.String())
+			log.KvDistribution.VInfof(ctx, 2, "[target_sls:%v,src_sls:%v]", targetSLS, srcSLS)
 		}
 	}()
 	if targetSLS.highDiskSpaceUtilization {
@@ -2078,7 +2078,7 @@ func (cs *clusterState) canShedAndAddLoad(
 		}
 		// The use of 33% is arbitrary.
 		if dimFractionIncrease > overloadedDimFractionIncrease/3 {
-			log.Dev.Infof(ctx, "%v: %f > %f/3", dim, dimFractionIncrease, overloadedDimFractionIncrease)
+			log.KvDistribution.Infof(ctx, "%v: %f > %f/3", dim, dimFractionIncrease, overloadedDimFractionIncrease)
 			otherDimensionsBecameWorseInTarget = true
 			break
 		}

pkg/kv/kvserver/allocator/mmaprototype/cluster_state.go

@@ -510,10 +510,10 @@ func loadSummaryForDimension(
 	defer func() {
 		if log.V(2) {
 			if storeID == 0 {
-				log.Dev.Infof(ctx, "n%d[%v]: load=%d, mean_load=%d, fraction above=%.2f, load_summary=%v",
+				log.KvDistribution.Infof(ctx, "n%d[%v]: load=%d, mean_load=%d, fraction above=%.2f, load_summary=%v",
 					nodeID, dim, load, meanLoad, fractionAbove, summary)
 			} else {
-				log.Dev.Infof(ctx, "s%d[%v]: load=%d, mean_load=%d, fraction above=%.2f, load_summary=%v",
+				log.KvDistribution.Infof(ctx, "s%d[%v]: load=%d, mean_load=%d, fraction above=%.2f, load_summary=%v",
 					storeID, dim, load, meanLoad, fractionAbove, summary)
 			}
 		}
@@ -575,7 +575,7 @@ func loadSummaryForDimension(
 
 func highDiskSpaceUtilization(load LoadValue, capacity LoadValue) bool {
 	if capacity == UnknownCapacity {
-		log.Dev.Errorf(context.Background(), "disk capacity is unknown")
+		log.KvDistribution.Errorf(context.Background(), "disk capacity is unknown")
 		return false
 	}
 	fractionUsed := float64(load) / float64(capacity)

pkg/kv/kvserver/allocator/mmaprototype/load.go

@@ -40,7 +40,7 @@ func (t *topKReplicas) addReplica(
 	msgStoreID roachpb.StoreID,
 ) {
 	if loadValue < t.threshold {
-		log.Dev.VInfof(ctx, 3, "(r%d,s%d,lhs%d): load%v<threshold%v, skipping for dim %s",
+		log.KvDistribution.VInfof(ctx, 3, "(r%d,s%d,lhs%d): load%v<threshold%v, skipping for dim %s",
 			rangeID, replicaStoreID, msgStoreID, loadValue, t.threshold, t.dim)
 		return
 	}

pkg/kv/kvserver/allocator/mmaprototype/top_k_replicas.go

@@ -487,7 +487,7 @@ func (sp *StorePool) storeGossipUpdate(_ string, content roachpb.Value, _ int64)
 
 	if err := content.GetProto(&storeDesc); err != nil {
 		ctx := sp.AnnotateCtx(context.TODO())
-		log.Dev.Errorf(ctx, "%v", err)
+		log.KvDistribution.Errorf(ctx, "%v", err)
 		return
 	}
 
@@ -930,7 +930,7 @@ func (sp *StorePool) liveAndDeadReplicasWithLiveness(
 				liveReplicas = append(liveReplicas, repl)
 			}
 		default:
-			log.Dev.Fatalf(context.TODO(), "unknown store status %d", status)
+			log.KvDistribution.Fatalf(context.TODO(), "unknown store status %d", status)
 		}
 	}
 	return
@@ -1278,11 +1278,11 @@ func (sp *StorePool) Throttle(reason ThrottleReason, why string, storeID roachpb
 		detail.ThrottledUntil = sp.clock.Now().AddDuration(timeout)
 		if log.V(2) {
 			ctx := sp.AnnotateCtx(context.TODO())
-			log.Dev.Infof(ctx, "snapshot failed (%s), s%d will be throttled for %s until %s",
+			log.KvDistribution.Infof(ctx, "snapshot failed (%s), s%d will be throttled for %s until %s",
 				why, storeID, timeout, detail.ThrottledUntil)
 		}
 	default:
-		log.Dev.Warningf(sp.AnnotateCtx(context.TODO()), "unknown throttle reason %v", reason)
+		log.KvDistribution.Warningf(sp.AnnotateCtx(context.TODO()), "unknown throttle reason %v", reason)
 	}
 }
 

pkg/kv/kvserver/allocator/storepool/store_pool.go

@@ -108,7 +108,7 @@ func (sa SteadyStateAssertion) Assert(
 	m := h.Recorded
 	ticks := len(m)
 	if sa.Ticks > ticks {
-		log.Dev.VInfof(ctx, 2,
+		log.KvDistribution.VInfof(ctx, 2,
 			"The history to run assertions against (%d) is shorter than "+
 				"the assertion duration (%d)", ticks, sa.Ticks)
 		return true, ""
@@ -213,7 +213,7 @@ func (ba BalanceAssertion) Assert(
 	m := h.Recorded
 	ticks := len(m)
 	if ba.Ticks > ticks {
-		log.Dev.VInfof(ctx, 2,
+		log.KvDistribution.VInfof(ctx, 2,
 			"The history to run assertions against (%d) is shorter than "+
 				"the assertion duration (%d)", ticks, ba.Ticks)
 		return true, ""
@@ -235,7 +235,7 @@ func (ba BalanceAssertion) Assert(
 		max, _ := stats.Max(tickStats)
 		maxMeanRatio := max / mean
 
-		log.Dev.VInfof(ctx, 2,
+		log.KvDistribution.VInfof(ctx, 2,
 			"Balance assertion: stat=%s, max/mean=%.2f, threshold=%+v raw=%v",
 			ba.Stat, maxMeanRatio, ba.Threshold, tickStats)
 		if ba.Threshold.isViolated(maxMeanRatio) {
@@ -276,7 +276,7 @@ func (sa StoreStatAssertion) Assert(
 	m := h.Recorded
 	ticks := len(m)
 	if sa.Ticks > ticks {
-		log.Dev.VInfof(ctx, 2,
+		log.KvDistribution.VInfof(ctx, 2,
 			"The history to run assertions against (%d) is shorter than "+
 				"the assertion duration (%d)", ticks, sa.Ticks)
 		return true, ""

pkg/kv/kvserver/asim/assertion/assert.go

@@ -164,7 +164,7 @@ func (sne SetNodeLivenessEvent) String() string {
 
 func (sce SetCapacityOverrideEvent) Func() EventFunc {
 	return MutationFunc(func(ctx context.Context, s state.State) {
-		log.Dev.Infof(ctx, "setting capacity override %v", sce.CapacityOverride)
+		log.KvDistribution.Infof(ctx, "setting capacity override %v", sce.CapacityOverride)
 		s.SetCapacityOverride(sce.StoreID, sce.CapacityOverride)
 	})
 }
@@ -175,7 +175,7 @@ func (sce SetCapacityOverrideEvent) String() string {
 
 func (sne SetNodeLocalityEvent) Func() EventFunc {
 	return MutationFunc(func(ctx context.Context, s state.State) {
-		log.Dev.Infof(ctx, "setting node locality %v", sne.LocalityString)
+		log.KvDistribution.Infof(ctx, "setting node locality %v", sne.LocalityString)
 		if sne.LocalityString != "" {
 			var locality roachpb.Locality
 			if err := locality.Set(sne.LocalityString); err != nil {

pkg/kv/kvserver/asim/event/mutation_event.go

@@ -103,6 +103,6 @@ func (m *ClusterMetricsTracker) Listen(ctx context.Context, sms []StoreMetrics)
 	record = append(record, fmt.Sprintf("%d", totalBytesRebalanced))
 
 	if err := m.write(record); err != nil {
-		log.Dev.Errorf(ctx, "Error writing cluster metrics %s", err.Error())
+		log.KvDistribution.Errorf(ctx, "Error writing cluster metrics %s", err.Error())
 	}
 }