diff --git a/src/Sentry.Maui/Internal/MauiEventsBinder.cs b/src/Sentry.Maui/Internal/MauiEventsBinder.cs index c796312968..90f5b50a8b 100644 --- a/src/Sentry.Maui/Internal/MauiEventsBinder.cs +++ b/src/Sentry.Maui/Internal/MauiEventsBinder.cs @@ -420,9 +420,8 @@ internal void StartUiTransaction(string name) if (CurrentUiTx is not null) { // Idle timer will clean up any previous UI transaction, but we don't want any more child spans on it - _hub.ConfigureScope(scope => scope.ResetTransaction(CurrentUiTx)); + _hub.ConfigureScope(static (scope, tx) => scope.ResetTransaction(tx), CurrentUiTx); } - CurrentUiTx = null; var context = new TransactionContext(name, UserInteractionClickOp) { @@ -430,11 +429,10 @@ internal void StartUiTransaction(string name) }; CurrentUiTx = _hub is IHubInternal internalHub ? internalHub.StartTransaction(context, _options.AutoTransactionIdleTimeout) - // never called in practice... all our hubs implement IHubInternal : _hub.StartTransaction(context); - // Only bind to scope if there is no other transaction already there (user-created or SDK-owned navigation). - _hub.ConfigureScope(scope => scope.Transaction ??= CurrentUiTx); + // Bind to scope only if no other transaction is already there (user-installed or SDK-owned navigation). + _hub.ConfigureScope(static (scope, tx) => scope.Transaction ??= tx, CurrentUiTx); } // Application Events @@ -472,13 +470,13 @@ private void OnWindowOnStopped(object? sender, EventArgs _) if (uiTx.Spans.Count > 0) { // Only finish UI transactions with child spans. - // Childless transactions will be discarded by the idle timeout. + // Childless transactions get discarded by the idle timeout. uiTx.Finish(SpanStatus.Ok); } else { - // No child spans, so just detach from scope and let idle timeout handle it. - _hub.ConfigureScope(scope => scope.ResetTransaction(CurrentUiTx)); + // No child spans, so just detach from scope and let idle timeout handle it + _hub.ConfigureScope(static (scope, tx) => scope.ResetTransaction(tx), uiTx); } } CurrentUiTx = null; diff --git a/src/Sentry/SpanTracer.cs b/src/Sentry/SpanTracer.cs index 608e0b404c..d79cb1a41b 100644 --- a/src/Sentry/SpanTracer.cs +++ b/src/Sentry/SpanTracer.cs @@ -34,11 +34,32 @@ public sealed class SpanTracer : IBaseTracer, ISpan /// public DateTimeOffset StartTimestamp { get; internal set; } + private DateTimeOffset? _endTimestamp; + private bool _isFinished; + /// - public DateTimeOffset? EndTimestamp { get; internal set; } + public DateTimeOffset? EndTimestamp + { + get => Volatile.Read(ref _isFinished) ? _endTimestamp : null; + internal set + { + // Ordering is load-bearing: the gate-flip is release-ordered against the data write, + // so lock-free readers gating on `_isFinished` see a consistent (timestamp, finished) pair. + if (value is null) + { + Volatile.Write(ref _isFinished, false); + _endTimestamp = null; + } + else + { + _endTimestamp = value; + Volatile.Write(ref _isFinished, true); + } + } + } /// - public bool IsFinished => EndTimestamp is not null; + public bool IsFinished => Volatile.Read(ref _isFinished); // Not readonly because of deserialization internal Dictionary? InternalMeasurements { get; private set; } diff --git a/src/Sentry/TransactionTracer.cs b/src/Sentry/TransactionTracer.cs index 8f1f3954b2..b899c315cc 100644 --- a/src/Sentry/TransactionTracer.cs +++ b/src/Sentry/TransactionTracer.cs @@ -17,8 +17,14 @@ public sealed class TransactionTracer : IBaseTracer, IAutoTimeoutTracer, ITransa private readonly ISentryTimer? _idleTimer; private readonly TimeSpan? _idleTimeout; private readonly SentryStopwatch _stopwatch = SentryStopwatch.StartNew(); + + /// + /// Set exactly once inside the `_lock` at the same time as setting `_endTimestamp` and disposing the idle timer. + /// `IsFinished` makes a volatile read of `_hasFinished` (no lock required as would be necessary for the more + /// complex `_endTimestamp` struct), which is essentially why we need this separate flag. + /// private bool _hasFinished; - private readonly object _finishLock = new(); + private readonly Lock _lock = new(); private readonly Instrumenter _instrumenter = Instrumenter.Sentry; @@ -69,8 +75,24 @@ public SentryId TraceId /// public DateTimeOffset StartTimestamp { get; internal set; } + /// + /// Guard writes with `_lock` + /// + private DateTimeOffset? _endTimestamp; + /// - public DateTimeOffset? EndTimestamp { get; internal set; } + public DateTimeOffset? EndTimestamp + { + // get => _endTimestamp; + get => Volatile.Read(ref _hasFinished) ? _endTimestamp : null; + internal set + { + lock (_lock) + { + _endTimestamp = value; + } + } + } /// public string Operation @@ -183,7 +205,7 @@ public IReadOnlyList Fingerprint internal bool HasMetrics => _metricsSummary.IsValueCreated; /// - public bool IsFinished => EndTimestamp is not null; + public bool IsFinished => Volatile.Read(ref _hasFinished); internal DynamicSamplingContext? DynamicSamplingContext { get; set; } @@ -260,21 +282,9 @@ private void OnIdleTimeout() return; } - // Discard if no child spans were ever started - bool shouldDiscard; - lock (_finishLock) + if (!TryBeginFinish(fromIdleTimer: true, out var shouldDiscard)) { - if (_spans.IsEmpty && !_hasFinished) - { - _hasFinished = true; - _idleTimer?.Dispose(); - EndTimestamp = _stopwatch.CurrentDateTimeOffset; - shouldDiscard = true; - } - else - { - shouldDiscard = false; - } + return; } if (shouldDiscard) @@ -284,7 +294,8 @@ private void OnIdleTimeout() return; } - Finish(Status ?? SpanStatus.Ok); + Status ??= SpanStatus.Ok; + CompleteCapture(); } /// @@ -324,24 +335,24 @@ internal ISpan StartChild(SpanId? spanId, SpanId parentSpanId, string operation, private void AddChildSpan(SpanTracer span) { - lock (_finishLock) + lock (_lock) { - if (_spans.Count >= SpanLimit) + if (_hasFinished) { - _options?.LogDebug("Discarding child span '{0}' due to {1} span limit", SpanId, SpanLimit); + _options?.LogDebug("Discarding child span '{0}' as the trace has already finished", SpanId); span.IsSampled = false; return; } - if (_hasFinished) + if (_spans.Count >= SpanLimit) { - _options?.LogDebug("Discarding child span '{0}' as the trace has already finished", SpanId); + _options?.LogDebug("Discarding child span '{0}' due to {1} span limit", SpanId, SpanLimit); span.IsSampled = false; return; } span.IsSampled = IsSampled; - _idleTimer?.Cancel(); // Pause the idle timer while a child span is in flight + _idleTimer?.Cancel(); _spans.Add(span); _activeSpanTracker.Push(span); } @@ -350,12 +361,12 @@ private void AddChildSpan(SpanTracer span) internal void ChildSpanFinished() { // Fast path: only idle-timeout transactions need to react to child finishes. - // _idleTimeout is readonly, so this check is safe outside the lock. + // `_idleTimeout` is readonly, so this check is safe outside the lock if (!_idleTimeout.HasValue) { return; } - lock (_finishLock) + lock (_lock) { if (_hasFinished) { @@ -372,53 +383,40 @@ internal void ChildSpanFinished() private class LastActiveSpanTracker { - private readonly Lock _lock = new(); - private readonly Lazy> _trackedSpans = new(); private Stack TrackedSpans => _trackedSpans.Value; - public void Push(ISpan span) - { - lock (_lock) - { - TrackedSpans.Push(span); - } - } + public void Push(ISpan span) => TrackedSpans.Push(span); public ISpan? PeekActive() { - lock (_lock) + // Non-destructive: leave finished spans in place so SpanTracer.Unfinish() can resurrect them. + foreach (var span in TrackedSpans) { - while (TrackedSpans.Count > 0) + if (!span.IsFinished) { - // Stop tracking inactive spans - var span = TrackedSpans.Peek(); - if (!span.IsFinished) - { - return span; - } - TrackedSpans.Pop(); + return span; } - return null; } + return null; } - public void Clear() - { - lock (_lock) - { - TrackedSpans.Clear(); - } - } + public void Clear() => TrackedSpans.Clear(); } private readonly LastActiveSpanTracker _activeSpanTracker = new LastActiveSpanTracker(); /// - public ISpan? GetLastActiveSpan() => _activeSpanTracker.PeekActive(); + public ISpan? GetLastActiveSpan() + { + lock (_lock) + { + return _activeSpanTracker.PeekActive(); + } + } void IAutoTimeoutTracer.ResetIdleTimeout() { - lock (_finishLock) + lock (_lock) { if (!_idleTimeout.HasValue || _hasFinished) { @@ -428,17 +426,75 @@ void IAutoTimeoutTracer.ResetIdleTimeout() } } - private bool TryFinishOnce() + /// + /// The single atomic primitive for transitioning Running -> Finished. Returns true to + /// exactly one caller; all subsequent calls return false. The Running -> Finished flip, + /// the `EndTimestamp` write, and the timer disposal all happen inside the same critical + /// section, so no observer can ever see an inconsistent intermediate state. + /// + /// + /// True when called from the idle-timer callback. In that case we also re-check whether + /// a child span is still active (it might have been added after the timer fired but + /// before we acquired the lock); if so, the firing is stale, and we refuse to finish. + /// + /// + /// True if the transaction had no child spans and the caller (idle timer) should + /// discard rather than capture. + /// + private bool TryBeginFinish(bool fromIdleTimer, out bool shouldDiscard) { - lock (_finishLock) + shouldDiscard = false; + lock (_lock) { if (_hasFinished) { return false; } - _hasFinished = true; + + if (fromIdleTimer) + { + // Defensive re-check: if a child span arrived between the timer firing and + // us acquiring the lock, AddChildSpan's `Cancel()` may have failed to stop + // the in-flight callback. The active-span check inside the lock is the + // authoritative answer. + if (_activeSpanTracker.PeekActive() != null) + { + return false; + } + + if (_spans.IsEmpty) + { + shouldDiscard = true; + } + } + + // Compute the end timestamp inside the lock. For idle transactions, trim to + // the latest finished child span when available. (Scanning `_spans` here is + // bounded by SpanLimit and only runs once per transaction.) + DateTimeOffset endTimestamp; + if (_idleTimeout.HasValue && !shouldDiscard) + { + DateTimeOffset latest = default; + foreach (var s in _spans) + { + if (s.IsFinished && s.EndTimestamp is { } et && et > latest) + { + latest = et; + } + } + endTimestamp = latest == default ? _stopwatch.CurrentDateTimeOffset : latest; + } + else + { + endTimestamp = _endTimestamp ?? _stopwatch.CurrentDateTimeOffset; + } + + _endTimestamp = endTimestamp; _idleTimer?.Cancel(); _idleTimer?.Dispose(); + + // MUST be the last write inside the lock for all logic that depends on volatile reads to work + Volatile.Write(ref _hasFinished, true); return true; } } @@ -446,7 +502,7 @@ private bool TryFinishOnce() /// public void Finish() { - if (!TryFinishOnce()) + if (!TryBeginFinish(fromIdleTimer: false, out _)) { return; } @@ -456,28 +512,21 @@ public void Finish() { // Normally we wouldn't start transactions for Sentry requests but when instrumenting with OpenTelemetry // we are only able to determine whether it's a sentry request or not when closing a span... we leave these - // to be garbage collected and we don't want idle timers triggering on them + // to be garbage collected. The idle timer has already been disposed inside TryBeginFinish. _options?.LogDebug("Transaction '{0}' is a Sentry Request. Don't complete.", SpanId); return; } - TransactionProfiler?.Finish(); Status ??= SpanStatus.Ok; + CompleteCapture(); + } - // For idle transactions, trim end time to the last finished child span - if (_idleTimeout.HasValue) - { - var latestSpanEnd = _spans - .Where(s => s.IsFinished) - .Select(s => s.EndTimestamp) - .DefaultIfEmpty() - .Max(); - EndTimestamp = latestSpanEnd ?? _stopwatch.CurrentDateTimeOffset; - } - else - { - EndTimestamp ??= _stopwatch.CurrentDateTimeOffset; - } + /// + /// Performs non-locked work that follows a successful Running -> Finished transition + /// + private void CompleteCapture() + { + TransactionProfiler?.Finish(); _options?.LogDebug("Finished Transaction '{0}'.", SpanId); diff --git a/test/Sentry.Tests/ApiApprovalTests.Run.Net4_8.verified.txt b/test/Sentry.Tests/ApiApprovalTests.Run.Net4_8.verified.txt index f9068edea7..1fc1e68f4b 100644 --- a/test/Sentry.Tests/ApiApprovalTests.Run.Net4_8.verified.txt +++ b/test/Sentry.Tests/ApiApprovalTests.Run.Net4_8.verified.txt @@ -812,7 +812,6 @@ namespace Sentry public int MaxCacheItems { get; set; } public int MaxQueueItems { get; set; } public Sentry.Extensibility.INetworkStatusListener? NetworkStatusListener { get; set; } - public string? OrgId { get; set; } public double? ProfilesSampleRate { get; set; } public bool PropagateTraceparent { get; set; } public string? Release { get; set; } @@ -828,7 +827,6 @@ namespace Sentry public System.TimeSpan ShutdownTimeout { get; set; } public string SpotlightUrl { get; set; } public Sentry.StackTraceMode StackTraceMode { get; set; } - public bool StrictTraceContinuation { get; set; } public System.Collections.Generic.IList TagFilters { get; set; } public System.Collections.Generic.IList TraceIgnoreStatusCodes { get; set; } public System.Collections.Generic.IList TracePropagationTargets { get; set; } diff --git a/test/Sentry.Tests/TransactionTracerTests.cs b/test/Sentry.Tests/TransactionTracerTests.cs index 6aaa408e19..dc859bcca1 100644 --- a/test/Sentry.Tests/TransactionTracerTests.cs +++ b/test/Sentry.Tests/TransactionTracerTests.cs @@ -216,4 +216,37 @@ public void LastSpan_Finish_ThenTimerFires_CapturesTransaction() // Then the transaction is captured hub.Received(1).CaptureTransaction(Arg.Any()); } + + [Fact] + public void IdleTimeout_AfterUnfinishedChildSpan_DoesNotCaptureTransaction() + { + // Regression: prior to the fix, LastActiveSpanTracker.PeekActive() destructively popped + // finished spans off the stack. That created a hole when combined with SpanTracer.Unfinish() + // (used by EF for connection-pool reuse): + // + // 1. SpanTracer.Finish() sets EndTimestamp and calls Transaction.ChildSpanFinished(). + // 2. ChildSpanFinished -> PeekActive() destructively pops the now-finished span. + // 3. Stack empty -> idle timer (re)starts. + // 4. SpanTracer.Unfinish() resets EndTimestamp = null on the span -- it is logically alive + // again, but no longer in _activeSpanTracker. + // 5. PeekActive() returns null -- the idle timer fires unopposed. + // 6. TryBeginFinish sees PeekActive() == null and _spans.Count > 0, captures the transaction + // while the unfinished span is still in-flight. + // + // Fix: PeekActive is non-destructive; an unfinished span stays in the tracker and is + // re-discoverable after Unfinish(). + + // Given an auto-generated UI event transaction with a child span that is finished then unfinished + var hub = Substitute.For(); + var (transaction, timer) = CreateIdleTransaction(hub); + var span = (SpanTracer)transaction.StartChild("child"); + span.Finish(); + span.Unfinish(); + + // When the idle timer fires + timer.Fire(); + + // Then the transaction is NOT captured because the unfinished span is still tracked as active + hub.DidNotReceive().CaptureTransaction(Arg.Any()); + } }