Merge #158505

158505: kvserver: finish tracing spans in tests r=tbg a=stevendanna

Failing to finish the tracing span can cause the server shutdown to hang and fills the logs with complains about the unfinsihed spans, complicating debugging.

Informs #158394

Release note: None

Co-authored-by: Steven Danna <[email protected]>

Author: craig[bot]

pkg/kv/kvserver/replica_learner_test.go

@@ -980,21 +980,22 @@ func testRaftSnapshotsToNonVoters(t *testing.T, drainReceivingNode bool) {
 		// Manually enqueue the leaseholder replica into its store's raft snapshot
 		// queue. We expect it to pick up on the fact that the non-voter on its range
 		// needs a snapshot.
-		ctx, rec := tracing.ContextWithRecordingSpan(ctx, leaseholderStore.GetStoreConfig().Tracer(), "trace-enqueue")
+		ctx, finish := tracing.ContextWithRecordingSpan(ctx, leaseholderStore.GetStoreConfig().Tracer(), "trace-enqueue")
 		pErr, err := leaseholderStore.Enqueue(
 			ctx,
 			"raftsnapshot",
 			leaseholderRepl,
 			false, /* skipShouldQueue */
 			false, /* async */
 		)
+		rec := finish()
 		if pErr != nil {
 			return pErr
 		}
 		if err != nil {
 			return err
 		}
-		matched, err := regexp.MatchString("streamed snapshot.*to.*NON_VOTER", rec().String())
+		matched, err := regexp.MatchString("streamed snapshot.*to.*NON_VOTER", rec.String())
 		if err != nil {
 			return err
 		}
@@ -1262,10 +1263,11 @@ func TestReplicateQueueSeesLearnerOrJointConfig(t *testing.T) {
 		processErr, err := store.Enqueue(
 			traceCtx, "replicate", repl, true /* skipShouldQueue */, false, /* async */
 		)
+		rec := finish()
 		require.NoError(t, err)
 		require.NoError(t, processErr)
 		action := "next replica action: remove learner"
-		require.NoError(t, testutils.MatchInOrder(finish().String(), []string{action}...))
+		require.NoError(t, testutils.MatchInOrder(rec.String(), []string{action}...))
 		require.Equal(t, int64(1), getFirstStoreMetric(t, tc.Server(0), `queue.replicate.removelearnerreplica`))
 
 		testutils.SucceedsSoon(t, func() error {
@@ -1292,10 +1294,12 @@ func TestReplicateQueueSeesLearnerOrJointConfig(t *testing.T) {
 		processErr, err := store.Enqueue(
 			traceCtx, "replicate", repl, true /* skipShouldQueue */, false, /* async */
 		)
+		rec := finish()
+
 		require.NoError(t, err)
 		require.NoError(t, processErr)
 		action := "next replica action: finalize conf change"
-		require.NoError(t, testutils.MatchInOrder(finish().String(), []string{action}...))
+		require.NoError(t, testutils.MatchInOrder(rec.String(), []string{action}...))
 
 		testutils.SucceedsSoon(t, func() error {
 			desc = tc.LookupRangeOrFatal(t, scratchStartKey)
@@ -1329,14 +1333,15 @@ func TestReplicaGCQueueSeesLearnerOrJointConfig(t *testing.T) {
 	// Run the replicaGC queue.
 	checkNoGC := func() roachpb.RangeDescriptor {
 		store, repl := getFirstStoreReplica(t, tc.Server(1), scratchStartKey)
-		traceCtx, rec := tracing.ContextWithRecordingSpan(ctx, store.GetStoreConfig().Tracer(), "trace-enqueue")
+		traceCtx, finish := tracing.ContextWithRecordingSpan(ctx, store.GetStoreConfig().Tracer(), "trace-enqueue")
 		processErr, err := store.Enqueue(
 			traceCtx, "replicaGC", repl, true /* skipShouldQueue */, false, /* async */
 		)
+		rec := finish()
 		require.NoError(t, err)
 		require.NoError(t, processErr)
 		const msg = `not gc'able, replica is still in range descriptor: (n2,s2):`
-		require.Contains(t, rec().String(), msg)
+		require.Contains(t, rec.String(), msg)
 		return tc.LookupRangeOrFatal(t, scratchStartKey)
 	}
 	desc := checkNoGC()
@@ -1392,18 +1397,19 @@ func TestRaftSnapshotQueueSeesLearner(t *testing.T) {
 	// raft to figure out that the replica needs a snapshot.
 	store, repl := getFirstStoreReplica(t, tc.Server(0), scratchStartKey)
 	testutils.SucceedsSoon(t, func() error {
-		traceCtx, rec := tracing.ContextWithRecordingSpan(ctx, store.GetStoreConfig().Tracer(), "trace-enqueue")
+		traceCtx, finish := tracing.ContextWithRecordingSpan(ctx, store.GetStoreConfig().Tracer(), "trace-enqueue")
 		processErr, err := store.Enqueue(
 			traceCtx, "raftsnapshot", repl, true /* skipShouldQueue */, false, /* async */
 		)
+		rec := finish()
 		if err != nil {
 			return err
 		}
 		if processErr != nil {
 			return processErr
 		}
 		const msg = `skipping snapshot; replica is likely a LEARNER in the process of being added: (n2,s2):2LEARNER`
-		formattedTrace := rec().String()
+		formattedTrace := rec.String()
 		if !strings.Contains(formattedTrace, msg) {
 			return errors.Errorf(`expected "%s" in trace got:\n%s`, msg, formattedTrace)
 		}
@@ -1545,17 +1551,18 @@ func TestLearnerReplicateQueueRace(t *testing.T) {
 	queue1ErrCh := make(chan error, 1)
 	go func() {
 		queue1ErrCh <- func() error {
-			traceCtx, rec := tracing.ContextWithRecordingSpan(ctx, store.GetStoreConfig().Tracer(), "trace-enqueue")
+			traceCtx, finish := tracing.ContextWithRecordingSpan(ctx, store.GetStoreConfig().Tracer(), "trace-enqueue")
 			processErr, err := store.Enqueue(
 				traceCtx, "replicate", repl, true /* skipShouldQueue */, false, /* async */
 			)
+			rec := finish()
 			if err != nil {
 				return err
 			}
 			if processErr == nil || !strings.Contains(processErr.Error(), `descriptor changed`) {
 				return errors.Wrap(processErr, `expected "descriptor changed" error got: %+v`)
 			}
-			formattedTrace := rec().String()
+			formattedTrace := rec.String()
 			expectedMessages := []string{
 				`could not promote .*?n3,s3.*? to voter, rolling back:.*?change replicas of r\d+ failed: descriptor changed`,
 				`learner to roll back not found`,
@@ -2088,13 +2095,14 @@ func TestMergeQueueSeesLearnerOrJointConfig(t *testing.T) {
 		})
 
 		store, repl := getFirstStoreReplica(t, tc.Server(0), scratchStartKey)
-		traceCtx, rec := tracing.ContextWithRecordingSpan(ctx, store.GetStoreConfig().Tracer(), "trace-enqueue")
+		traceCtx, finish := tracing.ContextWithRecordingSpan(ctx, store.GetStoreConfig().Tracer(), "trace-enqueue")
 		processErr, err := store.Enqueue(
 			traceCtx, "merge", repl, true /* skipShouldQueue */, false, /* async */
 		)
+		rec := finish()
 		require.NoError(t, err)
 		require.NoError(t, processErr)
-		formattedTrace := rec().String()
+		formattedTrace := rec.String()
 		expectedMessages := []string{
 			`removing learner replicas \[n2,s2\]`,
 			`merging to produce range: /Table/Max-/Max`,
@@ -2126,13 +2134,14 @@ func TestMergeQueueSeesLearnerOrJointConfig(t *testing.T) {
 		checkTransitioningOut := func() {
 			t.Helper()
 			store, repl := getFirstStoreReplica(t, tc.Server(0), scratchStartKey)
-			traceCtx, rec := tracing.ContextWithRecordingSpan(ctx, store.GetStoreConfig().Tracer(), "trace-enqueue")
+			traceCtx, finish := tracing.ContextWithRecordingSpan(ctx, store.GetStoreConfig().Tracer(), "trace-enqueue")
 			processErr, err := store.Enqueue(
 				traceCtx, "merge", repl, true /* skipShouldQueue */, false, /* async */
 			)
+			rec := finish()
 			require.NoError(t, err)
 			require.NoError(t, processErr)
-			formattedTrace := rec().String()
+			formattedTrace := rec.String()
 			expectedMessages := []string{
 				`transitioning out of joint configuration`,
 				`merging to produce range: /Table/Max-/Max`,