fix(logs): race condition in high volume logging scenarios (#4428)

Flash0ver · web-flow · commit cbd289b30720 · 2025-08-15T22:12:26.000+02:00
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -7,6 +7,7 @@
 - Experimental _Structured Logs_:
   - Remove `IDisposable` from `SentryStructuredLogger`. Disposal is intended through the owning `IHub` instance. ([#4424](https://github.com/getsentry/sentry-dotnet/pull/4424))
   - Ensure all buffered logs are sent to Sentry when the application terminates unexpectedly. ([#4425](https://github.com/getsentry/sentry-dotnet/pull/4425))
+  - `InvalidOperationException` potentially thrown during a race condition, especially in concurrent high-volume logging scenarios ([#4428](https://github.com/getsentry/sentry-dotnet/pull/4428))
 
 ### Dependencies
 
diff --git a/benchmarks/Sentry.Benchmarks/BenchmarkDotNet.Artifacts/results/Sentry.Benchmarks.StructuredLogBatchProcessorBenchmarks-report-github.md b/benchmarks/Sentry.Benchmarks/BenchmarkDotNet.Artifacts/results/Sentry.Benchmarks.StructuredLogBatchProcessorBenchmarks-report-github.md
@@ -1,18 +1,24 @@
 ```
 
-BenchmarkDotNet v0.13.12, macOS 15.5 (24F74) [Darwin 24.5.0]
+BenchmarkDotNet v0.13.12, macOS 15.6 (24G84) [Darwin 24.6.0]
 Apple M3 Pro, 1 CPU, 12 logical and 12 physical cores
 .NET SDK 9.0.301
   [Host]     : .NET 8.0.14 (8.0.1425.11118), Arm64 RyuJIT AdvSIMD
   DefaultJob : .NET 8.0.14 (8.0.1425.11118), Arm64 RyuJIT AdvSIMD
 
 
 ```
-| Method          | BatchCount | OperationsPerInvoke | Mean        | Error    | StdDev   | Gen0   | Allocated |
-|---------------- |----------- |-------------------- |------------:|---------:|---------:|-------:|----------:|
-| **EnqueueAndFlush** | **10**         | **100**                 |  **1,774.5 ns** |  **7.57 ns** |  **6.71 ns** | **0.6104** |      **5 KB** |
-| **EnqueueAndFlush** | **10**         | **200**                 |  **3,468.5 ns** | **11.16 ns** | **10.44 ns** | **1.2207** |     **10 KB** |
-| **EnqueueAndFlush** | **10**         | **1000**                | **17,259.7 ns** | **51.92 ns** | **46.02 ns** | **6.1035** |     **50 KB** |
-| **EnqueueAndFlush** | **100**        | **100**                 |    **857.5 ns** |  **4.21 ns** |  **3.73 ns** | **0.1469** |    **1.2 KB** |
-| **EnqueueAndFlush** | **100**        | **200**                 |  **1,681.4 ns** |  **1.74 ns** |  **1.63 ns** | **0.2937** |   **2.41 KB** |
-| **EnqueueAndFlush** | **100**        | **1000**                |  **8,302.2 ns** | **12.00 ns** | **10.64 ns** | **1.4648** |  **12.03 KB** |
+| Method                   | BatchCount | OperationsPerInvoke | Mean         | Error       | StdDev      | Gen0   | Allocated |
+|------------------------- |----------- |-------------------- |-------------:|------------:|------------:|-------:|----------:|
+| **EnqueueAndFlush**          | **10**         | **100**                 |   **1,793.4 ns** |    **13.75 ns** |    **12.86 ns** | **0.6104** |      **5 KB** |
+| EnqueueAndFlush_Parallel | 10         | 100                 |  18,550.8 ns |   368.24 ns |   889.34 ns | 1.1292 |   9.16 KB |
+| **EnqueueAndFlush**          | **10**         | **200**                 |   **3,679.8 ns** |    **18.65 ns** |    **16.53 ns** | **1.2207** |     **10 KB** |
+| EnqueueAndFlush_Parallel | 10         | 200                 |  41,246.4 ns |   508.07 ns |   475.25 ns | 1.7090 |  14.04 KB |
+| **EnqueueAndFlush**          | **10**         | **1000**                |  **17,239.1 ns** |    **62.50 ns** |    **58.46 ns** | **6.1035** |     **50 KB** |
+| EnqueueAndFlush_Parallel | 10         | 1000                | 192,059.3 ns |   956.92 ns |   895.11 ns | 4.3945 |  37.52 KB |
+| **EnqueueAndFlush**          | **100**        | **100**                 |     **866.7 ns** |     **1.99 ns** |     **1.77 ns** | **0.1469** |    **1.2 KB** |
+| EnqueueAndFlush_Parallel | 100        | 100                 |   6,714.8 ns |   100.75 ns |    94.24 ns | 0.5569 |   4.52 KB |
+| **EnqueueAndFlush**          | **100**        | **200**                 |   **1,714.5 ns** |     **3.20 ns** |     **3.00 ns** | **0.2937** |   **2.41 KB** |
+| EnqueueAndFlush_Parallel | 100        | 200                 |  43,842.8 ns |   860.74 ns | 1,718.99 ns | 0.9155 |   7.51 KB |
+| **EnqueueAndFlush**          | **100**        | **1000**                |   **8,537.8 ns** |     **9.80 ns** |     **9.17 ns** | **1.4648** |  **12.03 KB** |
+| EnqueueAndFlush_Parallel | 100        | 1000                | 313,421.4 ns | 6,159.27 ns | 6,846.01 ns | 1.9531 |  18.37 KB |
diff --git a/benchmarks/Sentry.Benchmarks/StructuredLogBatchProcessorBenchmarks.cs b/benchmarks/Sentry.Benchmarks/StructuredLogBatchProcessorBenchmarks.cs
@@ -1,5 +1,4 @@
 using BenchmarkDotNet.Attributes;
-using NSubstitute;
 using Sentry.Extensibility;
 using Sentry.Internal;
 
@@ -30,22 +29,10 @@ public void Setup()
         };
 
         var batchInterval = Timeout.InfiniteTimeSpan;
-
-        var clientReportRecorder = Substitute.For<IClientReportRecorder>();
-        clientReportRecorder
-            .When(static recorder => recorder.RecordDiscardedEvent(Arg.Any<DiscardReason>(), Arg.Any<DataCategory>(), Arg.Any<int>()))
-            .Throw<UnreachableException>();
-
-        var diagnosticLogger = Substitute.For<IDiagnosticLogger>();
-        diagnosticLogger
-            .When(static logger => logger.IsEnabled(Arg.Any<SentryLevel>()))
-            .Throw<UnreachableException>();
-        diagnosticLogger
-            .When(static logger => logger.Log(Arg.Any<SentryLevel>(), Arg.Any<string>(), Arg.Any<Exception>(), Arg.Any<object[]>()))
-            .Throw<UnreachableException>();
+        var clientReportRecorder = new NullClientReportRecorder();
 
         _hub = new Hub(options, DisabledHub.Instance);
-        _batchProcessor = new StructuredLogBatchProcessor(_hub, BatchCount, batchInterval, clientReportRecorder, diagnosticLogger);
+        _batchProcessor = new StructuredLogBatchProcessor(_hub, BatchCount, batchInterval, clientReportRecorder, null);
         _log = new SentryLog(DateTimeOffset.Now, SentryId.Empty, SentryLogLevel.Trace, "message");
     }
 
@@ -59,10 +46,38 @@ public void EnqueueAndFlush()
         _batchProcessor.Flush();
     }
 
+    [Benchmark]
+    public void EnqueueAndFlush_Parallel()
+    {
+        _ = Parallel.For(0, OperationsPerInvoke, (int i) =>
+        {
+            _batchProcessor.Enqueue(_log);
+        });
+        _batchProcessor.Flush();
+    }
+
     [GlobalCleanup]
     public void Cleanup()
     {
         _batchProcessor.Dispose();
         _hub.Dispose();
     }
 }
+
+file sealed class NullClientReportRecorder : IClientReportRecorder
+{
+    public void RecordDiscardedEvent(DiscardReason reason, DataCategory category, int quantity = 1)
+    {
+        // no-op
+    }
+
+    public ClientReport GenerateClientReport()
+    {
+        throw new UnreachableException();
+    }
+
+    public void Load(ClientReport report)
+    {
+        throw new UnreachableException();
+    }
+}
diff --git a/src/Sentry/Internal/StructuredLogBatchBuffer.cs b/src/Sentry/Internal/StructuredLogBatchBuffer.cs
@@ -8,6 +8,8 @@ namespace Sentry.Internal;
 /// <remarks>
 /// Must be attempted to flush via <see cref="TryEnterFlushScope"/> when either the <see cref="Capacity"/> is reached,
 /// or when the <see cref="_timeout"/> is exceeded.
+/// Utilizes a <see cref="ScopedCountdownLock"/>, basically used as an inverse <see cref="ReaderWriterLockSlim"/>,
+/// allowing multiple threads for <see cref="Add"/> or exclusive access for <see cref="FlushScope.Flush"/>.
 /// </remarks>
 [DebuggerDisplay("Name = {Name}, Capacity = {Capacity}, Additions = {_additions}, AddCount = {AddCount}, IsDisposed = {_disposed}")]
 internal sealed class StructuredLogBatchBuffer : IDisposable
diff --git a/src/Sentry/Threading/ScopedCountdownLock.cs b/src/Sentry/Threading/ScopedCountdownLock.cs
@@ -40,7 +40,7 @@ internal ScopedCountdownLock()
     internal bool IsEngaged => _isEngaged == 1;
 
     /// <summary>
-    /// No <see cref="CounterScope"/> will be entered when the <see cref="Count"/> has reached <see langword="0"/> while the lock is engaged via an active <see cref="LockScope"/>.
+    /// No <see cref="CounterScope"/> will be entered when the <see cref="Count"/> has reached <see langword="0"/>, or while the lock is engaged via an active <see cref="LockScope"/>.
     /// Check via <see cref="CounterScope.IsEntered"/> whether the underlying <see cref="CountdownEvent"/> has not been set/signaled yet.
     /// To signal the underlying <see cref="CountdownEvent"/>, ensure <see cref="CounterScope.Dispose"/> is called.
     /// </summary>
@@ -49,6 +49,11 @@ internal ScopedCountdownLock()
     /// </remarks>
     internal CounterScope TryEnterCounterScope()
     {
+        if (IsEngaged)
+        {
+            return new CounterScope();
+        }
+
         if (_event.TryAddCount(1))
         {
             return new CounterScope(this);
@@ -59,6 +64,7 @@ internal CounterScope TryEnterCounterScope()
 
     private void ExitCounterScope()
     {
+        Debug.Assert(_event.CurrentCount >= 1);
         _ = _event.Signal();
     }
 
@@ -75,7 +81,8 @@ internal LockScope TryEnterLockScope()
     {
         if (Interlocked.CompareExchange(ref _isEngaged, 1, 0) == 0)
         {
-            _ = _event.Signal(); // decrement the initial count of 1, so that the event can be set with the count reaching 0 when all 'CounterScope's have exited
+            Debug.Assert(_event.CurrentCount >= 1);
+            _ = _event.Signal(); // decrement the initial count of 1, so that the event can be set with the count reaching 0 when all entered 'CounterScope' instances have exited
             return new LockScope(this);
         }
 
@@ -84,13 +91,13 @@ internal LockScope TryEnterLockScope()
 
     private void ExitLockScope()
     {
-        if (Interlocked.CompareExchange(ref _isEngaged, 0, 1) == 1)
+        Debug.Assert(_event.IsSet);
+        _event.Reset(); // reset the signaled event to the initial count of 1, so that new 'CounterScope' instances can be entered again
+
+        if (Interlocked.CompareExchange(ref _isEngaged, 0, 1) != 1)
         {
-            _event.Reset(); // reset the signaled event to the initial count of 1, so that new `CounterScope`s can be entered again
-            return;
+            Debug.Fail("The Lock should have not been disengaged without being engaged first.");
         }
-
-        Debug.Fail("The Lock should have not been disengaged without being engaged first.");
     }
 
     /// <inheritdoc />
@@ -139,7 +146,7 @@ internal LockScope(ScopedCountdownLock lockObj)
         internal void Wait()
         {
             var lockObj = _lockObj;
-            lockObj?._event.Wait();
+            lockObj?._event.Wait(Timeout.Infinite, CancellationToken.None);
         }
 
         public void Dispose()
diff --git a/test/Sentry.Tests/Threading/ScopedCountdownLockTests.cs b/test/Sentry.Tests/Threading/ScopedCountdownLockTests.cs
@@ -79,20 +79,20 @@ public void TryEnterLockScope_IsEngaged_IsSet()
         lockTwo.Dispose();
         AssertEngaged(false, 1);
 
-        // successfully enter another CounterScope ... lock is engaged but not yet set
+        // cannot enter another CounterScope as long as the lock is already engaged by a LockScope
         var counterTwo = _lock.TryEnterCounterScope();
-        counterTwo.IsEntered.Should().BeTrue();
-        AssertEngaged(false, 2);
+        counterTwo.IsEntered.Should().BeFalse();
+        AssertEngaged(false, 1);
 
-        // exit a CounterScope ... decrement the count
+        // no-op ... CounterScope is not entered
         counterTwo.Dispose();
         AssertEngaged(false, 1);
 
         // exit last CounterScope ... count of engaged lock reaches zero ... sets the lock
         counterOne.Dispose();
         AssertEngaged(true, 0);
 
-        // cannot enter another CounterScope as long as the engaged lock is set
+        // cannot enter another CounterScope as long as the lock is engaged and set
         var counterThree = _lock.TryEnterCounterScope();
         counterThree.IsEntered.Should().BeFalse();
         AssertEngaged(true, 0);
@@ -102,11 +102,11 @@ public void TryEnterLockScope_IsEngaged_IsSet()
         // would block if the count of the engaged lock was not zero
         lockOne.Wait();
 
-        // exit the LockScope ... reset the lock
+        // exit the LockScope ... reset and disengage the lock
         lockOne.Dispose();
         AssertDisengaged(false, 0);
 
-        // can enter a CounterScope again ... the lock not set
+        // can enter a CounterScope again ... the lock is no longer set and no longer engaged
         var counterFour = _lock.TryEnterCounterScope();
         counterFour.IsEntered.Should().BeTrue();
         AssertDisengaged(false, 1);

Original file line number	Diff line number	Diff line change
`@@ -40,7 +40,7 @@ internal ScopedCountdownLock()`
`40`	`40`	`internal bool IsEngaged => _isEngaged == 1;`
`41`	`41`
`42`	`42`	`/// <summary>`
`43`		`- /// No <see cref="CounterScope"/> will be entered when the <see cref="Count"/> has reached <see langword="0"/> while the lock is engaged via an active <see cref="LockScope"/>.`
	`43`	`+ /// No <see cref="CounterScope"/> will be entered when the <see cref="Count"/> has reached <see langword="0"/>, or while the lock is engaged via an active <see cref="LockScope"/>.`
`44`	`44`	`/// Check via <see cref="CounterScope.IsEntered"/> whether the underlying <see cref="CountdownEvent"/> has not been set/signaled yet.`
`45`	`45`	`/// To signal the underlying <see cref="CountdownEvent"/>, ensure <see cref="CounterScope.Dispose"/> is called.`
`46`	`46`	`/// </summary>`
`@@ -49,6 +49,11 @@ internal ScopedCountdownLock()`
`49`	`49`	`/// </remarks>`
`50`	`50`	`internal CounterScope TryEnterCounterScope()`
`51`	`51`	`{`
	`52`	`+ if (IsEngaged)`
	`53`	`+ {`
	`54`	`+ return new CounterScope();`
	`55`	`+ }`
	`56`	`+`
`52`	`57`	`if (_event.TryAddCount(1))`
`53`	`58`	`{`
`54`	`59`	`return new CounterScope(this);`
`@@ -59,6 +64,7 @@ internal CounterScope TryEnterCounterScope()`
`59`	`64`
`60`	`65`	`private void ExitCounterScope()`
`61`	`66`	`{`
	`67`	`+ Debug.Assert(_event.CurrentCount >= 1);`
`62`	`68`	`_ = _event.Signal();`
`63`	`69`	`}`
`64`	`70`
`@@ -75,7 +81,8 @@ internal LockScope TryEnterLockScope()`
`75`	`81`	`{`
`76`	`82`	`if (Interlocked.CompareExchange(ref _isEngaged, 1, 0) == 0)`
`77`	`83`	`{`
`78`		`- _ = _event.Signal(); // decrement the initial count of 1, so that the event can be set with the count reaching 0 when all 'CounterScope's have exited`
	`84`	`+ Debug.Assert(_event.CurrentCount >= 1);`
	`85`	`+ _ = _event.Signal(); // decrement the initial count of 1, so that the event can be set with the count reaching 0 when all entered 'CounterScope' instances have exited`
`79`	`86`	`return new LockScope(this);`
`80`	`87`	`}`
`81`	`88`
`@@ -84,13 +91,13 @@ internal LockScope TryEnterLockScope()`
`84`	`91`
`85`	`92`	`private void ExitLockScope()`
`86`	`93`	`{`
`87`		`- if (Interlocked.CompareExchange(ref _isEngaged, 0, 1) == 1)`
	`94`	`+ Debug.Assert(_event.IsSet);`
	`95`	`+ _event.Reset(); // reset the signaled event to the initial count of 1, so that new 'CounterScope' instances can be entered again`
	`96`	`+`
	`97`	`+ if (Interlocked.CompareExchange(ref _isEngaged, 0, 1) != 1)`
`88`	`98`	`{`
`89`		- _event.Reset(); // reset the signaled event to the initial count of 1, so that new `CounterScope`s can be entered again
`90`		`- return;`
	`99`	`+ Debug.Fail("The Lock should have not been disengaged without being engaged first.");`
`91`	`100`	`}`
`92`		`-`
`93`		`- Debug.Fail("The Lock should have not been disengaged without being engaged first.");`
`94`	`101`	`}`
`95`	`102`
`96`	`103`	`/// <inheritdoc />`
`@@ -139,7 +146,7 @@ internal LockScope(ScopedCountdownLock lockObj)`
`139`	`146`	`internal void Wait()`
`140`	`147`	`{`
`141`	`148`	`var lockObj = _lockObj;`
`142`		`- lockObj?._event.Wait();`
	`149`	`+ lockObj?._event.Wait(Timeout.Infinite, CancellationToken.None);`
`143`	`150`	`}`
`144`	`151`
`145`	`152`	`public void Dispose()`