Merge pull request #157 from nblumhardt/buffered-durable-writes

More robust event formatting when writing to durable sink buffer files

global.json

@@ -1,6 +1,6 @@
 {
   "sdk": {
-    "version": "5.0.202",
-    "rollForward": "latestPatch"
+    "version": "5.0.401",
+    "rollForward": "latestFeature"
   }
 }

sample/Sample/Program.cs

@@ -5,7 +5,7 @@
 
 namespace Sample
 {
-    public class Program
+    public static class Program
     {
         public static void Main()
         {

sample/Sample/Sample.csproj

@@ -3,7 +3,7 @@
   <PropertyGroup>
     <Description>Sample Console Application</Description>
     <Authors>nblumhardt</Authors>
-    <TargetFrameworks>netcoreapp3.1;net47</TargetFrameworks>
+    <TargetFrameworks>net4.8;net5.0</TargetFrameworks>
     <AssemblyName>Sample</AssemblyName>
     <OutputType>Exe</OutputType>
     <PackageId>Sample</PackageId>
@@ -20,16 +20,12 @@
     <PackageReference Include="Serilog.Sinks.Console" Version="3.1.0" />
   </ItemGroup>
 
-  <ItemGroup Condition=" '$(TargetFramework)' == 'net47' ">
+  <ItemGroup Condition=" '$(TargetFramework)' == 'net4.8' ">
     <Reference Include="System.Net.Http" />
   </ItemGroup>
 
   <ItemGroup>
     <ProjectReference Include="..\..\src\Serilog.Sinks.Seq\Serilog.Sinks.Seq.csproj" />
   </ItemGroup>
 
-  <ItemGroup>
-    <Folder Include="logs\" />
-  </ItemGroup>
-
 </Project>

serilog-sinks-seq.sln.DotSettings

@@ -1,4 +1,5 @@
 <wpf:ResourceDictionary xml:space="preserve" xmlns:x="http://schemas.microsoft.com/winfx/2006/xaml" xmlns:s="clr-namespace:System;assembly=mscorlib" xmlns:ss="urn:shemas-jetbrains-com:settings-storage-xaml" xmlns:wpf="http://schemas.microsoft.com/winfx/2006/xaml/presentation">
+	<s:Boolean x:Key="/Default/UserDictionary/Words/=aaaaa/@EntryIndexedValue">True</s:Boolean>
 	<s:Boolean x:Key="/Default/UserDictionary/Words/=Backoff/@EntryIndexedValue">True</s:Boolean>
 	<s:Boolean x:Key="/Default/UserDictionary/Words/=delim/@EntryIndexedValue">True</s:Boolean>
 	<s:Boolean x:Key="/Default/UserDictionary/Words/=fdelim/@EntryIndexedValue">True</s:Boolean>

src/Serilog.Sinks.Seq/Serilog.Sinks.Seq.csproj

@@ -5,7 +5,7 @@
     <VersionPrefix>5.0.2</VersionPrefix>
     <Authors>Serilog Contributors</Authors>
     <Copyright>Copyright © Serilog Contributors</Copyright>
-    <TargetFrameworks>netstandard1.1;netstandard1.3;net45;netstandard2.0;netcoreapp3.1;net5.0</TargetFrameworks>
+    <TargetFrameworks>netstandard1.1;netstandard1.3;netstandard2.0;net4.5;netcoreapp3.1;net5.0</TargetFrameworks>
     <TreatWarningsAsErrors>true</TreatWarningsAsErrors>
     <GenerateDocumentationFile>true</GenerateDocumentationFile>
     <RootNamespace>Serilog</RootNamespace>
@@ -38,11 +38,11 @@
     <DefineConstants>$(DefineConstants);DURABLE;THREADING_TIMER</DefineConstants>
   </PropertyGroup>
 
-  <PropertyGroup Condition=" '$(TargetFramework)' == 'net45' ">
+  <PropertyGroup Condition=" '$(TargetFramework)' == 'net4.5' ">
     <DefineConstants>$(DefineConstants);DURABLE;THREADING_TIMER;HRESULTS</DefineConstants>
   </PropertyGroup>
 
-  <ItemGroup Condition=" '$(TargetFramework)' == 'net45' ">
+  <ItemGroup Condition=" '$(TargetFramework)' == 'net4.5' ">
     <Reference Include="System.Net.Http" />
   </ItemGroup>
 

src/Serilog.Sinks.Seq/Sinks/Seq/Audit/SeqAuditSink.cs

@@ -59,7 +59,6 @@ async Task EmitAsync(LogEvent logEvent)
 
             var payload = new StringWriter();
             CompactJsonFormatter.FormatEvent(logEvent, payload, JsonValueFormatter);
-            payload.WriteLine();
 
             var content = new StringContent(payload.ToString(), Encoding.UTF8, SeqApi.CompactLogEventFormatMimeType);
             if (!string.IsNullOrWhiteSpace(_apiKey))

src/Serilog.Sinks.Seq/Sinks/Seq/ConstrainedBufferedFormatter.cs

@@ -0,0 +1,125 @@
+// Serilog.Sinks.Seq Copyright 2014-2019 Serilog Contributors
+// 
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+// 
+//     http://www.apache.org/licenses/LICENSE-2.0
+// 
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+using System;
+using System.IO;
+using System.Text;
+using Serilog.Debugging;
+using Serilog.Events;
+using Serilog.Formatting;
+using Serilog.Formatting.Compact;
+using Serilog.Formatting.Json;
+using Serilog.Parsing;
+
+namespace Serilog.Sinks.Seq
+{
+    /// <summary>
+    /// Wraps a <see cref="CompactJsonFormatter" /> to suppress formatting errors and apply the event body size
+    /// limit, if any. Placeholder events are logged when an event is unable to be written itself.
+    /// </summary>
+    class ConstrainedBufferedFormatter : ITextFormatter
+    {
+        static readonly int NewLineByteCount = Encoding.UTF8.GetByteCount(Environment.NewLine);
+
+        readonly long? _eventBodyLimitBytes;
+        readonly CompactJsonFormatter _jsonFormatter = new CompactJsonFormatter(new JsonValueFormatter("$type"));
+
+        public ConstrainedBufferedFormatter(long? eventBodyLimitBytes)
+        {
+            _eventBodyLimitBytes = eventBodyLimitBytes;
+        }
+
+        public void Format(LogEvent logEvent, TextWriter output)
+        {
+            Format(logEvent, output, writePlaceholders: true);
+        }
+
+        void Format(LogEvent logEvent, TextWriter output, bool writePlaceholders)
+        {
+            var buffer = new StringWriter();
+
+            try
+            {
+                _jsonFormatter.Format(logEvent, buffer);
+            }
+            catch (Exception ex) when (writePlaceholders)
+            {
+                SelfLog.WriteLine(
+                    "Event with message template {0} at {1} could not be formatted as JSON and will be dropped: {2}",
+                    logEvent.MessageTemplate.Text, logEvent.Timestamp, ex);
+
+                var placeholder = CreateNonFormattableEventPlaceholder(logEvent, ex);
+                Format(placeholder, output, writePlaceholders: false);
+                return;
+            }
+
+            var jsonLine = buffer.ToString();
+            if (CheckEventBodySize(jsonLine, _eventBodyLimitBytes))
+            {
+                output.Write(jsonLine);
+            }
+            else
+            {
+                SelfLog.WriteLine(
+                    "Event JSON representation exceeds the byte size limit of {0} set for this Seq sink and will be dropped; data: {1}",
+                    _eventBodyLimitBytes, jsonLine);
+
+                if (writePlaceholders)
+                {
+                    var placeholder = CreateOversizeEventPlaceholder(logEvent, jsonLine, _eventBodyLimitBytes!.Value);
+                    Format(placeholder, output, writePlaceholders: false);
+                }
+            }
+        }
+
+        static LogEvent CreateNonFormattableEventPlaceholder(LogEvent logEvent, Exception ex)
+        {
+            return new LogEvent(
+                logEvent.Timestamp,
+                LogEventLevel.Error,
+                ex,
+                new MessageTemplateParser().Parse("Event with message template {OriginalMessageTemplate} could not be formatted as JSON"),
+                new[]
+                {
+                    new LogEventProperty("OriginalMessageTemplate", new ScalarValue(logEvent.MessageTemplate.Text)),
+                });
+        }
+
+        static bool CheckEventBodySize(string jsonLine, long? eventBodyLimitBytes)
+        {
+            if (eventBodyLimitBytes == null)
+                return true;
+
+            var byteCount = Encoding.UTF8.GetByteCount(jsonLine) - NewLineByteCount;
+            return byteCount <= eventBodyLimitBytes;
+        }
+
+        static LogEvent CreateOversizeEventPlaceholder(LogEvent logEvent, string jsonLine, long eventBodyLimitBytes)
+        {
+            // If the limit is so constrained as to disallow sending 512 bytes + packaging, that's okay - we'll just drop
+            // the placeholder, too.
+            var sample = jsonLine.Substring(0, Math.Min(jsonLine.Length, 512));
+            return new LogEvent(
+                logEvent.Timestamp,
+                LogEventLevel.Error,
+                exception: null,
+                new MessageTemplateParser().Parse("Event JSON representation exceeds the body size limit {EventBodyLimitBytes}; sample: {EventBodySample}"),
+                new[]
+                {
+                    new LogEventProperty("EventBodyLimitBytes", new ScalarValue(eventBodyLimitBytes)),
+                    new LogEventProperty("EventBodySample", new ScalarValue(sample)),
+                });
+        }
+    }
+}

src/Serilog.Sinks.Seq/Sinks/Seq/Durable/DurableSeqSink.cs

@@ -19,7 +19,6 @@
 using Serilog.Events;
 using System.Net.Http;
 using System.Text;
-using Serilog.Formatting.Compact;
 
 namespace Serilog.Sinks.Seq.Durable
 {
@@ -60,7 +59,7 @@ public DurableSeqSink(
             const long individualFileSizeLimitBytes = 100L * 1024 * 1024;
             _sink = new LoggerConfiguration()
                 .MinimumLevel.Verbose()
-                .WriteTo.File(new CompactJsonFormatter(),
+                .WriteTo.File(new ConstrainedBufferedFormatter(eventBodyLimitBytes),
                         fileSet.RollingFilePathFormat,
                         rollingInterval: RollingInterval.Day,
                         fileSizeLimitBytes: individualFileSizeLimitBytes,

src/Serilog.Sinks.Seq/Sinks/Seq/SeqSink.cs

@@ -14,6 +14,7 @@
 
 using System;
 using System.Collections.Generic;
+using System.IO;
 using System.Linq;
 using System.Net.Http;
 using System.Text;
@@ -33,7 +34,7 @@ class SeqSink : IBatchedLogEventSink, IDisposable
         static readonly TimeSpan RequiredLevelCheckInterval = TimeSpan.FromMinutes(2);
 
         readonly string _apiKey;
-        readonly long? _eventBodyLimitBytes;
+        readonly ConstrainedBufferedFormatter _formatter;
         readonly HttpClient _httpClient;
 
         DateTime _nextRequiredLevelCheckUtc = DateTime.UtcNow.Add(RequiredLevelCheckInterval);
@@ -49,9 +50,9 @@ public SeqSink(
             if (serverUrl == null) throw new ArgumentNullException(nameof(serverUrl));
             _controlledSwitch = controlledSwitch ?? throw new ArgumentNullException(nameof(controlledSwitch));
             _apiKey = apiKey;
-            _eventBodyLimitBytes = eventBodyLimitBytes;
             _httpClient = messageHandler != null ? new HttpClient(messageHandler) : new HttpClient();
             _httpClient.BaseAddress = new Uri(SeqApi.NormalizeServerBaseAddress(serverUrl));
+            _formatter = new ConstrainedBufferedFormatter(eventBodyLimitBytes);
         }
 
         public void Dispose()
@@ -74,10 +75,13 @@ public async Task EmitBatchAsync(IEnumerable<LogEvent> events)
         {
             _nextRequiredLevelCheckUtc = DateTime.UtcNow.Add(RequiredLevelCheckInterval);
 
-            var payloadContentType = SeqApi.CompactLogEventFormatMimeType;
-            var payload = SeqPayloadFormatter.FormatCompactPayload(events, _eventBodyLimitBytes);
+            var payload = new StringWriter();
+            foreach (var evt in events)
+            {
+                _formatter.Format(evt, payload);
+            }
 
-            var content = new StringContent(payload, Encoding.UTF8, payloadContentType);
+            var content = new StringContent(payload.ToString(), Encoding.UTF8, SeqApi.CompactLogEventFormatMimeType);
             if (!string.IsNullOrWhiteSpace(_apiKey))
                 content.Headers.Add(SeqApi.ApiKeyHeaderName, _apiKey);
 

test/Serilog.Sinks.Seq.Tests/Audit/SeqAuditSinkTests.cs

@@ -20,7 +20,7 @@ public void EarlyCommunicationErrorsPropagateToCallerWhenAuditing()
             }
         }
 
-        [Fact]
+        [Fact] // This test requires an outbound connection in order to execute properly.
         public void RemoteCommunicationErrorsPropagateToCallerWhenAuditing()
         {
             using (var logger = new LoggerConfiguration()