From 5c65eb58ca43be4354a6c4e6dad2201b087364c1 Mon Sep 17 00:00:00 2001 From: Dustin Masters Date: Tue, 26 Apr 2022 11:09:16 -0400 Subject: [PATCH] Determine next log file number from directory on first run --- .../HttpLogging/src/FileLoggerProcessor.cs | 48 ++++-- .../test/FileLoggerProcessorTests.cs | 137 ++++++++++++++++++ 2 files changed, 169 insertions(+), 16 deletions(-) diff --git a/src/Middleware/HttpLogging/src/FileLoggerProcessor.cs b/src/Middleware/HttpLogging/src/FileLoggerProcessor.cs index f6b5a1804da7..b3ab3dff727e 100644 --- a/src/Middleware/HttpLogging/src/FileLoggerProcessor.cs +++ b/src/Middleware/HttpLogging/src/FileLoggerProcessor.cs @@ -152,23 +152,28 @@ private async Task WriteMessagesAsync(List messages, CancellationToken c { // Files are written up to _maxFileSize before rolling to a new file DateTime today = SystemDateTime.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) { @@ -178,12 +183,6 @@ private async Task WriteMessagesAsync(List messages, CancellationToken c return; } var fileInfo = new FileInfo(fullName); - - if (!TryCreateDirectory()) - { - // return early if we fail to create the directory - return; - } var streamWriter = GetStreamWriter(fullName); try @@ -296,6 +295,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) diff --git a/src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs b/src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs index beb24a9ddd7e..59811d02a0da 100644 --- a/src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs +++ b/src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs @@ -1,9 +1,11 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. +using System.Collections.Concurrent; using Microsoft.AspNetCore.Testing; using Microsoft.Extensions.Hosting.Internal; using Microsoft.Extensions.Logging.Abstractions; +using Microsoft.Extensions.Logging.Testing; namespace Microsoft.AspNetCore.HttpLogging; @@ -13,6 +15,7 @@ public class FileLoggerProcessorTests private string _messageOne = "Message one"; private string _messageTwo = "Message two"; private string _messageThree = "Message three"; + private string _messageFour = "Message four"; private DateTime _today = new DateTime(2021, 01, 01, 12, 00, 00); @@ -200,6 +203,66 @@ public async Task RespectsMaxFileCount() } } + [Fact] + public async Task StopsLoggingAfter10000Files() + { + var path = Path.Combine(TempPath, Path.GetRandomFileName()); + Directory.CreateDirectory(path); + var mockSystemDateTime = new MockSystemDateTime + { + Now = _today + }; + + 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(options), new HostingEnvironment(), testLogger)) + { + logger.SystemDateTime = mockSystemDateTime; + 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(options), new HostingEnvironment(), testLogger2)) + { + Assert.Equal(0, testSink2.Writes.Count); + + logger.SystemDateTime = mockSystemDateTime; + logger.EnqueueMessage(_messageOne); + await WaitForCondition(() => testSink2.Writes.FirstOrDefault()?.EventId.Name == "MaxFilesReached").DefaultTimeout(); + } + } + finally + { + Helpers.DisposeDirectory(path); + } + } + [Fact] public async Task InstancesWriteToSameDirectory() { @@ -349,6 +412,72 @@ public async Task WritesToNewFileOnNewInstance() Helpers.DisposeDirectory(path); } } + [Fact] + public async Task RollsTextFilesWhenFirstLogOfDayIsMissing() + { + var mockSystemDateTime = new MockSystemDateTime + { + Now = _today + }; + + 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(options), new HostingEnvironment(), NullLoggerFactory.Instance)) + { + logger.SystemDateTime = mockSystemDateTime; + 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(options), new HostingEnvironment(), NullLoggerFactory.Instance)) + { + logger.SystemDateTime = mockSystemDateTime; + 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); + } + } [Fact] public async Task WritesToNewFileOnOptionsChange() @@ -428,6 +557,14 @@ private async Task WaitForFile(string fileName, int length) } } + private async Task WaitForCondition(Func waitForLog) + { + while (!waitForLog()) + { + await Task.Delay(10); + } + } + private async Task WaitForRoll(string fileName) { while (File.Exists(fileName))