From d24d165371f8e3a7981f7fb0d79e4945e2cbe36b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Thu, 26 Jun 2025 19:21:51 +0200 Subject: [PATCH 01/29] feat: add Batch Processor for Logs --- src/Sentry/Internal/BatchBuffer.cs | 62 +++++++++++++ src/Sentry/Internal/BatchProcessor.cs | 88 +++++++++++++++++++ .../Internal/DefaultSentryStructuredLogger.cs | 35 +++++++- src/Sentry/Internal/Hub.cs | 2 + src/Sentry/Protocol/Envelopes/Envelope.cs | 7 +- src/Sentry/Protocol/Envelopes/EnvelopeItem.cs | 7 +- src/Sentry/Protocol/StructuredLog.cs | 29 ++++++ src/Sentry/SentryLog.cs | 11 +-- src/Sentry/SentryOptions.cs | 17 ++++ src/Sentry/SentryStructuredLogger.cs | 17 +++- ...piApprovalTests.Run.DotNet8_0.verified.txt | 9 +- ...piApprovalTests.Run.DotNet9_0.verified.txt | 9 +- .../ApiApprovalTests.Run.Net4_8.verified.txt | 9 +- test/Sentry.Tests/HubTests.cs | 1 + test/Sentry.Tests/SentryLogTests.cs | 12 +-- .../SentryStructuredLoggerTests.cs | 12 ++- 16 files changed, 287 insertions(+), 40 deletions(-) create mode 100644 src/Sentry/Internal/BatchBuffer.cs create mode 100644 src/Sentry/Internal/BatchProcessor.cs create mode 100644 src/Sentry/Protocol/StructuredLog.cs diff --git a/src/Sentry/Internal/BatchBuffer.cs b/src/Sentry/Internal/BatchBuffer.cs new file mode 100644 index 0000000000..80f31277b5 --- /dev/null +++ b/src/Sentry/Internal/BatchBuffer.cs @@ -0,0 +1,62 @@ +namespace Sentry.Internal; + +internal sealed class BatchBuffer +{ + private readonly T[] _array; + private int _count; + + public BatchBuffer(int capacity) + { + _array = new T[capacity]; + _count = 0; + } + + internal int Count => _count; + internal int Capacity => _array.Length; + internal bool IsEmpty => _count == 0 && _array.Length != 0; + internal bool IsFull => _count == _array.Length; + + internal bool TryAdd(T item) + { + var count = Interlocked.Increment(ref _count); + + if (count <= _array.Length) + { + _array[count - 1] = item; + return true; + } + + return false; + } + + internal T[] ToArray() + { + if (_count == 0) + { + return Array.Empty(); + } + + var array = new T[_count]; + Array.Copy(_array, array, _count); + return array; + } + + internal void Clear() + { + if (_count == 0) + { + return; + } + + var count = _count; + _count = 0; + Array.Clear(_array, 0, count); + } + + internal T[] ToArrayAndClear() + { + var array = ToArray(); + Clear(); + return array; + } +} diff --git a/src/Sentry/Internal/BatchProcessor.cs b/src/Sentry/Internal/BatchProcessor.cs new file mode 100644 index 0000000000..2586496c3f --- /dev/null +++ b/src/Sentry/Internal/BatchProcessor.cs @@ -0,0 +1,88 @@ +using System.Timers; +using Sentry.Protocol.Envelopes; + +#if NET9_0_OR_GREATER +using Lock = System.Threading.Lock; +#else +using Lock = object; +#endif + +namespace Sentry.Internal; + +internal sealed class BatchProcessor : IDisposable +{ + private readonly IHub _hub; + private readonly System.Timers.Timer _timer; + private readonly BatchBuffer _logs; + private readonly Lock _lock; + + private DateTime _lastFlush = DateTime.MinValue; + + public BatchProcessor(IHub hub, int batchCount, TimeSpan batchInterval) + { + _hub = hub; + + _timer = new System.Timers.Timer(batchInterval.TotalMilliseconds) + { + AutoReset = false, + Enabled = false, + }; + _timer.Elapsed += IntervalElapsed; + + _logs = new BatchBuffer(batchCount); + _lock = new Lock(); + } + + internal void Enqueue(SentryLog log) + { + lock (_lock) + { + EnqueueCore(log); + } + } + + private void EnqueueCore(SentryLog log) + { + var empty = _logs.IsEmpty; + var added = _logs.TryAdd(log); + Debug.Assert(added, $"Since we currently have no lock-free scenario, it's unexpected to exceed the {nameof(BatchBuffer)}'s capacity."); + + if (empty && !_logs.IsFull) + { + _timer.Enabled = true; + } + else if (_logs.IsFull) + { + _timer.Enabled = false; + Flush(); + } + } + + private void Flush() + { + _lastFlush = DateTime.UtcNow; + + var logs = _logs.ToArrayAndClear(); + _ = _hub.CaptureEnvelope(Envelope.FromLogs(logs)); + } + + private void IntervalElapsed(object? sender, ElapsedEventArgs e) + { + _timer.Enabled = false; + + lock (_lock) + { + if (!_logs.IsEmpty && e.SignalTime > _lastFlush) + { + Flush(); + } + } + } + + public void Dispose() + { + _timer.Enabled = false; + _timer.Elapsed -= IntervalElapsed; + _timer.Dispose(); + } +} diff --git a/src/Sentry/Internal/DefaultSentryStructuredLogger.cs b/src/Sentry/Internal/DefaultSentryStructuredLogger.cs index 5f6bd64064..95b8e40a80 100644 --- a/src/Sentry/Internal/DefaultSentryStructuredLogger.cs +++ b/src/Sentry/Internal/DefaultSentryStructuredLogger.cs @@ -1,6 +1,5 @@ using Sentry.Extensibility; using Sentry.Infrastructure; -using Sentry.Protocol.Envelopes; namespace Sentry.Internal; @@ -10,6 +9,8 @@ internal sealed class DefaultSentryStructuredLogger : SentryStructuredLogger private readonly SentryOptions _options; private readonly ISystemClock _clock; + private readonly BatchProcessor _batchProcessor; + internal DefaultSentryStructuredLogger(IHub hub, SentryOptions options, ISystemClock clock) { Debug.Assert(options is { Experimental.EnableLogs: true }); @@ -17,6 +18,24 @@ internal DefaultSentryStructuredLogger(IHub hub, SentryOptions options, ISystemC _hub = hub; _options = options; _clock = clock; + + _batchProcessor = new BatchProcessor(hub, ClampBatchCount(options.Experimental.InternalBatchSize), ClampBatchInterval(options.Experimental.InternalBatchTimeout)); + } + + private static int ClampBatchCount(int batchCount) + { + return batchCount <= 0 + ? 1 + : batchCount > 1_000_000 + ? 1_000_000 + : batchCount; + } + + private static TimeSpan ClampBatchInterval(TimeSpan batchInterval) + { + return batchInterval.TotalMilliseconds is <= 0 or > int.MaxValue + ? TimeSpan.FromMilliseconds(int.MaxValue) + : batchInterval; } private protected override void CaptureLog(SentryLogLevel level, string template, object[]? parameters, Action? configureLog) @@ -71,9 +90,17 @@ private protected override void CaptureLog(SentryLogLevel level, string template if (configuredLog is not null) { - //TODO: enqueue in Batch-Processor / Background-Worker - // see https://github.com/getsentry/sentry-dotnet/issues/4132 - _ = _hub.CaptureEnvelope(Envelope.FromLog(configuredLog)); + _batchProcessor.Enqueue(configuredLog); } } + + protected override void Dispose(bool disposing) + { + if (disposing) + { + _batchProcessor.Dispose(); + } + + base.Dispose(disposing); + } } diff --git a/src/Sentry/Internal/Hub.cs b/src/Sentry/Internal/Hub.cs index 3efd71d896..b924e9872b 100644 --- a/src/Sentry/Internal/Hub.cs +++ b/src/Sentry/Internal/Hub.cs @@ -778,6 +778,8 @@ public void Dispose() _memoryMonitor?.Dispose(); #endif + Logger.Dispose(); + try { CurrentClient.FlushAsync(_options.ShutdownTimeout).ConfigureAwait(false).GetAwaiter().GetResult(); diff --git a/src/Sentry/Protocol/Envelopes/Envelope.cs b/src/Sentry/Protocol/Envelopes/Envelope.cs index d9ac774a60..bc169c52e2 100644 --- a/src/Sentry/Protocol/Envelopes/Envelope.cs +++ b/src/Sentry/Protocol/Envelopes/Envelope.cs @@ -445,17 +445,14 @@ internal static Envelope FromClientReport(ClientReport clientReport) return new Envelope(header, items); } - // TODO: This is temporary. We don't expect single log messages to become an envelope by themselves since batching is needed [Experimental(DiagnosticId.ExperimentalFeature)] - internal static Envelope FromLog(SentryLog log) + internal static Envelope FromLogs(SentryLog[] logs) { - //TODO: allow batching Sentry logs - //see https://github.com/getsentry/sentry-dotnet/issues/4132 var header = DefaultHeader; var items = new[] { - EnvelopeItem.FromLog(log) + EnvelopeItem.FromLogs(logs), }; return new Envelope(header, items); diff --git a/src/Sentry/Protocol/Envelopes/EnvelopeItem.cs b/src/Sentry/Protocol/Envelopes/EnvelopeItem.cs index 7da1c7b53a..b33bd63601 100644 --- a/src/Sentry/Protocol/Envelopes/EnvelopeItem.cs +++ b/src/Sentry/Protocol/Envelopes/EnvelopeItem.cs @@ -372,17 +372,16 @@ internal static EnvelopeItem FromClientReport(ClientReport report) } [Experimental(Infrastructure.DiagnosticId.ExperimentalFeature)] - internal static EnvelopeItem FromLog(SentryLog log) + internal static EnvelopeItem FromLogs(SentryLog[] logs) { - //TODO: allow batching Sentry logs - //see https://github.com/getsentry/sentry-dotnet/issues/4132 var header = new Dictionary(3, StringComparer.Ordinal) { [TypeKey] = TypeValueLog, - ["item_count"] = 1, + ["item_count"] = logs.Length, ["content_type"] = "application/vnd.sentry.items.log+json", }; + var log = new StructuredLog(logs); return new EnvelopeItem(header, new JsonSerializable(log)); } diff --git a/src/Sentry/Protocol/StructuredLog.cs b/src/Sentry/Protocol/StructuredLog.cs new file mode 100644 index 0000000000..07bb947372 --- /dev/null +++ b/src/Sentry/Protocol/StructuredLog.cs @@ -0,0 +1,29 @@ +using Sentry.Extensibility; + +namespace Sentry.Protocol; + +internal sealed class StructuredLog : ISentryJsonSerializable +{ + private readonly SentryLog[] _items; + + public StructuredLog(SentryLog[] logs) + { + _items = logs; + } + + public ReadOnlySpan Items => _items; + + public void WriteTo(Utf8JsonWriter writer, IDiagnosticLogger? logger) + { + writer.WriteStartObject(); + writer.WriteStartArray("items"); + + foreach (var log in _items) + { + log.WriteTo(writer, logger); + } + + writer.WriteEndArray(); + writer.WriteEndObject(); + } +} diff --git a/src/Sentry/SentryLog.cs b/src/Sentry/SentryLog.cs index 840bca9967..dab0813c2e 100644 --- a/src/Sentry/SentryLog.cs +++ b/src/Sentry/SentryLog.cs @@ -9,7 +9,7 @@ namespace Sentry; /// This API is experimental and it may change in the future. /// [Experimental(DiagnosticId.ExperimentalFeature)] -public sealed class SentryLog : ISentryJsonSerializable +public sealed class SentryLog { private readonly Dictionary _attributes; @@ -188,12 +188,9 @@ internal void SetDefaultAttributes(SentryOptions options, SdkVersion sdk) } } - /// - public void WriteTo(Utf8JsonWriter writer, IDiagnosticLogger? logger) + internal void WriteTo(Utf8JsonWriter writer, IDiagnosticLogger? logger) { writer.WriteStartObject(); - writer.WriteStartArray("items"); - writer.WriteStartObject(); writer.WriteNumber("timestamp", Timestamp.ToUnixTimeSeconds()); @@ -241,10 +238,8 @@ public void WriteTo(Utf8JsonWriter writer, IDiagnosticLogger? logger) writer.WriteEndObject(); } - writer.WriteEndObject(); + writer.WriteEndObject(); // attributes writer.WriteEndObject(); - writer.WriteEndArray(); - writer.WriteEndObject(); } } diff --git a/src/Sentry/SentryOptions.cs b/src/Sentry/SentryOptions.cs index c64bd6a288..8c1d9e0be0 100644 --- a/src/Sentry/SentryOptions.cs +++ b/src/Sentry/SentryOptions.cs @@ -1897,5 +1897,22 @@ public void SetBeforeSendLog(Func beforeSendLog) { _beforeSendLog = beforeSendLog; } + + /// + /// This API will be removed in the future. + /// + /// + /// Threshold of items in the buffer when sending all items, regardless of . + /// + public int InternalBatchSize { get; set; } = 100; + + /// + /// This API will be removed in the future. + /// + /// + /// Time after which all items in the buffer are sent, regardless of . + /// Must not exceed 30 seconds. + /// + public TimeSpan InternalBatchTimeout { get; set; } = TimeSpan.FromSeconds(5); } } diff --git a/src/Sentry/SentryStructuredLogger.cs b/src/Sentry/SentryStructuredLogger.cs index f61f9e74da..e63566c3b8 100644 --- a/src/Sentry/SentryStructuredLogger.cs +++ b/src/Sentry/SentryStructuredLogger.cs @@ -8,7 +8,7 @@ namespace Sentry; /// This API is experimental and it may change in the future. /// [Experimental(DiagnosticId.ExperimentalFeature)] -public abstract class SentryStructuredLogger +public abstract class SentryStructuredLogger : IDisposable { internal static SentryStructuredLogger Create(IHub hub, SentryOptions options, ISystemClock clock) { @@ -100,4 +100,19 @@ public void LogFatal(string template, object[]? parameters = null, Action + public void Dispose() + { + Dispose(true); + GC.SuppressFinalize(this); + } + + /// + /// Override in inherited types to clean up managed and unmanaged resources. + /// + /// Invoked from when ; Invoked from Finalize when . + protected virtual void Dispose(bool disposing) + { + } } diff --git a/test/Sentry.Tests/ApiApprovalTests.Run.DotNet8_0.verified.txt b/test/Sentry.Tests/ApiApprovalTests.Run.DotNet8_0.verified.txt index 691f760b3a..cf7ee306e7 100644 --- a/test/Sentry.Tests/ApiApprovalTests.Run.DotNet8_0.verified.txt +++ b/test/Sentry.Tests/ApiApprovalTests.Run.DotNet8_0.verified.txt @@ -637,7 +637,7 @@ namespace Sentry } [System.Diagnostics.CodeAnalysis.Experimental("SENTRY0001")] [System.Runtime.CompilerServices.RequiredMember] - public sealed class SentryLog : Sentry.ISentryJsonSerializable + public sealed class SentryLog { [System.Diagnostics.CodeAnalysis.Experimental("SENTRY0001")] [System.Runtime.CompilerServices.RequiredMember] @@ -661,7 +661,6 @@ namespace Sentry public void SetAttribute(string key, object value) { } [System.Diagnostics.CodeAnalysis.Experimental("SENTRY0001")] public bool TryGetAttribute(string key, [System.Diagnostics.CodeAnalysis.NotNullWhen(true)] out object? value) { } - public void WriteTo(System.Text.Json.Utf8JsonWriter writer, Sentry.Extensibility.IDiagnosticLogger? logger) { } } [System.Diagnostics.CodeAnalysis.Experimental("SENTRY0001")] public enum SentryLogLevel @@ -834,6 +833,8 @@ namespace Sentry public sealed class SentryExperimentalOptions { public bool EnableLogs { get; set; } + public int InternalBatchSize { get; set; } + public System.TimeSpan InternalBatchTimeout { get; set; } public void SetBeforeSendLog(System.Func beforeSendLog) { } } } @@ -1010,8 +1011,10 @@ namespace Sentry public static Sentry.SentryStackTrace FromJson(System.Text.Json.JsonElement json) { } } [System.Diagnostics.CodeAnalysis.Experimental("SENTRY0001")] - public abstract class SentryStructuredLogger + public abstract class SentryStructuredLogger : System.IDisposable { + public void Dispose() { } + protected virtual void Dispose(bool disposing) { } [System.Diagnostics.CodeAnalysis.Experimental("SENTRY0001")] public void LogDebug(string template, object[]? parameters = null, System.Action? configureLog = null) { } [System.Diagnostics.CodeAnalysis.Experimental("SENTRY0001")] diff --git a/test/Sentry.Tests/ApiApprovalTests.Run.DotNet9_0.verified.txt b/test/Sentry.Tests/ApiApprovalTests.Run.DotNet9_0.verified.txt index 691f760b3a..cf7ee306e7 100644 --- a/test/Sentry.Tests/ApiApprovalTests.Run.DotNet9_0.verified.txt +++ b/test/Sentry.Tests/ApiApprovalTests.Run.DotNet9_0.verified.txt @@ -637,7 +637,7 @@ namespace Sentry } [System.Diagnostics.CodeAnalysis.Experimental("SENTRY0001")] [System.Runtime.CompilerServices.RequiredMember] - public sealed class SentryLog : Sentry.ISentryJsonSerializable + public sealed class SentryLog { [System.Diagnostics.CodeAnalysis.Experimental("SENTRY0001")] [System.Runtime.CompilerServices.RequiredMember] @@ -661,7 +661,6 @@ namespace Sentry public void SetAttribute(string key, object value) { } [System.Diagnostics.CodeAnalysis.Experimental("SENTRY0001")] public bool TryGetAttribute(string key, [System.Diagnostics.CodeAnalysis.NotNullWhen(true)] out object? value) { } - public void WriteTo(System.Text.Json.Utf8JsonWriter writer, Sentry.Extensibility.IDiagnosticLogger? logger) { } } [System.Diagnostics.CodeAnalysis.Experimental("SENTRY0001")] public enum SentryLogLevel @@ -834,6 +833,8 @@ namespace Sentry public sealed class SentryExperimentalOptions { public bool EnableLogs { get; set; } + public int InternalBatchSize { get; set; } + public System.TimeSpan InternalBatchTimeout { get; set; } public void SetBeforeSendLog(System.Func beforeSendLog) { } } } @@ -1010,8 +1011,10 @@ namespace Sentry public static Sentry.SentryStackTrace FromJson(System.Text.Json.JsonElement json) { } } [System.Diagnostics.CodeAnalysis.Experimental("SENTRY0001")] - public abstract class SentryStructuredLogger + public abstract class SentryStructuredLogger : System.IDisposable { + public void Dispose() { } + protected virtual void Dispose(bool disposing) { } [System.Diagnostics.CodeAnalysis.Experimental("SENTRY0001")] public void LogDebug(string template, object[]? parameters = null, System.Action? configureLog = null) { } [System.Diagnostics.CodeAnalysis.Experimental("SENTRY0001")] diff --git a/test/Sentry.Tests/ApiApprovalTests.Run.Net4_8.verified.txt b/test/Sentry.Tests/ApiApprovalTests.Run.Net4_8.verified.txt index 5cb582e2d0..084f75cfe5 100644 --- a/test/Sentry.Tests/ApiApprovalTests.Run.Net4_8.verified.txt +++ b/test/Sentry.Tests/ApiApprovalTests.Run.Net4_8.verified.txt @@ -622,7 +622,7 @@ namespace Sentry [System.Runtime.Serialization.EnumMember(Value="fatal")] Fatal = 4, } - public sealed class SentryLog : Sentry.ISentryJsonSerializable + public sealed class SentryLog { public Sentry.SentryLogLevel Level { get; init; } public string Message { get; init; } @@ -633,7 +633,6 @@ namespace Sentry public Sentry.SentryId TraceId { get; init; } public void SetAttribute(string key, object value) { } public bool TryGetAttribute(string key, [System.Diagnostics.CodeAnalysis.NotNullWhen(true)] out object? value) { } - public void WriteTo(System.Text.Json.Utf8JsonWriter writer, Sentry.Extensibility.IDiagnosticLogger? logger) { } } public enum SentryLogLevel { @@ -796,6 +795,8 @@ namespace Sentry public sealed class SentryExperimentalOptions { public bool EnableLogs { get; set; } + public int InternalBatchSize { get; set; } + public System.TimeSpan InternalBatchTimeout { get; set; } public void SetBeforeSendLog(System.Func beforeSendLog) { } } } @@ -970,8 +971,10 @@ namespace Sentry public void WriteTo(System.Text.Json.Utf8JsonWriter writer, Sentry.Extensibility.IDiagnosticLogger? logger) { } public static Sentry.SentryStackTrace FromJson(System.Text.Json.JsonElement json) { } } - public abstract class SentryStructuredLogger + public abstract class SentryStructuredLogger : System.IDisposable { + public void Dispose() { } + protected virtual void Dispose(bool disposing) { } public void LogDebug(string template, object[]? parameters = null, System.Action? configureLog = null) { } public void LogError(string template, object[]? parameters = null, System.Action? configureLog = null) { } public void LogFatal(string template, object[]? parameters = null, System.Action? configureLog = null) { } diff --git a/test/Sentry.Tests/HubTests.cs b/test/Sentry.Tests/HubTests.cs index 51197c307d..1da106b42d 100644 --- a/test/Sentry.Tests/HubTests.cs +++ b/test/Sentry.Tests/HubTests.cs @@ -1444,6 +1444,7 @@ public void Logger_IsEnabled_DoesCaptureLog() { // Arrange _fixture.Options.Experimental.EnableLogs = true; + _fixture.Options.Experimental.InternalBatchSize = 1; var hub = _fixture.GetSut(); // Act diff --git a/test/Sentry.Tests/SentryLogTests.cs b/test/Sentry.Tests/SentryLogTests.cs index 4638d5896f..c97f99b137 100644 --- a/test/Sentry.Tests/SentryLogTests.cs +++ b/test/Sentry.Tests/SentryLogTests.cs @@ -78,7 +78,7 @@ public void WriteTo_Envelope_MinimalSerializedSentryLog() var log = new SentryLog(Timestamp, TraceId, SentryLogLevel.Trace, "message"); log.SetDefaultAttributes(options, new SdkVersion()); - var envelope = Envelope.FromLog(log); + var envelope = Envelope.FromLogs([log]); using var stream = new MemoryStream(); envelope.Serialize(stream, _output, Clock); @@ -156,7 +156,7 @@ public void WriteTo_EnvelopeItem_MaximalSerializedSentryLog() log.SetAttribute("double-attribute", 4.4); log.SetDefaultAttributes(options, new SdkVersion { Name = "Sentry.Test.SDK", Version = "1.2.3-test+Sentry" }); - var envelope = EnvelopeItem.FromLog(log); + var envelope = EnvelopeItem.FromLogs([log]); using var stream = new MemoryStream(); envelope.Serialize(stream, _output); @@ -286,9 +286,7 @@ public void WriteTo_MessageParameters_AsAttributes() writer.Flush(); var document = JsonDocument.Parse(bufferWriter.WrittenMemory); - var items = document.RootElement.GetProperty("items"); - items.GetArrayLength().Should().Be(1); - var attributes = items[0].GetProperty("attributes"); + var attributes = document.RootElement.GetProperty("attributes"); Assert.Collection(attributes.EnumerateObject().ToArray(), property => property.AssertAttributeInteger("sentry.message.parameter.0", json => json.GetSByte(), sbyte.MinValue), property => property.AssertAttributeInteger("sentry.message.parameter.1", json => json.GetByte(), byte.MaxValue), @@ -348,9 +346,7 @@ public void WriteTo_Attributes_AsJson() writer.Flush(); var document = JsonDocument.Parse(bufferWriter.WrittenMemory); - var items = document.RootElement.GetProperty("items"); - items.GetArrayLength().Should().Be(1); - var attributes = items[0].GetProperty("attributes"); + var attributes = document.RootElement.GetProperty("attributes"); Assert.Collection(attributes.EnumerateObject().ToArray(), property => property.AssertAttributeInteger("sbyte", json => json.GetSByte(), sbyte.MinValue), property => property.AssertAttributeInteger("byte", json => json.GetByte(), byte.MaxValue), diff --git a/test/Sentry.Tests/SentryStructuredLoggerTests.cs b/test/Sentry.Tests/SentryStructuredLoggerTests.cs index 429fa503b5..e5fd580e7d 100644 --- a/test/Sentry.Tests/SentryStructuredLoggerTests.cs +++ b/test/Sentry.Tests/SentryStructuredLoggerTests.cs @@ -84,6 +84,7 @@ public void Create_Disabled_CachedDisabledInstance() public void Log_Enabled_CapturesEnvelope(SentryLogLevel level) { _fixture.Options.Experimental.EnableLogs = true; + _fixture.Options.Experimental.InternalBatchSize = 1; var logger = _fixture.GetSut(); Envelope envelope = null!; @@ -117,6 +118,7 @@ public void Log_WithoutTraceHeader_CapturesEnvelope() { _fixture.WithoutTraceHeader(); _fixture.Options.Experimental.EnableLogs = true; + _fixture.Options.Experimental.InternalBatchSize = 1; var logger = _fixture.GetSut(); Envelope envelope = null!; @@ -135,6 +137,7 @@ public void Log_WithBeforeSendLog_InvokesCallback() SentryLog configuredLog = null!; _fixture.Options.Experimental.EnableLogs = true; + _fixture.Options.Experimental.InternalBatchSize = 1; _fixture.Options.Experimental.SetBeforeSendLog((SentryLog log) => { invocations++; @@ -231,7 +234,7 @@ public static void AssertEnvelope(this Envelope envelope, SentryStructuredLogger envelope.Header.Should().ContainSingle().Which.Key.Should().Be("sdk"); var item = envelope.Items.Should().ContainSingle().Which; - var log = item.Payload.Should().BeOfType().Which.Source.Should().BeOfType().Which; + var log = item.Payload.Should().BeOfType().Which.Source.Should().BeOfType().Which; AssertLog(log, fixture, level); Assert.Collection(item.Header, @@ -240,6 +243,13 @@ public static void AssertEnvelope(this Envelope envelope, SentryStructuredLogger element => Assert.Equal(CreateHeader("content_type", "application/vnd.sentry.items.log+json"), element)); } + public static void AssertLog(this StructuredLog log, SentryStructuredLoggerTests.Fixture fixture, SentryLogLevel level) + { + var items = log.Items; + items.Length.Should().Be(1); + AssertLog(items[0], fixture, level); + } + public static void AssertLog(this SentryLog log, SentryStructuredLoggerTests.Fixture fixture, SentryLogLevel level) { log.Timestamp.Should().Be(fixture.Clock.GetUtcNow()); From aad05997036ff11c801b07b9f0e3a74d85f808cd Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Thu, 26 Jun 2025 22:52:12 +0200 Subject: [PATCH 02/29] test: Batch Processor for Logs --- src/Sentry/Internal/BatchBuffer.cs | 22 ++- src/Sentry/Internal/BatchProcessor.cs | 16 +- src/Sentry/Internal/BatchProcessorTimer.cs | 61 ++++++ src/Sentry/Protocol/Envelopes/Envelope.cs | 4 +- src/Sentry/Protocol/Envelopes/EnvelopeItem.cs | 5 +- src/Sentry/Protocol/StructuredLog.cs | 6 + .../Internals/BatchBufferTests.cs | 175 ++++++++++++++++++ .../Internals/BatchProcessorTests.cs | 172 +++++++++++++++++ .../Protocol/StructuredLogTests.cs | 62 +++++++ test/Sentry.Tests/SentryLogTests.cs | 7 +- .../SentryStructuredLoggerTests.cs | 12 ++ 11 files changed, 523 insertions(+), 19 deletions(-) create mode 100644 src/Sentry/Internal/BatchProcessorTimer.cs create mode 100644 test/Sentry.Tests/Internals/BatchBufferTests.cs create mode 100644 test/Sentry.Tests/Internals/BatchProcessorTests.cs create mode 100644 test/Sentry.Tests/Protocol/StructuredLogTests.cs diff --git a/src/Sentry/Internal/BatchBuffer.cs b/src/Sentry/Internal/BatchBuffer.cs index 80f31277b5..3d68d66d36 100644 --- a/src/Sentry/Internal/BatchBuffer.cs +++ b/src/Sentry/Internal/BatchBuffer.cs @@ -7,6 +7,8 @@ internal sealed class BatchBuffer public BatchBuffer(int capacity) { + ThrowIfNegativeOrZero(capacity, nameof(capacity)); + _array = new T[capacity]; _count = 0; } @@ -18,11 +20,10 @@ public BatchBuffer(int capacity) internal bool TryAdd(T item) { - var count = Interlocked.Increment(ref _count); - - if (count <= _array.Length) + if (_count < _array.Length) { - _array[count - 1] = item; + _array[_count] = item; + _count++; return true; } @@ -59,4 +60,17 @@ internal T[] ToArrayAndClear() Clear(); return array; } + + private static void ThrowIfNegativeOrZero(int capacity, string paramName) + { + if (capacity <= 0) + { + ThrowNegativeOrZero(capacity, paramName); + } + } + + private static void ThrowNegativeOrZero(int capacity, string paramName) + { + throw new ArgumentOutOfRangeException(paramName, capacity, "Argument must neither be negative nor zero."); + } } diff --git a/src/Sentry/Internal/BatchProcessor.cs b/src/Sentry/Internal/BatchProcessor.cs index 2586496c3f..658729e605 100644 --- a/src/Sentry/Internal/BatchProcessor.cs +++ b/src/Sentry/Internal/BatchProcessor.cs @@ -1,4 +1,5 @@ using System.Timers; +using Sentry.Protocol; using Sentry.Protocol.Envelopes; #if NET9_0_OR_GREATER @@ -12,21 +13,22 @@ namespace Sentry.Internal; internal sealed class BatchProcessor : IDisposable { private readonly IHub _hub; - private readonly System.Timers.Timer _timer; + private readonly BatchProcessorTimer _timer; private readonly BatchBuffer _logs; private readonly Lock _lock; private DateTime _lastFlush = DateTime.MinValue; public BatchProcessor(IHub hub, int batchCount, TimeSpan batchInterval) + : this(hub, batchCount, new TimersBatchProcessorTimer(batchInterval)) + { + } + + public BatchProcessor(IHub hub, int batchCount, BatchProcessorTimer timer) { _hub = hub; - _timer = new System.Timers.Timer(batchInterval.TotalMilliseconds) - { - AutoReset = false, - Enabled = false, - }; + _timer = timer; _timer.Elapsed += IntervalElapsed; _logs = new BatchBuffer(batchCount); @@ -63,7 +65,7 @@ private void Flush() _lastFlush = DateTime.UtcNow; var logs = _logs.ToArrayAndClear(); - _ = _hub.CaptureEnvelope(Envelope.FromLogs(logs)); + _ = _hub.CaptureEnvelope(Envelope.FromLog(new StructuredLog(logs))); } private void IntervalElapsed(object? sender, ElapsedEventArgs e) diff --git a/src/Sentry/Internal/BatchProcessorTimer.cs b/src/Sentry/Internal/BatchProcessorTimer.cs new file mode 100644 index 0000000000..3b20ada767 --- /dev/null +++ b/src/Sentry/Internal/BatchProcessorTimer.cs @@ -0,0 +1,61 @@ +using System.Timers; + +namespace Sentry.Internal; + +internal abstract class BatchProcessorTimer : IDisposable +{ + protected BatchProcessorTimer() + { + } + + public abstract bool Enabled { get; set; } + + public abstract event EventHandler Elapsed; + + public void Dispose() + { + Dispose(true); + GC.SuppressFinalize(this); + } + + protected virtual void Dispose(bool disposing) + { + } +} + +internal sealed class TimersBatchProcessorTimer : BatchProcessorTimer +{ + private readonly System.Timers.Timer _timer; + + public TimersBatchProcessorTimer(TimeSpan interval) + { + _timer = new System.Timers.Timer(interval.TotalMilliseconds) + { + AutoReset = false, + Enabled = false, + }; + _timer.Elapsed += OnElapsed; + } + + public override bool Enabled + { + get => _timer.Enabled; + set => _timer.Enabled = value; + } + + public override event EventHandler? Elapsed; + + private void OnElapsed(object? sender, ElapsedEventArgs e) + { + Elapsed?.Invoke(sender, e); + } + + protected override void Dispose(bool disposing) + { + if (disposing) + { + _timer.Elapsed -= OnElapsed; + _timer.Dispose(); + } + } +} diff --git a/src/Sentry/Protocol/Envelopes/Envelope.cs b/src/Sentry/Protocol/Envelopes/Envelope.cs index bc169c52e2..2deca09790 100644 --- a/src/Sentry/Protocol/Envelopes/Envelope.cs +++ b/src/Sentry/Protocol/Envelopes/Envelope.cs @@ -446,13 +446,13 @@ internal static Envelope FromClientReport(ClientReport clientReport) } [Experimental(DiagnosticId.ExperimentalFeature)] - internal static Envelope FromLogs(SentryLog[] logs) + internal static Envelope FromLog(StructuredLog log) { var header = DefaultHeader; var items = new[] { - EnvelopeItem.FromLogs(logs), + EnvelopeItem.FromLog(log), }; return new Envelope(header, items); diff --git a/src/Sentry/Protocol/Envelopes/EnvelopeItem.cs b/src/Sentry/Protocol/Envelopes/EnvelopeItem.cs index b33bd63601..7528a14d63 100644 --- a/src/Sentry/Protocol/Envelopes/EnvelopeItem.cs +++ b/src/Sentry/Protocol/Envelopes/EnvelopeItem.cs @@ -372,16 +372,15 @@ internal static EnvelopeItem FromClientReport(ClientReport report) } [Experimental(Infrastructure.DiagnosticId.ExperimentalFeature)] - internal static EnvelopeItem FromLogs(SentryLog[] logs) + internal static EnvelopeItem FromLog(StructuredLog log) { var header = new Dictionary(3, StringComparer.Ordinal) { [TypeKey] = TypeValueLog, - ["item_count"] = logs.Length, + ["item_count"] = log.Length, ["content_type"] = "application/vnd.sentry.items.log+json", }; - var log = new StructuredLog(logs); return new EnvelopeItem(header, new JsonSerializable(log)); } diff --git a/src/Sentry/Protocol/StructuredLog.cs b/src/Sentry/Protocol/StructuredLog.cs index 07bb947372..3dc4069ec8 100644 --- a/src/Sentry/Protocol/StructuredLog.cs +++ b/src/Sentry/Protocol/StructuredLog.cs @@ -6,11 +6,17 @@ internal sealed class StructuredLog : ISentryJsonSerializable { private readonly SentryLog[] _items; + public StructuredLog(SentryLog log) + { + _items = [log]; + } + public StructuredLog(SentryLog[] logs) { _items = logs; } + public int Length => _items.Length; public ReadOnlySpan Items => _items; public void WriteTo(Utf8JsonWriter writer, IDiagnosticLogger? logger) diff --git a/test/Sentry.Tests/Internals/BatchBufferTests.cs b/test/Sentry.Tests/Internals/BatchBufferTests.cs new file mode 100644 index 0000000000..fd8fd8077a --- /dev/null +++ b/test/Sentry.Tests/Internals/BatchBufferTests.cs @@ -0,0 +1,175 @@ +namespace Sentry.Tests.Internals; + +public class BatchBufferTests +{ + [Fact] + public void Ctor_CapacityIsNegative_Throws() + { + var ctor = () => new BatchBuffer(-1); + + Assert.Throws("capacity", ctor); + } + + [Fact] + public void Ctor_CapacityIsZero_Throws() + { + var ctor = () => new BatchBuffer(0); + + Assert.Throws("capacity", ctor); + } + + [Fact] + public void TryAdd_CapacityOne_CanAddOnce() + { + var buffer = new BatchBuffer(1); + AssertProperties(buffer, 0, 1, true, false); + + buffer.TryAdd("one").Should().BeTrue(); + AssertProperties(buffer, 1, 1, false, true); + + buffer.TryAdd("two").Should().BeFalse(); + AssertProperties(buffer, 1, 1, false, true); + } + + [Fact] + public void TryAdd_CapacityTwo_CanAddTwice() + { + var buffer = new BatchBuffer(2); + AssertProperties(buffer, 0, 2, true, false); + + buffer.TryAdd("one").Should().BeTrue(); + AssertProperties(buffer, 1, 2, false, false); + + buffer.TryAdd("two").Should().BeTrue(); + AssertProperties(buffer, 2, 2, false, true); + + buffer.TryAdd("three").Should().BeFalse(); + AssertProperties(buffer, 2, 2, false, true); + } + + [Fact] + public void ToArray_IsEmpty_EmptyArray() + { + var buffer = new BatchBuffer(3); + + var array = buffer.ToArray(); + + Assert.Empty(array); + AssertProperties(buffer, 0, 3, true, false); + } + + [Fact] + public void ToArray_IsNotEmptyNorFull_PartialArray() + { + var buffer = new BatchBuffer(3); + buffer.TryAdd("one").Should().BeTrue(); + buffer.TryAdd("two").Should().BeTrue(); + + var array = buffer.ToArray(); + + Assert.Collection(array, + item => Assert.Equal("one", item), + item => Assert.Equal("two", item)); + AssertProperties(buffer, 2, 3, false, false); + } + + [Fact] + public void ToArray_IsFull_FullArray() + { + var buffer = new BatchBuffer(3); + buffer.TryAdd("one").Should().BeTrue(); + buffer.TryAdd("two").Should().BeTrue(); + buffer.TryAdd("three").Should().BeTrue(); + + var array = buffer.ToArray(); + + Assert.Collection(array, + item => Assert.Equal("one", item), + item => Assert.Equal("two", item), + item => Assert.Equal("three", item)); + AssertProperties(buffer, 3, 3, false, true); + } + + [Fact] + public void Clear_IsEmpty_NoOp() + { + var buffer = new BatchBuffer(2); + + AssertProperties(buffer, 0, 2, true, false); + buffer.Clear(); + AssertProperties(buffer, 0, 2, true, false); + } + + [Fact] + public void Clear_IsNotEmptyNorFull_ClearArray() + { + var buffer = new BatchBuffer(2); + buffer.TryAdd("one").Should().BeTrue(); + + AssertProperties(buffer, 1, 2, false, false); + buffer.Clear(); + AssertProperties(buffer, 0, 2, true, false); + } + + [Fact] + public void Clear_IsFull_ClearArray() + { + var buffer = new BatchBuffer(2); + buffer.TryAdd("one").Should().BeTrue(); + buffer.TryAdd("two").Should().BeTrue(); + + AssertProperties(buffer, 2, 2, false, true); + buffer.Clear(); + AssertProperties(buffer, 0, 2, true, false); + } + + [Fact] + public void ToArrayAndClear_IsEmpty_EmptyArray() + { + var buffer = new BatchBuffer(2); + + AssertProperties(buffer, 0, 2, true, false); + var array = buffer.ToArrayAndClear(); + AssertProperties(buffer, 0, 2, true, false); + Assert.Empty(array); + } + + [Fact] + public void ToArrayAndClear_IsNotEmptyNorFull_PartialArray() + { + var buffer = new BatchBuffer(2); + buffer.TryAdd("one").Should().BeTrue(); + + AssertProperties(buffer, 1, 2, false, false); + var array = buffer.ToArrayAndClear(); + AssertProperties(buffer, 0, 2, true, false); + Assert.Collection(array, + item => Assert.Equal("one", item)); + } + + [Fact] + public void ToArrayAndClear_IsFull_FullArray() + { + var buffer = new BatchBuffer(2); + buffer.TryAdd("one").Should().BeTrue(); + buffer.TryAdd("two").Should().BeTrue(); + + AssertProperties(buffer, 2, 2, false, true); + var array = buffer.ToArrayAndClear(); + AssertProperties(buffer, 0, 2, true, false); + Assert.Collection(array, + item => Assert.Equal("one", item), + item => Assert.Equal("two", item)); + } + + private static void AssertProperties(BatchBuffer buffer, int count, int capacity, bool empty, bool full) + { + using (new AssertionScope()) + { + buffer.Count.Should().Be(count); + buffer.Capacity.Should().Be(capacity); + buffer.IsEmpty.Should().Be(empty); + buffer.IsFull.Should().Be(full); + } + } +} diff --git a/test/Sentry.Tests/Internals/BatchProcessorTests.cs b/test/Sentry.Tests/Internals/BatchProcessorTests.cs new file mode 100644 index 0000000000..c16d45dfd0 --- /dev/null +++ b/test/Sentry.Tests/Internals/BatchProcessorTests.cs @@ -0,0 +1,172 @@ +#nullable enable + +using System.Timers; + +namespace Sentry.Tests.Internals; + +public class BatchProcessorTests +{ + private readonly IHub _hub; + private readonly FakeBatchProcessorTimer _timer; + private readonly List _envelopes; + + public BatchProcessorTests() + { + _hub = Substitute.For(); + _timer = new FakeBatchProcessorTimer(); + + _envelopes = []; + _hub.CaptureEnvelope(Arg.Do(arg => _envelopes.Add(arg))); + } + + [Theory] + [InlineData(-1)] + [InlineData(0)] + public void Ctor_CountOutOfRange_Throws(int count) + { + var ctor = () => new BatchProcessor(_hub, count, TimeSpan.FromMilliseconds(10)); + + Assert.Throws(ctor); + } + + [Theory] + [InlineData(-1)] + [InlineData(0)] + [InlineData(int.MaxValue + 1.0)] + public void Ctor_IntervalOutOfRange_Throws(double interval) + { + var ctor = () => new BatchProcessor(_hub, 1, TimeSpan.FromMilliseconds(interval)); + + Assert.Throws(ctor); + } + + [Fact] + public void Enqueue_NeitherSizeNorTimeoutReached_DoesNotCaptureEnvelope() + { + using var processor = new BatchProcessor(_hub, 2, _timer); + + processor.Enqueue(CreateLog("one")); + + AssertCaptureEnvelope(0); + AssertEnvelope(); + } + + [Fact] + public void Enqueue_SizeReached_CaptureEnvelope() + { + using var processor = new BatchProcessor(_hub, 2, _timer); + + processor.Enqueue(CreateLog("one")); + processor.Enqueue(CreateLog("two")); + + AssertCaptureEnvelope(1); + AssertEnvelope("one", "two"); + } + + [Fact] + public void Enqueue_TimeoutReached_CaptureEnvelope() + { + using var processor = new BatchProcessor(_hub, 2, _timer); + + processor.Enqueue(CreateLog("one")); + + _timer.InvokeElapsed(DateTime.Now); + + AssertCaptureEnvelope(1); + AssertEnvelope("one"); + } + + [Fact] + public void Enqueue_BothSizeAndTimeoutReached_CaptureEnvelopeOnce() + { + using var processor = new BatchProcessor(_hub, 2, _timer); + + processor.Enqueue(CreateLog("one")); + processor.Enqueue(CreateLog("two")); + _timer.InvokeElapsed(DateTime.Now); + + AssertCaptureEnvelope(1); + AssertEnvelope("one", "two"); + } + + [Fact] + public void Enqueue_BothTimeoutAndSizeReached_CaptureEnvelopes() + { + using var processor = new BatchProcessor(_hub, 2, _timer); + + _timer.InvokeElapsed(DateTime.Now); + processor.Enqueue(CreateLog("one")); + _timer.InvokeElapsed(DateTime.Now); + processor.Enqueue(CreateLog("two")); + processor.Enqueue(CreateLog("three")); + + AssertCaptureEnvelope(2); + AssertEnvelopes(["one"], ["two", "three"]); + } + + private static SentryLog CreateLog(string message) + { + return new SentryLog(DateTimeOffset.MinValue, SentryId.Empty, SentryLogLevel.Trace, message); + } + + private void AssertCaptureEnvelope(int requiredNumberOfCalls) + { + _hub.Received(requiredNumberOfCalls).CaptureEnvelope(Arg.Any()); + } + + private void AssertEnvelope(params string[] expected) + { + if (expected.Length == 0) + { + Assert.Empty(_envelopes); + return; + } + + var envelope = Assert.Single(_envelopes); + AssertEnvelope(envelope, expected); + } + + private void AssertEnvelopes(params string[][] expected) + { + if (expected.Length == 0) + { + Assert.Empty(_envelopes); + return; + } + + Assert.Equal(expected.Length, _envelopes.Count); + for (var index = 0; index < _envelopes.Count; index++) + { + AssertEnvelope(_envelopes[index], expected[index]); + } + } + + private static void AssertEnvelope(Envelope envelope, string[] expected) + { + var item = Assert.Single(envelope.Items); + var payload = Assert.IsType(item.Payload); + var log = payload.Source as StructuredLog; + Assert.NotNull(log); + Assert.Equal(expected, log.Items.ToArray().Select(static item => item.Message)); + } +} + +internal sealed class FakeBatchProcessorTimer : BatchProcessorTimer +{ + public override bool Enabled { get; set; } + + public override event EventHandler Elapsed = null!; + + internal void InvokeElapsed(DateTime signalTime) + { +#if NET9_0_OR_GREATER + var e = new ElapsedEventArgs(signalTime); +#else + var type = typeof(ElapsedEventArgs); + var ctor = BindingFlags.Instance | BindingFlags.NonPublic | BindingFlags.CreateInstance; + var instance = Activator.CreateInstance(type, ctor, null, [signalTime], null); + var e = (ElapsedEventArgs)instance!; +#endif + Elapsed.Invoke(this, e); + } +} diff --git a/test/Sentry.Tests/Protocol/StructuredLogTests.cs b/test/Sentry.Tests/Protocol/StructuredLogTests.cs new file mode 100644 index 0000000000..ecd0690610 --- /dev/null +++ b/test/Sentry.Tests/Protocol/StructuredLogTests.cs @@ -0,0 +1,62 @@ +namespace Sentry.Tests.Protocol; + +/// +/// See . +/// See also . +/// +public class StructuredLogTests +{ + private readonly TestOutputDiagnosticLogger _output; + + public StructuredLogTests(ITestOutputHelper output) + { + _output = new TestOutputDiagnosticLogger(output); + } + + [Fact] + public void Type_IsAssignableFrom_ISentryJsonSerializable() + { + var log = new StructuredLog([]); + + Assert.IsAssignableFrom(log); + } + + [Fact] + public void Length_One_Single() + { + var log = new StructuredLog([CreateLog()]); + + var length = log.Length; + + Assert.Equal(1, length); + } + + [Fact] + public void Items_One_Single() + { + var log = new StructuredLog([CreateLog()]); + + var items = log.Items; + + Assert.Equal(1, items.Length); + } + + [Fact] + public void WriteTo_Empty_AsJson() + { + var log = new StructuredLog([]); + + ArrayBufferWriter bufferWriter = new(); + using Utf8JsonWriter writer = new(bufferWriter); + log.WriteTo(writer, _output); + writer.Flush(); + + var document = JsonDocument.Parse(bufferWriter.WrittenMemory); + Assert.Equal("""{"items":[]}""", document.RootElement.ToString()); + } + + private static SentryLog CreateLog() + { + return new SentryLog(DateTimeOffset.MinValue, SentryId.Empty, SentryLogLevel.Trace, "message"); + } +} diff --git a/test/Sentry.Tests/SentryLogTests.cs b/test/Sentry.Tests/SentryLogTests.cs index c97f99b137..e41553bbf1 100644 --- a/test/Sentry.Tests/SentryLogTests.cs +++ b/test/Sentry.Tests/SentryLogTests.cs @@ -4,7 +4,8 @@ namespace Sentry.Tests; /// -/// +/// See . +/// See also . /// public class SentryLogTests { @@ -78,7 +79,7 @@ public void WriteTo_Envelope_MinimalSerializedSentryLog() var log = new SentryLog(Timestamp, TraceId, SentryLogLevel.Trace, "message"); log.SetDefaultAttributes(options, new SdkVersion()); - var envelope = Envelope.FromLogs([log]); + var envelope = Envelope.FromLog(new StructuredLog(log)); using var stream = new MemoryStream(); envelope.Serialize(stream, _output, Clock); @@ -156,7 +157,7 @@ public void WriteTo_EnvelopeItem_MaximalSerializedSentryLog() log.SetAttribute("double-attribute", 4.4); log.SetDefaultAttributes(options, new SdkVersion { Name = "Sentry.Test.SDK", Version = "1.2.3-test+Sentry" }); - var envelope = EnvelopeItem.FromLogs([log]); + var envelope = EnvelopeItem.FromLog(new StructuredLog(log)); using var stream = new MemoryStream(); envelope.Serialize(stream, _output); diff --git a/test/Sentry.Tests/SentryStructuredLoggerTests.cs b/test/Sentry.Tests/SentryStructuredLoggerTests.cs index e5fd580e7d..57ab659dd0 100644 --- a/test/Sentry.Tests/SentryStructuredLoggerTests.cs +++ b/test/Sentry.Tests/SentryStructuredLoggerTests.cs @@ -221,6 +221,18 @@ public void Log_InvalidBeforeSendLog_DoesNotCaptureEnvelope() entry.Args.Should().BeEmpty(); } + [Fact] + public void Dispose_Log_Throws() + { + _fixture.Options.Experimental.EnableLogs = true; + var logger = _fixture.GetSut(); + + logger.Dispose(); + var log = () => logger.LogTrace("Template string with arguments: {0}, {1}, {2}, {3}", ["string", true, 1, 2.2], ConfigureLog); + + Assert.Throws(log); + } + private static void ConfigureLog(SentryLog log) { log.SetAttribute("attribute-key", "attribute-value"); From 76fcc1b63e53664086e978c3962f22983d9149f5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Thu, 26 Jun 2025 23:01:20 +0200 Subject: [PATCH 03/29] docs: Batch Processor for Logs --- src/Sentry/Internal/BatchBuffer.cs | 4 ++++ src/Sentry/Internal/BatchProcessor.cs | 9 +++++++++ src/Sentry/Protocol/StructuredLog.cs | 7 +++++++ 3 files changed, 20 insertions(+) diff --git a/src/Sentry/Internal/BatchBuffer.cs b/src/Sentry/Internal/BatchBuffer.cs index 3d68d66d36..fad6ac3921 100644 --- a/src/Sentry/Internal/BatchBuffer.cs +++ b/src/Sentry/Internal/BatchBuffer.cs @@ -1,5 +1,9 @@ namespace Sentry.Internal; +/// +/// A slim wrapper over an , +/// intended for buffering. +/// internal sealed class BatchBuffer { private readonly T[] _array; diff --git a/src/Sentry/Internal/BatchProcessor.cs b/src/Sentry/Internal/BatchProcessor.cs index 658729e605..ad669ebff8 100644 --- a/src/Sentry/Internal/BatchProcessor.cs +++ b/src/Sentry/Internal/BatchProcessor.cs @@ -10,6 +10,15 @@ namespace Sentry.Internal; +/// +/// The Sentry Batch Processor. +/// This implementation is not complete yet. +/// Also, the specification is still work in progress. +/// +/// +/// Sentry Specification: . +/// OpenTelemetry spec: . +/// internal sealed class BatchProcessor : IDisposable { private readonly IHub _hub; diff --git a/src/Sentry/Protocol/StructuredLog.cs b/src/Sentry/Protocol/StructuredLog.cs index 3dc4069ec8..f7f3d0ab33 100644 --- a/src/Sentry/Protocol/StructuredLog.cs +++ b/src/Sentry/Protocol/StructuredLog.cs @@ -2,6 +2,13 @@ namespace Sentry.Protocol; +/// +/// Represents the Sentry Log protocol. +/// +/// +/// Sentry Docs: . +/// Sentry Developer Documentation: . +/// internal sealed class StructuredLog : ISentryJsonSerializable { private readonly SentryLog[] _items; From 2ad33f6055a8937562418e2157a63f8b4d1e9a08 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Fri, 27 Jun 2025 13:54:35 +0200 Subject: [PATCH 04/29] test: fix unavailable API on TargetFramework=net48 --- .../JsonSerializableExtensions.cs | 36 +++++++++++++++++-- .../Internals/DebugStackTraceTests.verify.cs | 1 + .../Protocol/StructuredLogTests.cs | 6 +--- 3 files changed, 36 insertions(+), 7 deletions(-) diff --git a/test/Sentry.Testing/JsonSerializableExtensions.cs b/test/Sentry.Testing/JsonSerializableExtensions.cs index a8e92c735d..696097880a 100644 --- a/test/Sentry.Testing/JsonSerializableExtensions.cs +++ b/test/Sentry.Testing/JsonSerializableExtensions.cs @@ -1,13 +1,15 @@ +#nullable enable + namespace Sentry.Testing; internal static class JsonSerializableExtensions { private static readonly bool IsWindows = RuntimeInformation.IsOSPlatform(OSPlatform.Windows); - public static string ToJsonString(this ISentryJsonSerializable serializable, IDiagnosticLogger logger = null, bool indented = false) => + public static string ToJsonString(this ISentryJsonSerializable serializable, IDiagnosticLogger? logger = null, bool indented = false) => WriteToJsonString(writer => writer.WriteSerializableValue(serializable, logger), indented); - public static string ToJsonString(this object @object, IDiagnosticLogger logger = null, bool indented = false) => + public static string ToJsonString(this object @object, IDiagnosticLogger? logger = null, bool indented = false) => WriteToJsonString(writer => writer.WriteDynamicValue(@object, logger), indented); private static string WriteToJsonString(Action writeAction, bool indented) @@ -43,4 +45,34 @@ private static string WriteToJsonString(Action writeAction, bool // Standardize on \n on all platforms, for consistency in tests. return IsWindows ? result.Replace("\r\n", "\n") : result; } + + public static JsonDocument ToJsonDocument(this ISentryJsonSerializable serializable, IDiagnosticLogger? logger = null) => + WriteToJsonDocument(writer => writer.WriteSerializableValue(serializable, logger)); + + public static JsonDocument ToJsonDocument(this object @object, IDiagnosticLogger? logger = null) => + WriteToJsonDocument(writer => writer.WriteDynamicValue(@object, logger)); + + private static JsonDocument WriteToJsonDocument(Action writeAction) + { +#if (NETCOREAPP3_0_OR_GREATER || NETSTANDARD2_1_OR_GREATER) + // This implementation is better, as it uses fewer allocations + var buffer = new ArrayBufferWriter(); + + using var writer = new Utf8JsonWriter(buffer); + writeAction(writer); + writer.Flush(); + + return JsonDocument.Parse(buffer.WrittenMemory); +#else + // This implementation is compatible with older targets + using var stream = new MemoryStream(); + + using var writer = new Utf8JsonWriter(stream); + writeAction(writer); + writer.Flush(); + + stream.Seek(0, SeekOrigin.Begin); + return JsonDocument.Parse(stream); +#endif + } } diff --git a/test/Sentry.Tests/Internals/DebugStackTraceTests.verify.cs b/test/Sentry.Tests/Internals/DebugStackTraceTests.verify.cs index aa4387d9af..42f7e90e02 100644 --- a/test/Sentry.Tests/Internals/DebugStackTraceTests.verify.cs +++ b/test/Sentry.Tests/Internals/DebugStackTraceTests.verify.cs @@ -240,6 +240,7 @@ public Task CreateFrame_ForNativeAOT() IP = 2, }); + Assert.NotNull(frame); return VerifyJson(frame.ToJsonString()); } #endif diff --git a/test/Sentry.Tests/Protocol/StructuredLogTests.cs b/test/Sentry.Tests/Protocol/StructuredLogTests.cs index ecd0690610..3c491900e3 100644 --- a/test/Sentry.Tests/Protocol/StructuredLogTests.cs +++ b/test/Sentry.Tests/Protocol/StructuredLogTests.cs @@ -46,12 +46,8 @@ public void WriteTo_Empty_AsJson() { var log = new StructuredLog([]); - ArrayBufferWriter bufferWriter = new(); - using Utf8JsonWriter writer = new(bufferWriter); - log.WriteTo(writer, _output); - writer.Flush(); + var document = log.ToJsonDocument(_output); - var document = JsonDocument.Parse(bufferWriter.WrittenMemory); Assert.Equal("""{"items":[]}""", document.RootElement.ToString()); } From 38e1c047e1351a50d508f2c9b42317a4d14c4a7f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Fri, 27 Jun 2025 15:26:51 +0200 Subject: [PATCH 05/29] test: run all Logs tests on full framework --- .../JsonSerializableExtensions.cs | 4 +- test/Sentry.Tests/SentryLogTests.cs | 73 +++++++++++-------- 2 files changed, 43 insertions(+), 34 deletions(-) diff --git a/test/Sentry.Testing/JsonSerializableExtensions.cs b/test/Sentry.Testing/JsonSerializableExtensions.cs index 696097880a..f71c758355 100644 --- a/test/Sentry.Testing/JsonSerializableExtensions.cs +++ b/test/Sentry.Testing/JsonSerializableExtensions.cs @@ -49,8 +49,8 @@ private static string WriteToJsonString(Action writeAction, bool public static JsonDocument ToJsonDocument(this ISentryJsonSerializable serializable, IDiagnosticLogger? logger = null) => WriteToJsonDocument(writer => writer.WriteSerializableValue(serializable, logger)); - public static JsonDocument ToJsonDocument(this object @object, IDiagnosticLogger? logger = null) => - WriteToJsonDocument(writer => writer.WriteDynamicValue(@object, logger)); + public static JsonDocument ToJsonDocument(this T @object, Action serialize, IDiagnosticLogger? logger = null) where T : class => + WriteToJsonDocument(writer => serialize.Invoke(@object, writer, logger)); private static JsonDocument WriteToJsonDocument(Action writeAction) { diff --git a/test/Sentry.Tests/SentryLogTests.cs b/test/Sentry.Tests/SentryLogTests.cs index e41553bbf1..313c27ce34 100644 --- a/test/Sentry.Tests/SentryLogTests.cs +++ b/test/Sentry.Tests/SentryLogTests.cs @@ -252,7 +252,6 @@ public void WriteTo_EnvelopeItem_MaximalSerializedSentryLog() _output.Entries.Should().BeEmpty(); } -#if (NETCOREAPP3_0_OR_GREATER || NETSTANDARD2_1_OR_GREATER) //System.Buffers.ArrayBufferWriter [Fact] public void WriteTo_MessageParameters_AsAttributes() { @@ -268,56 +267,62 @@ public void WriteTo_MessageParameters_AsAttributes() uint.MaxValue, long.MinValue, ulong.MaxValue, +#if NET5_0_OR_GREATER nint.MinValue, nuint.MaxValue, +#endif 1f, 2d, 3m, true, 'c', "string", +#if (NETCOREAPP2_0_OR_GREATER || NETSTANDARD2_1_OR_GREATER) KeyValuePair.Create("key", "value"), +#else + new KeyValuePair("key", "value"), +#endif null, ], }; - ArrayBufferWriter bufferWriter = new(); - using Utf8JsonWriter writer = new(bufferWriter); - log.WriteTo(writer, _output); - writer.Flush(); + var currentParameterAttributeIndex = -1; + string GetNextParameterAttributeName() => $"sentry.message.parameter.{++currentParameterAttributeIndex}"; - var document = JsonDocument.Parse(bufferWriter.WrittenMemory); + var document = log.ToJsonDocument(static (obj, writer, logger) => obj.WriteTo(writer, logger), _output); var attributes = document.RootElement.GetProperty("attributes"); Assert.Collection(attributes.EnumerateObject().ToArray(), - property => property.AssertAttributeInteger("sentry.message.parameter.0", json => json.GetSByte(), sbyte.MinValue), - property => property.AssertAttributeInteger("sentry.message.parameter.1", json => json.GetByte(), byte.MaxValue), - property => property.AssertAttributeInteger("sentry.message.parameter.2", json => json.GetInt16(), short.MinValue), - property => property.AssertAttributeInteger("sentry.message.parameter.3", json => json.GetUInt16(), ushort.MaxValue), - property => property.AssertAttributeInteger("sentry.message.parameter.4", json => json.GetInt32(), int.MinValue), - property => property.AssertAttributeInteger("sentry.message.parameter.5", json => json.GetUInt32(), uint.MaxValue), - property => property.AssertAttributeInteger("sentry.message.parameter.6", json => json.GetInt64(), long.MinValue), - property => property.AssertAttributeString("sentry.message.parameter.7", json => json.GetString(), ulong.MaxValue.ToString(NumberFormatInfo.InvariantInfo)), - property => property.AssertAttributeInteger("sentry.message.parameter.8", json => json.GetInt64(), nint.MinValue), - property => property.AssertAttributeString("sentry.message.parameter.9", json => json.GetString(), nuint.MaxValue.ToString(NumberFormatInfo.InvariantInfo)), - property => property.AssertAttributeDouble("sentry.message.parameter.10", json => json.GetSingle(), 1f), - property => property.AssertAttributeDouble("sentry.message.parameter.11", json => json.GetDouble(), 2d), - property => property.AssertAttributeString("sentry.message.parameter.12", json => json.GetString(), 3m.ToString(NumberFormatInfo.InvariantInfo)), - property => property.AssertAttributeBoolean("sentry.message.parameter.13", json => json.GetBoolean(), true), - property => property.AssertAttributeString("sentry.message.parameter.14", json => json.GetString(), "c"), - property => property.AssertAttributeString("sentry.message.parameter.15", json => json.GetString(), "string"), - property => property.AssertAttributeString("sentry.message.parameter.16", json => json.GetString(), "[key, value]") + property => property.AssertAttributeInteger(GetNextParameterAttributeName(), json => json.GetSByte(), sbyte.MinValue), + property => property.AssertAttributeInteger(GetNextParameterAttributeName(), json => json.GetByte(), byte.MaxValue), + property => property.AssertAttributeInteger(GetNextParameterAttributeName(), json => json.GetInt16(), short.MinValue), + property => property.AssertAttributeInteger(GetNextParameterAttributeName(), json => json.GetUInt16(), ushort.MaxValue), + property => property.AssertAttributeInteger(GetNextParameterAttributeName(), json => json.GetInt32(), int.MinValue), + property => property.AssertAttributeInteger(GetNextParameterAttributeName(), json => json.GetUInt32(), uint.MaxValue), + property => property.AssertAttributeInteger(GetNextParameterAttributeName(), json => json.GetInt64(), long.MinValue), + property => property.AssertAttributeString(GetNextParameterAttributeName(), json => json.GetString(), ulong.MaxValue.ToString(NumberFormatInfo.InvariantInfo)), +#if NET5_0_OR_GREATER + property => property.AssertAttributeInteger(GetNextParameterAttributeName(), json => json.GetInt64(), nint.MinValue), + property => property.AssertAttributeString(GetNextParameterAttributeName(), json => json.GetString(), nuint.MaxValue.ToString(NumberFormatInfo.InvariantInfo)), +#endif + property => property.AssertAttributeDouble(GetNextParameterAttributeName(), json => json.GetSingle(), 1f), + property => property.AssertAttributeDouble(GetNextParameterAttributeName(), json => json.GetDouble(), 2d), + property => property.AssertAttributeString(GetNextParameterAttributeName(), json => json.GetString(), 3m.ToString(NumberFormatInfo.InvariantInfo)), + property => property.AssertAttributeBoolean(GetNextParameterAttributeName(), json => json.GetBoolean(), true), + property => property.AssertAttributeString(GetNextParameterAttributeName(), json => json.GetString(), "c"), + property => property.AssertAttributeString(GetNextParameterAttributeName(), json => json.GetString(), "string"), + property => property.AssertAttributeString(GetNextParameterAttributeName(), json => json.GetString(), "[key, value]") ); Assert.Collection(_output.Entries, entry => entry.Message.Should().Match("*ulong*is not supported*overflow*"), +#if NET5_0_OR_GREATER entry => entry.Message.Should().Match("*nuint*is not supported*64-bit*"), +#endif entry => entry.Message.Should().Match("*decimal*is not supported*overflow*"), entry => entry.Message.Should().Match("*System.Collections.Generic.KeyValuePair`2[System.String,System.String]*is not supported*ToString*"), entry => entry.Message.Should().Match("*null*is not supported*ignored*") ); } -#endif -#if (NETCOREAPP3_0_OR_GREATER || NETSTANDARD2_1_OR_GREATER) //System.Buffers.ArrayBufferWriter [Fact] public void WriteTo_Attributes_AsJson() { @@ -330,23 +335,24 @@ public void WriteTo_Attributes_AsJson() log.SetAttribute("uint", uint.MaxValue); log.SetAttribute("long", long.MinValue); log.SetAttribute("ulong", ulong.MaxValue); +#if NET5_0_OR_GREATER log.SetAttribute("nint", nint.MinValue); log.SetAttribute("nuint", nuint.MaxValue); +#endif log.SetAttribute("float", 1f); log.SetAttribute("double", 2d); log.SetAttribute("decimal", 3m); log.SetAttribute("bool", true); log.SetAttribute("char", 'c'); log.SetAttribute("string", "string"); +#if (NETCOREAPP2_0_OR_GREATER || NETSTANDARD2_1_OR_GREATER) log.SetAttribute("object", KeyValuePair.Create("key", "value")); +#else + log.SetAttribute("object", new KeyValuePair("key", "value")); +#endif log.SetAttribute("null", null!); - ArrayBufferWriter bufferWriter = new(); - using Utf8JsonWriter writer = new(bufferWriter); - log.WriteTo(writer, _output); - writer.Flush(); - - var document = JsonDocument.Parse(bufferWriter.WrittenMemory); + var document = log.ToJsonDocument(static (obj, writer, logger) => obj.WriteTo(writer, logger), _output); var attributes = document.RootElement.GetProperty("attributes"); Assert.Collection(attributes.EnumerateObject().ToArray(), property => property.AssertAttributeInteger("sbyte", json => json.GetSByte(), sbyte.MinValue), @@ -357,8 +363,10 @@ public void WriteTo_Attributes_AsJson() property => property.AssertAttributeInteger("uint", json => json.GetUInt32(), uint.MaxValue), property => property.AssertAttributeInteger("long", json => json.GetInt64(), long.MinValue), property => property.AssertAttributeString("ulong", json => json.GetString(), ulong.MaxValue.ToString(NumberFormatInfo.InvariantInfo)), +#if NET5_0_OR_GREATER property => property.AssertAttributeInteger("nint", json => json.GetInt64(), nint.MinValue), property => property.AssertAttributeString("nuint", json => json.GetString(), nuint.MaxValue.ToString(NumberFormatInfo.InvariantInfo)), +#endif property => property.AssertAttributeDouble("float", json => json.GetSingle(), 1f), property => property.AssertAttributeDouble("double", json => json.GetDouble(), 2d), property => property.AssertAttributeString("decimal", json => json.GetString(), 3m.ToString(NumberFormatInfo.InvariantInfo)), @@ -369,13 +377,14 @@ public void WriteTo_Attributes_AsJson() ); Assert.Collection(_output.Entries, entry => entry.Message.Should().Match("*ulong*is not supported*overflow*"), +#if NET5_0_OR_GREATER entry => entry.Message.Should().Match("*nuint*is not supported*64-bit*"), +#endif entry => entry.Message.Should().Match("*decimal*is not supported*overflow*"), entry => entry.Message.Should().Match("*System.Collections.Generic.KeyValuePair`2[System.String,System.String]*is not supported*ToString*"), entry => entry.Message.Should().Match("*null*is not supported*ignored*") ); } -#endif } file static class AssertExtensions From f7a43b8d19fc73a5d5345f55cccb55d49d5d20b0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Fri, 27 Jun 2025 16:43:05 +0200 Subject: [PATCH 06/29] ref: remove usage of System.Threading.Lock --- src/Sentry/Internal/BatchProcessor.cs | 10 ++-------- 1 file changed, 2 insertions(+), 8 deletions(-) diff --git a/src/Sentry/Internal/BatchProcessor.cs b/src/Sentry/Internal/BatchProcessor.cs index ad669ebff8..1a92061e75 100644 --- a/src/Sentry/Internal/BatchProcessor.cs +++ b/src/Sentry/Internal/BatchProcessor.cs @@ -2,12 +2,6 @@ using Sentry.Protocol; using Sentry.Protocol.Envelopes; -#if NET9_0_OR_GREATER -using Lock = System.Threading.Lock; -#else -using Lock = object; -#endif - namespace Sentry.Internal; /// @@ -24,7 +18,7 @@ internal sealed class BatchProcessor : IDisposable private readonly IHub _hub; private readonly BatchProcessorTimer _timer; private readonly BatchBuffer _logs; - private readonly Lock _lock; + private readonly object _lock; private DateTime _lastFlush = DateTime.MinValue; @@ -41,7 +35,7 @@ public BatchProcessor(IHub hub, int batchCount, BatchProcessorTimer timer) _timer.Elapsed += IntervalElapsed; _logs = new BatchBuffer(batchCount); - _lock = new Lock(); + _lock = new object(); } internal void Enqueue(SentryLog log) From e6b0b7487209891c1a2390d6effcbcb2fb8be911 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Mon, 30 Jun 2025 11:17:56 +0200 Subject: [PATCH 07/29] ref: rename members for clarity --- src/Sentry/Internal/BatchProcessor.cs | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/Sentry/Internal/BatchProcessor.cs b/src/Sentry/Internal/BatchProcessor.cs index 1a92061e75..59b0e1cb6a 100644 --- a/src/Sentry/Internal/BatchProcessor.cs +++ b/src/Sentry/Internal/BatchProcessor.cs @@ -32,7 +32,7 @@ public BatchProcessor(IHub hub, int batchCount, BatchProcessorTimer timer) _hub = hub; _timer = timer; - _timer.Elapsed += IntervalElapsed; + _timer.Elapsed += OnIntervalElapsed; _logs = new BatchBuffer(batchCount); _lock = new object(); @@ -48,11 +48,11 @@ internal void Enqueue(SentryLog log) private void EnqueueCore(SentryLog log) { - var empty = _logs.IsEmpty; + var isFirstLog = _logs.IsEmpty; var added = _logs.TryAdd(log); Debug.Assert(added, $"Since we currently have no lock-free scenario, it's unexpected to exceed the {nameof(BatchBuffer)}'s capacity."); - if (empty && !_logs.IsFull) + if (isFirstLog && !_logs.IsFull) { _timer.Enabled = true; } @@ -71,7 +71,7 @@ private void Flush() _ = _hub.CaptureEnvelope(Envelope.FromLog(new StructuredLog(logs))); } - private void IntervalElapsed(object? sender, ElapsedEventArgs e) + private void OnIntervalElapsed(object? sender, ElapsedEventArgs e) { _timer.Enabled = false; @@ -87,7 +87,7 @@ private void IntervalElapsed(object? sender, ElapsedEventArgs e) public void Dispose() { _timer.Enabled = false; - _timer.Elapsed -= IntervalElapsed; + _timer.Elapsed -= OnIntervalElapsed; _timer.Dispose(); } } From 53c90ea23e5eb003ce2fdb6cdc5abd26d18f203e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Tue, 1 Jul 2025 16:40:51 +0200 Subject: [PATCH 08/29] ref: delete Timer-Abstraction and change to System.Threading.Timer --- src/Sentry/Internal/BatchProcessor.cs | 42 +++++++------ src/Sentry/Internal/BatchProcessorTimer.cs | 61 ------------------- .../Internal/DefaultSentryStructuredLogger.cs | 2 +- .../Internals/BatchProcessorTests.cs | 53 ++++++---------- .../SentryStructuredLoggerTests.cs | 2 +- 5 files changed, 44 insertions(+), 116 deletions(-) delete mode 100644 src/Sentry/Internal/BatchProcessorTimer.cs diff --git a/src/Sentry/Internal/BatchProcessor.cs b/src/Sentry/Internal/BatchProcessor.cs index 59b0e1cb6a..a0942ebfa4 100644 --- a/src/Sentry/Internal/BatchProcessor.cs +++ b/src/Sentry/Internal/BatchProcessor.cs @@ -1,4 +1,4 @@ -using System.Timers; +using Sentry.Extensibility; using Sentry.Protocol; using Sentry.Protocol.Envelopes; @@ -16,23 +16,21 @@ namespace Sentry.Internal; internal sealed class BatchProcessor : IDisposable { private readonly IHub _hub; - private readonly BatchProcessorTimer _timer; + private readonly TimeSpan _batchInterval; + private readonly IDiagnosticLogger? _diagnosticLogger; + private readonly Timer _timer; private readonly BatchBuffer _logs; private readonly object _lock; private DateTime _lastFlush = DateTime.MinValue; - public BatchProcessor(IHub hub, int batchCount, TimeSpan batchInterval) - : this(hub, batchCount, new TimersBatchProcessorTimer(batchInterval)) - { - } - - public BatchProcessor(IHub hub, int batchCount, BatchProcessorTimer timer) + public BatchProcessor(IHub hub, int batchCount, TimeSpan batchInterval, IDiagnosticLogger? diagnosticLogger) { _hub = hub; + _batchInterval = batchInterval; + _diagnosticLogger = diagnosticLogger; - _timer = timer; - _timer.Elapsed += OnIntervalElapsed; + _timer = new Timer(OnIntervalElapsed, this, Timeout.Infinite, Timeout.Infinite); _logs = new BatchBuffer(batchCount); _lock = new object(); @@ -54,11 +52,11 @@ private void EnqueueCore(SentryLog log) if (isFirstLog && !_logs.IsFull) { - _timer.Enabled = true; + EnableTimer(); } else if (_logs.IsFull) { - _timer.Enabled = false; + DisableTimer(); Flush(); } } @@ -71,23 +69,31 @@ private void Flush() _ = _hub.CaptureEnvelope(Envelope.FromLog(new StructuredLog(logs))); } - private void OnIntervalElapsed(object? sender, ElapsedEventArgs e) + internal void OnIntervalElapsed(object? state) { - _timer.Enabled = false; - lock (_lock) { - if (!_logs.IsEmpty && e.SignalTime > _lastFlush) + if (!_logs.IsEmpty && DateTime.UtcNow > _lastFlush) { Flush(); } } } + private void EnableTimer() + { + var updated = _timer.Change(_batchInterval, Timeout.InfiniteTimeSpan); + Debug.Assert(updated, "Timer was not successfully enabled."); + } + + private void DisableTimer() + { + var updated = _timer.Change(Timeout.Infinite, Timeout.Infinite); + Debug.Assert(updated, "Timer was not successfully disabled."); + } + public void Dispose() { - _timer.Enabled = false; - _timer.Elapsed -= OnIntervalElapsed; _timer.Dispose(); } } diff --git a/src/Sentry/Internal/BatchProcessorTimer.cs b/src/Sentry/Internal/BatchProcessorTimer.cs deleted file mode 100644 index 3b20ada767..0000000000 --- a/src/Sentry/Internal/BatchProcessorTimer.cs +++ /dev/null @@ -1,61 +0,0 @@ -using System.Timers; - -namespace Sentry.Internal; - -internal abstract class BatchProcessorTimer : IDisposable -{ - protected BatchProcessorTimer() - { - } - - public abstract bool Enabled { get; set; } - - public abstract event EventHandler Elapsed; - - public void Dispose() - { - Dispose(true); - GC.SuppressFinalize(this); - } - - protected virtual void Dispose(bool disposing) - { - } -} - -internal sealed class TimersBatchProcessorTimer : BatchProcessorTimer -{ - private readonly System.Timers.Timer _timer; - - public TimersBatchProcessorTimer(TimeSpan interval) - { - _timer = new System.Timers.Timer(interval.TotalMilliseconds) - { - AutoReset = false, - Enabled = false, - }; - _timer.Elapsed += OnElapsed; - } - - public override bool Enabled - { - get => _timer.Enabled; - set => _timer.Enabled = value; - } - - public override event EventHandler? Elapsed; - - private void OnElapsed(object? sender, ElapsedEventArgs e) - { - Elapsed?.Invoke(sender, e); - } - - protected override void Dispose(bool disposing) - { - if (disposing) - { - _timer.Elapsed -= OnElapsed; - _timer.Dispose(); - } - } -} diff --git a/src/Sentry/Internal/DefaultSentryStructuredLogger.cs b/src/Sentry/Internal/DefaultSentryStructuredLogger.cs index 95b8e40a80..6cbb9f3296 100644 --- a/src/Sentry/Internal/DefaultSentryStructuredLogger.cs +++ b/src/Sentry/Internal/DefaultSentryStructuredLogger.cs @@ -19,7 +19,7 @@ internal DefaultSentryStructuredLogger(IHub hub, SentryOptions options, ISystemC _options = options; _clock = clock; - _batchProcessor = new BatchProcessor(hub, ClampBatchCount(options.Experimental.InternalBatchSize), ClampBatchInterval(options.Experimental.InternalBatchTimeout)); + _batchProcessor = new BatchProcessor(hub, ClampBatchCount(options.Experimental.InternalBatchSize), ClampBatchInterval(options.Experimental.InternalBatchTimeout), _options.DiagnosticLogger); } private static int ClampBatchCount(int batchCount) diff --git a/test/Sentry.Tests/Internals/BatchProcessorTests.cs b/test/Sentry.Tests/Internals/BatchProcessorTests.cs index c16d45dfd0..08ee14c4bc 100644 --- a/test/Sentry.Tests/Internals/BatchProcessorTests.cs +++ b/test/Sentry.Tests/Internals/BatchProcessorTests.cs @@ -1,41 +1,39 @@ #nullable enable -using System.Timers; - namespace Sentry.Tests.Internals; -public class BatchProcessorTests +public class BatchProcessorTests : IDisposable { private readonly IHub _hub; - private readonly FakeBatchProcessorTimer _timer; + private readonly InMemoryDiagnosticLogger _diagnosticLogger; private readonly List _envelopes; public BatchProcessorTests() { _hub = Substitute.For(); - _timer = new FakeBatchProcessorTimer(); + _diagnosticLogger = new InMemoryDiagnosticLogger(); _envelopes = []; _hub.CaptureEnvelope(Arg.Do(arg => _envelopes.Add(arg))); } - [Theory] + [Theory(Skip = "May no longer be required after feedback.")] [InlineData(-1)] [InlineData(0)] public void Ctor_CountOutOfRange_Throws(int count) { - var ctor = () => new BatchProcessor(_hub, count, TimeSpan.FromMilliseconds(10)); + var ctor = () => new BatchProcessor(_hub, count, TimeSpan.FromMilliseconds(10), _diagnosticLogger); Assert.Throws(ctor); } - [Theory] + [Theory(Skip = "May no longer be required after feedback.")] [InlineData(-1)] [InlineData(0)] [InlineData(int.MaxValue + 1.0)] public void Ctor_IntervalOutOfRange_Throws(double interval) { - var ctor = () => new BatchProcessor(_hub, 1, TimeSpan.FromMilliseconds(interval)); + var ctor = () => new BatchProcessor(_hub, 1, TimeSpan.FromMilliseconds(interval), _diagnosticLogger); Assert.Throws(ctor); } @@ -43,7 +41,7 @@ public void Ctor_IntervalOutOfRange_Throws(double interval) [Fact] public void Enqueue_NeitherSizeNorTimeoutReached_DoesNotCaptureEnvelope() { - using var processor = new BatchProcessor(_hub, 2, _timer); + using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _diagnosticLogger); processor.Enqueue(CreateLog("one")); @@ -54,7 +52,7 @@ public void Enqueue_NeitherSizeNorTimeoutReached_DoesNotCaptureEnvelope() [Fact] public void Enqueue_SizeReached_CaptureEnvelope() { - using var processor = new BatchProcessor(_hub, 2, _timer); + using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _diagnosticLogger); processor.Enqueue(CreateLog("one")); processor.Enqueue(CreateLog("two")); @@ -66,11 +64,11 @@ public void Enqueue_SizeReached_CaptureEnvelope() [Fact] public void Enqueue_TimeoutReached_CaptureEnvelope() { - using var processor = new BatchProcessor(_hub, 2, _timer); + using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _diagnosticLogger); processor.Enqueue(CreateLog("one")); - _timer.InvokeElapsed(DateTime.Now); + processor.OnIntervalElapsed(null); AssertCaptureEnvelope(1); AssertEnvelope("one"); @@ -79,11 +77,11 @@ public void Enqueue_TimeoutReached_CaptureEnvelope() [Fact] public void Enqueue_BothSizeAndTimeoutReached_CaptureEnvelopeOnce() { - using var processor = new BatchProcessor(_hub, 2, _timer); + using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _diagnosticLogger); processor.Enqueue(CreateLog("one")); processor.Enqueue(CreateLog("two")); - _timer.InvokeElapsed(DateTime.Now); + processor.OnIntervalElapsed(null); AssertCaptureEnvelope(1); AssertEnvelope("one", "two"); @@ -92,11 +90,11 @@ public void Enqueue_BothSizeAndTimeoutReached_CaptureEnvelopeOnce() [Fact] public void Enqueue_BothTimeoutAndSizeReached_CaptureEnvelopes() { - using var processor = new BatchProcessor(_hub, 2, _timer); + using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _diagnosticLogger); - _timer.InvokeElapsed(DateTime.Now); + processor.OnIntervalElapsed(null); processor.Enqueue(CreateLog("one")); - _timer.InvokeElapsed(DateTime.Now); + processor.OnIntervalElapsed(null); processor.Enqueue(CreateLog("two")); processor.Enqueue(CreateLog("three")); @@ -149,24 +147,9 @@ private static void AssertEnvelope(Envelope envelope, string[] expected) Assert.NotNull(log); Assert.Equal(expected, log.Items.ToArray().Select(static item => item.Message)); } -} - -internal sealed class FakeBatchProcessorTimer : BatchProcessorTimer -{ - public override bool Enabled { get; set; } - - public override event EventHandler Elapsed = null!; - internal void InvokeElapsed(DateTime signalTime) + public void Dispose() { -#if NET9_0_OR_GREATER - var e = new ElapsedEventArgs(signalTime); -#else - var type = typeof(ElapsedEventArgs); - var ctor = BindingFlags.Instance | BindingFlags.NonPublic | BindingFlags.CreateInstance; - var instance = Activator.CreateInstance(type, ctor, null, [signalTime], null); - var e = (ElapsedEventArgs)instance!; -#endif - Elapsed.Invoke(this, e); + Assert.Empty(_diagnosticLogger.Entries); } } diff --git a/test/Sentry.Tests/SentryStructuredLoggerTests.cs b/test/Sentry.Tests/SentryStructuredLoggerTests.cs index 57ab659dd0..32ff9935f5 100644 --- a/test/Sentry.Tests/SentryStructuredLoggerTests.cs +++ b/test/Sentry.Tests/SentryStructuredLoggerTests.cs @@ -221,7 +221,7 @@ public void Log_InvalidBeforeSendLog_DoesNotCaptureEnvelope() entry.Args.Should().BeEmpty(); } - [Fact] + [Fact(Skip = "May no longer be required after feedback.")] public void Dispose_Log_Throws() { _fixture.Options.Experimental.EnableLogs = true; From 6580632e89a677500ecb931392482fe8b1e36079 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Tue, 1 Jul 2025 16:46:32 +0200 Subject: [PATCH 09/29] ref: delete .ctor only called from tests --- src/Sentry/Protocol/StructuredLog.cs | 5 ----- test/Sentry.Tests/SentryLogTests.cs | 4 ++-- 2 files changed, 2 insertions(+), 7 deletions(-) diff --git a/src/Sentry/Protocol/StructuredLog.cs b/src/Sentry/Protocol/StructuredLog.cs index f7f3d0ab33..6543d31ffc 100644 --- a/src/Sentry/Protocol/StructuredLog.cs +++ b/src/Sentry/Protocol/StructuredLog.cs @@ -13,11 +13,6 @@ internal sealed class StructuredLog : ISentryJsonSerializable { private readonly SentryLog[] _items; - public StructuredLog(SentryLog log) - { - _items = [log]; - } - public StructuredLog(SentryLog[] logs) { _items = logs; diff --git a/test/Sentry.Tests/SentryLogTests.cs b/test/Sentry.Tests/SentryLogTests.cs index 313c27ce34..4fd355839b 100644 --- a/test/Sentry.Tests/SentryLogTests.cs +++ b/test/Sentry.Tests/SentryLogTests.cs @@ -79,7 +79,7 @@ public void WriteTo_Envelope_MinimalSerializedSentryLog() var log = new SentryLog(Timestamp, TraceId, SentryLogLevel.Trace, "message"); log.SetDefaultAttributes(options, new SdkVersion()); - var envelope = Envelope.FromLog(new StructuredLog(log)); + var envelope = Envelope.FromLog(new StructuredLog([log])); using var stream = new MemoryStream(); envelope.Serialize(stream, _output, Clock); @@ -157,7 +157,7 @@ public void WriteTo_EnvelopeItem_MaximalSerializedSentryLog() log.SetAttribute("double-attribute", 4.4); log.SetDefaultAttributes(options, new SdkVersion { Name = "Sentry.Test.SDK", Version = "1.2.3-test+Sentry" }); - var envelope = EnvelopeItem.FromLog(new StructuredLog(log)); + var envelope = EnvelopeItem.FromLog(new StructuredLog([log])); using var stream = new MemoryStream(); envelope.Serialize(stream, _output); From 6e2ee9b7252913c294beba206cbe4db69b5f4849 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Wed, 2 Jul 2025 15:57:37 +0200 Subject: [PATCH 10/29] ref: switch Buffer-Processor to be lock-free but discarding --- src/Sentry/Internal/BatchBuffer.cs | 73 +++++++++++-------- src/Sentry/Internal/BatchProcessor.cs | 73 +++++++++++++------ .../Internals/BatchProcessorTests.cs | 26 +++++++ 3 files changed, 118 insertions(+), 54 deletions(-) diff --git a/src/Sentry/Internal/BatchBuffer.cs b/src/Sentry/Internal/BatchBuffer.cs index fad6ac3921..f02b3e71bb 100644 --- a/src/Sentry/Internal/BatchBuffer.cs +++ b/src/Sentry/Internal/BatchBuffer.cs @@ -4,77 +4,88 @@ namespace Sentry.Internal; /// A slim wrapper over an , /// intended for buffering. /// +/// +/// is thread-safe. +/// is thread-safe. +/// is not thread-safe. +/// is not thread-safe. +/// internal sealed class BatchBuffer { private readonly T[] _array; - private int _count; + private int _additions; public BatchBuffer(int capacity) { - ThrowIfNegativeOrZero(capacity, nameof(capacity)); + ThrowIfLessThanTwo(capacity, nameof(capacity)); _array = new T[capacity]; - _count = 0; + _additions = 0; } - internal int Count => _count; + //internal int Count => _count; internal int Capacity => _array.Length; - internal bool IsEmpty => _count == 0 && _array.Length != 0; - internal bool IsFull => _count == _array.Length; + internal bool IsEmpty => _additions == 0; + internal bool IsFull => _additions >= _array.Length; - internal bool TryAdd(T item) + internal bool TryAdd(T item, out int count) { - if (_count < _array.Length) + count = Interlocked.Increment(ref _additions); + + if (count <= _array.Length) { - _array[_count] = item; - _count++; + _array[count - 1] = item; return true; } return false; } - internal T[] ToArray() + internal T[] ToArrayAndClear() + { + return ToArrayAndClear(_additions); + } + + internal T[] ToArrayAndClear(int length) + { + var array = ToArray(length); + Clear(length); + return array; + } + + private T[] ToArray(int length) { - if (_count == 0) + if (length == 0) { return Array.Empty(); } - var array = new T[_count]; - Array.Copy(_array, array, _count); + var array = new T[length]; + Array.Copy(_array, array, length); return array; } - internal void Clear() + private void Clear(int length) { - if (_count == 0) + if (length == 0) { return; } - var count = _count; - _count = 0; - Array.Clear(_array, 0, count); - } - - internal T[] ToArrayAndClear() - { - var array = ToArray(); - Clear(); - return array; + _additions = 0; + Array.Clear(_array, 0, length); } - private static void ThrowIfNegativeOrZero(int capacity, string paramName) + private static void ThrowIfLessThanTwo(int capacity, string paramName) { - if (capacity <= 0) + if (capacity < 2) { - ThrowNegativeOrZero(capacity, paramName); + ThrowLessThanTwo(capacity, paramName); } } - private static void ThrowNegativeOrZero(int capacity, string paramName) + private static void ThrowLessThanTwo(int capacity, string paramName) { - throw new ArgumentOutOfRangeException(paramName, capacity, "Argument must neither be negative nor zero."); + throw new ArgumentOutOfRangeException(paramName, capacity, "Argument must be at least two."); } } diff --git a/src/Sentry/Internal/BatchProcessor.cs b/src/Sentry/Internal/BatchProcessor.cs index a0942ebfa4..1f971a21bc 100644 --- a/src/Sentry/Internal/BatchProcessor.cs +++ b/src/Sentry/Internal/BatchProcessor.cs @@ -18,9 +18,12 @@ internal sealed class BatchProcessor : IDisposable private readonly IHub _hub; private readonly TimeSpan _batchInterval; private readonly IDiagnosticLogger? _diagnosticLogger; + private readonly Timer _timer; - private readonly BatchBuffer _logs; - private readonly object _lock; + private readonly object _timerCallbackLock; + private readonly BatchBuffer _buffer1; + private readonly BatchBuffer _buffer2; + private volatile BatchBuffer _activeBuffer; private DateTime _lastFlush = DateTime.MinValue; @@ -31,51 +34,75 @@ public BatchProcessor(IHub hub, int batchCount, TimeSpan batchInterval, IDiagnos _diagnosticLogger = diagnosticLogger; _timer = new Timer(OnIntervalElapsed, this, Timeout.Infinite, Timeout.Infinite); + _timerCallbackLock = new object(); - _logs = new BatchBuffer(batchCount); - _lock = new object(); + _buffer1 = new BatchBuffer(batchCount); + _buffer2 = new BatchBuffer(batchCount); + _activeBuffer = _buffer1; } internal void Enqueue(SentryLog log) { - lock (_lock) + var activeBuffer = _activeBuffer; + + if (!TryEnqueue(activeBuffer, log)) { - EnqueueCore(log); + activeBuffer = activeBuffer == _buffer1 ? _buffer2 : _buffer1; + if (!TryEnqueue(activeBuffer, log)) + { + _diagnosticLogger?.LogInfo("Log Buffer full ... dropping log"); + } } } - private void EnqueueCore(SentryLog log) + private bool TryEnqueue(BatchBuffer buffer, SentryLog log) { - var isFirstLog = _logs.IsEmpty; - var added = _logs.TryAdd(log); - Debug.Assert(added, $"Since we currently have no lock-free scenario, it's unexpected to exceed the {nameof(BatchBuffer)}'s capacity."); - - if (isFirstLog && !_logs.IsFull) - { - EnableTimer(); - } - else if (_logs.IsFull) + if (buffer.TryAdd(log, out var count)) { - DisableTimer(); - Flush(); + if (count == 1) // is first of buffer + { + EnableTimer(); + } + + if (count == buffer.Capacity) // is buffer full + { + // swap active buffer atomically + var currentActiveBuffer = _activeBuffer; + var newActiveBuffer = ReferenceEquals(currentActiveBuffer, _buffer1) ? _buffer2 : _buffer1; + if (Interlocked.CompareExchange(ref _activeBuffer, newActiveBuffer, currentActiveBuffer) == currentActiveBuffer) + { + DisableTimer(); + Flush(buffer, count); + } + } + + return true; } + + return false; } - private void Flush() + private void Flush(BatchBuffer buffer, int count) { _lastFlush = DateTime.UtcNow; - var logs = _logs.ToArrayAndClear(); + var logs = buffer.ToArrayAndClear(count); _ = _hub.CaptureEnvelope(Envelope.FromLog(new StructuredLog(logs))); } internal void OnIntervalElapsed(object? state) { - lock (_lock) + lock (_timerCallbackLock) { - if (!_logs.IsEmpty && DateTime.UtcNow > _lastFlush) + var currentActiveBuffer = _activeBuffer; + + if (!currentActiveBuffer.IsEmpty && DateTime.UtcNow > _lastFlush) { - Flush(); + var newActiveBuffer = ReferenceEquals(currentActiveBuffer, _buffer1) ? _buffer2 : _buffer1; + if (Interlocked.CompareExchange(ref _activeBuffer, newActiveBuffer, currentActiveBuffer) == currentActiveBuffer) + { + Flush(currentActiveBuffer, -1); + } } } } diff --git a/test/Sentry.Tests/Internals/BatchProcessorTests.cs b/test/Sentry.Tests/Internals/BatchProcessorTests.cs index 08ee14c4bc..6d85e94ed7 100644 --- a/test/Sentry.Tests/Internals/BatchProcessorTests.cs +++ b/test/Sentry.Tests/Internals/BatchProcessorTests.cs @@ -102,6 +102,32 @@ public void Enqueue_BothTimeoutAndSizeReached_CaptureEnvelopes() AssertEnvelopes(["one"], ["two", "three"]); } + [Fact] + public async Task Enqueue_Concurrency_CaptureEnvelopes() + { + using var processor = new BatchProcessor(_hub, 100, Timeout.InfiniteTimeSpan, _diagnosticLogger); + using var sync = new ManualResetEvent(false); + + var tasks = new Task[5]; + for (var i = 0; i < tasks.Length; i++) + { + tasks[i] = Task.Factory.StartNew(static state => + { + var (sync, taskIndex, processor) = ((ManualResetEvent, int, BatchProcessor))state!; + sync.WaitOne(5_000); + for (var i = 0; i < 100; i++) + { + processor.Enqueue(CreateLog($"{taskIndex}-{i}")); + } + }, (sync, i, processor)); + } + + sync.Set(); + await Task.WhenAll(tasks); + + AssertCaptureEnvelope(5 * 100 / 100); + } + private static SentryLog CreateLog(string message) { return new SentryLog(DateTimeOffset.MinValue, SentryId.Empty, SentryLogLevel.Trace, message); From 0774709b07b9446efc04385e630a015ec13b473b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Thu, 3 Jul 2025 16:38:19 +0200 Subject: [PATCH 11/29] test: fix BatchBuffer and Tests --- src/Sentry/Internal/BatchBuffer.cs | 13 +- .../Internals/BatchBufferTests.cs | 174 ++++++++---------- 2 files changed, 84 insertions(+), 103 deletions(-) diff --git a/src/Sentry/Internal/BatchBuffer.cs b/src/Sentry/Internal/BatchBuffer.cs index f02b3e71bb..cb15883862 100644 --- a/src/Sentry/Internal/BatchBuffer.cs +++ b/src/Sentry/Internal/BatchBuffer.cs @@ -1,8 +1,8 @@ namespace Sentry.Internal; /// -/// A slim wrapper over an , -/// intended for buffering. +/// A slim wrapper over an , intended for buffering. +/// Requires a minimum capacity of 2. /// /// /// is thread-safe. @@ -23,7 +23,6 @@ public BatchBuffer(int capacity) _additions = 0; } - //internal int Count => _count; internal int Capacity => _array.Length; internal bool IsEmpty => _additions == 0; internal bool IsFull => _additions >= _array.Length; @@ -43,7 +42,13 @@ internal bool TryAdd(T item, out int count) internal T[] ToArrayAndClear() { - return ToArrayAndClear(_additions); + var additions = _additions; + var length = _array.Length; + if (additions < length) + { + length = additions; + } + return ToArrayAndClear(length); } internal T[] ToArrayAndClear(int length) diff --git a/test/Sentry.Tests/Internals/BatchBufferTests.cs b/test/Sentry.Tests/Internals/BatchBufferTests.cs index fd8fd8077a..fa8116ac9a 100644 --- a/test/Sentry.Tests/Internals/BatchBufferTests.cs +++ b/test/Sentry.Tests/Internals/BatchBufferTests.cs @@ -2,171 +2,147 @@ namespace Sentry.Tests.Internals; public class BatchBufferTests { - [Fact] - public void Ctor_CapacityIsNegative_Throws() + [Theory] + [InlineData(-1)] + [InlineData(0)] + [InlineData(1)] + public void Ctor_CapacityIsOutOfRange_Throws(int capacity) { - var ctor = () => new BatchBuffer(-1); + var ctor = () => new BatchBuffer(capacity); Assert.Throws("capacity", ctor); } [Fact] - public void Ctor_CapacityIsZero_Throws() + public void TryAdd_CapacityTwo_CanAddTwice() { - var ctor = () => new BatchBuffer(0); - - Assert.Throws("capacity", ctor); - } + var buffer = new BatchBuffer(2); + AssertEmpty(buffer, 2); - [Fact] - public void TryAdd_CapacityOne_CanAddOnce() - { - var buffer = new BatchBuffer(1); - AssertProperties(buffer, 0, 1, true, false); + buffer.TryAdd("one", out var first).Should().BeTrue(); + Assert.Equal(1, first); + AssertPartial(buffer, 2); - buffer.TryAdd("one").Should().BeTrue(); - AssertProperties(buffer, 1, 1, false, true); + buffer.TryAdd("two", out var second).Should().BeTrue(); + Assert.Equal(2, second); + AssertFull(buffer, 2); - buffer.TryAdd("two").Should().BeFalse(); - AssertProperties(buffer, 1, 1, false, true); + buffer.TryAdd("three", out var third).Should().BeFalse(); + Assert.Equal(3, third); + AssertFull(buffer, 2); } [Fact] - public void TryAdd_CapacityTwo_CanAddTwice() + public void TryAdd_CapacityThree_CanAddThrice() { - var buffer = new BatchBuffer(2); - AssertProperties(buffer, 0, 2, true, false); + var buffer = new BatchBuffer(3); + AssertEmpty(buffer, 3); + + buffer.TryAdd("one", out var first).Should().BeTrue(); + Assert.Equal(1, first); + AssertPartial(buffer, 3); - buffer.TryAdd("one").Should().BeTrue(); - AssertProperties(buffer, 1, 2, false, false); + buffer.TryAdd("two", out var second).Should().BeTrue(); + Assert.Equal(2, second); + AssertPartial(buffer, 3); - buffer.TryAdd("two").Should().BeTrue(); - AssertProperties(buffer, 2, 2, false, true); + buffer.TryAdd("three", out var third).Should().BeTrue(); + Assert.Equal(3, third); + AssertFull(buffer, 3); - buffer.TryAdd("three").Should().BeFalse(); - AssertProperties(buffer, 2, 2, false, true); + buffer.TryAdd("four", out var fourth).Should().BeFalse(); + Assert.Equal(4, fourth); + AssertFull(buffer, 3); } [Fact] - public void ToArray_IsEmpty_EmptyArray() + public void ToArrayAndClear_IsEmpty_EmptyArray() { - var buffer = new BatchBuffer(3); + var buffer = new BatchBuffer(2); - var array = buffer.ToArray(); + var array = buffer.ToArrayAndClear(); Assert.Empty(array); - AssertProperties(buffer, 0, 3, true, false); + AssertEmpty(buffer, 2); } [Fact] - public void ToArray_IsNotEmptyNorFull_PartialArray() + public void ToArrayAndClear_IsNotEmptyNorFull_PartialCopy() { - var buffer = new BatchBuffer(3); - buffer.TryAdd("one").Should().BeTrue(); - buffer.TryAdd("two").Should().BeTrue(); + var buffer = new BatchBuffer(2); + buffer.TryAdd("one", out _).Should().BeTrue(); - var array = buffer.ToArray(); + var array = buffer.ToArrayAndClear(); Assert.Collection(array, - item => Assert.Equal("one", item), - item => Assert.Equal("two", item)); - AssertProperties(buffer, 2, 3, false, false); + item => Assert.Equal("one", item)); + AssertEmpty(buffer, 2); } [Fact] - public void ToArray_IsFull_FullArray() + public void ToArrayAndClear_IsFull_FullCopy() { - var buffer = new BatchBuffer(3); - buffer.TryAdd("one").Should().BeTrue(); - buffer.TryAdd("two").Should().BeTrue(); - buffer.TryAdd("three").Should().BeTrue(); + var buffer = new BatchBuffer(2); + buffer.TryAdd("one", out _).Should().BeTrue(); + buffer.TryAdd("two", out _).Should().BeTrue(); - var array = buffer.ToArray(); + var array = buffer.ToArrayAndClear(); Assert.Collection(array, item => Assert.Equal("one", item), - item => Assert.Equal("two", item), - item => Assert.Equal("three", item)); - AssertProperties(buffer, 3, 3, false, true); + item => Assert.Equal("two", item)); + AssertEmpty(buffer, 2); } [Fact] - public void Clear_IsEmpty_NoOp() + public void ToArrayAndClear_CapacityExceeded_FullCopy() { var buffer = new BatchBuffer(2); + buffer.TryAdd("one", out _).Should().BeTrue(); + buffer.TryAdd("two", out _).Should().BeTrue(); + buffer.TryAdd("three", out _).Should().BeFalse(); - AssertProperties(buffer, 0, 2, true, false); - buffer.Clear(); - AssertProperties(buffer, 0, 2, true, false); - } - - [Fact] - public void Clear_IsNotEmptyNorFull_ClearArray() - { - var buffer = new BatchBuffer(2); - buffer.TryAdd("one").Should().BeTrue(); + var array = buffer.ToArrayAndClear(); - AssertProperties(buffer, 1, 2, false, false); - buffer.Clear(); - AssertProperties(buffer, 0, 2, true, false); + Assert.Collection(array, + item => Assert.Equal("one", item), + item => Assert.Equal("two", item)); + AssertEmpty(buffer, 2); } [Fact] - public void Clear_IsFull_ClearArray() + public void ToArrayAndClear_WithLength_PartialCopy() { var buffer = new BatchBuffer(2); - buffer.TryAdd("one").Should().BeTrue(); - buffer.TryAdd("two").Should().BeTrue(); + buffer.TryAdd("one", out _).Should().BeTrue(); + buffer.TryAdd("two", out _).Should().BeTrue(); + + var array = buffer.ToArrayAndClear(1); - AssertProperties(buffer, 2, 2, false, true); - buffer.Clear(); - AssertProperties(buffer, 0, 2, true, false); + Assert.Collection(array, + item => Assert.Equal("one", item)); + AssertEmpty(buffer, 2); } - [Fact] - public void ToArrayAndClear_IsEmpty_EmptyArray() + private static void AssertEmpty(BatchBuffer buffer, int capacity) { - var buffer = new BatchBuffer(2); - - AssertProperties(buffer, 0, 2, true, false); - var array = buffer.ToArrayAndClear(); - AssertProperties(buffer, 0, 2, true, false); - Assert.Empty(array); + AssertProperties(buffer, capacity, true, false); } - [Fact] - public void ToArrayAndClear_IsNotEmptyNorFull_PartialArray() + private static void AssertPartial(BatchBuffer buffer, int capacity) { - var buffer = new BatchBuffer(2); - buffer.TryAdd("one").Should().BeTrue(); - - AssertProperties(buffer, 1, 2, false, false); - var array = buffer.ToArrayAndClear(); - AssertProperties(buffer, 0, 2, true, false); - Assert.Collection(array, - item => Assert.Equal("one", item)); + AssertProperties(buffer, capacity, false, false); } - [Fact] - public void ToArrayAndClear_IsFull_FullArray() + private static void AssertFull(BatchBuffer buffer, int capacity) { - var buffer = new BatchBuffer(2); - buffer.TryAdd("one").Should().BeTrue(); - buffer.TryAdd("two").Should().BeTrue(); - - AssertProperties(buffer, 2, 2, false, true); - var array = buffer.ToArrayAndClear(); - AssertProperties(buffer, 0, 2, true, false); - Assert.Collection(array, - item => Assert.Equal("one", item), - item => Assert.Equal("two", item)); + AssertProperties(buffer, capacity, false, true); } - private static void AssertProperties(BatchBuffer buffer, int count, int capacity, bool empty, bool full) + private static void AssertProperties(BatchBuffer buffer, int capacity, bool empty, bool full) { using (new AssertionScope()) { - buffer.Count.Should().Be(count); buffer.Capacity.Should().Be(capacity); buffer.IsEmpty.Should().Be(empty); buffer.IsFull.Should().Be(full); From d9ae794c1243408fa0d0e58b60e9cde1642ff504 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Tue, 8 Jul 2025 16:30:51 +0200 Subject: [PATCH 12/29] fix: flushing buffer on Timeout --- src/Sentry/Internal/BatchBuffer.cs | 55 +++++++++++++++++++++++++-- src/Sentry/Internal/BatchProcessor.cs | 12 +++++- 2 files changed, 61 insertions(+), 6 deletions(-) diff --git a/src/Sentry/Internal/BatchBuffer.cs b/src/Sentry/Internal/BatchBuffer.cs index cb15883862..42a4db70a8 100644 --- a/src/Sentry/Internal/BatchBuffer.cs +++ b/src/Sentry/Internal/BatchBuffer.cs @@ -5,16 +5,19 @@ namespace Sentry.Internal; /// Requires a minimum capacity of 2. /// /// -/// is thread-safe. -/// is thread-safe. -/// is not thread-safe. -/// is not thread-safe. +/// Not all members are thread-safe. +/// See individual members for notes on thread safety. /// internal sealed class BatchBuffer { private readonly T[] _array; private int _additions; + /// + /// Create a new buffer. + /// + /// Length of new the buffer. + /// When is less than . public BatchBuffer(int capacity) { ThrowIfLessThanTwo(capacity, nameof(capacity)); @@ -23,10 +26,39 @@ public BatchBuffer(int capacity) _additions = 0; } + /// + /// Maximum number of elements that can be added to the buffer. + /// + /// + /// This property is thread-safe. + /// internal int Capacity => _array.Length; + + /// + /// Have any elements been added to the buffer? + /// + /// + /// This property is not thread-safe. + /// internal bool IsEmpty => _additions == 0; + + /// + /// Have number of elements been added to the buffer? + /// + /// + /// This property is not thread-safe. + /// internal bool IsFull => _additions >= _array.Length; + /// + /// Attempt to atomically add one element to the buffer. + /// + /// Element attempted to be added atomically. + /// When this method returns , is set to the Length at which the was added at. + /// when was added atomically; when was not added. + /// + /// This method is thread-safe. + /// internal bool TryAdd(T item, out int count) { count = Interlocked.Increment(ref _additions); @@ -40,6 +72,13 @@ internal bool TryAdd(T item, out int count) return false; } + /// + /// Returns a new Array consisting of the elements successfully added. + /// + /// An Array with Length of successful additions. + /// + /// This method is not thread-safe. + /// internal T[] ToArrayAndClear() { var additions = _additions; @@ -51,6 +90,14 @@ internal T[] ToArrayAndClear() return ToArrayAndClear(length); } + /// + /// Returns a new Array consisting of elements successfully added. + /// + /// The Length of the buffer a new Array is created from. + /// An Array with Length of . + /// + /// This method is not thread-safe. + /// internal T[] ToArrayAndClear(int length) { var array = ToArray(length); diff --git a/src/Sentry/Internal/BatchProcessor.cs b/src/Sentry/Internal/BatchProcessor.cs index 1f971a21bc..6c80796512 100644 --- a/src/Sentry/Internal/BatchProcessor.cs +++ b/src/Sentry/Internal/BatchProcessor.cs @@ -59,7 +59,7 @@ private bool TryEnqueue(BatchBuffer buffer, SentryLog log) { if (buffer.TryAdd(log, out var count)) { - if (count == 1) // is first of buffer + if (count == 1) // is first element added to buffer after flushed { EnableTimer(); } @@ -82,6 +82,14 @@ private bool TryEnqueue(BatchBuffer buffer, SentryLog log) return false; } + private void Flush(BatchBuffer buffer) + { + _lastFlush = DateTime.UtcNow; + + var logs = buffer.ToArrayAndClear(); + _ = _hub.CaptureEnvelope(Envelope.FromLog(new StructuredLog(logs))); + } + private void Flush(BatchBuffer buffer, int count) { _lastFlush = DateTime.UtcNow; @@ -101,7 +109,7 @@ internal void OnIntervalElapsed(object? state) var newActiveBuffer = ReferenceEquals(currentActiveBuffer, _buffer1) ? _buffer2 : _buffer1; if (Interlocked.CompareExchange(ref _activeBuffer, newActiveBuffer, currentActiveBuffer) == currentActiveBuffer) { - Flush(currentActiveBuffer, -1); + Flush(currentActiveBuffer); } } } From 7e1f5eab63b48404f4111e2a41f8de5736231ac5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Thu, 10 Jul 2025 16:46:52 +0200 Subject: [PATCH 13/29] feat: add Backpressure-ClientReport --- src/Sentry/Internal/BatchProcessor.cs | 5 +- .../Internal/DefaultSentryStructuredLogger.cs | 2 +- src/Sentry/Internal/DiscardReason.cs | 1 + .../Internals/BatchProcessorTests.cs | 84 ++++++++++++------- 4 files changed, 59 insertions(+), 33 deletions(-) diff --git a/src/Sentry/Internal/BatchProcessor.cs b/src/Sentry/Internal/BatchProcessor.cs index 6c80796512..d684713127 100644 --- a/src/Sentry/Internal/BatchProcessor.cs +++ b/src/Sentry/Internal/BatchProcessor.cs @@ -17,6 +17,7 @@ internal sealed class BatchProcessor : IDisposable { private readonly IHub _hub; private readonly TimeSpan _batchInterval; + private readonly IClientReportRecorder _clientReportRecorder; private readonly IDiagnosticLogger? _diagnosticLogger; private readonly Timer _timer; @@ -27,10 +28,11 @@ internal sealed class BatchProcessor : IDisposable private DateTime _lastFlush = DateTime.MinValue; - public BatchProcessor(IHub hub, int batchCount, TimeSpan batchInterval, IDiagnosticLogger? diagnosticLogger) + public BatchProcessor(IHub hub, int batchCount, TimeSpan batchInterval, IClientReportRecorder clientReportRecorder, IDiagnosticLogger? diagnosticLogger) { _hub = hub; _batchInterval = batchInterval; + _clientReportRecorder = clientReportRecorder; _diagnosticLogger = diagnosticLogger; _timer = new Timer(OnIntervalElapsed, this, Timeout.Infinite, Timeout.Infinite); @@ -50,6 +52,7 @@ internal void Enqueue(SentryLog log) activeBuffer = activeBuffer == _buffer1 ? _buffer2 : _buffer1; if (!TryEnqueue(activeBuffer, log)) { + _clientReportRecorder.RecordDiscardedEvent(DiscardReason.Backpressure, DataCategory.Default, 1); _diagnosticLogger?.LogInfo("Log Buffer full ... dropping log"); } } diff --git a/src/Sentry/Internal/DefaultSentryStructuredLogger.cs b/src/Sentry/Internal/DefaultSentryStructuredLogger.cs index 6cbb9f3296..e322476c9a 100644 --- a/src/Sentry/Internal/DefaultSentryStructuredLogger.cs +++ b/src/Sentry/Internal/DefaultSentryStructuredLogger.cs @@ -19,7 +19,7 @@ internal DefaultSentryStructuredLogger(IHub hub, SentryOptions options, ISystemC _options = options; _clock = clock; - _batchProcessor = new BatchProcessor(hub, ClampBatchCount(options.Experimental.InternalBatchSize), ClampBatchInterval(options.Experimental.InternalBatchTimeout), _options.DiagnosticLogger); + _batchProcessor = new BatchProcessor(hub, ClampBatchCount(options.Experimental.InternalBatchSize), ClampBatchInterval(options.Experimental.InternalBatchTimeout), _options.ClientReportRecorder, _options.DiagnosticLogger); } private static int ClampBatchCount(int batchCount) diff --git a/src/Sentry/Internal/DiscardReason.cs b/src/Sentry/Internal/DiscardReason.cs index 11a35fa2a3..afc71bd3e2 100644 --- a/src/Sentry/Internal/DiscardReason.cs +++ b/src/Sentry/Internal/DiscardReason.cs @@ -11,6 +11,7 @@ namespace Sentry.Internal; public static DiscardReason QueueOverflow = new("queue_overflow"); public static DiscardReason RateLimitBackoff = new("ratelimit_backoff"); public static DiscardReason SampleRate = new("sample_rate"); + public static DiscardReason Backpressure = new("backpressure"); private readonly string _value; diff --git a/test/Sentry.Tests/Internals/BatchProcessorTests.cs b/test/Sentry.Tests/Internals/BatchProcessorTests.cs index 6d85e94ed7..ad7b0c7618 100644 --- a/test/Sentry.Tests/Internals/BatchProcessorTests.cs +++ b/test/Sentry.Tests/Internals/BatchProcessorTests.cs @@ -5,16 +5,21 @@ namespace Sentry.Tests.Internals; public class BatchProcessorTests : IDisposable { private readonly IHub _hub; + private readonly ClientReportRecorder _clientReportRecorder; private readonly InMemoryDiagnosticLogger _diagnosticLogger; - private readonly List _envelopes; + private readonly List _capturedEnvelopes; public BatchProcessorTests() { + var options = new SentryOptions(); + var clock = new MockClock(); + _hub = Substitute.For(); + _clientReportRecorder = new ClientReportRecorder(options, clock); _diagnosticLogger = new InMemoryDiagnosticLogger(); - _envelopes = []; - _hub.CaptureEnvelope(Arg.Do(arg => _envelopes.Add(arg))); + _capturedEnvelopes = []; + _hub.CaptureEnvelope(Arg.Do(arg => _capturedEnvelopes.Add(arg))); } [Theory(Skip = "May no longer be required after feedback.")] @@ -22,7 +27,7 @@ public BatchProcessorTests() [InlineData(0)] public void Ctor_CountOutOfRange_Throws(int count) { - var ctor = () => new BatchProcessor(_hub, count, TimeSpan.FromMilliseconds(10), _diagnosticLogger); + var ctor = () => new BatchProcessor(_hub, count, TimeSpan.FromMilliseconds(10), _clientReportRecorder, _diagnosticLogger); Assert.Throws(ctor); } @@ -33,7 +38,7 @@ public void Ctor_CountOutOfRange_Throws(int count) [InlineData(int.MaxValue + 1.0)] public void Ctor_IntervalOutOfRange_Throws(double interval) { - var ctor = () => new BatchProcessor(_hub, 1, TimeSpan.FromMilliseconds(interval), _diagnosticLogger); + var ctor = () => new BatchProcessor(_hub, 1, TimeSpan.FromMilliseconds(interval), _clientReportRecorder, _diagnosticLogger); Assert.Throws(ctor); } @@ -41,56 +46,56 @@ public void Ctor_IntervalOutOfRange_Throws(double interval) [Fact] public void Enqueue_NeitherSizeNorTimeoutReached_DoesNotCaptureEnvelope() { - using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _diagnosticLogger); + using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _clientReportRecorder, _diagnosticLogger); processor.Enqueue(CreateLog("one")); - AssertCaptureEnvelope(0); + Assert.Empty(_capturedEnvelopes); AssertEnvelope(); } [Fact] public void Enqueue_SizeReached_CaptureEnvelope() { - using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _diagnosticLogger); + using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _clientReportRecorder, _diagnosticLogger); processor.Enqueue(CreateLog("one")); processor.Enqueue(CreateLog("two")); - AssertCaptureEnvelope(1); + Assert.Single(_capturedEnvelopes); AssertEnvelope("one", "two"); } [Fact] public void Enqueue_TimeoutReached_CaptureEnvelope() { - using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _diagnosticLogger); + using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _clientReportRecorder, _diagnosticLogger); processor.Enqueue(CreateLog("one")); processor.OnIntervalElapsed(null); - AssertCaptureEnvelope(1); + Assert.Single(_capturedEnvelopes); AssertEnvelope("one"); } [Fact] public void Enqueue_BothSizeAndTimeoutReached_CaptureEnvelopeOnce() { - using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _diagnosticLogger); + using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _clientReportRecorder, _diagnosticLogger); processor.Enqueue(CreateLog("one")); processor.Enqueue(CreateLog("two")); processor.OnIntervalElapsed(null); - AssertCaptureEnvelope(1); + Assert.Single(_capturedEnvelopes); AssertEnvelope("one", "two"); } [Fact] public void Enqueue_BothTimeoutAndSizeReached_CaptureEnvelopes() { - using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _diagnosticLogger); + using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _clientReportRecorder, _diagnosticLogger); processor.OnIntervalElapsed(null); processor.Enqueue(CreateLog("one")); @@ -98,14 +103,17 @@ public void Enqueue_BothTimeoutAndSizeReached_CaptureEnvelopes() processor.Enqueue(CreateLog("two")); processor.Enqueue(CreateLog("three")); - AssertCaptureEnvelope(2); + Assert.Equal(2, _capturedEnvelopes.Count); AssertEnvelopes(["one"], ["two", "three"]); } [Fact] public async Task Enqueue_Concurrency_CaptureEnvelopes() { - using var processor = new BatchProcessor(_hub, 100, Timeout.InfiniteTimeSpan, _diagnosticLogger); + const int batchCount = 3; + const int logsPerTask = 100; + + using var processor = new BatchProcessor(_hub, batchCount, Timeout.InfiniteTimeSpan, _clientReportRecorder, _diagnosticLogger); using var sync = new ManualResetEvent(false); var tasks = new Task[5]; @@ -113,19 +121,38 @@ public async Task Enqueue_Concurrency_CaptureEnvelopes() { tasks[i] = Task.Factory.StartNew(static state => { - var (sync, taskIndex, processor) = ((ManualResetEvent, int, BatchProcessor))state!; + var (sync, logsPerTask, taskIndex, processor) = ((ManualResetEvent, int, int, BatchProcessor))state!; sync.WaitOne(5_000); - for (var i = 0; i < 100; i++) + for (var i = 0; i < logsPerTask; i++) { processor.Enqueue(CreateLog($"{taskIndex}-{i}")); } - }, (sync, i, processor)); + }, (sync, logsPerTask, i, processor)); } sync.Set(); await Task.WhenAll(tasks); - AssertCaptureEnvelope(5 * 100 / 100); + var capturedLogs = _capturedEnvelopes + .SelectMany(static envelope => envelope.Items) + .Select(static item => item.Payload) + .OfType() + .Select(static payload => payload.Source) + .OfType() + .Sum(log => log.Items.Length); + var droppedLogs = 0; + + if (_clientReportRecorder.GenerateClientReport() is { } clientReport) + { + var discardedEvent = Assert.Single(clientReport.DiscardedEvents); + Assert.Equal(new DiscardReasonWithCategory(DiscardReason.Backpressure, DataCategory.Default), discardedEvent.Key); + + Assert.Equal(_diagnosticLogger.Entries.Count, discardedEvent.Value); + droppedLogs = discardedEvent.Value; + _diagnosticLogger.Entries.Clear(); + } + + Assert.Equal(tasks.Length * logsPerTask, capturedLogs + droppedLogs); } private static SentryLog CreateLog(string message) @@ -133,20 +160,15 @@ private static SentryLog CreateLog(string message) return new SentryLog(DateTimeOffset.MinValue, SentryId.Empty, SentryLogLevel.Trace, message); } - private void AssertCaptureEnvelope(int requiredNumberOfCalls) - { - _hub.Received(requiredNumberOfCalls).CaptureEnvelope(Arg.Any()); - } - private void AssertEnvelope(params string[] expected) { if (expected.Length == 0) { - Assert.Empty(_envelopes); + Assert.Empty(_capturedEnvelopes); return; } - var envelope = Assert.Single(_envelopes); + var envelope = Assert.Single(_capturedEnvelopes); AssertEnvelope(envelope, expected); } @@ -154,14 +176,14 @@ private void AssertEnvelopes(params string[][] expected) { if (expected.Length == 0) { - Assert.Empty(_envelopes); + Assert.Empty(_capturedEnvelopes); return; } - Assert.Equal(expected.Length, _envelopes.Count); - for (var index = 0; index < _envelopes.Count; index++) + Assert.Equal(expected.Length, _capturedEnvelopes.Count); + for (var index = 0; index < _capturedEnvelopes.Count; index++) { - AssertEnvelope(_envelopes[index], expected[index]); + AssertEnvelope(_capturedEnvelopes[index], expected[index]); } } From 365a2fb2a1a7c9175da5a8fc4f36acb8bf665618 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Fri, 11 Jul 2025 18:02:00 +0200 Subject: [PATCH 14/29] ref: make BatchProcessor more resilient --- src/Sentry/Internal/BatchBuffer.cs | 80 +++++++++++++++- src/Sentry/Internal/BatchProcessor.cs | 57 +++++++---- .../Internal/DefaultSentryStructuredLogger.cs | 2 +- src/Sentry/Threading/CounterEvent.cs | 96 +++++++++++++++++++ src/Sentry/Threading/NonReentrantLock.cs | 27 ++++++ test/Sentry.Tests/HubTests.cs | 2 +- .../Internals/BatchProcessorTests.cs | 45 +++++---- .../SentryStructuredLoggerTests.cs | 6 +- 8 files changed, 271 insertions(+), 44 deletions(-) create mode 100644 src/Sentry/Threading/CounterEvent.cs create mode 100644 src/Sentry/Threading/NonReentrantLock.cs diff --git a/src/Sentry/Internal/BatchBuffer.cs b/src/Sentry/Internal/BatchBuffer.cs index 42a4db70a8..ab40358e08 100644 --- a/src/Sentry/Internal/BatchBuffer.cs +++ b/src/Sentry/Internal/BatchBuffer.cs @@ -1,3 +1,5 @@ +using Sentry.Threading; + namespace Sentry.Internal; /// @@ -8,24 +10,39 @@ namespace Sentry.Internal; /// Not all members are thread-safe. /// See individual members for notes on thread safety. /// -internal sealed class BatchBuffer +[DebuggerDisplay("Name = {Name}, Capacity = {Capacity}, IsEmpty = {IsEmpty}, IsFull = {IsFull}, IsAddInProgress = {IsAddInProgress}")] +internal sealed class BatchBuffer : IDisposable { private readonly T[] _array; private int _additions; + private readonly CounterEvent _addCounter; + private readonly NonReentrantLock _addLock; /// /// Create a new buffer. /// - /// Length of new the buffer. + /// Length of the new buffer. + /// Name of the new buffer. /// When is less than . - public BatchBuffer(int capacity) + public BatchBuffer(int capacity, string? name = null) { ThrowIfLessThanTwo(capacity, nameof(capacity)); + Name = name ?? "default"; _array = new T[capacity]; _additions = 0; + _addCounter = new CounterEvent(); + _addLock = new NonReentrantLock(); } + /// + /// Name of the buffer. + /// + /// + /// This property is thread-safe. + /// + internal string Name { get; } + /// /// Maximum number of elements that can be added to the buffer. /// @@ -50,6 +67,29 @@ public BatchBuffer(int capacity) /// internal bool IsFull => _additions >= _array.Length; + internal FlushScope EnterFlushScope() + { + if (_addLock.TryEnter()) + { + return new FlushScope(this); + } + + Debug.Fail("The FlushScope should not have been entered again, before the previously entered FlushScope has exited."); + return new FlushScope(); + } + + private void ExitFlushScope() + { + _addLock.Exit(); + } + + internal bool IsAddInProgress => !_addCounter.IsSet; + + internal void WaitAddCompleted() + { + _addCounter.Wait(); + } + /// /// Attempt to atomically add one element to the buffer. /// @@ -61,6 +101,14 @@ public BatchBuffer(int capacity) /// internal bool TryAdd(T item, out int count) { + if (_addLock.IsEntered) + { + count = 0; + return false; + } + + using var scope = _addCounter.EnterScope(); + count = Interlocked.Increment(ref _additions); if (count <= _array.Length) @@ -100,6 +148,7 @@ internal T[] ToArrayAndClear() /// internal T[] ToArrayAndClear(int length) { + Debug.Assert(_addCounter.IsSet); var array = ToArray(length); Clear(length); return array; @@ -140,4 +189,29 @@ private static void ThrowLessThanTwo(int capacity, string paramName) { throw new ArgumentOutOfRangeException(paramName, capacity, "Argument must be at least two."); } + + public void Dispose() + { + _addCounter.Dispose(); + } + + internal ref struct FlushScope : IDisposable + { + private BatchBuffer? _lockObj; + + internal FlushScope(BatchBuffer lockObj) + { + _lockObj = lockObj; + } + + public void Dispose() + { + var lockObj = _lockObj; + if (lockObj is not null) + { + _lockObj = null; + lockObj.ExitFlushScope(); + } + } + } } diff --git a/src/Sentry/Internal/BatchProcessor.cs b/src/Sentry/Internal/BatchProcessor.cs index d684713127..f35a3b5642 100644 --- a/src/Sentry/Internal/BatchProcessor.cs +++ b/src/Sentry/Internal/BatchProcessor.cs @@ -1,6 +1,8 @@ using Sentry.Extensibility; +using Sentry.Infrastructure; using Sentry.Protocol; using Sentry.Protocol.Envelopes; +using Sentry.Threading; namespace Sentry.Internal; @@ -17,6 +19,7 @@ internal sealed class BatchProcessor : IDisposable { private readonly IHub _hub; private readonly TimeSpan _batchInterval; + private readonly ISystemClock _clock; private readonly IClientReportRecorder _clientReportRecorder; private readonly IDiagnosticLogger? _diagnosticLogger; @@ -25,22 +28,25 @@ internal sealed class BatchProcessor : IDisposable private readonly BatchBuffer _buffer1; private readonly BatchBuffer _buffer2; private volatile BatchBuffer _activeBuffer; + private readonly NonReentrantLock _swapLock; - private DateTime _lastFlush = DateTime.MinValue; + private DateTimeOffset _lastFlush = DateTimeOffset.MinValue; - public BatchProcessor(IHub hub, int batchCount, TimeSpan batchInterval, IClientReportRecorder clientReportRecorder, IDiagnosticLogger? diagnosticLogger) + public BatchProcessor(IHub hub, int batchCount, TimeSpan batchInterval, ISystemClock clock, IClientReportRecorder clientReportRecorder, IDiagnosticLogger? diagnosticLogger) { _hub = hub; _batchInterval = batchInterval; + _clock = clock; _clientReportRecorder = clientReportRecorder; _diagnosticLogger = diagnosticLogger; _timer = new Timer(OnIntervalElapsed, this, Timeout.Infinite, Timeout.Infinite); _timerCallbackLock = new object(); - _buffer1 = new BatchBuffer(batchCount); - _buffer2 = new BatchBuffer(batchCount); + _buffer1 = new BatchBuffer(batchCount, "Buffer 1"); + _buffer2 = new BatchBuffer(batchCount, "Buffer 2"); _activeBuffer = _buffer1; + _swapLock = new NonReentrantLock(); } internal void Enqueue(SentryLog log) @@ -49,7 +55,7 @@ internal void Enqueue(SentryLog log) if (!TryEnqueue(activeBuffer, log)) { - activeBuffer = activeBuffer == _buffer1 ? _buffer2 : _buffer1; + activeBuffer = ReferenceEquals(activeBuffer, _buffer1) ? _buffer2 : _buffer1; if (!TryEnqueue(activeBuffer, log)) { _clientReportRecorder.RecordDiscardedEvent(DiscardReason.Backpressure, DataCategory.Default, 1); @@ -69,14 +75,12 @@ private bool TryEnqueue(BatchBuffer buffer, SentryLog log) if (count == buffer.Capacity) // is buffer full { - // swap active buffer atomically + using var flushScope = buffer.EnterFlushScope(); + DisableTimer(); + var currentActiveBuffer = _activeBuffer; - var newActiveBuffer = ReferenceEquals(currentActiveBuffer, _buffer1) ? _buffer2 : _buffer1; - if (Interlocked.CompareExchange(ref _activeBuffer, newActiveBuffer, currentActiveBuffer) == currentActiveBuffer) - { - DisableTimer(); - Flush(buffer, count); - } + _ = TrySwapBuffer(currentActiveBuffer); + Flush(buffer, count); } return true; @@ -87,7 +91,8 @@ private bool TryEnqueue(BatchBuffer buffer, SentryLog log) private void Flush(BatchBuffer buffer) { - _lastFlush = DateTime.UtcNow; + buffer.WaitAddCompleted(); + _lastFlush = _clock.GetUtcNow(); var logs = buffer.ToArrayAndClear(); _ = _hub.CaptureEnvelope(Envelope.FromLog(new StructuredLog(logs))); @@ -95,7 +100,8 @@ private void Flush(BatchBuffer buffer) private void Flush(BatchBuffer buffer, int count) { - _lastFlush = DateTime.UtcNow; + buffer.WaitAddCompleted(); + _lastFlush = _clock.GetUtcNow(); var logs = buffer.ToArrayAndClear(count); _ = _hub.CaptureEnvelope(Envelope.FromLog(new StructuredLog(logs))); @@ -107,13 +113,10 @@ internal void OnIntervalElapsed(object? state) { var currentActiveBuffer = _activeBuffer; - if (!currentActiveBuffer.IsEmpty && DateTime.UtcNow > _lastFlush) + if (!currentActiveBuffer.IsEmpty && _clock.GetUtcNow() > _lastFlush) { - var newActiveBuffer = ReferenceEquals(currentActiveBuffer, _buffer1) ? _buffer2 : _buffer1; - if (Interlocked.CompareExchange(ref _activeBuffer, newActiveBuffer, currentActiveBuffer) == currentActiveBuffer) - { - Flush(currentActiveBuffer); - } + _ = TrySwapBuffer(currentActiveBuffer); + Flush(currentActiveBuffer); } } } @@ -130,6 +133,20 @@ private void DisableTimer() Debug.Assert(updated, "Timer was not successfully disabled."); } + private bool TrySwapBuffer(BatchBuffer currentActiveBuffer) + { + if (_swapLock.TryEnter()) + { + var newActiveBuffer = ReferenceEquals(currentActiveBuffer, _buffer1) ? _buffer2 : _buffer1; + var previousActiveBuffer = Interlocked.CompareExchange(ref _activeBuffer, newActiveBuffer, currentActiveBuffer); + + _swapLock.Exit(); + return previousActiveBuffer == currentActiveBuffer; + } + + return false; + } + public void Dispose() { _timer.Dispose(); diff --git a/src/Sentry/Internal/DefaultSentryStructuredLogger.cs b/src/Sentry/Internal/DefaultSentryStructuredLogger.cs index e322476c9a..9dadb3108b 100644 --- a/src/Sentry/Internal/DefaultSentryStructuredLogger.cs +++ b/src/Sentry/Internal/DefaultSentryStructuredLogger.cs @@ -19,7 +19,7 @@ internal DefaultSentryStructuredLogger(IHub hub, SentryOptions options, ISystemC _options = options; _clock = clock; - _batchProcessor = new BatchProcessor(hub, ClampBatchCount(options.Experimental.InternalBatchSize), ClampBatchInterval(options.Experimental.InternalBatchTimeout), _options.ClientReportRecorder, _options.DiagnosticLogger); + _batchProcessor = new BatchProcessor(hub, ClampBatchCount(options.Experimental.InternalBatchSize), ClampBatchInterval(options.Experimental.InternalBatchTimeout), clock, _options.ClientReportRecorder, _options.DiagnosticLogger); } private static int ClampBatchCount(int batchCount) diff --git a/src/Sentry/Threading/CounterEvent.cs b/src/Sentry/Threading/CounterEvent.cs new file mode 100644 index 0000000000..f96cdfaeca --- /dev/null +++ b/src/Sentry/Threading/CounterEvent.cs @@ -0,0 +1,96 @@ +namespace Sentry.Threading; + +/// +/// A synchronization primitive that tracks the amount of s held. +/// +[DebuggerDisplay("Count = {Count}, IsSet = {IsSet}")] +internal sealed class CounterEvent : IDisposable +{ + private readonly ManualResetEventSlim _event; + private int _count; + + internal CounterEvent() + { + _event = new ManualResetEventSlim(true); + _count = 0; + } + + /// + /// if the event is set/signaled; otherwise, . + /// + /// When , blocks the calling thread until reaches . + public bool IsSet => _event.IsSet; + + /// + /// Gets the number of remaining s required to exit to set/signal the event. + /// + /// When , the state of the event is set/signaled, which allows the thread ing on the event to proceed. + internal int Count => _count; + + /// + /// Enter a . + /// Sets the state of the event to non-signaled, which causes ing threads to block. + /// When all s have exited, the event is set/signaled. + /// + /// A new , that must be exited via . + internal Scope EnterScope() + { + var count = Interlocked.Increment(ref _count); + Debug.Assert(count > 0); + + if (count == 1) + { + _event.Reset(); + } + + return new Scope(this); + } + + private void ExitScope() + { + var count = Interlocked.Decrement(ref _count); + Debug.Assert(count >= 0); + + if (count == 0) + { + _event.Set(); + } + } + + /// + /// Blocks the current thread until the current reaches and the event is set/signaled. + /// + /// + /// The caller of this method blocks until reaches . + /// The caller will return immediately if the event is currently in a set/signaled state. + /// + internal void Wait() + { + _event.Wait(); + } + + public void Dispose() + { + _event.Dispose(); + } + + internal ref struct Scope : IDisposable + { + private CounterEvent? _event; + + internal Scope(CounterEvent @event) + { + _event = @event; + } + + public void Dispose() + { + var @event = _event; + if (@event is not null) + { + _event = null; + @event.ExitScope(); + } + } + } +} diff --git a/src/Sentry/Threading/NonReentrantLock.cs b/src/Sentry/Threading/NonReentrantLock.cs new file mode 100644 index 0000000000..9e72247707 --- /dev/null +++ b/src/Sentry/Threading/NonReentrantLock.cs @@ -0,0 +1,27 @@ +namespace Sentry.Threading; + +[DebuggerDisplay("IsEntered = {IsEntered}")] +internal sealed class NonReentrantLock +{ + private int _state; + + internal NonReentrantLock() + { + _state = 0; + } + + internal bool IsEntered => _state == 1; + + internal bool TryEnter() + { + return Interlocked.CompareExchange(ref _state, 1, 0) == 0; + } + + internal void Exit() + { + if (Interlocked.Exchange(ref _state, 0) != 1) + { + Debug.Fail("Do not Exit the lock scope when it has not been Entered."); + } + } +} diff --git a/test/Sentry.Tests/HubTests.cs b/test/Sentry.Tests/HubTests.cs index 1da106b42d..064f1a9d3b 100644 --- a/test/Sentry.Tests/HubTests.cs +++ b/test/Sentry.Tests/HubTests.cs @@ -1439,7 +1439,7 @@ public void Logger_IsDisabled_DoesNotCaptureLog() hub.Logger.Should().BeOfType(); } - [Fact] + [Fact(Skip = "Remove InternalBatchSize")] public void Logger_IsEnabled_DoesCaptureLog() { // Arrange diff --git a/test/Sentry.Tests/Internals/BatchProcessorTests.cs b/test/Sentry.Tests/Internals/BatchProcessorTests.cs index ad7b0c7618..ee5792978e 100644 --- a/test/Sentry.Tests/Internals/BatchProcessorTests.cs +++ b/test/Sentry.Tests/Internals/BatchProcessorTests.cs @@ -5,17 +5,18 @@ namespace Sentry.Tests.Internals; public class BatchProcessorTests : IDisposable { private readonly IHub _hub; + private readonly MockClock _clock; private readonly ClientReportRecorder _clientReportRecorder; private readonly InMemoryDiagnosticLogger _diagnosticLogger; - private readonly List _capturedEnvelopes; + private readonly BlockingCollection _capturedEnvelopes; public BatchProcessorTests() { var options = new SentryOptions(); - var clock = new MockClock(); _hub = Substitute.For(); - _clientReportRecorder = new ClientReportRecorder(options, clock); + _clock = new MockClock(); + _clientReportRecorder = new ClientReportRecorder(options, _clock); _diagnosticLogger = new InMemoryDiagnosticLogger(); _capturedEnvelopes = []; @@ -27,7 +28,7 @@ public BatchProcessorTests() [InlineData(0)] public void Ctor_CountOutOfRange_Throws(int count) { - var ctor = () => new BatchProcessor(_hub, count, TimeSpan.FromMilliseconds(10), _clientReportRecorder, _diagnosticLogger); + var ctor = () => new BatchProcessor(_hub, count, TimeSpan.FromMilliseconds(10), _clock, _clientReportRecorder, _diagnosticLogger); Assert.Throws(ctor); } @@ -38,7 +39,7 @@ public void Ctor_CountOutOfRange_Throws(int count) [InlineData(int.MaxValue + 1.0)] public void Ctor_IntervalOutOfRange_Throws(double interval) { - var ctor = () => new BatchProcessor(_hub, 1, TimeSpan.FromMilliseconds(interval), _clientReportRecorder, _diagnosticLogger); + var ctor = () => new BatchProcessor(_hub, 1, TimeSpan.FromMilliseconds(interval), _clock, _clientReportRecorder, _diagnosticLogger); Assert.Throws(ctor); } @@ -46,7 +47,7 @@ public void Ctor_IntervalOutOfRange_Throws(double interval) [Fact] public void Enqueue_NeitherSizeNorTimeoutReached_DoesNotCaptureEnvelope() { - using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _clientReportRecorder, _diagnosticLogger); + using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _clock, _clientReportRecorder, _diagnosticLogger); processor.Enqueue(CreateLog("one")); @@ -57,7 +58,7 @@ public void Enqueue_NeitherSizeNorTimeoutReached_DoesNotCaptureEnvelope() [Fact] public void Enqueue_SizeReached_CaptureEnvelope() { - using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _clientReportRecorder, _diagnosticLogger); + using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _clock, _clientReportRecorder, _diagnosticLogger); processor.Enqueue(CreateLog("one")); processor.Enqueue(CreateLog("two")); @@ -69,7 +70,7 @@ public void Enqueue_SizeReached_CaptureEnvelope() [Fact] public void Enqueue_TimeoutReached_CaptureEnvelope() { - using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _clientReportRecorder, _diagnosticLogger); + using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _clock, _clientReportRecorder, _diagnosticLogger); processor.Enqueue(CreateLog("one")); @@ -82,7 +83,7 @@ public void Enqueue_TimeoutReached_CaptureEnvelope() [Fact] public void Enqueue_BothSizeAndTimeoutReached_CaptureEnvelopeOnce() { - using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _clientReportRecorder, _diagnosticLogger); + using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _clock, _clientReportRecorder, _diagnosticLogger); processor.Enqueue(CreateLog("one")); processor.Enqueue(CreateLog("two")); @@ -95,7 +96,7 @@ public void Enqueue_BothSizeAndTimeoutReached_CaptureEnvelopeOnce() [Fact] public void Enqueue_BothTimeoutAndSizeReached_CaptureEnvelopes() { - using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _clientReportRecorder, _diagnosticLogger); + using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _clock, _clientReportRecorder, _diagnosticLogger); processor.OnIntervalElapsed(null); processor.Enqueue(CreateLog("one")); @@ -107,13 +108,13 @@ public void Enqueue_BothTimeoutAndSizeReached_CaptureEnvelopes() AssertEnvelopes(["one"], ["two", "three"]); } - [Fact] + [Fact(Skip = "TODO")] public async Task Enqueue_Concurrency_CaptureEnvelopes() { const int batchCount = 3; const int logsPerTask = 100; - using var processor = new BatchProcessor(_hub, batchCount, Timeout.InfiniteTimeSpan, _clientReportRecorder, _diagnosticLogger); + using var processor = new BatchProcessor(_hub, batchCount, Timeout.InfiniteTimeSpan, _clock, _clientReportRecorder, _diagnosticLogger); using var sync = new ManualResetEvent(false); var tasks = new Task[5]; @@ -131,7 +132,8 @@ public async Task Enqueue_Concurrency_CaptureEnvelopes() } sync.Set(); - await Task.WhenAll(tasks); + await Task.WhenAll(tasks).WaitAsync(TimeSpan.FromSeconds(5)); + _capturedEnvelopes.CompleteAdding(); var capturedLogs = _capturedEnvelopes .SelectMany(static envelope => envelope.Items) @@ -152,7 +154,16 @@ public async Task Enqueue_Concurrency_CaptureEnvelopes() _diagnosticLogger.Entries.Clear(); } - Assert.Equal(tasks.Length * logsPerTask, capturedLogs + droppedLogs); + var actualInvocations = tasks.Length * logsPerTask; + if (actualInvocations != capturedLogs + droppedLogs) + { + Assert.Fail($""" + Expected {actualInvocations} combined logs, + but actually received a total of {capturedLogs + droppedLogs} logs, + with {capturedLogs} captured logs and {droppedLogs} dropped logs, + which is a difference of {actualInvocations - capturedLogs - droppedLogs} logs. + """); + } } private static SentryLog CreateLog(string message) @@ -181,9 +192,11 @@ private void AssertEnvelopes(params string[][] expected) } Assert.Equal(expected.Length, _capturedEnvelopes.Count); - for (var index = 0; index < _capturedEnvelopes.Count; index++) + var index = 0; + foreach (var capturedEnvelope in _capturedEnvelopes) { - AssertEnvelope(_capturedEnvelopes[index], expected[index]); + AssertEnvelope(capturedEnvelope, expected[index]); + index++; } } diff --git a/test/Sentry.Tests/SentryStructuredLoggerTests.cs b/test/Sentry.Tests/SentryStructuredLoggerTests.cs index 32ff9935f5..f9f82710cb 100644 --- a/test/Sentry.Tests/SentryStructuredLoggerTests.cs +++ b/test/Sentry.Tests/SentryStructuredLoggerTests.cs @@ -74,7 +74,7 @@ public void Create_Disabled_CachedDisabledInstance() instance.Should().BeSameAs(other); } - [Theory] + [Theory(Skip = "Remove InternalBatchSize")] [InlineData(SentryLogLevel.Trace)] [InlineData(SentryLogLevel.Debug)] [InlineData(SentryLogLevel.Info)] @@ -113,7 +113,7 @@ public void Log_Disabled_DoesNotCaptureEnvelope(SentryLogLevel level) _fixture.Hub.Received(0).CaptureEnvelope(Arg.Any()); } - [Fact] + [Fact(Skip = "Remove InternalBatchSize")] public void Log_WithoutTraceHeader_CapturesEnvelope() { _fixture.WithoutTraceHeader(); @@ -130,7 +130,7 @@ public void Log_WithoutTraceHeader_CapturesEnvelope() envelope.AssertEnvelope(_fixture, SentryLogLevel.Trace); } - [Fact] + [Fact(Skip = "Remove InternalBatchSize")] public void Log_WithBeforeSendLog_InvokesCallback() { var invocations = 0; From c4783916baea4f7e2bda0151c38fe2eace0ca934 Mon Sep 17 00:00:00 2001 From: Sentry Github Bot Date: Fri, 11 Jul 2025 16:20:04 +0000 Subject: [PATCH 15/29] Format code --- test/Sentry.Tests/Internals/BatchProcessorTests.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/Sentry.Tests/Internals/BatchProcessorTests.cs b/test/Sentry.Tests/Internals/BatchProcessorTests.cs index ee5792978e..83f1a6fe38 100644 --- a/test/Sentry.Tests/Internals/BatchProcessorTests.cs +++ b/test/Sentry.Tests/Internals/BatchProcessorTests.cs @@ -5,7 +5,7 @@ namespace Sentry.Tests.Internals; public class BatchProcessorTests : IDisposable { private readonly IHub _hub; - private readonly MockClock _clock; + private readonly MockClock _clock; private readonly ClientReportRecorder _clientReportRecorder; private readonly InMemoryDiagnosticLogger _diagnosticLogger; private readonly BlockingCollection _capturedEnvelopes; From c699c2dc20ae8b8a561a6e5d7cf98c0f5497535b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Fri, 11 Jul 2025 19:13:38 +0200 Subject: [PATCH 16/29] test: fix on .NET Framework --- test/Sentry.Tests/Internals/BatchProcessorTests.cs | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/test/Sentry.Tests/Internals/BatchProcessorTests.cs b/test/Sentry.Tests/Internals/BatchProcessorTests.cs index 83f1a6fe38..f4515bab68 100644 --- a/test/Sentry.Tests/Internals/BatchProcessorTests.cs +++ b/test/Sentry.Tests/Internals/BatchProcessorTests.cs @@ -10,6 +10,8 @@ public class BatchProcessorTests : IDisposable private readonly InMemoryDiagnosticLogger _diagnosticLogger; private readonly BlockingCollection _capturedEnvelopes; + private int _expectedDiagnosticLogs; + public BatchProcessorTests() { var options = new SentryOptions(); @@ -21,6 +23,8 @@ public BatchProcessorTests() _capturedEnvelopes = []; _hub.CaptureEnvelope(Arg.Do(arg => _capturedEnvelopes.Add(arg))); + + _expectedDiagnosticLogs = 0; } [Theory(Skip = "May no longer be required after feedback.")] @@ -149,9 +153,8 @@ public async Task Enqueue_Concurrency_CaptureEnvelopes() var discardedEvent = Assert.Single(clientReport.DiscardedEvents); Assert.Equal(new DiscardReasonWithCategory(DiscardReason.Backpressure, DataCategory.Default), discardedEvent.Key); - Assert.Equal(_diagnosticLogger.Entries.Count, discardedEvent.Value); droppedLogs = discardedEvent.Value; - _diagnosticLogger.Entries.Clear(); + _expectedDiagnosticLogs = discardedEvent.Value; } var actualInvocations = tasks.Length * logsPerTask; @@ -211,6 +214,6 @@ private static void AssertEnvelope(Envelope envelope, string[] expected) public void Dispose() { - Assert.Empty(_diagnosticLogger.Entries); + Assert.Equal(_expectedDiagnosticLogs, _diagnosticLogger.Entries.Count); } } From b21b537a8297867be6d643b10921ac4e4fbd0fb4 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Mon, 14 Jul 2025 23:31:04 +0200 Subject: [PATCH 17/29] fix: BatchBuffer flushed on Shutdown/Dispose --- .../BatchProcessorBenchmarks.cs | 48 ++++++++++++++++++ src/Sentry/Internal/BatchBuffer.cs | 49 +++++++++++++++---- src/Sentry/Internal/BatchProcessor.cs | 13 ++++- .../Internal/DefaultSentryStructuredLogger.cs | 8 +++ .../DisabledSentryStructuredLogger.cs | 1 + src/Sentry/Internal/Hub.cs | 1 + src/Sentry/SentryStructuredLogger.cs | 16 ++++++ .../InMemorySentryStructuredLogger.cs | 1 + .../Internals/BatchProcessorTests.cs | 6 ++- 9 files changed, 129 insertions(+), 14 deletions(-) create mode 100644 benchmarks/Sentry.Benchmarks/BatchProcessorBenchmarks.cs diff --git a/benchmarks/Sentry.Benchmarks/BatchProcessorBenchmarks.cs b/benchmarks/Sentry.Benchmarks/BatchProcessorBenchmarks.cs new file mode 100644 index 0000000000..1047669977 --- /dev/null +++ b/benchmarks/Sentry.Benchmarks/BatchProcessorBenchmarks.cs @@ -0,0 +1,48 @@ +using BenchmarkDotNet.Attributes; +using NSubstitute; +using Sentry.Extensibility; +using Sentry.Internal; +using Sentry.Testing; + +namespace Sentry.Benchmarks; + +public class BatchProcessorBenchmarks +{ + private BatchProcessor _batchProcessor; + private SentryLog _log; + + [Params(10, 100)] + public int BatchCount { get; set; } + + [Params(100, 200, 1_000)] + public int OperationsPerInvoke { get; set; } + + [GlobalSetup] + public void Setup() + { + var hub = DisabledHub.Instance; + var batchInterval = Timeout.InfiniteTimeSpan; + var clock = new MockClock(); + var clientReportRecorder = Substitute.For(); + var diagnosticLogger = Substitute.For(); + _batchProcessor = new BatchProcessor(hub, BatchCount, batchInterval, clock, clientReportRecorder, diagnosticLogger); + + _log = new SentryLog(DateTimeOffset.Now, SentryId.Empty, SentryLogLevel.Trace, "message"); + } + + [Benchmark] + public void EnqueueAndFlush() + { + for (var i = 0; i < OperationsPerInvoke; i++) + { + _batchProcessor.Enqueue(_log); + } + _batchProcessor.Flush(); + } + + [GlobalCleanup] + public void Cleanup() + { + _batchProcessor.Dispose(); + } +} diff --git a/src/Sentry/Internal/BatchBuffer.cs b/src/Sentry/Internal/BatchBuffer.cs index ab40358e08..ae3d415801 100644 --- a/src/Sentry/Internal/BatchBuffer.cs +++ b/src/Sentry/Internal/BatchBuffer.cs @@ -10,7 +10,7 @@ namespace Sentry.Internal; /// Not all members are thread-safe. /// See individual members for notes on thread safety. /// -[DebuggerDisplay("Name = {Name}, Capacity = {Capacity}, IsEmpty = {IsEmpty}, IsFull = {IsFull}, IsAddInProgress = {IsAddInProgress}")] +[DebuggerDisplay("Name = {Name}, Capacity = {Capacity}, IsEmpty = {IsEmpty}, IsFull = {IsFull}, AddCount = {AddCount}")] internal sealed class BatchBuffer : IDisposable { private readonly T[] _array; @@ -67,24 +67,50 @@ public BatchBuffer(int capacity, string? name = null) /// internal bool IsFull => _additions >= _array.Length; - internal FlushScope EnterFlushScope() + /// + /// Number of operations in progress. + /// + /// + /// This property is used for debugging only. + /// + private int AddCount => _addCounter.Count; + + /// + /// Enters a used to ensure that only a single flush operation is in progress. + /// + /// A that must be disposed to exit. + /// + /// This method is thread-safe. + /// + internal FlushScope TryEnterFlushScope(out bool lockTaken) { if (_addLock.TryEnter()) { + lockTaken = true; return new FlushScope(this); } - Debug.Fail("The FlushScope should not have been entered again, before the previously entered FlushScope has exited."); + lockTaken = false; return new FlushScope(); } + /// + /// Exits the through . + /// + /// + /// This method is thread-safe. + /// private void ExitFlushScope() { _addLock.Exit(); } - internal bool IsAddInProgress => !_addCounter.IsSet; - + /// + /// Blocks the current thread until all operations have completed. + /// + /// + /// This method is thread-safe. + /// internal void WaitAddCompleted() { _addCounter.Wait(); @@ -177,6 +203,12 @@ private void Clear(int length) Array.Clear(_array, 0, length); } + /// + public void Dispose() + { + _addCounter.Dispose(); + } + private static void ThrowIfLessThanTwo(int capacity, string paramName) { if (capacity < 2) @@ -190,11 +222,6 @@ private static void ThrowLessThanTwo(int capacity, string paramName) throw new ArgumentOutOfRangeException(paramName, capacity, "Argument must be at least two."); } - public void Dispose() - { - _addCounter.Dispose(); - } - internal ref struct FlushScope : IDisposable { private BatchBuffer? _lockObj; @@ -204,6 +231,8 @@ internal FlushScope(BatchBuffer lockObj) _lockObj = lockObj; } + internal bool IsEntered => _lockObj is not null; + public void Dispose() { var lockObj = _lockObj; diff --git a/src/Sentry/Internal/BatchProcessor.cs b/src/Sentry/Internal/BatchProcessor.cs index f35a3b5642..f167c5fd50 100644 --- a/src/Sentry/Internal/BatchProcessor.cs +++ b/src/Sentry/Internal/BatchProcessor.cs @@ -64,6 +64,13 @@ internal void Enqueue(SentryLog log) } } + internal void Flush() + { + DisableTimer(); + Flush(_buffer1); + Flush(_buffer2); + } + private bool TryEnqueue(BatchBuffer buffer, SentryLog log) { if (buffer.TryAdd(log, out var count)) @@ -75,7 +82,7 @@ private bool TryEnqueue(BatchBuffer buffer, SentryLog log) if (count == buffer.Capacity) // is buffer full { - using var flushScope = buffer.EnterFlushScope(); + using var flushScope = buffer.TryEnterFlushScope(out var lockTaken); DisableTimer(); var currentActiveBuffer = _activeBuffer; @@ -113,7 +120,9 @@ internal void OnIntervalElapsed(object? state) { var currentActiveBuffer = _activeBuffer; - if (!currentActiveBuffer.IsEmpty && _clock.GetUtcNow() > _lastFlush) + using var scope = currentActiveBuffer.TryEnterFlushScope(out var lockTaken); + + if (lockTaken && !currentActiveBuffer.IsEmpty && _clock.GetUtcNow() > _lastFlush) { _ = TrySwapBuffer(currentActiveBuffer); Flush(currentActiveBuffer); diff --git a/src/Sentry/Internal/DefaultSentryStructuredLogger.cs b/src/Sentry/Internal/DefaultSentryStructuredLogger.cs index 9dadb3108b..b6d8186860 100644 --- a/src/Sentry/Internal/DefaultSentryStructuredLogger.cs +++ b/src/Sentry/Internal/DefaultSentryStructuredLogger.cs @@ -38,6 +38,7 @@ private static TimeSpan ClampBatchInterval(TimeSpan batchInterval) : batchInterval; } + /// private protected override void CaptureLog(SentryLogLevel level, string template, object[]? parameters, Action? configureLog) { var timestamp = _clock.GetUtcNow(); @@ -94,6 +95,13 @@ private protected override void CaptureLog(SentryLogLevel level, string template } } + /// + protected internal override void Flush() + { + _batchProcessor.Flush(); + } + + /// protected override void Dispose(bool disposing) { if (disposing) diff --git a/src/Sentry/Internal/DisabledSentryStructuredLogger.cs b/src/Sentry/Internal/DisabledSentryStructuredLogger.cs index 086f67a1bd..dba69e0833 100644 --- a/src/Sentry/Internal/DisabledSentryStructuredLogger.cs +++ b/src/Sentry/Internal/DisabledSentryStructuredLogger.cs @@ -8,6 +8,7 @@ internal DisabledSentryStructuredLogger() { } + /// private protected override void CaptureLog(SentryLogLevel level, string template, object[]? parameters, Action? configureLog) { // disabled diff --git a/src/Sentry/Internal/Hub.cs b/src/Sentry/Internal/Hub.cs index fb13510789..fcc7cd2ddb 100644 --- a/src/Sentry/Internal/Hub.cs +++ b/src/Sentry/Internal/Hub.cs @@ -796,6 +796,7 @@ public void Dispose() _memoryMonitor?.Dispose(); #endif + Logger.Flush(); Logger.Dispose(); try diff --git a/src/Sentry/SentryStructuredLogger.cs b/src/Sentry/SentryStructuredLogger.cs index e63566c3b8..33005e5964 100644 --- a/src/Sentry/SentryStructuredLogger.cs +++ b/src/Sentry/SentryStructuredLogger.cs @@ -21,6 +21,14 @@ private protected SentryStructuredLogger() { } + /// + /// Buffers a Sentry Log message + /// via the associated Batch Processor. + /// + /// The severity level of the log. + /// The parameterized template string. + /// The parameters to the string. + /// A configuration callback. Will be removed in a future version. private protected abstract void CaptureLog(SentryLogLevel level, string template, object[]? parameters, Action? configureLog); /// @@ -101,6 +109,14 @@ public void LogFatal(string template, object[]? parameters = null, Action + /// When overridden in a derived , + /// clears all buffers for this logger and causes any buffered logs to be sent by the underlying . + /// + protected internal virtual void Flush() + { + } + /// public void Dispose() { diff --git a/test/Sentry.Testing/InMemorySentryStructuredLogger.cs b/test/Sentry.Testing/InMemorySentryStructuredLogger.cs index c173fa7f17..fd697056cf 100644 --- a/test/Sentry.Testing/InMemorySentryStructuredLogger.cs +++ b/test/Sentry.Testing/InMemorySentryStructuredLogger.cs @@ -6,6 +6,7 @@ public sealed class InMemorySentryStructuredLogger : SentryStructuredLogger { public List Entries { get; } = new(); + /// private protected override void CaptureLog(SentryLogLevel level, string template, object[]? parameters, Action? configureLog) { Entries.Add(LogEntry.Create(level, template, parameters)); diff --git a/test/Sentry.Tests/Internals/BatchProcessorTests.cs b/test/Sentry.Tests/Internals/BatchProcessorTests.cs index f4515bab68..8facac9598 100644 --- a/test/Sentry.Tests/Internals/BatchProcessorTests.cs +++ b/test/Sentry.Tests/Internals/BatchProcessorTests.cs @@ -112,16 +112,17 @@ public void Enqueue_BothTimeoutAndSizeReached_CaptureEnvelopes() AssertEnvelopes(["one"], ["two", "three"]); } - [Fact(Skip = "TODO")] + [Fact] public async Task Enqueue_Concurrency_CaptureEnvelopes() { const int batchCount = 3; + const int maxDegreeOfParallelism = 5; const int logsPerTask = 100; using var processor = new BatchProcessor(_hub, batchCount, Timeout.InfiniteTimeSpan, _clock, _clientReportRecorder, _diagnosticLogger); using var sync = new ManualResetEvent(false); - var tasks = new Task[5]; + var tasks = new Task[maxDegreeOfParallelism]; for (var i = 0; i < tasks.Length; i++) { tasks[i] = Task.Factory.StartNew(static state => @@ -137,6 +138,7 @@ public async Task Enqueue_Concurrency_CaptureEnvelopes() sync.Set(); await Task.WhenAll(tasks).WaitAsync(TimeSpan.FromSeconds(5)); + processor.Flush(); _capturedEnvelopes.CompleteAdding(); var capturedLogs = _capturedEnvelopes From e8850db578a5f3a4ba9afb940fa934e365e89020 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Tue, 22 Jul 2025 15:45:34 +0200 Subject: [PATCH 18/29] ref: minimize locking --- ....BatchProcessorBenchmarks-report-github.md | 18 ++ src/Sentry/Internal/BatchBuffer.cs | 246 ++++++++++------- src/Sentry/Internal/BatchProcessor.cs | 115 +++----- src/Sentry/Threading/CounterEvent.cs | 96 ------- src/Sentry/Threading/NonReentrantLock.cs | 27 -- src/Sentry/Threading/ScopedCountdownLock.cs | 149 ++++++++++ ...piApprovalTests.Run.DotNet8_0.verified.txt | 1 + ...piApprovalTests.Run.DotNet9_0.verified.txt | 1 + .../ApiApprovalTests.Run.Net4_8.verified.txt | 1 + .../Internals/BatchBufferTests.cs | 256 ++++++++++++------ .../Internals/BatchProcessorTests.cs | 122 ++++----- .../Threading/ScopedCountdownLockTests.cs | 136 ++++++++++ 12 files changed, 724 insertions(+), 444 deletions(-) create mode 100644 benchmarks/Sentry.Benchmarks/BenchmarkDotNet.Artifacts/results/Sentry.Benchmarks.BatchProcessorBenchmarks-report-github.md delete mode 100644 src/Sentry/Threading/CounterEvent.cs delete mode 100644 src/Sentry/Threading/NonReentrantLock.cs create mode 100644 src/Sentry/Threading/ScopedCountdownLock.cs create mode 100644 test/Sentry.Tests/Threading/ScopedCountdownLockTests.cs diff --git a/benchmarks/Sentry.Benchmarks/BenchmarkDotNet.Artifacts/results/Sentry.Benchmarks.BatchProcessorBenchmarks-report-github.md b/benchmarks/Sentry.Benchmarks/BenchmarkDotNet.Artifacts/results/Sentry.Benchmarks.BatchProcessorBenchmarks-report-github.md new file mode 100644 index 0000000000..8046dceeda --- /dev/null +++ b/benchmarks/Sentry.Benchmarks/BenchmarkDotNet.Artifacts/results/Sentry.Benchmarks.BatchProcessorBenchmarks-report-github.md @@ -0,0 +1,18 @@ +``` + +BenchmarkDotNet v0.13.12, macOS 15.5 (24F74) [Darwin 24.5.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** | **2.209 μs** | **0.0221 μs** | **0.0196 μs** | **0.7095** | **5.8 KB** | +| **EnqueueAndFlush** | **10** | **200** | **3.829 μs** | **0.0287 μs** | **0.0268 μs** | **1.3199** | **10.8 KB** | +| **EnqueueAndFlush** | **10** | **1000** | **18.363 μs** | **0.2813 μs** | **0.2889 μs** | **6.1951** | **50.8 KB** | +| **EnqueueAndFlush** | **100** | **100** | **1.021 μs** | **0.0133 μs** | **0.0118 μs** | **0.2441** | **2 KB** | +| **EnqueueAndFlush** | **100** | **200** | **1.816 μs** | **0.0211 μs** | **0.0176 μs** | **0.3910** | **3.2 KB** | +| **EnqueueAndFlush** | **100** | **1000** | **8.762 μs** | **0.0761 μs** | **0.0675 μs** | **1.5564** | **12.83 KB** | diff --git a/src/Sentry/Internal/BatchBuffer.cs b/src/Sentry/Internal/BatchBuffer.cs index ae3d415801..ad6cf8684f 100644 --- a/src/Sentry/Internal/BatchBuffer.cs +++ b/src/Sentry/Internal/BatchBuffer.cs @@ -1,159 +1,156 @@ +using Sentry.Infrastructure; using Sentry.Threading; namespace Sentry.Internal; /// -/// A slim wrapper over an , intended for buffering. -/// Requires a minimum capacity of 2. +/// A wrapper over an , intended for reusable buffering. /// /// -/// Not all members are thread-safe. -/// See individual members for notes on thread safety. +/// Must be attempted to flush via when either the is reached, +/// or when the is exceeded. /// -[DebuggerDisplay("Name = {Name}, Capacity = {Capacity}, IsEmpty = {IsEmpty}, IsFull = {IsFull}, AddCount = {AddCount}")] +[DebuggerDisplay("Name = {Name}, Capacity = {Capacity}, Additions = {_additions}, AddCount = {AddCount}")] internal sealed class BatchBuffer : IDisposable { private readonly T[] _array; private int _additions; - private readonly CounterEvent _addCounter; - private readonly NonReentrantLock _addLock; + private readonly ScopedCountdownLock _addLock; + + private readonly ISystemClock _clock; + private readonly Timer _timer; + private readonly TimeSpan _timeout; + + private readonly Action, DateTimeOffset> _timeoutExceededAction; + + private DateTimeOffset _lastFlush = DateTimeOffset.MinValue; /// /// Create a new buffer. /// /// Length of the new buffer. + /// When the timeout exceeds after an item has been added and the not yet been exceeded, is invoked. + /// The with which to interpret . + /// The operation to execute when the exceeds if the buffer is neither empty nor full. /// Name of the new buffer. - /// When is less than . - public BatchBuffer(int capacity, string? name = null) + public BatchBuffer(int capacity, TimeSpan timeout, ISystemClock clock, Action, DateTimeOffset> timeoutExceededAction, string? name = null) { ThrowIfLessThanTwo(capacity, nameof(capacity)); - Name = name ?? "default"; + ThrowIfNegativeOrZero(timeout, nameof(timeout)); _array = new T[capacity]; _additions = 0; - _addCounter = new CounterEvent(); - _addLock = new NonReentrantLock(); + _addLock = new ScopedCountdownLock(); + + _clock = clock; + _timer = new Timer(OnIntervalElapsed, this, Timeout.Infinite, Timeout.Infinite); + _timeout = timeout; + + _timeoutExceededAction = timeoutExceededAction; + Name = name ?? "default"; } /// /// Name of the buffer. /// - /// - /// This property is thread-safe. - /// internal string Name { get; } /// /// Maximum number of elements that can be added to the buffer. /// - /// - /// This property is thread-safe. - /// internal int Capacity => _array.Length; /// - /// Have any elements been added to the buffer? + /// Gets a value indicating whether this buffer is empty. /// - /// - /// This property is not thread-safe. - /// internal bool IsEmpty => _additions == 0; /// - /// Have number of elements been added to the buffer? + /// Number of operations in progress. /// /// - /// This property is not thread-safe. + /// This property is used for debugging only. /// - internal bool IsFull => _additions >= _array.Length; + private int AddCount => _addLock.Count; /// - /// Number of operations in progress. + /// Attempt to atomically add one element to the buffer. /// - /// - /// This property is used for debugging only. - /// - private int AddCount => _addCounter.Count; + /// Element attempted to be added atomically. + /// An describing the result of the operation. + internal BatchBufferAddStatus Add(T item) + { + using var scope = _addLock.TryEnterCounterScope(); + if (!scope.IsEntered) + { + return BatchBufferAddStatus.IgnoredIsFlushing; + } + + var count = Interlocked.Increment(ref _additions); + + if (count == 1) + { + EnableTimer(); + _array[count - 1] = item; + return BatchBufferAddStatus.AddedFirst; + } + + if (count < _array.Length) + { + _array[count - 1] = item; + return BatchBufferAddStatus.Added; + } + + if (count == _array.Length) + { + DisableTimer(); + _array[count - 1] = item; + return BatchBufferAddStatus.AddedLast; + } + + Debug.Assert(count > _array.Length); + return BatchBufferAddStatus.IgnoredCapacityExceeded; + } /// /// Enters a used to ensure that only a single flush operation is in progress. /// - /// A that must be disposed to exit. /// - /// This method is thread-safe. + /// Must be disposed to exit. /// - internal FlushScope TryEnterFlushScope(out bool lockTaken) + internal FlushScope TryEnterFlushScope() { - if (_addLock.TryEnter()) + var scope = _addLock.TryEnterLockScope(); + if (scope.IsEntered) { - lockTaken = true; - return new FlushScope(this); + return new FlushScope(this, scope); } - lockTaken = false; return new FlushScope(); } /// /// Exits the through . /// - /// - /// This method is thread-safe. - /// private void ExitFlushScope() { - _addLock.Exit(); + Debug.Assert(_addLock.IsEngaged); } /// - /// Blocks the current thread until all operations have completed. + /// Forces invocation of a Timeout of the active buffer. /// - /// - /// This method is thread-safe. - /// - internal void WaitAddCompleted() + internal void OnIntervalElapsed(object? state) { - _addCounter.Wait(); - } - - /// - /// Attempt to atomically add one element to the buffer. - /// - /// Element attempted to be added atomically. - /// When this method returns , is set to the Length at which the was added at. - /// when was added atomically; when was not added. - /// - /// This method is thread-safe. - /// - internal bool TryAdd(T item, out int count) - { - if (_addLock.IsEntered) - { - count = 0; - return false; - } - - using var scope = _addCounter.EnterScope(); - - count = Interlocked.Increment(ref _additions); - - if (count <= _array.Length) - { - _array[count - 1] = item; - return true; - } - - return false; + var now = _clock.GetUtcNow(); + _timeoutExceededAction(this, now); } /// /// Returns a new Array consisting of the elements successfully added. /// /// An Array with Length of successful additions. - /// - /// This method is not thread-safe. - /// - internal T[] ToArrayAndClear() + private T[] ToArrayAndClear() { var additions = _additions; var length = _array.Length; @@ -169,12 +166,10 @@ internal T[] ToArrayAndClear() /// /// The Length of the buffer a new Array is created from. /// An Array with Length of . - /// - /// This method is not thread-safe. - /// - internal T[] ToArrayAndClear(int length) + private T[] ToArrayAndClear(int length) { - Debug.Assert(_addCounter.IsSet); + Debug.Assert(_addLock.IsSet); + var array = ToArray(length); Clear(length); return array; @@ -203,35 +198,87 @@ private void Clear(int length) Array.Clear(_array, 0, length); } + private void EnableTimer() + { + var updated = _timer.Change(_timeout, Timeout.InfiniteTimeSpan); + Debug.Assert(updated, "Timer was not successfully enabled."); + } + + private void DisableTimer() + { + var updated = _timer.Change(Timeout.Infinite, Timeout.Infinite); + Debug.Assert(updated, "Timer was not successfully disabled."); + } + /// public void Dispose() { - _addCounter.Dispose(); + _timer.Dispose(); + _addLock.Dispose(); } - private static void ThrowIfLessThanTwo(int capacity, string paramName) + private static void ThrowIfLessThanTwo(int value, string paramName) { - if (capacity < 2) + if (value < 2) { - ThrowLessThanTwo(capacity, paramName); + ThrowLessThanTwo(value, paramName); + } + + static void ThrowLessThanTwo(int value, string paramName) + { + throw new ArgumentOutOfRangeException(paramName, value, "Argument must be at least two."); } } - private static void ThrowLessThanTwo(int capacity, string paramName) + private static void ThrowIfNegativeOrZero(TimeSpan value, string paramName) { - throw new ArgumentOutOfRangeException(paramName, capacity, "Argument must be at least two."); + if (value <= TimeSpan.Zero && value != Timeout.InfiniteTimeSpan) + { + ThrowNegativeOrZero(value, paramName); + } + + static void ThrowNegativeOrZero(TimeSpan value, string paramName) + { + throw new ArgumentOutOfRangeException(paramName, value, "Argument must be a non-negative and non-zero value."); + } } + /// + /// A scope than ensures only a single operation is in progress, + /// and blocks the calling thread until all operations have finished. + /// When is , no more can be started, + /// which will then return immediately. + /// + /// + /// Only when scope . + /// internal ref struct FlushScope : IDisposable { private BatchBuffer? _lockObj; + private ScopedCountdownLock.LockScope _scope; - internal FlushScope(BatchBuffer lockObj) + internal FlushScope(BatchBuffer lockObj, ScopedCountdownLock.LockScope scope) { _lockObj = lockObj; + _scope = scope; } - internal bool IsEntered => _lockObj is not null; + internal bool IsEntered => _scope.IsEntered; + + internal T[] Flush() + { + var lockObj = _lockObj; + if (lockObj is not null) + { + lockObj._lastFlush = lockObj._clock.GetUtcNow(); + _scope.Wait(); + + var array = lockObj.ToArrayAndClear(); + return array; + } + + throw new ObjectDisposedException(nameof(FlushScope)); + } public void Dispose() { @@ -241,6 +288,17 @@ public void Dispose() _lockObj = null; lockObj.ExitFlushScope(); } + + _scope.Dispose(); } } } + +internal enum BatchBufferAddStatus : byte +{ + AddedFirst, + Added, + AddedLast, + IgnoredCapacityExceeded, + IgnoredIsFlushing, +} diff --git a/src/Sentry/Internal/BatchProcessor.cs b/src/Sentry/Internal/BatchProcessor.cs index f167c5fd50..91e96cd387 100644 --- a/src/Sentry/Internal/BatchProcessor.cs +++ b/src/Sentry/Internal/BatchProcessor.cs @@ -2,7 +2,6 @@ using Sentry.Infrastructure; using Sentry.Protocol; using Sentry.Protocol.Envelopes; -using Sentry.Threading; namespace Sentry.Internal; @@ -18,35 +17,22 @@ namespace Sentry.Internal; internal sealed class BatchProcessor : IDisposable { private readonly IHub _hub; - private readonly TimeSpan _batchInterval; - private readonly ISystemClock _clock; private readonly IClientReportRecorder _clientReportRecorder; private readonly IDiagnosticLogger? _diagnosticLogger; - private readonly Timer _timer; - private readonly object _timerCallbackLock; private readonly BatchBuffer _buffer1; private readonly BatchBuffer _buffer2; private volatile BatchBuffer _activeBuffer; - private readonly NonReentrantLock _swapLock; - - private DateTimeOffset _lastFlush = DateTimeOffset.MinValue; public BatchProcessor(IHub hub, int batchCount, TimeSpan batchInterval, ISystemClock clock, IClientReportRecorder clientReportRecorder, IDiagnosticLogger? diagnosticLogger) { _hub = hub; - _batchInterval = batchInterval; - _clock = clock; _clientReportRecorder = clientReportRecorder; _diagnosticLogger = diagnosticLogger; - _timer = new Timer(OnIntervalElapsed, this, Timeout.Infinite, Timeout.Infinite); - _timerCallbackLock = new object(); - - _buffer1 = new BatchBuffer(batchCount, "Buffer 1"); - _buffer2 = new BatchBuffer(batchCount, "Buffer 2"); + _buffer1 = new BatchBuffer(batchCount, batchInterval, clock, OnTimeoutExceeded, "Buffer 1"); + _buffer2 = new BatchBuffer(batchCount, batchInterval, clock, OnTimeoutExceeded, "Buffer 2"); _activeBuffer = _buffer1; - _swapLock = new NonReentrantLock(); } internal void Enqueue(SentryLog log) @@ -66,98 +52,67 @@ internal void Enqueue(SentryLog log) internal void Flush() { - DisableTimer(); - Flush(_buffer1); - Flush(_buffer2); + CaptureLogs(_buffer1); + CaptureLogs(_buffer2); } - private bool TryEnqueue(BatchBuffer buffer, SentryLog log) + internal void OnIntervalElapsed() { - if (buffer.TryAdd(log, out var count)) - { - if (count == 1) // is first element added to buffer after flushed - { - EnableTimer(); - } - - if (count == buffer.Capacity) // is buffer full - { - using var flushScope = buffer.TryEnterFlushScope(out var lockTaken); - DisableTimer(); + var activeBuffer = _activeBuffer; + activeBuffer.OnIntervalElapsed(activeBuffer); + } - var currentActiveBuffer = _activeBuffer; - _ = TrySwapBuffer(currentActiveBuffer); - Flush(buffer, count); - } + private bool TryEnqueue(BatchBuffer buffer, SentryLog log) + { + var status = buffer.Add(log); + if (status is BatchBufferAddStatus.AddedLast) + { + TrySwapActiveBuffer(buffer); + CaptureLogs(buffer); return true; } - return false; + return status is BatchBufferAddStatus.AddedFirst or BatchBufferAddStatus.Added; } - private void Flush(BatchBuffer buffer) + private bool TrySwapActiveBuffer(BatchBuffer currentActiveBuffer) { - buffer.WaitAddCompleted(); - _lastFlush = _clock.GetUtcNow(); - - var logs = buffer.ToArrayAndClear(); - _ = _hub.CaptureEnvelope(Envelope.FromLog(new StructuredLog(logs))); + var newActiveBuffer = ReferenceEquals(currentActiveBuffer, _buffer1) ? _buffer2 : _buffer1; + var previousActiveBuffer = Interlocked.CompareExchange(ref _activeBuffer, newActiveBuffer, currentActiveBuffer); + return previousActiveBuffer == currentActiveBuffer; } - private void Flush(BatchBuffer buffer, int count) + private void CaptureLogs(BatchBuffer buffer) { - buffer.WaitAddCompleted(); - _lastFlush = _clock.GetUtcNow(); + SentryLog[]? logs = null; - var logs = buffer.ToArrayAndClear(count); - _ = _hub.CaptureEnvelope(Envelope.FromLog(new StructuredLog(logs))); - } - - internal void OnIntervalElapsed(object? state) - { - lock (_timerCallbackLock) + using (var scope = buffer.TryEnterFlushScope()) { - var currentActiveBuffer = _activeBuffer; - - using var scope = currentActiveBuffer.TryEnterFlushScope(out var lockTaken); - - if (lockTaken && !currentActiveBuffer.IsEmpty && _clock.GetUtcNow() > _lastFlush) + if (scope.IsEntered) { - _ = TrySwapBuffer(currentActiveBuffer); - Flush(currentActiveBuffer); + logs = scope.Flush(); } } - } - - private void EnableTimer() - { - var updated = _timer.Change(_batchInterval, Timeout.InfiniteTimeSpan); - Debug.Assert(updated, "Timer was not successfully enabled."); - } - private void DisableTimer() - { - var updated = _timer.Change(Timeout.Infinite, Timeout.Infinite); - Debug.Assert(updated, "Timer was not successfully disabled."); + if (logs is not null) + { + _ = _hub.CaptureEnvelope(Envelope.FromLog(new StructuredLog(logs))); + } } - private bool TrySwapBuffer(BatchBuffer currentActiveBuffer) + private void OnTimeoutExceeded(BatchBuffer buffer, DateTimeOffset signalTime) { - if (_swapLock.TryEnter()) + if (!buffer.IsEmpty) { - var newActiveBuffer = ReferenceEquals(currentActiveBuffer, _buffer1) ? _buffer2 : _buffer1; - var previousActiveBuffer = Interlocked.CompareExchange(ref _activeBuffer, newActiveBuffer, currentActiveBuffer); - - _swapLock.Exit(); - return previousActiveBuffer == currentActiveBuffer; + TrySwapActiveBuffer(buffer); + CaptureLogs(buffer); } - - return false; } public void Dispose() { - _timer.Dispose(); + _buffer1.Dispose(); + _buffer2.Dispose(); } } diff --git a/src/Sentry/Threading/CounterEvent.cs b/src/Sentry/Threading/CounterEvent.cs deleted file mode 100644 index f96cdfaeca..0000000000 --- a/src/Sentry/Threading/CounterEvent.cs +++ /dev/null @@ -1,96 +0,0 @@ -namespace Sentry.Threading; - -/// -/// A synchronization primitive that tracks the amount of s held. -/// -[DebuggerDisplay("Count = {Count}, IsSet = {IsSet}")] -internal sealed class CounterEvent : IDisposable -{ - private readonly ManualResetEventSlim _event; - private int _count; - - internal CounterEvent() - { - _event = new ManualResetEventSlim(true); - _count = 0; - } - - /// - /// if the event is set/signaled; otherwise, . - /// - /// When , blocks the calling thread until reaches . - public bool IsSet => _event.IsSet; - - /// - /// Gets the number of remaining s required to exit to set/signal the event. - /// - /// When , the state of the event is set/signaled, which allows the thread ing on the event to proceed. - internal int Count => _count; - - /// - /// Enter a . - /// Sets the state of the event to non-signaled, which causes ing threads to block. - /// When all s have exited, the event is set/signaled. - /// - /// A new , that must be exited via . - internal Scope EnterScope() - { - var count = Interlocked.Increment(ref _count); - Debug.Assert(count > 0); - - if (count == 1) - { - _event.Reset(); - } - - return new Scope(this); - } - - private void ExitScope() - { - var count = Interlocked.Decrement(ref _count); - Debug.Assert(count >= 0); - - if (count == 0) - { - _event.Set(); - } - } - - /// - /// Blocks the current thread until the current reaches and the event is set/signaled. - /// - /// - /// The caller of this method blocks until reaches . - /// The caller will return immediately if the event is currently in a set/signaled state. - /// - internal void Wait() - { - _event.Wait(); - } - - public void Dispose() - { - _event.Dispose(); - } - - internal ref struct Scope : IDisposable - { - private CounterEvent? _event; - - internal Scope(CounterEvent @event) - { - _event = @event; - } - - public void Dispose() - { - var @event = _event; - if (@event is not null) - { - _event = null; - @event.ExitScope(); - } - } - } -} diff --git a/src/Sentry/Threading/NonReentrantLock.cs b/src/Sentry/Threading/NonReentrantLock.cs deleted file mode 100644 index 9e72247707..0000000000 --- a/src/Sentry/Threading/NonReentrantLock.cs +++ /dev/null @@ -1,27 +0,0 @@ -namespace Sentry.Threading; - -[DebuggerDisplay("IsEntered = {IsEntered}")] -internal sealed class NonReentrantLock -{ - private int _state; - - internal NonReentrantLock() - { - _state = 0; - } - - internal bool IsEntered => _state == 1; - - internal bool TryEnter() - { - return Interlocked.CompareExchange(ref _state, 1, 0) == 0; - } - - internal void Exit() - { - if (Interlocked.Exchange(ref _state, 0) != 1) - { - Debug.Fail("Do not Exit the lock scope when it has not been Entered."); - } - } -} diff --git a/src/Sentry/Threading/ScopedCountdownLock.cs b/src/Sentry/Threading/ScopedCountdownLock.cs new file mode 100644 index 0000000000..b91d605f61 --- /dev/null +++ b/src/Sentry/Threading/ScopedCountdownLock.cs @@ -0,0 +1,149 @@ +namespace Sentry.Threading; + +/// +/// A synchronization primitive that tracks the amount of s held, +/// and is signaled when the count reaches zero while a is held. +/// +/// +/// Similar to , +/// but allows to increment the current count after the count has reached zero without resetting to the initial count before a is entered. +/// Has a similar API shape to System.Threading.Lock. +/// +[DebuggerDisplay("IsSet = {IsSet}, Count = {Count}, IsEngaged = {IsEngaged}")] +internal sealed class ScopedCountdownLock : IDisposable +{ + private readonly CountdownEvent _event; + private volatile int _isEngaged; + + internal ScopedCountdownLock() + { + _event = new CountdownEvent(1); + _isEngaged = 0; + } + + /// + /// if the event is set/signaled; otherwise, . + /// When , the active can until the reaches . + /// + internal bool IsSet => _event.IsSet; + + /// + /// Gets the number of remaining required to exit in order to set/signal the event while a is active. + /// When and while a is active, no more can be entered. + /// + internal int Count => _isEngaged == 1 ? _event.CurrentCount : _event.CurrentCount - 1; + + /// + /// Determines whether the event can be set/signaled by reaching . + /// Returns when a is active. + /// + internal bool IsEngaged => _isEngaged == 1; + + /// + /// No will be entered when the has reached while the lock is engaged via an active . + /// Check via whether the underlying has not been set/signaled yet. + /// To signal the underlying , ensure is called. + /// + internal CounterScope TryEnterCounterScope() + { + if (_event.TryAddCount(1)) + { + return new CounterScope(this); + } + + return new CounterScope(); + } + + private void ExitCounterScope() + { + _ = _event.Signal(); + } + + /// + /// When successful, the lock , can reach and the event be set/signaled. + /// Check via whether the Lock . + /// Use to block until every active has exited before performing the locked operation. + /// After the locked operation has completed, disengage the Lock via . + /// + internal LockScope TryEnterLockScope() + { + if (Interlocked.CompareExchange(ref _isEngaged, 1, 0) == 0) + { + _ = _event.Signal(); + return new LockScope(this); + } + + return new LockScope(); + } + + private void ExitLockScope() + { + if (Interlocked.CompareExchange(ref _isEngaged, 0, 1) == 1) + { + _event.Reset(); + return; + } + + Debug.Fail("The Lock should have not been disengaged without being engaged first."); + } + + /// + public void Dispose() + { + _event.Dispose(); + } + + internal ref struct CounterScope : IDisposable + { + private ScopedCountdownLock? _lockObj; + + internal CounterScope(ScopedCountdownLock lockObj) + { + _lockObj = lockObj; + } + + internal bool IsEntered => _lockObj is not null; + + public void Dispose() + { + var lockObj = _lockObj; + if (lockObj is not null) + { + _lockObj = null; + lockObj.ExitCounterScope(); + } + } + } + + internal ref struct LockScope : IDisposable + { + private ScopedCountdownLock? _lockObj; + + internal LockScope(ScopedCountdownLock lockObj) + { + _lockObj = lockObj; + } + + internal bool IsEntered => _lockObj is not null; + + /// + /// Blocks the current thread until the current reaches and the event is set/signaled. + /// The caller will return immediately if the event is currently in a set/signaled state. + /// + internal void Wait() + { + var lockObj = _lockObj; + lockObj?._event.Wait(); + } + + public void Dispose() + { + var lockObj = _lockObj; + if (lockObj is not null) + { + _lockObj = null; + lockObj.ExitLockScope(); + } + } + } +} diff --git a/test/Sentry.Tests/ApiApprovalTests.Run.DotNet8_0.verified.txt b/test/Sentry.Tests/ApiApprovalTests.Run.DotNet8_0.verified.txt index d16b051657..afe6c36ae0 100644 --- a/test/Sentry.Tests/ApiApprovalTests.Run.DotNet8_0.verified.txt +++ b/test/Sentry.Tests/ApiApprovalTests.Run.DotNet8_0.verified.txt @@ -1017,6 +1017,7 @@ namespace Sentry { public void Dispose() { } protected virtual void Dispose(bool disposing) { } + protected virtual void Flush() { } [System.Diagnostics.CodeAnalysis.Experimental("SENTRY0001")] public void LogDebug(string template, object[]? parameters = null, System.Action? configureLog = null) { } [System.Diagnostics.CodeAnalysis.Experimental("SENTRY0001")] diff --git a/test/Sentry.Tests/ApiApprovalTests.Run.DotNet9_0.verified.txt b/test/Sentry.Tests/ApiApprovalTests.Run.DotNet9_0.verified.txt index d16b051657..afe6c36ae0 100644 --- a/test/Sentry.Tests/ApiApprovalTests.Run.DotNet9_0.verified.txt +++ b/test/Sentry.Tests/ApiApprovalTests.Run.DotNet9_0.verified.txt @@ -1017,6 +1017,7 @@ namespace Sentry { public void Dispose() { } protected virtual void Dispose(bool disposing) { } + protected virtual void Flush() { } [System.Diagnostics.CodeAnalysis.Experimental("SENTRY0001")] public void LogDebug(string template, object[]? parameters = null, System.Action? configureLog = null) { } [System.Diagnostics.CodeAnalysis.Experimental("SENTRY0001")] diff --git a/test/Sentry.Tests/ApiApprovalTests.Run.Net4_8.verified.txt b/test/Sentry.Tests/ApiApprovalTests.Run.Net4_8.verified.txt index 1664c48d92..633f821c1f 100644 --- a/test/Sentry.Tests/ApiApprovalTests.Run.Net4_8.verified.txt +++ b/test/Sentry.Tests/ApiApprovalTests.Run.Net4_8.verified.txt @@ -977,6 +977,7 @@ namespace Sentry { public void Dispose() { } protected virtual void Dispose(bool disposing) { } + protected virtual void Flush() { } public void LogDebug(string template, object[]? parameters = null, System.Action? configureLog = null) { } public void LogError(string template, object[]? parameters = null, System.Action? configureLog = null) { } public void LogFatal(string template, object[]? parameters = null, System.Action? configureLog = null) { } diff --git a/test/Sentry.Tests/Internals/BatchBufferTests.cs b/test/Sentry.Tests/Internals/BatchBufferTests.cs index fa8116ac9a..6c822ab9ba 100644 --- a/test/Sentry.Tests/Internals/BatchBufferTests.cs +++ b/test/Sentry.Tests/Internals/BatchBufferTests.cs @@ -1,151 +1,247 @@ +#nullable enable + namespace Sentry.Tests.Internals; public class BatchBufferTests { + private sealed class Fixture + { + public int Capacity { get; set; } = 2; + public TimeSpan Timeout { get; set; } = System.Threading.Timeout.InfiniteTimeSpan; + public MockClock Clock { get; } = new(); + public List<(BatchBuffer Buffer, DateTimeOffset SignalTime)> TimeoutExceededInvocations { get; } = new(); + public string? Name { get; set; } + + public BatchBuffer GetSut() + { + return new BatchBuffer(Capacity, Timeout, Clock, OnTimeoutExceeded, Name); + } + + private void OnTimeoutExceeded(BatchBuffer buffer, DateTimeOffset signalTime) + { + TimeoutExceededInvocations.Add((buffer, signalTime)); + } + } + + private readonly Fixture _fixture = new(); + [Theory] [InlineData(-1)] [InlineData(0)] [InlineData(1)] public void Ctor_CapacityIsOutOfRange_Throws(int capacity) { - var ctor = () => new BatchBuffer(capacity); + _fixture.Capacity = capacity; + + var ctor = () => _fixture.GetSut(); Assert.Throws("capacity", ctor); } - [Fact] - public void TryAdd_CapacityTwo_CanAddTwice() + [Theory] + [InlineData(-2)] + [InlineData(0)] + public void Ctor_TimeoutIsOutOfRange_Throws(int millisecondsTimeout) { - var buffer = new BatchBuffer(2); - AssertEmpty(buffer, 2); - - buffer.TryAdd("one", out var first).Should().BeTrue(); - Assert.Equal(1, first); - AssertPartial(buffer, 2); + _fixture.Timeout = TimeSpan.FromMilliseconds(millisecondsTimeout); - buffer.TryAdd("two", out var second).Should().BeTrue(); - Assert.Equal(2, second); - AssertFull(buffer, 2); + var ctor = () => _fixture.GetSut(); - buffer.TryAdd("three", out var third).Should().BeFalse(); - Assert.Equal(3, third); - AssertFull(buffer, 2); + Assert.Throws("timeout", ctor); } [Fact] - public void TryAdd_CapacityThree_CanAddThrice() + public void Add_CapacityTwo_CanAddTwice() { - var buffer = new BatchBuffer(3); - AssertEmpty(buffer, 3); + _fixture.Capacity = 2; + using var buffer = _fixture.GetSut(); - buffer.TryAdd("one", out var first).Should().BeTrue(); - Assert.Equal(1, first); - AssertPartial(buffer, 3); + buffer.Capacity.Should().Be(2); + buffer.IsEmpty.Should().BeTrue(); - buffer.TryAdd("two", out var second).Should().BeTrue(); - Assert.Equal(2, second); - AssertPartial(buffer, 3); + buffer.Add("one").Should().Be(BatchBufferAddStatus.AddedFirst); + buffer.IsEmpty.Should().BeFalse(); - buffer.TryAdd("three", out var third).Should().BeTrue(); - Assert.Equal(3, third); - AssertFull(buffer, 3); + buffer.Add("two").Should().Be(BatchBufferAddStatus.AddedLast); + buffer.IsEmpty.Should().BeFalse(); - buffer.TryAdd("four", out var fourth).Should().BeFalse(); - Assert.Equal(4, fourth); - AssertFull(buffer, 3); + buffer.Add("three").Should().Be(BatchBufferAddStatus.IgnoredCapacityExceeded); + buffer.IsEmpty.Should().BeFalse(); + + buffer.Add("four").Should().Be(BatchBufferAddStatus.IgnoredCapacityExceeded); + buffer.IsEmpty.Should().BeFalse(); } [Fact] - public void ToArrayAndClear_IsEmpty_EmptyArray() + public void Add_CapacityThree_CanAddThrice() { - var buffer = new BatchBuffer(2); + _fixture.Capacity = 3; + using var buffer = _fixture.GetSut(); + + buffer.Capacity.Should().Be(3); + buffer.IsEmpty.Should().BeTrue(); + + buffer.Add("one").Should().Be(BatchBufferAddStatus.AddedFirst); + buffer.IsEmpty.Should().BeFalse(); - var array = buffer.ToArrayAndClear(); + buffer.Add("two").Should().Be(BatchBufferAddStatus.Added); + buffer.IsEmpty.Should().BeFalse(); - Assert.Empty(array); - AssertEmpty(buffer, 2); + buffer.Add("three").Should().Be(BatchBufferAddStatus.AddedLast); + buffer.IsEmpty.Should().BeFalse(); + + buffer.Add("four").Should().Be(BatchBufferAddStatus.IgnoredCapacityExceeded); + buffer.IsEmpty.Should().BeFalse(); } [Fact] - public void ToArrayAndClear_IsNotEmptyNorFull_PartialCopy() + public void Flush_IsEmpty_EmptyArray() { - var buffer = new BatchBuffer(2); - buffer.TryAdd("one", out _).Should().BeTrue(); + _fixture.Capacity = 2; + using var buffer = _fixture.GetSut(); - var array = buffer.ToArrayAndClear(); + using var flushScope = buffer.TryEnterFlushScope(); + var array = flushScope.Flush(); - Assert.Collection(array, - item => Assert.Equal("one", item)); - AssertEmpty(buffer, 2); + array.Should().BeEmpty(); + buffer.Capacity.Should().Be(2); + buffer.IsEmpty.Should().BeTrue(); } [Fact] - public void ToArrayAndClear_IsFull_FullCopy() + public void Flush_IsNotEmptyNorFull_PartialCopy() { - var buffer = new BatchBuffer(2); - buffer.TryAdd("one", out _).Should().BeTrue(); - buffer.TryAdd("two", out _).Should().BeTrue(); + _fixture.Capacity = 2; + using var buffer = _fixture.GetSut(); - var array = buffer.ToArrayAndClear(); + buffer.Add("one"); + using var flushScope = buffer.TryEnterFlushScope(); + var array = flushScope.Flush(); - Assert.Collection(array, - item => Assert.Equal("one", item), - item => Assert.Equal("two", item)); - AssertEmpty(buffer, 2); + array.Should().Equal(["one"]); + buffer.Capacity.Should().Be(2); + buffer.IsEmpty.Should().BeTrue(); } [Fact] - public void ToArrayAndClear_CapacityExceeded_FullCopy() + public void Flush_IsFull_FullCopy() { - var buffer = new BatchBuffer(2); - buffer.TryAdd("one", out _).Should().BeTrue(); - buffer.TryAdd("two", out _).Should().BeTrue(); - buffer.TryAdd("three", out _).Should().BeFalse(); + _fixture.Capacity = 2; + using var buffer = _fixture.GetSut(); + + buffer.Add("one"); + buffer.Add("two"); + using var flushScope = buffer.TryEnterFlushScope(); + var array = flushScope.Flush(); - var array = buffer.ToArrayAndClear(); + array.Should().Equal(["one", "two"]); + buffer.Capacity.Should().Be(2); + buffer.IsEmpty.Should().BeTrue(); + } - Assert.Collection(array, - item => Assert.Equal("one", item), - item => Assert.Equal("two", item)); - AssertEmpty(buffer, 2); + [Fact] + public void Flush_CapacityExceeded_FullCopy() + { + _fixture.Capacity = 2; + using var buffer = _fixture.GetSut(); + + buffer.Add("one"); + buffer.Add("two"); + buffer.Add("three"); + using var flushScope = buffer.TryEnterFlushScope(); + var array = flushScope.Flush(); + + array.Should().Equal(["one", "two"]); + buffer.Capacity.Should().Be(2); + buffer.IsEmpty.Should().BeTrue(); } [Fact] - public void ToArrayAndClear_WithLength_PartialCopy() + public void Flush_DoubleFlush_SecondArrayIsEmpty() { - var buffer = new BatchBuffer(2); - buffer.TryAdd("one", out _).Should().BeTrue(); - buffer.TryAdd("two", out _).Should().BeTrue(); + _fixture.Capacity = 2; + using var buffer = _fixture.GetSut(); - var array = buffer.ToArrayAndClear(1); + buffer.Add("one"); + buffer.Add("two"); + using var flushScope = buffer.TryEnterFlushScope(); + var first = flushScope.Flush(); + var second = flushScope.Flush(); - Assert.Collection(array, - item => Assert.Equal("one", item)); - AssertEmpty(buffer, 2); + first.Should().Equal(["one", "two"]); + second.Should().BeEmpty(); } - private static void AssertEmpty(BatchBuffer buffer, int capacity) + [Fact] + public void Flush_SecondFlush_NoFlushNoClear() { - AssertProperties(buffer, capacity, true, false); + _fixture.Capacity = 2; + using var buffer = _fixture.GetSut(); + + buffer.Add("one"); + buffer.Add("two"); + + using (var flushScope = buffer.TryEnterFlushScope()) + { + flushScope.IsEntered.Should().BeTrue(); + buffer.IsEmpty.Should().BeFalse(); + } + + using (var flushScope = buffer.TryEnterFlushScope()) + { + flushScope.IsEntered.Should().BeTrue(); + flushScope.Flush().Should().Equal(["one", "two"]); + buffer.IsEmpty.Should().BeTrue(); + } } - private static void AssertPartial(BatchBuffer buffer, int capacity) + [Fact] + public void Flush_TryEnterFlushScopeTwice_CanOnlyEnterOnce() { - AssertProperties(buffer, capacity, false, false); + _fixture.Capacity = 2; + using var buffer = _fixture.GetSut(); + + buffer.Add("one"); + buffer.Add("two"); + using var first = buffer.TryEnterFlushScope(); + using var second = buffer.TryEnterFlushScope(); + + first.IsEntered.Should().BeTrue(); + second.IsEntered.Should().BeFalse(); + + first.Flush().Should().Equal(["one", "two"]); + AssertFlushThrows(second); } - private static void AssertFull(BatchBuffer buffer, int capacity) + [Fact] + public void Flush_Disposed_Throws() { - AssertProperties(buffer, capacity, false, true); + _fixture.Capacity = 2; + using var buffer = _fixture.GetSut(); + + buffer.Add("one"); + buffer.Add("two"); + var flushScope = buffer.TryEnterFlushScope(); + flushScope.Dispose(); + + AssertFlushThrows(flushScope); } - private static void AssertProperties(BatchBuffer buffer, int capacity, bool empty, bool full) + // cannot use xUnit's Throws() nor Fluent Assertions' ThrowExactly() because the FlushScope is a ref struct + private static void AssertFlushThrows(BatchBuffer.FlushScope flushScope) + where T : Exception { - using (new AssertionScope()) + Exception? exception = null; + try { - buffer.Capacity.Should().Be(capacity); - buffer.IsEmpty.Should().Be(empty); - buffer.IsFull.Should().Be(full); + flushScope.Flush(); } + catch (Exception e) + { + exception = e; + } + + exception.Should().NotBeNull(); + exception.Should().BeOfType(); } } diff --git a/test/Sentry.Tests/Internals/BatchProcessorTests.cs b/test/Sentry.Tests/Internals/BatchProcessorTests.cs index 8facac9598..d37d0be35a 100644 --- a/test/Sentry.Tests/Internals/BatchProcessorTests.cs +++ b/test/Sentry.Tests/Internals/BatchProcessorTests.cs @@ -4,122 +4,115 @@ namespace Sentry.Tests.Internals; public class BatchProcessorTests : IDisposable { - private readonly IHub _hub; - private readonly MockClock _clock; - private readonly ClientReportRecorder _clientReportRecorder; - private readonly InMemoryDiagnosticLogger _diagnosticLogger; - private readonly BlockingCollection _capturedEnvelopes; - - private int _expectedDiagnosticLogs; - - public BatchProcessorTests() + private sealed class Fixture { - var options = new SentryOptions(); + public IHub Hub { get; } + public MockClock Clock { get; } + public ClientReportRecorder ClientReportRecorder { get; } + public InMemoryDiagnosticLogger DiagnosticLogger { get; } + public BlockingCollection CapturedEnvelopes { get; } - _hub = Substitute.For(); - _clock = new MockClock(); - _clientReportRecorder = new ClientReportRecorder(options, _clock); - _diagnosticLogger = new InMemoryDiagnosticLogger(); + public int ExpectedDiagnosticLogs { get; set; } - _capturedEnvelopes = []; - _hub.CaptureEnvelope(Arg.Do(arg => _capturedEnvelopes.Add(arg))); + public Fixture() + { + var options = new SentryOptions(); - _expectedDiagnosticLogs = 0; - } + Hub = Substitute.For(); + Clock = new MockClock(); + ClientReportRecorder = new ClientReportRecorder(options, Clock); + DiagnosticLogger = new InMemoryDiagnosticLogger(); - [Theory(Skip = "May no longer be required after feedback.")] - [InlineData(-1)] - [InlineData(0)] - public void Ctor_CountOutOfRange_Throws(int count) - { - var ctor = () => new BatchProcessor(_hub, count, TimeSpan.FromMilliseconds(10), _clock, _clientReportRecorder, _diagnosticLogger); + CapturedEnvelopes = []; + Hub.CaptureEnvelope(Arg.Do(arg => CapturedEnvelopes.Add(arg))); - Assert.Throws(ctor); + ExpectedDiagnosticLogs = 0; + } + + public BatchProcessor GetSut(int batchCount) + { + return new BatchProcessor(Hub, batchCount, Timeout.InfiniteTimeSpan, Clock, ClientReportRecorder, DiagnosticLogger); + } } - [Theory(Skip = "May no longer be required after feedback.")] - [InlineData(-1)] - [InlineData(0)] - [InlineData(int.MaxValue + 1.0)] - public void Ctor_IntervalOutOfRange_Throws(double interval) - { - var ctor = () => new BatchProcessor(_hub, 1, TimeSpan.FromMilliseconds(interval), _clock, _clientReportRecorder, _diagnosticLogger); + private readonly Fixture _fixture = new(); - Assert.Throws(ctor); + public void Dispose() + { + Assert.Equal(_fixture.ExpectedDiagnosticLogs, _fixture.DiagnosticLogger.Entries.Count); } [Fact] public void Enqueue_NeitherSizeNorTimeoutReached_DoesNotCaptureEnvelope() { - using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _clock, _clientReportRecorder, _diagnosticLogger); + using var processor = _fixture.GetSut(2); processor.Enqueue(CreateLog("one")); - Assert.Empty(_capturedEnvelopes); + Assert.Empty(_fixture.CapturedEnvelopes); AssertEnvelope(); } [Fact] public void Enqueue_SizeReached_CaptureEnvelope() { - using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _clock, _clientReportRecorder, _diagnosticLogger); + using var processor = _fixture.GetSut(2); processor.Enqueue(CreateLog("one")); processor.Enqueue(CreateLog("two")); - Assert.Single(_capturedEnvelopes); + Assert.Single(_fixture.CapturedEnvelopes); AssertEnvelope("one", "two"); } [Fact] public void Enqueue_TimeoutReached_CaptureEnvelope() { - using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _clock, _clientReportRecorder, _diagnosticLogger); + using var processor = _fixture.GetSut(2); processor.Enqueue(CreateLog("one")); + processor.OnIntervalElapsed(); - processor.OnIntervalElapsed(null); - - Assert.Single(_capturedEnvelopes); + Assert.Single(_fixture.CapturedEnvelopes); AssertEnvelope("one"); } [Fact] public void Enqueue_BothSizeAndTimeoutReached_CaptureEnvelopeOnce() { - using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _clock, _clientReportRecorder, _diagnosticLogger); + using var processor = _fixture.GetSut(2); processor.Enqueue(CreateLog("one")); processor.Enqueue(CreateLog("two")); - processor.OnIntervalElapsed(null); + processor.OnIntervalElapsed(); - Assert.Single(_capturedEnvelopes); + Assert.Single(_fixture.CapturedEnvelopes); AssertEnvelope("one", "two"); } [Fact] public void Enqueue_BothTimeoutAndSizeReached_CaptureEnvelopes() { - using var processor = new BatchProcessor(_hub, 2, Timeout.InfiniteTimeSpan, _clock, _clientReportRecorder, _diagnosticLogger); + using var processor = _fixture.GetSut(2); - processor.OnIntervalElapsed(null); + processor.OnIntervalElapsed(); processor.Enqueue(CreateLog("one")); - processor.OnIntervalElapsed(null); + processor.OnIntervalElapsed(); processor.Enqueue(CreateLog("two")); processor.Enqueue(CreateLog("three")); - Assert.Equal(2, _capturedEnvelopes.Count); + Assert.Equal(2, _fixture.CapturedEnvelopes.Count); AssertEnvelopes(["one"], ["two", "three"]); } [Fact] public async Task Enqueue_Concurrency_CaptureEnvelopes() { - const int batchCount = 3; - const int maxDegreeOfParallelism = 5; - const int logsPerTask = 100; + const int batchCount = 5; + const int maxDegreeOfParallelism = 10; + const int logsPerTask = 1_000; - using var processor = new BatchProcessor(_hub, batchCount, Timeout.InfiniteTimeSpan, _clock, _clientReportRecorder, _diagnosticLogger); + using var processor = _fixture.GetSut(batchCount); using var sync = new ManualResetEvent(false); var tasks = new Task[maxDegreeOfParallelism]; @@ -139,9 +132,9 @@ public async Task Enqueue_Concurrency_CaptureEnvelopes() sync.Set(); await Task.WhenAll(tasks).WaitAsync(TimeSpan.FromSeconds(5)); processor.Flush(); - _capturedEnvelopes.CompleteAdding(); + _fixture.CapturedEnvelopes.CompleteAdding(); - var capturedLogs = _capturedEnvelopes + var capturedLogs = _fixture.CapturedEnvelopes .SelectMany(static envelope => envelope.Items) .Select(static item => item.Payload) .OfType() @@ -150,16 +143,16 @@ public async Task Enqueue_Concurrency_CaptureEnvelopes() .Sum(log => log.Items.Length); var droppedLogs = 0; - if (_clientReportRecorder.GenerateClientReport() is { } clientReport) + if (_fixture.ClientReportRecorder.GenerateClientReport() is { } clientReport) { var discardedEvent = Assert.Single(clientReport.DiscardedEvents); Assert.Equal(new DiscardReasonWithCategory(DiscardReason.Backpressure, DataCategory.Default), discardedEvent.Key); droppedLogs = discardedEvent.Value; - _expectedDiagnosticLogs = discardedEvent.Value; + _fixture.ExpectedDiagnosticLogs = discardedEvent.Value; } - var actualInvocations = tasks.Length * logsPerTask; + var actualInvocations = maxDegreeOfParallelism * logsPerTask; if (actualInvocations != capturedLogs + droppedLogs) { Assert.Fail($""" @@ -180,11 +173,11 @@ private void AssertEnvelope(params string[] expected) { if (expected.Length == 0) { - Assert.Empty(_capturedEnvelopes); + Assert.Empty(_fixture.CapturedEnvelopes); return; } - var envelope = Assert.Single(_capturedEnvelopes); + var envelope = Assert.Single(_fixture.CapturedEnvelopes); AssertEnvelope(envelope, expected); } @@ -192,13 +185,13 @@ private void AssertEnvelopes(params string[][] expected) { if (expected.Length == 0) { - Assert.Empty(_capturedEnvelopes); + Assert.Empty(_fixture.CapturedEnvelopes); return; } - Assert.Equal(expected.Length, _capturedEnvelopes.Count); + Assert.Equal(expected.Length, _fixture.CapturedEnvelopes.Count); var index = 0; - foreach (var capturedEnvelope in _capturedEnvelopes) + foreach (var capturedEnvelope in _fixture.CapturedEnvelopes) { AssertEnvelope(capturedEnvelope, expected[index]); index++; @@ -213,9 +206,4 @@ private static void AssertEnvelope(Envelope envelope, string[] expected) Assert.NotNull(log); Assert.Equal(expected, log.Items.ToArray().Select(static item => item.Message)); } - - public void Dispose() - { - Assert.Equal(_expectedDiagnosticLogs, _diagnosticLogger.Entries.Count); - } } diff --git a/test/Sentry.Tests/Threading/ScopedCountdownLockTests.cs b/test/Sentry.Tests/Threading/ScopedCountdownLockTests.cs new file mode 100644 index 0000000000..58bd3f090d --- /dev/null +++ b/test/Sentry.Tests/Threading/ScopedCountdownLockTests.cs @@ -0,0 +1,136 @@ +using Sentry.Threading; + +namespace Sentry.Tests.Threading; + +public class ScopedCountdownLockTests : IDisposable +{ + private readonly ScopedCountdownLock _lock = new(); + + public void Dispose() + { + _lock.Dispose(); + } + + [Fact] + public void Init_IsNotEngaged_IsNotSet() + { + AssertDisengaged(false, 0); + } + + [Fact] + public void TryEnterCounterScope_IsNotEngaged_IsNotSet() + { + // increment the count + var counterOne = _lock.TryEnterCounterScope(); + counterOne.IsEntered.Should().BeTrue(); + AssertDisengaged(false, 1); + + // increment the count + var counterTwo = _lock.TryEnterCounterScope(); + counterTwo.IsEntered.Should().BeTrue(); + AssertDisengaged(false, 2); + + // decrement the count + counterOne.Dispose(); + counterOne.IsEntered.Should().BeFalse(); + AssertDisengaged(false, 1); + + // decrement the count + counterTwo.Dispose(); + counterTwo.IsEntered.Should().BeFalse(); + AssertDisengaged(false, 0); + + // no-op ... already disposed + counterOne.Dispose(); + counterTwo.Dispose(); + AssertDisengaged(false, 0); + + // increment the count + var counterThree = _lock.TryEnterCounterScope(); + counterThree.IsEntered.Should().BeTrue(); + AssertDisengaged(false, 1); + + // decrement the count + counterThree.Dispose(); + counterThree.IsEntered.Should().BeFalse(); + AssertDisengaged(false, 0); + } + + [Fact] + public void TryEnterLockScope_IsEngaged_IsSet() + { + // successfully enter a CounterScope ... increment the count + var counterOne = _lock.TryEnterCounterScope(); + counterOne.IsEntered.Should().BeTrue(); + AssertDisengaged(false, 1); + + // successfully enter a LockScope ... engages the lock + var lockOne = _lock.TryEnterLockScope(); + lockOne.IsEntered.Should().BeTrue(); + AssertEngaged(false, 1); + + // cannot enter another LockScope as long as the lock is already engaged by a LockScope + var lockTwo = _lock.TryEnterLockScope(); + lockTwo.IsEntered.Should().BeFalse(); + AssertEngaged(false, 1); + + // no-op ... LockScope is not entered + lockTwo.Wait(); + lockTwo.Dispose(); + AssertEngaged(false, 1); + + // successfully enter another CounterScope ... lock is engaged but not yet set + var counterTwo = _lock.TryEnterCounterScope(); + counterTwo.IsEntered.Should().BeTrue(); + AssertEngaged(false, 2); + + // exit a CounterScope ... decrement the count + 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 + var counterThree = _lock.TryEnterCounterScope(); + counterThree.IsEntered.Should().BeFalse(); + AssertEngaged(true, 0); + counterThree.Dispose(); + AssertEngaged(true, 0); + + // would block if the count of the engaged lock was not zero + lockOne.Wait(); + + // exit the LockScope ... reset the lock + lockOne.Dispose(); + AssertDisengaged(false, 0); + + // can enter a CounterScope again ... the lock not set + var counterFour = _lock.TryEnterCounterScope(); + counterFour.IsEntered.Should().BeTrue(); + AssertDisengaged(false, 1); + counterFour.Dispose(); + AssertDisengaged(false, 0); + } + + private void AssertEngaged(bool isSet, int count) + { + using (new AssertionScope()) + { + _lock.IsSet.Should().Be(isSet); + _lock.Count.Should().Be(count); + _lock.IsEngaged.Should().BeTrue(); + } + } + + private void AssertDisengaged(bool isSet, int count) + { + using (new AssertionScope()) + { + _lock.IsSet.Should().Be(isSet); + _lock.Count.Should().Be(count); + _lock.IsEngaged.Should().BeFalse(); + } + } +} From c63bc53145e39c086a4d91eaff41d4aca1d27567 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Tue, 22 Jul 2025 16:40:02 +0200 Subject: [PATCH 19/29] ref: rename BatchProcessor to StructuredLogBatchProcessor --- ...BatchProcessorBenchmarks-report-github.md} | 0 ... StructuredLogBatchProcessorBenchmarks.cs} | 6 ++-- .../Internal/DefaultSentryStructuredLogger.cs | 4 +-- ...ssor.cs => StructuredLogBatchProcessor.cs} | 29 ++++++++++++++----- ...cs => StructuredLogBatchProcessorTests.cs} | 8 ++--- 5 files changed, 31 insertions(+), 16 deletions(-) rename benchmarks/Sentry.Benchmarks/BenchmarkDotNet.Artifacts/results/{Sentry.Benchmarks.BatchProcessorBenchmarks-report-github.md => Sentry.Benchmarks.StructuredLogBatchProcessorBenchmarks-report-github.md} (100%) rename benchmarks/Sentry.Benchmarks/{BatchProcessorBenchmarks.cs => StructuredLogBatchProcessorBenchmarks.cs} (81%) rename src/Sentry/Internal/{BatchProcessor.cs => StructuredLogBatchProcessor.cs} (65%) rename test/Sentry.Tests/Internals/{BatchProcessorTests.cs => StructuredLogBatchProcessorTests.cs} (95%) diff --git a/benchmarks/Sentry.Benchmarks/BenchmarkDotNet.Artifacts/results/Sentry.Benchmarks.BatchProcessorBenchmarks-report-github.md b/benchmarks/Sentry.Benchmarks/BenchmarkDotNet.Artifacts/results/Sentry.Benchmarks.StructuredLogBatchProcessorBenchmarks-report-github.md similarity index 100% rename from benchmarks/Sentry.Benchmarks/BenchmarkDotNet.Artifacts/results/Sentry.Benchmarks.BatchProcessorBenchmarks-report-github.md rename to benchmarks/Sentry.Benchmarks/BenchmarkDotNet.Artifacts/results/Sentry.Benchmarks.StructuredLogBatchProcessorBenchmarks-report-github.md diff --git a/benchmarks/Sentry.Benchmarks/BatchProcessorBenchmarks.cs b/benchmarks/Sentry.Benchmarks/StructuredLogBatchProcessorBenchmarks.cs similarity index 81% rename from benchmarks/Sentry.Benchmarks/BatchProcessorBenchmarks.cs rename to benchmarks/Sentry.Benchmarks/StructuredLogBatchProcessorBenchmarks.cs index 1047669977..34410dde54 100644 --- a/benchmarks/Sentry.Benchmarks/BatchProcessorBenchmarks.cs +++ b/benchmarks/Sentry.Benchmarks/StructuredLogBatchProcessorBenchmarks.cs @@ -6,9 +6,9 @@ namespace Sentry.Benchmarks; -public class BatchProcessorBenchmarks +public class StructuredLogBatchProcessorBenchmarks { - private BatchProcessor _batchProcessor; + private StructuredLogBatchProcessor _batchProcessor; private SentryLog _log; [Params(10, 100)] @@ -25,7 +25,7 @@ public void Setup() var clock = new MockClock(); var clientReportRecorder = Substitute.For(); var diagnosticLogger = Substitute.For(); - _batchProcessor = new BatchProcessor(hub, BatchCount, batchInterval, clock, clientReportRecorder, diagnosticLogger); + _batchProcessor = new StructuredLogBatchProcessor(hub, BatchCount, batchInterval, clock, clientReportRecorder, diagnosticLogger); _log = new SentryLog(DateTimeOffset.Now, SentryId.Empty, SentryLogLevel.Trace, "message"); } diff --git a/src/Sentry/Internal/DefaultSentryStructuredLogger.cs b/src/Sentry/Internal/DefaultSentryStructuredLogger.cs index b6d8186860..8cf975919b 100644 --- a/src/Sentry/Internal/DefaultSentryStructuredLogger.cs +++ b/src/Sentry/Internal/DefaultSentryStructuredLogger.cs @@ -9,7 +9,7 @@ internal sealed class DefaultSentryStructuredLogger : SentryStructuredLogger private readonly SentryOptions _options; private readonly ISystemClock _clock; - private readonly BatchProcessor _batchProcessor; + private readonly StructuredLogBatchProcessor _batchProcessor; internal DefaultSentryStructuredLogger(IHub hub, SentryOptions options, ISystemClock clock) { @@ -19,7 +19,7 @@ internal DefaultSentryStructuredLogger(IHub hub, SentryOptions options, ISystemC _options = options; _clock = clock; - _batchProcessor = new BatchProcessor(hub, ClampBatchCount(options.Experimental.InternalBatchSize), ClampBatchInterval(options.Experimental.InternalBatchTimeout), clock, _options.ClientReportRecorder, _options.DiagnosticLogger); + _batchProcessor = new StructuredLogBatchProcessor(hub, ClampBatchCount(options.Experimental.InternalBatchSize), ClampBatchInterval(options.Experimental.InternalBatchTimeout), clock, _options.ClientReportRecorder, _options.DiagnosticLogger); } private static int ClampBatchCount(int batchCount) diff --git a/src/Sentry/Internal/BatchProcessor.cs b/src/Sentry/Internal/StructuredLogBatchProcessor.cs similarity index 65% rename from src/Sentry/Internal/BatchProcessor.cs rename to src/Sentry/Internal/StructuredLogBatchProcessor.cs index 91e96cd387..c26c7cc317 100644 --- a/src/Sentry/Internal/BatchProcessor.cs +++ b/src/Sentry/Internal/StructuredLogBatchProcessor.cs @@ -6,15 +6,30 @@ namespace Sentry.Internal; /// -/// The Sentry Batch Processor. -/// This implementation is not complete yet. -/// Also, the specification is still work in progress. +/// The Batch Processor for Sentry Logs. /// /// -/// Sentry Specification: . -/// OpenTelemetry spec: . +/// Used 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. +/// Flushing blocks the calling thread until all pending add operations have completed. +/// +/// - 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 +/// - Swap currently active buffer when +/// - buffer is full +/// - timeout has exceeded +/// - Batch and Capture logs after swapping currently active buffer +/// - wait until all pending add/enqueue operations have completed (required for timeout) +/// - flush the buffer and capture an envelope containing the batched logs +/// - After flush, logs can be enqueued again into the buffer +/// /// -internal sealed class BatchProcessor : IDisposable +/// Sentry Logs +/// Sentry Batch Processor +/// OpenTelemetry Batch Processor +internal sealed class StructuredLogBatchProcessor : IDisposable { private readonly IHub _hub; private readonly IClientReportRecorder _clientReportRecorder; @@ -24,7 +39,7 @@ internal sealed class BatchProcessor : IDisposable private readonly BatchBuffer _buffer2; private volatile BatchBuffer _activeBuffer; - public BatchProcessor(IHub hub, int batchCount, TimeSpan batchInterval, ISystemClock clock, IClientReportRecorder clientReportRecorder, IDiagnosticLogger? diagnosticLogger) + public StructuredLogBatchProcessor(IHub hub, int batchCount, TimeSpan batchInterval, ISystemClock clock, IClientReportRecorder clientReportRecorder, IDiagnosticLogger? diagnosticLogger) { _hub = hub; _clientReportRecorder = clientReportRecorder; diff --git a/test/Sentry.Tests/Internals/BatchProcessorTests.cs b/test/Sentry.Tests/Internals/StructuredLogBatchProcessorTests.cs similarity index 95% rename from test/Sentry.Tests/Internals/BatchProcessorTests.cs rename to test/Sentry.Tests/Internals/StructuredLogBatchProcessorTests.cs index d37d0be35a..73a496e44b 100644 --- a/test/Sentry.Tests/Internals/BatchProcessorTests.cs +++ b/test/Sentry.Tests/Internals/StructuredLogBatchProcessorTests.cs @@ -2,7 +2,7 @@ namespace Sentry.Tests.Internals; -public class BatchProcessorTests : IDisposable +public class StructuredLogBatchProcessorTests : IDisposable { private sealed class Fixture { @@ -29,9 +29,9 @@ public Fixture() ExpectedDiagnosticLogs = 0; } - public BatchProcessor GetSut(int batchCount) + public StructuredLogBatchProcessor GetSut(int batchCount) { - return new BatchProcessor(Hub, batchCount, Timeout.InfiniteTimeSpan, Clock, ClientReportRecorder, DiagnosticLogger); + return new StructuredLogBatchProcessor(Hub, batchCount, Timeout.InfiniteTimeSpan, Clock, ClientReportRecorder, DiagnosticLogger); } } @@ -120,7 +120,7 @@ public async Task Enqueue_Concurrency_CaptureEnvelopes() { tasks[i] = Task.Factory.StartNew(static state => { - var (sync, logsPerTask, taskIndex, processor) = ((ManualResetEvent, int, int, BatchProcessor))state!; + var (sync, logsPerTask, taskIndex, processor) = ((ManualResetEvent, int, int, StructuredLogBatchProcessor))state!; sync.WaitOne(5_000); for (var i = 0; i < logsPerTask; i++) { From f28cc6d7750e2b5fea81eaf78c1d0a23033ed2c1 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Tue, 22 Jul 2025 17:06:45 +0200 Subject: [PATCH 20/29] ref: rename BatchBuffer to StructuredLogBatchBuffer --- ...hBuffer.cs => StructuredLogBatchBuffer.cs} | 30 +++++++-------- .../Internal/StructuredLogBatchProcessor.cs | 21 +++++----- ...ts.cs => StructuredLogBatchBufferTests.cs} | 38 +++++++++++++------ 3 files changed, 53 insertions(+), 36 deletions(-) rename src/Sentry/Internal/{BatchBuffer.cs => StructuredLogBatchBuffer.cs} (89%) rename test/Sentry.Tests/Internals/{BatchBufferTests.cs => StructuredLogBatchBufferTests.cs} (82%) diff --git a/src/Sentry/Internal/BatchBuffer.cs b/src/Sentry/Internal/StructuredLogBatchBuffer.cs similarity index 89% rename from src/Sentry/Internal/BatchBuffer.cs rename to src/Sentry/Internal/StructuredLogBatchBuffer.cs index ad6cf8684f..7cb00a5002 100644 --- a/src/Sentry/Internal/BatchBuffer.cs +++ b/src/Sentry/Internal/StructuredLogBatchBuffer.cs @@ -11,9 +11,9 @@ namespace Sentry.Internal; /// or when the is exceeded. /// [DebuggerDisplay("Name = {Name}, Capacity = {Capacity}, Additions = {_additions}, AddCount = {AddCount}")] -internal sealed class BatchBuffer : IDisposable +internal sealed class StructuredLogBatchBuffer : IDisposable { - private readonly T[] _array; + private readonly SentryLog[] _array; private int _additions; private readonly ScopedCountdownLock _addLock; @@ -21,7 +21,7 @@ internal sealed class BatchBuffer : IDisposable private readonly Timer _timer; private readonly TimeSpan _timeout; - private readonly Action, DateTimeOffset> _timeoutExceededAction; + private readonly Action _timeoutExceededAction; private DateTimeOffset _lastFlush = DateTimeOffset.MinValue; @@ -33,12 +33,12 @@ internal sealed class BatchBuffer : IDisposable /// The with which to interpret . /// The operation to execute when the exceeds if the buffer is neither empty nor full. /// Name of the new buffer. - public BatchBuffer(int capacity, TimeSpan timeout, ISystemClock clock, Action, DateTimeOffset> timeoutExceededAction, string? name = null) + public StructuredLogBatchBuffer(int capacity, TimeSpan timeout, ISystemClock clock, Action timeoutExceededAction, string? name = null) { ThrowIfLessThanTwo(capacity, nameof(capacity)); ThrowIfNegativeOrZero(timeout, nameof(timeout)); - _array = new T[capacity]; + _array = new SentryLog[capacity]; _additions = 0; _addLock = new ScopedCountdownLock(); @@ -78,7 +78,7 @@ public BatchBuffer(int capacity, TimeSpan timeout, ISystemClock clock, Action /// Element attempted to be added atomically. /// An describing the result of the operation. - internal BatchBufferAddStatus Add(T item) + internal BatchBufferAddStatus Add(SentryLog item) { using var scope = _addLock.TryEnterCounterScope(); if (!scope.IsEntered) @@ -138,7 +138,7 @@ private void ExitFlushScope() } /// - /// Forces invocation of a Timeout of the active buffer. + /// Callback when Timer has elapsed after first item has been added. /// internal void OnIntervalElapsed(object? state) { @@ -150,7 +150,7 @@ internal void OnIntervalElapsed(object? state) /// Returns a new Array consisting of the elements successfully added. /// /// An Array with Length of successful additions. - private T[] ToArrayAndClear() + private SentryLog[] ToArrayAndClear() { var additions = _additions; var length = _array.Length; @@ -166,7 +166,7 @@ private T[] ToArrayAndClear() /// /// The Length of the buffer a new Array is created from. /// An Array with Length of . - private T[] ToArrayAndClear(int length) + private SentryLog[] ToArrayAndClear(int length) { Debug.Assert(_addLock.IsSet); @@ -175,14 +175,14 @@ private T[] ToArrayAndClear(int length) return array; } - private T[] ToArray(int length) + private SentryLog[] ToArray(int length) { if (length == 0) { - return Array.Empty(); + return Array.Empty(); } - var array = new T[length]; + var array = new SentryLog[length]; Array.Copy(_array, array, length); return array; } @@ -254,10 +254,10 @@ static void ThrowNegativeOrZero(TimeSpan value, string paramName) /// internal ref struct FlushScope : IDisposable { - private BatchBuffer? _lockObj; + private StructuredLogBatchBuffer? _lockObj; private ScopedCountdownLock.LockScope _scope; - internal FlushScope(BatchBuffer lockObj, ScopedCountdownLock.LockScope scope) + internal FlushScope(StructuredLogBatchBuffer lockObj, ScopedCountdownLock.LockScope scope) { _lockObj = lockObj; _scope = scope; @@ -265,7 +265,7 @@ internal FlushScope(BatchBuffer lockObj, ScopedCountdownLock.LockScope scope) internal bool IsEntered => _scope.IsEntered; - internal T[] Flush() + internal SentryLog[] Flush() { var lockObj = _lockObj; if (lockObj is not null) diff --git a/src/Sentry/Internal/StructuredLogBatchProcessor.cs b/src/Sentry/Internal/StructuredLogBatchProcessor.cs index c26c7cc317..1b2a318253 100644 --- a/src/Sentry/Internal/StructuredLogBatchProcessor.cs +++ b/src/Sentry/Internal/StructuredLogBatchProcessor.cs @@ -35,9 +35,9 @@ internal sealed class StructuredLogBatchProcessor : IDisposable private readonly IClientReportRecorder _clientReportRecorder; private readonly IDiagnosticLogger? _diagnosticLogger; - private readonly BatchBuffer _buffer1; - private readonly BatchBuffer _buffer2; - private volatile BatchBuffer _activeBuffer; + private readonly StructuredLogBatchBuffer _buffer1; + private readonly StructuredLogBatchBuffer _buffer2; + private volatile StructuredLogBatchBuffer _activeBuffer; public StructuredLogBatchProcessor(IHub hub, int batchCount, TimeSpan batchInterval, ISystemClock clock, IClientReportRecorder clientReportRecorder, IDiagnosticLogger? diagnosticLogger) { @@ -45,8 +45,8 @@ public StructuredLogBatchProcessor(IHub hub, int batchCount, TimeSpan batchInter _clientReportRecorder = clientReportRecorder; _diagnosticLogger = diagnosticLogger; - _buffer1 = new BatchBuffer(batchCount, batchInterval, clock, OnTimeoutExceeded, "Buffer 1"); - _buffer2 = new BatchBuffer(batchCount, batchInterval, clock, OnTimeoutExceeded, "Buffer 2"); + _buffer1 = new StructuredLogBatchBuffer(batchCount, batchInterval, clock, OnTimeoutExceeded, "Buffer 1"); + _buffer2 = new StructuredLogBatchBuffer(batchCount, batchInterval, clock, OnTimeoutExceeded, "Buffer 2"); _activeBuffer = _buffer1; } @@ -71,13 +71,16 @@ internal void Flush() CaptureLogs(_buffer2); } + /// + /// Forces invocation of a Timeout of the active buffer. + /// internal void OnIntervalElapsed() { var activeBuffer = _activeBuffer; activeBuffer.OnIntervalElapsed(activeBuffer); } - private bool TryEnqueue(BatchBuffer buffer, SentryLog log) + private bool TryEnqueue(StructuredLogBatchBuffer buffer, SentryLog log) { var status = buffer.Add(log); @@ -91,14 +94,14 @@ private bool TryEnqueue(BatchBuffer buffer, SentryLog log) return status is BatchBufferAddStatus.AddedFirst or BatchBufferAddStatus.Added; } - private bool TrySwapActiveBuffer(BatchBuffer currentActiveBuffer) + private bool TrySwapActiveBuffer(StructuredLogBatchBuffer currentActiveBuffer) { var newActiveBuffer = ReferenceEquals(currentActiveBuffer, _buffer1) ? _buffer2 : _buffer1; var previousActiveBuffer = Interlocked.CompareExchange(ref _activeBuffer, newActiveBuffer, currentActiveBuffer); return previousActiveBuffer == currentActiveBuffer; } - private void CaptureLogs(BatchBuffer buffer) + private void CaptureLogs(StructuredLogBatchBuffer buffer) { SentryLog[]? logs = null; @@ -116,7 +119,7 @@ private void CaptureLogs(BatchBuffer buffer) } } - private void OnTimeoutExceeded(BatchBuffer buffer, DateTimeOffset signalTime) + private void OnTimeoutExceeded(StructuredLogBatchBuffer buffer, DateTimeOffset signalTime) { if (!buffer.IsEmpty) { diff --git a/test/Sentry.Tests/Internals/BatchBufferTests.cs b/test/Sentry.Tests/Internals/StructuredLogBatchBufferTests.cs similarity index 82% rename from test/Sentry.Tests/Internals/BatchBufferTests.cs rename to test/Sentry.Tests/Internals/StructuredLogBatchBufferTests.cs index 6c822ab9ba..dc31dd0921 100644 --- a/test/Sentry.Tests/Internals/BatchBufferTests.cs +++ b/test/Sentry.Tests/Internals/StructuredLogBatchBufferTests.cs @@ -2,22 +2,22 @@ namespace Sentry.Tests.Internals; -public class BatchBufferTests +public class StructuredLogBatchBufferTests { private sealed class Fixture { public int Capacity { get; set; } = 2; public TimeSpan Timeout { get; set; } = System.Threading.Timeout.InfiniteTimeSpan; public MockClock Clock { get; } = new(); - public List<(BatchBuffer Buffer, DateTimeOffset SignalTime)> TimeoutExceededInvocations { get; } = new(); + public List<(StructuredLogBatchBuffer Buffer, DateTimeOffset SignalTime)> TimeoutExceededInvocations { get; } = new(); public string? Name { get; set; } - public BatchBuffer GetSut() + public StructuredLogBatchBuffer GetSut() { - return new BatchBuffer(Capacity, Timeout, Clock, OnTimeoutExceeded, Name); + return new StructuredLogBatchBuffer(Capacity, Timeout, Clock, OnTimeoutExceeded, Name); } - private void OnTimeoutExceeded(BatchBuffer buffer, DateTimeOffset signalTime) + private void OnTimeoutExceeded(StructuredLogBatchBuffer buffer, DateTimeOffset signalTime) { TimeoutExceededInvocations.Add((buffer, signalTime)); } @@ -118,7 +118,7 @@ public void Flush_IsNotEmptyNorFull_PartialCopy() using var flushScope = buffer.TryEnterFlushScope(); var array = flushScope.Flush(); - array.Should().Equal(["one"]); + array.Messages().Should().Equal(["one"]); buffer.Capacity.Should().Be(2); buffer.IsEmpty.Should().BeTrue(); } @@ -134,7 +134,7 @@ public void Flush_IsFull_FullCopy() using var flushScope = buffer.TryEnterFlushScope(); var array = flushScope.Flush(); - array.Should().Equal(["one", "two"]); + array.Messages().Should().Equal(["one", "two"]); buffer.Capacity.Should().Be(2); buffer.IsEmpty.Should().BeTrue(); } @@ -151,7 +151,7 @@ public void Flush_CapacityExceeded_FullCopy() using var flushScope = buffer.TryEnterFlushScope(); var array = flushScope.Flush(); - array.Should().Equal(["one", "two"]); + array.Messages().Should().Equal(["one", "two"]); buffer.Capacity.Should().Be(2); buffer.IsEmpty.Should().BeTrue(); } @@ -168,7 +168,7 @@ public void Flush_DoubleFlush_SecondArrayIsEmpty() var first = flushScope.Flush(); var second = flushScope.Flush(); - first.Should().Equal(["one", "two"]); + first.Messages().Should().Equal(["one", "two"]); second.Should().BeEmpty(); } @@ -190,7 +190,7 @@ public void Flush_SecondFlush_NoFlushNoClear() using (var flushScope = buffer.TryEnterFlushScope()) { flushScope.IsEntered.Should().BeTrue(); - flushScope.Flush().Should().Equal(["one", "two"]); + flushScope.Flush().Messages().Should().Equal(["one", "two"]); buffer.IsEmpty.Should().BeTrue(); } } @@ -209,7 +209,7 @@ public void Flush_TryEnterFlushScopeTwice_CanOnlyEnterOnce() first.IsEntered.Should().BeTrue(); second.IsEntered.Should().BeFalse(); - first.Flush().Should().Equal(["one", "two"]); + first.Flush().Messages().Should().Equal(["one", "two"]); AssertFlushThrows(second); } @@ -228,7 +228,7 @@ public void Flush_Disposed_Throws() } // cannot use xUnit's Throws() nor Fluent Assertions' ThrowExactly() because the FlushScope is a ref struct - private static void AssertFlushThrows(BatchBuffer.FlushScope flushScope) + private static void AssertFlushThrows(StructuredLogBatchBuffer.FlushScope flushScope) where T : Exception { Exception? exception = null; @@ -245,3 +245,17 @@ private static void AssertFlushThrows(BatchBuffer.FlushScope flushSco exception.Should().BeOfType(); } } + +file static class StructuredLogBatchBufferHelpers +{ + public static BatchBufferAddStatus Add(this StructuredLogBatchBuffer buffer, string item) + { + SentryLog log = new(DateTimeOffset.MinValue, SentryId.Empty, SentryLogLevel.Trace, item); + return buffer.Add(log); + } + + public static string[] Messages(this SentryLog[] logs) + { + return logs.Select(static log => log.Message).ToArray(); + } +} From 79ce02e6988d8b13773d39dc7e2affb862f00318 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Wed, 23 Jul 2025 14:27:54 +0200 Subject: [PATCH 21/29] ref: remove internal options --- .../Internal/DefaultSentryStructuredLogger.cs | 20 ++------------- .../Internal/StructuredLogBatchProcessor.cs | 2 +- src/Sentry/SentryOptions.cs | 17 ------------- src/Sentry/SentryStructuredLogger.cs | 5 +++- ...piApprovalTests.Run.DotNet8_0.verified.txt | 2 -- ...piApprovalTests.Run.DotNet9_0.verified.txt | 2 -- .../ApiApprovalTests.Run.Net4_8.verified.txt | 2 -- test/Sentry.Tests/HubTests.cs | 25 +++++++++++++++++-- .../SentryStructuredLoggerTests.cs | 20 +++++++++------ 9 files changed, 42 insertions(+), 53 deletions(-) diff --git a/src/Sentry/Internal/DefaultSentryStructuredLogger.cs b/src/Sentry/Internal/DefaultSentryStructuredLogger.cs index 8cf975919b..56809bb9ce 100644 --- a/src/Sentry/Internal/DefaultSentryStructuredLogger.cs +++ b/src/Sentry/Internal/DefaultSentryStructuredLogger.cs @@ -11,7 +11,7 @@ internal sealed class DefaultSentryStructuredLogger : SentryStructuredLogger private readonly StructuredLogBatchProcessor _batchProcessor; - internal DefaultSentryStructuredLogger(IHub hub, SentryOptions options, ISystemClock clock) + internal DefaultSentryStructuredLogger(IHub hub, SentryOptions options, ISystemClock clock, int batchCount, TimeSpan batchInterval) { Debug.Assert(options is { Experimental.EnableLogs: true }); @@ -19,23 +19,7 @@ internal DefaultSentryStructuredLogger(IHub hub, SentryOptions options, ISystemC _options = options; _clock = clock; - _batchProcessor = new StructuredLogBatchProcessor(hub, ClampBatchCount(options.Experimental.InternalBatchSize), ClampBatchInterval(options.Experimental.InternalBatchTimeout), clock, _options.ClientReportRecorder, _options.DiagnosticLogger); - } - - private static int ClampBatchCount(int batchCount) - { - return batchCount <= 0 - ? 1 - : batchCount > 1_000_000 - ? 1_000_000 - : batchCount; - } - - private static TimeSpan ClampBatchInterval(TimeSpan batchInterval) - { - return batchInterval.TotalMilliseconds is <= 0 or > int.MaxValue - ? TimeSpan.FromMilliseconds(int.MaxValue) - : batchInterval; + _batchProcessor = new StructuredLogBatchProcessor(hub, batchCount, batchInterval, clock, _options.ClientReportRecorder, _options.DiagnosticLogger); } /// diff --git a/src/Sentry/Internal/StructuredLogBatchProcessor.cs b/src/Sentry/Internal/StructuredLogBatchProcessor.cs index 1b2a318253..60275cd4dd 100644 --- a/src/Sentry/Internal/StructuredLogBatchProcessor.cs +++ b/src/Sentry/Internal/StructuredLogBatchProcessor.cs @@ -113,7 +113,7 @@ private void CaptureLogs(StructuredLogBatchBuffer buffer) } } - if (logs is not null) + if (logs is not null && logs.Length != 0) { _ = _hub.CaptureEnvelope(Envelope.FromLog(new StructuredLog(logs))); } diff --git a/src/Sentry/SentryOptions.cs b/src/Sentry/SentryOptions.cs index 8c1d9e0be0..c64bd6a288 100644 --- a/src/Sentry/SentryOptions.cs +++ b/src/Sentry/SentryOptions.cs @@ -1897,22 +1897,5 @@ public void SetBeforeSendLog(Func beforeSendLog) { _beforeSendLog = beforeSendLog; } - - /// - /// This API will be removed in the future. - /// - /// - /// Threshold of items in the buffer when sending all items, regardless of . - /// - public int InternalBatchSize { get; set; } = 100; - - /// - /// This API will be removed in the future. - /// - /// - /// Time after which all items in the buffer are sent, regardless of . - /// Must not exceed 30 seconds. - /// - public TimeSpan InternalBatchTimeout { get; set; } = TimeSpan.FromSeconds(5); } } diff --git a/src/Sentry/SentryStructuredLogger.cs b/src/Sentry/SentryStructuredLogger.cs index 33005e5964..241b16fe6f 100644 --- a/src/Sentry/SentryStructuredLogger.cs +++ b/src/Sentry/SentryStructuredLogger.cs @@ -11,9 +11,12 @@ namespace Sentry; public abstract class SentryStructuredLogger : IDisposable { internal static SentryStructuredLogger Create(IHub hub, SentryOptions options, ISystemClock clock) + => Create(hub, options, clock, 100, TimeSpan.FromSeconds(5)); + + internal static SentryStructuredLogger Create(IHub hub, SentryOptions options, ISystemClock clock, int batchCount, TimeSpan batchInterval) { return options.Experimental.EnableLogs - ? new DefaultSentryStructuredLogger(hub, options, clock) + ? new DefaultSentryStructuredLogger(hub, options, clock, batchCount, batchInterval) : DisabledSentryStructuredLogger.Instance; } diff --git a/test/Sentry.Tests/ApiApprovalTests.Run.DotNet8_0.verified.txt b/test/Sentry.Tests/ApiApprovalTests.Run.DotNet8_0.verified.txt index ecc959813f..17528e0ea2 100644 --- a/test/Sentry.Tests/ApiApprovalTests.Run.DotNet8_0.verified.txt +++ b/test/Sentry.Tests/ApiApprovalTests.Run.DotNet8_0.verified.txt @@ -833,8 +833,6 @@ namespace Sentry public sealed class SentryExperimentalOptions { public bool EnableLogs { get; set; } - public int InternalBatchSize { get; set; } - public System.TimeSpan InternalBatchTimeout { get; set; } public void SetBeforeSendLog(System.Func beforeSendLog) { } } } diff --git a/test/Sentry.Tests/ApiApprovalTests.Run.DotNet9_0.verified.txt b/test/Sentry.Tests/ApiApprovalTests.Run.DotNet9_0.verified.txt index ecc959813f..17528e0ea2 100644 --- a/test/Sentry.Tests/ApiApprovalTests.Run.DotNet9_0.verified.txt +++ b/test/Sentry.Tests/ApiApprovalTests.Run.DotNet9_0.verified.txt @@ -833,8 +833,6 @@ namespace Sentry public sealed class SentryExperimentalOptions { public bool EnableLogs { get; set; } - public int InternalBatchSize { get; set; } - public System.TimeSpan InternalBatchTimeout { get; set; } public void SetBeforeSendLog(System.Func beforeSendLog) { } } } diff --git a/test/Sentry.Tests/ApiApprovalTests.Run.Net4_8.verified.txt b/test/Sentry.Tests/ApiApprovalTests.Run.Net4_8.verified.txt index 22304be4c5..457db9add6 100644 --- a/test/Sentry.Tests/ApiApprovalTests.Run.Net4_8.verified.txt +++ b/test/Sentry.Tests/ApiApprovalTests.Run.Net4_8.verified.txt @@ -795,8 +795,6 @@ namespace Sentry public sealed class SentryExperimentalOptions { public bool EnableLogs { get; set; } - public int InternalBatchSize { get; set; } - public System.TimeSpan InternalBatchTimeout { get; set; } public void SetBeforeSendLog(System.Func beforeSendLog) { } } } diff --git a/test/Sentry.Tests/HubTests.cs b/test/Sentry.Tests/HubTests.cs index e3c236612f..917c77a0f5 100644 --- a/test/Sentry.Tests/HubTests.cs +++ b/test/Sentry.Tests/HubTests.cs @@ -1429,6 +1429,7 @@ public void Logger_IsDisabled_DoesNotCaptureLog() // Act hub.Logger.LogWarning("Message"); + hub.Logger.Flush(); // Assert _fixture.Client.Received(0).CaptureEnvelope( @@ -1439,16 +1440,16 @@ public void Logger_IsDisabled_DoesNotCaptureLog() hub.Logger.Should().BeOfType(); } - [Fact(Skip = "Remove InternalBatchSize")] + [Fact] public void Logger_IsEnabled_DoesCaptureLog() { // Arrange _fixture.Options.Experimental.EnableLogs = true; - _fixture.Options.Experimental.InternalBatchSize = 1; var hub = _fixture.GetSut(); // Act hub.Logger.LogWarning("Message"); + hub.Logger.Flush(); // Assert _fixture.Client.Received(1).CaptureEnvelope( @@ -1487,6 +1488,26 @@ public void Logger_DisableAfterCreate_HasNoEffect() hub.Logger.Should().BeOfType(); } + [Fact] + public void Logger_Dispose_DoesCaptureLog() + { + // Arrange + _fixture.Options.Experimental.EnableLogs = true; + var hub = _fixture.GetSut(); + hub.Logger.LogWarning("Message"); + + // Act + hub.Dispose(); + + // Assert + _fixture.Client.Received(1).CaptureEnvelope( + Arg.Is(envelope => + envelope.Items.Single(item => item.Header["type"].Equals("log")).Payload.GetType().IsAssignableFrom(typeof(JsonSerializable)) + ) + ); + hub.Logger.Should().BeOfType(); + } + [Fact] public void Dispose_IsEnabled_SetToFalse() { diff --git a/test/Sentry.Tests/SentryStructuredLoggerTests.cs b/test/Sentry.Tests/SentryStructuredLoggerTests.cs index f9f82710cb..687714e6e9 100644 --- a/test/Sentry.Tests/SentryStructuredLoggerTests.cs +++ b/test/Sentry.Tests/SentryStructuredLoggerTests.cs @@ -19,6 +19,8 @@ public Fixture() DiagnosticLogger = DiagnosticLogger, }; Clock = new MockClock(new DateTimeOffset(2025, 04, 22, 14, 51, 00, TimeSpan.Zero)); + BatchSize = 2; + BatchTimeout = Timeout.InfiniteTimeSpan; TraceId = SentryId.Create(); ParentSpanId = SpanId.Create(); @@ -30,6 +32,8 @@ public Fixture() public IHub Hub { get; } public SentryOptions Options { get; } public ISystemClock Clock { get; } + public int BatchSize { get; set; } + public TimeSpan BatchTimeout { get; set; } public SentryId TraceId { get; private set; } public SpanId? ParentSpanId { get; private set; } @@ -40,7 +44,7 @@ public void WithoutTraceHeader() ParentSpanId = SpanId.Empty; } - public SentryStructuredLogger GetSut() => SentryStructuredLogger.Create(Hub, Options, Clock); + public SentryStructuredLogger GetSut() => SentryStructuredLogger.Create(Hub, Options, Clock, BatchSize, BatchTimeout); } private readonly Fixture _fixture; @@ -74,7 +78,7 @@ public void Create_Disabled_CachedDisabledInstance() instance.Should().BeSameAs(other); } - [Theory(Skip = "Remove InternalBatchSize")] + [Theory] [InlineData(SentryLogLevel.Trace)] [InlineData(SentryLogLevel.Debug)] [InlineData(SentryLogLevel.Info)] @@ -84,13 +88,13 @@ public void Create_Disabled_CachedDisabledInstance() public void Log_Enabled_CapturesEnvelope(SentryLogLevel level) { _fixture.Options.Experimental.EnableLogs = true; - _fixture.Options.Experimental.InternalBatchSize = 1; var logger = _fixture.GetSut(); Envelope envelope = null!; _fixture.Hub.CaptureEnvelope(Arg.Do(arg => envelope = arg)); logger.Log(level, "Template string with arguments: {0}, {1}, {2}, {3}", ["string", true, 1, 2.2], ConfigureLog); + logger.Flush(); _fixture.Hub.Received(1).CaptureEnvelope(Arg.Any()); envelope.AssertEnvelope(_fixture, level); @@ -113,31 +117,30 @@ public void Log_Disabled_DoesNotCaptureEnvelope(SentryLogLevel level) _fixture.Hub.Received(0).CaptureEnvelope(Arg.Any()); } - [Fact(Skip = "Remove InternalBatchSize")] + [Fact] public void Log_WithoutTraceHeader_CapturesEnvelope() { _fixture.WithoutTraceHeader(); _fixture.Options.Experimental.EnableLogs = true; - _fixture.Options.Experimental.InternalBatchSize = 1; var logger = _fixture.GetSut(); Envelope envelope = null!; _fixture.Hub.CaptureEnvelope(Arg.Do(arg => envelope = arg)); logger.LogTrace("Template string with arguments: {0}, {1}, {2}, {3}", ["string", true, 1, 2.2], ConfigureLog); + logger.Flush(); _fixture.Hub.Received(1).CaptureEnvelope(Arg.Any()); envelope.AssertEnvelope(_fixture, SentryLogLevel.Trace); } - [Fact(Skip = "Remove InternalBatchSize")] + [Fact] public void Log_WithBeforeSendLog_InvokesCallback() { var invocations = 0; SentryLog configuredLog = null!; _fixture.Options.Experimental.EnableLogs = true; - _fixture.Options.Experimental.InternalBatchSize = 1; _fixture.Options.Experimental.SetBeforeSendLog((SentryLog log) => { invocations++; @@ -147,6 +150,7 @@ public void Log_WithBeforeSendLog_InvokesCallback() var logger = _fixture.GetSut(); logger.LogTrace("Template string with arguments: {0}, {1}, {2}, {3}", ["string", true, 1, 2.2], ConfigureLog); + logger.Flush(); _fixture.Hub.Received(1).CaptureEnvelope(Arg.Any()); invocations.Should().Be(1); @@ -221,7 +225,7 @@ public void Log_InvalidBeforeSendLog_DoesNotCaptureEnvelope() entry.Args.Should().BeEmpty(); } - [Fact(Skip = "May no longer be required after feedback.")] + [Fact] public void Dispose_Log_Throws() { _fixture.Options.Experimental.EnableLogs = true; From 07027969a2552da02205b420940cbe59b9eb45e7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Wed, 23 Jul 2025 14:47:50 +0200 Subject: [PATCH 22/29] test: ref --- test/Sentry.Tests/HubTests.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/Sentry.Tests/HubTests.cs b/test/Sentry.Tests/HubTests.cs index 917c77a0f5..1bbe1b5ebf 100644 --- a/test/Sentry.Tests/HubTests.cs +++ b/test/Sentry.Tests/HubTests.cs @@ -1494,9 +1494,9 @@ public void Logger_Dispose_DoesCaptureLog() // Arrange _fixture.Options.Experimental.EnableLogs = true; var hub = _fixture.GetSut(); - hub.Logger.LogWarning("Message"); // Act + hub.Logger.LogWarning("Message"); hub.Dispose(); // Assert From 4e5f09738b3ec21d67dcac76771f085cbdc0fa9f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Wed, 23 Jul 2025 14:58:53 +0200 Subject: [PATCH 23/29] perf: update Benchmark result --- ...dLogBatchProcessorBenchmarks-report-github.md | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) 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 index 8046dceeda..1c526dc758 100644 --- 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 @@ -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** | **2.209 μs** | **0.0221 μs** | **0.0196 μs** | **0.7095** | **5.8 KB** | -| **EnqueueAndFlush** | **10** | **200** | **3.829 μs** | **0.0287 μs** | **0.0268 μs** | **1.3199** | **10.8 KB** | -| **EnqueueAndFlush** | **10** | **1000** | **18.363 μs** | **0.2813 μs** | **0.2889 μs** | **6.1951** | **50.8 KB** | -| **EnqueueAndFlush** | **100** | **100** | **1.021 μs** | **0.0133 μs** | **0.0118 μs** | **0.2441** | **2 KB** | -| **EnqueueAndFlush** | **100** | **200** | **1.816 μs** | **0.0211 μs** | **0.0176 μs** | **0.3910** | **3.2 KB** | -| **EnqueueAndFlush** | **100** | **1000** | **8.762 μs** | **0.0761 μs** | **0.0675 μs** | **1.5564** | **12.83 KB** | +| 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** | From 12767255f71905e113ea53e591ca96ed63c68c85 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Thu, 24 Jul 2025 22:03:16 +0200 Subject: [PATCH 24/29] ref: make SentryStructuredLogger. Flush abstract --- .../Internal/DisabledSentryStructuredLogger.cs | 6 ++++++ src/Sentry/SentryStructuredLogger.cs | 13 +++++-------- .../InMemorySentryStructuredLogger.cs | 6 ++++++ .../ApiApprovalTests.Run.DotNet8_0.verified.txt | 2 +- .../ApiApprovalTests.Run.DotNet9_0.verified.txt | 2 +- .../ApiApprovalTests.Run.Net4_8.verified.txt | 2 +- 6 files changed, 20 insertions(+), 11 deletions(-) diff --git a/src/Sentry/Internal/DisabledSentryStructuredLogger.cs b/src/Sentry/Internal/DisabledSentryStructuredLogger.cs index dba69e0833..efe0e65ad2 100644 --- a/src/Sentry/Internal/DisabledSentryStructuredLogger.cs +++ b/src/Sentry/Internal/DisabledSentryStructuredLogger.cs @@ -13,4 +13,10 @@ private protected override void CaptureLog(SentryLogLevel level, string template { // disabled } + + /// + protected internal override void Flush() + { + // disabled + } } diff --git a/src/Sentry/SentryStructuredLogger.cs b/src/Sentry/SentryStructuredLogger.cs index 241b16fe6f..f5b444960e 100644 --- a/src/Sentry/SentryStructuredLogger.cs +++ b/src/Sentry/SentryStructuredLogger.cs @@ -34,6 +34,11 @@ private protected SentryStructuredLogger() /// A configuration callback. Will be removed in a future version. private protected abstract void CaptureLog(SentryLogLevel level, string template, object[]? parameters, Action? configureLog); + /// + /// Clears all buffers for this logger and causes any buffered logs to be sent by the underlying . + /// + protected internal abstract void Flush(); + /// /// Creates and sends a structured log to Sentry, with severity , when enabled and sampled. /// This API is experimental and it may change in the future. @@ -112,14 +117,6 @@ public void LogFatal(string template, object[]? parameters = null, Action - /// When overridden in a derived , - /// clears all buffers for this logger and causes any buffered logs to be sent by the underlying . - /// - protected internal virtual void Flush() - { - } - /// public void Dispose() { diff --git a/test/Sentry.Testing/InMemorySentryStructuredLogger.cs b/test/Sentry.Testing/InMemorySentryStructuredLogger.cs index fd697056cf..b180a776b0 100644 --- a/test/Sentry.Testing/InMemorySentryStructuredLogger.cs +++ b/test/Sentry.Testing/InMemorySentryStructuredLogger.cs @@ -12,6 +12,12 @@ private protected override void CaptureLog(SentryLogLevel level, string template Entries.Add(LogEntry.Create(level, template, parameters)); } + /// + protected internal override void Flush() + { + // no-op + } + public sealed class LogEntry : IEquatable { public static LogEntry Create(SentryLogLevel level, string template, object[]? parameters) diff --git a/test/Sentry.Tests/ApiApprovalTests.Run.DotNet8_0.verified.txt b/test/Sentry.Tests/ApiApprovalTests.Run.DotNet8_0.verified.txt index 17528e0ea2..e826dba774 100644 --- a/test/Sentry.Tests/ApiApprovalTests.Run.DotNet8_0.verified.txt +++ b/test/Sentry.Tests/ApiApprovalTests.Run.DotNet8_0.verified.txt @@ -1015,7 +1015,7 @@ namespace Sentry { public void Dispose() { } protected virtual void Dispose(bool disposing) { } - protected virtual void Flush() { } + protected abstract void Flush(); [System.Diagnostics.CodeAnalysis.Experimental("SENTRY0001")] public void LogDebug(string template, object[]? parameters = null, System.Action? configureLog = null) { } [System.Diagnostics.CodeAnalysis.Experimental("SENTRY0001")] diff --git a/test/Sentry.Tests/ApiApprovalTests.Run.DotNet9_0.verified.txt b/test/Sentry.Tests/ApiApprovalTests.Run.DotNet9_0.verified.txt index 17528e0ea2..e826dba774 100644 --- a/test/Sentry.Tests/ApiApprovalTests.Run.DotNet9_0.verified.txt +++ b/test/Sentry.Tests/ApiApprovalTests.Run.DotNet9_0.verified.txt @@ -1015,7 +1015,7 @@ namespace Sentry { public void Dispose() { } protected virtual void Dispose(bool disposing) { } - protected virtual void Flush() { } + protected abstract void Flush(); [System.Diagnostics.CodeAnalysis.Experimental("SENTRY0001")] public void LogDebug(string template, object[]? parameters = null, System.Action? configureLog = null) { } [System.Diagnostics.CodeAnalysis.Experimental("SENTRY0001")] diff --git a/test/Sentry.Tests/ApiApprovalTests.Run.Net4_8.verified.txt b/test/Sentry.Tests/ApiApprovalTests.Run.Net4_8.verified.txt index 457db9add6..296ea74dc8 100644 --- a/test/Sentry.Tests/ApiApprovalTests.Run.Net4_8.verified.txt +++ b/test/Sentry.Tests/ApiApprovalTests.Run.Net4_8.verified.txt @@ -975,7 +975,7 @@ namespace Sentry { public void Dispose() { } protected virtual void Dispose(bool disposing) { } - protected virtual void Flush() { } + protected abstract void Flush(); public void LogDebug(string template, object[]? parameters = null, System.Action? configureLog = null) { } public void LogError(string template, object[]? parameters = null, System.Action? configureLog = null) { } public void LogFatal(string template, object[]? parameters = null, System.Action? configureLog = null) { } From 3816fab70606cd8ef251609c17ba7d34bbce7b68 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Thu, 24 Jul 2025 22:28:46 +0200 Subject: [PATCH 25/29] ref: guard an invariant of the Flush-Scope --- src/Sentry/Internal/StructuredLogBatchBuffer.cs | 1 + 1 file changed, 1 insertion(+) diff --git a/src/Sentry/Internal/StructuredLogBatchBuffer.cs b/src/Sentry/Internal/StructuredLogBatchBuffer.cs index 7cb00a5002..93debba942 100644 --- a/src/Sentry/Internal/StructuredLogBatchBuffer.cs +++ b/src/Sentry/Internal/StructuredLogBatchBuffer.cs @@ -259,6 +259,7 @@ static void ThrowNegativeOrZero(TimeSpan value, string paramName) internal FlushScope(StructuredLogBatchBuffer lockObj, ScopedCountdownLock.LockScope scope) { + Debug.Assert(scope.IsEntered); _lockObj = lockObj; _scope = scope; } From 28b6654a96ba38031759e3078db73f0b49779406 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Thu, 24 Jul 2025 23:08:20 +0200 Subject: [PATCH 26/29] ref: remove unused values --- .../Internal/DefaultSentryStructuredLogger.cs | 2 +- .../Internal/StructuredLogBatchBuffer.cs | 14 ++----- .../Internal/StructuredLogBatchProcessor.cs | 17 ++++---- .../StructuredLogBatchBufferTests.cs | 39 ++++++++++++++++--- .../StructuredLogBatchProcessorTests.cs | 14 +++---- 5 files changed, 53 insertions(+), 33 deletions(-) diff --git a/src/Sentry/Internal/DefaultSentryStructuredLogger.cs b/src/Sentry/Internal/DefaultSentryStructuredLogger.cs index 56809bb9ce..5b50412265 100644 --- a/src/Sentry/Internal/DefaultSentryStructuredLogger.cs +++ b/src/Sentry/Internal/DefaultSentryStructuredLogger.cs @@ -19,7 +19,7 @@ internal DefaultSentryStructuredLogger(IHub hub, SentryOptions options, ISystemC _options = options; _clock = clock; - _batchProcessor = new StructuredLogBatchProcessor(hub, batchCount, batchInterval, clock, _options.ClientReportRecorder, _options.DiagnosticLogger); + _batchProcessor = new StructuredLogBatchProcessor(hub, batchCount, batchInterval, _options.ClientReportRecorder, _options.DiagnosticLogger); } /// diff --git a/src/Sentry/Internal/StructuredLogBatchBuffer.cs b/src/Sentry/Internal/StructuredLogBatchBuffer.cs index 93debba942..1fed684d11 100644 --- a/src/Sentry/Internal/StructuredLogBatchBuffer.cs +++ b/src/Sentry/Internal/StructuredLogBatchBuffer.cs @@ -1,4 +1,3 @@ -using Sentry.Infrastructure; using Sentry.Threading; namespace Sentry.Internal; @@ -17,23 +16,19 @@ internal sealed class StructuredLogBatchBuffer : IDisposable private int _additions; private readonly ScopedCountdownLock _addLock; - private readonly ISystemClock _clock; private readonly Timer _timer; private readonly TimeSpan _timeout; - private readonly Action _timeoutExceededAction; - - private DateTimeOffset _lastFlush = DateTimeOffset.MinValue; + private readonly Action _timeoutExceededAction; /// /// Create a new buffer. /// /// Length of the new buffer. /// When the timeout exceeds after an item has been added and the not yet been exceeded, is invoked. - /// The with which to interpret . /// The operation to execute when the exceeds if the buffer is neither empty nor full. /// Name of the new buffer. - public StructuredLogBatchBuffer(int capacity, TimeSpan timeout, ISystemClock clock, Action timeoutExceededAction, string? name = null) + public StructuredLogBatchBuffer(int capacity, TimeSpan timeout, Action timeoutExceededAction, string? name = null) { ThrowIfLessThanTwo(capacity, nameof(capacity)); ThrowIfNegativeOrZero(timeout, nameof(timeout)); @@ -42,7 +37,6 @@ public StructuredLogBatchBuffer(int capacity, TimeSpan timeout, ISystemClock clo _additions = 0; _addLock = new ScopedCountdownLock(); - _clock = clock; _timer = new Timer(OnIntervalElapsed, this, Timeout.Infinite, Timeout.Infinite); _timeout = timeout; @@ -142,8 +136,7 @@ private void ExitFlushScope() /// internal void OnIntervalElapsed(object? state) { - var now = _clock.GetUtcNow(); - _timeoutExceededAction(this, now); + _timeoutExceededAction(this); } /// @@ -271,7 +264,6 @@ internal SentryLog[] Flush() var lockObj = _lockObj; if (lockObj is not null) { - lockObj._lastFlush = lockObj._clock.GetUtcNow(); _scope.Wait(); var array = lockObj.ToArrayAndClear(); diff --git a/src/Sentry/Internal/StructuredLogBatchProcessor.cs b/src/Sentry/Internal/StructuredLogBatchProcessor.cs index 60275cd4dd..7242d1a02d 100644 --- a/src/Sentry/Internal/StructuredLogBatchProcessor.cs +++ b/src/Sentry/Internal/StructuredLogBatchProcessor.cs @@ -39,14 +39,14 @@ internal sealed class StructuredLogBatchProcessor : IDisposable private readonly StructuredLogBatchBuffer _buffer2; private volatile StructuredLogBatchBuffer _activeBuffer; - public StructuredLogBatchProcessor(IHub hub, int batchCount, TimeSpan batchInterval, ISystemClock clock, IClientReportRecorder clientReportRecorder, IDiagnosticLogger? diagnosticLogger) + public StructuredLogBatchProcessor(IHub hub, int batchCount, TimeSpan batchInterval, IClientReportRecorder clientReportRecorder, IDiagnosticLogger? diagnosticLogger) { _hub = hub; _clientReportRecorder = clientReportRecorder; _diagnosticLogger = diagnosticLogger; - _buffer1 = new StructuredLogBatchBuffer(batchCount, batchInterval, clock, OnTimeoutExceeded, "Buffer 1"); - _buffer2 = new StructuredLogBatchBuffer(batchCount, batchInterval, clock, OnTimeoutExceeded, "Buffer 2"); + _buffer1 = new StructuredLogBatchBuffer(batchCount, batchInterval, OnTimeoutExceeded, "Buffer 1"); + _buffer2 = new StructuredLogBatchBuffer(batchCount, batchInterval, OnTimeoutExceeded, "Buffer 2"); _activeBuffer = _buffer1; } @@ -86,7 +86,7 @@ private bool TryEnqueue(StructuredLogBatchBuffer buffer, SentryLog log) if (status is BatchBufferAddStatus.AddedLast) { - TrySwapActiveBuffer(buffer); + SwapActiveBuffer(buffer); CaptureLogs(buffer); return true; } @@ -94,11 +94,10 @@ private bool TryEnqueue(StructuredLogBatchBuffer buffer, SentryLog log) return status is BatchBufferAddStatus.AddedFirst or BatchBufferAddStatus.Added; } - private bool TrySwapActiveBuffer(StructuredLogBatchBuffer currentActiveBuffer) + private void SwapActiveBuffer(StructuredLogBatchBuffer currentActiveBuffer) { var newActiveBuffer = ReferenceEquals(currentActiveBuffer, _buffer1) ? _buffer2 : _buffer1; - var previousActiveBuffer = Interlocked.CompareExchange(ref _activeBuffer, newActiveBuffer, currentActiveBuffer); - return previousActiveBuffer == currentActiveBuffer; + _ = Interlocked.CompareExchange(ref _activeBuffer, newActiveBuffer, currentActiveBuffer); } private void CaptureLogs(StructuredLogBatchBuffer buffer) @@ -119,11 +118,11 @@ private void CaptureLogs(StructuredLogBatchBuffer buffer) } } - private void OnTimeoutExceeded(StructuredLogBatchBuffer buffer, DateTimeOffset signalTime) + private void OnTimeoutExceeded(StructuredLogBatchBuffer buffer) { if (!buffer.IsEmpty) { - TrySwapActiveBuffer(buffer); + SwapActiveBuffer(buffer); CaptureLogs(buffer); } } diff --git a/test/Sentry.Tests/Internals/StructuredLogBatchBufferTests.cs b/test/Sentry.Tests/Internals/StructuredLogBatchBufferTests.cs index dc31dd0921..9628198629 100644 --- a/test/Sentry.Tests/Internals/StructuredLogBatchBufferTests.cs +++ b/test/Sentry.Tests/Internals/StructuredLogBatchBufferTests.cs @@ -8,18 +8,18 @@ private sealed class Fixture { public int Capacity { get; set; } = 2; public TimeSpan Timeout { get; set; } = System.Threading.Timeout.InfiniteTimeSpan; - public MockClock Clock { get; } = new(); - public List<(StructuredLogBatchBuffer Buffer, DateTimeOffset SignalTime)> TimeoutExceededInvocations { get; } = new(); public string? Name { get; set; } + public List TimeoutExceededInvocations { get; } = []; + public StructuredLogBatchBuffer GetSut() { - return new StructuredLogBatchBuffer(Capacity, Timeout, Clock, OnTimeoutExceeded, Name); + return new StructuredLogBatchBuffer(Capacity, Timeout, OnTimeoutExceeded, Name); } - private void OnTimeoutExceeded(StructuredLogBatchBuffer buffer, DateTimeOffset signalTime) + private void OnTimeoutExceeded(StructuredLogBatchBuffer buffer) { - TimeoutExceededInvocations.Add((buffer, signalTime)); + TimeoutExceededInvocations.Add(buffer); } } @@ -50,6 +50,19 @@ public void Ctor_TimeoutIsOutOfRange_Throws(int millisecondsTimeout) Assert.Throws("timeout", ctor); } + [Fact] + public void Ctor() + { + _fixture.Capacity = 9; + _fixture.Name = nameof(Ctor); + + using var buffer = _fixture.GetSut(); + + buffer.Capacity.Should().Be(_fixture.Capacity); + buffer.IsEmpty.Should().BeTrue(); + buffer.Name.Should().Be(_fixture.Name); + } + [Fact] public void Add_CapacityTwo_CanAddTwice() { @@ -227,6 +240,22 @@ public void Flush_Disposed_Throws() AssertFlushThrows(flushScope); } + [Fact] + public void OnIntervalElapsed_Timeout_InvokesCallback() + { + _fixture.Timeout = Timeout.InfiniteTimeSpan; + using var buffer = _fixture.GetSut(); + + buffer.OnIntervalElapsed(null); + _fixture.TimeoutExceededInvocations.Should().HaveCount(1); + + buffer.OnIntervalElapsed(null); + _fixture.TimeoutExceededInvocations.Should().HaveCount(2); + + _fixture.TimeoutExceededInvocations[0].Should().BeSameAs(buffer); + _fixture.TimeoutExceededInvocations[1].Should().BeSameAs(buffer); + } + // cannot use xUnit's Throws() nor Fluent Assertions' ThrowExactly() because the FlushScope is a ref struct private static void AssertFlushThrows(StructuredLogBatchBuffer.FlushScope flushScope) where T : Exception diff --git a/test/Sentry.Tests/Internals/StructuredLogBatchProcessorTests.cs b/test/Sentry.Tests/Internals/StructuredLogBatchProcessorTests.cs index 73a496e44b..0696784ee3 100644 --- a/test/Sentry.Tests/Internals/StructuredLogBatchProcessorTests.cs +++ b/test/Sentry.Tests/Internals/StructuredLogBatchProcessorTests.cs @@ -6,8 +6,8 @@ public class StructuredLogBatchProcessorTests : IDisposable { private sealed class Fixture { - public IHub Hub { get; } - public MockClock Clock { get; } + private readonly IHub _hub; + public ClientReportRecorder ClientReportRecorder { get; } public InMemoryDiagnosticLogger DiagnosticLogger { get; } public BlockingCollection CapturedEnvelopes { get; } @@ -17,21 +17,21 @@ private sealed class Fixture public Fixture() { var options = new SentryOptions(); + var clock = new MockClock(); - Hub = Substitute.For(); - Clock = new MockClock(); - ClientReportRecorder = new ClientReportRecorder(options, Clock); + _hub = Substitute.For(); + ClientReportRecorder = new ClientReportRecorder(options, clock); DiagnosticLogger = new InMemoryDiagnosticLogger(); CapturedEnvelopes = []; - Hub.CaptureEnvelope(Arg.Do(arg => CapturedEnvelopes.Add(arg))); + _hub.CaptureEnvelope(Arg.Do(arg => CapturedEnvelopes.Add(arg))); ExpectedDiagnosticLogs = 0; } public StructuredLogBatchProcessor GetSut(int batchCount) { - return new StructuredLogBatchProcessor(Hub, batchCount, Timeout.InfiniteTimeSpan, Clock, ClientReportRecorder, DiagnosticLogger); + return new StructuredLogBatchProcessor(_hub, batchCount, Timeout.InfiniteTimeSpan, ClientReportRecorder, DiagnosticLogger); } } From 1eef3304df670e78c3dba200ef2a482577c71cb9 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Fri, 25 Jul 2025 00:02:23 +0200 Subject: [PATCH 27/29] docs: improve comments --- src/Sentry/Threading/ScopedCountdownLock.cs | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/Sentry/Threading/ScopedCountdownLock.cs b/src/Sentry/Threading/ScopedCountdownLock.cs index b91d605f61..5a8db288f7 100644 --- a/src/Sentry/Threading/ScopedCountdownLock.cs +++ b/src/Sentry/Threading/ScopedCountdownLock.cs @@ -34,8 +34,8 @@ internal ScopedCountdownLock() internal int Count => _isEngaged == 1 ? _event.CurrentCount : _event.CurrentCount - 1; /// - /// Determines whether the event can be set/signaled by reaching . - /// Returns when a is active. + /// Returns when a is active and the event can be set/signaled by reaching . + /// Returns when the can only reach the initial count of when no is active any longer. /// internal bool IsEngaged => _isEngaged == 1; @@ -60,7 +60,7 @@ private void ExitCounterScope() } /// - /// When successful, the lock , can reach and the event be set/signaled. + /// When successful, the lock , can reach when no is active, and the event be set/signaled. /// Check via whether the Lock . /// Use to block until every active has exited before performing the locked operation. /// After the locked operation has completed, disengage the Lock via . @@ -69,7 +69,7 @@ internal LockScope TryEnterLockScope() { if (Interlocked.CompareExchange(ref _isEngaged, 1, 0) == 0) { - _ = _event.Signal(); + _ = _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 return new LockScope(this); } @@ -80,7 +80,7 @@ private void ExitLockScope() { if (Interlocked.CompareExchange(ref _isEngaged, 0, 1) == 1) { - _event.Reset(); + _event.Reset(); // reset the signaled event to the initial count of 1, so that new `CounterScope`s can be entered again return; } From d72ca5c6397cc7b93220c5d7acef6578a6cb119a Mon Sep 17 00:00:00 2001 From: Flash0ver <38893694+Flash0ver@users.noreply.github.com> Date: Fri, 25 Jul 2025 02:29:57 +0200 Subject: [PATCH 28/29] perf: update Benchmark after signature change --- .../StructuredLogBatchProcessorBenchmarks.cs | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/benchmarks/Sentry.Benchmarks/StructuredLogBatchProcessorBenchmarks.cs b/benchmarks/Sentry.Benchmarks/StructuredLogBatchProcessorBenchmarks.cs index 34410dde54..cec3eaa64f 100644 --- a/benchmarks/Sentry.Benchmarks/StructuredLogBatchProcessorBenchmarks.cs +++ b/benchmarks/Sentry.Benchmarks/StructuredLogBatchProcessorBenchmarks.cs @@ -2,7 +2,6 @@ using NSubstitute; using Sentry.Extensibility; using Sentry.Internal; -using Sentry.Testing; namespace Sentry.Benchmarks; @@ -22,10 +21,9 @@ public void Setup() { var hub = DisabledHub.Instance; var batchInterval = Timeout.InfiniteTimeSpan; - var clock = new MockClock(); var clientReportRecorder = Substitute.For(); var diagnosticLogger = Substitute.For(); - _batchProcessor = new StructuredLogBatchProcessor(hub, BatchCount, batchInterval, clock, clientReportRecorder, diagnosticLogger); + _batchProcessor = new StructuredLogBatchProcessor(hub, BatchCount, batchInterval, clientReportRecorder, diagnosticLogger); _log = new SentryLog(DateTimeOffset.Now, SentryId.Empty, SentryLogLevel.Trace, "message"); } From 49fefc162e1f42a7ea906f09435dd12aed63aec6 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Stefan=20P=C3=B6lz?= <38893694+Flash0ver@users.noreply.github.com> Date: Mon, 28 Jul 2025 22:21:12 +0200 Subject: [PATCH 29/29] ref: discard logs gracefully when Hub is (being) disposed --- ...gBatchProcessorBenchmarks-report-github.md | 16 ++-- .../StructuredLogBatchProcessorBenchmarks.cs | 26 ++++++- .../Internal/DefaultSentryStructuredLogger.cs | 1 + .../Internal/StructuredLogBatchBuffer.cs | 58 +++++++++------ .../Internal/StructuredLogBatchProcessor.cs | 18 ++++- src/Sentry/Threading/ScopedCountdownLock.cs | 8 +- .../InMemoryDiagnosticLogger.cs | 10 +++ .../StructuredLogBatchBufferTests.cs | 74 ++++++++++++++++--- .../StructuredLogBatchProcessorTests.cs | 48 ++++++++++++ .../SentryStructuredLoggerTests.cs | 48 ++++++++++-- .../Threading/ScopedCountdownLockTests.cs | 9 +++ 11 files changed, 261 insertions(+), 55 deletions(-) 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 index 1c526dc758..befa791365 100644 --- 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 @@ -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** | diff --git a/benchmarks/Sentry.Benchmarks/StructuredLogBatchProcessorBenchmarks.cs b/benchmarks/Sentry.Benchmarks/StructuredLogBatchProcessorBenchmarks.cs index cec3eaa64f..336d726926 100644 --- a/benchmarks/Sentry.Benchmarks/StructuredLogBatchProcessorBenchmarks.cs +++ b/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(); + clientReportRecorder + .When(static recorder => recorder.RecordDiscardedEvent(Arg.Any(), Arg.Any(), Arg.Any())) + .Throw(); + var diagnosticLogger = Substitute.For(); - _batchProcessor = new StructuredLogBatchProcessor(hub, BatchCount, batchInterval, clientReportRecorder, diagnosticLogger); + diagnosticLogger + .When(static logger => logger.IsEnabled(Arg.Any())) + .Throw(); + diagnosticLogger + .When(static logger => logger.Log(Arg.Any(), Arg.Any(), Arg.Any(), Arg.Any())) + .Throw(); + _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(); } } diff --git a/src/Sentry/Internal/DefaultSentryStructuredLogger.cs b/src/Sentry/Internal/DefaultSentryStructuredLogger.cs index 5b50412265..75a8cee778 100644 --- a/src/Sentry/Internal/DefaultSentryStructuredLogger.cs +++ b/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; diff --git a/src/Sentry/Internal/StructuredLogBatchBuffer.cs b/src/Sentry/Internal/StructuredLogBatchBuffer.cs index 1fed684d11..7e518253a6 100644 --- a/src/Sentry/Internal/StructuredLogBatchBuffer.cs +++ b/src/Sentry/Internal/StructuredLogBatchBuffer.cs @@ -9,7 +9,7 @@ namespace Sentry.Internal; /// Must be attempted to flush via when either the is reached, /// or when the is exceeded. /// -[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 _timeoutExceededAction; + private volatile bool _disposed; + /// /// Create a new buffer. /// @@ -39,8 +40,8 @@ public StructuredLogBatchBuffer(int capacity, TimeSpan timeout, Action /// Number of operations in progress. /// - /// - /// This property is used for debugging only. - /// private int AddCount => _addLock.Count; /// - /// Attempt to atomically add one element to the buffer. + /// Attempt to add one element to the buffer. + /// Is thread-safe. /// - /// Element attempted to be added atomically. - /// An describing the result of the operation. - internal BatchBufferAddStatus Add(SentryLog item) + /// Element attempted to be added. + /// An describing the result of the thread-safe operation. + 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; } /// @@ -114,6 +118,11 @@ internal BatchBufferAddStatus Add(SentryLog item) /// internal FlushScope TryEnterFlushScope() { + if (_disposed) + { + return new FlushScope(); + } + var scope = _addLock.TryEnterLockScope(); if (scope.IsEntered) { @@ -132,11 +141,14 @@ private void ExitFlushScope() } /// - /// 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. /// internal void OnIntervalElapsed(object? state) { - _timeoutExceededAction(this); + if (!_disposed) + { + _timeoutExceededAction(this); + } } /// @@ -193,14 +205,12 @@ 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); } /// @@ -208,6 +218,7 @@ 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 operation is in progress, /// and blocks the calling thread until all operations have finished. /// When is , no more can be started, - /// which will then return immediately. + /// which will then return immediately. /// /// /// Only when scope . @@ -287,11 +298,12 @@ public void Dispose() } } -internal enum BatchBufferAddStatus : byte +internal enum StructuredLogBatchBufferAddStatus : byte { AddedFirst, Added, AddedLast, IgnoredCapacityExceeded, IgnoredIsFlushing, + IgnoredIsDisposed, } diff --git a/src/Sentry/Internal/StructuredLogBatchProcessor.cs b/src/Sentry/Internal/StructuredLogBatchProcessor.cs index 7242d1a02d..2fe5db924e 100644 --- a/src/Sentry/Internal/StructuredLogBatchProcessor.cs +++ b/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. /// /// -/// 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. /// +/// 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() /// /// Forces invocation of a Timeout of the active buffer. /// + /// + /// Intended for Testing only. + /// 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) diff --git a/src/Sentry/Threading/ScopedCountdownLock.cs b/src/Sentry/Threading/ScopedCountdownLock.cs index 5a8db288f7..bc3725f1a9 100644 --- a/src/Sentry/Threading/ScopedCountdownLock.cs +++ b/src/Sentry/Threading/ScopedCountdownLock.cs @@ -44,6 +44,9 @@ internal ScopedCountdownLock() /// Check via whether the underlying has not been set/signaled yet. /// To signal the underlying , ensure is called. /// + /// + /// Must be disposed to exit. + /// internal CounterScope TryEnterCounterScope() { if (_event.TryAddCount(1)) @@ -60,11 +63,14 @@ private void ExitCounterScope() } /// - /// When successful, the lock , can reach when no is active, and the event be set/signaled. + /// When successful, the lock , can reach when no is active, and the event can be set/signaled. /// Check via whether the Lock . /// Use to block until every active has exited before performing the locked operation. /// After the locked operation has completed, disengage the Lock via . /// + /// + /// Must be disposed to exit. + /// internal LockScope TryEnterLockScope() { if (Interlocked.CompareExchange(ref _isEngaged, 1, 0) == 0) diff --git a/test/Sentry.Testing/InMemoryDiagnosticLogger.cs b/test/Sentry.Testing/InMemoryDiagnosticLogger.cs index 39c554345f..b1715a161f 100644 --- a/test/Sentry.Testing/InMemoryDiagnosticLogger.cs +++ b/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, diff --git a/test/Sentry.Tests/Internals/StructuredLogBatchBufferTests.cs b/test/Sentry.Tests/Internals/StructuredLogBatchBufferTests.cs index 9628198629..77d8d34ebd 100644 --- a/test/Sentry.Tests/Internals/StructuredLogBatchBufferTests.cs +++ b/test/Sentry.Tests/Internals/StructuredLogBatchBufferTests.cs @@ -72,16 +72,16 @@ public void Add_CapacityTwo_CanAddTwice() buffer.Capacity.Should().Be(2); buffer.IsEmpty.Should().BeTrue(); - buffer.Add("one").Should().Be(BatchBufferAddStatus.AddedFirst); + buffer.Add("one").Should().Be(StructuredLogBatchBufferAddStatus.AddedFirst); buffer.IsEmpty.Should().BeFalse(); - buffer.Add("two").Should().Be(BatchBufferAddStatus.AddedLast); + buffer.Add("two").Should().Be(StructuredLogBatchBufferAddStatus.AddedLast); buffer.IsEmpty.Should().BeFalse(); - buffer.Add("three").Should().Be(BatchBufferAddStatus.IgnoredCapacityExceeded); + buffer.Add("three").Should().Be(StructuredLogBatchBufferAddStatus.IgnoredCapacityExceeded); buffer.IsEmpty.Should().BeFalse(); - buffer.Add("four").Should().Be(BatchBufferAddStatus.IgnoredCapacityExceeded); + buffer.Add("four").Should().Be(StructuredLogBatchBufferAddStatus.IgnoredCapacityExceeded); buffer.IsEmpty.Should().BeFalse(); } @@ -94,19 +94,48 @@ public void Add_CapacityThree_CanAddThrice() buffer.Capacity.Should().Be(3); buffer.IsEmpty.Should().BeTrue(); - buffer.Add("one").Should().Be(BatchBufferAddStatus.AddedFirst); + buffer.Add("one").Should().Be(StructuredLogBatchBufferAddStatus.AddedFirst); buffer.IsEmpty.Should().BeFalse(); - buffer.Add("two").Should().Be(BatchBufferAddStatus.Added); + buffer.Add("two").Should().Be(StructuredLogBatchBufferAddStatus.Added); buffer.IsEmpty.Should().BeFalse(); - buffer.Add("three").Should().Be(BatchBufferAddStatus.AddedLast); + buffer.Add("three").Should().Be(StructuredLogBatchBufferAddStatus.AddedLast); buffer.IsEmpty.Should().BeFalse(); - buffer.Add("four").Should().Be(BatchBufferAddStatus.IgnoredCapacityExceeded); + buffer.Add("four").Should().Be(StructuredLogBatchBufferAddStatus.IgnoredCapacityExceeded); buffer.IsEmpty.Should().BeFalse(); } + [Fact] + public void Add_Flushing_CannotAdd() + { + _fixture.Capacity = 2; + var buffer = _fixture.GetSut(); + + var flushScope = buffer.TryEnterFlushScope(); + + buffer.Add("one").Should().Be(StructuredLogBatchBufferAddStatus.IgnoredIsFlushing); + buffer.IsEmpty.Should().BeTrue(); + + flushScope.Dispose(); + + buffer.Add("two").Should().Be(StructuredLogBatchBufferAddStatus.AddedFirst); + buffer.IsEmpty.Should().BeFalse(); + } + + [Fact] + public void Add_Disposed_CannotAdd() + { + _fixture.Capacity = 2; + var buffer = _fixture.GetSut(); + + buffer.Dispose(); + + buffer.Add("one").Should().Be(StructuredLogBatchBufferAddStatus.IgnoredIsDisposed); + buffer.IsEmpty.Should().BeTrue(); + } + [Fact] public void Flush_IsEmpty_EmptyArray() { @@ -227,7 +256,7 @@ public void Flush_TryEnterFlushScopeTwice_CanOnlyEnterOnce() } [Fact] - public void Flush_Disposed_Throws() + public void Flush_DisposedScope_Throws() { _fixture.Capacity = 2; using var buffer = _fixture.GetSut(); @@ -240,6 +269,19 @@ public void Flush_Disposed_Throws() AssertFlushThrows(flushScope); } + [Fact] + public void Flush_DisposedBuffer_CannotEnter() + { + _fixture.Capacity = 2; + var buffer = _fixture.GetSut(); + + buffer.Dispose(); + using var flushScope = buffer.TryEnterFlushScope(); + + flushScope.IsEntered.Should().BeFalse(); + AssertFlushThrows(flushScope); + } + [Fact] public void OnIntervalElapsed_Timeout_InvokesCallback() { @@ -256,6 +298,18 @@ public void OnIntervalElapsed_Timeout_InvokesCallback() _fixture.TimeoutExceededInvocations[1].Should().BeSameAs(buffer); } + [Fact] + public void OnIntervalElapsed_Disposed_DoesNotInvokeCallback() + { + _fixture.Timeout = Timeout.InfiniteTimeSpan; + var buffer = _fixture.GetSut(); + + buffer.Dispose(); + buffer.OnIntervalElapsed(null); + + _fixture.TimeoutExceededInvocations.Should().BeEmpty(); + } + // cannot use xUnit's Throws() nor Fluent Assertions' ThrowExactly() because the FlushScope is a ref struct private static void AssertFlushThrows(StructuredLogBatchBuffer.FlushScope flushScope) where T : Exception @@ -277,7 +331,7 @@ private static void AssertFlushThrows(StructuredLogBatchBuffer.FlushScope flu file static class StructuredLogBatchBufferHelpers { - public static BatchBufferAddStatus Add(this StructuredLogBatchBuffer buffer, string item) + public static StructuredLogBatchBufferAddStatus Add(this StructuredLogBatchBuffer buffer, string item) { SentryLog log = new(DateTimeOffset.MinValue, SentryId.Empty, SentryLogLevel.Trace, item); return buffer.Add(log); diff --git a/test/Sentry.Tests/Internals/StructuredLogBatchProcessorTests.cs b/test/Sentry.Tests/Internals/StructuredLogBatchProcessorTests.cs index 0696784ee3..200050e81d 100644 --- a/test/Sentry.Tests/Internals/StructuredLogBatchProcessorTests.cs +++ b/test/Sentry.Tests/Internals/StructuredLogBatchProcessorTests.cs @@ -25,10 +25,16 @@ public Fixture() CapturedEnvelopes = []; _hub.CaptureEnvelope(Arg.Do(arg => CapturedEnvelopes.Add(arg))); + _hub.IsEnabled.Returns(true); ExpectedDiagnosticLogs = 0; } + public void DisableHub() + { + _hub.IsEnabled.Returns(false); + } + public StructuredLogBatchProcessor GetSut(int batchCount) { return new StructuredLogBatchProcessor(_hub, batchCount, Timeout.InfiniteTimeSpan, ClientReportRecorder, DiagnosticLogger); @@ -164,6 +170,48 @@ which is a difference of {actualInvocations - capturedLogs - droppedLogs} logs. } } + [Fact] + public void Enqueue_HubDisabled_DoesNotCaptureEnvelope() + { + var processor = _fixture.GetSut(2); + + processor.Enqueue(CreateLog("one")); + _fixture.DisableHub(); + processor.Enqueue(CreateLog("two")); + Assert.Empty(_fixture.CapturedEnvelopes); + + processor.Flush(); + Assert.Single(_fixture.CapturedEnvelopes); + AssertEnvelope("one"); + } + + [Fact] + public void Flush_NeitherSizeNorTimeoutReached_CaptureEnvelope() + { + using var processor = _fixture.GetSut(2); + + processor.Enqueue(CreateLog("one")); + processor.Flush(); + + Assert.Single(_fixture.CapturedEnvelopes); + AssertEnvelope("one"); + } + + [Fact] + public void Dispose_Enqueue_DoesNotCaptureEnvelope() + { + var processor = _fixture.GetSut(2); + + processor.Enqueue(CreateLog("one")); + processor.Dispose(); + processor.Enqueue(CreateLog("two")); + processor.Flush(); + + Assert.Empty(_fixture.CapturedEnvelopes); + AssertEnvelope(); + _fixture.ExpectedDiagnosticLogs = 1; + } + private static SentryLog CreateLog(string message) { return new SentryLog(DateTimeOffset.MinValue, SentryId.Empty, SentryLogLevel.Trace, message); diff --git a/test/Sentry.Tests/SentryStructuredLoggerTests.cs b/test/Sentry.Tests/SentryStructuredLoggerTests.cs index 687714e6e9..aa303ba690 100644 --- a/test/Sentry.Tests/SentryStructuredLoggerTests.cs +++ b/test/Sentry.Tests/SentryStructuredLoggerTests.cs @@ -5,7 +5,7 @@ namespace Sentry.Tests; /// /// /// -public class SentryStructuredLoggerTests +public class SentryStructuredLoggerTests : IDisposable { internal sealed class Fixture { @@ -24,6 +24,8 @@ public Fixture() TraceId = SentryId.Create(); ParentSpanId = SpanId.Create(); + Hub.IsEnabled.Returns(true); + var traceHeader = new SentryTraceHeader(TraceId, ParentSpanId.Value, null); Hub.GetTraceHeader().Returns(traceHeader); } @@ -54,6 +56,11 @@ public SentryStructuredLoggerTests() _fixture = new Fixture(); } + public void Dispose() + { + _fixture.DiagnosticLogger.Entries.Should().BeEmpty(); + } + [Fact] public void Create_Enabled_NewDefaultInstance() { @@ -185,7 +192,7 @@ public void Log_InvalidFormat_DoesNotCaptureEnvelope() logger.LogTrace("Template string with arguments: {0}, {1}, {2}, {3}, {4}", ["string", true, 1, 2.2]); _fixture.Hub.Received(0).CaptureEnvelope(Arg.Any()); - var entry = _fixture.DiagnosticLogger.Entries.Should().ContainSingle().Which; + var entry = _fixture.DiagnosticLogger.Dequeue(); entry.Level.Should().Be(SentryLevel.Error); entry.Message.Should().Be("Template string does not match the provided argument. The Log will be dropped."); entry.Exception.Should().BeOfType(); @@ -201,7 +208,7 @@ public void Log_InvalidConfigureLog_DoesNotCaptureEnvelope() logger.LogTrace("Template string with arguments: {0}, {1}, {2}, {3}", ["string", true, 1, 2.2], static (SentryLog log) => throw new InvalidOperationException()); _fixture.Hub.Received(0).CaptureEnvelope(Arg.Any()); - var entry = _fixture.DiagnosticLogger.Entries.Should().ContainSingle().Which; + var entry = _fixture.DiagnosticLogger.Dequeue(); entry.Level.Should().Be(SentryLevel.Error); entry.Message.Should().Be("The configureLog callback threw an exception. The Log will be dropped."); entry.Exception.Should().BeOfType(); @@ -218,7 +225,7 @@ public void Log_InvalidBeforeSendLog_DoesNotCaptureEnvelope() logger.LogTrace("Template string with arguments: {0}, {1}, {2}, {3}", ["string", true, 1, 2.2]); _fixture.Hub.Received(0).CaptureEnvelope(Arg.Any()); - var entry = _fixture.DiagnosticLogger.Entries.Should().ContainSingle().Which; + var entry = _fixture.DiagnosticLogger.Dequeue(); entry.Level.Should().Be(SentryLevel.Error); entry.Message.Should().Be("The BeforeSendLog callback threw an exception. The Log will be dropped."); entry.Exception.Should().BeOfType(); @@ -226,15 +233,42 @@ public void Log_InvalidBeforeSendLog_DoesNotCaptureEnvelope() } [Fact] - public void Dispose_Log_Throws() + public void Flush_AfterLog_CapturesEnvelope() + { + _fixture.Options.Experimental.EnableLogs = true; + var logger = _fixture.GetSut(); + + Envelope envelope = null!; + _fixture.Hub.CaptureEnvelope(Arg.Do(arg => envelope = arg)); + + logger.Flush(); + _fixture.Hub.Received(0).CaptureEnvelope(Arg.Any()); + envelope.Should().BeNull(); + + logger.LogTrace("Template string with arguments: {0}, {1}, {2}, {3}", ["string", true, 1, 2.2], ConfigureLog); + _fixture.Hub.Received(0).CaptureEnvelope(Arg.Any()); + envelope.Should().BeNull(); + + logger.Flush(); + _fixture.Hub.Received(1).CaptureEnvelope(Arg.Any()); + envelope.AssertEnvelope(_fixture, SentryLogLevel.Trace); + } + + [Fact] + public void Dispose_BeforeLog_DoesNotCaptureEnvelope() { _fixture.Options.Experimental.EnableLogs = true; var logger = _fixture.GetSut(); logger.Dispose(); - var log = () => logger.LogTrace("Template string with arguments: {0}, {1}, {2}, {3}", ["string", true, 1, 2.2], ConfigureLog); + logger.LogTrace("Template string with arguments: {0}, {1}, {2}, {3}", ["string", true, 1, 2.2], ConfigureLog); - Assert.Throws(log); + _fixture.Hub.Received(0).CaptureEnvelope(Arg.Any()); + var entry = _fixture.DiagnosticLogger.Dequeue(); + entry.Level.Should().Be(SentryLevel.Info); + entry.Message.Should().Be("Log Buffer full ... dropping log"); + entry.Exception.Should().BeNull(); + entry.Args.Should().BeEmpty(); } private static void ConfigureLog(SentryLog log) diff --git a/test/Sentry.Tests/Threading/ScopedCountdownLockTests.cs b/test/Sentry.Tests/Threading/ScopedCountdownLockTests.cs index 58bd3f090d..dad07e1e23 100644 --- a/test/Sentry.Tests/Threading/ScopedCountdownLockTests.cs +++ b/test/Sentry.Tests/Threading/ScopedCountdownLockTests.cs @@ -114,6 +114,15 @@ public void TryEnterLockScope_IsEngaged_IsSet() AssertDisengaged(false, 0); } + [Fact] + public void Dispose_UseAfterDispose_Throws() + { + _lock.Dispose(); + + Assert.Throws(() => _lock.TryEnterCounterScope()); + Assert.Throws(() => _lock.TryEnterLockScope()); + } + private void AssertEngaged(bool isSet, int count) { using (new AssertionScope())