Merge pull request #31 from serilog/dev

1.2.0 Release

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

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
+    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 }

README.md

@@ -1,8 +1,8 @@
 # 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.
 
-**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
 
@@ -12,36 +12,94 @@ 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()
-    
+
 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();
 ```
 
-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.
 
-### 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. 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)
+```
+
+### Health Monitoring via the Monitor and Inspector interfaces
 
-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 `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 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
-    // Reduce the buffer to 500 events
-    .WriteTo.Async(a => a.RollingFile("logs/myapp-{Date}.txt"), 500)
+// 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
+
+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 awaiting ingestion by the pipeline
+.WriteTo.Async(a => a.File("logs/myapp.log"), blockWhenFull: true)
 ```
 
 ### XML `<appSettings>` 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": "Console"
+        }]
+      }
+    }]
+  }
+}
+```
+
+XML configuration support has not yet been added for this wrapper.
 
 ### About this sink
 

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
@@ -16,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)$/

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,42 +11,41 @@ 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
 		Debug|Any CPU = Debug|Any CPU
 		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

src/Serilog.Sinks.Async/LoggerConfigurationAsyncExtensions.cs

@@ -1,6 +1,6 @@
 using System;
+using System.ComponentModel;
 using Serilog.Configuration;
-using Serilog.Events;
 using Serilog.Sinks.Async;
 
 namespace Serilog
@@ -19,19 +19,59 @@ public static class LoggerConfigurationAsyncExtensions
         /// 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.</param>
         /// <returns>A <see cref="LoggerConfiguration"/> allowing configuration to continue.</returns>
+        [EditorBrowsable(EditorBrowsableState.Never)]
         public static LoggerConfiguration Async(
             this LoggerSinkConfiguration loggerSinkConfiguration,
             Action<LoggerSinkConfiguration> configure,
-            int bufferSize = 10000)
+            int bufferSize)
         {
-            var sublogger = new LoggerConfiguration();
-            sublogger.MinimumLevel.Is(LevelAlias.Minimum);
-
-            configure(sublogger.WriteTo);
+            return loggerSinkConfiguration.Async(configure, bufferSize, false);
+        }
 
-            var wrapper = new BackgroundWorkerSink(sublogger.CreateLogger(), bufferSize);
+        /// <summary>
+        /// Configure a sink to be invoked asynchronously, on a background worker thread.
+        /// </summary>
+        /// <param name="loggerSinkConfiguration">The <see cref="LoggerSinkConfiguration"/> being configured.</param>
+        /// <param name="configure">An action that configures the wrapped sink.</param>
+        /// <param name="bufferSize">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
+        /// <paramref name="blockWhenFull"/> the queue will block or subsequent events will be dropped until
+        /// room is made in the queue.</param>
+        /// <param name="blockWhenFull">Block when the queue is full, instead of dropping events.</param>
+        /// <returns>A <see cref="LoggerConfiguration"/> allowing configuration to continue.</returns>
+        public static LoggerConfiguration Async(
+            this LoggerSinkConfiguration loggerSinkConfiguration,
+            Action<LoggerSinkConfiguration> configure,
+            int bufferSize = 10000,
+            bool blockWhenFull = false)
+        {
+            return loggerSinkConfiguration.Async(configure, null, bufferSize, blockWhenFull);
+        }
 
-            return loggerSinkConfiguration.Sink(wrapper);
+        /// <summary>
+        /// Configure a sink to be invoked asynchronously, on a background worker thread.
+        /// Accepts a reference to a <paramref name="monitor"/> that will be supplied the internal state interface for health monitoring purposes.
+        /// </summary>
+        /// <param name="loggerSinkConfiguration">The <see cref="LoggerSinkConfiguration"/> being configured.</param>
+        /// <param name="configure">An action that configures the wrapped sink.</param>
+        /// <param name="bufferSize">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
+        /// <paramref name="blockWhenFull"/> the queue will block or subsequent events will be dropped until
+        /// room is made in the queue.</param>
+        /// <param name="blockWhenFull">Block when the queue is full, instead of dropping events.</param>
+        /// <param name="monitor">Monitor to supply buffer information to.</param>
+        /// <returns>A <see cref="LoggerConfiguration"/> allowing configuration to continue.</returns>
+        public static LoggerConfiguration Async(
+            this LoggerSinkConfiguration loggerSinkConfiguration,
+            Action<LoggerSinkConfiguration> configure,
+            IAsyncLogEventSinkMonitor monitor,
+            int bufferSize = 10000,
+            bool blockWhenFull = false)
+        {
+            return LoggerSinkConfiguration.Wrap(
+                loggerSinkConfiguration,
+                wrappedSink => new BackgroundWorkerSink(wrappedSink, bufferSize, blockWhenFull, monitor),
+                configure);
         }
     }
-}
+}

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" +