From 1a662f228e4ca8420a829362ed135cdda06a8bfe Mon Sep 17 00:00:00 2001 From: Joe Elliott Date: Tue, 13 Oct 2020 16:31:16 -0400 Subject: [PATCH 1/6] Removed skip and added additional span accessors Signed-off-by: Joe Elliott --- span_test.go | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/span_test.go b/span_test.go index 18083039..f4a04db1 100644 --- a/span_test.go +++ b/span_test.go @@ -363,7 +363,6 @@ func TestSpan_References(t *testing.T) { } func TestSpanContextRaces(t *testing.T) { - t.Skip("Skipped: test will panic with -race, see https://github.com/jaegertracing/jaeger-client-go/issues/526") tracer, closer := NewTracer("test", NewConstSampler(true), NewNullReporter()) defer closer.Close() @@ -395,6 +394,15 @@ func TestSpanContextRaces(t *testing.T) { go accessor(func() { span.BaggageItem("k") }) + go accessor(func() { + ext.SamplingPriority.Set(span, 0) + }) + go accessor(func() { + EnableFirehose(span) + }) + go accessor(func() { + span.SpanContext().samplingState.setFlag(flagDebug) + }) time.Sleep(100 * time.Millisecond) close(end) } From 40fcac1c0435cc29819ecf9551dabe6b14748cb1 Mon Sep 17 00:00:00 2001 From: Joe Elliott Date: Tue, 13 Oct 2020 16:49:37 -0400 Subject: [PATCH 2/6] Added appropriate locking -race passes Signed-off-by: Joe Elliott --- sampler_v2_test.go | 44 ++++++++++++++++++------------------- span.go | 54 ++++++++++++++++++++++++++++++---------------- span_test.go | 3 +++ tracer.go | 6 +++--- 4 files changed, 63 insertions(+), 44 deletions(-) diff --git a/sampler_v2_test.go b/sampler_v2_test.go index 66dfbeb8..037f0cda 100644 --- a/sampler_v2_test.go +++ b/sampler_v2_test.go @@ -72,16 +72,16 @@ func TestSpanRemainsWriteable(t *testing.T) { defer closer.Close() span := tracer.StartSpan("op1").(*Span) - assert.True(t, span.isWriteable(), "span is writeable when created") - assert.False(t, span.isSamplingFinalized(), "span is not finalized when created") + assert.True(t, span.context.isWriteable(), "span is writeable when created") + assert.False(t, span.context.isSamplingFinalized(), "span is not finalized when created") span.SetTag("k1", "v1") - assert.True(t, span.isWriteable(), "span is writeable after setting tags") + assert.True(t, span.context.isWriteable(), "span is writeable after setting tags") assert.Equal(t, opentracing.Tags{"k1": "v1"}, span.Tags()) span.SetOperationName("op2") - assert.False(t, span.isWriteable(), "span is not writeable after sampler returns retryable=true") - assert.True(t, span.isSamplingFinalized(), "span is finalized after sampler returns retryable=true") + assert.False(t, span.context.isWriteable(), "span is not writeable after sampler returns retryable=true") + assert.True(t, span.context.isSamplingFinalized(), "span is finalized after sampler returns retryable=true") } func TestSpanSharesSamplingStateWithChildren(t *testing.T) { @@ -89,14 +89,14 @@ func TestSpanSharesSamplingStateWithChildren(t *testing.T) { defer closer.Close() sp1 := tracer.StartSpan("op1").(*Span) - assert.False(t, sp1.isSamplingFinalized(), "span is not finalized when created") + assert.False(t, sp1.context.isSamplingFinalized(), "span is not finalized when created") sp2 := tracer.StartSpan("op2", opentracing.ChildOf(sp1.Context())).(*Span) - assert.False(t, sp2.isSamplingFinalized(), "child span is not finalized when created") + assert.False(t, sp2.context.isSamplingFinalized(), "child span is not finalized when created") sp2.SetOperationName("op3") - assert.True(t, sp2.isSamplingFinalized(), "child span is finalized after changing operation name") - assert.True(t, sp1.isSamplingFinalized(), "parent span is also finalized after child is finalized") + assert.True(t, sp2.context.isSamplingFinalized(), "child span is finalized after changing operation name") + assert.True(t, sp1.context.isSamplingFinalized(), "parent span is also finalized after child is finalized") } func TestSamplingIsFinalizedOnSamplingPriorityTag(t *testing.T) { @@ -125,10 +125,10 @@ func TestSamplingIsFinalizedOnSamplingPriorityTag(t *testing.T) { for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { span := tracer.StartSpan("op1").(*Span) - assert.False(t, span.isSamplingFinalized(), "span is not finalized when created") + assert.False(t, span.context.isSamplingFinalized(), "span is not finalized when created") ext.SamplingPriority.Set(span, tt.priority) - assert.True(t, span.isSamplingFinalized(), "span is finalized after sampling.priority tag") + assert.True(t, span.context.isSamplingFinalized(), "span is finalized after sampling.priority tag") assert.Equal(t, tt.expectedSampled, span.context.IsSampled(), "span is sampled after sampling.priority tag") assert.Equal(t, tt.expectedTags, span.Tags(), "sampling.priority tag in the span") }) @@ -149,7 +149,7 @@ func TestSamplingIsFinalizedWithV1Samplers(t *testing.T) { defer closer.Close() span := tracer.StartSpan("op1").(*Span) - assert.True(t, span.isSamplingFinalized(), "span is finalized when created with V1 sampler") + assert.True(t, span.context.isSamplingFinalized(), "span is finalized when created with V1 sampler") }) } } @@ -159,12 +159,12 @@ func TestSamplingIsNotFinalizedWhenContextIsInjected(t *testing.T) { defer closer.Close() span := tracer.StartSpan("op1").(*Span) - assert.False(t, span.isSamplingFinalized(), "span is not finalized when created") + assert.False(t, span.context.isSamplingFinalized(), "span is not finalized when created") err := tracer.Inject(span.Context(), opentracing.TextMap, opentracing.TextMapCarrier{}) require.NoError(t, err) - assert.False(t, span.isSamplingFinalized(), "span is not finalized after context is serialized") + assert.False(t, span.context.isSamplingFinalized(), "span is not finalized after context is serialized") } func TestSamplingIsFinalizedInChildSpanOfRemoteParent(t *testing.T) { @@ -174,7 +174,7 @@ func TestSamplingIsFinalizedInChildSpanOfRemoteParent(t *testing.T) { defer closer.Close() span := tracer.StartSpan("parent").(*Span) - assert.False(t, span.isSamplingFinalized(), "span is not finalized when created") + assert.False(t, span.context.isSamplingFinalized(), "span is not finalized when created") assert.Equal(t, sampled, span.context.IsSampled()) carrier := opentracing.TextMapCarrier{} @@ -184,7 +184,7 @@ func TestSamplingIsFinalizedInChildSpanOfRemoteParent(t *testing.T) { parentContext, err := tracer.Extract(opentracing.TextMap, carrier) require.NoError(t, err) childSpan := tracer.StartSpan("child", opentracing.ChildOf(parentContext)).(*Span) - assert.True(t, childSpan.isSamplingFinalized(), "child span is finalized") + assert.True(t, childSpan.context.isSamplingFinalized(), "child span is finalized") assert.Equal(t, sampled, childSpan.context.IsSampled()) }) } @@ -195,15 +195,15 @@ func TestSpanIsWriteableIfSampledOrNotFinalized(t *testing.T) { defer closer.Close() span := tracer.StartSpan("span").(*Span) - assert.False(t, span.isSamplingFinalized(), "span is not finalized when created") + assert.False(t, span.context.isSamplingFinalized(), "span is not finalized when created") assert.False(t, span.context.IsSampled(), "span is not sampled") - assert.True(t, span.isWriteable(), "span is writeable") + assert.True(t, span.context.isWriteable(), "span is writeable") tracer.(*Tracer).sampler = NewConstSampler(true) span = tracer.StartSpan("span").(*Span) - assert.True(t, span.isSamplingFinalized(), "span is finalized when created") + assert.True(t, span.context.isSamplingFinalized(), "span is finalized when created") assert.True(t, span.context.IsSampled(), "span is sampled") - assert.True(t, span.isWriteable(), "span is writeable") + assert.True(t, span.context.isWriteable(), "span is writeable") } func TestSetOperationOverridesOperationOnSampledSpan(t *testing.T) { @@ -211,14 +211,14 @@ func TestSetOperationOverridesOperationOnSampledSpan(t *testing.T) { defer closer.Close() span := tracer.StartSpan("op1").(*Span) - assert.True(t, span.isSamplingFinalized(), "span is finalized when created") + assert.True(t, span.context.isSamplingFinalized(), "span is finalized when created") assert.True(t, span.context.IsSampled(), "span is sampled") assert.Equal(t, "op1", span.OperationName()) assert.Equal(t, makeSamplerTags("const", true), span.tags) span.tags = []Tag{} // easier to check that tags are not re-added span.SetOperationName("op2") - assert.True(t, span.isSamplingFinalized(), "span is finalized when created") + assert.True(t, span.context.isSamplingFinalized(), "span is finalized when created") assert.True(t, span.context.IsSampled(), "span is sampled") assert.Equal(t, "op2", span.OperationName()) assert.Equal(t, []Tag{}, span.tags, "sampling tags are not re-added") diff --git a/span.go b/span.go index efc37067..2248f08c 100644 --- a/span.go +++ b/span.go @@ -85,8 +85,9 @@ func NewTag(key string, value interface{}) Tag { func (s *Span) SetOperationName(operationName string) opentracing.Span { s.Lock() s.operationName = operationName + ctx := s.context s.Unlock() - if !s.isSamplingFinalized() { + if !ctx.isSamplingFinalized() { decision := s.tracer.sampler.OnSetOperationName(s, operationName) s.applySamplingDecision(decision, true) } @@ -100,15 +101,22 @@ func (s *Span) SetTag(key string, value interface{}) opentracing.Span { } func (s *Span) setTagInternal(key string, value interface{}, lock bool) opentracing.Span { + var ctx SpanContext + if lock { + ctx = s.SpanContext() + } else { + ctx = s.context + } + s.observer.OnSetTag(key, value) - if key == string(ext.SamplingPriority) && !setSamplingPriority(s, value) { + if key == string(ext.SamplingPriority) && !setSamplingPriority(s, ctx, value) { return s } - if !s.isSamplingFinalized() { + if !ctx.isSamplingFinalized() { decision := s.tracer.sampler.OnSetTag(s, key, value) s.applySamplingDecision(decision, lock) } - if s.isWriteable() { + if ctx.isWriteable() { if lock { s.Lock() defer s.Unlock() @@ -340,12 +348,13 @@ func (s *Span) FinishWithOptions(options opentracing.FinishOptions) { s.observer.OnFinish(options) s.Lock() s.duration = options.FinishTime.Sub(s.startTime) + ctx := s.context s.Unlock() - if !s.isSamplingFinalized() { + if !ctx.isSamplingFinalized() { decision := s.tracer.sampler.OnFinishSpan(s) s.applySamplingDecision(decision, true) } - if s.context.IsSampled() { + if ctx.IsSampled() { s.Lock() s.fixLogsIfDropped() if len(options.LogRecords) > 0 || len(options.BulkLogData) > 0 { @@ -426,11 +435,18 @@ func (s *Span) serviceName() string { } func (s *Span) applySamplingDecision(decision SamplingDecision, lock bool) { + var ctx SpanContext + if lock { + ctx = s.SpanContext() + } else { + ctx = s.context + } + if !decision.Retryable { - s.context.samplingState.setFinal() + ctx.samplingState.setFinal() } if decision.Sample { - s.context.samplingState.setSampled() + ctx.samplingState.setSampled() if len(decision.Tags) > 0 { if lock { s.Lock() @@ -444,13 +460,13 @@ func (s *Span) applySamplingDecision(decision SamplingDecision, lock bool) { } // Span can be written to if it is sampled or the sampling decision has not been finalized. -func (s *Span) isWriteable() bool { - state := s.context.samplingState +func (s SpanContext) isWriteable() bool { + state := s.samplingState return !state.isFinal() || state.isSampled() } -func (s *Span) isSamplingFinalized() bool { - return s.context.samplingState.isFinal() +func (s SpanContext) isSamplingFinalized() bool { + return s.samplingState.isFinal() } // setSamplingPriority returns true if the flag was updated successfully, false otherwise. @@ -464,23 +480,23 @@ func (s *Span) isSamplingFinalized() bool { // // This means that doing a setSamplingPriority(span, 1) followed by setSamplingPriority(span, 0) can // leave flagDebug set -func setSamplingPriority(s *Span, value interface{}) bool { +func setSamplingPriority(s *Span, ctx SpanContext, value interface{}) bool { val, ok := value.(uint16) if !ok { return false } if val == 0 { - s.context.samplingState.unsetSampled() - s.context.samplingState.setFinal() + ctx.samplingState.unsetSampled() + ctx.samplingState.setFinal() return true } if s.tracer.options.noDebugFlagOnForcedSampling { - s.context.samplingState.setSampled() - s.context.samplingState.setFinal() + ctx.samplingState.setSampled() + ctx.samplingState.setFinal() return true } else if s.tracer.isDebugAllowed(s.operationName) { - s.context.samplingState.setDebugAndSampled() - s.context.samplingState.setFinal() + ctx.samplingState.setDebugAndSampled() + ctx.samplingState.setFinal() return true } return false diff --git a/span_test.go b/span_test.go index f4a04db1..49f9efc9 100644 --- a/span_test.go +++ b/span_test.go @@ -403,6 +403,9 @@ func TestSpanContextRaces(t *testing.T) { go accessor(func() { span.SpanContext().samplingState.setFlag(flagDebug) }) + go accessor(func() { + span.SetOperationName("test") + }) time.Sleep(100 * time.Millisecond) close(end) } diff --git a/tracer.go b/tracer.go index 477c6eae..9a43d45a 100644 --- a/tracer.go +++ b/tracer.go @@ -320,7 +320,7 @@ func (t *Tracer) startSpanWithOptions( sp.references = references sp.firstInProcess = rpcServer || sp.context.parentID == 0 - if !sp.isSamplingFinalized() { + if !sp.context.isSamplingFinalized() { decision := t.sampler.OnCreateSpan(sp) sp.applySamplingDecision(decision, false) } @@ -413,7 +413,7 @@ func (t *Tracer) newSpan() *Span { // calling client-side span, but obviously the server side span is // no longer a root span of the trace. func (t *Tracer) emitNewSpanMetrics(sp *Span, newTrace bool) { - if !sp.isSamplingFinalized() { + if !sp.context.isSamplingFinalized() { t.metrics.SpansStartedDelayedSampling.Inc(1) if newTrace { t.metrics.TracesStartedDelayedSampling.Inc(1) @@ -437,7 +437,7 @@ func (t *Tracer) emitNewSpanMetrics(sp *Span, newTrace bool) { } func (t *Tracer) reportSpan(sp *Span) { - if !sp.isSamplingFinalized() { + if !sp.context.isSamplingFinalized() { t.metrics.SpansFinishedDelayedSampling.Inc(1) } else if sp.context.IsSampled() { t.metrics.SpansFinishedSampled.Inc(1) From f6c06b9509ead5de8f2d7f3e058c074fbd2564b2 Mon Sep 17 00:00:00 2001 From: Joe Elliott Date: Tue, 13 Oct 2020 21:16:48 -0400 Subject: [PATCH 3/6] improved setSamplingPriority signature Signed-off-by: Joe Elliott --- span.go | 23 +++++++++++++---------- 1 file changed, 13 insertions(+), 10 deletions(-) diff --git a/span.go b/span.go index 2248f08c..7a32fd18 100644 --- a/span.go +++ b/span.go @@ -102,14 +102,17 @@ func (s *Span) SetTag(key string, value interface{}) opentracing.Span { func (s *Span) setTagInternal(key string, value interface{}, lock bool) opentracing.Span { var ctx SpanContext + var operationName string if lock { ctx = s.SpanContext() + operationName = s.OperationName() } else { ctx = s.context + operationName = s.operationName } s.observer.OnSetTag(key, value) - if key == string(ext.SamplingPriority) && !setSamplingPriority(s, ctx, value) { + if key == string(ext.SamplingPriority) && !setSamplingPriority(ctx.samplingState, operationName, s.tracer, value) { return s } if !ctx.isSamplingFinalized() { @@ -480,23 +483,23 @@ func (s SpanContext) isSamplingFinalized() bool { // // This means that doing a setSamplingPriority(span, 1) followed by setSamplingPriority(span, 0) can // leave flagDebug set -func setSamplingPriority(s *Span, ctx SpanContext, value interface{}) bool { +func setSamplingPriority(state *samplingState, operationName string, tracer *Tracer, value interface{}) bool { val, ok := value.(uint16) if !ok { return false } if val == 0 { - ctx.samplingState.unsetSampled() - ctx.samplingState.setFinal() + state.unsetSampled() + state.setFinal() return true } - if s.tracer.options.noDebugFlagOnForcedSampling { - ctx.samplingState.setSampled() - ctx.samplingState.setFinal() + if tracer.options.noDebugFlagOnForcedSampling { + state.setSampled() + state.setFinal() return true - } else if s.tracer.isDebugAllowed(s.operationName) { - ctx.samplingState.setDebugAndSampled() - ctx.samplingState.setFinal() + } else if tracer.isDebugAllowed(operationName) { + state.setDebugAndSampled() + state.setFinal() return true } return false From 796c3480107d69fa7c2a9d6c110045d32200c1aa Mon Sep 17 00:00:00 2001 From: Joe Elliott Date: Tue, 13 Oct 2020 21:29:23 -0400 Subject: [PATCH 4/6] updated setSamplingPriority comment Signed-off-by: Joe Elliott --- span.go | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/span.go b/span.go index 7a32fd18..9d6a460a 100644 --- a/span.go +++ b/span.go @@ -475,13 +475,13 @@ func (s SpanContext) isSamplingFinalized() bool { // setSamplingPriority returns true if the flag was updated successfully, false otherwise. // The behavior of setSamplingPriority is surprising // If noDebugFlagOnForcedSampling is set -// setSamplingPriority(span, 1) always sets only flagSampled +// setSamplingPriority(..., 1) always sets only flagSampled // If noDebugFlagOnForcedSampling is unset, and isDebugAllowed passes -// setSamplingPriority(span, 1) sets both flagSampled and flagDebug +// setSamplingPriority(..., 1) sets both flagSampled and flagDebug // However, -// setSamplingPriority(span, 0) always only resets flagSampled +// setSamplingPriority(..., 0) always only resets flagSampled // -// This means that doing a setSamplingPriority(span, 1) followed by setSamplingPriority(span, 0) can +// This means that doing a setSamplingPriority(..., 1) followed by setSamplingPriority(..., 0) can // leave flagDebug set func setSamplingPriority(state *samplingState, operationName string, tracer *Tracer, value interface{}) bool { val, ok := value.(uint16) From 75c64fecd07fd2b1b9e7324a604e23d0e0ec9b95 Mon Sep 17 00:00:00 2001 From: Joe Elliott Date: Wed, 14 Oct 2020 10:40:41 -0400 Subject: [PATCH 5/6] moved isWriteable and isSamplingFinalized to the correct file Signed-off-by: Joe Elliott --- span.go | 10 ---------- span_context.go | 10 ++++++++++ 2 files changed, 10 insertions(+), 10 deletions(-) diff --git a/span.go b/span.go index 9d6a460a..997cffdd 100644 --- a/span.go +++ b/span.go @@ -462,16 +462,6 @@ func (s *Span) applySamplingDecision(decision SamplingDecision, lock bool) { } } -// Span can be written to if it is sampled or the sampling decision has not been finalized. -func (s SpanContext) isWriteable() bool { - state := s.samplingState - return !state.isFinal() || state.isSampled() -} - -func (s SpanContext) isSamplingFinalized() bool { - return s.samplingState.isFinal() -} - // setSamplingPriority returns true if the flag was updated successfully, false otherwise. // The behavior of setSamplingPriority is surprising // If noDebugFlagOnForcedSampling is set diff --git a/span_context.go b/span_context.go index 568764a7..d3627624 100644 --- a/span_context.go +++ b/span_context.go @@ -271,6 +271,16 @@ func (c SpanContext) Flags() byte { return c.samplingState.flags() } +// Span can be written to if it is sampled or the sampling decision has not been finalized. +func (c SpanContext) isWriteable() bool { + state := c.samplingState + return !state.isFinal() || state.isSampled() +} + +func (c SpanContext) isSamplingFinalized() bool { + return c.samplingState.isFinal() +} + // NewSpanContext creates a new instance of SpanContext func NewSpanContext(traceID TraceID, spanID, parentID SpanID, sampled bool, baggage map[string]string) SpanContext { samplingState := &samplingState{} From 1be7d73fd90025bb69ea0bd283dbb2ddbfc29a6f Mon Sep 17 00:00:00 2001 From: Joe Elliott Date: Wed, 14 Oct 2020 10:48:05 -0400 Subject: [PATCH 6/6] Fixed report span and added FinishedWithOptions to race test Signed-off-by: Joe Elliott --- span_test.go | 3 +++ tracer.go | 8 +++++--- 2 files changed, 8 insertions(+), 3 deletions(-) diff --git a/span_test.go b/span_test.go index 49f9efc9..01e07275 100644 --- a/span_test.go +++ b/span_test.go @@ -406,6 +406,9 @@ func TestSpanContextRaces(t *testing.T) { go accessor(func() { span.SetOperationName("test") }) + go accessor(func() { + span.FinishWithOptions(opentracing.FinishOptions{}) + }) time.Sleep(100 * time.Millisecond) close(end) } diff --git a/tracer.go b/tracer.go index 9a43d45a..9a627bed 100644 --- a/tracer.go +++ b/tracer.go @@ -437,9 +437,11 @@ func (t *Tracer) emitNewSpanMetrics(sp *Span, newTrace bool) { } func (t *Tracer) reportSpan(sp *Span) { - if !sp.context.isSamplingFinalized() { + ctx := sp.SpanContext() + + if !ctx.isSamplingFinalized() { t.metrics.SpansFinishedDelayedSampling.Inc(1) - } else if sp.context.IsSampled() { + } else if ctx.IsSampled() { t.metrics.SpansFinishedSampled.Inc(1) } else { t.metrics.SpansFinishedNotSampled.Inc(1) @@ -448,7 +450,7 @@ func (t *Tracer) reportSpan(sp *Span) { // Note: if the reporter is processing Span asynchronously then it needs to Retain() the span, // and then Release() it when no longer needed. // Otherwise, the span may be reused for another trace and its data may be overwritten. - if sp.context.IsSampled() { + if ctx.IsSampled() { t.reporter.Report(sp) }