Merge #60725

60725: tracing: harden against use-after-Finish r=knz a=tbg

`net/trace`'s `Trace` is notoriously panicky when used after a call to
`.Finish()`. We don't like such calls and try to avoid them, but they
are hard to conclusively disprove. Besides, the opposite - never calling
`.Finish()` is even worse, so in general we'd like to err on the side of
use-after-free and want that to be safe.

This commit does that: we move `Span` to `spanInner` and `*Span` becomes
a simple wrapper that turns most operations into no-ops once the first
call to `.Finish` has been initiated.

While I was there, I also removed `IsBlackHole()` which wasn't really
useful any more.

This fixes the following crash:

#58489 (comment)

which was surfaced by a recent switch in that test to enable tracing
throughout (precisely to find these crashes!).

Release note (bug fix): fixed a bug that could result in crashes during
tracing when using the `trace.debug.enable` cluster setting.


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

pkg/kv/kvclient/kvcoord/txn_coord_sender.go

@@ -471,12 +471,12 @@ func (tc *TxnCoordSender) Send(
 	if tc.mu.txn.ID == (uuid.UUID{}) {
 		log.Fatalf(ctx, "cannot send transactional request through unbound TxnCoordSender")
 	}
-	if !sp.IsBlackHole() {
+	if sp.IsVerbose() {
 		sp.SetBaggageItem("txnID", tc.mu.txn.ID.String())
-	}
-	ctx = logtags.AddTag(ctx, "txn", uuid.ShortStringer(tc.mu.txn.ID))
-	if log.V(2) {
-		ctx = logtags.AddTag(ctx, "ts", tc.mu.txn.WriteTimestamp)
+		ctx = logtags.AddTag(ctx, "txn", uuid.ShortStringer(tc.mu.txn.ID))
+		if log.V(2) {
+			ctx = logtags.AddTag(ctx, "ts", tc.mu.txn.WriteTimestamp)
+		}
 	}
 
 	// It doesn't make sense to use inconsistent reads in a transaction. However,

pkg/kv/kvserver/replica_proposal.go

@@ -865,7 +865,7 @@ func (r *Replica) getTraceData(ctx context.Context) map[string]string {
 	if sp == nil {
 		return nil
 	}
-	if sp.IsBlackHole() {
+	if !sp.IsVerbose() {
 		return nil
 	}
 

pkg/sql/opt/exec/execbuilder/testdata/autocommit_nonmetamorphic

@@ -668,7 +668,6 @@ WHERE message       LIKE '%r$rangeid: sending batch%'
 ----
 dist sender send  r36: sending batch 1 DelRng to (n1,s1):1
 dist sender send  r36: sending batch 2 CPut to (n1,s1):1
-dist sender send  r36: sending batch 2 Scan to (n1,s1):1
 dist sender send  r36: sending batch 1 EndTxn to (n1,s1):1
 
 query B
@@ -693,7 +692,6 @@ WHERE message       LIKE '%r$rangeid: sending batch%'
 dist sender send  r36: sending batch 1 DelRng to (n1,s1):1
 dist sender send  r36: sending batch 1 Scan to (n1,s1):1
 dist sender send  r36: sending batch 1 Put to (n1,s1):1
-dist sender send  r36: sending batch 1 Scan to (n1,s1):1
 dist sender send  r36: sending batch 1 EndTxn to (n1,s1):1
 
 query B
@@ -719,7 +717,6 @@ WHERE message       LIKE '%r$rangeid: sending batch%'
 dist sender send  r36: sending batch 1 DelRng to (n1,s1):1
 dist sender send  r36: sending batch 1 Scan to (n1,s1):1
 dist sender send  r36: sending batch 1 Del to (n1,s1):1
-dist sender send  r36: sending batch 1 Scan to (n1,s1):1
 dist sender send  r36: sending batch 1 EndTxn to (n1,s1):1
 
 # Test with a single cascade, which should use autocommit.
@@ -746,7 +743,6 @@ WHERE message       LIKE '%r$rangeid: sending batch%'
 ----
 dist sender send  r36: sending batch 1 DelRng to (n1,s1):1
 dist sender send  r36: sending batch 1 DelRng to (n1,s1):1
-dist sender send  r36: sending batch 1 Scan to (n1,s1):1
 dist sender send  r36: sending batch 1 Del, 1 EndTxn to (n1,s1):1
 
 # -----------------------

pkg/sql/opt/exec/execbuilder/testdata/partial_index_nonmetamorphic

@@ -905,7 +905,6 @@ query T kvtrace
 DELETE FROM t57085_p WHERE p = 1;
 ----
 DelRange /Table/56/1/1 - /Table/56/1/1/#
-Scan /Table/57/{1-2}
 Del /Table/57/2/1/10/0
 Del /Table/57/1/10/0
 Del /Table/57/1/20/0

pkg/util/log/ambient_context_test.go

@@ -79,7 +79,7 @@ func TestAnnotateCtxSpan(t *testing.T) {
 	ctx, sp := ac.AnnotateCtxWithSpan(context.Background(), "s")
 	require.Equal(t, sp, tracing.SpanFromContext(ctx))
 	require.NotNil(t, sp)
-	require.True(t, sp.IsBlackHole())
+	require.False(t, sp.IsVerbose())
 }
 
 func TestAnnotateCtxNodeStoreReplica(t *testing.T) {

pkg/util/log/trace.go

@@ -92,7 +92,7 @@ func FinishEventLog(ctx context.Context) {
 // false.
 func getSpanOrEventLog(ctx context.Context) (*tracing.Span, *ctxEventLog, bool) {
 	if sp := tracing.SpanFromContext(ctx); sp != nil {
-		if sp.IsBlackHole() {
+		if !sp.IsVerbose() {
 			return nil, nil, false
 		}
 		return sp, nil, true

pkg/util/tracing/context.go

@@ -59,7 +59,7 @@ func maybeWrapCtx(ctx context.Context, octx *optimizedContext, sp *Span) (contex
 	}
 	// NB: we check sp != nil explicitly because some callers want to remove a
 	// Span from a Context, and thus pass nil.
-	if sp != nil && sp.isNoop() {
+	if sp != nil && sp.i.isNoop() {
 		// If the context originally had the noop span, and we would now be wrapping
 		// the noop span in it again, we don't have to wrap at all and can save an
 		// allocation.
@@ -68,7 +68,7 @@ func maybeWrapCtx(ctx context.Context, octx *optimizedContext, sp *Span) (contex
 		// constitute a bug: A real, non-recording span might later start recording.
 		// Besides, the caller expects to get their own span, and will .Finish() it,
 		// leading to an extra, premature call to Finish().
-		if ctxSp := SpanFromContext(ctx); ctxSp != nil && ctxSp.isNoop() {
+		if ctxSp := SpanFromContext(ctx); ctxSp != nil && ctxSp.i.isNoop() {
 			return ctx, sp
 		}
 	}

pkg/util/tracing/grpc_interceptor.go

@@ -208,7 +208,7 @@ func (ss *tracingServerStream) Context() context.Context {
 //
 // See #17177.
 func spanInclusionFuncForClient(parent *Span) bool {
-	return parent != nil && !parent.isNoop()
+	return parent != nil && !parent.i.isNoop()
 }
 
 func injectSpanMeta(ctx context.Context, tracer *Tracer, clientSpan *Span) context.Context {