From be2efcfd0ade7d431aee17c6cf7a51786d46f0b0 Mon Sep 17 00:00:00 2001 From: Anton Ovchinnikov Date: Tue, 4 Jul 2023 16:34:38 +0200 Subject: [PATCH 1/3] fix(tracing): Make Span.Finish a no-op when the span is already finished --- tracing.go | 19 +++++++++++++------ tracing_test.go | 25 +++++++++++++++++++++++++ 2 files changed, 38 insertions(+), 6 deletions(-) diff --git a/tracing.go b/tracing.go index 8466bacca..1e14cc633 100644 --- a/tracing.go +++ b/tracing.go @@ -60,6 +60,8 @@ type Span struct { //nolint: maligned // prefer readability over optimal memory contexts map[string]Context // profiler instance if attached, nil otherwise. profiler transactionProfiler + // a Once instance to make sure that Finish() is only called once + finishOnce sync.Once } // TraceParentContext describes the context of a (remote) parent span. @@ -194,12 +196,8 @@ func StartSpan(ctx context.Context, operation string, options ...SpanOption) *Sp return &span } -// Finish sets the span's end time, unless already set. If the span is the root -// of a span tree, Finish sends the span tree to Sentry as a transaction. -func (s *Span) Finish() { - // TODO(tracing): maybe make Finish run at most once, such that - // (incorrectly) calling it twice never double sends to Sentry. - +// doFinish runs the actual Span.Finish() logic +func (s *Span) doFinish() { // For the timing to be correct, the profiler must be stopped before s.EndTime. var profile *profileInfo if s.profiler != nil { @@ -227,6 +225,15 @@ func (s *Span) Finish() { hub.CaptureEvent(event) } +// Finish sets the span's end time, unless already set. If the span is the root +// of a span tree, Finish sends the span tree to Sentry as a transaction. +// +// The logic is executed at most once per span, so that (incorrectly) calling it twice +// never double sends to Sentry. +func (s *Span) Finish() { + s.finishOnce.Do(s.doFinish) +} + // Context returns the context containing the span. func (s *Span) Context() context.Context { return s.ctx } diff --git a/tracing_test.go b/tracing_test.go index dc7fd9d75..0e5102e30 100644 --- a/tracing_test.go +++ b/tracing_test.go @@ -980,3 +980,28 @@ func TestAdjustingTransactionSourceBeforeSending(t *testing.T) { }) } } + +// This is a regression test for https://github.com/getsentry/sentry-go/issues/587 +// Without the "spans can be finished only once" fix, this test will fail +// when run with race detection ("-race"). +func TestSpanFinishConcurrentlyWithoutRaces(t *testing.T) { + ctx := NewTestContext(ClientOptions{ + EnableTracing: true, + TracesSampleRate: 1, + }) + transaction := StartTransaction(ctx, "op") + + go func() { + for { + transaction.Finish() + } + }() + + go func() { + for { + transaction.Finish() + } + }() + + time.Sleep(50 * time.Millisecond) +} From 364a30401a5298bea8485d72841184f5ca32b6f6 Mon Sep 17 00:00:00 2001 From: Anton Ovchinnikov Date: Tue, 4 Jul 2023 17:38:07 +0200 Subject: [PATCH 2/3] linter --- tracing.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tracing.go b/tracing.go index 1e14cc633..bf0e15d09 100644 --- a/tracing.go +++ b/tracing.go @@ -60,7 +60,7 @@ type Span struct { //nolint: maligned // prefer readability over optimal memory contexts map[string]Context // profiler instance if attached, nil otherwise. profiler transactionProfiler - // a Once instance to make sure that Finish() is only called once + // a Once instance to make sure that Finish() is only called once. finishOnce sync.Once } @@ -196,7 +196,7 @@ func StartSpan(ctx context.Context, operation string, options ...SpanOption) *Sp return &span } -// doFinish runs the actual Span.Finish() logic +// doFinish runs the actual Span.Finish() logic. func (s *Span) doFinish() { // For the timing to be correct, the profiler must be stopped before s.EndTime. var profile *profileInfo From 035bce74417da4f5d26840ad544f674bc119230a Mon Sep 17 00:00:00 2001 From: Anton Ovchinnikov Date: Wed, 5 Jul 2023 12:07:51 +0200 Subject: [PATCH 3/3] move doFinish --- tracing.go | 58 +++++++++++++++++++++++++++--------------------------- 1 file changed, 29 insertions(+), 29 deletions(-) diff --git a/tracing.go b/tracing.go index bf0e15d09..a6cf743a9 100644 --- a/tracing.go +++ b/tracing.go @@ -196,35 +196,6 @@ func StartSpan(ctx context.Context, operation string, options ...SpanOption) *Sp return &span } -// doFinish runs the actual Span.Finish() logic. -func (s *Span) doFinish() { - // For the timing to be correct, the profiler must be stopped before s.EndTime. - var profile *profileInfo - if s.profiler != nil { - profile = s.profiler.Finish(s) - } - - if s.EndTime.IsZero() { - s.EndTime = monotonicTimeSince(s.StartTime) - } - - if !s.Sampled.Bool() { - return - } - event := s.toEvent() - if event == nil { - return - } - - event.sdkMetaData.transactionProfile = profile - - // TODO(tracing): add breadcrumbs - // (see https://github.com/getsentry/sentry-python/blob/f6f3525f8812f609/sentry_sdk/tracing.py#L372) - - hub := hubFromContext(s.ctx) - hub.CaptureEvent(event) -} - // Finish sets the span's end time, unless already set. If the span is the root // of a span tree, Finish sends the span tree to Sentry as a transaction. // @@ -360,6 +331,35 @@ func (s *Span) SetDynamicSamplingContext(dsc DynamicSamplingContext) { } } +// doFinish runs the actual Span.Finish() logic. +func (s *Span) doFinish() { + // For the timing to be correct, the profiler must be stopped before s.EndTime. + var profile *profileInfo + if s.profiler != nil { + profile = s.profiler.Finish(s) + } + + if s.EndTime.IsZero() { + s.EndTime = monotonicTimeSince(s.StartTime) + } + + if !s.Sampled.Bool() { + return + } + event := s.toEvent() + if event == nil { + return + } + + event.sdkMetaData.transactionProfile = profile + + // TODO(tracing): add breadcrumbs + // (see https://github.com/getsentry/sentry-python/blob/f6f3525f8812f609/sentry_sdk/tracing.py#L372) + + hub := hubFromContext(s.ctx) + hub.CaptureEvent(event) +} + // sentryTracePattern matches either // // TRACE_ID - SPAN_ID