Log file being re-opened every 30 minutes when rolling by size

[cocowalla]

An issue in serilog-sinks-file-header suggested something wrong with handling of the OnFileOpened hook, as the header was being written precisely every 30 minutes. I've been able to reproduce this by using a configuration where files are rolled by size and not time, e.g.:

Log.Logger = new LoggerConfiguration()
    .WriteTo.File(@"reproduce.log",
        fileSizeLimitBytes: 1048576,
        rollOnFileSizeLimit: true,
        outputTemplate: "{Timestamp:dd/MM/yyyy HH:mm:ss.fff} {Level:u3} [{ThreadId} {ThreadName}] {Message:lj}{NewLine}{Exception}")
    .CreateLogger();

So, after every log is written by RollingFileSink.Emit(), it calls into AlignCurrentFileTo(), which in turn calls into OpenFile(), where we see:

 // We only try periodically because repeated failures
// to open log files REALLY slow an app down.
_nextCheckpoint = _roller.GetNextCheckpoint(now) ?? now.AddMinutes(30);

This is the source of the 30-minute oddity.

@nblumhardt Unless I'm missing something (very possible 😄), we can fix this in RollingFileSink.Emit():

...
// Current code
var now = Clock.DateTimeNow;
AlignCurrentFileTo(now);
...
// Proposed code
if (_retainedFileTimeLimit.HasValue)
{
    var now = Clock.DateTimeNow;
    AlignCurrentFileTo(now);
}

[nblumhardt]

Hmm interesting! I need to take a closer look; at first glance, it seems like the proposed fix would prevent rolling on date/time from being correctly performed, where we roll but don't set a time limit? 🤔

[nblumhardt]

May be one to close as stale @cocowalla ?

[cocowalla]

Closing as stale; haven't had any time to delve further into this.