Serilog: Flush an ILogger

[invino4]

A few questions before you begin:

Does this issue relate to a new feature or an existing bug?

• [ ] Bug
• [x ] New Feature

What version of Serilog is affected? Please list the related NuGet package.
v2.6.0

What is the target framework and operating system? See target frameworks & net standard matrix.

• [x ] netCore 2.0
• [ ] netCore 1.0
• [ ] 4.7
• [ ] 4.6.x
• [ ] 4.5.x

Please describe the current behavior?
Any pending writes can only be flushed by effectively disposing the entire log pipeline (usually at the end of the app).

Please describe the expected behavior?
The ability to Flush pending writes in the sink pipeline and receive a notification (preferable using an Async pattern) once all pending writes have been written.

There are points in a program logic where it is desirable to know that log events prior to that point have been committed before proceeding. This would involve doing a Flush of some sort and waiting for the Flush to complete. Currently CloseAndFlush() or Dispose can only really be called at the end of the application because both effectively tear down the existing logging pipeline. It would be great if there was a way to Flush at an intermediary point.

Two suggestions on how one might think about this:

1. Add a Flush method to ILogger. This would flush the pipeline and resolve when all pending writes are written. Since of course new writes may be introduced concurrently, the Flush represents a partial order for concurrent events, but should obey temporal causality for events written before the flush.
2. Make ILogger IDisposable (instead of just Logger). Then sub-loggers could be created which when disposed would imply that all events written from that ILogger instances have been flushed. This provides a weaker order guarantee since it doesn't say anything about log events that were written by other ILogger instances before the dispose event, but lends itself to hierarchical structuring better. (Of course this could still be achieved with try {...} finally { logger.Flush()} for case (1).

Since Flush necessitates blocking for I/O (either disk or network or both) it seems reasonable that this should implement some kind of async pattern (while individual log calls are expected to be buffered and likely return immediately). Ideally this would use Task (or ValueTask now that it is available generally), but since Serilog doesn't currently incorporate any use of Task there might be better choices.

[nblumhardt]

Thanks for the suggestion!

In your particular scenario, would a successful flush imply success, or just best-effort? (I.e. if events had to be dropped because of a network failure, would Flush() throw exceptions?

[invino4]

I would think the contract needs to be stronger than "best effort" as there really should be an unrecoverable issue (e.g. network failure, buffer exhaustion) before a proper implementation would choose to drop events. Obviously different sinks would have to address what this means within the confines of their unique constraints. As an example, for disk based logging, I wouldn't expect Flush to fail because events were dropped due to insufficiently available disk space. But at the same time, I would consider a disk sink to be an improper implementation if it just dropped events in response to a Flush for no reason other than it was an easier way to implement Flush. :)

Perhaps Flush's result should indicate only progress but return an eventual boolean that indicates whether events might have been dropped. E.g.:

csharp Task<bool> Flush();

Where the result would never fail just because events were lost, but would return false. (It might fail for some other reason if Flush actually encounters a failure condition.)

Out of curiosity, what is the semantic for CloseAndFlush/Dispose today? Do network sinks drop events when they are called?

[nblumhardt]

Network sinks tend to buffer events for a set amount of time (say, 10 mins) during which they'll keep re-trying, before dropping events to prevent memory issues.

Is AuditTo a potential fit for what you're aiming to achieve?

[invino4]

AuditTo, if I understand it correctly, doesn't seem like quite the right fit. It has an implication on every event that is written to a sink. Flush doesn't imply anything about normal log action and has zero cost unless Flush is actually called. Flush is just a signal to the sinks that now is a good time to write any buffered writes (as opposed to whatever aggregation policy they normally apply).

Network sinks buffer, but when you are about to CloseAndFlush they know that the pipeline is going to end. Don't they have to force their pending writes then? What do they do if the network isn't available at that moment? Does CloseAndFlush block until the network comes back up?

[nblumhardt]

Thanks for the reply!

has zero cost unless Flush is actually called.

Not necessarily true for all sinks - there's a bit of synchronization that would be required for this I think (fair to assume that it's minor but nonzero)

What do they do if the network isn't available at that moment?

Fail and drop events, at the moment; blocking shutdown was considered, but could be a cause of production outages in some cases (we're upgrading an app, start shut-down, block at the last minute, and can't then get the new version of the app running.)

