ref: discard logs gracefully when Hub is (being) disposed

Author: Flash0ver

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

@@ -8,11 +8,11 @@ Apple M3 Pro, 1 CPU, 12 logical and 12 physical cores
 
 
 ```
-| Method          | BatchCount | OperationsPerInvoke | Mean        | Error     | StdDev    | Gen0   | Allocated |
-|---------------- |----------- |-------------------- |------------:|----------:|----------:|-------:|----------:|
-| **EnqueueAndFlush** | **10**         | **100**                 |  **1,874.9 ns** |  **33.18 ns** |  **31.04 ns** | **0.6104** |      **5 KB** |
-| **EnqueueAndFlush** | **10**         | **200**                 |  **3,770.1 ns** |  **55.49 ns** |  **51.91 ns** | **1.2207** |     **10 KB** |
-| **EnqueueAndFlush** | **10**         | **1000**                | **17,993.8 ns** | **359.21 ns** | **467.07 ns** | **6.1035** |     **50 KB** |
-| **EnqueueAndFlush** | **100**        | **100**                 |    **809.3 ns** |  **15.05 ns** |  **15.45 ns** | **0.1469** |    **1.2 KB** |
-| **EnqueueAndFlush** | **100**        | **200**                 |  **1,551.0 ns** |  **16.17 ns** |  **14.33 ns** | **0.2937** |   **2.41 KB** |
-| **EnqueueAndFlush** | **100**        | **1000**                |  **7,782.0 ns** | **123.71 ns** | **109.67 ns** | **1.4648** |  **12.03 KB** |
+| 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** |

benchmarks/Sentry.Benchmarks/StructuredLogBatchProcessorBenchmarks.cs

@@ -7,6 +7,7 @@ namespace Sentry.Benchmarks;
 
 public class StructuredLogBatchProcessorBenchmarks
 {
+    private Hub _hub;
     private StructuredLogBatchProcessor _batchProcessor;
     private SentryLog _log;
 
@@ -19,12 +20,32 @@ public class StructuredLogBatchProcessorBenchmarks
     [GlobalSetup]
     public void Setup()
     {
-        var hub = DisabledHub.Instance;
+        SentryOptions options = new()
+        {
+            Dsn = DsnSamples.ValidDsn,
+            Experimental =
+            {
+                EnableLogs = true,
+            },
+        };
+
         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>();
-        _batchProcessor = new StructuredLogBatchProcessor(hub, BatchCount, batchInterval, clientReportRecorder, diagnosticLogger);
+        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>();
 
+        _hub = new Hub(options, DisabledHub.Instance);
+        _batchProcessor = new StructuredLogBatchProcessor(_hub, BatchCount, batchInterval, clientReportRecorder, diagnosticLogger);
         _log = new SentryLog(DateTimeOffset.Now, SentryId.Empty, SentryLogLevel.Trace, "message");
     }
 
@@ -42,5 +63,6 @@ public void EnqueueAndFlush()
     public void Cleanup()
     {
         _batchProcessor.Dispose();
+        _hub.Dispose();
     }
 }

src/Sentry/Internal/DefaultSentryStructuredLogger.cs

@@ -13,6 +13,7 @@ internal sealed class DefaultSentryStructuredLogger : SentryStructuredLogger
 
     internal DefaultSentryStructuredLogger(IHub hub, SentryOptions options, ISystemClock clock, int batchCount, TimeSpan batchInterval)
     {
+        Debug.Assert(hub.IsEnabled);
         Debug.Assert(options is { Experimental.EnableLogs: true });
 
         _hub = hub;

src/Sentry/Internal/StructuredLogBatchBuffer.cs

@@ -9,7 +9,7 @@ namespace Sentry.Internal;
 /// 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.
 /// </remarks>
-[DebuggerDisplay("Name = {Name}, Capacity = {Capacity}, Additions = {_additions}, AddCount = {AddCount}")]
+[DebuggerDisplay("Name = {Name}, Capacity = {Capacity}, Additions = {_additions}, AddCount = {AddCount}, IsDisposed = {_disposed}")]
 internal sealed class StructuredLogBatchBuffer : IDisposable
 {
     private readonly SentryLog[] _array;
@@ -18,9 +18,10 @@ internal sealed class StructuredLogBatchBuffer : IDisposable
 
     private readonly Timer _timer;
     private readonly TimeSpan _timeout;
-
     private readonly Action<StructuredLogBatchBuffer> _timeoutExceededAction;
 
+    private volatile bool _disposed;
+
     /// <summary>
     /// Create a new buffer.
     /// </summary>
@@ -39,8 +40,8 @@ public StructuredLogBatchBuffer(int capacity, TimeSpan timeout, Action<Structure
 
         _timer = new Timer(OnIntervalElapsed, this, Timeout.Infinite, Timeout.Infinite);
         _timeout = timeout;
-
         _timeoutExceededAction = timeoutExceededAction;
+
         Name = name ?? "default";
     }
 
@@ -62,22 +63,25 @@ public StructuredLogBatchBuffer(int capacity, TimeSpan timeout, Action<Structure
     /// <summary>
     /// Number of <see cref="Add"/> operations in progress.
     /// </summary>
-    /// <remarks>
-    /// This property is used for debugging only.
-    /// </remarks>
     private int AddCount => _addLock.Count;
 
     /// <summary>
-    /// Attempt to atomically add one element to the buffer.
+    /// Attempt to add one element to the buffer.
+    /// Is thread-safe.
     /// </summary>
-    /// <param name="item">Element attempted to be added atomically.</param>
-    /// <returns>An <see cref="BatchBufferAddStatus"/> describing the result of the operation.</returns>
-    internal BatchBufferAddStatus Add(SentryLog item)
+    /// <param name="item">Element attempted to be added.</param>
+    /// <returns>An <see cref="StructuredLogBatchBufferAddStatus"/> describing the result of the thread-safe operation.</returns>
+    internal StructuredLogBatchBufferAddStatus Add(SentryLog item)
     {
+        if (_disposed)
+        {
+            return StructuredLogBatchBufferAddStatus.IgnoredIsDisposed;
+        }
+
         using var scope = _addLock.TryEnterCounterScope();
         if (!scope.IsEntered)
         {
-            return BatchBufferAddStatus.IgnoredIsFlushing;
+            return StructuredLogBatchBufferAddStatus.IgnoredIsFlushing;
         }
 
         var count = Interlocked.Increment(ref _additions);
@@ -86,24 +90,24 @@ internal BatchBufferAddStatus Add(SentryLog item)
         {
             EnableTimer();
             _array[count - 1] = item;
-            return BatchBufferAddStatus.AddedFirst;
+            return StructuredLogBatchBufferAddStatus.AddedFirst;
         }
 
         if (count < _array.Length)
         {
             _array[count - 1] = item;
-            return BatchBufferAddStatus.Added;
+            return StructuredLogBatchBufferAddStatus.Added;
         }
 
         if (count == _array.Length)
         {
             DisableTimer();
             _array[count - 1] = item;
-            return BatchBufferAddStatus.AddedLast;
+            return StructuredLogBatchBufferAddStatus.AddedLast;
         }
 
         Debug.Assert(count > _array.Length);
-        return BatchBufferAddStatus.IgnoredCapacityExceeded;
+        return StructuredLogBatchBufferAddStatus.IgnoredCapacityExceeded;
     }
 
     /// <summary>
@@ -114,6 +118,11 @@ internal BatchBufferAddStatus Add(SentryLog item)
     /// </remarks>
     internal FlushScope TryEnterFlushScope()
     {
+        if (_disposed)
+        {
+            return new FlushScope();
+        }
+
         var scope = _addLock.TryEnterLockScope();
         if (scope.IsEntered)
         {
@@ -132,11 +141,14 @@ private void ExitFlushScope()
     }
 
     /// <summary>
-    /// Callback when Timer has elapsed after first item has been added.
+    /// Callback when Timer has elapsed after first item has been added and buffer is not full yet.
     /// </summary>
     internal void OnIntervalElapsed(object? state)
     {
-        _timeoutExceededAction(this);
+        if (!_disposed)
+        {
+            _timeoutExceededAction(this);
+        }
     }
 
     /// <summary>
@@ -193,21 +205,20 @@ private void Clear(int length)
 
     private void EnableTimer()
     {
-        var updated = _timer.Change(_timeout, Timeout.InfiniteTimeSpan);
-        Debug.Assert(updated, "Timer was not successfully enabled.");
+        _ = _timer.Change(_timeout, Timeout.InfiniteTimeSpan);
     }
 
     private void DisableTimer()
     {
-        var updated = _timer.Change(Timeout.Infinite, Timeout.Infinite);
-        Debug.Assert(updated, "Timer was not successfully disabled.");
+        _ = _timer.Change(Timeout.Infinite, Timeout.Infinite);
     }
 
     /// <inheritdoc />
     public void Dispose()
     {
         _timer.Dispose();
         _addLock.Dispose();
+        _disposed = true;
     }
 
     private static void ThrowIfLessThanTwo(int value, string paramName)
@@ -240,7 +251,7 @@ static void ThrowNegativeOrZero(TimeSpan value, string paramName)
     /// A scope than ensures only a single <see cref="Flush"/> operation is in progress,
     /// and blocks the calling thread until all <see cref="Add"/> operations have finished.
     /// When <see cref="IsEntered"/> is <see langword="true"/>, no more <see cref="Add"/> can be started,
-    /// which will then return <see cref="BatchBufferAddStatus.IgnoredIsFlushing"/> immediately.
+    /// which will then return <see cref="StructuredLogBatchBufferAddStatus.IgnoredIsFlushing"/> immediately.
     /// </summary>
     /// <remarks>
     /// Only <see cref="Flush"/> when scope <see cref="IsEntered"/>.
@@ -287,11 +298,12 @@ public void Dispose()
     }
 }
 
-internal enum BatchBufferAddStatus : byte
+internal enum StructuredLogBatchBufferAddStatus : byte
 {
     AddedFirst,
     Added,
     AddedLast,
     IgnoredCapacityExceeded,
     IgnoredIsFlushing,
+    IgnoredIsDisposed,
 }

src/Sentry/Internal/StructuredLogBatchProcessor.cs

@@ -1,5 +1,4 @@
 using Sentry.Extensibility;
-using Sentry.Infrastructure;
 using Sentry.Protocol;
 using Sentry.Protocol.Envelopes;
 
@@ -9,11 +8,14 @@ namespace Sentry.Internal;
 /// The Batch Processor for Sentry Logs.
 /// </summary>
 /// <remarks>
-/// Used a double buffer strategy to achieve synchronous and lock-free adding.
+/// Uses a double buffer strategy to achieve synchronous and lock-free adding.
 /// Switches the active buffer either when full or timeout exceeded (after first item added).
 /// Logs are dropped when both buffers are either full or being flushed.
+/// Logs are not enqueued when the Hub is disabled (Hub is being or has been disposed).
 /// Flushing blocks the calling thread until all pending add operations have completed.
 /// <code>
+/// Implementation:
+/// - When Hub is disabled (i.e. disposed), does not enqueue log
 /// - Try to enqueue log into currently active buffer
 ///   - when currently active buffer is full, try to enqueue log into the other buffer
 ///   - when the other buffer is also full, or currently being flushed, then the log is dropped and a discarded event is recorded as a client report
@@ -52,6 +54,11 @@ public StructuredLogBatchProcessor(IHub hub, int batchCount, TimeSpan batchInter
 
     internal void Enqueue(SentryLog log)
     {
+        if (!_hub.IsEnabled)
+        {
+            return;
+        }
+
         var activeBuffer = _activeBuffer;
 
         if (!TryEnqueue(activeBuffer, log))
@@ -74,6 +81,9 @@ internal void Flush()
     /// <summary>
     /// Forces invocation of a Timeout of the active buffer.
     /// </summary>
+    /// <remarks>
+    /// Intended for Testing only.
+    /// </remarks>
     internal void OnIntervalElapsed()
     {
         var activeBuffer = _activeBuffer;
@@ -84,14 +94,14 @@ private bool TryEnqueue(StructuredLogBatchBuffer buffer, SentryLog log)
     {
         var status = buffer.Add(log);
 
-        if (status is BatchBufferAddStatus.AddedLast)
+        if (status is StructuredLogBatchBufferAddStatus.AddedLast)
         {
             SwapActiveBuffer(buffer);
             CaptureLogs(buffer);
             return true;
         }
 
-        return status is BatchBufferAddStatus.AddedFirst or BatchBufferAddStatus.Added;
+        return status is StructuredLogBatchBufferAddStatus.AddedFirst or StructuredLogBatchBufferAddStatus.Added;
     }
 
     private void SwapActiveBuffer(StructuredLogBatchBuffer currentActiveBuffer)

src/Sentry/Threading/ScopedCountdownLock.cs

@@ -44,6 +44,9 @@ internal ScopedCountdownLock()
     /// 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>
+    /// <remarks>
+    /// Must be disposed to exit.
+    /// </remarks>
     internal CounterScope TryEnterCounterScope()
     {
         if (_event.TryAddCount(1))
@@ -60,11 +63,14 @@ private void ExitCounterScope()
     }
 
     /// <summary>
-    /// When successful, the lock <see cref="IsEngaged"/>, <see cref="Count"/> can reach <see langword="0"/> when no <see cref="CounterScope"/> is active, and the event be set/signaled.
+    /// When successful, the lock <see cref="IsEngaged"/>, <see cref="Count"/> can reach <see langword="0"/> when no <see cref="CounterScope"/> is active, and the event can be set/signaled.
     /// Check via <see cref="LockScope.IsEntered"/> whether the Lock <see cref="IsEngaged"/>.
     /// Use <see cref="LockScope.Wait"/> to block until every active <see cref="CounterScope"/> has exited before performing the locked operation.
     /// After the locked operation has completed, disengage the Lock via <see cref="LockScope.Dispose"/>.
     /// </summary>
+    /// <remarks>
+    /// Must be disposed to exit.
+    /// </remarks>
     internal LockScope TryEnterLockScope()
     {
         if (Interlocked.CompareExchange(ref _isEngaged, 1, 0) == 0)

test/Sentry.Testing/InMemoryDiagnosticLogger.cs

@@ -11,6 +11,16 @@ public void Log(SentryLevel logLevel, string message, Exception exception = null
         Entries.Enqueue(new Entry(logLevel, message, exception, args));
     }
 
+    internal Entry Dequeue()
+    {
+        if (Entries.TryDequeue(out var entry))
+        {
+            return entry;
+        }
+
+        throw new InvalidOperationException("Queue is empty.");
+    }
+
     public record Entry(
         SentryLevel Level,
         string Message,