Skip to content

Commit 7c44444

Browse files
Falco20019Falco20019
committed
Fix issue with force-reopen after 30 minutes
1 parent 5e3ff41 commit 7c44444

File tree

3 files changed

+243
-44
lines changed

3 files changed

+243
-44
lines changed

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

Lines changed: 69 additions & 43 deletions
Original file line numberDiff line numberDiff line change
@@ -83,16 +83,21 @@ public void Emit(LogEvent logEvent)
8383
{
8484
AlignCurrentFileTo(now, nextSequence: true);
8585
}
86+
87+
if (_currentFile == null)
88+
{
89+
SelfLog.WriteLine("Log event {0} was lost since it was not possible to open the file or create a new one.", logEvent.RenderMessage());
90+
}
8691
}
8792
}
8893

8994
void AlignCurrentFileTo(DateTime now, bool nextSequence = false)
9095
{
91-
if (!_nextCheckpoint.HasValue)
96+
if (_currentFile == null && !_nextCheckpoint.HasValue)
9297
{
9398
OpenFile(now);
9499
}
95-
else if (nextSequence || now >= _nextCheckpoint.Value)
100+
else if (nextSequence || (_nextCheckpoint.HasValue && now >= _nextCheckpoint.Value))
96101
{
97102
int? minSequence = null;
98103
if (nextSequence)
@@ -112,68 +117,89 @@ void OpenFile(DateTime now, int? minSequence = null)
112117
{
113118
var currentCheckpoint = _roller.GetCurrentCheckpoint(now);
114119

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

119-
var existingFiles = Enumerable.Empty<string>();
120122
try
121123
{
122-
if (Directory.Exists(_roller.LogFileDirectory))
124+
var existingFiles = Enumerable.Empty<string>();
125+
try
126+
{
127+
if (Directory.Exists(_roller.LogFileDirectory))
128+
{
129+
// ReSharper disable once ConvertClosureToMethodGroup
130+
existingFiles = Directory.GetFiles(_roller.LogFileDirectory, _roller.DirectorySearchPattern)
131+
.Select(f => Path.GetFileName(f));
132+
}
133+
}
134+
catch (DirectoryNotFoundException)
123135
{
124-
// ReSharper disable once ConvertClosureToMethodGroup
125-
existingFiles = Directory.GetFiles(_roller.LogFileDirectory, _roller.DirectorySearchPattern)
126-
.Select(f => Path.GetFileName(f));
127136
}
128-
}
129-
catch (DirectoryNotFoundException) { }
130137

131-
var latestForThisCheckpoint = _roller
132-
.SelectMatches(existingFiles)
133-
.Where(m => m.DateTime == currentCheckpoint)
138+
var latestForThisCheckpoint = _roller
139+
.SelectMatches(existingFiles)
140+
.Where(m => m.DateTime == currentCheckpoint)
134141
#if ENUMERABLE_MAXBY
135142
.MaxBy(m => m.SequenceNumber);
136143
#else
137-
.OrderByDescending(m => m.SequenceNumber)
138-
.FirstOrDefault();
144+
.OrderByDescending(m => m.SequenceNumber)
145+
.FirstOrDefault();
139146
#endif
140147

141-
var sequence = latestForThisCheckpoint?.SequenceNumber;
142-
if (minSequence != null)
143-
{
144-
if (sequence == null || sequence.Value < minSequence.Value)
145-
sequence = minSequence;
146-
}
147-
148-
const int maxAttempts = 3;
149-
for (var attempt = 0; attempt < maxAttempts; attempt++)
150-
{
151-
_roller.GetLogFilePath(now, sequence, out var path);
148+
var sequence = latestForThisCheckpoint?.SequenceNumber;
149+
if (minSequence != null)
150+
{
151+
if (sequence == null || sequence.Value < minSequence.Value)
152+
sequence = minSequence;
153+
}
152154

153-
try
155+
const int maxAttempts = 3;
156+
for (var attempt = 0; attempt < maxAttempts; attempt++)
154157
{
155-
_currentFile = _shared ?
158+
_roller.GetLogFilePath(now, sequence, out var path);
159+
160+
try
161+
{
162+
_currentFile = _shared
163+
?
156164
#pragma warning disable 618
157-
new SharedFileSink(path, _textFormatter, _fileSizeLimitBytes, _encoding) :
165+
new SharedFileSink(path, _textFormatter, _fileSizeLimitBytes, _encoding)
166+
:
158167
#pragma warning restore 618
159-
new FileSink(path, _textFormatter, _fileSizeLimitBytes, _encoding, _buffered, _hooks);
168+
new FileSink(path, _textFormatter, _fileSizeLimitBytes, _encoding, _buffered, _hooks);
160169

161-
_currentFileSequence = sequence;
170+
_currentFileSequence = sequence;
171+
}
172+
catch (IOException ex)
173+
{
174+
if (IOErrors.IsLockedFile(ex))
175+
{
176+
SelfLog.WriteLine(
177+
"File target {0} was locked, attempting to open next in sequence (attempt {1})", path,
178+
attempt + 1);
179+
sequence = (sequence ?? 0) + 1;
180+
continue;
181+
}
182+
183+
throw;
184+
}
185+
186+
ApplyRetentionPolicy(path, now);
187+
return;
162188
}
163-
catch (IOException ex)
189+
}
190+
finally
191+
{
192+
if (_currentFile == null)
164193
{
165-
if (IOErrors.IsLockedFile(ex))
194+
// We only try periodically because repeated failures
195+
// to open log files REALLY slow an app down.
196+
// If the next checkpoint would be earlier, keep it!
197+
var retryCheckpoint = now.AddMinutes(30);
198+
if (_nextCheckpoint == null || retryCheckpoint < _nextCheckpoint)
166199
{
167-
SelfLog.WriteLine("File target {0} was locked, attempting to open next in sequence (attempt {1})", path, attempt + 1);
168-
sequence = (sequence ?? 0) + 1;
169-
continue;
200+
_nextCheckpoint = retryCheckpoint;
170201
}
171-
172-
throw;
173202
}
174-
175-
ApplyRetentionPolicy(path, now);
176-
return;
177203
}
178204
}
179205

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

Lines changed: 138 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -4,11 +4,19 @@
44
using Serilog.Sinks.File.Tests.Support;
55
using Serilog.Configuration;
66
using Serilog.Core;
7+
using Xunit.Abstractions;
78

89
namespace Serilog.Sinks.File.Tests;
910

1011
public class RollingFileSinkTests
1112
{
13+
private readonly ITestOutputHelper _testOutputHelper;
14+
15+
public RollingFileSinkTests(ITestOutputHelper testOutputHelper)
16+
{
17+
_testOutputHelper = testOutputHelper;
18+
}
19+
1220
[Fact]
1321
public void LogEventsAreEmittedToTheFileNamedAccordingToTheEventTimestamp()
1422
{
@@ -145,6 +153,130 @@ public void WhenRetentionCountAndArchivingHookIsSetOldFilesAreCopiedAndOriginalD
145153
});
146154
}
147155

156+
[Fact]
157+
public void WhenFirstOpeningFailedWithLockRetryDelayedUntilNextCheckpoint()
158+
{
159+
var fileName = Some.String() + ".txt";
160+
using var temp = new TempFolder();
161+
using var log = new LoggerConfiguration()
162+
.WriteTo.File(Path.Combine(temp.Path, fileName), rollOnFileSizeLimit: true, fileSizeLimitBytes: 1, rollingInterval: RollingInterval.Minute, hooks: new FailOpeningHook(true, 2, 3, 4))
163+
.CreateLogger();
164+
LogEvent e1 = Some.InformationEvent(new DateTime(2012, 10, 28)),
165+
e2 = Some.InformationEvent(e1.Timestamp.AddSeconds(1)),
166+
e3 = Some.InformationEvent(e1.Timestamp.AddMinutes(5)),
167+
e4 = Some.InformationEvent(e1.Timestamp.AddMinutes(31));
168+
LogEvent[] logEvents = new[] { e1, e2, e3, e4 };
169+
170+
foreach (var logEvent in logEvents)
171+
{
172+
Clock.SetTestDateTimeNow(logEvent.Timestamp.DateTime);
173+
log.Write(logEvent);
174+
}
175+
176+
var files = Directory.GetFiles(temp.Path)
177+
.OrderBy(p => p, StringComparer.OrdinalIgnoreCase)
178+
.ToArray();
179+
var pattern = "yyyyMMddHHmm";
180+
181+
Assert.Equal(6, files.Length);
182+
// Successful write of e1:
183+
Assert.True(files[0].EndsWith(ExpectedFileName(fileName, e1.Timestamp, pattern)), files[0]);
184+
// Failing writes for e2, will be dropped and logged to SelfLog:
185+
Assert.True(files[1].EndsWith("_001.txt"), files[1]);
186+
Assert.True(files[2].EndsWith("_002.txt"), files[2]);
187+
Assert.True(files[3].EndsWith("_003.txt"), files[3]);
188+
// Successful write of e3:
189+
Assert.True(files[4].EndsWith(ExpectedFileName(fileName, e3.Timestamp, pattern)), files[4]);
190+
// Successful write of e4:
191+
Assert.True(files[5].EndsWith(ExpectedFileName(fileName, e4.Timestamp, pattern)), files[5]);
192+
}
193+
194+
[Fact]
195+
public void WhenFirstOpeningFailedWithLockRetryDelayed30Minutes()
196+
{
197+
var fileName = Some.String() + ".txt";
198+
using var temp = new TempFolder();
199+
LogEvent e1 = Some.InformationEvent(new DateTime(2012, 10, 28)),
200+
e2 = Some.InformationEvent(e1.Timestamp.AddSeconds(1)),
201+
e3 = Some.InformationEvent(e1.Timestamp.AddMinutes(5)),
202+
e4 = Some.InformationEvent(e1.Timestamp.AddMinutes(31));
203+
LogEvent[] logEvents = new[] { e1, e2, e3, e4 };
204+
205+
using (var log = new LoggerConfiguration()
206+
.WriteTo.File(Path.Combine(temp.Path, fileName), rollOnFileSizeLimit: true, fileSizeLimitBytes: 1,
207+
rollingInterval: RollingInterval.Hour, hooks: new FailOpeningHook(true, 2, 3, 4))
208+
.CreateLogger())
209+
{
210+
foreach (var logEvent in logEvents)
211+
{
212+
Clock.SetTestDateTimeNow(logEvent.Timestamp.DateTime);
213+
log.Write(logEvent);
214+
}
215+
}
216+
217+
var files = Directory.GetFiles(temp.Path)
218+
.OrderBy(p => p, StringComparer.OrdinalIgnoreCase)
219+
.ToArray();
220+
var pattern = "yyyyMMddHH";
221+
222+
foreach (var file in files)
223+
{
224+
_testOutputHelper.WriteLine(file + ": " + System.IO.File.ReadAllText(file));
225+
}
226+
Assert.Equal(5, files.Length);
227+
// Successful write of e1:
228+
Assert.True(files[0].EndsWith(ExpectedFileName(fileName, e1.Timestamp, pattern)), files[0]);
229+
// Failing writes for e2, will be dropped and logged to SelfLog; on lock it will try it three times:
230+
Assert.True(files[1].EndsWith("_001.txt"), files[1]);
231+
Assert.True(files[2].EndsWith("_002.txt"), files[2]);
232+
Assert.True(files[3].EndsWith("_003.txt"), files[3]);
233+
/* 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! */
234+
// Successful write of e4:
235+
Assert.True(files[4].EndsWith("_004.txt"), files[4]);
236+
}
237+
238+
[Fact]
239+
public void WhenFirstOpeningFailedWithoutLockRetryDelayed30Minutes()
240+
{
241+
var fileName = Some.String() + ".txt";
242+
using var temp = new TempFolder();
243+
LogEvent e1 = Some.InformationEvent(new DateTime(2012, 10, 28)),
244+
e2 = Some.InformationEvent(e1.Timestamp.AddSeconds(1)),
245+
e3 = Some.InformationEvent(e1.Timestamp.AddMinutes(5)),
246+
e4 = Some.InformationEvent(e1.Timestamp.AddMinutes(31));
247+
LogEvent[] logEvents = new[] { e1, e2, e3, e4 };
248+
249+
using (var log = new LoggerConfiguration()
250+
.WriteTo.File(Path.Combine(temp.Path, fileName), rollOnFileSizeLimit: true, fileSizeLimitBytes: 1,
251+
rollingInterval: RollingInterval.Hour, hooks: new FailOpeningHook(false, 2))
252+
.CreateLogger())
253+
{
254+
foreach (var logEvent in logEvents)
255+
{
256+
Clock.SetTestDateTimeNow(logEvent.Timestamp.DateTime);
257+
log.Write(logEvent);
258+
}
259+
}
260+
261+
var files = Directory.GetFiles(temp.Path)
262+
.OrderBy(p => p, StringComparer.OrdinalIgnoreCase)
263+
.ToArray();
264+
var pattern = "yyyyMMddHH";
265+
266+
foreach (var file in files)
267+
{
268+
_testOutputHelper.WriteLine(file + ": " + System.IO.File.ReadAllText(file));
269+
}
270+
Assert.Equal(3, files.Length);
271+
// Successful write of e1:
272+
Assert.True(files[0].EndsWith(ExpectedFileName(fileName, e1.Timestamp, pattern)), files[0]);
273+
// Failing writes for e2, will be dropped and logged to SelfLog; on non-lock it will try it once:
274+
Assert.True(files[1].EndsWith("_001.txt"), files[1]);
275+
/* 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! */
276+
// Successful write of e4:
277+
Assert.True(files[2].EndsWith("_002.txt"), files[2]);
278+
}
279+
148280
[Fact]
149281
public void WhenSizeLimitIsBreachedNewFilesCreated()
150282
{
@@ -279,7 +411,7 @@ static void TestRollingEventSequence(
279411
Clock.SetTestDateTimeNow(@event.Timestamp.DateTime);
280412
log.Write(@event);
281413

282-
var expected = pathFormat.Replace(".txt", @event.Timestamp.ToString("yyyyMMdd") + ".txt");
414+
var expected = ExpectedFileName(pathFormat, @event.Timestamp, "yyyyMMdd");
283415
Assert.True(System.IO.File.Exists(expected));
284416

285417
verified.Add(expected);
@@ -292,4 +424,9 @@ static void TestRollingEventSequence(
292424
Directory.Delete(folder, true);
293425
}
294426
}
427+
428+
static string ExpectedFileName(string fileName, DateTimeOffset timestamp, string pattern)
429+
{
430+
return fileName.Replace(".txt", timestamp.ToString(pattern) + ".txt");
431+
}
295432
}

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

Lines changed: 36 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,36 @@
1+
using System.Text;
2+
3+
namespace Serilog.Sinks.File.Tests.Support;
4+
5+
/// <inheritdoc />
6+
/// <summary>
7+
/// Demonstrates the use of <seealso cref="T:Serilog.FileLifecycleHooks" />, by failing to open for the given amount of times.
8+
/// </summary>
9+
class FailOpeningHook : FileLifecycleHooks
10+
{
11+
readonly bool _asFileLocked;
12+
readonly int[] _failingInstances;
13+
14+
public int TimesOpened { get; private set; }
15+
16+
public FailOpeningHook(bool asFileLocked, params int[] failingInstances)
17+
{
18+
_asFileLocked = asFileLocked;
19+
_failingInstances = failingInstances;
20+
}
21+
22+
public override Stream OnFileOpened(string path, Stream _, Encoding __)
23+
{
24+
TimesOpened++;
25+
if (_failingInstances.Contains(TimesOpened))
26+
{
27+
var message = $"We failed on try {TimesOpened}, the file was locked: {_asFileLocked}";
28+
29+
throw _asFileLocked
30+
? new IOException(message)
31+
: new Exception(message);
32+
}
33+
34+
return base.OnFileOpened(path, _, __);
35+
}
36+
}

0 commit comments

Comments
 (0)