Auditing does have some more cost; it'd be interesting to know though whether your actual application scenario can be re-cast in a way where the critical events are audited instead of going through the regular pipeline. It's not a complete replacement for flushing, but when digging into specific situations (audit an event before calling an external credit card payment API, for example), then auditing often turns out to be the better solution.

Definitely can't rule out adding flush at some future point, but it (like auditing) would require ecosystem buy-in, so it's a long way off at best.

Just for interest's sake, if you can share any details of where you would need to insert the flush calls in your app, it would be great to have the data point.

Thanks again!

[MaxShoshin]

Nicholas,

I can share our use case where Flush method will be very usefull:

```c#
void RestartApp()
{
// Flush method instead Dispose will be very usefull here:
_logger.Dispose();

try
{
    // During this method our process can be killed without any chance to dispose logger.
    // In our scenario in most cases our application killed here, so we need to dispose
    // logger in code above to be sure that all events are flushed
    ExitImmediatleyOrThrowException(); 
}
catch(Exception ex)
{
    // But in some cases we got exception instead process kill:
    // we lost information about error as _logger already disposed
    _logger.Error(ex, "Error"); 
}

}
````

In our case we it will be ok if some sinks drop events during flush in case of some kind failures.

Thank you!

[invino4]

Nicholas,

Sorry for the late response on this (got busy with something else). So far I have run across two scenarios where Flush would have been useful:

1.) Assert failure implementation: Here we are following a fail-fast strategy such that Asserts lead basically to an Environment.Exit. Before exiting the process an attempt is made to flush the log buffers, snapshot the stack of the failing thread, etc. It would be great if this could Flush. The main thread typically is sitting on a using to Dispose, but it may be the thread asserting and we won't return up the stack from the Assert call. The asserting thread will be blocked so Flush would either have to be sync or async but not require the caller to run. If ILogger doesn't implement Flush or IDisposable the only access to Dispose is through a global static of the root of the pipeline (which we try to avoid - i.e. capability based model).

2.) Test framework: Here we create a logger in the suite and reuse it for each test method in the suite. It would be great to force a Flush in the test clean up method. This has two benefits: a.) it ensures that a crash from a subsequent test won't drop the log of a previous test thus confusing the investigation, and b.) for log output redirectors (like VSO's build/test automation) it ensures that when they capture and then tear the output per test method that they associate the right log entries with the right test method.

It the first case "best effort" in terms of losing events is the best we can ask for, but in the latter case I'd expect no events to be lost unless an unrecoverable failure occurs that should result in the test failing.

Hope that's useful.

Jason.

[nblumhardt]

Hey, thanks for the reply! Great data :+1:

1. Dispose() on Logger is a synchronous method and doesn't require the caller to run :+1: ... ILogger is not disposable, but if you check the return value of CreateLogger(), it's the concrete Logger type - you can e.g. register a delegate linked to its Dispose() method for close/flush purposes if you're using IoC and not setting up the global Log class.

2. In tests, logger mocks usually run synchronously, so there's no need to flush; i.e. I usually (when I can't avoid it, or if I'm testing logging infrastructure), have an ILogger or ILogEventSink set up that adds LogEvents to a synchronized collection somewhere. If you have to use a non-local logger for tests, you can also try AuditTo, which logs synchronously and requires no flushing - File() and Seq() are the two sinks that have been updated to support it currently, but more can be added.

Hope this helps,
Nick

[StefanBertels]

I would appreciate some (global) Flush() method, too.

Similar use case as @MaxShoshin (make sure things are flushed before eventually crashing / unclean shutdown).

Maybe some minimal / straight forward Flush implemention could behave similar to Dispose() regarding delivery guarantees or synchronisation.

[mbp]

This is also a wanted feature for us. E.g. when using Serilog in an ASP.NET Core application, we would like to log any errors on application shutdown, but since some of our sinks are periodic or buffered, we might loose messages. We can obviously call CloseAndFlush() in IApplicationLifetime.ApplicationStopped, but we will not be able to get the One or more hosted services failed to stop log: https://github.com/aspnet/Hosting/blob/f9d145887773e0c650e66165e0c61886153bcc0b/src/Microsoft.Extensions.Hosting/Internal/Host.cs#L92

[tippmar]

CloseAndFlush() works just fine for the ASP.NET Core app I'm working on. I've found, however, that I have to Sleep(2000) or so before the app terminates so that all the sinks can do their business.

    public static int Main(string[] args)
    {
        ConfigureLogging(); // set up Serilog

        try
        {
            Log.Logger.Information("Custom.API Server is starting.");
            var webHost = BuildWebHost(args);
            webHost.Run();

            Log.Logger.Information("Custom.API Server is starting.");
            return 0;
        }
        catch (Exception ex)
        {
            Log.Fatal(ex, "Host terminated unexpectedly.");
            return 1;
        }
        finally
        {
            Log.CloseAndFlush();
            Thread.Sleep(2000); // give serilog / seq time to flush the messages
        }
    }

`

