Fix issue with force-reopen after 30 minutes

src/Serilog.Sinks.File/Sinks/File/FileSink.cs

@@ -91,8 +91,16 @@ internal FileSink(
 
         if (hooks != null)
         {
-            outputStream = hooks.OnFileOpened(path, outputStream, encoding) ??
-                           throw new InvalidOperationException($"The file lifecycle hook `{nameof(FileLifecycleHooks.OnFileOpened)}(...)` returned `null`.");
+            try
+            {
+                outputStream = hooks.OnFileOpened(path, outputStream, encoding) ??
+                               throw new InvalidOperationException($"The file lifecycle hook `{nameof(FileLifecycleHooks.OnFileOpened)}(...)` returned `null`.");
+            }
+            catch
+            {
+                outputStream?.Dispose();
+                throw;
+            }
         }
 
         _output = new StreamWriter(outputStream, encoding);

src/Serilog.Sinks.File/Sinks/File/RollingFileSink.cs

@@ -83,16 +83,23 @@ public void Emit(LogEvent logEvent)
             {
                 AlignCurrentFileTo(now, nextSequence: true);
             }
+
+            /* TODO: We REALLY should add this to avoid stuff become missing undetected.
+            if (_currentFile == null)
+            {
+                SelfLog.WriteLine("Log event {0} was lost since it was not possible to open the file or create a new one.", logEvent.RenderMessage());
+            }
+            */
         }
     }
 
     void AlignCurrentFileTo(DateTime now, bool nextSequence = false)
     {
-        if (!_nextCheckpoint.HasValue)
+        if (_currentFile == null && !_nextCheckpoint.HasValue)
         {
             OpenFile(now);
         }
-        else if (nextSequence || now >= _nextCheckpoint.Value)
+        else if (nextSequence || (_nextCheckpoint.HasValue && now >= _nextCheckpoint.Value))
         {
             int? minSequence = null;
             if (nextSequence)
@@ -112,68 +119,89 @@ void OpenFile(DateTime now, int? minSequence = null)
     {
         var currentCheckpoint = _roller.GetCurrentCheckpoint(now);
 
-        // We only try periodically because repeated failures
-        // to open log files REALLY slow an app down.
-        _nextCheckpoint = _roller.GetNextCheckpoint(now) ?? now.AddMinutes(30);
+        _nextCheckpoint = _roller.GetNextCheckpoint(now);
 
-        var existingFiles = Enumerable.Empty<string>();
         try
         {
-            if (Directory.Exists(_roller.LogFileDirectory))
+            var existingFiles = Enumerable.Empty<string>();
+            try
+            {
+                if (Directory.Exists(_roller.LogFileDirectory))
+                {
+                    // ReSharper disable once ConvertClosureToMethodGroup
+                    existingFiles = Directory.GetFiles(_roller.LogFileDirectory, _roller.DirectorySearchPattern)
+                        .Select(f => Path.GetFileName(f));
+                }
+            }
+            catch (DirectoryNotFoundException)
             {
-                // ReSharper disable once ConvertClosureToMethodGroup
-                existingFiles = Directory.GetFiles(_roller.LogFileDirectory, _roller.DirectorySearchPattern)
-                    .Select(f => Path.GetFileName(f));
             }
-        }
-        catch (DirectoryNotFoundException) { }
 
-        var latestForThisCheckpoint = _roller
-            .SelectMatches(existingFiles)
-            .Where(m => m.DateTime == currentCheckpoint)
+            var latestForThisCheckpoint = _roller
+                .SelectMatches(existingFiles)
+                .Where(m => m.DateTime == currentCheckpoint)
 #if ENUMERABLE_MAXBY
             .MaxBy(m => m.SequenceNumber);
 #else
-            .OrderByDescending(m => m.SequenceNumber)
-            .FirstOrDefault();
+                .OrderByDescending(m => m.SequenceNumber)
+                .FirstOrDefault();
 #endif
 
-        var sequence = latestForThisCheckpoint?.SequenceNumber;
-        if (minSequence != null)
-        {
-            if (sequence == null || sequence.Value < minSequence.Value)
-                sequence = minSequence;
-        }
-
-        const int maxAttempts = 3;
-        for (var attempt = 0; attempt < maxAttempts; attempt++)
-        {
-            _roller.GetLogFilePath(now, sequence, out var path);
+            var sequence = latestForThisCheckpoint?.SequenceNumber;
+            if (minSequence != null)
+            {
+                if (sequence == null || sequence.Value < minSequence.Value)
+                    sequence = minSequence;
+            }
 
-            try
+            const int maxAttempts = 3;
+            for (var attempt = 0; attempt < maxAttempts; attempt++)
             {
-                _currentFile = _shared ?
+                _roller.GetLogFilePath(now, sequence, out var path);
+
+                try
+                {
+                    _currentFile = _shared
+                        ?
 #pragma warning disable 618
-                    new SharedFileSink(path, _textFormatter, _fileSizeLimitBytes, _encoding) :
+                        new SharedFileSink(path, _textFormatter, _fileSizeLimitBytes, _encoding)
+                        :
 #pragma warning restore 618
-                    new FileSink(path, _textFormatter, _fileSizeLimitBytes, _encoding, _buffered, _hooks);
+                        new FileSink(path, _textFormatter, _fileSizeLimitBytes, _encoding, _buffered, _hooks);
 
-                _currentFileSequence = sequence;
+                    _currentFileSequence = sequence;
+                }
+                catch (IOException ex)
+                {
+                    if (IOErrors.IsLockedFile(ex))
+                    {
+                        SelfLog.WriteLine(
+                            "File target {0} was locked, attempting to open next in sequence (attempt {1})", path,
+                            attempt + 1);
+                        sequence = (sequence ?? 0) + 1;
+                        continue;
+                    }
+
+                    throw;
+                }
+
+                ApplyRetentionPolicy(path, now);
+                return;
             }
-            catch (IOException ex)
+        }
+        finally
+        {
+            if (_currentFile == null)
             {
-                if (IOErrors.IsLockedFile(ex))
+                // We only try periodically because repeated failures
+                // to open log files REALLY slow an app down.
+                // If the next checkpoint would be earlier, keep it!
+                var retryCheckpoint = now.AddMinutes(30);
+                if (_nextCheckpoint == null || retryCheckpoint < _nextCheckpoint)
                 {
-                    SelfLog.WriteLine("File target {0} was locked, attempting to open next in sequence (attempt {1})", path, attempt + 1);
-                    sequence = (sequence ?? 0) + 1;
-                    continue;
+                    _nextCheckpoint = retryCheckpoint;
                 }
-
-                throw;
             }
-
-            ApplyRetentionPolicy(path, now);
-            return;
         }
     }
 

test/Serilog.Sinks.File.Tests/RollingFileSinkTests.cs

@@ -4,11 +4,25 @@
 using Serilog.Sinks.File.Tests.Support;
 using Serilog.Configuration;
 using Serilog.Core;
+using Serilog.Debugging;
+using Xunit.Abstractions;
 
 namespace Serilog.Sinks.File.Tests;
 
-public class RollingFileSinkTests
+public class RollingFileSinkTests : IDisposable
 {
+    private readonly ITestOutputHelper _testOutputHelper;
+
+    public RollingFileSinkTests(ITestOutputHelper testOutputHelper)
+    {
+        _testOutputHelper = testOutputHelper;
+    }
+
+    public void Dispose()
+    {
+        SelfLog.Disable();
+    }
+
     [Fact]
     public void LogEventsAreEmittedToTheFileNamedAccordingToTheEventTimestamp()
     {
@@ -145,6 +159,116 @@ public void WhenRetentionCountAndArchivingHookIsSetOldFilesAreCopiedAndOriginalD
             });
     }
 
+    [Fact]
+    public void WhenFirstOpeningFailedWithLockRetryDelayedUntilNextCheckpoint()
+    {
+        var fileName = Some.String() + ".txt";
+        using var temp = new TempFolder();
+        using var log = new LoggerConfiguration()
+            .WriteTo.File(Path.Combine(temp.Path, fileName), rollOnFileSizeLimit: true, fileSizeLimitBytes: 1, rollingInterval: RollingInterval.Minute, hooks: new FailOpeningHook(true, 2, 3, 4))
+            .CreateLogger();
+        LogEvent e1 = Some.InformationEvent(new DateTime(2012, 10, 28)),
+            e2 = Some.InformationEvent(e1.Timestamp.AddSeconds(1)),
+            e3 = Some.InformationEvent(e1.Timestamp.AddMinutes(5)),
+            e4 = Some.InformationEvent(e1.Timestamp.AddMinutes(31));
+        LogEvent[] logEvents = new[] { e1, e2, e3, e4 };
+
+        foreach (var logEvent in logEvents)
+        {
+            Clock.SetTestDateTimeNow(logEvent.Timestamp.DateTime);
+            log.Write(logEvent);
+        }
+
+        var files = Directory.GetFiles(temp.Path)
+            .OrderBy(p => p, StringComparer.OrdinalIgnoreCase)
+            .ToArray();
+        var pattern = "yyyyMMddHHmm";
+
+        Assert.Equal(6, files.Length);
+        // Successful write of e1:
+        Assert.True(files[0].EndsWith(ExpectedFileName(fileName, e1.Timestamp, pattern)), files[0]);
+        // Failing writes for e2, will be dropped and logged to SelfLog:
+        Assert.True(files[1].EndsWith("_001.txt"), files[1]);
+        Assert.True(files[2].EndsWith("_002.txt"), files[2]);
+        Assert.True(files[3].EndsWith("_003.txt"), files[3]);
+        // Successful write of e3:
+        Assert.True(files[4].EndsWith(ExpectedFileName(fileName, e3.Timestamp, pattern)), files[4]);
+        // Successful write of e4:
+        Assert.True(files[5].EndsWith(ExpectedFileName(fileName, e4.Timestamp, pattern)), files[5]);
+    }
+
+    [Fact]
+    public void WhenFirstOpeningFailedWithLockRetryDelayed30Minutes()
+    {
+        var fileName = Some.String() + ".txt";
+        using var temp = new TempFolder();
+        using var log = new LoggerConfiguration()
+            .WriteTo.File(Path.Combine(temp.Path, fileName), rollOnFileSizeLimit: true, fileSizeLimitBytes: 1, rollingInterval: RollingInterval.Hour, hooks: new FailOpeningHook(true, 2, 3, 4))
+            .CreateLogger();
+        LogEvent e1 = Some.InformationEvent(new DateTime(2012, 10, 28)),
+            e2 = Some.InformationEvent(e1.Timestamp.AddSeconds(1)),
+            e3 = Some.InformationEvent(e1.Timestamp.AddMinutes(5)),
+            e4 = Some.InformationEvent(e1.Timestamp.AddMinutes(31));
+        LogEvent[] logEvents = new[] { e1, e2, e3, e4 };
+
+        SelfLog.Enable(_testOutputHelper.WriteLine);
+        foreach (var logEvent in logEvents)
+        {
+            Clock.SetTestDateTimeNow(logEvent.Timestamp.DateTime);
+            log.Write(logEvent);
+        }
+
+        var files = Directory.GetFiles(temp.Path)
+            .OrderBy(p => p, StringComparer.OrdinalIgnoreCase)
+            .ToArray();
+        var pattern = "yyyyMMddHH";
+
+        Assert.Equal(4, files.Length);
+        // Successful write of e1:
+        Assert.True(files[0].EndsWith(ExpectedFileName(fileName, e1.Timestamp, pattern)), files[0]);
+        // Failing writes for e2, will be dropped and logged to SelfLog; on lock it will try it three times:
+        Assert.True(files[1].EndsWith("_001.txt"), files[1]);
+        Assert.True(files[2].EndsWith("_002.txt"), files[2]);
+        /* e3 will be dropped and logged to SelfLog without new file as it's in the 30 minutes cooldown and roller only starts on next hour! */
+        // Successful write of e4, the third file will be retried after failing initially:
+        Assert.True(files[3].EndsWith("_003.txt"), files[3]);
+    }
+
+    [Fact]
+    public void WhenFirstOpeningFailedWithoutLockRetryDelayed30Minutes()
+    {
+        var fileName = Some.String() + ".txt";
+        using var temp = new TempFolder();
+        using var log = new LoggerConfiguration()
+            .WriteTo.File(Path.Combine(temp.Path, fileName), rollOnFileSizeLimit: true, fileSizeLimitBytes: 1, rollingInterval: RollingInterval.Hour, hooks: new FailOpeningHook(false, 2))
+            .CreateLogger();
+        LogEvent e1 = Some.InformationEvent(new DateTime(2012, 10, 28)),
+            e2 = Some.InformationEvent(e1.Timestamp.AddSeconds(1)),
+            e3 = Some.InformationEvent(e1.Timestamp.AddMinutes(5)),
+            e4 = Some.InformationEvent(e1.Timestamp.AddMinutes(31));
+        LogEvent[] logEvents = new[] { e1, e2, e3, e4 };
+
+        SelfLog.Enable(_testOutputHelper.WriteLine);
+        foreach (var logEvent in logEvents)
+        {
+            Clock.SetTestDateTimeNow(logEvent.Timestamp.DateTime);
+            log.Write(logEvent);
+        }
+
+        var files = Directory.GetFiles(temp.Path)
+            .OrderBy(p => p, StringComparer.OrdinalIgnoreCase)
+            .ToArray();
+        var pattern = "yyyyMMddHH";
+
+        Assert.Equal(2, files.Length);
+        // Successful write of e1:
+        Assert.True(files[0].EndsWith(ExpectedFileName(fileName, e1.Timestamp, pattern)), files[0]);
+        /* Failing writes for e2, will be dropped and logged to SelfLog; on non-lock it will try it once */
+        /* e3 will be dropped and logged to SelfLog without new file as it's in the 30 minutes cooldown and roller only starts on next hour! */
+        // Successful write of e4, the file will be retried after failing initially:
+        Assert.True(files[1].EndsWith("_001.txt"), files[1]);
+    }
+
     [Fact]
     public void WhenSizeLimitIsBreachedNewFilesCreated()
     {
@@ -279,7 +403,7 @@ static void TestRollingEventSequence(
                 Clock.SetTestDateTimeNow(@event.Timestamp.DateTime);
                 log.Write(@event);
 
-                var expected = pathFormat.Replace(".txt", @event.Timestamp.ToString("yyyyMMdd") + ".txt");
+                var expected = ExpectedFileName(pathFormat, @event.Timestamp, "yyyyMMdd");
                 Assert.True(System.IO.File.Exists(expected));
 
                 verified.Add(expected);
@@ -292,4 +416,9 @@ static void TestRollingEventSequence(
             Directory.Delete(folder, true);
         }
     }
+
+    static string ExpectedFileName(string fileName, DateTimeOffset timestamp, string pattern)
+    {
+        return fileName.Replace(".txt", timestamp.ToString(pattern) + ".txt");
+    }
 }

test/Serilog.Sinks.File.Tests/Support/FailOpeningHook.cs

@@ -0,0 +1,36 @@
+using System.Text;
+
+namespace Serilog.Sinks.File.Tests.Support;
+
+/// <inheritdoc />
+/// <summary>
+/// Demonstrates the use of <seealso cref="T:Serilog.FileLifecycleHooks" />, by failing to open for the given amount of times.
+/// </summary>
+class FailOpeningHook : FileLifecycleHooks
+{
+    readonly bool _asFileLocked;
+    readonly int[] _failingInstances;
+
+    public int TimesOpened { get; private set; }
+
+    public FailOpeningHook(bool asFileLocked, params int[] failingInstances)
+    {
+        _asFileLocked = asFileLocked;
+        _failingInstances = failingInstances;
+    }
+
+    public override Stream OnFileOpened(string path, Stream stream, Encoding encoding)
+    {
+        TimesOpened++;
+        if (_failingInstances.Contains(TimesOpened))
+        {
+            var message = $"We failed on try {TimesOpened}, the file was locked: {_asFileLocked}";
+
+            throw _asFileLocked
+                ? new IOException(message)
+                : new Exception(message);
+        }
+
+        return base.OnFileOpened(path, stream, encoding);
+    }
+}