1
0
mirror of https://github.com/open-telemetry/opentelemetry-go.git synced 2024-12-12 10:04:29 +02:00

Fix synchronization issues in global trace delegate implementation (#1686)

* Fix synchronization issues in global trace delegate implementation

Running tests with `-race` and before the fix
```
➜  opentelemetry-go git:(fixconcurrency) go test -race go.opentelemetry.io/otel/internal/global
==================
WARNING: DATA RACE
Write at 0x00c00010ffc8 by goroutine 28:
  go.opentelemetry.io/otel/internal/global.(*tracer).setDelegate.func1()
      /Users/lazy/github/opentelemetry-go/internal/global/trace.go:118 +0xf4
  sync.(*Once).doSlow()
      /usr/local/opt/go/libexec/src/sync/once.go:68 +0x109
  sync.(*Once).Do()
      /usr/local/opt/go/libexec/src/sync/once.go:59 +0x68
  go.opentelemetry.io/otel/internal/global.(*tracer).setDelegate()
      /Users/lazy/github/opentelemetry-go/internal/global/trace.go:118 +0x76
  go.opentelemetry.io/otel/internal/global.(*tracerProvider).setDelegate()
      /Users/lazy/github/opentelemetry-go/internal/global/trace.go:75 +0x16f
  go.opentelemetry.io/otel/internal/global.SetTracerProvider.func1()
      /Users/lazy/github/opentelemetry-go/internal/global/state.go:65 +0xd0
  sync.(*Once).doSlow()
      /usr/local/opt/go/libexec/src/sync/once.go:68 +0x109
  sync.(*Once).Do()
      /usr/local/opt/go/libexec/src/sync/once.go:59 +0x68
  go.opentelemetry.io/otel/internal/global.SetTracerProvider()
      /Users/lazy/github/opentelemetry-go/internal/global/state.go:57 +0x79
  go.opentelemetry.io/otel.SetTracerProvider()
      /Users/lazy/github/opentelemetry-go/trace.go:43 +0x388
  go.opentelemetry.io/otel/internal/global_test.TestTracerDelegates_MultiGoRoutines()
      /Users/lazy/github/opentelemetry-go/internal/global/trace_test.go:177 +0x373
  testing.tRunner()
      /usr/local/opt/go/libexec/src/testing/testing.go:1194 +0x202

Previous read at 0x00c00010ffc8 by goroutine 29:
  go.opentelemetry.io/otel/internal/global.(*tracer).Start()
      /Users/lazy/github/opentelemetry-go/internal/global/trace.go:124 +0x64
  go.opentelemetry.io/otel/internal/global_test.TestTracerDelegates_MultiGoRoutines.func1()
      /Users/lazy/github/opentelemetry-go/internal/global/trace_test.go:165 +0xf1

Goroutine 28 (running) created at:
  testing.(*T).Run()
      /usr/local/opt/go/libexec/src/testing/testing.go:1239 +0x5d7
  testing.runTests.func1()
      /usr/local/opt/go/libexec/src/testing/testing.go:1512 +0xa6
  testing.tRunner()
      /usr/local/opt/go/libexec/src/testing/testing.go:1194 +0x202
  testing.runTests()
      /usr/local/opt/go/libexec/src/testing/testing.go:1510 +0x612
  testing.(*M).Run()
      /usr/local/opt/go/libexec/src/testing/testing.go:1418 +0x3b3
  go.opentelemetry.io/otel/internal/global_test.TestMain()
      /Users/lazy/github/opentelemetry-go/internal/global/internal_test.go:39 +0x4dc
  main.main()
      _testmain.go:85 +0x271

Goroutine 29 (running) created at:
  go.opentelemetry.io/otel/internal/global_test.TestTracerDelegates_MultiGoRoutines()
      /Users/lazy/github/opentelemetry-go/internal/global/trace_test.go:160 +0x259
  testing.tRunner()
      /usr/local/opt/go/libexec/src/testing/testing.go:1194 +0x202
==================
==================
WARNING: DATA RACE
Write at 0x00c00037a000 by goroutine 29:
  sync/atomic.StoreInt32()
      /usr/local/opt/go/libexec/src/runtime/race_amd64.s:242 +0xb
  go.opentelemetry.io/otel/internal/global_test.TestTracerDelegates_MultiGoRoutines.func2.1()
      /Users/lazy/github/opentelemetry-go/internal/global/trace_test.go:183 +0x6d
  go.opentelemetry.io/otel/internal/global_test.fnTracer.Start()
      /Users/lazy/github/opentelemetry-go/internal/global/trace_test.go:81 +0x98
  go.opentelemetry.io/otel/internal/global.(*tracer).Start()
      /Users/lazy/github/opentelemetry-go/internal/global/trace.go:125 +0xfd
  go.opentelemetry.io/otel/internal/global_test.TestTracerDelegates_MultiGoRoutines.func1()
      /Users/lazy/github/opentelemetry-go/internal/global/trace_test.go:165 +0xf1

Previous write at 0x00c00037a000 by goroutine 28:
  go.opentelemetry.io/otel/internal/global_test.TestTracerDelegates_MultiGoRoutines()
      /Users/lazy/github/opentelemetry-go/internal/global/trace_test.go:176 +0x2c4
  testing.tRunner()
      /usr/local/opt/go/libexec/src/testing/testing.go:1194 +0x202

Goroutine 29 (running) created at:
  go.opentelemetry.io/otel/internal/global_test.TestTracerDelegates_MultiGoRoutines()
      /Users/lazy/github/opentelemetry-go/internal/global/trace_test.go:160 +0x259
  testing.tRunner()
      /usr/local/opt/go/libexec/src/testing/testing.go:1194 +0x202

Goroutine 28 (running) created at:
  testing.(*T).Run()
      /usr/local/opt/go/libexec/src/testing/testing.go:1239 +0x5d7
  testing.runTests.func1()
      /usr/local/opt/go/libexec/src/testing/testing.go:1512 +0xa6
  testing.tRunner()
      /usr/local/opt/go/libexec/src/testing/testing.go:1194 +0x202
  testing.runTests()
      /usr/local/opt/go/libexec/src/testing/testing.go:1510 +0x612
  testing.(*M).Run()
      /usr/local/opt/go/libexec/src/testing/testing.go:1418 +0x3b3
  go.opentelemetry.io/otel/internal/global_test.TestMain()
      /Users/lazy/github/opentelemetry-go/internal/global/internal_test.go:39 +0x4dc
  main.main()
      _testmain.go:85 +0x271
==================
--- FAIL: TestTracerDelegates_MultiGoRoutines (0.20s)
    testing.go:1093: race detected during execution of test
FAIL
FAIL    go.opentelemetry.io/otel/internal/global        0.920s
FAIL
```

Signed-off-by: Bogdan Drutu <bogdandrutu@gmail.com>

* Update internal/global/trace_test.go

Co-authored-by: Tyler Yahn <MrAlias@users.noreply.github.com>

* Update internal/global/trace_test.go

Co-authored-by: Tyler Yahn <MrAlias@users.noreply.github.com>

* Make tests not flaky

Signed-off-by: Bogdan Drutu <bogdandrutu@gmail.com>

Co-authored-by: Tyler Yahn <MrAlias@users.noreply.github.com>
This commit is contained in:
Bogdan Drutu 2021-03-10 08:45:31 -08:00 committed by GitHub
parent 58f69f091e
commit 9d3416cc91
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
3 changed files with 115 additions and 16 deletions

View File

@ -39,6 +39,7 @@ This project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.htm
span's `SpanContext`. (#1655) span's `SpanContext`. (#1655)
- Jaeger Exporter: Ensure mapping between OTEL and Jaeger span data complies with the specification. (#1626) - Jaeger Exporter: Ensure mapping between OTEL and Jaeger span data complies with the specification. (#1626)
- The `otel-collector` example now correctly flushes metric events prior to shutting down the exporter. (#1678) - The `otel-collector` example now correctly flushes metric events prior to shutting down the exporter. (#1678)
- Synchronization issues in global trace delegate implementation. (#1686)
### Fixed ### Fixed
- Do not set span status message in `SpanStatusFromHTTPStatusCode` if it can be inferred from `http.status_code`. (#1681) - Do not set span status message in `SpanStatusFromHTTPStatusCode` if it can be inferred from `http.status_code`. (#1681)

View File

@ -34,6 +34,7 @@ SDK prior to any Tracer creation.
import ( import (
"context" "context"
"sync" "sync"
"sync/atomic"
"go.opentelemetry.io/otel/internal/trace/noop" "go.opentelemetry.io/otel/internal/trace/noop"
"go.opentelemetry.io/otel/trace" "go.opentelemetry.io/otel/trace"
@ -44,9 +45,8 @@ import (
// All TracerProvider functionality is forwarded to a delegate once // All TracerProvider functionality is forwarded to a delegate once
// configured. // configured.
type tracerProvider struct { type tracerProvider struct {
mtx sync.Mutex mtx sync.Mutex
tracers []*tracer tracers []*tracer
delegate trace.TracerProvider delegate trace.TracerProvider
} }
@ -60,13 +60,8 @@ var _ trace.TracerProvider = &tracerProvider{}
// All Tracers provided prior to this function call are switched out to be // All Tracers provided prior to this function call are switched out to be
// Tracers provided by provider. // Tracers provided by provider.
// //
// Delegation only happens on the first call to this method. All subsequent // It is guaranteed by the caller that this happens only once.
// calls result in no delegation changes.
func (p *tracerProvider) setDelegate(provider trace.TracerProvider) { func (p *tracerProvider) setDelegate(provider trace.TracerProvider) {
if p.delegate != nil {
return
}
p.mtx.Lock() p.mtx.Lock()
defer p.mtx.Unlock() defer p.mtx.Unlock()
@ -97,11 +92,10 @@ func (p *tracerProvider) Tracer(name string, opts ...trace.TracerOption) trace.T
// All Tracer functionality is forwarded to a delegate once configured. // All Tracer functionality is forwarded to a delegate once configured.
// Otherwise, all functionality is forwarded to a NoopTracer. // Otherwise, all functionality is forwarded to a NoopTracer.
type tracer struct { type tracer struct {
once sync.Once
name string name string
opts []trace.TracerOption opts []trace.TracerOption
delegate trace.Tracer delegate atomic.Value
} }
// Compile-time guarantee that tracer implements the trace.Tracer interface. // Compile-time guarantee that tracer implements the trace.Tracer interface.
@ -112,17 +106,17 @@ var _ trace.Tracer = &tracer{}
// //
// All subsequent calls to the Tracer methods will be passed to the delegate. // All subsequent calls to the Tracer methods will be passed to the delegate.
// //
// Delegation only happens on the first call to this method. All subsequent // It is guaranteed by the caller that this happens only once.
// calls result in no delegation changes.
func (t *tracer) setDelegate(provider trace.TracerProvider) { func (t *tracer) setDelegate(provider trace.TracerProvider) {
t.once.Do(func() { t.delegate = provider.Tracer(t.name, t.opts...) }) t.delegate.Store(provider.Tracer(t.name, t.opts...))
} }
// Start implements trace.Tracer by forwarding the call to t.delegate if // Start implements trace.Tracer by forwarding the call to t.delegate if
// set, otherwise it forwards the call to a NoopTracer. // set, otherwise it forwards the call to a NoopTracer.
func (t *tracer) Start(ctx context.Context, name string, opts ...trace.SpanOption) (context.Context, trace.Span) { func (t *tracer) Start(ctx context.Context, name string, opts ...trace.SpanOption) (context.Context, trace.Span) {
if t.delegate != nil { delegate := t.delegate.Load()
return t.delegate.Start(ctx, name, opts...) if delegate != nil {
return delegate.(trace.Tracer).Start(ctx, name, opts...)
} }
return noop.Tracer.Start(ctx, name, opts...) return noop.Tracer.Start(ctx, name, opts...)
} }

View File

@ -16,7 +16,9 @@ package global_test
import ( import (
"context" "context"
"sync/atomic"
"testing" "testing"
"time"
"github.com/stretchr/testify/assert" "github.com/stretchr/testify/assert"
@ -71,6 +73,14 @@ func (fn fnTracerProvider) Tracer(instrumentationName string, opts ...trace.Trac
return fn.tracer(instrumentationName, opts...) return fn.tracer(instrumentationName, opts...)
} }
type fnTracer struct {
start func(ctx context.Context, spanName string, opts ...trace.SpanOption) (context.Context, trace.Span)
}
func (fn fnTracer) Start(ctx context.Context, spanName string, opts ...trace.SpanOption) (context.Context, trace.Span) {
return fn.start(ctx, spanName, opts...)
}
func TestTraceProviderDelegates(t *testing.T) { func TestTraceProviderDelegates(t *testing.T) {
global.ResetForTest() global.ResetForTest()
@ -91,3 +101,97 @@ func TestTraceProviderDelegates(t *testing.T) {
gtp.Tracer("abc", trace.WithInstrumentationVersion("xyz")) gtp.Tracer("abc", trace.WithInstrumentationVersion("xyz"))
assert.True(t, called, "expected configured TraceProvider to be called") assert.True(t, called, "expected configured TraceProvider to be called")
} }
func TestTraceProviderDelegatesConcurrentSafe(t *testing.T) {
global.ResetForTest()
// Retrieve the placeholder TracerProvider.
gtp := otel.GetTracerProvider()
done := make(chan struct{})
quit := make(chan struct{})
go func() {
defer close(done)
for {
select {
case <-time.After(1 * time.Millisecond):
gtp.Tracer("abc", trace.WithInstrumentationVersion("xyz"))
case <-quit:
return
}
}
}()
// Wait for the goroutine to make some calls before installing the provider.
<-time.After(100 * time.Millisecond)
// Configure it with a spy.
called := int32(0)
otel.SetTracerProvider(fnTracerProvider{
tracer: func(name string, opts ...trace.TracerOption) trace.Tracer {
newVal := atomic.AddInt32(&called, 1)
assert.Equal(t, "abc", name)
assert.Equal(t, []trace.TracerOption{trace.WithInstrumentationVersion("xyz")}, opts)
if newVal == 10 {
// Signal the goroutine to finish.
close(quit)
}
return trace.NewNoopTracerProvider().Tracer("")
},
})
// Wait for the go routine to finish
<-done
assert.LessOrEqual(t, int32(10), atomic.LoadInt32(&called), "expected configured TraceProvider to be called")
}
func TestTracerDelegatesConcurrentSafe(t *testing.T) {
global.ResetForTest()
// Retrieve the placeholder TracerProvider.
gtp := otel.GetTracerProvider()
tracer := gtp.Tracer("abc", trace.WithInstrumentationVersion("xyz"))
done := make(chan struct{})
quit := make(chan struct{})
go func() {
defer close(done)
for {
select {
case <-time.After(1 * time.Millisecond):
tracer.Start(context.Background(), "name")
case <-quit:
return
}
}
}()
// Wait for the goroutine to make some calls before installing the provider.
<-time.After(100 * time.Millisecond)
// Configure it with a spy.
called := int32(0)
otel.SetTracerProvider(fnTracerProvider{
tracer: func(name string, opts ...trace.TracerOption) trace.Tracer {
assert.Equal(t, "abc", name)
assert.Equal(t, []trace.TracerOption{trace.WithInstrumentationVersion("xyz")}, opts)
return fnTracer{
start: func(ctx context.Context, spanName string, opts ...trace.SpanOption) (context.Context, trace.Span) {
newVal := atomic.AddInt32(&called, 1)
assert.Equal(t, "name", spanName)
if newVal == 10 {
// Signal the goroutine to finish.
close(quit)
}
return trace.NewNoopTracerProvider().Tracer("").Start(ctx, spanName)
},
}
},
})
// Wait for the go routine to finish
<-done
assert.LessOrEqual(t, int32(10), atomic.LoadInt32(&called), "expected configured TraceProvider to be called")
}