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

CHANGELOG.md

@@ -5,6 +5,8 @@
 ### Fixes
 
 - Crontabs now support day names (MON-SUN) and allow step values and ranges to be combined ([#4407](https://github.com/getsentry/sentry-dotnet/pull/4407))
+- Experimental _Structured Logs_:
+  - `InvalidOperationException` potentially thrown during a race condition in high volume logging scenarios ([#4428](https://github.com/getsentry/sentry-dotnet/pull/4428))
 
 ### Dependencies
 

benchmarks/Sentry.Benchmarks/BenchmarkDotNet.Artifacts/results/Sentry.Benchmarks.StructuredLogBatchProcessorBenchmarks-report-github.md

@@ -8,11 +8,17 @@ Apple M3 Pro, 1 CPU, 12 logical and 12 physical cores
 
 
 ```
-| 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      | Median       | Gen0   | Allocated |
+|------------------------- |----------- |-------------------- |-------------:|------------:|------------:|-------------:|-------:|----------:|
+| **EnqueueAndFlush**          | **10**         | **100**                 |   **1,896.0 ns** |     **6.92 ns** |     **6.13 ns** |   **1,895.0 ns** | **0.6104** |      **5 KB** |
+| EnqueueAndFlush_Parallel | 10         | 100                 |  18,372.7 ns |   362.04 ns |   731.34 ns |  18,432.1 ns | 1.1292 |   9.21 KB |
+| **EnqueueAndFlush**          | **10**         | **200**                 |   **3,683.3 ns** |    **11.97 ns** |    **10.61 ns** |   **3,682.6 ns** | **1.2207** |     **10 KB** |
+| EnqueueAndFlush_Parallel | 10         | 200                 |  41,416.1 ns |   814.20 ns | 1,360.35 ns |  40,730.6 ns | 1.7090 |  14.01 KB |
+| **EnqueueAndFlush**          | **10**         | **1000**                |  **17,336.4 ns** |    **80.76 ns** |    **75.54 ns** |  **17,324.4 ns** | **6.1035** |     **50 KB** |
+| EnqueueAndFlush_Parallel | 10         | 1000                | 188,962.0 ns | 1,311.63 ns | 1,226.90 ns | 189,209.6 ns | 4.3945 |   36.6 KB |
+| **EnqueueAndFlush**          | **100**        | **100**                 |     **863.0 ns** |     **0.88 ns** |     **0.73 ns** |     **862.8 ns** | **0.1469** |    **1.2 KB** |
+| EnqueueAndFlush_Parallel | 100        | 100                 |   6,898.0 ns |    58.37 ns |    54.60 ns |   6,898.0 ns | 0.5646 |   4.55 KB |
+| **EnqueueAndFlush**          | **100**        | **200**                 |   **1,729.4 ns** |     **4.33 ns** |     **3.84 ns** |   **1,729.1 ns** | **0.2937** |   **2.41 KB** |
+| EnqueueAndFlush_Parallel | 100        | 200                 |  34,233.3 ns |   286.48 ns |   267.97 ns |  34,238.6 ns | 0.9155 |   7.42 KB |
+| **EnqueueAndFlush**          | **100**        | **1000**                |   **8,515.8 ns** |    **21.32 ns** |    **18.90 ns** |   **8,514.8 ns** | **1.4648** |  **12.03 KB** |
+| EnqueueAndFlush_Parallel | 100        | 1000                | 317,992.9 ns | 2,076.68 ns | 1,942.53 ns | 318,190.1 ns | 1.9531 |  17.71 KB |

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();
+    }
+}

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

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()

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);