Skip to content

Commit 3d84394

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

File tree

3 files changed

+221
-44
lines changed

3 files changed

+221
-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: 116 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -145,6 +145,116 @@ public void WhenRetentionCountAndArchivingHookIsSetOldFilesAreCopiedAndOriginalD
145145
});
146146
}
147147

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

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

285395
verified.Add(expected);
@@ -292,4 +402,9 @@ static void TestRollingEventSequence(
292402
Directory.Delete(folder, true);
293403
}
294404
}
405+
406+
static string ExpectedFileName(string fileName, DateTimeOffset timestamp, string pattern)
407+
{
408+
return fileName.Replace(".txt", timestamp.ToString(pattern) + ".txt");
409+
}
295410
}

‎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)