From fc636e8a0db252c718e6a239517b54d33fab7f93 Mon Sep 17 00:00:00 2001 From: Nicholas Blumhardt Date: Tue, 27 Jun 2017 08:19:52 +1000 Subject: [PATCH 01/23] Dev version bump [Skip CI] --- src/Serilog.Sinks.Async/project.json | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Serilog.Sinks.Async/project.json b/src/Serilog.Sinks.Async/project.json index 37fcd51..4e2c07a 100644 --- a/src/Serilog.Sinks.Async/project.json +++ b/src/Serilog.Sinks.Async/project.json @@ -1,5 +1,5 @@ { - "version": "1.1.0-*", + "version": "1.1.1-*", "description": "Asynchronous sink wrapper for Serilog.", "authors": [ "Jezz Santos", "Serilog Contributors" ], From 4ed2d2dc57df055524a16172ef6ed34b164da3e0 Mon Sep 17 00:00:00 2001 From: Sergey Komisarchik Date: Wed, 28 Jun 2017 09:35:44 +0300 Subject: [PATCH 02/23] vs2017 tooling update --- Bench.ps1 | 2 +- Build.ps1 | 2 +- appveyor.yml | 8 +--- global.json | 6 --- serilog-sinks-async.sln | 42 +++++++++---------- .../Properties/AssemblyInfo.cs | 1 - .../Serilog.Sinks.Async.csproj | 38 +++++++++++++++++ .../Serilog.Sinks.Async.xproj | 17 -------- src/Serilog.Sinks.Async/project.json | 33 --------------- ...erilog.Sinks.Async.PerformanceTests.csproj | 31 ++++++++++++++ ...Serilog.Sinks.Async.PerformanceTests.xproj | 18 -------- .../project.json | 30 ------------- .../xunit.runner.json | 3 ++ .../Serilog.Sinks.Async.Tests.csproj | 26 ++++++++++++ .../Serilog.Sinks.Async.Tests.xproj | 18 -------- test/Serilog.Sinks.Async.Tests/project.json | 28 ------------- 16 files changed, 121 insertions(+), 182 deletions(-) delete mode 100644 global.json create mode 100644 src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj delete mode 100644 src/Serilog.Sinks.Async/Serilog.Sinks.Async.xproj delete mode 100644 src/Serilog.Sinks.Async/project.json create mode 100644 test/Serilog.Sinks.Async.PerformanceTests/Serilog.Sinks.Async.PerformanceTests.csproj delete mode 100644 test/Serilog.Sinks.Async.PerformanceTests/Serilog.Sinks.Async.PerformanceTests.xproj delete mode 100644 test/Serilog.Sinks.Async.PerformanceTests/project.json create mode 100644 test/Serilog.Sinks.Async.PerformanceTests/xunit.runner.json create mode 100644 test/Serilog.Sinks.Async.Tests/Serilog.Sinks.Async.Tests.csproj delete mode 100644 test/Serilog.Sinks.Async.Tests/Serilog.Sinks.Async.Tests.xproj delete mode 100644 test/Serilog.Sinks.Async.Tests/project.json diff --git a/Bench.ps1 b/Bench.ps1 index 3dd58ee..c931cda 100644 --- a/Bench.ps1 +++ b/Bench.ps1 @@ -9,7 +9,7 @@ foreach ($test in ls test/*.PerformanceTests) { echo "bench: Benchmarking project in $test" - & dotnet test -c Release --framework net4.5.2 + & dotnet test -c Release --framework net46 if($LASTEXITCODE -ne 0) { exit 3 } Pop-Location diff --git a/Build.ps1 b/Build.ps1 index 7c5a85f..4830b07 100644 --- a/Build.ps1 +++ b/Build.ps1 @@ -20,7 +20,7 @@ foreach ($src in ls src/*) { echo "build: Packaging project in $src" - & dotnet pack -c Release -o ..\..\artifacts --version-suffix=$suffix + & dotnet pack -c Release -o ..\..\artifacts --version-suffix=$suffix --include-source if($LASTEXITCODE -ne 0) { exit 1 } Pop-Location diff --git a/appveyor.yml b/appveyor.yml index 19d0d28..4b2f3bd 100644 --- a/appveyor.yml +++ b/appveyor.yml @@ -1,13 +1,7 @@ version: '{build}' skip_tags: true -image: Visual Studio 2015 +image: Visual Studio 2017 configuration: Release -install: - - ps: mkdir -Force ".\build\" | Out-Null - - ps: Invoke-WebRequest "https://raw.githubusercontent.com/dotnet/cli/rel/1.0.0-preview2/scripts/obtain/dotnet-install.ps1" -OutFile ".\build\installcli.ps1" - - ps: $env:DOTNET_INSTALL_DIR = "$pwd\.dotnetcli" - - ps: '& .\build\installcli.ps1 -InstallDir "$env:DOTNET_INSTALL_DIR" -NoPath -Version 1.0.0-preview2-003121' - - ps: $env:Path = "$env:DOTNET_INSTALL_DIR;$env:Path" build_script: - ps: ./Build.ps1 test: off diff --git a/global.json b/global.json deleted file mode 100644 index a2b2a41..0000000 --- a/global.json +++ /dev/null @@ -1,6 +0,0 @@ -{ - "projects": [ "src", "test" ], - "sdk": { - "version": "1.0.0-preview2-003121" - } -} diff --git a/serilog-sinks-async.sln b/serilog-sinks-async.sln index 29c66c6..53c3f7e 100644 --- a/serilog-sinks-async.sln +++ b/serilog-sinks-async.sln @@ -1,7 +1,6 @@ - Microsoft Visual Studio Solution File, Format Version 12.00 -# Visual Studio 14 -VisualStudioVersion = 14.0.25420.1 +# Visual Studio 15 +VisualStudioVersion = 15.0.26430.14 MinimumVisualStudioVersion = 10.0.40219.1 Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "src", "src", "{76C9F320-3DBC-4613-83AA-3CCD0D9012D9}" EndProject @@ -12,16 +11,15 @@ Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "global", "global", "{154C7C appveyor.yml = appveyor.yml Bench.ps1 = Bench.ps1 Build.ps1 = Build.ps1 - global.json = global.json LICENSE = LICENSE README.md = README.md EndProjectSection EndProject -Project("{8BB2217D-0F2D-49D1-97BC-3654ED321F3B}") = "Serilog.Sinks.Async", "src\Serilog.Sinks.Async\Serilog.Sinks.Async.xproj", "{803CD13A-D54B-4CEC-A55F-E22AE3D93B3C}" +Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Serilog.Sinks.Async", "src\Serilog.Sinks.Async\Serilog.Sinks.Async.csproj", "{003F6AB2-79F8-4A63-B501-5C564B4A4655}" EndProject -Project("{8BB2217D-0F2D-49D1-97BC-3654ED321F3B}") = "Serilog.Sinks.Async.Tests", "test\Serilog.Sinks.Async.Tests\Serilog.Sinks.Async.Tests.xproj", "{3C2D8E01-5580-426A-BDD9-EC59CD98E618}" +Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Serilog.Sinks.Async.PerformanceTests", "test\Serilog.Sinks.Async.PerformanceTests\Serilog.Sinks.Async.PerformanceTests.csproj", "{19E64565-3BE1-43FE-9E8B-7800C7061877}" EndProject -Project("{8BB2217D-0F2D-49D1-97BC-3654ED321F3B}") = "Serilog.Sinks.Async.PerformanceTests", "test\Serilog.Sinks.Async.PerformanceTests\Serilog.Sinks.Async.PerformanceTests.xproj", "{D7A37F73-BBA3-4DAE-9648-1A753A86F968}" +Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Serilog.Sinks.Async.Tests", "test\Serilog.Sinks.Async.Tests\Serilog.Sinks.Async.Tests.csproj", "{E8AE4DDD-6C28-4239-A752-075309A86D41}" EndProject Global GlobalSection(SolutionConfigurationPlatforms) = preSolution @@ -29,25 +27,25 @@ Global Release|Any CPU = Release|Any CPU EndGlobalSection GlobalSection(ProjectConfigurationPlatforms) = postSolution - {803CD13A-D54B-4CEC-A55F-E22AE3D93B3C}.Debug|Any CPU.ActiveCfg = Debug|Any CPU - {803CD13A-D54B-4CEC-A55F-E22AE3D93B3C}.Debug|Any CPU.Build.0 = Debug|Any CPU - {803CD13A-D54B-4CEC-A55F-E22AE3D93B3C}.Release|Any CPU.ActiveCfg = Release|Any CPU - {803CD13A-D54B-4CEC-A55F-E22AE3D93B3C}.Release|Any CPU.Build.0 = Release|Any CPU - {3C2D8E01-5580-426A-BDD9-EC59CD98E618}.Debug|Any CPU.ActiveCfg = Debug|Any CPU - {3C2D8E01-5580-426A-BDD9-EC59CD98E618}.Debug|Any CPU.Build.0 = Debug|Any CPU - {3C2D8E01-5580-426A-BDD9-EC59CD98E618}.Release|Any CPU.ActiveCfg = Release|Any CPU - {3C2D8E01-5580-426A-BDD9-EC59CD98E618}.Release|Any CPU.Build.0 = Release|Any CPU - {D7A37F73-BBA3-4DAE-9648-1A753A86F968}.Debug|Any CPU.ActiveCfg = Debug|Any CPU - {D7A37F73-BBA3-4DAE-9648-1A753A86F968}.Debug|Any CPU.Build.0 = Debug|Any CPU - {D7A37F73-BBA3-4DAE-9648-1A753A86F968}.Release|Any CPU.ActiveCfg = Release|Any CPU - {D7A37F73-BBA3-4DAE-9648-1A753A86F968}.Release|Any CPU.Build.0 = Release|Any CPU + {003F6AB2-79F8-4A63-B501-5C564B4A4655}.Debug|Any CPU.ActiveCfg = Debug|Any CPU + {003F6AB2-79F8-4A63-B501-5C564B4A4655}.Debug|Any CPU.Build.0 = Debug|Any CPU + {003F6AB2-79F8-4A63-B501-5C564B4A4655}.Release|Any CPU.ActiveCfg = Release|Any CPU + {003F6AB2-79F8-4A63-B501-5C564B4A4655}.Release|Any CPU.Build.0 = Release|Any CPU + {19E64565-3BE1-43FE-9E8B-7800C7061877}.Debug|Any CPU.ActiveCfg = Debug|Any CPU + {19E64565-3BE1-43FE-9E8B-7800C7061877}.Debug|Any CPU.Build.0 = Debug|Any CPU + {19E64565-3BE1-43FE-9E8B-7800C7061877}.Release|Any CPU.ActiveCfg = Release|Any CPU + {19E64565-3BE1-43FE-9E8B-7800C7061877}.Release|Any CPU.Build.0 = Release|Any CPU + {E8AE4DDD-6C28-4239-A752-075309A86D41}.Debug|Any CPU.ActiveCfg = Debug|Any CPU + {E8AE4DDD-6C28-4239-A752-075309A86D41}.Debug|Any CPU.Build.0 = Debug|Any CPU + {E8AE4DDD-6C28-4239-A752-075309A86D41}.Release|Any CPU.ActiveCfg = Release|Any CPU + {E8AE4DDD-6C28-4239-A752-075309A86D41}.Release|Any CPU.Build.0 = Release|Any CPU EndGlobalSection GlobalSection(SolutionProperties) = preSolution HideSolutionNode = FALSE EndGlobalSection GlobalSection(NestedProjects) = preSolution - {803CD13A-D54B-4CEC-A55F-E22AE3D93B3C} = {76C9F320-3DBC-4613-83AA-3CCD0D9012D9} - {3C2D8E01-5580-426A-BDD9-EC59CD98E618} = {C36755AA-CED6-482B-B7B1-AE483BC3D273} - {D7A37F73-BBA3-4DAE-9648-1A753A86F968} = {C36755AA-CED6-482B-B7B1-AE483BC3D273} + {003F6AB2-79F8-4A63-B501-5C564B4A4655} = {76C9F320-3DBC-4613-83AA-3CCD0D9012D9} + {19E64565-3BE1-43FE-9E8B-7800C7061877} = {C36755AA-CED6-482B-B7B1-AE483BC3D273} + {E8AE4DDD-6C28-4239-A752-075309A86D41} = {C36755AA-CED6-482B-B7B1-AE483BC3D273} EndGlobalSection EndGlobal diff --git a/src/Serilog.Sinks.Async/Properties/AssemblyInfo.cs b/src/Serilog.Sinks.Async/Properties/AssemblyInfo.cs index ab2df5b..c93ed16 100644 --- a/src/Serilog.Sinks.Async/Properties/AssemblyInfo.cs +++ b/src/Serilog.Sinks.Async/Properties/AssemblyInfo.cs @@ -2,7 +2,6 @@ using System.Reflection; using System.Runtime.CompilerServices; -[assembly: AssemblyVersion("1.0.0.0")] [assembly: CLSCompliant(true)] [assembly: InternalsVisibleTo("Serilog.Sinks.Async.Tests, PublicKey=" + "0024000004800000940000000602000000240000525341310004000001000100fb8d13fd344a1c" + diff --git a/src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj b/src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj new file mode 100644 index 0000000..9f2b9c6 --- /dev/null +++ b/src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj @@ -0,0 +1,38 @@ + + + + Asynchronous sink wrapper for Serilog. + 1.0.0 + 1.1.1 + Jezz Santos;Serilog Contributors + net45;netstandard1.1 + true + true + Serilog.Sinks.Async + ../../assets/Serilog.snk + true + true + Serilog.Sinks.Async + serilog;async + http://serilog.net/images/serilog-sink-nuget.png + https://serilog.net + http://www.apache.org/licenses/LICENSE-2.0 + True + + true + + + + + + + + + + + + + + + + diff --git a/src/Serilog.Sinks.Async/Serilog.Sinks.Async.xproj b/src/Serilog.Sinks.Async/Serilog.Sinks.Async.xproj deleted file mode 100644 index 865914c..0000000 --- a/src/Serilog.Sinks.Async/Serilog.Sinks.Async.xproj +++ /dev/null @@ -1,17 +0,0 @@ - - - - 14.0 - $(MSBuildExtensionsPath32)\Microsoft\VisualStudio\v$(VisualStudioVersion) - - - - 803cd13a-d54b-4cec-a55f-e22ae3d93b3c - Serilog - .\obj - .\bin\ - - 2.0 - - - diff --git a/src/Serilog.Sinks.Async/project.json b/src/Serilog.Sinks.Async/project.json deleted file mode 100644 index 4e2c07a..0000000 --- a/src/Serilog.Sinks.Async/project.json +++ /dev/null @@ -1,33 +0,0 @@ -{ - "version": "1.1.1-*", - - "description": "Asynchronous sink wrapper for Serilog.", - "authors": [ "Jezz Santos", "Serilog Contributors" ], - - "packOptions": { - "tags": [ "serilog", "async" ], - "projectUrl": "https://serilog.net", - "licenseUrl": "http://www.apache.org/licenses/LICENSE-2.0", - "iconUrl": "http://serilog.net/images/serilog-sink-nuget.png" - }, - - "buildOptions": { - "keyFile": "../../assets/Serilog.snk", - "xmlDoc": true, - "warningsAsErrors": true - }, - - "dependencies": { - "Serilog": "2.1" - }, - - "frameworks": { - "net4.5": { - }, - "netstandard1.1": { - "dependencies": { - "System.Collections.Concurrent": "4.0.12" - } - } - } -} diff --git a/test/Serilog.Sinks.Async.PerformanceTests/Serilog.Sinks.Async.PerformanceTests.csproj b/test/Serilog.Sinks.Async.PerformanceTests/Serilog.Sinks.Async.PerformanceTests.csproj new file mode 100644 index 0000000..990767f --- /dev/null +++ b/test/Serilog.Sinks.Async.PerformanceTests/Serilog.Sinks.Async.PerformanceTests.csproj @@ -0,0 +1,31 @@ + + + + net46;netcoreapp1.1 + Serilog.Sinks.Async.PerformanceTests + ../../assets/Serilog.snk + true + true + + + + + + + + + + + + + + + + + + + + + + + diff --git a/test/Serilog.Sinks.Async.PerformanceTests/Serilog.Sinks.Async.PerformanceTests.xproj b/test/Serilog.Sinks.Async.PerformanceTests/Serilog.Sinks.Async.PerformanceTests.xproj deleted file mode 100644 index f4df042..0000000 --- a/test/Serilog.Sinks.Async.PerformanceTests/Serilog.Sinks.Async.PerformanceTests.xproj +++ /dev/null @@ -1,18 +0,0 @@ - - - - 14.0 - $(MSBuildExtensionsPath32)\Microsoft\VisualStudio\v$(VisualStudioVersion) - - - - d7a37f73-bba3-4dae-9648-1a753a86f968 - Serilog.PerformanceTests - .\obj - .\bin\ - - - 2.0 - - - diff --git a/test/Serilog.Sinks.Async.PerformanceTests/project.json b/test/Serilog.Sinks.Async.PerformanceTests/project.json deleted file mode 100644 index 5e76d51..0000000 --- a/test/Serilog.Sinks.Async.PerformanceTests/project.json +++ /dev/null @@ -1,30 +0,0 @@ -{ - "testRunner": "xunit", - - "dependencies": { - "Serilog.Sinks.Async": { "target": "project" }, - "Serilog.Sinks.File": "2.2.0", - "xunit": "2.1.0", - "dotnet-test-xunit": "1.0.0-rc2-build10025", - "BenchmarkDotNet": "0.9.7-beta" - }, - "buildOptions": { - "keyFile": "../../assets/Serilog.snk" - }, - "frameworks": { - "net4.5.2": { - }, - "netcoreapp1.0": { - "dependencies": { - "Microsoft.NETCore.App": { - "type": "platform", - "version": "1.0.0" - } - }, - "imports": [ - "dnxcore50", - "portable-net45+win8" - ] - } - } -} diff --git a/test/Serilog.Sinks.Async.PerformanceTests/xunit.runner.json b/test/Serilog.Sinks.Async.PerformanceTests/xunit.runner.json new file mode 100644 index 0000000..34b2fe2 --- /dev/null +++ b/test/Serilog.Sinks.Async.PerformanceTests/xunit.runner.json @@ -0,0 +1,3 @@ +{ + "shadowCopy": false +} \ 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 new file mode 100644 index 0000000..067ba2d --- /dev/null +++ b/test/Serilog.Sinks.Async.Tests/Serilog.Sinks.Async.Tests.csproj @@ -0,0 +1,26 @@ + + + + net452;netcoreapp1.0 + Serilog.Sinks.Async.Tests + ../../assets/Serilog.snk + true + true + Serilog.Sinks.Async.Tests + + + + + + + + + + + + + + + + + diff --git a/test/Serilog.Sinks.Async.Tests/Serilog.Sinks.Async.Tests.xproj b/test/Serilog.Sinks.Async.Tests/Serilog.Sinks.Async.Tests.xproj deleted file mode 100644 index 2f81baf..0000000 --- a/test/Serilog.Sinks.Async.Tests/Serilog.Sinks.Async.Tests.xproj +++ /dev/null @@ -1,18 +0,0 @@ - - - - 14.0 - $(MSBuildExtensionsPath32)\Microsoft\VisualStudio\v$(VisualStudioVersion) - - - - 3c2d8e01-5580-426a-bdd9-ec59cd98e618 - Serilog.Sinks.Async.Tests - .\obj - .\bin\ - - - 2.0 - - - \ No newline at end of file diff --git a/test/Serilog.Sinks.Async.Tests/project.json b/test/Serilog.Sinks.Async.Tests/project.json deleted file mode 100644 index 6452b45..0000000 --- a/test/Serilog.Sinks.Async.Tests/project.json +++ /dev/null @@ -1,28 +0,0 @@ -{ - "testRunner": "xunit", - - "dependencies": { - "Serilog.Sinks.Async": { "target": "project" }, - "xunit": "2.1.0", - "dotnet-test-xunit": "1.0.0-rc2-build10025" - }, - - "buildOptions": { - "keyFile": "../../assets/Serilog.snk" - }, - "frameworks": { - "net4.5.2": {}, - "netcoreapp1.0": { - "dependencies": { - "Microsoft.NETCore.App": { - "type": "platform", - "version": "1.0.0" - } - }, - "imports": [ - "dnxcore50", - "portable-net45+win8" - ] - } - } -} From 67cfc0ee17f4650dbfa024e01e1bef203f494509 Mon Sep 17 00:00:00 2001 From: Sergey Komisarchik Date: Wed, 28 Jun 2017 11:51:00 +0300 Subject: [PATCH 03/23] make use of lightweight LoggingSinkConfiguration.Wrap(..) --- .../LoggerConfigurationAsyncExtensions.cs | 14 +++++--------- src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj | 2 +- .../Sinks/Async/BackgroundWorkerSink.cs | 10 +++++----- 3 files changed, 11 insertions(+), 15 deletions(-) diff --git a/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs b/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs index a1be59f..4b56f29 100644 --- a/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs +++ b/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs @@ -1,6 +1,6 @@ using System; using Serilog.Configuration; -using Serilog.Events; + using Serilog.Sinks.Async; namespace Serilog @@ -24,14 +24,10 @@ public static LoggerConfiguration Async( Action configure, int bufferSize = 10000) { - var sublogger = new LoggerConfiguration(); - sublogger.MinimumLevel.Is(LevelAlias.Minimum); - - configure(sublogger.WriteTo); - - var wrapper = new BackgroundWorkerSink(sublogger.CreateLogger(), bufferSize); - - return loggerSinkConfiguration.Sink(wrapper); + return LoggerSinkConfiguration.Wrap( + loggerSinkConfiguration, + wrappedSink => new BackgroundWorkerSink(wrappedSink, bufferSize), + configure); } } } diff --git a/src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj b/src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj index 9f2b9c6..8dca4a8 100644 --- a/src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj +++ b/src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj @@ -23,7 +23,7 @@ - + diff --git a/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs b/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs index 4d150c9..e3fffe4 100644 --- a/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs +++ b/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs @@ -10,14 +10,14 @@ namespace Serilog.Sinks.Async { sealed class BackgroundWorkerSink : ILogEventSink, IDisposable { - readonly Logger _pipeline; + readonly ILogEventSink _pipeline; readonly int _bufferCapacity; volatile bool _disposed; readonly CancellationTokenSource _cancel = new CancellationTokenSource(); readonly BlockingCollection _queue; readonly Task _worker; - public BackgroundWorkerSink(Logger pipeline, int bufferCapacity) + public BackgroundWorkerSink(ILogEventSink pipeline, int bufferCapacity) { if (pipeline == null) throw new ArgumentNullException(nameof(pipeline)); if (bufferCapacity <= 0) throw new ArgumentOutOfRangeException(nameof(bufferCapacity)); @@ -40,7 +40,7 @@ public void Dispose() _disposed = true; _cancel.Cancel(); _worker.Wait(); - _pipeline.Dispose(); + (_pipeline as IDisposable)?.Dispose(); // _cancel not disposed, because it will make _cancel.Cancel() non-idempotent } @@ -53,14 +53,14 @@ void Pump() while (true) { var next = _queue.Take(_cancel.Token); - _pipeline.Write(next); + _pipeline.Emit(next); } } catch (OperationCanceledException) { LogEvent next; while (_queue.TryTake(out next)) - _pipeline.Write(next); + _pipeline.Emit(next); } } catch (Exception ex) From 1a6689fe8abf179dfd919c55e04f1c073c4c50bd Mon Sep 17 00:00:00 2001 From: Nicholas Blumhardt Date: Tue, 18 Jul 2017 07:33:39 +1000 Subject: [PATCH 04/23] Added JSON configuration example [Skip CI] --- README.md | 19 ++++++++++++++++++- 1 file changed, 18 insertions(+), 1 deletion(-) diff --git a/README.md b/README.md index b8b1d31..c89bb42 100644 --- a/README.md +++ b/README.md @@ -41,7 +41,24 @@ The default memory buffer feeding the worker thread is capped to 10,000 items, a ### XML `` and JSON configuration -XML and JSON configuration support has not yet been added for this wrapper. +Using [Serilog.Settings.Configuration](https://github.com/serilog/serilog-settings-configuration) JSON: + +```json +{ + "Serilog": { + "WriteTo": [{ + "Name": "Async", + "Args": { + "configure": [{ + "Name": "LiterateConsole" + }] + } + }] + } +} +``` + +XML configuration support has not yet been added for this wrapper. ### About this sink From 2ee0f264f71289ed822d0e9472f6ef6a09f6422f Mon Sep 17 00:00:00 2001 From: cocowalla Date: Thu, 3 Aug 2017 13:44:44 +0100 Subject: [PATCH 05/23] Add option to block when the queue is full, instead of dropping events Also, use `GetConsumingEnumerable` to enumerate the queue, instead of a `while` loop --- .../LoggerConfigurationAsyncExtensions.cs | 11 ++- .../Sinks/Async/BackgroundWorkerSink.cs | 36 ++++---- .../BackgroundWorkerSinkSpec.cs | 84 +++++++++++++++++-- .../BackgroundWorkerSinkTests.cs | 7 +- .../Support/MemorySink.cs | 5 ++ 5 files changed, 110 insertions(+), 33 deletions(-) diff --git a/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs b/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs index 4b56f29..60f56e7 100644 --- a/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs +++ b/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs @@ -16,17 +16,20 @@ 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, subsequent events will be - /// dropped until room is made in the queue. + /// 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) + int bufferSize = 10000, + bool blockWhenFull = false) { return LoggerSinkConfiguration.Wrap( loggerSinkConfiguration, - wrappedSink => new BackgroundWorkerSink(wrappedSink, bufferSize), + wrappedSink => new BackgroundWorkerSink(wrappedSink, bufferSize, blockWhenFull), configure); } } diff --git a/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs b/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs index e3fffe4..ab9100b 100644 --- a/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs +++ b/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs @@ -12,17 +12,18 @@ sealed class BackgroundWorkerSink : ILogEventSink, IDisposable { readonly ILogEventSink _pipeline; readonly int _bufferCapacity; + readonly bool _blockWhenFull; volatile bool _disposed; - readonly CancellationTokenSource _cancel = new CancellationTokenSource(); readonly BlockingCollection _queue; readonly Task _worker; - public BackgroundWorkerSink(ILogEventSink pipeline, int bufferCapacity) + public BackgroundWorkerSink(ILogEventSink pipeline, int bufferCapacity, bool blockWhenFull) { if (pipeline == null) throw new ArgumentNullException(nameof(pipeline)); if (bufferCapacity <= 0) throw new ArgumentOutOfRangeException(nameof(bufferCapacity)); _pipeline = pipeline; _bufferCapacity = bufferCapacity; + _blockWhenFull = blockWhenFull; _queue = new BlockingCollection(_bufferCapacity); _worker = Task.Factory.StartNew(Pump, CancellationToken.None, TaskCreationOptions.LongRunning | TaskCreationOptions.DenyChildAttach, TaskScheduler.Default); } @@ -31,36 +32,35 @@ public void Emit(LogEvent logEvent) { // The disposed check is racy, but only ensures we don't prevent flush from // completing by pushing more events. - if (!_disposed && !_queue.TryAdd(logEvent)) - SelfLog.WriteLine("{0} unable to enqueue, capacity {1}", typeof(BackgroundWorkerSink), _bufferCapacity); + if (_disposed) + return; + + if (!this._blockWhenFull) + { + if (!_queue.TryAdd(logEvent)) + SelfLog.WriteLine("{0} unable to enqueue, capacity {1}", typeof(BackgroundWorkerSink), _bufferCapacity); + } + else + { + this._queue.Add(logEvent); + } } public void Dispose() { _disposed = true; - _cancel.Cancel(); + _queue.CompleteAdding(); _worker.Wait(); (_pipeline as IDisposable)?.Dispose(); - // _cancel not disposed, because it will make _cancel.Cancel() non-idempotent } void Pump() { try { - try - { - while (true) - { - var next = _queue.Take(_cancel.Token); - _pipeline.Emit(next); - } - } - catch (OperationCanceledException) + foreach (var next in _queue.GetConsumingEnumerable()) { - LogEvent next; - while (_queue.TryTake(out next)) - _pipeline.Emit(next); + _pipeline.Emit(next); } } catch (Exception ex) diff --git a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs index 119eccc..6b6ef26 100644 --- a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs +++ b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs @@ -1,11 +1,12 @@ using System; using System.Collections.Generic; +using System.Diagnostics; using System.Linq; using System.Threading.Tasks; using Serilog.Core; +using Serilog.Debugging; using Serilog.Events; using Serilog.Parsing; -using Serilog.Sinks.Async.Tests; using Serilog.Sinks.Async.Tests.Support; using Xunit; @@ -13,14 +14,15 @@ namespace Serilog.Sinks.Async.Tests { public class BackgroundWorkerSinkSpec : IDisposable { + readonly Logger _logger; readonly MemorySink _innerSink; - readonly BackgroundWorkerSink _sink; + BackgroundWorkerSink _sink; public BackgroundWorkerSinkSpec() { _innerSink = new MemorySink(); - var logger = new LoggerConfiguration().WriteTo.Sink(_innerSink).CreateLogger(); - _sink = new BackgroundWorkerSink(logger, 10000); + _logger = new LoggerConfiguration().WriteTo.Sink(_innerSink).CreateLogger(); + _sink = new BackgroundWorkerSink(_logger, 10000, false); } public void Dispose() @@ -31,7 +33,7 @@ public void Dispose() [Fact] public void WhenCtorWithNullSink_ThenThrows() { - Assert.Throws(() => new BackgroundWorkerSink(null, 10000)); + Assert.Throws(() => new BackgroundWorkerSink(null, 10000, false)); } [Fact] @@ -39,6 +41,7 @@ public async Task WhenEmitSingle_ThenRelaysToInnerSink() { var logEvent = CreateEvent(); _sink.Emit(logEvent); + _sink.Dispose(); await Task.Delay(TimeSpan.FromSeconds(3)); @@ -80,6 +83,77 @@ public async Task WhenEmitMultipleTimes_ThenRelaysToInnerSink() Assert.Equal(3, _innerSink.Events.Count); } + [Fact] + public async Task WhenQueueFull_ThenDropsEvents() + { + _sink = new BackgroundWorkerSink(_logger, 1, false); + + // 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 = true; + + var events = new List + { + CreateEvent(), + CreateEvent(), + CreateEvent(), + CreateEvent(), + CreateEvent() + }; + events.ForEach(e => + { + var sw = Stopwatch.StartNew(); + _sink.Emit(e); + sw.Stop(); + + Assert.True(sw.ElapsedMilliseconds < 2000, "Should not block the caller when the queue is full"); + }); + + // If we *weren't* dropped events, the delay in the inner sink would mean the 5 events would take + // at least 15 seconds to process + await Task.Delay(TimeSpan.FromSeconds(18)); + + // Events should be dropped + Assert.Equal(2, _innerSink.Events.Count); + } + + [Fact] + public async Task WhenQueueFull_ThenBlocks() + { + _sink = new BackgroundWorkerSink(_logger, 1, 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 = true; + + 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 > 2000, "Should block the caller when the queue is full"); + } + }); + + await Task.Delay(TimeSpan.FromSeconds(12)); + + // No events should be dropped + Assert.Equal(3, _innerSink.Events.Count); + } + private static LogEvent CreateEvent() { return new LogEvent(DateTimeOffset.MaxValue, LogEventLevel.Error, null, diff --git a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkTests.cs b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkTests.cs index a54f92a..aca516f 100644 --- a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkTests.cs +++ b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkTests.cs @@ -1,9 +1,4 @@ -using System; -using System.Threading; -using Serilog.Core; -using Serilog.Events; -using Serilog.Parsing; -using Serilog.Sinks.Async.Tests.Support; +using Serilog.Sinks.Async.Tests.Support; using Xunit; namespace Serilog.Sinks.Async.Tests diff --git a/test/Serilog.Sinks.Async.Tests/Support/MemorySink.cs b/test/Serilog.Sinks.Async.Tests/Support/MemorySink.cs index 4d756f6..44e178f 100644 --- a/test/Serilog.Sinks.Async.Tests/Support/MemorySink.cs +++ b/test/Serilog.Sinks.Async.Tests/Support/MemorySink.cs @@ -2,6 +2,7 @@ using Serilog.Core; using System.Collections.Concurrent; using System; +using System.Threading.Tasks; namespace Serilog.Sinks.Async.Tests.Support { @@ -9,9 +10,13 @@ public class MemorySink : ILogEventSink { public ConcurrentBag Events { get; } = new ConcurrentBag(); public bool ThrowAfterCollecting { get; set; } + public bool DelayEmit { get; set; } public void Emit(LogEvent logEvent) { + if (DelayEmit) + Task.Delay(TimeSpan.FromSeconds(3)).Wait(); + Events.Add(logEvent); if (ThrowAfterCollecting) From 188741e9617670f3653fa692b75d05a2025b892d Mon Sep 17 00:00:00 2001 From: cocowalla Date: Fri, 4 Aug 2017 13:17:53 +0100 Subject: [PATCH 06/23] Response to review of #21 Response to review of #21 --- .../LoggerConfigurationAsyncExtensions.cs | 21 ++++++++++++- .../Sinks/Async/BackgroundWorkerSink.cs | 30 ++++++++++++------- .../BackgroundWorkerSinkSpec.cs | 14 ++++----- .../Support/MemorySink.cs | 6 ++-- 4 files changed, 48 insertions(+), 23 deletions(-) diff --git a/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs b/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs index 60f56e7..451fcc9 100644 --- a/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs +++ b/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs @@ -1,6 +1,6 @@ using System; +using System.ComponentModel; using Serilog.Configuration; - using Serilog.Sinks.Async; namespace Serilog @@ -10,6 +10,24 @@ namespace Serilog /// public static class LoggerConfigurationAsyncExtensions { + /// + /// 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. /// @@ -32,5 +50,6 @@ public static LoggerConfiguration Async( wrappedSink => new BackgroundWorkerSink(wrappedSink, bufferSize, blockWhenFull), configure); } + } } diff --git a/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs b/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs index ab9100b..694cb6e 100644 --- a/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs +++ b/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs @@ -13,7 +13,6 @@ sealed class BackgroundWorkerSink : ILogEventSink, IDisposable readonly ILogEventSink _pipeline; readonly int _bufferCapacity; readonly bool _blockWhenFull; - volatile bool _disposed; readonly BlockingCollection _queue; readonly Task _worker; @@ -30,27 +29,36 @@ public BackgroundWorkerSink(ILogEventSink pipeline, int bufferCapacity, bool blo public void Emit(LogEvent logEvent) { - // The disposed check is racy, but only ensures we don't prevent flush from - // completing by pushing more events. - if (_disposed) + if (this._queue.IsAddingCompleted) return; - if (!this._blockWhenFull) + try { - if (!_queue.TryAdd(logEvent)) - SelfLog.WriteLine("{0} unable to enqueue, capacity {1}", typeof(BackgroundWorkerSink), _bufferCapacity); + if (_blockWhenFull) + { + _queue.Add(logEvent); + } + else + { + if (!_queue.TryAdd(logEvent)) + SelfLog.WriteLine("{0} unable to enqueue, capacity {1}", typeof(BackgroundWorkerSink), _bufferCapacity); + } } - else + catch (InvalidOperationException) { - this._queue.Add(logEvent); + // Thrown in the event of a race condition when we try to add another event after + // CompleteAdding has been called } } public void Dispose() { - _disposed = true; + // Prevent any more events from being added _queue.CompleteAdding(); - _worker.Wait(); + + // Allow queued events to be flushed + _worker.Wait(); + (_pipeline as IDisposable)?.Dispose(); } diff --git a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs index 6b6ef26..1198e10 100644 --- a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs +++ b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs @@ -4,7 +4,6 @@ using System.Linq; using System.Threading.Tasks; using Serilog.Core; -using Serilog.Debugging; using Serilog.Events; using Serilog.Parsing; using Serilog.Sinks.Async.Tests.Support; @@ -41,7 +40,6 @@ public async Task WhenEmitSingle_ThenRelaysToInnerSink() { var logEvent = CreateEvent(); _sink.Emit(logEvent); - _sink.Dispose(); await Task.Delay(TimeSpan.FromSeconds(3)); @@ -90,7 +88,7 @@ public async Task WhenQueueFull_ThenDropsEvents() // 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 = true; + _innerSink.DelayEmit = TimeSpan.FromMilliseconds(300); var events = new List { @@ -106,12 +104,12 @@ public async Task WhenQueueFull_ThenDropsEvents() _sink.Emit(e); sw.Stop(); - Assert.True(sw.ElapsedMilliseconds < 2000, "Should not block the caller when the queue is full"); + Assert.True(sw.ElapsedMilliseconds < 200, "Should not block the caller when the queue is full"); }); // If we *weren't* dropped events, the delay in the inner sink would mean the 5 events would take // at least 15 seconds to process - await Task.Delay(TimeSpan.FromSeconds(18)); + await Task.Delay(TimeSpan.FromSeconds(2)); // Events should be dropped Assert.Equal(2, _innerSink.Events.Count); @@ -124,7 +122,7 @@ public async Task WhenQueueFull_ThenBlocks() // 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 = true; + _innerSink.DelayEmit = TimeSpan.FromMilliseconds(300); var events = new List { @@ -144,11 +142,11 @@ public async Task WhenQueueFull_ThenBlocks() // subsequent calls, the queue should be full, so we should be blocked if (i > 0) { - Assert.True(sw.ElapsedMilliseconds > 2000, "Should block the caller when the queue is full"); + Assert.True(sw.ElapsedMilliseconds > 200, "Should block the caller when the queue is full"); } }); - await Task.Delay(TimeSpan.FromSeconds(12)); + await Task.Delay(TimeSpan.FromSeconds(2)); // No events should be dropped Assert.Equal(3, _innerSink.Events.Count); diff --git a/test/Serilog.Sinks.Async.Tests/Support/MemorySink.cs b/test/Serilog.Sinks.Async.Tests/Support/MemorySink.cs index 44e178f..2945863 100644 --- a/test/Serilog.Sinks.Async.Tests/Support/MemorySink.cs +++ b/test/Serilog.Sinks.Async.Tests/Support/MemorySink.cs @@ -10,12 +10,12 @@ public class MemorySink : ILogEventSink { public ConcurrentBag Events { get; } = new ConcurrentBag(); public bool ThrowAfterCollecting { get; set; } - public bool DelayEmit { get; set; } + public TimeSpan? DelayEmit { get; set; } public void Emit(LogEvent logEvent) { - if (DelayEmit) - Task.Delay(TimeSpan.FromSeconds(3)).Wait(); + if (DelayEmit.HasValue) + Task.Delay(DelayEmit.Value).Wait(); Events.Add(logEvent); From 3e5a186188ca5e0c087fb4c66fac7b940f1fc866 Mon Sep 17 00:00:00 2001 From: cocowalla Date: Mon, 7 Aug 2017 19:48:41 +0100 Subject: [PATCH 07/23] Remove _sink field Instantiate sink in in test instead. Response to feedback in #21 --- .../BackgroundWorkerSinkSpec.cs | 175 +++++++++--------- 1 file changed, 92 insertions(+), 83 deletions(-) diff --git a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs index 1198e10..76f124b 100644 --- a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs +++ b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs @@ -11,22 +11,15 @@ namespace Serilog.Sinks.Async.Tests { - public class BackgroundWorkerSinkSpec : IDisposable + public class BackgroundWorkerSinkSpec { readonly Logger _logger; readonly MemorySink _innerSink; - BackgroundWorkerSink _sink; public BackgroundWorkerSinkSpec() { _innerSink = new MemorySink(); _logger = new LoggerConfiguration().WriteTo.Sink(_innerSink).CreateLogger(); - _sink = new BackgroundWorkerSink(_logger, 10000, false); - } - - public void Dispose() - { - _sink.Dispose(); } [Fact] @@ -38,118 +31,134 @@ public void WhenCtorWithNullSink_ThenThrows() [Fact] public async Task WhenEmitSingle_ThenRelaysToInnerSink() { - var logEvent = CreateEvent(); - _sink.Emit(logEvent); + using (var sink = this.CreateSinkWithDefaultOptions()) + { + var logEvent = CreateEvent(); + + sink.Emit(logEvent); - await Task.Delay(TimeSpan.FromSeconds(3)); + await Task.Delay(TimeSpan.FromSeconds(3)); - Assert.Equal(1, _innerSink.Events.Count); + Assert.Equal(1, _innerSink.Events.Count); + } } [Fact] public async Task WhenInnerEmitThrows_ThenContinuesRelaysToInnerSink() { - _innerSink.ThrowAfterCollecting = true; - - var events = new List + using (var sink = this.CreateSinkWithDefaultOptions()) { - CreateEvent(), - CreateEvent(), - CreateEvent() - }; - events.ForEach(e => _sink.Emit(e)); + _innerSink.ThrowAfterCollecting = true; - await Task.Delay(TimeSpan.FromSeconds(3)); + var events = new List + { + CreateEvent(), + CreateEvent(), + CreateEvent() + }; + events.ForEach(e => sink.Emit(e)); + + await Task.Delay(TimeSpan.FromSeconds(3)); - Assert.Equal(3, _innerSink.Events.Count); + Assert.Equal(3, _innerSink.Events.Count); + } } [Fact] public async Task WhenEmitMultipleTimes_ThenRelaysToInnerSink() { - var events = new List + using (var sink = this.CreateSinkWithDefaultOptions()) { - CreateEvent(), - CreateEvent(), - CreateEvent() - }; - - events.ForEach(e => { _sink.Emit(e); }); + var events = new List + { + 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 WhenQueueFull_ThenDropsEvents() { - _sink = new BackgroundWorkerSink(_logger, 1, false); - - // 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 + using (var sink = new BackgroundWorkerSink(_logger, 1, false)) { - CreateEvent(), - CreateEvent(), - CreateEvent(), - CreateEvent(), - CreateEvent() - }; - events.ForEach(e => - { - var sw = Stopwatch.StartNew(); - _sink.Emit(e); - sw.Stop(); + // 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(), + CreateEvent(), + CreateEvent() + }; + events.ForEach(e => + { + var sw = Stopwatch.StartNew(); + sink.Emit(e); + sw.Stop(); - Assert.True(sw.ElapsedMilliseconds < 200, "Should not block the caller when the queue is full"); - }); + Assert.True(sw.ElapsedMilliseconds < 200, "Should not block the caller when the queue is full"); + }); - // If we *weren't* dropped events, the delay in the inner sink would mean the 5 events would take - // at least 15 seconds to process - await Task.Delay(TimeSpan.FromSeconds(2)); + // If we *weren't* dropped events, the delay in the inner sink would mean the 5 events would take + // at least 15 seconds to process + await Task.Delay(TimeSpan.FromSeconds(2)); - // Events should be dropped - Assert.Equal(2, _innerSink.Events.Count); + // Events should be dropped + Assert.Equal(2, _innerSink.Events.Count); + } } [Fact] public async Task WhenQueueFull_ThenBlocks() { - _sink = new BackgroundWorkerSink(_logger, 1, 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 + using (var sink = new BackgroundWorkerSink(_logger, 1, true)) { - CreateEvent(), - CreateEvent(), - CreateEvent() - }; + // 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); - 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) + var events = new List { - Assert.True(sw.ElapsedMilliseconds > 200, "Should block the caller when the queue is full"); - } - }); + CreateEvent(), + CreateEvent(), + CreateEvent() + }; - await Task.Delay(TimeSpan.FromSeconds(2)); + 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); + } + } - // No events should be dropped - Assert.Equal(3, _innerSink.Events.Count); + private BackgroundWorkerSink CreateSinkWithDefaultOptions() + { + return new BackgroundWorkerSink(_logger, 10000, false); } private static LogEvent CreateEvent() From 86c9a4c859c35ea5281d302a81547b8fc9ee0486 Mon Sep 17 00:00:00 2001 From: Nicholas Blumhardt Date: Tue, 8 Aug 2017 07:57:17 +1000 Subject: [PATCH 08/23] Bump minor version - new `blockWhenFull` option --- src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj b/src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj index 8dca4a8..ace381e 100644 --- a/src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj +++ b/src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj @@ -3,7 +3,7 @@ Asynchronous sink wrapper for Serilog. 1.0.0 - 1.1.1 + 1.2.0 Jezz Santos;Serilog Contributors net45;netstandard1.1 true From b59d7a9171a066634e4ff0b4d7683cf879690b8c Mon Sep 17 00:00:00 2001 From: Michael Freidgeim Date: Sat, 23 Sep 2017 10:03:18 +1000 Subject: [PATCH 09/23] Fixed https:serilog-sinks-rollingfile --- README.md | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/README.md b/README.md index c89bb42..af16822 100644 --- a/README.md +++ b/README.md @@ -1,7 +1,7 @@ # Serilog.Sinks.Async [![Build status](https://ci.appveyor.com/api/projects/status/gvk0wl7aows14spn?svg=true)](https://ci.appveyor.com/project/serilog/serilog-sinks-async) [![NuGet](https://img.shields.io/nuget/v/Serilog.Sinks.Async.svg)](https://www.nuget.org/packages/Serilog.Sinks.Async) [![Join the chat at https://gitter.im/serilog/serilog](https://img.shields.io/gitter/room/serilog/serilog.svg)](https://gitter.im/serilog/serilog) -An asynchronous wrapper for other [Serilog](https://serilog.net) sinks. Use this sink to reduce the overhead of logging calls by delegating work to a background thread. This is especially suited to non-batching sinks like the [File](https://github.com/serilog/serilog-sinks-file) and [RollingFile](https://github.com/serilog-serilog-sinks-rollingfile) sinks that may be affected by I/O bottlenecks. - +An asynchronous wrapper for other [Serilog](https://serilog.net) sinks. Use this sink to reduce the overhead of logging calls by delegating work to a background thread. This is especially suited to non-batching sinks like the [File](https://github.com/serilog/serilog-sinks-file) and [RollingFile](https://github.com/serilog/serilog-sinks-rollingfile) sinks that may be affected by I/O bottlenecks. +u **Note:** many of the network-based sinks (_CouchDB_, _Elasticsearch_, _MongoDB_, _Seq_, _Splunk_...) already perform asychronous batching natively and do not benefit from this wrapper. ### Getting started From f88c6426b99541eef6aeb227590015bc29c8a829 Mon Sep 17 00:00:00 2001 From: Nicholas Blumhardt Date: Sat, 23 Sep 2017 12:34:25 +1000 Subject: [PATCH 10/23] Remove a stray letter 'u' --- README.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/README.md b/README.md index af16822..81b2925 100644 --- a/README.md +++ b/README.md @@ -1,7 +1,7 @@ # Serilog.Sinks.Async [![Build status](https://ci.appveyor.com/api/projects/status/gvk0wl7aows14spn?svg=true)](https://ci.appveyor.com/project/serilog/serilog-sinks-async) [![NuGet](https://img.shields.io/nuget/v/Serilog.Sinks.Async.svg)](https://www.nuget.org/packages/Serilog.Sinks.Async) [![Join the chat at https://gitter.im/serilog/serilog](https://img.shields.io/gitter/room/serilog/serilog.svg)](https://gitter.im/serilog/serilog) An asynchronous wrapper for other [Serilog](https://serilog.net) sinks. Use this sink to reduce the overhead of logging calls by delegating work to a background thread. This is especially suited to non-batching sinks like the [File](https://github.com/serilog/serilog-sinks-file) and [RollingFile](https://github.com/serilog/serilog-sinks-rollingfile) sinks that may be affected by I/O bottlenecks. -u + **Note:** many of the network-based sinks (_CouchDB_, _Elasticsearch_, _MongoDB_, _Seq_, _Splunk_...) already perform asychronous batching natively and do not benefit from this wrapper. ### Getting started From 33127160eedb72b19e3b79074cf6ace88404ac7d Mon Sep 17 00:00:00 2001 From: Ruben Bartelink Date: Wed, 18 Apr 2018 15:36:15 +0100 Subject: [PATCH 11/23] Document Blocking support, minor doc tweaks --- README.md | 22 +++++++++++++++++----- 1 file changed, 17 insertions(+), 5 deletions(-) diff --git a/README.md b/README.md index 81b2925..91abfb2 100644 --- a/README.md +++ b/README.md @@ -12,11 +12,11 @@ Install from [NuGet](https://nuget.org/packages/serilog.sinks.async): Install-Package Serilog.Sinks.Async ``` -Assuming you have already installed the target sink, such as the rolling file sink, move the wrapped sink's configuration within a `WriteTo.Async()` statement: +Assuming you have already installed the target sink, such as the file sink, move the wrapped sink's configuration within a `WriteTo.Async()` statement: ```csharp Log.Logger = new LoggerConfiguration() - .WriteTo.Async(a => a.RollingFile("logs/myapp-{Date}.txt")) + .WriteTo.Async(a => a.File("logs/myapp.log")) // Other logger configuration .CreateLogger() @@ -26,7 +26,7 @@ Log.Information("This will be written to disk on the worker thread"); Log.CloseAndFlush(); ``` -The wrapped sink (`RollingFile` in this case) will be invoked on a worker thread while your application's thread gets on with more important stuff. +The wrapped sink (`File` in this case) will be invoked on a worker thread while your application's thread gets on with more important stuff. Because the memory buffer may contain events that have not yet been written to the target sink, it is important to call `Log.CloseAndFlush()` or `Logger.Dispose()` when the application exits. @@ -36,7 +36,19 @@ The default memory buffer feeding the worker thread is capped to 10,000 items, a ```csharp // Reduce the buffer to 500 events - .WriteTo.Async(a => a.RollingFile("logs/myapp-{Date}.txt"), 500) + .WriteTo.Async(a => a.File("logs/myapp.log"), bufferSize: 500) +``` + +### 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. + +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`. + +```csharp + // Wait for any queued event to be accepted by the `File` log before allowing the calling thread + // to resume its application work after a logging call when there are 10,000 LogEvents waiting + .WriteTo.Async(a => a.File("logs/myapp.log"), blockWhenFull: true) ``` ### XML `` and JSON configuration @@ -50,7 +62,7 @@ Using [Serilog.Settings.Configuration](https://github.com/serilog/serilog-settin "Name": "Async", "Args": { "configure": [{ - "Name": "LiterateConsole" + "Name": "Console" }] } }] From 46d30769c2477a7a3b5856dfcbb1de38ad95d97e Mon Sep 17 00:00:00 2001 From: Ruben Bartelink Date: Wed, 18 Apr 2018 18:52:33 +0100 Subject: [PATCH 12/23] Reformatting/cleanup --- .../LoggerConfigurationAsyncExtensions.cs | 6 +++--- .../Sinks/Async/BackgroundWorkerSink.cs | 12 +++++------- 2 files changed, 8 insertions(+), 10 deletions(-) diff --git a/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs b/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs index 451fcc9..c1a7681 100644 --- a/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs +++ b/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs @@ -16,7 +16,7 @@ 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, subsequent events will be + /// 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)] @@ -34,8 +34,8 @@ public static LoggerConfiguration Async( /// 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 + /// 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. diff --git a/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs b/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs index 694cb6e..29175fd 100644 --- a/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs +++ b/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs @@ -1,17 +1,16 @@ using System; using System.Collections.Concurrent; using System.Threading; +using System.Threading.Tasks; using Serilog.Core; using Serilog.Debugging; using Serilog.Events; -using System.Threading.Tasks; namespace Serilog.Sinks.Async { sealed class BackgroundWorkerSink : ILogEventSink, IDisposable { readonly ILogEventSink _pipeline; - readonly int _bufferCapacity; readonly bool _blockWhenFull; readonly BlockingCollection _queue; readonly Task _worker; @@ -21,15 +20,14 @@ public BackgroundWorkerSink(ILogEventSink pipeline, int bufferCapacity, bool blo if (pipeline == null) throw new ArgumentNullException(nameof(pipeline)); if (bufferCapacity <= 0) throw new ArgumentOutOfRangeException(nameof(bufferCapacity)); _pipeline = pipeline; - _bufferCapacity = bufferCapacity; _blockWhenFull = blockWhenFull; - _queue = new BlockingCollection(_bufferCapacity); + _queue = new BlockingCollection(bufferCapacity); _worker = Task.Factory.StartNew(Pump, CancellationToken.None, TaskCreationOptions.LongRunning | TaskCreationOptions.DenyChildAttach, TaskScheduler.Default); } public void Emit(LogEvent logEvent) { - if (this._queue.IsAddingCompleted) + if (_queue.IsAddingCompleted) return; try @@ -41,12 +39,12 @@ public void Emit(LogEvent logEvent) else { if (!_queue.TryAdd(logEvent)) - SelfLog.WriteLine("{0} unable to enqueue, capacity {1}", typeof(BackgroundWorkerSink), _bufferCapacity); + SelfLog.WriteLine("{0} unable to enqueue, capacity {1}", typeof(BackgroundWorkerSink), _queue.BoundedCapacity); } } catch (InvalidOperationException) { - // Thrown in the event of a race condition when we try to add another event after + // Thrown in the event of a race condition when we try to add another event after // CompleteAdding has been called } } From 5cdcb14e9b74dafd9d174631fbe82f6720879369 Mon Sep 17 00:00:00 2001 From: Ruben Bartelink Date: Wed, 18 Apr 2018 18:51:44 +0100 Subject: [PATCH 13/23] xUnit update; remove xUnit warnings --- .../Serilog.Sinks.Async.PerformanceTests.csproj | 4 ++-- .../BackgroundWorkerSinkIntegrationSpec.cs | 2 +- .../BackgroundWorkerSinkSpec.cs | 10 +++++----- .../BackgroundWorkerSinkTests.cs | 2 +- .../Serilog.Sinks.Async.Tests.csproj | 4 ++-- 5 files changed, 11 insertions(+), 11 deletions(-) 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 990767f..54ec36f 100644 --- a/test/Serilog.Sinks.Async.PerformanceTests/Serilog.Sinks.Async.PerformanceTests.csproj +++ b/test/Serilog.Sinks.Async.PerformanceTests/Serilog.Sinks.Async.PerformanceTests.csproj @@ -18,8 +18,8 @@ - - + + diff --git a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkIntegrationSpec.cs b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkIntegrationSpec.cs index 7e664d4..14c0441 100644 --- a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkIntegrationSpec.cs +++ b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkIntegrationSpec.cs @@ -130,7 +130,7 @@ public void WhenAuditSingle_ThenQueued() var result = RetrieveEvents(_memorySink, 1); - Assert.Equal(1, result.Count); + Assert.Single(result); } [Fact] diff --git a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs index 76f124b..dd121f6 100644 --- a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs +++ b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs @@ -39,7 +39,7 @@ public async Task WhenEmitSingle_ThenRelaysToInnerSink() await Task.Delay(TimeSpan.FromSeconds(3)); - Assert.Equal(1, _innerSink.Events.Count); + Assert.Single(_innerSink.Events); } } @@ -88,7 +88,7 @@ public async Task WhenQueueFull_ThenDropsEvents() { using (var sink = new BackgroundWorkerSink(_logger, 1, false)) { - // Cause a delay when emmitting to the inner sink, allowing us to fill the queue to capacity + // 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); @@ -109,7 +109,7 @@ public async Task WhenQueueFull_ThenDropsEvents() Assert.True(sw.ElapsedMilliseconds < 200, "Should not block the caller when the queue is full"); }); - // If we *weren't* dropped events, the delay in the inner sink would mean the 5 events would take + // If we *weren't* dropped events, the delay in the inner sink would mean the 5 events would take // at least 15 seconds to process await Task.Delay(TimeSpan.FromSeconds(2)); @@ -123,7 +123,7 @@ public async Task WhenQueueFull_ThenBlocks() { using (var sink = new BackgroundWorkerSink(_logger, 1, true)) { - // Cause a delay when emmitting to the inner sink, allowing us to fill the queue to capacity + // 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); @@ -141,7 +141,7 @@ public async Task WhenQueueFull_ThenBlocks() sink.Emit(e); sw.Stop(); - // Emit should return immediately the first time, since the queue is not yet full. On + // 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) { diff --git a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkTests.cs b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkTests.cs index aca516f..179564c 100644 --- a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkTests.cs +++ b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkTests.cs @@ -32,7 +32,7 @@ public void DisposeCompletesWithoutWorkPerformed() { } - Assert.Equal(0, collector.Events.Count); + Assert.Empty(collector.Events); } } } 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 067ba2d..8b7a497 100644 --- a/test/Serilog.Sinks.Async.Tests/Serilog.Sinks.Async.Tests.csproj +++ b/test/Serilog.Sinks.Async.Tests/Serilog.Sinks.Async.Tests.csproj @@ -15,8 +15,8 @@ - - + + From fda2f4d89b4d5ac1e5a75202077de4f3c58549a0 Mon Sep 17 00:00:00 2001 From: Ruben Bartelink Date: Thu, 19 Apr 2018 11:27:19 +0100 Subject: [PATCH 14/23] Fix test timing sensitivity; split test --- .../BackgroundWorkerSinkSpec.cs | 83 +++++++++++++------ 1 file changed, 56 insertions(+), 27 deletions(-) diff --git a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs index dd121f6..4dd089d 100644 --- a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs +++ b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs @@ -84,44 +84,73 @@ public async Task WhenEmitMultipleTimes_ThenRelaysToInnerSink() } [Fact] - public async Task WhenQueueFull_ThenDropsEvents() + public async Task GivenDefaultConfig_WhenQueueOverCapacity_DoesNotBlock() { - using (var sink = new BackgroundWorkerSink(_logger, 1, false)) + var batchTiming = Stopwatch.StartNew(); + using (var sink = new BackgroundWorkerSink(_logger, 1, blockWhenFull: false /*default*/)) { - // 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(), - CreateEvent(), - CreateEvent() - }; - events.ForEach(e => + // Cause a delay when emmitting 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 sw = Stopwatch.StartNew(); - sink.Emit(e); - sw.Stop(); + var emissionTiming = Stopwatch.StartNew(); + sink.Emit(CreateEvent()); + emissionTiming.Stop(); - Assert.True(sw.ElapsedMilliseconds < 200, "Should not block the caller when the queue is full"); - }); + // Should not block the caller when the queue is full + Assert.InRange(emissionTiming.ElapsedMilliseconds, 0, 200); + } - // If we *weren't* dropped events, the delay in the inner sink would mean the 5 events would take - // at least 15 seconds to process - await Task.Delay(TimeSpan.FromSeconds(2)); + // Allow at least one to propagate + await Task.Delay(TimeSpan.FromSeconds(1)).ConfigureAwait(false); + } + // 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_WhenRequestsOverCapacity_ThenDropsEventsAndRecovers() + { + using (var sink = new BackgroundWorkerSink(_logger, 1, blockWhenFull: false /*default*/)) + { + var acceptInterval = TimeSpan.FromMilliseconds(200); + _innerSink.DelayEmit = acceptInterval; - // Events should be dropped - Assert.Equal(2, _innerSink.Events.Count); + 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)); } } [Fact] - public async Task WhenQueueFull_ThenBlocks() + public async Task GivenConfiguredToBlock_WhenQueueFilled_ThenBlocks() { - using (var sink = new BackgroundWorkerSink(_logger, 1, true)) + 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 From 579a0cf02f9c09641cfa296f572866cb66cb9d93 Mon Sep 17 00:00:00 2001 From: Ruben Bartelink Date: Wed, 18 Apr 2018 16:57:21 +0100 Subject: [PATCH 15/23] Add monitor facility --- README.md | 16 ++++++++++ .../LoggerConfigurationAsyncExtensions.cs | 8 +++-- .../Serilog.Sinks.Async.csproj | 11 ++++++- .../Sinks/Async/BackgroundWorkerSink.cs | 30 ++++++++++++++++--- .../BackgroundWorkerSinkSpec.cs | 25 ++++++++++++++++ 5 files changed, 83 insertions(+), 7 deletions(-) diff --git a/README.md b/README.md index 91abfb2..930dc0c 100644 --- a/README.md +++ b/README.md @@ -39,6 +39,22 @@ The default memory buffer feeding the worker thread is capped to 10,000 items, a .WriteTo.Async(a => a.File("logs/myapp.log"), bufferSize: 500) ``` +### Monitoring + +Typically, one should assign adequate buffer capacity to enable the wrapped sinks to ingest the events as they are processed without ever approaching the limit. In order to gain awareness of the processing backlog becoming abnormal, it's possible to instrument the Async sink by suppling a `monitor` callback that allows for periodic inspection of the backlog + +```csharp + void LogBufferMonitor(buffer : BlockingQueue queue) + { + var usagePct = queue.Count * 100 / queue.BoundedCapacity; + if (usagePct > 50) SelfLog.WriteLine("Log buffer exceeded {0:p0} usage (limit: {1})", usage, queue.BoundedCapacity); + } + + // Wait for any queued event to be accepted by the `File` log before allowing the calling thread + // to resume its application work after a logging call when there are 10,000 LogEvents waiting + .WriteTo.Async(a => a.File("logs/myapp.log"), monitorIntervalSeconds: 60, monitor: LogBufferMonitor) +``` + ### 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. diff --git a/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs b/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs index c1a7681..9ccd829 100644 --- a/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs +++ b/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs @@ -38,16 +38,20 @@ public static LoggerConfiguration Async( /// 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. + /// Interval between invocations of . + /// Callback to facilitate health checking the internal queue. Frequency is controlled by . /// A allowing configuration to continue. public static LoggerConfiguration Async( this LoggerSinkConfiguration loggerSinkConfiguration, Action configure, int bufferSize = 10000, - bool blockWhenFull = false) + bool blockWhenFull = false, + int monitorIntervalSeconds = 10, + Action> monitor = null) { return LoggerSinkConfiguration.Wrap( loggerSinkConfiguration, - wrappedSink => new BackgroundWorkerSink(wrappedSink, bufferSize, blockWhenFull), + wrappedSink => new BackgroundWorkerSink(wrappedSink, bufferSize, blockWhenFull, monitorIntervalSeconds, monitor), configure); } diff --git a/src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj b/src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj index ace381e..d597b4f 100644 --- a/src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj +++ b/src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj @@ -5,7 +5,7 @@ 1.0.0 1.2.0 Jezz Santos;Serilog Contributors - net45;netstandard1.1 + net45;netstandard1.1;netstandard1.2 true true Serilog.Sinks.Async @@ -26,6 +26,10 @@ + + $(DefineConstants);NETSTANDARD_NO_TIMER + + @@ -35,4 +39,9 @@ + + + + + diff --git a/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs b/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs index 29175fd..a3bc896 100644 --- a/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs +++ b/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs @@ -14,15 +14,32 @@ sealed class BackgroundWorkerSink : ILogEventSink, IDisposable readonly bool _blockWhenFull; readonly BlockingCollection _queue; readonly Task _worker; - - public BackgroundWorkerSink(ILogEventSink pipeline, int bufferCapacity, bool blockWhenFull) +#if! NETSTANDARD_NO_TIMER + readonly Timer _monitorCallbackInvocationTimer; +#endif + public BackgroundWorkerSink( + ILogEventSink pipeline, int bufferCapacity, + bool blockWhenFull, + int monitorIntervalSeconds = 0, Action> monitor = null) { if (pipeline == null) throw new ArgumentNullException(nameof(pipeline)); if (bufferCapacity <= 0) throw new ArgumentOutOfRangeException(nameof(bufferCapacity)); + if (monitorIntervalSeconds < 0) throw new ArgumentOutOfRangeException(nameof(monitorIntervalSeconds)); _pipeline = pipeline; _blockWhenFull = blockWhenFull; _queue = new BlockingCollection(bufferCapacity); _worker = Task.Factory.StartNew(Pump, CancellationToken.None, TaskCreationOptions.LongRunning | TaskCreationOptions.DenyChildAttach, TaskScheduler.Default); + + if (monitor != null) + { + if (monitorIntervalSeconds < 1) throw new ArgumentOutOfRangeException(nameof(monitorIntervalSeconds), "must be >=1"); +#if! NETSTANDARD_NO_TIMER + var interval = TimeSpan.FromSeconds(monitorIntervalSeconds); + _monitorCallbackInvocationTimer = new Timer(queue => monitor((BlockingCollection)queue), _queue, interval, interval); +#else + throw new PlatformNotSupportedException($"Please use a platform supporting .netstandard1.2 or later to avail of the ${nameof(monitor)} facility."); +#endif + } } public void Emit(LogEvent logEvent) @@ -55,8 +72,13 @@ public void Dispose() _queue.CompleteAdding(); // Allow queued events to be flushed - _worker.Wait(); - + _worker.Wait(); + +#if! NETSTANDARD_NO_TIMER + // Only stop monitoring when we've actually completed flushing + _monitorCallbackInvocationTimer?.Dispose(); +#endif + (_pipeline as IDisposable)?.Dispose(); } diff --git a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs index 4dd089d..d4d347f 100644 --- a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs +++ b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs @@ -1,4 +1,5 @@ using System; +using System.Collections.Concurrent; using System.Collections.Generic; using System.Diagnostics; using System.Linq; @@ -185,6 +186,30 @@ public async Task GivenConfiguredToBlock_WhenQueueFilled_ThenBlocks() } } +#if !NETSTANDARD_NO_TIMER + [Fact] + public void MonitorArgumentAffordsBacklogHealthMonitoringFacility() + { + bool logWasObservedToHaveReachedHalfFull = false; + void inspectBuffer(BlockingCollection queue) => + + logWasObservedToHaveReachedHalfFull = logWasObservedToHaveReachedHalfFull + || queue.Count * 100 / queue.BoundedCapacity >= 50; + + var collector = new MemorySink { DelayEmit = TimeSpan.FromSeconds(3) }; + using (var logger = new LoggerConfiguration() + .WriteTo.Async(w => w.Sink(collector), bufferSize: 2, monitorIntervalSeconds: 1, monitor: inspectBuffer) + .CreateLogger()) + { + logger.Information("Something to block the pipe"); + logger.Information("I'll just leave this here pending for a few seconds so I can observe it"); + System.Threading.Thread.Sleep(TimeSpan.FromSeconds(2)); + } + + Assert.True(logWasObservedToHaveReachedHalfFull); + } +#endif + private BackgroundWorkerSink CreateSinkWithDefaultOptions() { return new BackgroundWorkerSink(_logger, 10000, false); From dcd24ac49091e5dfc0c74e796e66ed1c15e2f978 Mon Sep 17 00:00:00 2001 From: Ruben Bartelink Date: Fri, 20 Apr 2018 01:54:48 +0100 Subject: [PATCH 16/23] Add IQueueState inspector --- README.md | 21 ++++--- .../LoggerConfigurationAsyncExtensions.cs | 60 +++++++++++++++++-- .../Serilog.Sinks.Async.csproj | 11 +--- .../Sinks/Async/BackgroundWorkerSink.cs | 35 +++-------- .../BackgroundWorkerSinkSpec.cs | 41 ++++++------- 5 files changed, 97 insertions(+), 71 deletions(-) diff --git a/README.md b/README.md index 930dc0c..f167bcf 100644 --- a/README.md +++ b/README.md @@ -39,20 +39,25 @@ The default memory buffer feeding the worker thread is capped to 10,000 items, a .WriteTo.Async(a => a.File("logs/myapp.log"), bufferSize: 500) ``` -### Monitoring +### Health Monitoring via the Buffer Inspection interface -Typically, one should assign adequate buffer capacity to enable the wrapped sinks to ingest the events as they are processed without ever approaching the limit. In order to gain awareness of the processing backlog becoming abnormal, it's possible to instrument the Async sink by suppling a `monitor` callback that allows for periodic inspection of the backlog +The Async wrapper is primarily intended to allow one to achieve minimal logging latency at all times, even when writing to sinks that may momentarily block during the course of their processing (e.g., a File sink might block for a low number of ms while flushing). The dropping behavior is an important failsafe in that it avoids having an unbounded buffering behaviour should logging frequency overwhelm the sink, or the sink ingestion throughput degrades to a major degree. + +In practice, this configuration (assuming one provisions an adequate `bufferSize`) achieves an efficient and resilient logging configuration that can handle load gracefully. The key risk is of course that events may be dropped when the buffer threshold gets breached. The `inspector` allows one to arrange for your Application's health monitoring mechanism to actively validate that the buffer allocation is not being exceeded in practice. ```csharp - void LogBufferMonitor(buffer : BlockingQueue queue) + // Example check: log message to an out of band alarm channel if logging is showing signs of getting overwhelmed + void PeriodicMonitorCheck(IQueueState inspector) { - var usagePct = queue.Count * 100 / queue.BoundedCapacity; - if (usagePct > 50) SelfLog.WriteLine("Log buffer exceeded {0:p0} usage (limit: {1})", usage, queue.BoundedCapacity); + var usagePct = inspector.Count * 100 / inspector.BoundedCapacity; + if (usagePct > 50) SelfLog.WriteLine("Log buffer exceeded {0:p0} usage (limit: {1})", usagePct, inspector.BoundedCapacity); } - // Wait for any queued event to be accepted by the `File` log before allowing the calling thread - // to resume its application work after a logging call when there are 10,000 LogEvents waiting - .WriteTo.Async(a => a.File("logs/myapp.log"), monitorIntervalSeconds: 60, monitor: LogBufferMonitor) + // Allow a backlog of up to 10,000 items to be maintained (dropping extras if full) + .WriteTo.Async(a => a.File("logs/myapp.log"), inspector: out IQueueState inspector) ... + + // Wire the inspector through to health monitoring and/or metrics in order to periodically emit a metric, raise an alarm, etc. + ... healthMonitoring.RegisterCheck(() => new PeriodicMonitorCheck(inspector)); ``` ### Blocking diff --git a/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs b/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs index 9ccd829..77d630b 100644 --- a/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs +++ b/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs @@ -38,22 +38,70 @@ public static LoggerConfiguration Async( /// 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. - /// Interval between invocations of . - /// Callback to facilitate health checking the internal queue. Frequency is controlled by . /// A allowing configuration to continue. public static LoggerConfiguration Async( this LoggerSinkConfiguration loggerSinkConfiguration, Action configure, int bufferSize = 10000, - bool blockWhenFull = false, - int monitorIntervalSeconds = 10, - Action> monitor = null) + bool blockWhenFull = false) { return LoggerSinkConfiguration.Wrap( loggerSinkConfiguration, - wrappedSink => new BackgroundWorkerSink(wrappedSink, bufferSize, blockWhenFull, monitorIntervalSeconds, monitor), + wrappedSink => new BackgroundWorkerSink(wrappedSink, bufferSize, blockWhenFull), configure); } + /// + /// Configure a sink to be invoked asynchronously, on a background worker thread. + /// Provides an that can be used to check the live state of the buffer 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. + /// Provides a way to inspect the state of the queue for health monitoring purposes. + /// A allowing configuration to continue. + public static LoggerConfiguration Async( + this LoggerSinkConfiguration loggerSinkConfiguration, + Action configure, + out IQueueState inspector, + int bufferSize = 10000, + bool blockWhenFull = false) + { + // Cannot assign directly to the out param from within the lambda, so we need a temp + IQueueState stateLens = null; + var result = LoggerSinkConfiguration.Wrap( + loggerSinkConfiguration, + wrappedSink => + { + var sink = new BackgroundWorkerSink(wrappedSink, bufferSize, blockWhenFull); + stateLens = sink; + return sink; + }, + configure); + inspector = stateLens; + return result; + } + } + + /// + /// Provides a way to inspect the current state of Async wrapper's ingestion queue. + /// + public interface IQueueState + { + /// + /// Count of items currently awaiting ingestion. + /// + /// The Sink has been disposed. + int Count { get; } + + /// + /// Maximum number of items permitted to be held in the buffer awaiting ingestion. + /// + /// The Sink has been disposed. + int BufferSize { get; } } } diff --git a/src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj b/src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj index d597b4f..ace381e 100644 --- a/src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj +++ b/src/Serilog.Sinks.Async/Serilog.Sinks.Async.csproj @@ -5,7 +5,7 @@ 1.0.0 1.2.0 Jezz Santos;Serilog Contributors - net45;netstandard1.1;netstandard1.2 + net45;netstandard1.1 true true Serilog.Sinks.Async @@ -26,10 +26,6 @@ - - $(DefineConstants);NETSTANDARD_NO_TIMER - - @@ -39,9 +35,4 @@ - - - - - diff --git a/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs b/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs index a3bc896..8097571 100644 --- a/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs +++ b/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs @@ -8,38 +8,20 @@ namespace Serilog.Sinks.Async { - sealed class BackgroundWorkerSink : ILogEventSink, IDisposable + sealed class BackgroundWorkerSink : ILogEventSink, IQueueState, IDisposable { readonly ILogEventSink _pipeline; readonly bool _blockWhenFull; readonly BlockingCollection _queue; readonly Task _worker; -#if! NETSTANDARD_NO_TIMER - readonly Timer _monitorCallbackInvocationTimer; -#endif - public BackgroundWorkerSink( - ILogEventSink pipeline, int bufferCapacity, - bool blockWhenFull, - int monitorIntervalSeconds = 0, Action> monitor = null) + + public BackgroundWorkerSink(ILogEventSink pipeline, int bufferCapacity, bool blockWhenFull) { - if (pipeline == null) throw new ArgumentNullException(nameof(pipeline)); if (bufferCapacity <= 0) throw new ArgumentOutOfRangeException(nameof(bufferCapacity)); - if (monitorIntervalSeconds < 0) throw new ArgumentOutOfRangeException(nameof(monitorIntervalSeconds)); - _pipeline = pipeline; + _pipeline = pipeline ?? throw new ArgumentNullException(nameof(pipeline)); _blockWhenFull = blockWhenFull; _queue = new BlockingCollection(bufferCapacity); _worker = Task.Factory.StartNew(Pump, CancellationToken.None, TaskCreationOptions.LongRunning | TaskCreationOptions.DenyChildAttach, TaskScheduler.Default); - - if (monitor != null) - { - if (monitorIntervalSeconds < 1) throw new ArgumentOutOfRangeException(nameof(monitorIntervalSeconds), "must be >=1"); -#if! NETSTANDARD_NO_TIMER - var interval = TimeSpan.FromSeconds(monitorIntervalSeconds); - _monitorCallbackInvocationTimer = new Timer(queue => monitor((BlockingCollection)queue), _queue, interval, interval); -#else - throw new PlatformNotSupportedException($"Please use a platform supporting .netstandard1.2 or later to avail of the ${nameof(monitor)} facility."); -#endif - } } public void Emit(LogEvent logEvent) @@ -74,11 +56,6 @@ public void Dispose() // Allow queued events to be flushed _worker.Wait(); -#if! NETSTANDARD_NO_TIMER - // Only stop monitoring when we've actually completed flushing - _monitorCallbackInvocationTimer?.Dispose(); -#endif - (_pipeline as IDisposable)?.Dispose(); } @@ -96,5 +73,9 @@ void Pump() SelfLog.WriteLine("{0} fatal error in worker thread: {1}", typeof(BackgroundWorkerSink), ex); } } + + int IQueueState.Count => _queue.Count; + + int IQueueState.BufferSize => _queue.BoundedCapacity; } } diff --git a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs index d4d347f..b43706e 100644 --- a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs +++ b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs @@ -1,5 +1,4 @@ using System; -using System.Collections.Concurrent; using System.Collections.Generic; using System.Diagnostics; using System.Linq; @@ -85,12 +84,12 @@ public async Task WhenEmitMultipleTimes_ThenRelaysToInnerSink() } [Fact] - public async Task GivenDefaultConfig_WhenQueueOverCapacity_DoesNotBlock() + public async Task GivenDefaultConfig_WhenRequestsExceedCapacity_DoesNotBlock() { var batchTiming = Stopwatch.StartNew(); using (var sink = new BackgroundWorkerSink(_logger, 1, blockWhenFull: false /*default*/)) { - // Cause a delay when emmitting to the inner sink, allowing us to easily fill the queue to capacity + // 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; @@ -115,7 +114,7 @@ public async Task GivenDefaultConfig_WhenQueueOverCapacity_DoesNotBlock() } [Fact] - public async Task GivenDefaultConfig_WhenRequestsOverCapacity_ThenDropsEventsAndRecovers() + public async Task GivenDefaultConfig_WhenRequestsExceedCapacity_ThenDropsEventsAndRecovers() { using (var sink = new BackgroundWorkerSink(_logger, 1, blockWhenFull: false /*default*/)) { @@ -186,29 +185,31 @@ public async Task GivenConfiguredToBlock_WhenQueueFilled_ThenBlocks() } } -#if !NETSTANDARD_NO_TIMER [Fact] - public void MonitorArgumentAffordsBacklogHealthMonitoringFacility() + public async Task InspectorOutParameterAffordsHealthMonitoringHook() { - bool logWasObservedToHaveReachedHalfFull = false; - void inspectBuffer(BlockingCollection queue) => - - logWasObservedToHaveReachedHalfFull = logWasObservedToHaveReachedHalfFull - || queue.Count * 100 / queue.BoundedCapacity >= 50; - - var collector = new MemorySink { DelayEmit = TimeSpan.FromSeconds(3) }; + 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; using (var logger = new LoggerConfiguration() - .WriteTo.Async(w => w.Sink(collector), bufferSize: 2, monitorIntervalSeconds: 1, monitor: inspectBuffer) + .WriteTo.Async(w => w.Sink(collector), bufferSize: 2, inspector: out IQueueState inspector) .CreateLogger()) { - logger.Information("Something to block the pipe"); - logger.Information("I'll just leave this here pending for a few seconds so I can observe it"); - System.Threading.Thread.Sleep(TimeSpan.FromSeconds(2)); + Assert.Equal(bufferSize, inspector.BufferSize); + Assert.Equal(0, inspector.Count); + logger.Information("Something to freeze the processing for 2s"); + await Task.Delay(TimeSpan.FromMilliseconds(200)); + // Can be taken from queue either instantanously or be awaiting consumer to take + Assert.InRange(inspector.Count, 0, 1); + logger.Information("Something that will sit in the queue"); + // 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. + await Task.Delay(TimeSpan.FromMilliseconds(200)); + Assert.InRange(inspector.Count, 1, 2); + Assert.Equal(bufferSize, inspector.BufferSize); } - - Assert.True(logWasObservedToHaveReachedHalfFull); } -#endif private BackgroundWorkerSink CreateSinkWithDefaultOptions() { From d3b530949dc23af79f1dd156383147cacf3b509d Mon Sep 17 00:00:00 2001 From: Ruben Bartelink Date: Fri, 20 Apr 2018 15:02:05 +0100 Subject: [PATCH 17/23] Surface dropped events count. Resolves #13 --- README.md | 4 ++-- .../LoggerConfigurationAsyncExtensions.cs | 5 +++++ .../Sinks/Async/BackgroundWorkerSink.cs | 7 +++++++ .../BackgroundWorkerSinkSpec.cs | 19 ++++++++++++++++--- 4 files changed, 30 insertions(+), 5 deletions(-) diff --git a/README.md b/README.md index f167bcf..234ce46 100644 --- a/README.md +++ b/README.md @@ -30,9 +30,9 @@ The wrapped sink (`File` in this case) will be invoked on a worker thread while Because the memory buffer may contain events that have not yet been written to the target sink, it is important to call `Log.CloseAndFlush()` or `Logger.Dispose()` when the application exits. -### Buffering +### Buffering & Dropping -The default memory buffer feeding the worker thread is capped to 10,000 items, after which arriving events will be dropped. To increase or decrease this limit, specify it when configuring the async sink. +The default memory buffer feeding the worker thread is capped to 10,000 items, after which arriving events will be dropped. To increase or decrease this limit, specify it when configuring the async sink. One can determine whether events have been dropped via `IQueueState.DroppedMessagesCount` (see Buffer Inspection interface below). ```csharp // Reduce the buffer to 500 events diff --git a/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs b/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs index 77d630b..2adeee4 100644 --- a/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs +++ b/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs @@ -98,6 +98,11 @@ public interface IQueueState /// The Sink has been disposed. int Count { get; } + /// + /// Accumulated number of messages dropped due to attempted submission having breached limit. + /// + long DroppedMessagesCount { get; } + /// /// Maximum number of items permitted to be held in the buffer awaiting ingestion. /// diff --git a/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs b/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs index 8097571..b7a741b 100644 --- a/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs +++ b/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs @@ -15,6 +15,8 @@ sealed class BackgroundWorkerSink : ILogEventSink, IQueueState, IDisposable readonly BlockingCollection _queue; readonly Task _worker; + long _droppedMessages; + public BackgroundWorkerSink(ILogEventSink pipeline, int bufferCapacity, bool blockWhenFull) { if (bufferCapacity <= 0) throw new ArgumentOutOfRangeException(nameof(bufferCapacity)); @@ -38,7 +40,10 @@ public void Emit(LogEvent logEvent) else { if (!_queue.TryAdd(logEvent)) + { + Interlocked.Increment(ref _droppedMessages); SelfLog.WriteLine("{0} unable to enqueue, capacity {1}", typeof(BackgroundWorkerSink), _queue.BoundedCapacity); + } } } catch (InvalidOperationException) @@ -77,5 +82,7 @@ void Pump() int IQueueState.Count => _queue.Count; int IQueueState.BufferSize => _queue.BoundedCapacity; + + long IQueueState.DroppedMessagesCount => _droppedMessages; } } diff --git a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs index b43706e..7071e79 100644 --- a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs +++ b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs @@ -106,6 +106,7 @@ public async Task GivenDefaultConfig_WhenRequestsExceedCapacity_DoesNotBlock() // Allow at least one to propagate await Task.Delay(TimeSpan.FromSeconds(1)).ConfigureAwait(false); + Assert.NotEqual(0, ((IQueueState)sink).DroppedMessagesCount); } // Sanity check the overall timing batchTiming.Stop(); @@ -144,6 +145,7 @@ from e in _innerSink.Events 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, ((IQueueState)sink).DroppedMessagesCount); } } @@ -182,11 +184,12 @@ public async Task GivenConfiguredToBlock_WhenQueueFilled_ThenBlocks() // No events should be dropped Assert.Equal(3, _innerSink.Events.Count); + Assert.Equal(0, ((IQueueState)sink).DroppedMessagesCount); } } [Fact] - public async Task InspectorOutParameterAffordsHealthMonitoringHook() + public void InspectorOutParameterAffordsHealthMonitoringHook() { 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 @@ -197,17 +200,27 @@ public async Task InspectorOutParameterAffordsHealthMonitoringHook() { Assert.Equal(bufferSize, inspector.BufferSize); Assert.Equal(0, inspector.Count); + Assert.Equal(0, inspector.DroppedMessagesCount); logger.Information("Something to freeze the processing for 2s"); - await Task.Delay(TimeSpan.FromMilliseconds(200)); // 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. - await Task.Delay(TimeSpan.FromMilliseconds(200)); 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); } } From 510db8d0461de5d863b6b08598a622f353fc300b Mon Sep 17 00:00:00 2001 From: Ruben Bartelink Date: Sun, 22 Apr 2018 02:46:19 +0100 Subject: [PATCH 18/23] Address nblumhardt review comments --- README.md | 14 ++++----- .../LoggerConfigurationAsyncExtensions.cs | 29 ++----------------- .../Sinks/Async/BackgroundWorkerSink.cs | 8 ++--- .../Sinks/Async/IAsyncLogEventSinkState.cs | 25 ++++++++++++++++ .../BackgroundWorkerSinkSpec.cs | 8 ++--- 5 files changed, 43 insertions(+), 41 deletions(-) create mode 100644 src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkState.cs diff --git a/README.md b/README.md index 234ce46..25f13bf 100644 --- a/README.md +++ b/README.md @@ -32,18 +32,18 @@ Because the memory buffer may contain events that have not yet been written to t ### Buffering & Dropping -The default memory buffer feeding the worker thread is capped to 10,000 items, after which arriving events will be dropped. To increase or decrease this limit, specify it when configuring the async sink. One can determine whether events have been dropped via `IQueueState.DroppedMessagesCount` (see Buffer Inspection interface below). +The default memory buffer feeding the worker thread is capped to 10,000 items, after which arriving events will be dropped. To increase or decrease this limit, specify it when configuring the async sink. One can determine whether events have been dropped via `Serilog.Async.IAsyncLogEventSinkState.DroppedMessagesCount` (see Sink State Inspection interface below). ```csharp // Reduce the buffer to 500 events .WriteTo.Async(a => a.File("logs/myapp.log"), bufferSize: 500) ``` -### Health Monitoring via the Buffer Inspection interface +### Health Monitoring via the Sink State Inspection interface -The Async wrapper is primarily intended to allow one to achieve minimal logging latency at all times, even when writing to sinks that may momentarily block during the course of their processing (e.g., a File sink might block for a low number of ms while flushing). The dropping behavior is an important failsafe in that it avoids having an unbounded buffering behaviour should logging frequency overwhelm the sink, or the sink ingestion throughput degrades to a major degree. +The `Async` wrapper is primarily intended to allow one to achieve minimal logging latency at all times, even when writing to sinks that may momentarily block during the course of their processing (e.g., a `File` Sink might block for a low number of ms while flushing). The dropping behavior is an important failsafe; it avoids having an unbounded buffering behaviour should logging frequency overwhelm the sink, or the sink ingestion throughput degrade to a major degree. -In practice, this configuration (assuming one provisions an adequate `bufferSize`) achieves an efficient and resilient logging configuration that can handle load gracefully. The key risk is of course that events may be dropped when the buffer threshold gets breached. The `inspector` allows one to arrange for your Application's health monitoring mechanism to actively validate that the buffer allocation is not being exceeded in practice. +In practice, this configuration (assuming one provisions an adequate `bufferSize`) achieves an efficient and resilient logging configuration that can handle load safely. The key risk is of course that events get be dropped when the buffer threshold gets breached. The `inspector` allows one to arrange for your Application's health monitoring mechanism to actively validate that the buffer allocation is not being exceeded in practice. ```csharp // Example check: log message to an out of band alarm channel if logging is showing signs of getting overwhelmed @@ -54,10 +54,10 @@ In practice, this configuration (assuming one provisions an adequate `bufferSize } // Allow a backlog of up to 10,000 items to be maintained (dropping extras if full) - .WriteTo.Async(a => a.File("logs/myapp.log"), inspector: out IQueueState inspector) ... + .WriteTo.Async(a => a.File("logs/myapp.log"), inspector: out Async.IAsyncLogEventSinkState inspector) ... - // Wire the inspector through to health monitoring and/or metrics in order to periodically emit a metric, raise an alarm, etc. - ... healthMonitoring.RegisterCheck(() => new PeriodicMonitorCheck(inspector)); + // Wire the inspector through to application health monitoring and/or metrics in order to periodically emit a metric, raise an alarm, etc. + ... HealthMonitor.RegisterAsyncLogSink(inspector); ``` ### Blocking diff --git a/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs b/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs index 2adeee4..ea53e0b 100644 --- a/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs +++ b/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs @@ -67,12 +67,12 @@ public static LoggerConfiguration Async( public static LoggerConfiguration Async( this LoggerSinkConfiguration loggerSinkConfiguration, Action configure, - out IQueueState inspector, + out IAsyncLogEventSinkState inspector, int bufferSize = 10000, bool blockWhenFull = false) { // Cannot assign directly to the out param from within the lambda, so we need a temp - IQueueState stateLens = null; + IAsyncLogEventSinkState stateLens = null; var result = LoggerSinkConfiguration.Wrap( loggerSinkConfiguration, wrappedSink => @@ -86,27 +86,4 @@ public static LoggerConfiguration Async( return result; } } - - /// - /// Provides a way to inspect the current state of Async wrapper's ingestion queue. - /// - public interface IQueueState - { - /// - /// Count of items currently awaiting ingestion. - /// - /// The Sink has been disposed. - int Count { get; } - - /// - /// Accumulated number of messages dropped due to attempted submission having breached limit. - /// - long DroppedMessagesCount { get; } - - /// - /// Maximum number of items permitted to be held in the buffer awaiting ingestion. - /// - /// The Sink has been disposed. - int BufferSize { get; } - } -} +} \ No newline at end of file diff --git a/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs b/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs index b7a741b..75239f5 100644 --- a/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs +++ b/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs @@ -8,7 +8,7 @@ namespace Serilog.Sinks.Async { - sealed class BackgroundWorkerSink : ILogEventSink, IQueueState, IDisposable + sealed class BackgroundWorkerSink : ILogEventSink, IAsyncLogEventSinkState, IDisposable { readonly ILogEventSink _pipeline; readonly bool _blockWhenFull; @@ -79,10 +79,10 @@ void Pump() } } - int IQueueState.Count => _queue.Count; + int IAsyncLogEventSinkState.BufferSize => _queue.BoundedCapacity; - int IQueueState.BufferSize => _queue.BoundedCapacity; + int IAsyncLogEventSinkState.Count => _queue.Count; - long IQueueState.DroppedMessagesCount => _droppedMessages; + long IAsyncLogEventSinkState.DroppedMessagesCount => _droppedMessages; } } diff --git a/src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkState.cs b/src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkState.cs new file mode 100644 index 0000000..f4ce960 --- /dev/null +++ b/src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkState.cs @@ -0,0 +1,25 @@ +namespace Serilog.Sinks.Async +{ + /// + /// Provides a way to monitor the state of Async wrapper's ingestion queue. + /// + public interface IAsyncLogEventSinkState + { + /// + /// Configured maximum number of items permitted to be held in the buffer awaiting ingestion. + /// + /// 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; } + + /// + /// Accumulated number of messages dropped due to breach of limit. + /// + long DroppedMessagesCount { get; } + } +} \ 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 7071e79..9a0e572 100644 --- a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs +++ b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs @@ -106,7 +106,7 @@ public async Task GivenDefaultConfig_WhenRequestsExceedCapacity_DoesNotBlock() // Allow at least one to propagate await Task.Delay(TimeSpan.FromSeconds(1)).ConfigureAwait(false); - Assert.NotEqual(0, ((IQueueState)sink).DroppedMessagesCount); + Assert.NotEqual(0, ((IAsyncLogEventSinkState)sink).DroppedMessagesCount); } // Sanity check the overall timing batchTiming.Stop(); @@ -145,7 +145,7 @@ from e in _innerSink.Events 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, ((IQueueState)sink).DroppedMessagesCount); + Assert.NotEqual(0, ((IAsyncLogEventSinkState)sink).DroppedMessagesCount); } } @@ -184,7 +184,7 @@ public async Task GivenConfiguredToBlock_WhenQueueFilled_ThenBlocks() // No events should be dropped Assert.Equal(3, _innerSink.Events.Count); - Assert.Equal(0, ((IQueueState)sink).DroppedMessagesCount); + Assert.Equal(0, ((IAsyncLogEventSinkState)sink).DroppedMessagesCount); } } @@ -195,7 +195,7 @@ public void InspectorOutParameterAffordsHealthMonitoringHook() // 2 spaces in queue; 1 would make the second log entry eligible for dropping if consumer does not activate instantaneously var bufferSize = 2; using (var logger = new LoggerConfiguration() - .WriteTo.Async(w => w.Sink(collector), bufferSize: 2, inspector: out IQueueState inspector) + .WriteTo.Async(w => w.Sink(collector), bufferSize: 2, inspector: out IAsyncLogEventSinkState inspector) .CreateLogger()) { Assert.Equal(bufferSize, inspector.BufferSize); From 6546958286d20ea37edefff75d55c77e3363e181 Mon Sep 17 00:00:00 2001 From: Ruben Bartelink Date: Tue, 24 Apr 2018 14:15:38 +0100 Subject: [PATCH 19/23] Add IAsyncLogEventSinkMonitor --- .../LoggerConfigurationAsyncExtensions.cs | 32 +++++++++++++++++-- .../Sinks/Async/BackgroundWorkerSink.cs | 6 +++- .../Sinks/Async/IAsyncLogEventSinkMonitor.cs | 15 +++++++++ .../BackgroundWorkerSinkSpec.cs | 2 +- 4 files changed, 51 insertions(+), 4 deletions(-) create mode 100644 src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkMonitor.cs diff --git a/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs b/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs index ea53e0b..2bf7091 100644 --- a/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs +++ b/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs @@ -44,10 +44,38 @@ public static LoggerConfiguration Async( 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. If the monitor implements , Dispose() will be called to advise of the Sink being Dispose()d. + /// A allowing configuration to continue. + public static LoggerConfiguration Async( + this LoggerSinkConfiguration loggerSinkConfiguration, + Action configure, + IAsyncLogEventSinkMonitor monitor, + int bufferSize, + bool blockWhenFull) { return LoggerSinkConfiguration.Wrap( loggerSinkConfiguration, - wrappedSink => new BackgroundWorkerSink(wrappedSink, bufferSize, blockWhenFull), + wrappedSink => + { + var sink = new BackgroundWorkerSink(wrappedSink, bufferSize, blockWhenFull, monitor); + monitor?.MonitorState(sink); + return sink; + }, configure); } @@ -77,7 +105,7 @@ public static LoggerConfiguration Async( loggerSinkConfiguration, wrappedSink => { - var sink = new BackgroundWorkerSink(wrappedSink, bufferSize, blockWhenFull); + var sink = new BackgroundWorkerSink(wrappedSink, bufferSize, blockWhenFull, null); stateLens = sink; return sink; }, diff --git a/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs b/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs index 75239f5..91b3221 100644 --- a/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs +++ b/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs @@ -14,16 +14,18 @@ sealed class BackgroundWorkerSink : ILogEventSink, IAsyncLogEventSinkState, IDis readonly bool _blockWhenFull; readonly BlockingCollection _queue; readonly Task _worker; + readonly IAsyncLogEventSinkMonitor _monitor; long _droppedMessages; - public BackgroundWorkerSink(ILogEventSink pipeline, int bufferCapacity, bool blockWhenFull) + public BackgroundWorkerSink(ILogEventSink pipeline, int bufferCapacity, bool blockWhenFull, IAsyncLogEventSinkMonitor monitor = null) { if (bufferCapacity <= 0) throw new ArgumentOutOfRangeException(nameof(bufferCapacity)); _pipeline = pipeline ?? throw new ArgumentNullException(nameof(pipeline)); _blockWhenFull = blockWhenFull; _queue = new BlockingCollection(bufferCapacity); _worker = Task.Factory.StartNew(Pump, CancellationToken.None, TaskCreationOptions.LongRunning | TaskCreationOptions.DenyChildAttach, TaskScheduler.Default); + _monitor = monitor; } public void Emit(LogEvent logEvent) @@ -62,6 +64,8 @@ public void Dispose() _worker.Wait(); (_pipeline as IDisposable)?.Dispose(); + + (_monitor as IDisposable)?.Dispose(); } void Pump() diff --git a/src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkMonitor.cs b/src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkMonitor.cs new file mode 100644 index 0000000..4b88ef3 --- /dev/null +++ b/src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkMonitor.cs @@ -0,0 +1,15 @@ +namespace Serilog.Sinks.Async +{ + /// + /// Defines a mechanism for the Async Sink to provide buffer metadata to facilitate integration into system health checking. + /// + /// If the instance implements , it will be Dispose()d at then time the Sink is. + public interface IAsyncLogEventSinkMonitor + { + /// + /// Invoked by Sink to supply the buffer state hook to the monitor. + /// + /// The Async Sink's state information interface. + void MonitorState(IAsyncLogEventSinkState state); + } +} \ 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 9a0e572..048ed62 100644 --- a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs +++ b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs @@ -25,7 +25,7 @@ public BackgroundWorkerSinkSpec() [Fact] public void WhenCtorWithNullSink_ThenThrows() { - Assert.Throws(() => new BackgroundWorkerSink(null, 10000, false)); + Assert.Throws(() => new BackgroundWorkerSink(null, 10000, false, null)); } [Fact] From 17e077908aad61d593fa98735ce099b39d12b5eb Mon Sep 17 00:00:00 2001 From: Ruben Bartelink Date: Wed, 25 Apr 2018 03:18:19 +0100 Subject: [PATCH 20/23] Complete IAsyncLogEventSinkMonitor impl --- README.md | 54 +++++++++++-------- .../LoggerConfigurationAsyncExtensions.cs | 46 ++-------------- .../Sinks/Async/BackgroundWorkerSink.cs | 13 ++--- ...tate.cs => IAsyncLogEventSinkInspector.cs} | 6 +-- .../Sinks/Async/IAsyncLogEventSinkMonitor.cs | 15 ++++-- .../BackgroundWorkerSinkSpec.cs | 16 ++++-- .../BackgroundWorkerSinkTests.cs | 18 ++++++- .../Support/DummyMonitor.cs | 14 +++++ 8 files changed, 96 insertions(+), 86 deletions(-) rename src/Serilog.Sinks.Async/Sinks/Async/{IAsyncLogEventSinkState.cs => IAsyncLogEventSinkInspector.cs} (83%) create mode 100644 test/Serilog.Sinks.Async.Tests/Support/DummyMonitor.cs diff --git a/README.md b/README.md index 25f13bf..70a3b45 100644 --- a/README.md +++ b/README.md @@ -19,10 +19,10 @@ Log.Logger = new LoggerConfiguration() .WriteTo.Async(a => a.File("logs/myapp.log")) // Other logger configuration .CreateLogger() - + Log.Information("This will be written to disk on the worker thread"); -// At application shutdown +// At application shutdown (results in monitors getting StopMonitoring calls) Log.CloseAndFlush(); ``` @@ -32,32 +32,40 @@ Because the memory buffer may contain events that have not yet been written to t ### Buffering & Dropping -The default memory buffer feeding the worker thread is capped to 10,000 items, after which arriving events will be dropped. To increase or decrease this limit, specify it when configuring the async sink. One can determine whether events have been dropped via `Serilog.Async.IAsyncLogEventSinkState.DroppedMessagesCount` (see Sink State Inspection interface below). +The default memory buffer feeding the worker thread is capped to 10,000 items, after which arriving events will be dropped. To increase or decrease this limit, specify it when configuring the async sink. One can determine whether events have been dropped via `Serilog.Async.IAsyncLogEventSinkInspector.DroppedMessagesCount` (see Sink State Inspection interface below). ```csharp - // Reduce the buffer to 500 events - .WriteTo.Async(a => a.File("logs/myapp.log"), bufferSize: 500) +// Reduce the buffer to 500 events +.WriteTo.Async(a => a.File("logs/myapp.log"), bufferSize: 500) ``` -### Health Monitoring via the Sink State Inspection interface +### Health Monitoring via the Monitor and Inspector interfaces -The `Async` wrapper is primarily intended to allow one to achieve minimal logging latency at all times, even when writing to sinks that may momentarily block during the course of their processing (e.g., a `File` Sink might block for a low number of ms while flushing). The dropping behavior is an important failsafe; it avoids having an unbounded buffering behaviour should logging frequency overwhelm the sink, or the sink ingestion throughput degrade to a major degree. +The `Async` wrapper is primarily intended to allow one to achieve minimal logging latency at all times, even when writing to sinks that may momentarily block during the course of their processing (e.g., a `File` Sink might block for a low number of ms while flushing). The dropping behavior is an important failsafe; it avoids having an unbounded buffering behaviour should logging throughput overwhelm the sink, or the sink ingestion throughput degrade. -In practice, this configuration (assuming one provisions an adequate `bufferSize`) achieves an efficient and resilient logging configuration that can handle load safely. The key risk is of course that events get be dropped when the buffer threshold gets breached. The `inspector` allows one to arrange for your Application's health monitoring mechanism to actively validate that the buffer allocation is not being exceeded in practice. +In practice, this configuration (assuming one provisions an adequate `bufferSize`) achieves an efficient and resilient logging configuration that can safely handle load without impacting processing throughput. The risk is of course that events get be dropped if the buffer threshold gets breached. The inspection interface, `IAsyncLogEventSinkInspector` (obtained by providing an `IAsyncLogEventSinkMonitor` when configuring the `Async` Sink), enables a health monitoring mechanism to actively validate that the buffer allocation is not being exceeded in practice. ```csharp - // Example check: log message to an out of band alarm channel if logging is showing signs of getting overwhelmed - void PeriodicMonitorCheck(IQueueState inspector) - { - var usagePct = inspector.Count * 100 / inspector.BoundedCapacity; - if (usagePct > 50) SelfLog.WriteLine("Log buffer exceeded {0:p0} usage (limit: {1})", usagePct, inspector.BoundedCapacity); - } - - // Allow a backlog of up to 10,000 items to be maintained (dropping extras if full) - .WriteTo.Async(a => a.File("logs/myapp.log"), inspector: out Async.IAsyncLogEventSinkState inspector) ... - - // Wire the inspector through to application health monitoring and/or metrics in order to periodically emit a metric, raise an alarm, etc. - ... HealthMonitor.RegisterAsyncLogSink(inspector); +// Example check: log message to an out of band alarm channel if logging is showing signs of getting overwhelmed +void ExecuteAsyncBufferCheck(IAsyncLogEventSinkInspector inspector) +{ + var usagePct = inspector.Count * 100 / inspector.BoundedCapacity; + if (usagePct > 50) SelfLog.WriteLine("Log buffer exceeded {0:p0} usage (limit: {1})", usagePct, inspector.BoundedCapacity); +} + +class MonitorConfiguration : IAsyncLogEventSinkMonitor +{ + public void StartMonitoring(IAsyncLogEventSinkInspector inspector) => + HealthMonitor.AddPeriodicCheck(() => ExecuteAsyncBufferCheck(inspector)); + + public void StopMonitoring(IAsyncLogEventSinkInspector inspector) + { /* reverse of StartMonitoring */ } +} + +// Provide monitor so we can wire the health check to the inspector +var monitor = new MonitorConfiguration(); +// Use default config (drop events if >10,000 backlog) +.WriteTo.Async(a => a.File("logs/myapp.log"), monitor: monitor) ... ``` ### Blocking @@ -67,9 +75,9 @@ Warning: For the same reason one typically does not want exceptions from logging 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`. ```csharp - // Wait for any queued event to be accepted by the `File` log before allowing the calling thread - // to resume its application work after a logging call when there are 10,000 LogEvents waiting - .WriteTo.Async(a => a.File("logs/myapp.log"), blockWhenFull: true) +// Wait for any queued event to be accepted by the `File` log before allowing the calling thread to resume its +// application work after a logging call when there are 10,000 LogEvents awaiting ingestion by the pipeline +.WriteTo.Async(a => a.File("logs/myapp.log"), blockWhenFull: true) ``` ### XML `` and JSON configuration diff --git a/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs b/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs index 2bf7091..aa3cdf4 100644 --- a/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs +++ b/src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs @@ -59,59 +59,19 @@ public static LoggerConfiguration Async( /// 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. If the monitor implements , Dispose() will be called to advise of the Sink being Dispose()d. + /// Monitor to supply buffer information to. /// A allowing configuration to continue. public static LoggerConfiguration Async( this LoggerSinkConfiguration loggerSinkConfiguration, Action configure, IAsyncLogEventSinkMonitor monitor, - int bufferSize, - bool blockWhenFull) - { - return LoggerSinkConfiguration.Wrap( - loggerSinkConfiguration, - wrappedSink => - { - var sink = new BackgroundWorkerSink(wrappedSink, bufferSize, blockWhenFull, monitor); - monitor?.MonitorState(sink); - return sink; - }, - configure); - } - - /// - /// Configure a sink to be invoked asynchronously, on a background worker thread. - /// Provides an that can be used to check the live state of the buffer 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. - /// Provides a way to inspect the state of the queue for health monitoring purposes. - /// A allowing configuration to continue. - public static LoggerConfiguration Async( - this LoggerSinkConfiguration loggerSinkConfiguration, - Action configure, - out IAsyncLogEventSinkState inspector, int bufferSize = 10000, bool blockWhenFull = false) { - // Cannot assign directly to the out param from within the lambda, so we need a temp - IAsyncLogEventSinkState stateLens = null; - var result = LoggerSinkConfiguration.Wrap( + return LoggerSinkConfiguration.Wrap( loggerSinkConfiguration, - wrappedSink => - { - var sink = new BackgroundWorkerSink(wrappedSink, bufferSize, blockWhenFull, null); - stateLens = sink; - return sink; - }, + wrappedSink => new BackgroundWorkerSink(wrappedSink, bufferSize, blockWhenFull, monitor), configure); - inspector = stateLens; - return result; } } } \ No newline at end of file diff --git a/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs b/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs index 91b3221..b77f32b 100644 --- a/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs +++ b/src/Serilog.Sinks.Async/Sinks/Async/BackgroundWorkerSink.cs @@ -8,7 +8,7 @@ namespace Serilog.Sinks.Async { - sealed class BackgroundWorkerSink : ILogEventSink, IAsyncLogEventSinkState, IDisposable + sealed class BackgroundWorkerSink : ILogEventSink, IAsyncLogEventSinkInspector, IDisposable { readonly ILogEventSink _pipeline; readonly bool _blockWhenFull; @@ -26,6 +26,7 @@ public BackgroundWorkerSink(ILogEventSink pipeline, int bufferCapacity, bool blo _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) @@ -65,7 +66,7 @@ public void Dispose() (_pipeline as IDisposable)?.Dispose(); - (_monitor as IDisposable)?.Dispose(); + _monitor?.StopMonitoring(this); } void Pump() @@ -83,10 +84,10 @@ void Pump() } } - int IAsyncLogEventSinkState.BufferSize => _queue.BoundedCapacity; + int IAsyncLogEventSinkInspector.BufferSize => _queue.BoundedCapacity; - int IAsyncLogEventSinkState.Count => _queue.Count; + int IAsyncLogEventSinkInspector.Count => _queue.Count; - long IAsyncLogEventSinkState.DroppedMessagesCount => _droppedMessages; + long IAsyncLogEventSinkInspector.DroppedMessagesCount => _droppedMessages; } -} +} \ No newline at end of file diff --git a/src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkState.cs b/src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkInspector.cs similarity index 83% rename from src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkState.cs rename to src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkInspector.cs index f4ce960..0edccdc 100644 --- a/src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkState.cs +++ b/src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkInspector.cs @@ -1,9 +1,9 @@ namespace Serilog.Sinks.Async { /// - /// Provides a way to monitor the state of Async wrapper's ingestion queue. + /// Provides a way to inspect the state of Async wrapper's ingestion queue. /// - public interface IAsyncLogEventSinkState + public interface IAsyncLogEventSinkInspector { /// /// Configured maximum number of items permitted to be held in the buffer awaiting ingestion. @@ -18,7 +18,7 @@ public interface IAsyncLogEventSinkState int Count { get; } /// - /// Accumulated number of messages dropped due to breach of limit. + /// Accumulated number of messages dropped due to breaches of limit. /// long DroppedMessagesCount { get; } } diff --git a/src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkMonitor.cs b/src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkMonitor.cs index 4b88ef3..26a43d1 100644 --- a/src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkMonitor.cs +++ b/src/Serilog.Sinks.Async/Sinks/Async/IAsyncLogEventSinkMonitor.cs @@ -1,15 +1,20 @@ namespace Serilog.Sinks.Async { /// - /// Defines a mechanism for the Async Sink to provide buffer metadata to facilitate integration into system health checking. + /// Defines a mechanism for the Async Sink to afford Health Checks a buffer metadata inspection mechanism. /// - /// If the instance implements , it will be Dispose()d at then time the Sink is. public interface IAsyncLogEventSinkMonitor { /// - /// Invoked by Sink to supply the buffer state hook to the monitor. + /// Invoked by Sink to supply the inspector to the monitor. /// - /// The Async Sink's state information interface. - void MonitorState(IAsyncLogEventSinkState state); + /// 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); } } \ 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 048ed62..5b5876d 100644 --- a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs +++ b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkSpec.cs @@ -2,6 +2,7 @@ using System.Collections.Generic; using System.Diagnostics; using System.Linq; +using System.Threading; using System.Threading.Tasks; using Serilog.Core; using Serilog.Events; @@ -106,7 +107,7 @@ public async Task GivenDefaultConfig_WhenRequestsExceedCapacity_DoesNotBlock() // Allow at least one to propagate await Task.Delay(TimeSpan.FromSeconds(1)).ConfigureAwait(false); - Assert.NotEqual(0, ((IAsyncLogEventSinkState)sink).DroppedMessagesCount); + Assert.NotEqual(0, ((IAsyncLogEventSinkInspector)sink).DroppedMessagesCount); } // Sanity check the overall timing batchTiming.Stop(); @@ -145,7 +146,7 @@ from e in _innerSink.Events 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, ((IAsyncLogEventSinkState)sink).DroppedMessagesCount); + Assert.NotEqual(0, ((IAsyncLogEventSinkInspector)sink).DroppedMessagesCount); } } @@ -184,20 +185,23 @@ public async Task GivenConfiguredToBlock_WhenQueueFilled_ThenBlocks() // No events should be dropped Assert.Equal(3, _innerSink.Events.Count); - Assert.Equal(0, ((IAsyncLogEventSinkState)sink).DroppedMessagesCount); + Assert.Equal(0, ((IAsyncLogEventSinkInspector)sink).DroppedMessagesCount); } } [Fact] - public void InspectorOutParameterAffordsHealthMonitoringHook() + 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, inspector: out IAsyncLogEventSinkState inspector) + .WriteTo.Async(w => w.Sink(collector), bufferSize: 2, monitor: monitor) .CreateLogger()) { + // Construction of BackgroundWorkerSink triggers StartMonitoring + var inspector = monitor.Inspector; Assert.Equal(bufferSize, inspector.BufferSize); Assert.Equal(0, inspector.Count); Assert.Equal(0, inspector.DroppedMessagesCount); @@ -222,6 +226,8 @@ public void InspectorOutParameterAffordsHealthMonitoringHook() // 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); } private BackgroundWorkerSink CreateSinkWithDefaultOptions() diff --git a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkTests.cs b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkTests.cs index 179564c..598be5b 100644 --- a/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkTests.cs +++ b/test/Serilog.Sinks.Async.Tests/BackgroundWorkerSinkTests.cs @@ -34,5 +34,21 @@ public void DisposeCompletesWithoutWorkPerformed() Assert.Empty(collector.Events); } + + [Fact] + public void CtorAndDisposeInformMonitor() + { + var collector = new MemorySink(); + var monitor = new DummyMonitor(); + + 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/Support/DummyMonitor.cs b/test/Serilog.Sinks.Async.Tests/Support/DummyMonitor.cs new file mode 100644 index 0000000..2d630cd --- /dev/null +++ b/test/Serilog.Sinks.Async.Tests/Support/DummyMonitor.cs @@ -0,0 +1,14 @@ +namespace Serilog.Sinks.Async.Tests.Support +{ + class DummyMonitor : IAsyncLogEventSinkMonitor + { + IAsyncLogEventSinkInspector inspector; + public IAsyncLogEventSinkInspector Inspector => inspector; + + void IAsyncLogEventSinkMonitor.StartMonitoring(IAsyncLogEventSinkInspector inspector) => + this.inspector = inspector; + + void IAsyncLogEventSinkMonitor.StopMonitoring(IAsyncLogEventSinkInspector inspector) => + System.Threading.Interlocked.CompareExchange(ref this.inspector, null, inspector); + } +} \ No newline at end of file From 2b56fe90dae338947725028ec2a12d5c07b489f1 Mon Sep 17 00:00:00 2001 From: Nicholas Blumhardt Date: Wed, 2 May 2018 18:42:08 +1000 Subject: [PATCH 21/23] Async typo [Skip CI] --- README.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/README.md b/README.md index 70a3b45..12b9210 100644 --- a/README.md +++ b/README.md @@ -2,7 +2,7 @@ An asynchronous wrapper for other [Serilog](https://serilog.net) sinks. Use this sink to reduce the overhead of logging calls by delegating work to a background thread. This is especially suited to non-batching sinks like the [File](https://github.com/serilog/serilog-sinks-file) and [RollingFile](https://github.com/serilog/serilog-sinks-rollingfile) sinks that may be affected by I/O bottlenecks. -**Note:** many of the network-based sinks (_CouchDB_, _Elasticsearch_, _MongoDB_, _Seq_, _Splunk_...) already perform asychronous batching natively and do not benefit from this wrapper. +**Note:** many of the network-based sinks (_CouchDB_, _Elasticsearch_, _MongoDB_, _Seq_, _Splunk_...) already perform asynchronous batching natively and do not benefit from this wrapper. ### Getting started From 90149395f266f4ba229bb40fabee335edd4aea8d Mon Sep 17 00:00:00 2001 From: Matthew Erbs Date: Wed, 9 May 2018 15:43:43 +1000 Subject: [PATCH 22/23] New NuGet API Key --- appveyor.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/appveyor.yml b/appveyor.yml index 4b2f3bd..0e93876 100644 --- a/appveyor.yml +++ b/appveyor.yml @@ -10,7 +10,7 @@ artifacts: deploy: - provider: NuGet api_key: - secure: nvZ/z+pMS91b3kG4DgfES5AcmwwGoBYQxr9kp4XiJHj25SAlgdIxFx++1N0lFH2x + secure: bd9z4P73oltOXudAjPehwp9iDKsPtC+HbgshOrSgoyQKr5xVK+bxJQngrDJkHdY8 skip_symbols: true on: branch: /^(master|dev)$/ From 0c6b675e6af87bd5cc717d9d94bd1787885165d3 Mon Sep 17 00:00:00 2001 From: Nicholas Blumhardt Date: Thu, 10 May 2018 08:10:20 +1000 Subject: [PATCH 23/23] $suffix build script fix --- Build.ps1 | 15 ++++++++++----- 1 file changed, 10 insertions(+), 5 deletions(-) diff --git a/Build.ps1 b/Build.ps1 index 4830b07..9b2d878 100644 --- a/Build.ps1 +++ b/Build.ps1 @@ -18,9 +18,14 @@ echo "build: Version suffix is $suffix" foreach ($src in ls src/*) { Push-Location $src - echo "build: Packaging project in $src" - - & dotnet pack -c Release -o ..\..\artifacts --version-suffix=$suffix --include-source + echo "build: Packaging project in $src" + + if ($suffix) { + & dotnet pack -c Release -o ..\..\artifacts --version-suffix=$suffix --include-source + } else { + & dotnet pack -c Release -o ..\..\artifacts --include-source + } + if($LASTEXITCODE -ne 0) { exit 1 } Pop-Location @@ -29,7 +34,7 @@ foreach ($src in ls src/*) { foreach ($test in ls test/*.PerformanceTests) { Push-Location $test - echo "build: Building performance test project in $test" + echo "build: Building performance test project in $test" & dotnet build -c Release if($LASTEXITCODE -ne 0) { exit 2 } @@ -40,7 +45,7 @@ foreach ($test in ls test/*.PerformanceTests) { 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 }