Data race when accessing `go.opentelemetry.io/otel/sdk/trace.recordingSpan.Attributes` concurrently

[maxsours]

Description

go.opentelemetry.io/otel/sdk/trace.recordingSpan.Attributes locks its internal mutex before deleting attribute.KeyValue elems with matching keys. However, since it does so on the same backing array that is eventually returned, the return value is unsafe to read without locking the mutex. This means concurrent Attributes calls on the same recordingSpan can trigger a data race.

Environment

• OS: darwin
• Architecture: arm64
• Go Version: go1.26.5
• opentelemetry-go version: v1.45.0

Steps To Reproduce

package main

import (
	"context"
	"testing"

	"go.opentelemetry.io/otel/attribute"
	sdktrace "go.opentelemetry.io/otel/sdk/trace"
	"go.opentelemetry.io/otel/trace"
)

func TestRace(t *testing.T) {
	tp := sdktrace.NewTracerProvider()
	tracer := tp.Tracer("recorder")
	_, s := tracer.Start(context.Background(), "foo", trace.WithAttributes(attribute.String("key", "value")))
	span := s.(sdktrace.ReadOnlySpan)
	for range 2 {
		go func() {
			for _, attr := range span.Attributes() {
				_ = attr
			}
		}()
	}
}

Running the above test with the race detector reveals a data race:

% go test -run TestRace -count=1 -race .
PASS
==================
WARNING: DATA RACE
Write at 0x00c00007ce00 by goroutine 10:
  go.opentelemetry.io/otel/sdk/trace.(*recordingSpan).dedupeAttrsFromRecord()
      /Users/maxsours/go/pkg/mod/go.opentelemetry.io/otel/sdk@v1.45.0/trace/span.go:619 +0x30c
  go.opentelemetry.io/otel/sdk/trace.(*recordingSpan).dedupeAttrs()
      /Users/maxsours/go/pkg/mod/go.opentelemetry.io/otel/sdk@v1.45.0/trace/span.go:605 +0x120
  go.opentelemetry.io/otel/sdk/trace.(*recordingSpan).Attributes()
      /Users/maxsours/go/pkg/mod/go.opentelemetry.io/otel/sdk@v1.45.0/trace/span.go:594 +0x90
  max-scratch-app.TestRace.func1()
      /Users/maxsours/Documents/contrast/max-scratch-app/app_test.go:19 +0x38

Previous read at 0x00c00007ce00 by goroutine 9:
  max-scratch-app.TestRace.func1()
      /Users/maxsours/Documents/contrast/max-scratch-app/app_test.go:19 +0x68

Goroutine 10 (running) created at:
  max-scratch-app.TestRace()
      /Users/maxsours/Documents/contrast/max-scratch-app/app_test.go:18 +0x294
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:2036 +0x164
  testing.(*T).Run.gowrap1()
      /usr/local/go/src/testing/testing.go:2101 +0x34

Goroutine 9 (finished) created at:
  max-scratch-app.TestRace()
      /Users/maxsours/Documents/contrast/max-scratch-app/app_test.go:18 +0x294
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:2036 +0x164
  testing.(*T).Run.gowrap1()
      /usr/local/go/src/testing/testing.go:2101 +0x34
==================
Found 1 data race(s)
FAIL    max-scratch-app 1.560s
FAIL

The source of the issue appears to be in go.opentelemetry.io/sdk/trace/span.go:

// Attributes returns the attributes of this span.
//
// The order of the returned attributes is not guaranteed to be stable.
func (s *recordingSpan) Attributes() []attribute.KeyValue {
	s.mu.Lock()
	defer s.mu.Unlock()
	s.dedupeAttrs()
	return s.attributes
}

// dedupeAttrs deduplicates the attributes of s to fit capacity.
//
// This method assumes s.mu.Lock is held by the caller.
func (s *recordingSpan) dedupeAttrs() {
	// Do not set a capacity when creating this map. Benchmark testing has
	// showed this to only add unused memory allocations in general use.
	exists := make(map[attribute.Key]int, len(s.attributes))
	s.dedupeAttrsFromRecord(exists)
}

// dedupeAttrsFromRecord deduplicates the attributes of s to fit capacity
// using record as the record of unique attribute keys to their index.
//
// This method assumes s.mu.Lock is held by the caller.
func (s *recordingSpan) dedupeAttrsFromRecord(record map[attribute.Key]int) {
	// Use the fact that slices share the same backing array.
	unique := s.attributes[:0]
	for _, a := range s.attributes {
		if idx, ok := record[a.Key]; ok {
			unique[idx] = a
		} else {
			unique = append(unique, a)
			record[a.Key] = len(unique) - 1
		}
	}
	clear(s.attributes[len(unique):]) // Erase unneeded elements to let GC collect objects.
	s.attributes = unique
}

Since recordingSpan.dedupeAttrsFromRecord writes to the same backing array as recordingSpan.attributes, all reads to the same backing array (returned by recordingSpan.Attributes) need to be gated behind the mutex. This does not seem like intended behavior.

I also strongly suspect the same race condition could be reproduced by passing in go.opentelemetry.io/otel/sdk/trace.WithBatcher to the tracer, since batchSpanProcessor will split off a goroutine to consume and export spans in the queue. This results in two concurrent recordingSpan.Attributes calls.

package main

import (
	"context"
	"log"
	"testing"
	"time"

	"go.opentelemetry.io/otel/attribute"
	"go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp"
	sdktrace "go.opentelemetry.io/otel/sdk/trace"
	"go.opentelemetry.io/otel/sdk/trace/tracetest"
	"go.opentelemetry.io/otel/trace"
)

func TestRace(t *testing.T) {
	exporter, err := otlptracehttp.New(context.Background())
	if err != nil {
		log.Fatal(err)
	}
	rc := tracetest.NewSpanRecorder()
	tp := sdktrace.NewTracerProvider(
		sdktrace.WithBatcher(exporter), // spins off goroutine that eventually calls `recordingSpan.Attributes` in `go.opentelemetry.io/otel/exports/otlp/otlptrace/internal/tracetransform/span.go:109`
		sdktrace.WithSpanProcessor(rc),
	)
	time.Sleep(time.Second)
	tracer := tp.Tracer("recorder")
	_, s := tracer.Start(context.Background(), "foo", trace.WithAttributes(attribute.String("key", "value")))
	span := s.(sdktrace.ReadOnlySpan)
	for _, attr := range span.Attributes() {
		_ = attr
	}
}

I have good reason to believe the above code could produce the same race described above, but I have not been able to trip the race detector with a simple reproducer.

Expected behavior

Expect no data race when accessing span attributes concurrently.

[MrAlias]

Confirmed on current main (6618f9b) with a synchronized reproducer under the race detector

The race is between recordingSpan.dedupeAttrsFromRecord rewriting the internal attribute slice and another caller reading the slice previously returned by recordingSpan.Attributes.

The WithBatcher example is not needed to establish the bug. The normal batch path receives the snapshot created by recordingSpan.End, rather than the live recordingSpan, and the example in the issue does not call End.

This is a valid sdk/trace concurrency bug. The fix should ensure the attributes returned from a live recordingSpan do not alias storage that the span may subsequently mutate.