diff --git a/Build.ps1 b/Build.ps1 index 9b2d878..3c41f46 100644 --- a/Build.ps1 +++ b/Build.ps1 @@ -11,41 +11,33 @@ if(Test-Path .\artifacts) { $branch = @{ $true = $env:APPVEYOR_REPO_BRANCH; $false = $(git symbolic-ref --short -q HEAD) }[$env:APPVEYOR_REPO_BRANCH -ne $NULL]; $revision = @{ $true = "{0:00000}" -f [convert]::ToInt32("0" + $env:APPVEYOR_BUILD_NUMBER, 10); $false = "local" }[$env:APPVEYOR_BUILD_NUMBER -ne $NULL]; -$suffix = @{ $true = ""; $false = "$($branch.Substring(0, [math]::Min(10,$branch.Length)))-$revision"}[$branch -eq "master" -and $revision -ne "local"] +$suffix = @{ $true = ""; $false = "$($branch.Substring(0, [math]::Min(10,$branch.Length)))-$revision"}[$branch -eq "main" -and $revision -ne "local"] +$commitHash = $(git rev-parse --short HEAD) +$buildSuffix = @{ $true = "$($suffix)-$($commitHash)"; $false = "$($branch)-$($commitHash)" }[$suffix -ne ""] -echo "build: Version suffix is $suffix" +echo "build: Package version suffix is $suffix" +echo "build: Build version suffix is $buildSuffix" foreach ($src in ls src/*) { Push-Location $src - echo "build: Packaging project in $src" + echo "build: Packaging project in $src" + & dotnet build -c Release --version-suffix=$buildSuffix -p:EnableSourceLink=true if ($suffix) { - & dotnet pack -c Release -o ..\..\artifacts --version-suffix=$suffix --include-source + & dotnet pack -c Release -o ..\..\artifacts --version-suffix=$suffix --no-build } else { - & dotnet pack -c Release -o ..\..\artifacts --include-source + & dotnet pack -c Release -o ..\..\artifacts --no-build } - if($LASTEXITCODE -ne 0) { exit 1 } Pop-Location } -foreach ($test in ls test/*.PerformanceTests) { - Push-Location $test - - echo "build: Building performance test project in $test" - - & dotnet build -c Release - if($LASTEXITCODE -ne 0) { exit 2 } - - Pop-Location -} - foreach ($test in ls test/*.Tests) { Push-Location $test - echo "build: Testing project in $test" + echo "build: Testing project in $test" & dotnet test -c Release if($LASTEXITCODE -ne 0) { exit 3 } diff --git a/README.md b/README.md index d2ef981..6b09740 100644 --- a/README.md +++ b/README.md @@ -70,7 +70,7 @@ var monitor = new MonitorConfiguration(); ### Blocking -Warning: For the same reason one typically does not want exceptions from logging to leak into the execution path, one typically does not want a logger to be able to have the side-efect of actually interrupting application processing until the log propagation has been unblocked. +Warning: For the same reason one typically does not want exceptions from logging to leak into the execution path, one typically does not want a logger to be able to have the side-effect of actually interrupting application processing until the log propagation has been unblocked. When the buffer size limit is reached, the default behavior is to drop any further attempted writes until the queue abates, reporting each such failure to the `Serilog.Debugging.SelfLog`. To replace this with a blocking behaviour, set `blockWhenFull` to `true`. diff --git a/appveyor.yml b/appveyor.yml index d342c71..88fbdbd 100644 --- a/appveyor.yml +++ b/appveyor.yml @@ -1,22 +1,22 @@ version: '{build}' skip_tags: true -image: Visual Studio 2019 +image: Visual Studio 2022 build_script: -- ps: ./Build.ps1 +- pwsh: ./Build.ps1 test: off artifacts: - path: artifacts/Serilog.*.nupkg deploy: - provider: NuGet api_key: - secure: rbdBqxBpLt4MkB+mrDOYNDOd8aVZ1zMkysaVNAXNKnC41FYifzX3l9LM8DCrUWU5 + secure: ZpUO4ECx4c/V0Ecj04cfV1UGd+ZABeEG9DDW2fjG8vITjNYhmbiiJH0qNOnRy2G3 skip_symbols: true on: - branch: /^(master|dev)$/ + branch: /^(main|dev)$/ - provider: GitHub auth_token: secure: p4LpVhBKxGS5WqucHxFQ5c7C8cP74kbNB0Z8k9Oxx/PMaDQ1+ibmoexNqVU5ZlmX artifact: /Serilog.*\.nupkg/ tag: v$(appveyor_build_version) on: - branch: master + branch: main diff --git a/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs b/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs index 2656026..e505c4f 100644 --- a/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs +++ b/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs @@ -1,80 +1,51 @@ -using System; -using System.ComponentModel; +// Copyright © Serilog Contributors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +using System; using Serilog.Configuration; using Serilog.Sinks.Async; -using Serilog.Events; -namespace Serilog +namespace Serilog; + +/// +/// Extends with methods for configuring asynchronous logging. +/// +public static class LoggerConfigurationAsyncExtensions { /// - /// Extends with methods for configuring asynchronous logging. + /// Configure a sink to be invoked asynchronously, on a background worker thread. + /// Accepts a reference to a that will be supplied the internal state interface for health monitoring purposes. /// - public static class LoggerConfigurationAsyncExtensions + /// The being configured. + /// An action that configures the wrapped sink. + /// The size of the concurrent queue used to feed the background worker thread. If + /// the thread is unable to process events quickly enough and the queue is filled, depending on + /// the queue will block or subsequent events will be dropped until + /// room is made in the queue. + /// Block when the queue is full, instead of dropping events. + /// Monitor to supply buffer information to. + /// A allowing configuration to continue. + public static LoggerConfiguration Async( + this LoggerSinkConfiguration loggerSinkConfiguration, + Action configure, + int bufferSize = 10000, + bool blockWhenFull = false, + IAsyncLogEventSinkMonitor? monitor = null) { - /// - /// Configure a sink to be invoked asynchronously, on a background worker thread. - /// - /// The being configured. - /// An action that configures the wrapped sink. - /// The size of the concurrent queue used to feed the background worker thread. If - /// the thread is unable to process events quickly enough and the queue is filled, subsequent events will be - /// dropped until room is made in the queue. - /// A allowing configuration to continue. - [EditorBrowsable(EditorBrowsableState.Never)] - public static LoggerConfiguration Async( - this LoggerSinkConfiguration loggerSinkConfiguration, - Action configure, - int bufferSize) - { - return loggerSinkConfiguration.Async(configure, bufferSize, false); - } - - /// - /// Configure a sink to be invoked asynchronously, on a background worker thread. - /// - /// The being configured. - /// An action that configures the wrapped sink. - /// The size of the concurrent queue used to feed the background worker thread. If - /// the thread is unable to process events quickly enough and the queue is filled, depending on - /// the queue will block or subsequent events will be dropped until - /// room is made in the queue. - /// Block when the queue is full, instead of dropping events. - /// A allowing configuration to continue. - public static LoggerConfiguration Async( - this LoggerSinkConfiguration loggerSinkConfiguration, - Action configure, - int bufferSize = 10000, - bool blockWhenFull = false) - { - return loggerSinkConfiguration.Async(configure, null, bufferSize, blockWhenFull); - } - - /// - /// Configure a sink to be invoked asynchronously, on a background worker thread. - /// Accepts a reference to a that will be supplied the internal state interface for health monitoring purposes. - /// - /// The being configured. - /// An action that configures the wrapped sink. - /// The size of the concurrent queue used to feed the background worker thread. If - /// the thread is unable to process events quickly enough and the queue is filled, depending on - /// the queue will block or subsequent events will be dropped until - /// room is made in the queue. - /// Block when the queue is full, instead of dropping events. - /// Monitor to supply buffer information to. - /// A allowing configuration to continue. - public static LoggerConfiguration Async( - this LoggerSinkConfiguration loggerSinkConfiguration, - Action configure, - IAsyncLogEventSinkMonitor monitor, - int bufferSize = 10000, - bool blockWhenFull = false) - { - return LoggerSinkConfiguration.Wrap( - loggerSinkConfiguration, - wrappedSink => new BackgroundWorkerSink(wrappedSink, bufferSize, blockWhenFull, monitor), - configure, - LevelAlias.Minimum, - null); - } + var wrapper = LoggerSinkConfiguration.Wrap( + wrappedSink => new BackgroundWorkerSink(wrappedSink, bufferSize, blockWhenFull, monitor), + configure); + return loggerSinkConfiguration.Sink(wrapper); } } \ No newline at end of file diff --git a/src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj b/src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj index 40dafa7..6b2733f 100644 --- a/src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj +++ b/src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj @@ -2,17 +2,20 @@ Asynchronous sink wrapper for Serilog. - 1.5.0 + 2.0.0 Jezz Santos;Serilog Contributors - net45;netstandard1.1;net461;netstandard2.0 + + net471;net462 + + $(TargetFrameworks);net8.0;net6.0;netstandard2.0 true true - Serilog.Sinks.Async Serilog ../../assets/Serilog.snk true true - Serilog.Sinks.Async serilog;async serilog-sink-nuget.png https://serilog.net @@ -20,27 +23,19 @@ https://github.com/serilog/serilog-sinks-async git True + README.md + 12 + enable - - - true - - - - - - - - + + - - True - - + + diff --git a/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs b/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs index a27f878..e755cf3 100644 --- a/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs +++ b/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs @@ -1,4 +1,18 @@ -using System; +// Copyright © Serilog Contributors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +using System; using System.Collections.Concurrent; using System.Threading; using System.Threading.Tasks; @@ -6,95 +20,94 @@ using Serilog.Debugging; using Serilog.Events; -namespace Serilog.Sinks.Async +namespace Serilog.Sinks.Async; + +sealed class BackgroundWorkerSink : ILogEventSink, IAsyncLogEventSinkInspector, IDisposable { - sealed class BackgroundWorkerSink : ILogEventSink, IAsyncLogEventSinkInspector, IDisposable - { - readonly ILogEventSink _wrappedSink; - readonly bool _blockWhenFull; - readonly BlockingCollection _queue; - readonly Task _worker; - readonly IAsyncLogEventSinkMonitor _monitor; + readonly ILogEventSink _wrappedSink; + readonly bool _blockWhenFull; + readonly BlockingCollection _queue; + readonly Task _worker; + readonly IAsyncLogEventSinkMonitor? _monitor; - long _droppedMessages; + long _droppedMessages; - public BackgroundWorkerSink(ILogEventSink wrappedSink, int bufferCapacity, bool blockWhenFull, IAsyncLogEventSinkMonitor monitor = null) - { - if (bufferCapacity <= 0) throw new ArgumentOutOfRangeException(nameof(bufferCapacity)); - _wrappedSink = wrappedSink ?? throw new ArgumentNullException(nameof(wrappedSink)); - _blockWhenFull = blockWhenFull; - _queue = new BlockingCollection(bufferCapacity); - _worker = Task.Factory.StartNew(Pump, CancellationToken.None, TaskCreationOptions.LongRunning | TaskCreationOptions.DenyChildAttach, TaskScheduler.Default); - _monitor = monitor; - monitor?.StartMonitoring(this); - } + public BackgroundWorkerSink(ILogEventSink wrappedSink, int bufferCapacity, bool blockWhenFull, IAsyncLogEventSinkMonitor? monitor) + { + if (bufferCapacity <= 0) throw new ArgumentOutOfRangeException(nameof(bufferCapacity)); + _wrappedSink = wrappedSink ?? throw new ArgumentNullException(nameof(wrappedSink)); + _blockWhenFull = blockWhenFull; + _queue = new BlockingCollection(bufferCapacity); + _worker = Task.Factory.StartNew(Pump, CancellationToken.None, TaskCreationOptions.LongRunning | TaskCreationOptions.DenyChildAttach, TaskScheduler.Default); + _monitor = monitor; + monitor?.StartMonitoring(this); + } - public void Emit(LogEvent logEvent) - { - if (_queue.IsAddingCompleted) - return; + public void Emit(LogEvent logEvent) + { + if (_queue.IsAddingCompleted) + return; - try + try + { + if (_blockWhenFull) { - if (_blockWhenFull) - { - _queue.Add(logEvent); - } - else - { - if (!_queue.TryAdd(logEvent)) - { - Interlocked.Increment(ref _droppedMessages); - SelfLog.WriteLine("{0} unable to enqueue, capacity {1}", typeof(BackgroundWorkerSink), _queue.BoundedCapacity); - } - } + _queue.Add(logEvent); } - catch (InvalidOperationException) + else { - // Thrown in the event of a race condition when we try to add another event after - // CompleteAdding has been called + if (!_queue.TryAdd(logEvent)) + { + Interlocked.Increment(ref _droppedMessages); + SelfLog.WriteLine("{0} unable to enqueue, capacity {1}", typeof(BackgroundWorkerSink), _queue.BoundedCapacity); + } } } - - public void Dispose() + catch (InvalidOperationException) { - // Prevent any more events from being added - _queue.CompleteAdding(); + // Thrown in the event of a race condition when we try to add another event after + // CompleteAdding has been called + } + } + + public void Dispose() + { + // Prevent any more events from being added + _queue.CompleteAdding(); - // Allow queued events to be flushed - _worker.Wait(); + // Allow queued events to be flushed + _worker.Wait(); - (_wrappedSink as IDisposable)?.Dispose(); + (_wrappedSink as IDisposable)?.Dispose(); - _monitor?.StopMonitoring(this); - } + _monitor?.StopMonitoring(this); + } - void Pump() + void Pump() + { + try { - try + foreach (var next in _queue.GetConsumingEnumerable()) { - foreach (var next in _queue.GetConsumingEnumerable()) + try { - try - { - _wrappedSink.Emit(next); - } - catch (Exception ex) - { - SelfLog.WriteLine("{0} failed to emit event to wrapped sink: {1}", typeof(BackgroundWorkerSink), ex); - } + _wrappedSink.Emit(next); + } + catch (Exception ex) + { + SelfLog.WriteLine("{0} failed to emit event to wrapped sink: {1}", typeof(BackgroundWorkerSink), ex); } - } - catch (Exception fatal) - { - SelfLog.WriteLine("{0} fatal error in worker thread: {1}", typeof(BackgroundWorkerSink), fatal); } } + catch (Exception fatal) + { + SelfLog.WriteLine("{0} fatal error in worker thread: {1}", typeof(BackgroundWorkerSink), fatal); + } + } - int IAsyncLogEventSinkInspector.BufferSize => _queue.BoundedCapacity; + int IAsyncLogEventSinkInspector.BufferSize => _queue.BoundedCapacity; - int IAsyncLogEventSinkInspector.Count => _queue.Count; + int IAsyncLogEventSinkInspector.Count => _queue.Count; - long IAsyncLogEventSinkInspector.DroppedMessagesCount => _droppedMessages; - } + long IAsyncLogEventSinkInspector.DroppedMessagesCount => _droppedMessages; } \ No newline at end of file diff --git a/src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkInspector.cs b/src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkInspector.cs index 0edccdc..8e011dd 100644 --- a/src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkInspector.cs +++ b/src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkInspector.cs @@ -1,25 +1,38 @@ -namespace Serilog.Sinks.Async +// Copyright © Serilog Contributors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +namespace Serilog.Sinks.Async; + +/// +/// Provides a way to inspect the state of Async wrapper's ingestion queue. +/// +public interface IAsyncLogEventSinkInspector { /// - /// Provides a way to inspect the state of Async wrapper's ingestion queue. + /// Configured maximum number of items permitted to be held in the buffer awaiting ingestion. /// - public interface IAsyncLogEventSinkInspector - { - /// - /// Configured maximum number of items permitted to be held in the buffer awaiting ingestion. - /// - /// The Sink has been disposed. - int BufferSize { get; } + /// The Sink has been disposed. + int BufferSize { get; } - /// - /// Current moment-in-time Count of items currently awaiting ingestion. - /// - /// The Sink has been disposed. - int Count { get; } + /// + /// Current moment-in-time Count of items currently awaiting ingestion. + /// + /// The Sink has been disposed. + int Count { get; } - /// - /// Accumulated number of messages dropped due to breaches of limit. - /// - long DroppedMessagesCount { get; } - } + /// + /// Accumulated number of messages dropped due to breaches of limit. + /// + long DroppedMessagesCount { get; } } \ No newline at end of file diff --git a/src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkMonitor.cs b/src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkMonitor.cs index 26a43d1..98c801f 100644 --- a/src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkMonitor.cs +++ b/src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkMonitor.cs @@ -1,20 +1,33 @@ -namespace Serilog.Sinks.Async +// Copyright © Serilog Contributors +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +namespace Serilog.Sinks.Async; + +/// +/// Defines a mechanism for the Async Sink to afford Health Checks a buffer metadata inspection mechanism. +/// +public interface IAsyncLogEventSinkMonitor { /// - /// Defines a mechanism for the Async Sink to afford Health Checks a buffer metadata inspection mechanism. + /// Invoked by Sink to supply the inspector to the monitor. /// - public interface IAsyncLogEventSinkMonitor - { - /// - /// Invoked by Sink to supply the inspector to the monitor. - /// - /// The Async Sink's inspector. - void StartMonitoring(IAsyncLogEventSinkInspector inspector); + /// The Async Sink's inspector. + void StartMonitoring(IAsyncLogEventSinkInspector inspector); - /// - /// Invoked by Sink to indicate that it is being Disposed. - /// - /// The Async Sink's inspector. - void StopMonitoring(IAsyncLogEventSinkInspector inspector); - } + /// + /// Invoked by Sink to indicate that it is being Disposed. + /// + /// The Async Sink's inspector. + void StopMonitoring(IAsyncLogEventSinkInspector inspector); } \ No newline at end of file diff --git a/test/Serilog.Sinks.Async.PerformanceTests/Benchmarks.cs b/test/Serilog.Sinks.Async.PerformanceTests/Benchmarks.cs index 399b3e9..a735d35 100644 --- a/test/Serilog.Sinks.Async.PerformanceTests/Benchmarks.cs +++ b/test/Serilog.Sinks.Async.PerformanceTests/Benchmarks.cs @@ -1,15 +1,14 @@ using BenchmarkDotNet.Running; using Xunit; -namespace Serilog.Sinks.Async.PerformanceTests +namespace Serilog.Sinks.Async.PerformanceTests; + +public class Benchmarks { - public class Benchmarks + [Fact] + public void Benchmark() { - [Fact] - public void Benchmark() - { - BenchmarkRunner.Run(); - BenchmarkRunner.Run(); - } + BenchmarkRunner.Run(); + BenchmarkRunner.Run(); } } \ No newline at end of file diff --git a/test/Serilog.Sinks.Async.PerformanceTests/LatencyBenchmark.cs b/test/Serilog.Sinks.Async.PerformanceTests/LatencyBenchmark.cs index adaacea..45ce8c6 100644 --- a/test/Serilog.Sinks.Async.PerformanceTests/LatencyBenchmark.cs +++ b/test/Serilog.Sinks.Async.PerformanceTests/LatencyBenchmark.cs @@ -7,72 +7,71 @@ using Serilog.Parsing; using Serilog.Sinks.Async.PerformanceTests.Support; -namespace Serilog.Sinks.Async.PerformanceTests +namespace Serilog.Sinks.Async.PerformanceTests; + +public class LatencyBenchmark { - public class LatencyBenchmark - { - readonly LogEvent _evt = new LogEvent(DateTimeOffset.Now, LogEventLevel.Information, null, - new MessageTemplate(new[] {new TextToken("Hello")}), new LogEventProperty[0]); + readonly LogEvent _evt = new LogEvent(DateTimeOffset.Now, LogEventLevel.Information, null, + new MessageTemplate(new[] {new TextToken("Hello")}), new LogEventProperty[0]); - Logger _syncLogger, _asyncLogger, _fileLogger, _asyncFileLogger; + Logger _syncLogger, _asyncLogger, _fileLogger, _asyncFileLogger; - static LatencyBenchmark() + static LatencyBenchmark() + { + SelfLog.Enable(new TerminatingTextWriter()); + } + + [GlobalSetup] + public void Reset() + { + foreach (var logger in new[] { _syncLogger, _asyncLogger, _fileLogger, _asyncFileLogger}) { - SelfLog.Enable(new TerminatingTextWriter()); + logger?.Dispose(); } - [GlobalSetup] - public void Reset() + foreach (var tmp in Directory.GetFiles(".", "*.tmplog")) { - foreach (var logger in new[] { _syncLogger, _asyncLogger, _fileLogger, _asyncFileLogger}) - { - logger?.Dispose(); - } - - foreach (var tmp in Directory.GetFiles(".", "*.tmplog")) - { - System.IO.File.Delete(tmp); - } + System.IO.File.Delete(tmp); + } - _syncLogger = new LoggerConfiguration() - .WriteTo.Sink(new SilentSink()) - .CreateLogger(); + _syncLogger = new LoggerConfiguration() + .WriteTo.Sink(new SilentSink()) + .CreateLogger(); - _asyncLogger = new LoggerConfiguration() - .WriteTo.Async(a => a.Sink(new SilentSink()), 10000000) - .CreateLogger(); + _asyncLogger = new LoggerConfiguration() + .WriteTo.Async(a => a.Sink(new SilentSink()), 10000000) + .CreateLogger(); - _fileLogger = new LoggerConfiguration() - .WriteTo.File("sync-file.tmplog") - .CreateLogger(); + _fileLogger = new LoggerConfiguration() + .WriteTo.File("sync-file.tmplog") + .CreateLogger(); - _asyncFileLogger = new LoggerConfiguration() - .WriteTo.Async(a => a.File("async-file.tmplog"), 10000000) - .CreateLogger(); - } + _asyncFileLogger = new LoggerConfiguration() + .WriteTo.Async(a => a.File("async-file.tmplog"), 10000000) + .CreateLogger(); + } - [Benchmark(Baseline = true)] - public void Sync() - { - _syncLogger.Write(_evt); - } + [Benchmark(Baseline = true)] + public void Sync() + { + _syncLogger.Write(_evt); + } - [Benchmark] - public void Async() - { - _asyncLogger.Write(_evt); - } + [Benchmark] + public void Async() + { + _asyncLogger.Write(_evt); + } - [Benchmark] - public void File() - { - _fileLogger.Write(_evt); - } + [Benchmark] + public void File() + { + _fileLogger.Write(_evt); + } - [Benchmark] - public void AsyncFile() - { - _asyncFileLogger.Write(_evt); - } + [Benchmark] + public void AsyncFile() + { + _asyncFileLogger.Write(_evt); } -} +} \ No newline at end of file diff --git a/test/Serilog.Sinks.Async.PerformanceTests/Serilog.Sinks.Async.PerformanceTests.csproj b/test/Serilog.Sinks.Async.PerformanceTests/Serilog.Sinks.Async.PerformanceTests.csproj index ffe0d1d..5ea1c91 100644 --- a/test/Serilog.Sinks.Async.PerformanceTests/Serilog.Sinks.Async.PerformanceTests.csproj +++ b/test/Serilog.Sinks.Async.PerformanceTests/Serilog.Sinks.Async.PerformanceTests.csproj @@ -1,8 +1,8 @@  - net461;netcoreapp2.0 - Serilog.Sinks.Async.PerformanceTests + net48 + $(TargetFrameworks);net6.0;net8.0 ../../assets/Serilog.snk true true @@ -17,18 +17,14 @@ - - - + + + all runtime; build; native; contentfiles; analyzers - - - - - - + + diff --git a/test/Serilog.Sinks.Async.PerformanceTests/SignallingSink.cs b/test/Serilog.Sinks.Async.PerformanceTests/SignallingSink.cs index 2882227..56b6c66 100644 --- a/test/Serilog.Sinks.Async.PerformanceTests/SignallingSink.cs +++ b/test/Serilog.Sinks.Async.PerformanceTests/SignallingSink.cs @@ -3,36 +3,35 @@ using Serilog.Core; using Serilog.Events; -namespace Serilog.Sinks.Async.PerformanceTests +namespace Serilog.Sinks.Async.PerformanceTests; + +class SignallingSink : ILogEventSink { - class SignallingSink : ILogEventSink - { - readonly int _expectedCount; - readonly ManualResetEvent _wh; - int _current; + readonly int _expectedCount; + readonly ManualResetEvent _wh; + int _current; - public SignallingSink(int expectedCount) - { - _expectedCount = expectedCount; - _wh = new ManualResetEvent(false); - } + public SignallingSink(int expectedCount) + { + _expectedCount = expectedCount; + _wh = new ManualResetEvent(false); + } - public void Emit(LogEvent logEvent) - { - if (Interlocked.Increment(ref _current) == _expectedCount) - _wh.Set(); - } + public void Emit(LogEvent logEvent) + { + if (Interlocked.Increment(ref _current) == _expectedCount) + _wh.Set(); + } - public void Reset() - { - _wh.Reset(); - _current = 0; - } + public void Reset() + { + _wh.Reset(); + _current = 0; + } - public void Wait() - { - if (!_wh.WaitOne(60000)) - throw new TimeoutException("Event was not signaled within 60s."); - } + public void Wait() + { + if (!_wh.WaitOne(60000)) + throw new TimeoutException("Event was not signaled within 60s."); } } \ No newline at end of file diff --git a/test/Serilog.Sinks.Async.PerformanceTests/SilentSink.cs b/test/Serilog.Sinks.Async.PerformanceTests/SilentSink.cs index 767b877..cf67d58 100644 --- a/test/Serilog.Sinks.Async.PerformanceTests/SilentSink.cs +++ b/test/Serilog.Sinks.Async.PerformanceTests/SilentSink.cs @@ -1,12 +1,11 @@ using Serilog.Core; using Serilog.Events; -namespace Serilog.Sinks.Async.PerformanceTests +namespace Serilog.Sinks.Async.PerformanceTests; + +public class SilentSink : ILogEventSink { - public class SilentSink : ILogEventSink + public void Emit(LogEvent logEvent) { - public void Emit(LogEvent logEvent) - { - } } } \ No newline at end of file diff --git a/test/Serilog.Sinks.Async.PerformanceTests/Support/TerminatingTextWriter.cs b/test/Serilog.Sinks.Async.PerformanceTests/Support/TerminatingTextWriter.cs index deae8ba..64321e9 100644 --- a/test/Serilog.Sinks.Async.PerformanceTests/Support/TerminatingTextWriter.cs +++ b/test/Serilog.Sinks.Async.PerformanceTests/Support/TerminatingTextWriter.cs @@ -2,16 +2,15 @@ using System.IO; using System.Text; -namespace Serilog.Sinks.Async.PerformanceTests.Support +namespace Serilog.Sinks.Async.PerformanceTests.Support; + +public class TerminatingTextWriter : TextWriter { - public class TerminatingTextWriter : TextWriter - { - public override Encoding Encoding { get; } = Encoding.ASCII; + public override Encoding Encoding { get; } = Encoding.ASCII; - public override void Write(char value) - { - Console.WriteLine("SelfLog triggered"); - Environment.Exit(1); - } + public override void Write(char value) + { + Console.WriteLine("SelfLog triggered"); + Environment.Exit(1); } } \ No newline at end of file diff --git a/test/Serilog.Sinks.Async.PerformanceTests/ThroughputBenchmark.cs b/test/Serilog.Sinks.Async.PerformanceTests/ThroughputBenchmark.cs index f527e1e..4a7e201 100644 --- a/test/Serilog.Sinks.Async.PerformanceTests/ThroughputBenchmark.cs +++ b/test/Serilog.Sinks.Async.PerformanceTests/ThroughputBenchmark.cs @@ -4,26 +4,26 @@ using Serilog.Events; using Serilog.Parsing; -namespace Serilog.Sinks.Async.PerformanceTests +namespace Serilog.Sinks.Async.PerformanceTests; + +public class ThroughputBenchmark { - public class ThroughputBenchmark - { - const int Count = 10000; + const int Count = 10000; - readonly LogEvent _evt = new LogEvent(DateTimeOffset.Now, LogEventLevel.Information, null, - new MessageTemplate(new[] {new TextToken("Hello")}), new LogEventProperty[0]); + readonly LogEvent _evt = new LogEvent(DateTimeOffset.Now, LogEventLevel.Information, null, + new MessageTemplate(new[] {new TextToken("Hello")}), new LogEventProperty[0]); - readonly SignallingSink _signal; - Logger _syncLogger, _asyncLogger; + readonly SignallingSink _signal; + Logger _syncLogger, _asyncLogger; - public ThroughputBenchmark() - { + public ThroughputBenchmark() + { _signal = new SignallingSink(Count); } - [GlobalSetup] - public void Reset() - { + [GlobalSetup] + public void Reset() + { _syncLogger?.Dispose(); _asyncLogger?.Dispose(); @@ -38,9 +38,9 @@ public void Reset() .CreateLogger(); } - [Benchmark(Baseline = true)] - public void Sync() - { + [Benchmark(Baseline = true)] + public void Sync() + { for (var i = 0; i < Count; ++i) { _syncLogger.Write(_evt); @@ -50,9 +50,9 @@ public void Sync() _signal.Wait(); } - [Benchmark] - public void Async() - { + [Benchmark] + public void Async() + { for (var i = 0; i < Count; ++i) { _asyncLogger.Write(_evt); @@ -60,5 +60,4 @@ public void Async() _signal.Wait(); } - } } \ No newline at end of file diff --git a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkIntegrationSpec.cs b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkIntegrationSpec.cs index 23a937e..ff379f8 100644 --- a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkIntegrationSpec.cs +++ b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkIntegrationSpec.cs @@ -8,160 +8,160 @@ using Xunit; using System.Linq; -namespace Serilog.Sinks.Async.Tests +namespace Serilog.Sinks.Async.Tests; + +public static class BackgroundWorkerSinkIntegrationSpec { - public class BackgroundWorkerSinkIntegrationSpec + /// + /// If , then adds a 1sec delay before every fifth element created + /// + static void CreateAudits(ILogger logger, int count, bool withDelay) { - /// - /// If , then adds a 1sec delay before every fifth element created - /// - static void CreateAudits(ILogger logger, int count, bool withDelay) + var delay = TimeSpan.FromMilliseconds(1000); + var sw = new Stopwatch(); + sw.Start(); + Debug.WriteLine("{0:h:mm:ss tt} Start: Writing {1} audits", DateTime.Now, count); + try { - var delay = TimeSpan.FromMilliseconds(1000); - var sw = new Stopwatch(); - sw.Start(); - Debug.WriteLine("{0:h:mm:ss tt} Start: Writing {1} audits", DateTime.Now, count); - try + var delayCount = 0; + Loop.For(counter => { - var delayCount = 0; - Loop.For(counter => + if (withDelay + && counter > 0 + && counter % 5 == 0) { - if (withDelay - && counter > 0 - && counter%5 == 0) - { - delayCount++; - Debug.WriteLine("{0:h:mm:ss tt} Delay ({1}) after {2}th write, for {3:0.###}secs", DateTime.Now, - delayCount, counter, - delay.TotalSeconds); - Thread.Sleep(delay); - } - logger.Information("{$Counter}", counter); - }, count); - } - finally - { - sw.Stop(); - Debug.WriteLine("{0:h:mm:ss tt} End: Writing {1} audits, taking {2:0.###}", DateTime.Now, count, - sw.Elapsed.TotalSeconds); - } - } + delayCount++; + Debug.WriteLine("{0:h:mm:ss tt} Delay ({1}) after {2}th write, for {3:0.###}secs", DateTime.Now, + delayCount, counter, + delay.TotalSeconds); + Thread.Sleep(delay); + } - static List RetrieveEvents(MemorySink sink, int count) + logger.Information("{$Counter}", counter); + }, count); + } + finally { - Debug.WriteLine("{0:h:mm:ss tt} Retrieving {1} events", DateTime.Now, count); + sw.Stop(); + Debug.WriteLine("{0:h:mm:ss tt} End: Writing {1} audits, taking {2:0.###}", DateTime.Now, count, + sw.Elapsed.TotalSeconds); + } + } - Loop.Retry(() => sink.Events, events => events != null && events.Count >= count, TimeSpan.FromSeconds(1), - TimeSpan.FromSeconds(30)); + static List RetrieveEvents(MemorySink sink, int count) + { + Debug.WriteLine("{0:h:mm:ss tt} Retrieving {1} events", DateTime.Now, count); - return sink.Events.ToList(); - } + Loop.Retry(() => sink.Events, events => events != null && events.Count >= count, TimeSpan.FromSeconds(1), + TimeSpan.FromSeconds(30)); - public class GivenNoBufferQueueAndNoDelays : SinkSpecBase - { - public GivenNoBufferQueueAndNoDelays() - : base(false, false) - { - } - } + return sink.Events.ToList(); + } - public class GivenBufferQueueAndNoDelays : SinkSpecBase + public class GivenNoBufferQueueAndNoDelays : SinkSpecBase + { + public GivenNoBufferQueueAndNoDelays() + : base(false, false) { - public GivenBufferQueueAndNoDelays() - : base(true, false) - { - } } + } - public class GivenNoBufferQueueAndDelays : SinkSpecBase + public class GivenBufferQueueAndNoDelays : SinkSpecBase + { + public GivenBufferQueueAndNoDelays() + : base(true, false) { - public GivenNoBufferQueueAndDelays() - : base(false, true) - { - } } + } - public class GivenBufferQueueAndDelays : SinkSpecBase + public class GivenNoBufferQueueAndDelays : SinkSpecBase + { + public GivenNoBufferQueueAndDelays() + : base(false, true) { - public GivenBufferQueueAndDelays() - : base(true, true) - { - } } + } - public abstract class SinkSpecBase : IDisposable + public class GivenBufferQueueAndDelays : SinkSpecBase + { + public GivenBufferQueueAndDelays() + : base(true, true) { - bool _delayCreation; - Logger _logger; - MemorySink _memorySink; + } + } - protected SinkSpecBase(bool useBufferedQueue, bool delayCreation) - { - _delayCreation = delayCreation; + public abstract class SinkSpecBase : IDisposable + { + readonly bool _delayCreation; + readonly Logger _logger; + readonly MemorySink _memorySink; - _memorySink = new MemorySink(); + protected SinkSpecBase(bool useBufferedQueue, bool delayCreation) + { + _delayCreation = delayCreation; - if (useBufferedQueue) - { - _logger = new LoggerConfiguration() - .WriteTo.Async(a => a.Sink(_memorySink)) - .CreateLogger(); - } - else - { - _logger = new LoggerConfiguration() - .WriteTo.Sink(_memorySink) - .CreateLogger(); - } + _memorySink = new MemorySink(); - Debug.WriteLine("{0:h:mm:ss tt} Started test", DateTime.Now); + if (useBufferedQueue) + { + _logger = new LoggerConfiguration() + .WriteTo.Async(a => a.Sink(_memorySink)) + .CreateLogger(); } - - public void Dispose() + else { - _logger.Dispose(); - Debug.WriteLine("{0:h:mm:ss tt} Ended test", DateTime.Now); + _logger = new LoggerConfiguration() + .WriteTo.Sink(_memorySink) + .CreateLogger(); } - [Fact] - public void WhenAuditSingle_ThenQueued() - { - CreateAudits(_logger, 1, _delayCreation); + Debug.WriteLine("{0:h:mm:ss tt} Started test", DateTime.Now); + } - var result = RetrieveEvents(_memorySink, 1); + public void Dispose() + { + _logger.Dispose(); + Debug.WriteLine("{0:h:mm:ss tt} Ended test", DateTime.Now); + } - Assert.Single(result); - } + [Fact] + public void WhenAuditSingle_ThenQueued() + { + CreateAudits(_logger, 1, _delayCreation); - [Fact] - public void WhenAuditTen_ThenQueued() - { - CreateAudits(_logger, 10, _delayCreation); + var result = RetrieveEvents(_memorySink, 1); - var result = RetrieveEvents(_memorySink, 10); + Assert.Single(result); + } - Assert.Equal(10, result.Count); - } + [Fact] + public void WhenAuditTen_ThenQueued() + { + CreateAudits(_logger, 10, _delayCreation); - [Fact] - public void WhenAuditHundred_ThenQueued() - { - CreateAudits(_logger, 100, _delayCreation); + var result = RetrieveEvents(_memorySink, 10); - var result = RetrieveEvents(_memorySink, 100); + Assert.Equal(10, result.Count); + } - Assert.Equal(100, result.Count); - } + [Fact] + public void WhenAuditHundred_ThenQueued() + { + CreateAudits(_logger, 100, _delayCreation); - [Fact] - public void WhenAuditFiveHundred_ThenQueued() - { - CreateAudits(_logger, 500, _delayCreation); + var result = RetrieveEvents(_memorySink, 100); - var result = RetrieveEvents(_memorySink, 500); + Assert.Equal(100, result.Count); + } - Assert.Equal(500, result.Count); - } + [Fact] + public void WhenAuditFiveHundred_ThenQueued() + { + CreateAudits(_logger, 500, _delayCreation); + + var result = RetrieveEvents(_memorySink, 500); + + Assert.Equal(500, result.Count); } } } \ No newline at end of file diff --git a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs index dff5d5d..b42e633 100644 --- a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs +++ b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs @@ -2,7 +2,6 @@ using System.Collections.Generic; using System.Diagnostics; using System.Linq; -using System.Threading; using System.Threading.Tasks; using Serilog.Core; using Serilog.Events; @@ -10,236 +9,229 @@ using Serilog.Sinks.Async.Tests.Support; using Xunit; -namespace Serilog.Sinks.Async.Tests +namespace Serilog.Sinks.Async.Tests; + +public class BackgroundWorkerSinkSpec { - public class BackgroundWorkerSinkSpec + readonly Logger _logger; + readonly MemorySink _innerSink; + + public BackgroundWorkerSinkSpec() { - readonly Logger _logger; - readonly MemorySink _innerSink; + _innerSink = new MemorySink(); + _logger = new LoggerConfiguration().WriteTo.Sink(_innerSink).CreateLogger(); + } - public BackgroundWorkerSinkSpec() - { - _innerSink = new MemorySink(); - _logger = new LoggerConfiguration().WriteTo.Sink(_innerSink).CreateLogger(); - } + [Fact] + public void WhenCtorWithNullSink_ThenThrows() + { + Assert.Throws(() => new BackgroundWorkerSink(null!, 10000, false, null)); + } - [Fact] - public void WhenCtorWithNullSink_ThenThrows() - { - Assert.Throws(() => new BackgroundWorkerSink(null, 10000, false, null)); - } + [Fact] + public async Task WhenEmitSingle_ThenRelaysToInnerSink() + { + using var sink = CreateSinkWithDefaultOptions(); + var logEvent = CreateEvent(); - [Fact] - public async Task WhenEmitSingle_ThenRelaysToInnerSink() - { - using (var sink = this.CreateSinkWithDefaultOptions()) - { - var logEvent = CreateEvent(); + sink.Emit(logEvent); - sink.Emit(logEvent); + await Task.Delay(TimeSpan.FromSeconds(3)); - await Task.Delay(TimeSpan.FromSeconds(3)); + Assert.Single(_innerSink.Events); + } - Assert.Single(_innerSink.Events); - } - } + [Fact] + public async Task WhenInnerEmitThrows_ThenContinuesRelaysToInnerSink() + { + using var sink = CreateSinkWithDefaultOptions(); + _innerSink.ThrowAfterCollecting = true; - [Fact] - public async Task WhenInnerEmitThrows_ThenContinuesRelaysToInnerSink() + var events = new List { - using (var sink = this.CreateSinkWithDefaultOptions()) - { - _innerSink.ThrowAfterCollecting = true; - - var events = new List - { - CreateEvent(), - CreateEvent(), - CreateEvent() - }; - events.ForEach(e => sink.Emit(e)); + CreateEvent(), + CreateEvent(), + CreateEvent() + }; + events.ForEach(e => sink.Emit(e)); - await Task.Delay(TimeSpan.FromSeconds(3)); + await Task.Delay(TimeSpan.FromSeconds(3)); - Assert.Equal(3, _innerSink.Events.Count); - } - } + Assert.Equal(3, _innerSink.Events.Count); + } - [Fact] - public async Task WhenEmitMultipleTimes_ThenRelaysToInnerSink() + [Fact] + public async Task WhenEmitMultipleTimes_ThenRelaysToInnerSink() + { + using var sink = CreateSinkWithDefaultOptions(); + var events = new List { - using (var sink = this.CreateSinkWithDefaultOptions()) - { - var events = new List - { - CreateEvent(), - CreateEvent(), - CreateEvent() - }; - events.ForEach(e => { sink.Emit(e); }); + CreateEvent(), + CreateEvent(), + CreateEvent() + }; + events.ForEach(e => { sink.Emit(e); }); - await Task.Delay(TimeSpan.FromSeconds(3)); + await Task.Delay(TimeSpan.FromSeconds(3)); - Assert.Equal(3, _innerSink.Events.Count); - } - } + Assert.Equal(3, _innerSink.Events.Count); + } - [Fact] - public async Task GivenDefaultConfig_WhenRequestsExceedCapacity_DoesNotBlock() + [Fact] + public async Task GivenDefaultConfig_WhenRequestsExceedCapacity_DoesNotBlock() + { + var batchTiming = Stopwatch.StartNew(); + using (var sink = new BackgroundWorkerSink(_logger, 1, false, null)) { - var batchTiming = Stopwatch.StartNew(); - using (var sink = new BackgroundWorkerSink(_logger, 1, blockWhenFull: false /*default*/)) + // Cause a delay when emitting to the inner sink, allowing us to easily fill the queue to capacity + // while the first event is being propagated + var acceptInterval = TimeSpan.FromMilliseconds(500); + _innerSink.DelayEmit = acceptInterval; + var tenSecondsWorth = 10_000 / acceptInterval.TotalMilliseconds + 1; + for (int i = 0; i < tenSecondsWorth; i++) { - // Cause a delay when emitting to the inner sink, allowing us to easily fill the queue to capacity - // while the first event is being propagated - var acceptInterval = TimeSpan.FromMilliseconds(500); - _innerSink.DelayEmit = acceptInterval; - var tenSecondsWorth = 10_000 / acceptInterval.TotalMilliseconds + 1; - for (int i = 0; i < tenSecondsWorth; i++) - { - var emissionTiming = Stopwatch.StartNew(); - sink.Emit(CreateEvent()); - emissionTiming.Stop(); - - // Should not block the caller when the queue is full - Assert.InRange(emissionTiming.ElapsedMilliseconds, 0, 200); - } - - // Allow at least one to propagate - await Task.Delay(TimeSpan.FromSeconds(1)).ConfigureAwait(false); - Assert.NotEqual(0, ((IAsyncLogEventSinkInspector)sink).DroppedMessagesCount); + var emissionTiming = Stopwatch.StartNew(); + sink.Emit(CreateEvent()); + emissionTiming.Stop(); + + // Should not block the caller when the queue is full + Assert.InRange(emissionTiming.ElapsedMilliseconds, 0, 200); } - // Sanity check the overall timing - batchTiming.Stop(); - // Need to add a significant fudge factor as AppVeyor build can result in `await` taking quite some time - Assert.InRange(batchTiming.ElapsedMilliseconds, 950, 2050); + + // Allow at least one to propagate + await Task.Delay(TimeSpan.FromSeconds(1)); + Assert.NotEqual(0, ((IAsyncLogEventSinkInspector)sink).DroppedMessagesCount); } - [Fact] - public async Task GivenDefaultConfig_WhenRequestsExceedCapacity_ThenDropsEventsAndRecovers() + // Sanity check the overall timing + batchTiming.Stop(); + // Need to add a significant fudge factor as AppVeyor build can result in `await` taking quite some time + Assert.InRange(batchTiming.ElapsedMilliseconds, 950, 2050); + } + + [Fact] + public async Task GivenDefaultConfig_WhenRequestsExceedCapacity_ThenDropsEventsAndRecovers() + { + using var sink = new BackgroundWorkerSink(_logger, 1, false, null); + var acceptInterval = TimeSpan.FromMilliseconds(200); + _innerSink.DelayEmit = acceptInterval; + + for (int i = 0; i < 2; i++) { - using (var sink = new BackgroundWorkerSink(_logger, 1, blockWhenFull: false /*default*/)) - { - var acceptInterval = TimeSpan.FromMilliseconds(200); - _innerSink.DelayEmit = acceptInterval; - - for (int i = 0; i < 2; i++) - { - sink.Emit(CreateEvent()); - sink.Emit(CreateEvent()); - await Task.Delay(acceptInterval); - sink.Emit(CreateEvent()); - } - // Wait for the buffer and propagation to complete - await Task.Delay(TimeSpan.FromSeconds(1)); - // Now verify things are back to normal; emit an event... - var finalEvent = CreateEvent(); - sink.Emit(finalEvent); - // ... give adequate time for it to be guaranteed to have percolated through - await Task.Delay(TimeSpan.FromSeconds(1)); - - // At least one of the preceding events should not have made it through - var propagatedExcludingFinal = - from e in _innerSink.Events - where !Object.ReferenceEquals(finalEvent, e) - select e; - Assert.InRange(2, 2 * 3 / 2 - 1, propagatedExcludingFinal.Count()); - // Final event should have made it through - Assert.Contains(_innerSink.Events, x => Object.ReferenceEquals(finalEvent, x)); - Assert.NotEqual(0, ((IAsyncLogEventSinkInspector)sink).DroppedMessagesCount); - } + sink.Emit(CreateEvent()); + sink.Emit(CreateEvent()); + await Task.Delay(acceptInterval); + sink.Emit(CreateEvent()); } - [Fact] - public async Task GivenConfiguredToBlock_WhenQueueFilled_ThenBlocks() + // Wait for the buffer and propagation to complete + await Task.Delay(TimeSpan.FromSeconds(1)); + // Now verify things are back to normal; emit an event... + var finalEvent = CreateEvent(); + sink.Emit(finalEvent); + // ... give adequate time for it to be guaranteed to have percolated through + await Task.Delay(TimeSpan.FromSeconds(1)); + + // At least one of the preceding events should not have made it through + var propagatedExcludingFinal = + from e in _innerSink.Events + where !Object.ReferenceEquals(finalEvent, e) + select e; + Assert.InRange(2, 2 * 3 / 2 - 1, propagatedExcludingFinal.Count()); + // Final event should have made it through + Assert.Contains(_innerSink.Events, x => ReferenceEquals(finalEvent, x)); + Assert.NotEqual(0, ((IAsyncLogEventSinkInspector)sink).DroppedMessagesCount); + } + + [Fact] + public async Task GivenConfiguredToBlock_WhenQueueFilled_ThenBlocks() + { + using var sink = new BackgroundWorkerSink(_logger, 1, true, null); + // Cause a delay when emitting to the inner sink, allowing us to fill the queue to capacity + // after the first event is popped + _innerSink.DelayEmit = TimeSpan.FromMilliseconds(300); + + var events = new List { - using (var sink = new BackgroundWorkerSink(_logger, 1, blockWhenFull: true)) - { - // Cause a delay when emmitting to the inner sink, allowing us to fill the queue to capacity - // after the first event is popped - _innerSink.DelayEmit = TimeSpan.FromMilliseconds(300); - - var events = new List - { - CreateEvent(), - CreateEvent(), - CreateEvent() - }; - - int i = 0; - events.ForEach(e => - { - var sw = Stopwatch.StartNew(); - sink.Emit(e); - sw.Stop(); - - // Emit should return immediately the first time, since the queue is not yet full. On - // subsequent calls, the queue should be full, so we should be blocked - if (i > 0) - { - Assert.True(sw.ElapsedMilliseconds > 200, "Should block the caller when the queue is full"); - } - }); - - await Task.Delay(TimeSpan.FromSeconds(2)); - - // No events should be dropped - Assert.Equal(3, _innerSink.Events.Count); - Assert.Equal(0, ((IAsyncLogEventSinkInspector)sink).DroppedMessagesCount); - } - } + CreateEvent(), + CreateEvent(), + CreateEvent() + }; - [Fact] - public void MonitorParameterAffordsSinkInspectorSuitableForHealthChecking() + int i = 0; + events.ForEach(e => { - var collector = new MemorySink { DelayEmit = TimeSpan.FromSeconds(2) }; - // 2 spaces in queue; 1 would make the second log entry eligible for dropping if consumer does not activate instantaneously - var bufferSize = 2; - var monitor = new DummyMonitor(); - using (var logger = new LoggerConfiguration() - .WriteTo.Async(w => w.Sink(collector), bufferSize: 2, monitor: monitor) - .CreateLogger()) + var sw = Stopwatch.StartNew(); + sink.Emit(e); + sw.Stop(); + + // Emit should return immediately the first time, since the queue is not yet full. On + // subsequent calls, the queue should be full, so we should be blocked + if (i > 0) { - // Construction of BackgroundWorkerSink triggers StartMonitoring - var inspector = monitor.Inspector; - Assert.Equal(bufferSize, inspector.BufferSize); - Assert.Equal(0, inspector.Count); - Assert.Equal(0, inspector.DroppedMessagesCount); - logger.Information("Something to freeze the processing for 2s"); - // Can be taken from queue either instantanously or be awaiting consumer to take - Assert.InRange(inspector.Count, 0, 1); - Assert.Equal(0, inspector.DroppedMessagesCount); - logger.Information("Something that will sit in the queue"); - Assert.InRange(inspector.Count, 1, 2); - logger.Information("Something that will probably also sit in the queue (but could get dropped if first message has still not been picked up)"); - Assert.InRange(inspector.Count, 1, 2); - logger.Information("Something that will get dropped unless we get preempted for 2s during our execution"); - const string droppedMessage = "Something that will definitely get dropped"; - logger.Information(droppedMessage); - Assert.InRange(inspector.Count, 1, 2); - // Unless we are put to sleep for a Rip Van Winkle period, either: - // a) the BackgroundWorker will be emitting the item [and incurring the 2s delay we established], leaving a single item in the buffer - // or b) neither will have been picked out of the buffer yet. - Assert.InRange(inspector.Count, 1, 2); - Assert.Equal(bufferSize, inspector.BufferSize); - Assert.DoesNotContain(collector.Events, x => x.MessageTemplate.Text == droppedMessage); - // Because messages wait 2 seconds, the only real way to get one into the buffer is with a debugger breakpoint or a sleep - Assert.InRange(collector.Events.Count, 0, 3); + Assert.True(sw.ElapsedMilliseconds > 200, "Should block the caller when the queue is full"); } - // Dispose should trigger a StopMonitoring call - Assert.Null(monitor.Inspector); - } + }); - BackgroundWorkerSink CreateSinkWithDefaultOptions() - { - return new BackgroundWorkerSink(_logger, 10000, false); - } + await Task.Delay(TimeSpan.FromSeconds(2)); - static LogEvent CreateEvent() + // No events should be dropped + Assert.Equal(3, _innerSink.Events.Count); + Assert.Equal(0, ((IAsyncLogEventSinkInspector)sink).DroppedMessagesCount); + } + + [Fact] + public void MonitorParameterAffordsSinkInspectorSuitableForHealthChecking() + { + var collector = new MemorySink { DelayEmit = TimeSpan.FromSeconds(2) }; + // 2 spaces in queue; 1 would make the second log entry eligible for dropping if consumer does not activate instantaneously + var bufferSize = 2; + var monitor = new DummyMonitor(); + using (var logger = new LoggerConfiguration() + .WriteTo.Async(w => w.Sink(collector), bufferSize: 2, monitor: monitor) + .CreateLogger()) { - return new LogEvent(DateTimeOffset.MaxValue, LogEventLevel.Error, null, - new MessageTemplate("amessage", Enumerable.Empty()), - Enumerable.Empty()); + // Construction of BackgroundWorkerSink triggers StartMonitoring + var inspector = monitor.Inspector; + Assert.Equal(bufferSize, inspector.BufferSize); + Assert.Equal(0, inspector.Count); + Assert.Equal(0, inspector.DroppedMessagesCount); + logger.Information("Something to freeze the processing for 2s"); + // Can be taken from queue either instantanously or be awaiting consumer to take + Assert.InRange(inspector.Count, 0, 1); + Assert.Equal(0, inspector.DroppedMessagesCount); + logger.Information("Something that will sit in the queue"); + Assert.InRange(inspector.Count, 1, 2); + logger.Information( + "Something that will probably also sit in the queue (but could get dropped if first message has still not been picked up)"); + Assert.InRange(inspector.Count, 1, 2); + logger.Information("Something that will get dropped unless we get preempted for 2s during our execution"); + const string droppedMessage = "Something that will definitely get dropped"; + logger.Information(droppedMessage); + Assert.InRange(inspector.Count, 1, 2); + // Unless we are put to sleep for a Rip Van Winkle period, either: + // a) the BackgroundWorker will be emitting the item [and incurring the 2s delay we established], leaving a single item in the buffer + // or b) neither will have been picked out of the buffer yet. + Assert.InRange(inspector.Count, 1, 2); + Assert.Equal(bufferSize, inspector.BufferSize); + Assert.DoesNotContain(collector.Events, x => x.MessageTemplate.Text == droppedMessage); + // Because messages wait 2 seconds, the only real way to get one into the buffer is with a debugger breakpoint or a sleep + Assert.InRange(collector.Events.Count, 0, 3); } + + // Dispose should trigger a StopMonitoring call + Assert.Null(monitor.Inspector); + } + + BackgroundWorkerSink CreateSinkWithDefaultOptions() + { + return new BackgroundWorkerSink(_logger, 10000, false, null); + } + + static LogEvent CreateEvent() + { + return new LogEvent(DateTimeOffset.MaxValue, LogEventLevel.Error, null, + new MessageTemplate("amessage", Enumerable.Empty()), + Enumerable.Empty()); } } \ No newline at end of file diff --git a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkTests.cs b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkTests.cs index 598be5b..50b6ce4 100644 --- a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkTests.cs +++ b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkTests.cs @@ -1,54 +1,53 @@ using Serilog.Sinks.Async.Tests.Support; using Xunit; -namespace Serilog.Sinks.Async.Tests +namespace Serilog.Sinks.Async.Tests; + +public class BackgroundWorkerSinkTests { - public class BackgroundWorkerSinkTests + [Fact] + public void EventsArePassedToInnerSink() { - [Fact] - public void EventsArePassedToInnerSink() - { - var collector = new MemorySink(); + var collector = new MemorySink(); - using (var log = new LoggerConfiguration() - .WriteTo.Async(w => w.Sink(collector)) - .CreateLogger()) - { - log.Information("Hello, async world!"); - log.Information("Hello again!"); - } - - Assert.Equal(2, collector.Events.Count); + using (var log = new LoggerConfiguration() + .WriteTo.Async(w => w.Sink(collector)) + .CreateLogger()) + { + log.Information("Hello, async world!"); + log.Information("Hello again!"); } - [Fact] - public void DisposeCompletesWithoutWorkPerformed() - { - var collector = new MemorySink(); + Assert.Equal(2, collector.Events.Count); + } - using (new LoggerConfiguration() - .WriteTo.Async(w => w.Sink(collector)) - .CreateLogger()) - { - } + [Fact] + public void DisposeCompletesWithoutWorkPerformed() + { + var collector = new MemorySink(); - Assert.Empty(collector.Events); + using (new LoggerConfiguration() + .WriteTo.Async(w => w.Sink(collector)) + .CreateLogger()) + { } - [Fact] - public void CtorAndDisposeInformMonitor() - { - var collector = new MemorySink(); - var monitor = new DummyMonitor(); + Assert.Empty(collector.Events); + } - using (new LoggerConfiguration() - .WriteTo.Async(w => w.Sink(collector), monitor: monitor) - .CreateLogger()) - { - Assert.NotNull(monitor.Inspector); - } + [Fact] + public void CtorAndDisposeInformMonitor() + { + var collector = new MemorySink(); + var monitor = new DummyMonitor(); - Assert.Null(monitor.Inspector); + using (new LoggerConfiguration() + .WriteTo.Async(w => w.Sink(collector), monitor: monitor) + .CreateLogger()) + { + Assert.NotNull(monitor.Inspector); } + + Assert.Null(monitor.Inspector); } } \ No newline at end of file diff --git a/test/Serilog.Sinks.Async.Tests/Serilog.Sinks.Async.Tests.csproj b/test/Serilog.Sinks.Async.Tests/Serilog.Sinks.Async.Tests.csproj index 36f324b..644e6db 100644 --- a/test/Serilog.Sinks.Async.Tests/Serilog.Sinks.Async.Tests.csproj +++ b/test/Serilog.Sinks.Async.Tests/Serilog.Sinks.Async.Tests.csproj @@ -1,12 +1,11 @@  - net461;netcoreapp2.0 - Serilog.Sinks.Async.Tests + net48 + $(TargetFrameworks);net6.0;net8.0 ../../assets/Serilog.snk true true - Serilog.Sinks.Async.Tests @@ -14,16 +13,12 @@ - - + + all runtime; build; native; contentfiles; analyzers - - - - - + diff --git a/test/Serilog.Sinks.Async.Tests/Support/DummyMonitor.cs b/test/Serilog.Sinks.Async.Tests/Support/DummyMonitor.cs index 2d630cd..6cb4d26 100644 --- a/test/Serilog.Sinks.Async.Tests/Support/DummyMonitor.cs +++ b/test/Serilog.Sinks.Async.Tests/Support/DummyMonitor.cs @@ -1,14 +1,13 @@ -namespace Serilog.Sinks.Async.Tests.Support +namespace Serilog.Sinks.Async.Tests.Support; + +class DummyMonitor : IAsyncLogEventSinkMonitor { - class DummyMonitor : IAsyncLogEventSinkMonitor - { - IAsyncLogEventSinkInspector inspector; - public IAsyncLogEventSinkInspector Inspector => inspector; + IAsyncLogEventSinkInspector inspector; + public IAsyncLogEventSinkInspector Inspector => inspector; - void IAsyncLogEventSinkMonitor.StartMonitoring(IAsyncLogEventSinkInspector inspector) => - this.inspector = inspector; + void IAsyncLogEventSinkMonitor.StartMonitoring(IAsyncLogEventSinkInspector inspector) => + this.inspector = inspector; - void IAsyncLogEventSinkMonitor.StopMonitoring(IAsyncLogEventSinkInspector inspector) => - System.Threading.Interlocked.CompareExchange(ref this.inspector, null, inspector); - } + void IAsyncLogEventSinkMonitor.StopMonitoring(IAsyncLogEventSinkInspector inspector) => + System.Threading.Interlocked.CompareExchange(ref this.inspector, null, inspector); } \ No newline at end of file diff --git a/test/Serilog.Sinks.Async.Tests/Support/Loop.cs b/test/Serilog.Sinks.Async.Tests/Support/Loop.cs index 2514d1a..d73aad6 100644 --- a/test/Serilog.Sinks.Async.Tests/Support/Loop.cs +++ b/test/Serilog.Sinks.Async.Tests/Support/Loop.cs @@ -2,128 +2,127 @@ using System.Diagnostics; using System.Threading.Tasks; -namespace Serilog.Sinks.Async.Tests.Support +namespace Serilog.Sinks.Async.Tests.Support; + +public static class Loop { - public static class Loop + /// + /// Repeats the specified , until the specified returns true, + /// With a delay between retries of , or until the is exceeded. + /// + /// The type of the result of the + /// The action to perform + /// The predicate which determines whether the action has completed + /// The delay between retries + /// The time after which the retries are cancelled + /// + public static RetryResult Retry(this Func action, Predicate until, + TimeSpan retryInterval, TimeSpan timeout) { - /// - /// Repeats the specified , until the specified returns true, - /// With a delay between retries of , or until the is exceeded. - /// - /// The type of the result of the - /// The action to perform - /// The predicate which determines whether the action has completed - /// The delay between retries - /// The time after which the retries are cancelled - /// - public static RetryResult Retry(this Func action, Predicate until, - TimeSpan retryInterval, TimeSpan timeout) + var retries = 0; + TResult result; + var stopwatch = Stopwatch.StartNew(); + do { - var retries = 0; - TResult result; - var stopwatch = Stopwatch.StartNew(); - do - { - retries++; - result = action(); + retries++; + result = action(); - if (until(result)) - { - return new RetryResult(result, retries, stopwatch.Elapsed); - } + if (until(result)) + { + return new RetryResult(result, retries, stopwatch.Elapsed); + } - Task.Delay((int)retryInterval.TotalMilliseconds).Wait(); - } while (stopwatch.Elapsed < timeout); + Task.Delay((int)retryInterval.TotalMilliseconds).Wait(); + } while (stopwatch.Elapsed < timeout); - return new RetryResult(result, retries, stopwatch.Elapsed); - } + return new RetryResult(result, retries, stopwatch.Elapsed); + } - /// - /// Repeats the specified , until the specified , - /// With a delay between retries of - /// - /// The type of the result of the - /// The action to perform - /// The delay between retries - /// The time after which the retries are cancelled - /// - public static RetryResult RetryUntilTimesout(this Func action, - TimeSpan retryInterval, TimeSpan timeout) + /// + /// Repeats the specified , until the specified , + /// With a delay between retries of + /// + /// The type of the result of the + /// The action to perform + /// The delay between retries + /// The time after which the retries are cancelled + /// + public static RetryResult RetryUntilTimesout(this Func action, + TimeSpan retryInterval, TimeSpan timeout) + { + var retries = 0; + TResult result; + var stopwatch = Stopwatch.StartNew(); + do { - var retries = 0; - TResult result; - var stopwatch = Stopwatch.StartNew(); - do - { - retries++; - result = action(); + retries++; + result = action(); - Task.Delay((int)retryInterval.TotalMilliseconds).Wait(); - } while (stopwatch.Elapsed < timeout); + Task.Delay((int)retryInterval.TotalMilliseconds).Wait(); + } while (stopwatch.Elapsed < timeout); - return new RetryResult(result, retries, stopwatch.Elapsed); - } + return new RetryResult(result, retries, stopwatch.Elapsed); + } - /// - /// Repeats the specified the specified number of times - /// - public static void For(Action action, int times) + /// + /// Repeats the specified the specified number of times + /// + public static void For(Action action, int times) + { + if (times > 0) { - if (times > 0) + for (var counter = 0; counter < times; counter++) { - for (var counter = 0; counter < times; counter++) - { - action(); - } + action(); } } + } - /// - /// Repeats the specified the specified number of times, from 0 to - /// - public static void For(Action action, int to) + /// + /// Repeats the specified the specified number of times, from 0 to + /// + public static void For(Action action, int to) + { + if (to > 0) { - if (to > 0) + for (var counter = 0; counter < to; counter++) { - for (var counter = 0; counter < to; counter++) - { - action(counter); - } + action(counter); } } + } - /// - /// Repeats the specified the specified number of times, from to - /// - /// - public static void For(Action action, int from, int to) + /// + /// Repeats the specified the specified number of times, from to + /// + /// + public static void For(Action action, int from, int to) + { + if (to > 0 + && from >= 0 + && from <= to) { - if (to > 0 - && from >= 0 - && from <= to) + var maxCount = (from > 0) ? (to + 1) : to; + for (var counter = from; counter < maxCount; counter++) { - var maxCount = (from > 0) ? (to + 1) : to; - for (var counter = from; counter < maxCount; counter++) - { - action(counter); - } + action(counter); } } } +} - public class RetryResult +public class RetryResult +{ + public RetryResult(TResult result, int retries, TimeSpan elapsed) { - public RetryResult(TResult result, int retries, TimeSpan elapsed) - { - Result = result; - Retries = retries; - Elapsed = elapsed; - } + Result = result; + Retries = retries; + Elapsed = elapsed; + } - public int Retries { get; private set; } + public int Retries { get; private set; } - public TimeSpan Elapsed { get; private set; } + public TimeSpan Elapsed { get; private set; } - public TResult Result { get; private set; } - } -} + public TResult Result { get; private set; } +} \ No newline at end of file diff --git a/test/Serilog.Sinks.Async.Tests/Support/MemorySink.cs b/test/Serilog.Sinks.Async.Tests/Support/MemorySink.cs index 2945863..0d54a03 100644 --- a/test/Serilog.Sinks.Async.Tests/Support/MemorySink.cs +++ b/test/Serilog.Sinks.Async.Tests/Support/MemorySink.cs @@ -4,23 +4,22 @@ using System; using System.Threading.Tasks; -namespace Serilog.Sinks.Async.Tests.Support +namespace Serilog.Sinks.Async.Tests.Support; + +public class MemorySink : ILogEventSink { - public class MemorySink : ILogEventSink - { - public ConcurrentBag Events { get; } = new ConcurrentBag(); - public bool ThrowAfterCollecting { get; set; } - public TimeSpan? DelayEmit { get; set; } + public ConcurrentBag Events { get; } = new ConcurrentBag(); + public bool ThrowAfterCollecting { get; set; } + public TimeSpan? DelayEmit { get; set; } - public void Emit(LogEvent logEvent) - { - if (DelayEmit.HasValue) - Task.Delay(DelayEmit.Value).Wait(); + public void Emit(LogEvent logEvent) + { + if (DelayEmit.HasValue) + Task.Delay(DelayEmit.Value).Wait(); - Events.Add(logEvent); + Events.Add(logEvent); - if (ThrowAfterCollecting) - throw new Exception($"Exception requested through {nameof(ThrowAfterCollecting)}."); - } + if (ThrowAfterCollecting) + throw new Exception($"Exception requested through {nameof(ThrowAfterCollecting)}."); } } \ No newline at end of file