Merge #156368

156368: kvcoord: more tracing for leaseholder backoffs r=tbg a=tbg

Informs #156284.

Epic: none

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

Author: craig[bot]

pkg/kv/kvclient/kvcoord/dist_sender.go

@@ -370,6 +370,9 @@ const (
 	// The maximum number of times a replica is retried when it repeatedly returns
 	// stale lease info.
 	sameReplicaRetryLimit = 10
+	// InLeaseTransferBackoffTraceMessage is traced when DistSender backs off as a
+	// result of a NotLeaseholderError. It is exported for testing.
+	InLeaseTransferBackoffTraceMessage = "backing off due to NotLeaseHolderErr with stale info"
 )
 
 var rangeDescriptorCacheSize = settings.RegisterIntSetting(
@@ -2899,6 +2902,7 @@ func (ds *DistSender) sendToReplicas(
 			// If we get a gRPC error against the leaseholder, we don't want to
 			// backoff and keep trying the request against the same leaseholder.
 			if lh := routing.Leaseholder(); lh != nil && lh.IsSame(curReplica) {
+				log.VEventf(ctx, 2, "RPC error and lh %s != curReplica %s; marking leaseholder as unavailable", lh, curReplica)
 				leaseholderUnavailable = true
 			}
 		} else {
@@ -3008,6 +3012,7 @@ func (ds *DistSender) sendToReplicas(
 					// error out when the transport is exhausted even if multiple replicas
 					// return NLHEs to different replicas all returning RUEs.
 					replicaUnavailableError = br.Error.GoError()
+					log.VEventf(ctx, 2, "got RUE from lh and lh equals curReplica; marking as leaseholderUnavailable")
 					leaseholderUnavailable = true
 				} else if replicaUnavailableError == nil {
 					// This is the first time we see a RUE. Record it, such that we'll
@@ -3054,6 +3059,8 @@ func (ds *DistSender) sendToReplicas(
 					// prevents accidentally returning a replica unavailable
 					// error too aggressively.
 					if updatedLeaseholder {
+						log.VEventf(ctx, 2,
+							"updated leaseholder; resetting leaseholderUnavailable and routing to leaseholder")
 						leaseholderUnavailable = false
 						routeToLeaseholder = true
 						// If we changed the leaseholder, reset the transport to try all the
@@ -3130,7 +3137,10 @@ func (ds *DistSender) sendToReplicas(
 					shouldBackoff := !updatedLeaseholder && !intentionallySentToFollower && !leaseholderUnavailable
 					if shouldBackoff {
 						ds.metrics.InLeaseTransferBackoffs.Inc(1)
-						log.VErrEventf(ctx, 2, "backing off due to NotLeaseHolderErr with stale info")
+						log.VErrEventf(ctx, 2,
+							InLeaseTransferBackoffTraceMessage+
+								" (updatedLH=%t intentionallySentToFollower=%t leaseholderUnavailable=%t)",
+							updatedLeaseholder, intentionallySentToFollower, leaseholderUnavailable)
 					} else {
 						inTransferRetry.Reset() // The following Next() call will not block.
 					}

pkg/kv/kvserver/client_replica_circuit_breaker_test.go

@@ -863,14 +863,20 @@ func TestReplicaCircuitBreaker_Partial_Retry(t *testing.T) {
 			requireRUEs := func(t *testing.T, dbs []*kv.DB) {
 				t.Helper()
 				for _, db := range dbs {
-					backoffMetric := (db.NonTransactionalSender().(*kv.CrossRangeTxnWrapperSender)).Wrapped().(*kvcoord.DistSender).Metrics().InLeaseTransferBackoffs
-					initialBackoff := backoffMetric.Count()
+					ctx, finishAndGetRec := tracing.ContextWithRecordingSpan(context.Background(), db.Tracer, "requireRUEs")
+					defer func() {
+						rec := finishAndGetRec()
+						if !t.Failed() {
+							return
+						}
+						t.Logf("failure trace:\n%s", rec)
+					}()
 					err := db.Put(ctx, key, value)
-					// Verify that we did not perform any backoff while executing this request.
-					require.EqualValues(t, 0, backoffMetric.Count()-initialBackoff)
 					require.Error(t, err)
 					require.True(t, errors.HasType(err, (*kvpb.ReplicaUnavailableError)(nil)),
 						"expected ReplicaUnavailableError, got %v", err)
+					// Verify that we did not perform any backoff while executing this request.
+					require.NotContains(t, finishAndGetRec(), kvcoord.InLeaseTransferBackoffTraceMessage)
 				}
 				t.Logf("writes failed with ReplicaUnavailableError")
 			}
@@ -921,7 +927,7 @@ func TestReplicaCircuitBreaker_Partial_Retry(t *testing.T) {
 			// and it will return RUE.
 			lease, _ := repl3.GetLease()
 			manualClock.Increment(tc.Servers[0].RaftConfig().RangeLeaseDuration.Nanoseconds())
-			t.Logf("expired n%d lease", lease.Replica.ReplicaID)
+			t.Logf("expired first lease (n%d)", lease.Replica.ReplicaID) // always n3
 
 			requireRUEs(t, dbs)
 
@@ -968,7 +974,7 @@ func TestReplicaCircuitBreaker_Partial_Retry(t *testing.T) {
 			// because the leader's circuit breaker is tripped.
 			lease, _ = repl1.GetLease()
 			manualClock.Increment(tc.Servers[0].RaftConfig().RangeLeaseDuration.Nanoseconds())
-			t.Logf("expired n%d lease", lease.Replica.ReplicaID)
+			t.Logf("expired second lease (n%d)", lease.Replica.ReplicaID)
 
 			requireRUEs(t, dbs)
 
@@ -982,7 +988,7 @@ func TestReplicaCircuitBreaker_Partial_Retry(t *testing.T) {
 				}
 				return true
 			}, 10*time.Second, 100*time.Millisecond)
-			t.Logf("no raft leader")
+			t.Logf("expired raft leader")
 
 			requireRUEs(t, dbs)