From 44e048c43ac2dd2a9eceab9b057b3fc43f78239a Mon Sep 17 00:00:00 2001 From: Kaushal28 Date: Thu, 30 Mar 2023 17:06:18 +0530 Subject: [PATCH 1/8] Fixed race condition in OnEnd and added a test --- sdk/trace/simple_span_processor.go | 4 ++-- sdk/trace/simple_span_processor_test.go | 31 +++++++++++++++++++++++++ 2 files changed, 33 insertions(+), 2 deletions(-) diff --git a/sdk/trace/simple_span_processor.go b/sdk/trace/simple_span_processor.go index c3bb7f9ea9c..5be877671cf 100644 --- a/sdk/trace/simple_span_processor.go +++ b/sdk/trace/simple_span_processor.go @@ -54,8 +54,8 @@ func (ssp *simpleSpanProcessor) OnStart(context.Context, ReadWriteSpan) {} // OnEnd immediately exports a ReadOnlySpan. func (ssp *simpleSpanProcessor) OnEnd(s ReadOnlySpan) { - ssp.exporterMu.RLock() - defer ssp.exporterMu.RUnlock() + ssp.exporterMu.Lock() + defer ssp.exporterMu.Unlock() if ssp.exporter != nil && s.SpanContext().TraceFlags().IsSampled() { if err := ssp.exporter.ExportSpans(context.Background(), []ReadOnlySpan{s}); err != nil { diff --git a/sdk/trace/simple_span_processor_test.go b/sdk/trace/simple_span_processor_test.go index ea0f8de49de..19db9913f70 100644 --- a/sdk/trace/simple_span_processor_test.go +++ b/sdk/trace/simple_span_processor_test.go @@ -17,6 +17,7 @@ package trace_test import ( "context" "errors" + "sync" "testing" "time" @@ -150,6 +151,36 @@ func TestSimpleSpanProcessorShutdownOnEndConcurrency(t *testing.T) { <-done } +func TestSimpleSpanProcessorShutdownOnEndRace(t *testing.T) { + exporter := &testExporter{} + ssp := sdktrace.NewSimpleSpanProcessor(exporter) + tp := basicTracerProvider(t) + tp.RegisterSpanProcessor(ssp) + + var wg sync.WaitGroup + wg.Add(2) + go func() { + _, span := tp.Tracer("test").Start(context.Background(), "A") + defer span.End() + wg.Done() + }() + + go func() { + _, span := tp.Tracer("test").Start(context.Background(), "A") + defer span.End() + wg.Done() + }() + + wg.Wait() + + if err := ssp.Shutdown(context.Background()); err != nil { + t.Errorf("shutting the SimpleSpanProcessor down: %v", err) + } + if !exporter.shutdown { + t.Error("SimpleSpanProcessor.Shutdown did not shut down exporter") + } +} + func TestSimpleSpanProcessorShutdownHonorsContextDeadline(t *testing.T) { ctx, cancel := context.WithTimeout(context.Background(), time.Nanosecond) defer cancel() From baabe66ab93d4e68924cff8dfdf0d57c4c15e68b Mon Sep 17 00:00:00 2001 From: Kaushal28 Date: Fri, 31 Mar 2023 11:39:45 +0530 Subject: [PATCH 2/8] fixed code review comments --- CHANGELOG.md | 1 + sdk/trace/simple_span_processor.go | 2 +- sdk/trace/simple_span_processor_test.go | 25 ++++++++++--------------- 3 files changed, 12 insertions(+), 16 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index cc30053118d..0b4afa5759a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -18,6 +18,7 @@ This project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.htm - `TracerProvider` allows calling `Tracer()` while it's shutting down. It used to deadlock. (#3924) +- Data race in `exporters/jaeger` when calling `End()` on spans from concurrent goroutines. (#3951) ## [1.15.0-rc.2/0.38.0-rc.2] 2023-03-23 diff --git a/sdk/trace/simple_span_processor.go b/sdk/trace/simple_span_processor.go index 5be877671cf..f8770fff79b 100644 --- a/sdk/trace/simple_span_processor.go +++ b/sdk/trace/simple_span_processor.go @@ -25,7 +25,7 @@ import ( // simpleSpanProcessor is a SpanProcessor that synchronously sends all // completed Spans to a trace.Exporter immediately. type simpleSpanProcessor struct { - exporterMu sync.RWMutex + exporterMu sync.Mutex exporter SpanExporter stopOnce sync.Once } diff --git a/sdk/trace/simple_span_processor_test.go b/sdk/trace/simple_span_processor_test.go index 19db9913f70..58f6d0c1c1c 100644 --- a/sdk/trace/simple_span_processor_test.go +++ b/sdk/trace/simple_span_processor_test.go @@ -21,6 +21,7 @@ import ( "testing" "time" + "github.com/stretchr/testify/assert" sdktrace "go.opentelemetry.io/otel/sdk/trace" "go.opentelemetry.io/otel/trace" ) @@ -159,26 +160,20 @@ func TestSimpleSpanProcessorShutdownOnEndRace(t *testing.T) { var wg sync.WaitGroup wg.Add(2) - go func() { - _, span := tp.Tracer("test").Start(context.Background(), "A") - defer span.End() - wg.Done() - }() - go func() { - _, span := tp.Tracer("test").Start(context.Background(), "A") + span := func(spanName string) { + defer wg.Done() + _, span := tp.Tracer("test").Start(context.Background(), spanName) defer span.End() - wg.Done() - }() + } + + go span("test-span-1") + go span("test-span-2") wg.Wait() - if err := ssp.Shutdown(context.Background()); err != nil { - t.Errorf("shutting the SimpleSpanProcessor down: %v", err) - } - if !exporter.shutdown { - t.Error("SimpleSpanProcessor.Shutdown did not shut down exporter") - } + assert.NoError(t, ssp.Shutdown(context.Background())) + assert.True(t, exporter.shutdown) } func TestSimpleSpanProcessorShutdownHonorsContextDeadline(t *testing.T) { From 138dd2d02a9363091974f5d7c3f9a5943f3077f5 Mon Sep 17 00:00:00 2001 From: Kaushal28 Date: Fri, 31 Mar 2023 12:08:49 +0530 Subject: [PATCH 3/8] fixed lint --- sdk/trace/simple_span_processor_test.go | 1 + 1 file changed, 1 insertion(+) diff --git a/sdk/trace/simple_span_processor_test.go b/sdk/trace/simple_span_processor_test.go index 58f6d0c1c1c..cfdfea25aeb 100644 --- a/sdk/trace/simple_span_processor_test.go +++ b/sdk/trace/simple_span_processor_test.go @@ -22,6 +22,7 @@ import ( "time" "github.com/stretchr/testify/assert" + sdktrace "go.opentelemetry.io/otel/sdk/trace" "go.opentelemetry.io/otel/trace" ) From 5a0913f5885420ff00df4b76a18ed0534fe215e8 Mon Sep 17 00:00:00 2001 From: Kaushal Shah Date: Fri, 31 Mar 2023 13:15:32 +0530 Subject: [PATCH 4/8] Update CHANGELOG.md MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Robert Pająk --- CHANGELOG.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 8d70bf532f8..aa660f8ade6 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -23,7 +23,7 @@ This project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.htm - `TracerProvider` allows calling `Tracer()` while it's shutting down. It used to deadlock. (#3924) - Use the SDK version for the Telemetry SDK resource detector in `go.opentelemetry.io/otel/sdk/resource`. (#3949) -- Data race in `exporters/jaeger` when calling `End()` on spans from concurrent goroutines. (#3951) +- Fix a data race in `SpanProcessor` returned by `NewSimpleSpanProcessor` in `go.opentelemetry.io/otel/sdk/trace`. (#3951) ## [1.15.0-rc.2/0.38.0-rc.2] 2023-03-23 From 4b6b8fbc90174d7ffff8d30b2a2194f102643bd7 Mon Sep 17 00:00:00 2001 From: Kaushal Shah Date: Mon, 3 Apr 2023 10:12:57 +0530 Subject: [PATCH 5/8] Update sdk/trace/simple_span_processor_test.go Co-authored-by: Tyler Yahn --- sdk/trace/simple_span_processor_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sdk/trace/simple_span_processor_test.go b/sdk/trace/simple_span_processor_test.go index cfdfea25aeb..b34a8111e53 100644 --- a/sdk/trace/simple_span_processor_test.go +++ b/sdk/trace/simple_span_processor_test.go @@ -174,7 +174,7 @@ func TestSimpleSpanProcessorShutdownOnEndRace(t *testing.T) { wg.Wait() assert.NoError(t, ssp.Shutdown(context.Background())) - assert.True(t, exporter.shutdown) + assert.True(t, exporter.shutdown, "exporter shutdown") } func TestSimpleSpanProcessorShutdownHonorsContextDeadline(t *testing.T) { From 3770625cee5da80d53e4c333fbb5a01d0281a9f5 Mon Sep 17 00:00:00 2001 From: Kaushal Shah Date: Mon, 3 Apr 2023 16:19:01 +0530 Subject: [PATCH 6/8] Update sdk/trace/simple_span_processor_test.go Co-authored-by: Tyler Yahn --- sdk/trace/simple_span_processor_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sdk/trace/simple_span_processor_test.go b/sdk/trace/simple_span_processor_test.go index b34a8111e53..d583b438de5 100644 --- a/sdk/trace/simple_span_processor_test.go +++ b/sdk/trace/simple_span_processor_test.go @@ -165,7 +165,7 @@ func TestSimpleSpanProcessorShutdownOnEndRace(t *testing.T) { span := func(spanName string) { defer wg.Done() _, span := tp.Tracer("test").Start(context.Background(), spanName) - defer span.End() + span.End() } go span("test-span-1") From 50765e04f41229c300e21bd3889a8586f37bd77e Mon Sep 17 00:00:00 2001 From: Kaushal Shah Date: Mon, 3 Apr 2023 16:19:18 +0530 Subject: [PATCH 7/8] Update sdk/trace/simple_span_processor_test.go Co-authored-by: Tyler Yahn --- sdk/trace/simple_span_processor_test.go | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/sdk/trace/simple_span_processor_test.go b/sdk/trace/simple_span_processor_test.go index d583b438de5..996d1c622a2 100644 --- a/sdk/trace/simple_span_processor_test.go +++ b/sdk/trace/simple_span_processor_test.go @@ -168,8 +168,10 @@ func TestSimpleSpanProcessorShutdownOnEndRace(t *testing.T) { span.End() } - go span("test-span-1") - go span("test-span-2") + assert.NotPanics(t, func() { + go span("test-span-1") + go span("test-span-2") + }) wg.Wait() From a943a6423f6d6dbc5e8998dc0fb3f78090ce4958 Mon Sep 17 00:00:00 2001 From: Kaushal28 Date: Fri, 14 Apr 2023 11:03:30 +0530 Subject: [PATCH 8/8] fixed panic check --- sdk/trace/simple_span_processor_test.go | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/sdk/trace/simple_span_processor_test.go b/sdk/trace/simple_span_processor_test.go index 996d1c622a2..fc038978314 100644 --- a/sdk/trace/simple_span_processor_test.go +++ b/sdk/trace/simple_span_processor_test.go @@ -163,15 +163,15 @@ func TestSimpleSpanProcessorShutdownOnEndRace(t *testing.T) { wg.Add(2) span := func(spanName string) { - defer wg.Done() - _, span := tp.Tracer("test").Start(context.Background(), spanName) - span.End() + assert.NotPanics(t, func() { + defer wg.Done() + _, span := tp.Tracer("test").Start(context.Background(), spanName) + span.End() + }) } - assert.NotPanics(t, func() { - go span("test-span-1") - go span("test-span-2") - }) + go span("test-span-1") + go span("test-span-2") wg.Wait()