Determine next log file number from directory on first run (#41492)

Author: dustinsoftware

src/Middleware/HttpLogging/src/FileLoggerProcessor.cs

@@ -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)
             {
@@ -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)

src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs

@@ -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;
 
@@ -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()
         {
@@ -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()
         {
@@ -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()
@@ -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))