Using Serilog format specifier for ints makes buffer file invalid

[DavidLievrouw]

Symptom

I accidentally used an invalid Serilog format specifier in a message template. Although it was my mistake, it kind of had severe consequences.

No logs of this application ever arrive in Seq when using durable log shipping. It works fine when setting bufferBaseFilename to null.

Cause

When using the :l format specifier, and passing an int as property value, the durable buffer file is corrupted. It contains invalid json. This causes the HttpLogShipper to receive 500 response from Seq.

Even after fixing the incorrect format specifier, the logs never arrived in Seq. I needed to delete the buffer file, causing loss of log entries.

Replay

using System;
using Serilog;
using Serilog.Events;

namespace ConsoleApp1
{
    class Program
    {
        static void Main(string[] args)
        {
            var loggerConfiguration = new LoggerConfiguration()
                .MinimumLevel.Verbose()
                .Enrich.WithProperty("Application", "ConsoleApp1", destructureObjects: false)
                .WriteTo.Seq(
                    restrictedToMinimumLevel: LogEventLevel.Debug,
                    serverUrl: "http://localhost:5341",
                    bufferBaseFilename: Environment.ExpandEnvironmentVariables("%ALLUSERSPROFILE%\\ConsoleApp1")
                );

            Log.Logger = loggerConfiguration.CreateLogger();
            
            Log.Logger.Information("I will be logged with a string argument {0:l}.", "abc");
            Log.Logger.Information("I will corrupt the buffer file {0:l}.", 123); // Notice it's an int, not a string
            Log.Logger.Information("This will never be logged. HttpLogShipper receives 500.");
            
            Log.CloseAndFlush();
        }
    }
}

Causes the following text in the buffer file (notice that it's invalid json):

{"@t":"2021-10-25T12:22:38.0452847Z","@mt":"I will be logged with a string argument {0:l}.","@r":["abc"],"0":"abc","Application":"ConsoleApp1"}
{"@t":"2021-10-25T12:22:38.1094993Z","@mt":"I will corrupt the buffer file {0:l}.","@r":[{"@t":"2021-10-25T12:22:38.1141918Z","@mt":"This will never be logged. HttpLogShipper receives 500.","Application":"ConsoleApp1"}

And the Seq server-side error:

[12:19:40 ERR] HTTP "POST" "/api/events/raw" responded 500 in 5.7451 ms
System.InvalidCastException: Cannot cast Newtonsoft.Json.Linq.JObject to Newtonsoft.Json.Linq.JToken.
   at Newtonsoft.Json.Linq.Extensions.Convert[T,U](T token)
   at Seq.Server.Storage.StorageEventNormalizer.<>c.<FromClefFormat>b__3_1(PropertyToken p, JToken j)
   at System.Linq.Enumerable.ZipIterator[TFirst,TSecond,TResult](IEnumerable`1 first, IEnumerable`1 second, Func`3 resultSelector)+MoveNext()
   at System.Linq.Lookup`2.Create(IEnumerable`1 source, Func`2 keySelector, IEqualityComparer`1 comparer)
   at System.Linq.GroupedEnumerable`2.GetEnumerator()
   at System.Linq.Enumerable.ToDictionary[TSource,TKey,TElement](IEnumerable`1 source, Func`2 keySelector, Func`2 elementSelector, IEqualityComparer`1 comparer)
   at Seq.Server.Storage.StorageEventNormalizer.FromClefFormat(Int32 lineNumber, Object evt, InputSettings inputSettings, StorageEventCreationData& creationData, String& error)
   at Seq.Server.Web.Api.IngestionController.TryParseClefBody(Input input, InputSettings inputSettings, StorageEventCreationData[]& events, String& errorMessage)
   at Seq.Server.Web.Api.IngestionController.TryParseBody(Input input, InputSettings inputSettings, StorageEventCreationData[]& events, String& errorMessage)
   at Seq.Server.Web.Api.IngestionController.Ingest()
   at lambda_method532(Closure , Object , Object[] )
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.SyncActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeActionMethodAsync()
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeNextActionFilterAsync()
--- End of stack trace from previous location ---
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync()
--- End of stack trace from previous location ---
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextResourceFilter>g__Awaited|24_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Rethrow(ResourceExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeFilterPipelineAsync()
--- End of stack trace from previous location ---
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Awaited|17_0(ResourceInvoker invoker, Task task, IDisposable scope)
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Seq.Server.Web.Middleware.WebSocketAcceptMiddleware.Invoke(HttpContext context)
   at Seq.Server.Web.Middleware.RequestAuthenticationMiddleware.Invoke(HttpContext httpContext)
   at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
   at Seq.Server.Web.Middleware.ServerStatusMiddleware.Invoke(HttpContext context)
   at Seq.Server.Web.Middleware.BrowserSecurityOptionsMiddleware.Invoke(HttpContext context)
   at Seq.Server.Web.Middleware.RequestCompletionMiddleware.Invoke(HttpContext httpContext)

Expected behaviour

• The invalid use of a format specifier should not corrupt the buffer file.
• Even when this occurs, I would prefer to continue logging the entries that actually do work, ignoring the invalid entry (maybe warn to the console or something).

Imho, making such a trivial mistake in a message template, should not make all logging to Seq fail (until you delete the buffer file).

Any pointers to where to start looking, would be nice.

[nblumhardt]

Thanks for the report! The default (non-durable) sink already handles this situation; I think it makes sense now to carry this across to the durable option.

We might also start recording dropped events to the stream itself, so that the situation is easier to detect on the Seq side 👍

[nblumhardt]

Fixed now in 5.0.2-dev-00203 on NuGet; will queue up a stable/main build once we're happy we haven't broken anything :-)

[nblumhardt]

Hi @DavidLievrouw - did you have a chance to check out the fixed build? Thanks!

[DavidLievrouw]

Yes, it works with 5.0.2-dev-00203. For the above replay-scenario, the output is:

And more importantly, the entries that are logged after the erroneous message, arrive in Seq correctly.

Thank you for your assistance.

[nblumhardt]

Awesome, thanks for the follow-up, David.