Serilog does not automatically flush batched output sinks when disposed (and has no manual method for doing so)

[mqudsi]

Description

When using Serilog (in conjunction with an asynchronous logging sink or a batched logging sink) in client-side applications that may terminate at any time due to an unhandled exception (vs in server-side applications where it is expected that requests are failed but the "app" remains running), Serilog currently exits without informing the sink that it should flush its pipeline of batched/deferred log messages.

Ironically, these are probably the most important log events but they are excluded from the log in this manner.

Reproduction

I've reproduced this various batching sinks, most recently with the AWS Cloudwatch sink. The relevant issue in that repo is here where the author reports that this is an upstream serilog problem that affects all batching sinks.

1. Use Serilog with a batching sink like Seq or AWS Cloudwatch
2. Ensure the configured sink batch count is sufficiently high and the periodic interval is sufficiently long enough for lone events (at your current logging rate) not to be immediately posted to the backend.
3. Ensure that Log.CloseAndFlush() is called on normal/abnormal exit
4. Generate a log event then immediately trigger an exit (that triggers the exit handler that disposes the Serilog instance)
5. Observe that the most recent log messages that were in the batched pipeline are not written to the destination.

A very contrived version of this can be seen in the following:

var logger = new LoggerConfiguration()
    .MinimumLevel.Verbose()
    .WriteTo.AmazonCloudWatch(..)
    .CreateLogger();
logger.Information("Generating a test log event");
logger.Dispose(); // or await logger.DisposeAsync();
Environment.Exit(0);

Expected behavior
A call to Serilog.Dispose() (or Log.CloseAndFlush()) should trigger a flush of the queued log events to the final destination in asynchronous or batched sinks.

Additionally, there should be a way to explicitly flush all serilog sinks without disposing and resetting the logger - i.e. in the event of a critical but non-fatal error, there should be the option of doing something along the lines of await Log.FlushAsync() that will trigger a clearing of any queued log events in the sinks but without resetting the associated log allowing continued use of all configured log entrypoints.

Relevant package, tooling and runtime versions
Serilog 4.2.0 under .NET 9

[nblumhardt]

Hi!

Serilog's built-in IBatchedLogEventSink support does support this functionality, and includes test suite entries that cover it.

Although Serilog.Sinks.AwsCloudWatch is uses recent APIs, it has dependencies on old versions of the packages involved (probably to maximise backwards compatibility). NuGet's default package installation algorithm resolves dependencies to the minimum, rather than maximum, version that can support the other packages in your solution.

To make sure your app actually uses the latest functionality, your best bets are:

• Add an explicit reference to version 5.0.0 of Serilog.Sinks.PeriodicBatching, or
• Update Serilog.Sinks.AwsCloudWatch to remove the Serilog.Sinks.PeriodicBatching dependency, using the built-in Serilog package's batching features directly.

Hope this helps,

Nick

[mqudsi]

Hey Nick, thanks so much for this package and for taking the time to respond.

Your explanation makes sense and I'm adding Serilog.Sinks.PeriodicBatching as a top-level dependency so I can specifically install the latest version, but I still have a question about how to actually use the PeriodicBatchingSink.EmitAsync() from the consumer-side of things.

I'm assuming that what left unsaid in your response is that a call to logger.Dispose() will automatically emit the batched log events after upgrading to PeriodicBatching 5.x?

Do you mind clarifying when/where the call to EmitAsync() is being made? CloudWatchLogSink instantiates a PeriodicBatchingSink with an inner PeriodicBatchingSinkImplementationCallback implementing IBatchedLogEventSink, but neither PeriodicBatchingSink doesn't call EmitBatch()/EmitBatchAsync() in its Dispose() implementation and the other nuget's PeriodicBatchingSinkImplementationCallback isn't even disposable. I see that a DisposingAggregateSink gets created from the CreateSink call, but that's not aware of IBatchedLogEventSink (so far as I can tell).

Separately, as the PeriodicBatchingSink instance is private (via composition) to CloudWatchLogSink (and CloudWatchLogSink doesn't implement IBatchedLogEventSink itself), I think the other part of my question about flushing all sinks without disposing the logger is still not possible? Even if/when CloudWatchLogSink skips the intermediary PeriodicBatching crate and directly using the batching APIs in newer serilog versions, Serilog doesn't really provide access to a logger instance's sinks (because they're treated as immutable) so there's no convenient way to call EmitBatchAsync() externally without bypassing the easy-to-use static LoggerConfiguration extension methods and creating your own instance of XxxSink then storing it somewhere so you can manually call EmitBatchAsync() (or its native serilog alternative?) when and where needed?

I really appreciate your help and patience, sorry for asking all these questions but despite using Serilog for probably over a decade this is the first time I've had to dive into its internals.

[nblumhardt]

Thanks for your reply, Mahmoud.

Just to answer your second question, which I skipped earlier - there's no API for manually flushing a batched sink in Serilog, as things stand. It's been considered a few times in the past but hasn't seemed worth the added complexity, for the scenarios it would cover.

The latest Serilog.Sinks.PeriodicBatching package is a fairly complex compatibility shim to keep the ecosystem working, but there's probably not much point digging into its internals here. For a maintained sink like the CloudWatch one, switching over to use the newer Serilog functionality directly will be a better bet for the long haul.

The new batching sink is this one:

https://github.com/serilog/serilog/blob/dev/src/Serilog/Core/Sinks/Batching/BatchingSink.cs

Its dispose methods signal to the background task that shutdown is required, and then wait on the background task to complete:

https://github.com/serilog/serilog/blob/dev/src/Serilog/Core/Sinks/Batching/BatchingSink.cs#L263

The task itself, after observing cancellation, works its way through the remainder of the queue:

https://github.com/serilog/serilog/blob/dev/src/Serilog/Core/Sinks/Batching/BatchingSink.cs#L169