Skip to content

Commit a9a2d19

Browse files
wtgodbewtgodbe
authored
FileLoggerProcessor write to a new file on new instance or Fields change (#34652)
* FileLoggerProcessor write to a new file on new instance or Fields change * Fixup comment * Feedback * Feedback
1 parent 47be8bc commit a9a2d19

File tree

3 files changed

+176
-20
lines changed

3 files changed

+176
-20
lines changed

‎src/Middleware/HttpLogging/src/FileLoggerProcessor.cs

Lines changed: 48 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -29,7 +29,9 @@ internal class FileLoggerProcessor : IAsyncDisposable
2929
private int _fileNumber;
3030
private bool _maxFilesReached;
3131
private TimeSpan _flushInterval;
32+
private W3CLoggingFields _fields;
3233
private DateTime _today = DateTime.Now;
34+
private bool _firstFile = true;
3335

3436
private readonly IOptionsMonitor<W3CLoggerOptions> _options;
3537
private readonly BlockingCollection<string> _messageQueue = new BlockingCollection<string>(_maxQueuedMessages);
@@ -42,6 +44,8 @@ internal class FileLoggerProcessor : IAsyncDisposable
4244

4345
public FileLoggerProcessor(IOptionsMonitor<W3CLoggerOptions> options, IHostEnvironment environment, ILoggerFactory factory)
4446
{
47+
_logger = factory.CreateLogger(typeof(FileLoggerProcessor));
48+
4549
_options = options;
4650
var loggerOptions = _options.CurrentValue;
4751

@@ -62,25 +66,38 @@ public FileLoggerProcessor(IOptionsMonitor<W3CLoggerOptions> options, IHostEnvir
6266
_maxFileSize = loggerOptions.FileSizeLimit;
6367
_maxRetainedFiles = loggerOptions.RetainedFileCountLimit;
6468
_flushInterval = loggerOptions.FlushInterval;
69+
_fields = loggerOptions.LoggingFields;
6570
_options.OnChange(options =>
6671
{
6772
lock (_pathLock)
6873
{
6974
// Clear the cached settings.
7075
loggerOptions = options;
76+
77+
// Move to a new file if the fields have changed
78+
if (_fields != loggerOptions.LoggingFields)
79+
{
80+
_fileNumber++;
81+
if (_fileNumber >= W3CLoggerOptions.MaxFileCount)
82+
{
83+
_maxFilesReached = true;
84+
Log.MaxFilesReached(_logger);
85+
}
86+
_fields = loggerOptions.LoggingFields;
87+
}
88+
7189
if (!string.IsNullOrEmpty(loggerOptions.LogDirectory))
7290
{
7391
_path = loggerOptions.LogDirectory;
7492
}
93+
7594
_fileName = loggerOptions.FileName;
7695
_maxFileSize = loggerOptions.FileSizeLimit;
7796
_maxRetainedFiles = loggerOptions.RetainedFileCountLimit;
7897
_flushInterval = loggerOptions.FlushInterval;
7998
}
8099
});
81100

82-
_logger = factory.CreateLogger(typeof(FileLoggerProcessor));
83-
84101
// Start message queue processor
85102
_cancellationTokenSource = new CancellationTokenSource();
86103
_outputTask = Task.Run(ProcessLogQueue);
@@ -140,6 +157,23 @@ private async Task WriteMessagesAsync(List<string> messages, CancellationToken c
140157
// Files are written up to _maxFileSize before rolling to a new file
141158
DateTime today = DateTime.Now;
142159
var fullName = GetFullName(today);
160+
// Don't write to an incomplete file left around by a previous FileLoggerProcessor
161+
if (_firstFile)
162+
{
163+
while (File.Exists(fullName))
164+
{
165+
_fileNumber++;
166+
if (_fileNumber >= W3CLoggerOptions.MaxFileCount)
167+
{
168+
_maxFilesReached = true;
169+
// Return early if log directory is already full
170+
Log.MaxFilesReached(_logger);
171+
return;
172+
}
173+
fullName = GetFullName(today);
174+
}
175+
}
176+
_firstFile = false;
143177
if (_maxFilesReached)
144178
{
145179
// Return early if we've already logged that today's file limit has been reached.
@@ -167,26 +201,20 @@ private async Task WriteMessagesAsync(List<string> messages, CancellationToken c
167201
fileInfo.Refresh();
168202
// Roll to new file if _maxFileSize is reached
169203
// _maxFileSize could be less than the length of the file header - in that case we still write the first log message before rolling.
170-
// Previous instance of FileLoggerProcessor could have already written files to the same directory.
171-
// Loop through them until we find what the current _fileNumber should be.
172204
if (fileInfo.Exists && fileInfo.Length > _maxFileSize)
173205
{
174206
streamWriter.Dispose();
175-
do
207+
_fileNumber++;
208+
if (_fileNumber >= W3CLoggerOptions.MaxFileCount)
176209
{
177-
_fileNumber++;
178-
if (_fileNumber >= W3CLoggerOptions.MaxFileCount)
179-
{
180-
streamWriter = null;
181-
_maxFilesReached = true;
182-
// Return early if log directory is already full
183-
Log.MaxFilesReached(_logger, new ApplicationException());
184-
return;
185-
}
186-
fullName = GetFullName(today);
187-
fileInfo = new FileInfo(fullName);
210+
streamWriter = null;
211+
_maxFilesReached = true;
212+
// Return early if log directory is already full
213+
Log.MaxFilesReached(_logger);
214+
return;
188215
}
189-
while (fileInfo.Exists && fileInfo.Length > _maxFileSize);
216+
fullName = GetFullName(today);
217+
fileInfo = new FileInfo(fullName);
190218
if (!TryCreateDirectory())
191219
{
192220
streamWriter = null;
@@ -309,13 +337,13 @@ private static class Log
309337

310338
public static void CreateDirectoryFailed(ILogger logger, string path, Exception ex) => _createDirectoryFailed(logger, path, ex);
311339

312-
private static readonly Action<ILogger, Exception> _maxFilesReached =
340+
private static readonly Action<ILogger, Exception?> _maxFilesReached =
313341
LoggerMessage.Define(
314342
LogLevel.Warning,
315343
new EventId(3, "MaxFilesReached"),
316-
"Limit of 10,000 files per day has been reached");
344+
$"Limit of {W3CLoggerOptions.MaxFileCount} files per day has been reached");
317345

318-
public static void MaxFilesReached(ILogger logger, Exception ex) => _maxFilesReached(logger, ex);
346+
public static void MaxFilesReached(ILogger logger) => _maxFilesReached(logger, null);
319347
}
320348
}
321349

‎src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs

Lines changed: 120 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -271,6 +271,126 @@ public async Task InstancesWriteToSameDirectory()
271271
}
272272
}
273273

274+
[Fact]
275+
public async Task WritesToNewFileOnNewInstance()
276+
{
277+
var now = DateTimeOffset.Now;
278+
if (now.Hour == 23)
279+
{
280+
// Don't bother trying to run this test when it's almost midnight.
281+
return;
282+
}
283+
284+
var path = Path.Combine(TempPath, Path.GetRandomFileName());
285+
Directory.CreateDirectory(path);
286+
287+
try
288+
{
289+
var options = new W3CLoggerOptions()
290+
{
291+
LogDirectory = path,
292+
FileSizeLimit = 5
293+
};
294+
var fileName1 = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{now.Year:0000}{now.Month:00}{now.Day:00}.0000.txt"));
295+
var fileName2 = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{now.Year:0000}{now.Month:00}{now.Day:00}.0001.txt"));
296+
var fileName3 = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{now.Year:0000}{now.Month:00}{now.Day:00}.0002.txt"));
297+
298+
await using (var logger = new FileLoggerProcessor(new OptionsWrapperMonitor<W3CLoggerOptions>(options), new HostingEnvironment(), NullLoggerFactory.Instance))
299+
{
300+
logger.EnqueueMessage("Message one");
301+
logger.EnqueueMessage("Message two");
302+
// Pause for a bit before disposing so logger can finish logging
303+
await WaitForFile(fileName2).DefaultTimeout();
304+
}
305+
306+
// Even with a big enough FileSizeLimit, we still won't try to write to files from a previous instance.
307+
options.FileSizeLimit = 10000;
308+
309+
await using (var logger = new FileLoggerProcessor(new OptionsWrapperMonitor<W3CLoggerOptions>(options), new HostingEnvironment(), NullLoggerFactory.Instance))
310+
{
311+
logger.EnqueueMessage("Message three");
312+
// Pause for a bit before disposing so logger can finish logging
313+
await WaitForFile(fileName3).DefaultTimeout();
314+
}
315+
316+
var actualFiles = new DirectoryInfo(path)
317+
.GetFiles()
318+
.Select(f => f.Name)
319+
.OrderBy(f => f)
320+
.ToArray();
321+
322+
Assert.Equal(3, actualFiles.Length);
323+
324+
Assert.True(File.Exists(fileName1));
325+
Assert.True(File.Exists(fileName2));
326+
Assert.True(File.Exists(fileName3));
327+
328+
Assert.Equal("Message one" + Environment.NewLine, File.ReadAllText(fileName1));
329+
Assert.Equal("Message two" + Environment.NewLine, File.ReadAllText(fileName2));
330+
Assert.Equal("Message three" + Environment.NewLine, File.ReadAllText(fileName3));
331+
}
332+
finally
333+
{
334+
Helpers.DisposeDirectory(path);
335+
}
336+
}
337+
338+
[Fact]
339+
public async Task WritesToNewFileOnOptionsChange()
340+
{
341+
var now = DateTimeOffset.Now;
342+
if (now.Hour == 23)
343+
{
344+
// Don't bother trying to run this test when it's almost midnight.
345+
return;
346+
}
347+
348+
var path = Path.Combine(TempPath, Path.GetRandomFileName());
349+
Directory.CreateDirectory(path);
350+
351+
try
352+
{
353+
var options = new W3CLoggerOptions()
354+
{
355+
LogDirectory = path,
356+
LoggingFields = W3CLoggingFields.Time,
357+
FileSizeLimit = 10000
358+
};
359+
var fileName1 = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{now.Year:0000}{now.Month:00}{now.Day:00}.0000.txt"));
360+
var fileName2 = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{now.Year:0000}{now.Month:00}{now.Day:00}.0001.txt"));
361+
var monitor = new OptionsWrapperMonitor<W3CLoggerOptions>(options);
362+
363+
await using (var logger = new FileLoggerProcessor(monitor, new HostingEnvironment(), NullLoggerFactory.Instance))
364+
{
365+
logger.EnqueueMessage("Message one");
366+
await WaitForFile(fileName1).DefaultTimeout();
367+
options.LoggingFields = W3CLoggingFields.Date;
368+
monitor.InvokeChanged();
369+
logger.EnqueueMessage("Message two");
370+
// Pause for a bit before disposing so logger can finish logging
371+
await WaitForFile(fileName2).DefaultTimeout();
372+
}
373+
374+
var actualFiles = new DirectoryInfo(path)
375+
.GetFiles()
376+
.Select(f => f.Name)
377+
.OrderBy(f => f)
378+
.ToArray();
379+
380+
Assert.Equal(2, actualFiles.Length);
381+
382+
Assert.True(File.Exists(fileName1));
383+
Assert.True(File.Exists(fileName2));
384+
385+
Assert.Equal("Message one" + Environment.NewLine, File.ReadAllText(fileName1));
386+
Assert.Equal("Message two" + Environment.NewLine, File.ReadAllText(fileName2));
387+
}
388+
finally
389+
{
390+
Helpers.DisposeDirectory(path);
391+
}
392+
}
393+
274394
private async Task WaitForFile(string fileName)
275395
{
276396
while (!File.Exists(fileName))

‎src/Middleware/HttpLogging/test/OptionsWrapperMonitor.cs

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -8,18 +8,26 @@ namespace Microsoft.AspNetCore.HttpLogging
88
{
99
internal class OptionsWrapperMonitor<T> : IOptionsMonitor<T>
1010
{
11+
private event Action<T, string> _listener;
12+
1113
public OptionsWrapperMonitor(T currentValue)
1214
{
1315
CurrentValue = currentValue;
1416
}
1517

1618
public IDisposable OnChange(Action<T, string> listener)
1719
{
20+
_listener = listener;
1821
return null;
1922
}
2023

2124
public T Get(string name) => CurrentValue;
2225

2326
public T CurrentValue { get; }
27+
28+
internal void InvokeChanged()
29+
{
30+
_listener.Invoke(CurrentValue, null);
31+
}
2432
}
2533
}

0 commit comments

Comments
 (0)