From 09d3380092531d76966e4f80cf3f278b78d7672e Mon Sep 17 00:00:00 2001 From: Benedikt Date: Tue, 17 Aug 2021 22:37:01 +0200 Subject: [PATCH 1/3] Make FileLoggerProcessTests systemtime independent --- .../HttpLogging/src/FileLoggerProcessor.cs | 9 +- .../HttpLogging/src/ISystemDateTime.cs | 6 + .../HttpLogging/src/SystemDateTime.cs | 10 ++ .../test/FileLoggerProcessorTests.cs | 140 ++++++++---------- .../HttpLogging/test/MockSystemDateTime.cs | 10 ++ 5 files changed, 91 insertions(+), 84 deletions(-) create mode 100644 src/Middleware/HttpLogging/src/ISystemDateTime.cs create mode 100644 src/Middleware/HttpLogging/src/SystemDateTime.cs create mode 100644 src/Middleware/HttpLogging/test/MockSystemDateTime.cs 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..cfe992ee60c1 --- /dev/null +++ b/src/Middleware/HttpLogging/src/ISystemDateTime.cs @@ -0,0 +1,6 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +internal interface ISystemDateTime { + DateTime Now { get; } +} \ No newline at end of file diff --git a/src/Middleware/HttpLogging/src/SystemDateTime.cs b/src/Middleware/HttpLogging/src/SystemDateTime.cs new file mode 100644 index 000000000000..2806d11a6a04 --- /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; + } +} \ No newline at end of file diff --git a/src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs b/src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs index 8ab807f87f63..6ba2f22c9e3e 100644 --- a/src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs +++ b/src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs @@ -34,34 +34,27 @@ public FileLoggerProcessorTests() [Fact] public async Task WritesToTextFile() { + var today = new DateTime(2021, 01, 01, 12, 00, 00); + 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)); @@ -83,7 +76,11 @@ public async Task RollsTextFiles() { string fileName1; string fileName2; - var now = DateTimeOffset.Now; + var today = new DateTime(2021, 01, 01, 12, 00, 00); + var mockSystemDateTime = new MockSystemDateTime + { + Now = today + }; var options = new W3CLoggerOptions() { LogDirectory = path, @@ -91,30 +88,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)); @@ -134,12 +114,15 @@ public async Task RespectsMaxFileCount() var path = Path.Combine(TempPath, Path.GetRandomFileName()); Directory.CreateDirectory(path); File.WriteAllText(Path.Combine(path, "randomFile.txt"), "Text"); + var today = new DateTime(2021, 01, 01, 12, 00, 00); + 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 +131,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 +155,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 @@ -194,12 +167,11 @@ public async Task RespectsMaxFileCount() [Fact] public async Task InstancesWriteToSameDirectory() { - var now = DateTimeOffset.Now; - if (now.Hour == 23) + var today = new DateTime(2021, 01, 01, 12, 00, 00); + 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 +186,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 +199,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 +218,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 +242,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 +254,11 @@ public async Task InstancesWriteToSameDirectory() [Fact] public async Task WritesToNewFileOnNewInstance() { - var now = DateTimeOffset.Now; - if (now.Hour == 23) + var today = new DateTime(2021, 01, 01, 12, 00, 00); + 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 +270,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 +288,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 +319,11 @@ public async Task WritesToNewFileOnNewInstance() [Fact] public async Task WritesToNewFileOnOptionsChange() { - var now = DateTimeOffset.Now; - if (now.Hour == 23) + var today = new DateTime(2021, 01, 01, 12, 00, 00); + 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 +336,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..002ccae2dee7 --- /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; } + } +} \ No newline at end of file From 89be4321a4425ed018ae33ee932c9a2767c25fa8 Mon Sep 17 00:00:00 2001 From: Benedikt Date: Wed, 18 Aug 2021 10:50:06 +0200 Subject: [PATCH 2/3] Added test case for rolling files based on date --- .../HttpLogging/src/ISystemDateTime.cs | 2 +- .../HttpLogging/src/SystemDateTime.cs | 2 +- .../test/FileLoggerProcessorTests.cs | 114 ++++++++++++------ .../HttpLogging/test/MockSystemDateTime.cs | 2 +- 4 files changed, 82 insertions(+), 38 deletions(-) diff --git a/src/Middleware/HttpLogging/src/ISystemDateTime.cs b/src/Middleware/HttpLogging/src/ISystemDateTime.cs index cfe992ee60c1..750b1451cfd7 100644 --- a/src/Middleware/HttpLogging/src/ISystemDateTime.cs +++ b/src/Middleware/HttpLogging/src/ISystemDateTime.cs @@ -3,4 +3,4 @@ internal interface ISystemDateTime { DateTime Now { get; } -} \ No newline at end of file +} diff --git a/src/Middleware/HttpLogging/src/SystemDateTime.cs b/src/Middleware/HttpLogging/src/SystemDateTime.cs index 2806d11a6a04..ca786711a127 100644 --- a/src/Middleware/HttpLogging/src/SystemDateTime.cs +++ b/src/Middleware/HttpLogging/src/SystemDateTime.cs @@ -7,4 +7,4 @@ internal class SystemDateTime : ISystemDateTime { public DateTime Now => DateTime.Now; } -} \ No newline at end of file +} diff --git a/src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs b/src/Middleware/HttpLogging/test/FileLoggerProcessorTests.cs index 6ba2f22c9e3e..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,11 +35,10 @@ public FileLoggerProcessorTests() [Fact] public async Task WritesToTextFile() - { - var today = new DateTime(2021, 01, 01, 12, 00, 00); + { var mockSystemDateTime = new MockSystemDateTime { - Now = today + Now = _today }; var path = Path.Combine(TempPath, Path.GetRandomFileName()); @@ -52,7 +53,7 @@ public async Task WritesToTextFile() { logger.SystemDateTime = mockSystemDateTime; logger.EnqueueMessage(_messageOne); - fileName = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{today.Year:0000}{today.Month:00}{today.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 await WaitForFile(fileName, _messageOne.Length).DefaultTimeout(); } @@ -66,20 +67,67 @@ 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 today = new DateTime(2021, 01, 01, 12, 00, 00); + string fileName2; var mockSystemDateTime = new MockSystemDateTime { - Now = today + Now = _today }; var options = new W3CLoggerOptions() { @@ -91,8 +139,8 @@ public async Task RollsTextFiles() logger.SystemDateTime = mockSystemDateTime; logger.EnqueueMessage(_messageOne); logger.EnqueueMessage(_messageTwo); - 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")); + 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 await WaitForFile(fileName2, _messageTwo.Length).DefaultTimeout(); } @@ -113,11 +161,10 @@ public async Task RespectsMaxFileCount() { var path = Path.Combine(TempPath, Path.GetRandomFileName()); Directory.CreateDirectory(path); - File.WriteAllText(Path.Combine(path, "randomFile.txt"), "Text"); - var today = new DateTime(2021, 01, 01, 12, 00, 00); + File.WriteAllText(Path.Combine(path, "randomFile.txt"), "Text"); var mockSystemDateTime = new MockSystemDateTime { - Now = today + Now = _today }; try @@ -136,12 +183,12 @@ public async Task RespectsMaxFileCount() { logger.EnqueueMessage(_messageOne); } - lastFileName = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{today.Year:0000}{today.Month:00}{today.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 await WaitForFile(lastFileName, _messageOne.Length).DefaultTimeout(); for (int i = 0; i < 6; i++) { - await WaitForRoll(Path.Combine(path, FormattableString.Invariant($"{options.FileName}{today.Year:0000}{today.Month:00}{today.Day:00}.{i:0000}.txt"))).DefaultTimeout(); + await WaitForRoll(Path.Combine(path, FormattableString.Invariant($"{options.FileName}{_today.Year:0000}{_today.Month:00}{_today.Day:00}.{i:0000}.txt"))).DefaultTimeout(); } } @@ -155,7 +202,7 @@ public async Task RespectsMaxFileCount() Assert.Equal("randomFile.txt", actualFiles[0]); for (int i = 1; i < 4; i++) { - Assert.True((actualFiles[i].StartsWith($"{options.FileName}{today.Year:0000}{today.Month:00}{today.Day:00}", StringComparison.InvariantCulture))); + Assert.True((actualFiles[i].StartsWith($"{options.FileName}{_today.Year:0000}{_today.Month:00}{_today.Day:00}", StringComparison.InvariantCulture))); } } finally @@ -166,11 +213,10 @@ public async Task RespectsMaxFileCount() [Fact] public async Task InstancesWriteToSameDirectory() - { - var today = new DateTime(2021, 01, 01, 12, 00, 00); + { var mockSystemDateTime = new MockSystemDateTime { - Now = today + Now = _today }; var path = Path.Combine(TempPath, Path.GetRandomFileName()); @@ -191,7 +237,7 @@ public async Task InstancesWriteToSameDirectory() { logger.EnqueueMessage(_messageOne); } - var filePath = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{today.Year:0000}{today.Month:00}{today.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(); } @@ -204,7 +250,7 @@ public async Task InstancesWriteToSameDirectory() { logger.EnqueueMessage(_messageOne); } - var filePath = Path.Combine(path, FormattableString.Invariant($"{options.FileName}{today.Year:0000}{today.Month:00}{today.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(); } @@ -218,7 +264,7 @@ public async Task InstancesWriteToSameDirectory() Assert.Equal(6, actualFiles1.Length); for (int i = 0; i < 6; i++) { - Assert.Contains($"{options.FileName}{today.Year:0000}{today.Month:00}{today.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 @@ -228,9 +274,9 @@ public async Task InstancesWriteToSameDirectory() 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}{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(); + 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) @@ -242,7 +288,7 @@ public async Task InstancesWriteToSameDirectory() Assert.Equal(5, actualFiles2.Length); for (int i = 0; i < 5; i++) { - Assert.Equal($"{options.FileName}{today.Year:0000}{today.Month:00}{today.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 @@ -254,10 +300,9 @@ public async Task InstancesWriteToSameDirectory() [Fact] public async Task WritesToNewFileOnNewInstance() { - var today = new DateTime(2021, 01, 01, 12, 00, 00); var mockSystemDateTime = new MockSystemDateTime { - Now = today + Now = _today }; var path = Path.Combine(TempPath, Path.GetRandomFileName()); @@ -270,9 +315,9 @@ public async Task WritesToNewFileOnNewInstance() LogDirectory = path, FileSizeLimit = 5 }; - 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 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)) { @@ -319,10 +364,9 @@ public async Task WritesToNewFileOnNewInstance() [Fact] public async Task WritesToNewFileOnOptionsChange() { - var today = new DateTime(2021, 01, 01, 12, 00, 00); var mockSystemDateTime = new MockSystemDateTime { - Now = today + Now = _today }; var path = Path.Combine(TempPath, Path.GetRandomFileName()); @@ -336,8 +380,8 @@ public async Task WritesToNewFileOnOptionsChange() LoggingFields = W3CLoggingFields.Time, FileSizeLimit = 10000 }; - 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 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)) diff --git a/src/Middleware/HttpLogging/test/MockSystemDateTime.cs b/src/Middleware/HttpLogging/test/MockSystemDateTime.cs index 002ccae2dee7..17f8d3face67 100644 --- a/src/Middleware/HttpLogging/test/MockSystemDateTime.cs +++ b/src/Middleware/HttpLogging/test/MockSystemDateTime.cs @@ -7,4 +7,4 @@ internal class MockSystemDateTime : ISystemDateTime { public DateTime Now { get; set; } } -} \ No newline at end of file +} From 20bafa8bd484141626d92a311b790ada3ebacaff Mon Sep 17 00:00:00 2001 From: Benedikt Date: Sat, 23 Oct 2021 22:13:31 +0200 Subject: [PATCH 3/3] add summary & namespace --- src/Middleware/HttpLogging/src/ISystemDateTime.cs | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/src/Middleware/HttpLogging/src/ISystemDateTime.cs b/src/Middleware/HttpLogging/src/ISystemDateTime.cs index 750b1451cfd7..654a42852c45 100644 --- a/src/Middleware/HttpLogging/src/ISystemDateTime.cs +++ b/src/Middleware/HttpLogging/src/ISystemDateTime.cs @@ -1,6 +1,13 @@ // Licensed to the .NET Foundation under one or more agreements. // The .NET Foundation licenses this file to you under the MIT license. -internal interface ISystemDateTime { - DateTime Now { get; } +namespace Microsoft.AspNetCore.HttpLogging +{ + internal interface ISystemDateTime + { + /// + /// Retrieves the date and time currently set for this machine. + /// + DateTime Now { get; } + } }