Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
42 changes: 32 additions & 10 deletions src/Middleware/HttpLogging/src/FileLoggerProcessor.cs
Original file line number Diff line number Diff line change
Expand Up @@ -156,23 +156,28 @@ private async Task WriteMessagesAsync(List<string> messages, CancellationToken c
{
// Files are written up to _maxFileSize before rolling to a new file
DateTime today = DateTime.Now;

if (!TryCreateDirectory())
{
// return early if we fail to create the directory
return;
}

var fullName = GetFullName(today);
// Don't write to an incomplete file left around by a previous FileLoggerProcessor
if (_firstFile)
{
while (File.Exists(fullName))
_fileNumber = GetFirstFileCount(today);
fullName = GetFullName(today);
if (_fileNumber >= W3CLoggerOptions.MaxFileCount)
{
_fileNumber++;
if (_fileNumber >= W3CLoggerOptions.MaxFileCount)
{
_maxFilesReached = true;
// Return early if log directory is already full
Log.MaxFilesReached(_logger);
return;
}
fullName = GetFullName(today);
_maxFilesReached = true;
// Return early if log directory is already full
Log.MaxFilesReached(_logger);
return;
}
}

_firstFile = false;
if (_maxFilesReached)
{
Expand Down Expand Up @@ -300,6 +305,23 @@ public async ValueTask DisposeAsync()
await _outputTask;
}

private int GetFirstFileCount(DateTime date)
{
lock (_pathLock)
{
var searchString = FormattableString.Invariant($"{_fileName}{date.Year:0000}{date.Month:00}{date.Day:00}.*.txt");
var files = new DirectoryInfo(_path)
.GetFiles(searchString);

return files.Length == 0
? 0
: files
.Max(x => int.TryParse(x.Name.Split('.').ElementAtOrDefault(Index.FromEnd(2)), out var parsed)
? parsed + 1
: 0);
}
}

private string GetFullName(DateTime date)
{
lock (_pathLock)
Expand Down
125 changes: 125 additions & 0 deletions src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,7 @@
using Microsoft.AspNetCore.Testing;
using Microsoft.Extensions.Hosting.Internal;
using Microsoft.Extensions.Logging.Abstractions;
using Microsoft.Extensions.Logging.Testing;
using Microsoft.Net.Http.Headers;
using Xunit;

Expand All @@ -23,6 +24,8 @@ public class FileLoggerProcessorTests
private string _messageOne = "Message one";
private string _messageTwo = "Message two";
private string _messageThree = "Message three";
private string _messageFour = "Message four";
private readonly DateTime _today = DateTime.UtcNow;

public FileLoggerProcessorTests()
{
Expand Down Expand Up @@ -190,6 +193,60 @@ public async Task RespectsMaxFileCount()
}
}

[Fact]
public async Task StopsLoggingAfter10000Files()
{
var path = Path.Combine(TempPath, Path.GetRandomFileName());
Directory.CreateDirectory(path);

try
{
string lastFileName;
var options = new W3CLoggerOptions()
{
LogDirectory = path,
FileSizeLimit = 5,
RetainedFileCountLimit = 10000
};
var testSink = new TestSink();
var testLogger = new TestLoggerFactory(testSink, enabled:true);
await using (var logger = new FileLoggerProcessor(new OptionsWrapperMonitor<W3CLoggerOptions>(options), new HostingEnvironment(), testLogger))
{
for (int i = 0; i < 10000; i++)
{
logger.EnqueueMessage(_messageOne);
}
lastFileName = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{_today.Year:0000}{_today.Month:00}{_today.Day:00}.9999.txt"));
await WaitForFile(lastFileName, _messageOne.Length).DefaultTimeout();

// directory is full, no warnings yet
Assert.Equal(0, testSink.Writes.Count);

logger.EnqueueMessage(_messageOne);
await WaitForCondition(() => testSink.Writes.FirstOrDefault()?.EventId.Name == "MaxFilesReached").DefaultTimeout();
}

Assert.Equal(10000, new DirectoryInfo(path)
.GetFiles()
.ToArray().Length);

// restarting the logger should do nothing since the folder is still full
var testSink2 = new TestSink();
var testLogger2 = new TestLoggerFactory(testSink2, enabled:true);
await using (var logger = new FileLoggerProcessor(new OptionsWrapperMonitor<W3CLoggerOptions>(options), new HostingEnvironment(), testLogger2))
{
Assert.Equal(0, testSink2.Writes.Count);

logger.EnqueueMessage(_messageOne);
await WaitForCondition(() => testSink2.Writes.FirstOrDefault()?.EventId.Name == "MaxFilesReached").DefaultTimeout();
}
}
finally
{
Helpers.DisposeDirectory(path);
}
}

[Fact]
public async Task InstancesWriteToSameDirectory()
{
Expand Down Expand Up @@ -340,6 +397,66 @@ public async Task WritesToNewFileOnNewInstance()
}
}

[Fact]
public async Task RollsTextFilesWhenFirstLogOfDayIsMissing()
{
var path = Path.Combine(TempPath, Path.GetRandomFileName());
Directory.CreateDirectory(path);

try
{
var options = new W3CLoggerOptions()
{
LogDirectory = path,
FileSizeLimit = 5,
RetainedFileCountLimit = 2,
};
var fileName1 = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{_today.Year:0000}{_today.Month:00}{_today.Day:00}.0000.txt"));
var fileName2 = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{_today.Year:0000}{_today.Month:00}{_today.Day:00}.0001.txt"));
var fileName3 = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{_today.Year:0000}{_today.Month:00}{_today.Day:00}.0002.txt"));
var fileName4 = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{_today.Year:0000}{_today.Month:00}{_today.Day:00}.0003.txt"));

await using (var logger = new FileLoggerProcessor(new OptionsWrapperMonitor<W3CLoggerOptions>(options), new HostingEnvironment(), NullLoggerFactory.Instance))
{
logger.EnqueueMessage(_messageOne);
logger.EnqueueMessage(_messageTwo);
logger.EnqueueMessage(_messageThree);
// Pause for a bit before disposing so logger can finish logging
await WaitForFile(fileName3, _messageThree.Length).DefaultTimeout();
}

// Even with a big enough FileSizeLimit, we still won't try to write to files from a previous instance.
options.FileSizeLimit = 10000;

await using (var logger = new FileLoggerProcessor(new OptionsWrapperMonitor<W3CLoggerOptions>(options), new HostingEnvironment(), NullLoggerFactory.Instance))
{
logger.EnqueueMessage(_messageFour);
// Pause for a bit before disposing so logger can finish logging
await WaitForFile(fileName4, _messageFour.Length).DefaultTimeout();
}

var actualFiles = new DirectoryInfo(path)
.GetFiles()
.Select(f => f.Name)
.OrderBy(f => f)
.ToArray();

Assert.Equal(2, actualFiles.Length);

Assert.False(File.Exists(fileName1));
Assert.False(File.Exists(fileName2));
Assert.True(File.Exists(fileName3));
Assert.True(File.Exists(fileName4));

Assert.Equal(_messageThree + Environment.NewLine, File.ReadAllText(fileName3));
Assert.Equal(_messageFour + Environment.NewLine, File.ReadAllText(fileName4));
}
finally
{
Helpers.DisposeDirectory(path);
}
}

[QuarantinedTest("https://github.com/dotnet/aspnetcore/issues/34982")]
[Fact]
public async Task WritesToNewFileOnOptionsChange()
Expand Down Expand Up @@ -420,6 +537,14 @@ private async Task WaitForFile(string fileName, int length)
}
}

private async Task WaitForCondition(Func<bool> waitForLog)
{
while (!waitForLog())
{
await Task.Delay(10);
}
}

private async Task WaitForRoll(string fileName)
{
while (File.Exists(fileName))
Expand Down