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

Author: dustinsoftware

src/Middleware/HttpLogging/src/FileLoggerProcessor.cs

@@ -152,23 +152,28 @@ private async Task WriteMessagesAsync(List<string> 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<string> 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)

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<W3CLoggerOptions>(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<W3CLoggerOptions>(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<W3CLoggerOptions>(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<W3CLoggerOptions>(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<bool> waitForLog)
+    {
+        while (!waitForLog())
+        {
+            await Task.Delay(10);
+        }
+    }
+
     private async Task WaitForRoll(string fileName)
     {
         while (File.Exists(fileName))