[nblumhardt]

@tippmar it looks like something could be wrong with the way the logger is being configured, here (or we have some tricky bug in the works) - there should never be a need to sleep after calling CloseAndFlush(). Is it possible to raise a new ticket showing some more code from the app? Thanks!

[nblumhardt]

Folks, looking at this some more, I think it's unlikely there will be an implementation of this in Serilog in the near future (although I can see it makes the ergonomics of some scenarios better, it's a deep change that would need some really compelling scenarios to justify the work and ecosystem churn).

If anyone's keen, I have an idea how this could be implemented as an extension package on top of the Serilog we have today. It'd take a little work to figure out the API, but would end up something like:

// Note we're handed a `LoggerConfiguration`; this may be called multiple times
var flushable = new FlushableLogger(c => c
  .WriteTo.Console()
  .WriteTo.Seq(":-)"));

Log.Logger = flushable;

// Callable any time:
flusable.Flush();

// Once we're completely done:
Log.CloseAndFlush();

Internally, FlushableLogger.Flush() would tear down the logging pipeline (to flush it), and then replace the pipeline with a completely new one created by calling the delegate again.

From the application side, there would be a small performance and synchronization overhead (the cost of the call delegation - tiny - and the cost of a ReaderWriterLockSlim.EnterReadLock() - also small - for each log event). It's unlikely any native Serilog implementation could implement this any faster.

The Flush() call would be expected to have very low overhead apart from the cost of the actual flushing.

Any takers? 😎

[MuruIOT]

We are using Serilog in .NET core 2 based projects and we see that there are memory leaks, while we do the performance testing of our WebAPI services. Flushable logger could be a good approach to solve the memory issues. We could flush the memory at the end of each request. Can you put a sample code to do the flushable logger? I am not clear on how we can get the handle on logging pipe line?. Do you suggest to create logger object for each and every disposal of Controller object?

[nblumhardt]

Hi @MuruIOT - it sounds like something else is going on, in your case. Are you using a single, shared logger? Ideally, your app will only create a single LoggerConfiguration and call CreateLogger() just once - creating a whole logging pipeline per request (my guess here) usually results in a variety of unwanted perf impacts (depending on the sinks you're using). HTH!

[MuruIOT]

Hi,

Thanks for your mail.

Currently i am having only one Static loggerconfiguration. But there are
multiple nonstatic forContext logger for each request. I assume that could
be a problem.

I need to know how can i flush all the logger object and its content per
request.

Your thoughts please

On Thu, Feb 14, 2019, 06:54 Nicholas Blumhardt <[email protected]
wrote:

Hi @MuruIOT https://github.com/MuruIOT - it sounds like something else
is going on, in your case. Are you using a single, shared logger? Ideally,
your app will only create a single LoggerConfiguration and call
CreateLogger() just once - creating a whole logging pipeline per request
(my guess here) usually results in a variety of unwanted perf impacts
(depending on the sinks you're using). HTH!

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/serilog/serilog/issues/1111#issuecomment-463446670,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AtY8ZTfqONE8_dUJQ2xT2fMVFiSB4Yldks5vNLrTgaJpZM4SMkDS
.

[nblumhardt]

@MuruIOT still seems like something else is going on; opening a new ticket, or posting to Stack Overflow, with the details below, should get some movement on it:

• Your logger configuration, including how it's wired up to your controllers/IoC, which sinks you're using, etc
• Details of why you think the memory issue is Serilog-related, and why you think flushing will be the answer
• Any other interesting data you've collected in your troubleshooting so far

HTH,
Nick

[nblumhardt]

Folks, I think this should be closed simply because it won't move forward in the immediate future; I'm keen to try sketching out FlushableLogger if anyone is interested in helping to make that happen. If that's you, please drop me a line on this (closed) ticket and I'll share what info/suggestions I can. It should be a fairly short piece of code, but will still require some careful coding.