diff --git a/src/Middleware/HttpLogging/src/FileLoggerProcessor.cs b/src/Middleware/HttpLogging/src/FileLoggerProcessor.cs index 9f0e4f5821ba..43762020243e 100644 --- a/src/Middleware/HttpLogging/src/FileLoggerProcessor.cs +++ b/src/Middleware/HttpLogging/src/FileLoggerProcessor.cs @@ -30,7 +30,7 @@ internal partial class FileLoggerProcessor : IAsyncDisposable private bool _maxFilesReached; private TimeSpan _flushInterval; private W3CLoggingFields _fields; - private DateTime _today = DateTime.Now; + private DateTime _today; private bool _firstFile = true; private readonly IOptionsMonitor _options; @@ -40,6 +40,9 @@ internal partial class FileLoggerProcessor : IAsyncDisposable private readonly Task _outputTask; private readonly CancellationTokenSource _cancellationTokenSource; + // Internal to allow for testing + internal ISystemDateTime SystemDateTime {get; set;} = new SystemDateTime(); + private readonly object _pathLock = new object(); public FileLoggerProcessor(IOptionsMonitor options, IHostEnvironment environment, ILoggerFactory factory) @@ -98,6 +101,8 @@ public FileLoggerProcessor(IOptionsMonitor options, IHostEnvir } }); + _today = SystemDateTime.Now; + // Start message queue processor _cancellationTokenSource = new CancellationTokenSource(); _outputTask = Task.Run(ProcessLogQueue); @@ -155,7 +160,7 @@ private async Task ProcessLogQueue() private async Task WriteMessagesAsync(List messages, CancellationToken cancellationToken) { // Files are written up to _maxFileSize before rolling to a new file - DateTime today = DateTime.Now; + DateTime today = SystemDateTime.Now; var fullName = GetFullName(today); // Don't write to an incomplete file left around by a previous FileLoggerProcessor if (_firstFile) diff --git a/src/Middleware/HttpLogging/src/ISystemDateTime.cs b/src/Middleware/HttpLogging/src/ISystemDateTime.cs new file mode 100644 index 000000000000..654a42852c45 --- /dev/null +++ b/src/Middleware/HttpLogging/src/ISystemDateTime.cs @@ -0,0 +1,13 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +namespace Microsoft.AspNetCore.HttpLogging +{ + internal interface ISystemDateTime + { + /// + /// Retrieves the date and time currently set for this machine. + /// + DateTime Now { get; } + } +} diff --git a/src/Middleware/HttpLogging/src/SystemDateTime.cs b/src/Middleware/HttpLogging/src/SystemDateTime.cs new file mode 100644 index 000000000000..ca786711a127 --- /dev/null +++ b/src/Middleware/HttpLogging/src/SystemDateTime.cs @@ -0,0 +1,10 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +namespace Microsoft.AspNetCore.HttpLogging +{ + internal class SystemDateTime : ISystemDateTime + { + public DateTime Now => DateTime.Now; + } +} diff --git a/src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs b/src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs index 8ab807f87f63..f667381c1923 100644 --- a/src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs +++ b/src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs @@ -24,6 +24,8 @@ public class FileLoggerProcessorTests private string _messageTwo = "Message two"; private string _messageThree = "Message three"; + private DateTime _today = new DateTime(2021, 01, 01, 12, 00, 00); + public FileLoggerProcessorTests() { TempPath = Path.GetTempFileName() + "_"; @@ -33,35 +35,27 @@ public FileLoggerProcessorTests() [Fact] public async Task WritesToTextFile() - { + { + var mockSystemDateTime = new MockSystemDateTime + { + Now = _today + }; var path = Path.Combine(TempPath, Path.GetRandomFileName()); try { string fileName; - var now = DateTimeOffset.Now; var options = new W3CLoggerOptions() { LogDirectory = path }; await using (var logger = new FileLoggerProcessor(new OptionsWrapperMonitor(options), new HostingEnvironment(), NullLoggerFactory.Instance)) { + logger.SystemDateTime = mockSystemDateTime; logger.EnqueueMessage(_messageOne); - fileName = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{now.Year:0000}{now.Month:00}{now.Day:00}.0000.txt")); + fileName = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{_today.Year:0000}{_today.Month:00}{_today.Day:00}.0000.txt")); // Pause for a bit before disposing so logger can finish logging - try - { - await WaitForFile(fileName, _messageOne.Length).DefaultTimeout(); - } - catch - { - // Midnight could have struck between taking the DateTime & writing the log - if (!File.Exists(fileName)) - { - var tomorrow = now.AddDays(1); - fileName = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{tomorrow.Year:0000}{tomorrow.Month:00}{tomorrow.Day:00}.0000.txt")); - } - } + await WaitForFile(fileName, _messageOne.Length).DefaultTimeout(); } Assert.True(File.Exists(fileName)); @@ -73,17 +67,68 @@ public async Task WritesToTextFile() } } + [Fact] + public async Task RollsTextFilesBasedOnDate() + { + var mockSystemDateTime = new MockSystemDateTime + { + Now = _today + }; + var tomorrow = _today.AddDays(1); + + var path = Path.Combine(TempPath, Path.GetRandomFileName()); + var options = new W3CLoggerOptions() + { + LogDirectory = path + }; + + try + { + string fileNameToday; + string fileNameTomorrow; + + await using (var logger = new FileLoggerProcessor(new OptionsWrapperMonitor(options), new HostingEnvironment(), NullLoggerFactory.Instance)) + { + logger.SystemDateTime = mockSystemDateTime; + logger.EnqueueMessage(_messageOne); + + fileNameToday = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{_today.Year:0000}{_today.Month:00}{_today.Day:00}.0000.txt")); + + await WaitForFile(fileNameToday, _messageOne.Length).DefaultTimeout(); + + mockSystemDateTime.Now = tomorrow; + logger.EnqueueMessage(_messageTwo); + + fileNameTomorrow = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{tomorrow.Year:0000}{tomorrow.Month:00}{tomorrow.Day:00}.0000.txt")); + + await WaitForFile(fileNameTomorrow, _messageTwo.Length).DefaultTimeout(); + } + + Assert.True(File.Exists(fileNameToday)); + Assert.Equal(_messageOne + Environment.NewLine, File.ReadAllText(fileNameToday)); + Assert.True(File.Exists(fileNameTomorrow)); + Assert.Equal(_messageTwo + Environment.NewLine, File.ReadAllText(fileNameTomorrow)); + } + finally + { + Helpers.DisposeDirectory(path); + } + } + [QuarantinedTest("https://github.com/dotnet/aspnetcore/issues/34284")] [Fact] - public async Task RollsTextFiles() + public async Task RollsTextFilesBasedOnSize() { var path = Path.Combine(TempPath, Path.GetRandomFileName()); try { string fileName1; - string fileName2; - var now = DateTimeOffset.Now; + string fileName2; + var mockSystemDateTime = new MockSystemDateTime + { + Now = _today + }; var options = new W3CLoggerOptions() { LogDirectory = path, @@ -91,30 +136,13 @@ public async Task RollsTextFiles() }; await using (var logger = new FileLoggerProcessor(new OptionsWrapperMonitor(options), new HostingEnvironment(), NullLoggerFactory.Instance)) { + logger.SystemDateTime = mockSystemDateTime; logger.EnqueueMessage(_messageOne); logger.EnqueueMessage(_messageTwo); - fileName1 = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{now.Year:0000}{now.Month:00}{now.Day:00}.0000.txt")); - fileName2 = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{now.Year:0000}{now.Month:00}{now.Day:00}.0001.txt")); + fileName1 = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{_today.Year:0000}{_today.Month:00}{_today.Day:00}.0000.txt")); + fileName2 = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{_today.Year:0000}{_today.Month:00}{_today.Day:00}.0001.txt")); // Pause for a bit before disposing so logger can finish logging - try - { - await WaitForFile(fileName2, _messageTwo.Length).DefaultTimeout(); - } - catch - { - // Midnight could have struck between taking the DateTime & writing the log - // It also could have struck between writing file 1 & file 2 - var tomorrow = now.AddDays(1); - if (!File.Exists(fileName1)) - { - fileName1 = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{tomorrow.Year:0000}{tomorrow.Month:00}{tomorrow.Day:00}.0000.txt")); - fileName2 = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{tomorrow.Year:0000}{tomorrow.Month:00}{tomorrow.Day:00}.0001.txt")); - } - else if (!File.Exists(fileName2)) - { - fileName2 = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{tomorrow.Year:0000}{tomorrow.Month:00}{tomorrow.Day:00}.0000.txt")); - } - } + await WaitForFile(fileName2, _messageTwo.Length).DefaultTimeout(); } Assert.True(File.Exists(fileName1)); Assert.True(File.Exists(fileName2)); @@ -133,13 +161,15 @@ public async Task RespectsMaxFileCount() { var path = Path.Combine(TempPath, Path.GetRandomFileName()); Directory.CreateDirectory(path); - File.WriteAllText(Path.Combine(path, "randomFile.txt"), "Text"); + File.WriteAllText(Path.Combine(path, "randomFile.txt"), "Text"); + var mockSystemDateTime = new MockSystemDateTime + { + Now = _today + }; try { string lastFileName; - var now = DateTimeOffset.Now; - var tomorrow = now.AddDays(1); var options = new W3CLoggerOptions() { LogDirectory = path, @@ -148,25 +178,17 @@ public async Task RespectsMaxFileCount() }; await using (var logger = new FileLoggerProcessor(new OptionsWrapperMonitor(options), new HostingEnvironment(), NullLoggerFactory.Instance)) { + logger.SystemDateTime = mockSystemDateTime; for (int i = 0; i < 10; i++) { logger.EnqueueMessage(_messageOne); } - lastFileName = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{now.Year:0000}{now.Month:00}{now.Day:00}.0009.txt")); + lastFileName = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{_today.Year:0000}{_today.Month:00}{_today.Day:00}.0009.txt")); // Pause for a bit before disposing so logger can finish logging - try + await WaitForFile(lastFileName, _messageOne.Length).DefaultTimeout(); + for (int i = 0; i < 6; i++) { - await WaitForFile(lastFileName, _messageOne.Length).DefaultTimeout(); - for (int i = 0; i < 6; i++) - { - await WaitForRoll(Path.Combine(path, FormattableString.Invariant($"{options.FileName}{now.Year:0000}{now.Month:00}{now.Day:00}.{i:0000}.txt"))).DefaultTimeout(); - } - } - catch - { - // Midnight could have struck between taking the DateTime & writing the log. - // It also could have struck any time after writing the first file. - // So we keep going even if waiting timed out, in case we're wrong about the assumed file name + await WaitForRoll(Path.Combine(path, FormattableString.Invariant($"{options.FileName}{_today.Year:0000}{_today.Month:00}{_today.Day:00}.{i:0000}.txt"))).DefaultTimeout(); } } @@ -180,9 +202,7 @@ public async Task RespectsMaxFileCount() Assert.Equal("randomFile.txt", actualFiles[0]); for (int i = 1; i < 4; i++) { - // File name will either start with today's date or tomorrow's date (if midnight struck during the execution of the test) - Assert.True((actualFiles[i].StartsWith($"{options.FileName}{now.Year:0000}{now.Month:00}{now.Day:00}", StringComparison.InvariantCulture)) || - (actualFiles[i].StartsWith($"{options.FileName}{tomorrow.Year:0000}{tomorrow.Month:00}{tomorrow.Day:00}", StringComparison.InvariantCulture))); + Assert.True((actualFiles[i].StartsWith($"{options.FileName}{_today.Year:0000}{_today.Month:00}{_today.Day:00}", StringComparison.InvariantCulture))); } } finally @@ -193,13 +213,11 @@ public async Task RespectsMaxFileCount() [Fact] public async Task InstancesWriteToSameDirectory() - { - var now = DateTimeOffset.Now; - if (now.Hour == 23) + { + var mockSystemDateTime = new MockSystemDateTime { - // Don't bother trying to run this test when it's almost midnight. - return; - } + Now = _today + }; var path = Path.Combine(TempPath, Path.GetRandomFileName()); Directory.CreateDirectory(path); @@ -214,11 +232,12 @@ public async Task InstancesWriteToSameDirectory() }; await using (var logger = new FileLoggerProcessor(new OptionsWrapperMonitor(options), new HostingEnvironment(), NullLoggerFactory.Instance)) { + logger.SystemDateTime = mockSystemDateTime; for (int i = 0; i < 3; i++) { logger.EnqueueMessage(_messageOne); } - var filePath = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{now.Year:0000}{now.Month:00}{now.Day:00}.0002.txt")); + var filePath = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{_today.Year:0000}{_today.Month:00}{_today.Day:00}.0002.txt")); // Pause for a bit before disposing so logger can finish logging await WaitForFile(filePath, _messageOne.Length).DefaultTimeout(); } @@ -226,11 +245,12 @@ public async Task InstancesWriteToSameDirectory() // Second instance should pick up where first one left off await using (var logger = new FileLoggerProcessor(new OptionsWrapperMonitor(options), new HostingEnvironment(), NullLoggerFactory.Instance)) { + logger.SystemDateTime = mockSystemDateTime; for (int i = 0; i < 3; i++) { logger.EnqueueMessage(_messageOne); } - var filePath = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{now.Year:0000}{now.Month:00}{now.Day:00}.0005.txt")); + var filePath = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{_today.Year:0000}{_today.Month:00}{_today.Day:00}.0005.txt")); // Pause for a bit before disposing so logger can finish logging await WaitForFile(filePath, _messageOne.Length).DefaultTimeout(); } @@ -244,18 +264,19 @@ public async Task InstancesWriteToSameDirectory() Assert.Equal(6, actualFiles1.Length); for (int i = 0; i < 6; i++) { - Assert.Contains($"{options.FileName}{now.Year:0000}{now.Month:00}{now.Day:00}.{i:0000}.txt", actualFiles1[i]); + Assert.Contains($"{options.FileName}{_today.Year:0000}{_today.Month:00}{_today.Day:00}.{i:0000}.txt", actualFiles1[i]); } // Third instance should roll to 5 most recent files options.RetainedFileCountLimit = 5; await using (var logger = new FileLoggerProcessor(new OptionsWrapperMonitor(options), new HostingEnvironment(), NullLoggerFactory.Instance)) { + logger.SystemDateTime = mockSystemDateTime; logger.EnqueueMessage(_messageOne); // Pause for a bit before disposing so logger can finish logging - await WaitForFile(Path.Combine(path, FormattableString.Invariant($"{options.FileName}{now.Year:0000}{now.Month:00}{now.Day:00}.0006.txt")), _messageOne.Length).DefaultTimeout(); - await WaitForRoll(Path.Combine(path, FormattableString.Invariant($"{options.FileName}{now.Year:0000}{now.Month:00}{now.Day:00}.0000.txt"))).DefaultTimeout(); - await WaitForRoll(Path.Combine(path, FormattableString.Invariant($"{options.FileName}{now.Year:0000}{now.Month:00}{now.Day:00}.0001.txt"))).DefaultTimeout(); + await WaitForFile(Path.Combine(path, FormattableString.Invariant($"{options.FileName}{_today.Year:0000}{_today.Month:00}{_today.Day:00}.0006.txt")), _messageOne.Length).DefaultTimeout(); + await WaitForRoll(Path.Combine(path, FormattableString.Invariant($"{options.FileName}{_today.Year:0000}{_today.Month:00}{_today.Day:00}.0000.txt"))).DefaultTimeout(); + await WaitForRoll(Path.Combine(path, FormattableString.Invariant($"{options.FileName}{_today.Year:0000}{_today.Month:00}{_today.Day:00}.0001.txt"))).DefaultTimeout(); } var actualFiles2 = new DirectoryInfo(path) @@ -267,7 +288,7 @@ public async Task InstancesWriteToSameDirectory() Assert.Equal(5, actualFiles2.Length); for (int i = 0; i < 5; i++) { - Assert.Equal($"{options.FileName}{now.Year:0000}{now.Month:00}{now.Day:00}.{i + 2:0000}.txt", actualFiles2[i]); + Assert.Equal($"{options.FileName}{_today.Year:0000}{_today.Month:00}{_today.Day:00}.{i + 2:0000}.txt", actualFiles2[i]); } } finally @@ -279,12 +300,10 @@ public async Task InstancesWriteToSameDirectory() [Fact] public async Task WritesToNewFileOnNewInstance() { - var now = DateTimeOffset.Now; - if (now.Hour == 23) + var mockSystemDateTime = new MockSystemDateTime { - // Don't bother trying to run this test when it's almost midnight. - return; - } + Now = _today + }; var path = Path.Combine(TempPath, Path.GetRandomFileName()); Directory.CreateDirectory(path); @@ -296,12 +315,13 @@ public async Task WritesToNewFileOnNewInstance() LogDirectory = path, FileSizeLimit = 5 }; - var fileName1 = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{now.Year:0000}{now.Month:00}{now.Day:00}.0000.txt")); - var fileName2 = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{now.Year:0000}{now.Month:00}{now.Day:00}.0001.txt")); - var fileName3 = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{now.Year:0000}{now.Month:00}{now.Day:00}.0002.txt")); + 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")); await using (var logger = new FileLoggerProcessor(new OptionsWrapperMonitor(options), new HostingEnvironment(), NullLoggerFactory.Instance)) { + logger.SystemDateTime = mockSystemDateTime; logger.EnqueueMessage(_messageOne); logger.EnqueueMessage(_messageTwo); // Pause for a bit before disposing so logger can finish logging @@ -313,6 +333,7 @@ public async Task WritesToNewFileOnNewInstance() await using (var logger = new FileLoggerProcessor(new OptionsWrapperMonitor(options), new HostingEnvironment(), NullLoggerFactory.Instance)) { + logger.SystemDateTime = mockSystemDateTime; logger.EnqueueMessage(_messageThree); // Pause for a bit before disposing so logger can finish logging await WaitForFile(fileName3, _messageThree.Length).DefaultTimeout(); @@ -343,12 +364,10 @@ public async Task WritesToNewFileOnNewInstance() [Fact] public async Task WritesToNewFileOnOptionsChange() { - var now = DateTimeOffset.Now; - if (now.Hour == 23) + var mockSystemDateTime = new MockSystemDateTime { - // Don't bother trying to run this test when it's almost midnight. - return; - } + Now = _today + }; var path = Path.Combine(TempPath, Path.GetRandomFileName()); Directory.CreateDirectory(path); @@ -361,12 +380,13 @@ public async Task WritesToNewFileOnOptionsChange() LoggingFields = W3CLoggingFields.Time, FileSizeLimit = 10000 }; - var fileName1 = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{now.Year:0000}{now.Month:00}{now.Day:00}.0000.txt")); - var fileName2 = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{now.Year:0000}{now.Month:00}{now.Day:00}.0001.txt")); + 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 monitor = new OptionsWrapperMonitor(options); await using (var logger = new FileLoggerProcessor(monitor, new HostingEnvironment(), NullLoggerFactory.Instance)) { + logger.SystemDateTime = mockSystemDateTime; logger.EnqueueMessage(_messageOne); await WaitForFile(fileName1, _messageOne.Length).DefaultTimeout(); options.LoggingFields = W3CLoggingFields.Date; diff --git a/src/Middleware/HttpLogging/test/MockSystemDateTime.cs b/src/Middleware/HttpLogging/test/MockSystemDateTime.cs new file mode 100644 index 000000000000..17f8d3face67 --- /dev/null +++ b/src/Middleware/HttpLogging/test/MockSystemDateTime.cs @@ -0,0 +1,10 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +namespace Microsoft.AspNetCore.HttpLogging +{ + internal class MockSystemDateTime : ISystemDateTime + { + public DateTime Now { get; set; } + } +}