Merge #153348

153348: kvserver: improve logging in TestPromoteNonVoterInAddVoter r=tbg a=tbg

See #134383 (comment).

Touches #153084.


Epic: None

Co-authored-by: Tobias Grieger <[email protected]>

Author: craig[bot]

pkg/kv/kvserver/replicate_queue_test.go

@@ -2151,12 +2151,32 @@ func TestPromoteNonVoterInAddVoter(t *testing.T) {
 	scope := log.Scope(t)
 	defer scope.Close(t)
 
+	// Add some debugging helpful for #134383, where the zone config update that
+	// should lead to down-replication is simply "ignored" and it's unclear who
+	// is to blame.
+	// `store=2` unconditionally logs changed spanconfigs in
+	// `spanconfigstore/store.go` and `reconciler=3` logs incoming updates from
+	// the rangefeed on the zone configs table. You'll need to look at the
+	// complete logs (not just the default log) and search for "test setting ZONE
+	// survival configuration" to find the start of the interesting bit. In
+	// passing runs, this shows the AUTO SPAN RECONCILIATION job acting on a new
+	// SQL update, changing the span configs (which should register on all nodes),
+	// and subsequent replication changes. In failing runs, it will be interesting
+	// which prefix of events remains.
+	{
+		old := log.GetVModule()
+		changed := "store=2,reconciler=3"
+		if old != "" {
+			changed = old + "," + changed
+		}
+		require.NoError(t, log.SetVModule(changed))
+		defer func() { _ = log.SetVModule(old) }()
+	}
+
 	// This test is slow under stress/race and can time out when upreplicating /
 	// rebalancing to ensure all stores have the same range count initially, due
 	// to slow heartbeats.
-	skip.UnderStress(t)
-	skip.UnderDeadlock(t)
-	skip.UnderRace(t)
+	skip.UnderDuress(t)
 
 	defer testutils.StartExecTrace(t, scope.GetDirectory()).Finish(t)
 

pkg/spanconfig/spanconfigreconciler/reconciler.go

@@ -7,6 +7,7 @@ package spanconfigreconciler
 
 import (
 	"context"
+	"runtime/trace"
 	"time"
 
 	"github.com/cockroachdb/cockroach/pkg/keys"
@@ -139,6 +140,7 @@ func (r *Reconciler) Reconcile(
 	session sqlliveness.Session,
 	onCheckpoint func() error,
 ) error {
+	defer trace.StartRegion(ctx, "spanconfig.Reconciler.Reconcile").End()
 	// TODO(irfansharif): Avoid the full reconciliation pass if the startTS
 	// provided is visible to the rangefeed. Right now we're doing a full
 	// reconciliation pass every time the reconciliation job kicks us off.
@@ -185,6 +187,9 @@ func (r *Reconciler) Reconcile(
 		r.mu.lastCheckpoint = reconciledUpUntil
 		r.mu.Unlock()
 
+		if log.V(3) {
+			log.Dev.Infof(ctx, "reconciled up until %s", reconciledUpUntil)
+		}
 		return onCheckpoint()
 	})
 }
@@ -502,6 +507,9 @@ func (r *incrementalReconciler) reconcile(
 			if len(sqlUpdates) == 0 {
 				return callback(checkpoint) // nothing to do; propagate the checkpoint
 			}
+			if log.V(3) {
+				log.Dev.Infof(ctx, "processing %d SQL updates", len(sqlUpdates))
+			}
 
 			// Process the SQLUpdates and identify all descriptor IDs that require
 			// translation. If the SQLUpdates includes ProtectedTimestampUpdates then