diff --git a/src/Serilog.Sinks.File/Sinks/File/FileSink.cs b/src/Serilog.Sinks.File/Sinks/File/FileSink.cs index a246b66..0763fc3 100644 --- a/src/Serilog.Sinks.File/Sinks/File/FileSink.cs +++ b/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); diff --git a/src/Serilog.Sinks.File/Sinks/File/RollingFileSink.cs b/src/Serilog.Sinks.File/Sinks/File/RollingFileSink.cs index 6c55d44..dc8d33c 100644 --- a/src/Serilog.Sinks.File/Sinks/File/RollingFileSink.cs +++ b/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(); try { - if (Directory.Exists(_roller.LogFileDirectory)) + var existingFiles = Enumerable.Empty(); + 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; } } diff --git a/test/Serilog.Sinks.File.Tests/RollingFileSinkTests.cs b/test/Serilog.Sinks.File.Tests/RollingFileSinkTests.cs index 5739983..830af11 100644 --- a/test/Serilog.Sinks.File.Tests/RollingFileSinkTests.cs +++ b/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"); + } } diff --git a/test/Serilog.Sinks.File.Tests/Support/FailOpeningHook.cs b/test/Serilog.Sinks.File.Tests/Support/FailOpeningHook.cs new file mode 100644 index 0000000..54ce65b --- /dev/null +++ b/test/Serilog.Sinks.File.Tests/Support/FailOpeningHook.cs @@ -0,0 +1,36 @@ +using System.Text; + +namespace Serilog.Sinks.File.Tests.Support; + +/// +/// +/// Demonstrates the use of , by failing to open for the given amount of times. +/// +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); + } +}