diff --git a/src/Middleware/HttpLogging/src/FileLoggerProcessor.cs b/src/Middleware/HttpLogging/src/FileLoggerProcessor.cs index 9f0e4f5821ba7864f78081d77c1ef8999c7802e8..60b4a6265867012f1c1cda8d497738d3f843dfc1 100644 --- a/src/Middleware/HttpLogging/src/FileLoggerProcessor.cs +++ b/src/Middleware/HttpLogging/src/FileLoggerProcessor.cs @@ -156,23 +156,28 @@ namespace Microsoft.AspNetCore.HttpLogging { // 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) { @@ -300,6 +305,23 @@ namespace Microsoft.AspNetCore.HttpLogging 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) diff --git a/src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs b/src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs index b051337a5c7d80e2e5d63625ebed36928c392d4d..fd00142756f4524ff07fdcc5d080909e2b86db3a 100644 --- a/src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs +++ b/src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs @@ -12,6 +12,7 @@ using Microsoft.AspNetCore.Http; 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; @@ -23,6 +24,8 @@ namespace Microsoft.AspNetCore.HttpLogging 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() { @@ -190,6 +193,60 @@ namespace Microsoft.AspNetCore.HttpLogging } } + [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() { @@ -340,6 +397,66 @@ namespace Microsoft.AspNetCore.HttpLogging } } + [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() @@ -420,6 +537,14 @@ namespace Microsoft.AspNetCore.HttpLogging } } + private async Task WaitForCondition(Func<bool> waitForLog) + { + while (!waitForLog()) + { + await Task.Delay(10); + } + } + private async Task WaitForRoll(string fileName) { while (File.Exists(fileName))