fix(ddtrace/tracer): postpone span events/links serialization (#3429)

Author: darccio

ddtrace/tracer/span.go

@@ -91,7 +91,6 @@ type span struct {
 
 	pprofCtxActive  context.Context `msg:"-"` // contains pprof.WithLabel labels to tell the profiler more about this span
 	pprofCtxRestore context.Context `msg:"-"` // contains pprof.WithLabel labels of the parent span (if any) that need to be restored when this span finishes
-	finishGuard     atomic.Uint32   `msg:"-"` // finishGuard value to detect if Span.Finish has been called to only finish the span once
 
 	taskEnd func() // ends execution tracer (runtime/trace) task, if started
 }
@@ -485,6 +484,15 @@ func (s *span) setMetric(key string, v float64) {
 
 // AddSpanLink appends the given link to the span's span links.
 func (s *span) AddSpanLink(link ddtrace.SpanLink) {
+	s.Lock()
+	defer s.Unlock()
+	// We don't lock spans when flushing, so we could have a data race when
+	// modifying a span as it's being flushed. This protects us against that
+	// race, since spans are marked `finished` before we flush them.
+	if s.finished {
+		// already finished
+		return
+	}
 	s.SpanLinks = append(s.SpanLinks, link)
 }
 
@@ -529,11 +537,6 @@ func (s *span) serializeSpanEvents() {
 // Finish closes this Span (but not its children) providing the duration
 // of its part of the tracing session.
 func (s *span) Finish(opts ...ddtrace.FinishOption) {
-	// If Span.Finish has already been called, do nothing.
-	// In this way, we can ensure that Span.Finish is called at most once.
-	if !s.finishGuard.CompareAndSwap(0, 1) {
-		return
-	}
 	t := now()
 	if len(opts) > 0 {
 		cfg := ddtrace.FinishConfig{
@@ -581,9 +584,6 @@ func (s *span) Finish(opts ...ddtrace.FinishOption) {
 		}
 	}
 
-	s.serializeSpanLinksInMeta()
-	s.serializeSpanEvents()
-
 	s.finish(t)
 	orchestrion.GLSPopValue(sharedinternal.ActiveSpanKey)
 }
@@ -612,6 +612,10 @@ func (s *span) finish(finishTime int64) {
 		// already finished
 		return
 	}
+
+	s.serializeSpanLinksInMeta()
+	s.serializeSpanEvents()
+
 	if s.Duration == 0 {
 		s.Duration = finishTime - s.Start
 	}
@@ -795,6 +799,8 @@ func (s *span) Format(f fmt.State, c rune) {
 
 // AddEvent attaches a new event to the current span.
 func (s *span) AddEvent(name string, opts ...ddtrace.SpanEventOption) {
+	s.Lock()
+	defer s.Unlock()
 	if s.finished {
 		return
 	}

ddtrace/tracer/spancontext_test.go

@@ -13,6 +13,7 @@ import (
 	"testing"
 	"time"
 
+	"gopkg.in/DataDog/dd-trace-go.v1/ddtrace"
 	"gopkg.in/DataDog/dd-trace-go.v1/ddtrace/ext"
 	"gopkg.in/DataDog/dd-trace-go.v1/internal/globalconfig"
 	"gopkg.in/DataDog/dd-trace-go.v1/internal/log"
@@ -55,6 +56,52 @@ func TestNewSpanContextPushError(t *testing.T) {
 	assert.Contains(t, tp.Logs()[0], "ERROR: trace buffer full (2)")
 }
 
+/*
+This test is an attempt to reproduce one of the panics from incident 37240 [1].
+Run the test with -count 100, and you should get a crash like the one shown
+below.
+
+[1] https://dd.slack.com/archives/C08NGNZR0C8/p1744390495200339
+
+	fatal error: concurrent map iteration and map write
+
+	goroutine 354 [running]:
+	internal/runtime/maps.fatal({0x102db4b48?, 0x14000101d98?})
+			/Users/felix.geisendoerfer/.local/share/mise/installs/go/1.24.2/src/runtime/panic.go:1058 +0x20
+	internal/runtime/maps.(*Iter).Next(0x1400009dca0?)
+			/Users/felix.geisendoerfer/.local/share/mise/installs/go/1.24.2/src/internal/runtime/maps/table.go:683 +0x94
+	gopkg.in/DataDog/dd-trace-go.v1/ddtrace/tracer.(*span).EncodeMsg(0x14000140140, 0x14000c1c000)
+			/Users/felix.geisendoerfer/go/src/github.com/DataDog/dd-trace-go/ddtrace/tracer/span_msgp.go:392 +0x2e8
+	gopkg.in/DataDog/dd-trace-go.v1/ddtrace/tracer.spanList.EncodeMsg({0x140003e0320, 0x1, 0x18?}, 0x14000c1c000)
+			/Users/felix.geisendoerfer/go/src/github.com/DataDog/dd-trace-go/ddtrace/tracer/span_msgp.go:596 +0x80
+	github.com/tinylib/msgp/msgp.Encode({0x1031ebd00?, 0x14000294d48?}, {0x1031ec060?, 0x1400000e090?})
+			/Users/felix.geisendoerfer/go/pkg/mod/github.com/tinylib/[email protected]/msgp/write.go:156 +0x60
+	gopkg.in/DataDog/dd-trace-go.v1/ddtrace/tracer.(*payload).push(0x14000294d20, {0x140003e0320, 0x1, 0xa})
+			/Users/felix.geisendoerfer/go/src/github.com/DataDog/dd-trace-go/ddtrace/tracer/payload.go:76 +0x98
+	gopkg.in/DataDog/dd-trace-go.v1/ddtrace/tracer.(*agentTraceWriter).add(0x140003e0000, {0x140003e0320?, 0x0?, 0x0?})
+			/Users/felix.geisendoerfer/go/src/github.com/DataDog/dd-trace-go/ddtrace/tracer/writer.go:69 +0x28
+	gopkg.in/DataDog/dd-trace-go.v1/ddtrace/tracer.(*tracer).worker(0x140000c40d0, 0x1400012b2d0)
+			/Users/felix.geisendoerfer/go/src/github.com/DataDog/dd-trace-go/ddtrace/tracer/tracer.go:457 +0x154
+	gopkg.in/DataDog/dd-trace-go.v1/ddtrace/tracer.newTracer.func2()
+			/Users/felix.geisendoerfer/go/src/github.com/DataDog/dd-trace-go/ddtrace/tracer/tracer.go:412 +0xa8
+	created by gopkg.in/DataDog/dd-trace-go.v1/ddtrace/tracer.newTracer in goroutine 326
+			/Users/felix.geisendoerfer/go/src/github.com/DataDog/dd-trace-go/ddtrace/tracer/tracer.go:404 +0x2b4
+*/
+func TestIncident37240DoubleFinish(t *testing.T) {
+	_, _, _, stop := startTestTracer(t)
+	defer stop()
+
+	root, _ := StartSpanFromContext(context.Background(), "root", Tag(ext.ManualKeep, true))
+	// My theory is that contrib/aws/internal/span_pointers/span_pointers.go
+	// adds a span link which is causes `serializeSpanLinksInMeta` to write to
+	// `s.Meta` without holding the lock. This crashes when the span flushing
+	// code tries to read `s.Meta` without holding the lock.
+	root.(*span).AddSpanLink(ddtrace.SpanLink{TraceID: 1, SpanID: 2})
+	for i := 0; i < 1000; i++ {
+		root.Finish()
+	}
+}
+
 func TestAsyncSpanRace(t *testing.T) {
 	testAsyncSpanRace(t)
 }