Merge pull request #337 from Falco20019/dev

Avoid forcing the file to be closed and reopened every 30 minutes if the previous open was successful. Avoids issues with file hooks needing to reprocess the same file.

Author: nblumhardt

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);
+    }
+}