diff --git a/src/AspNetCoreModuleV2/CommonLib/FileOutputManager.cpp b/src/AspNetCoreModuleV2/CommonLib/FileOutputManager.cpp index 6e16ac2acd..15bc54cbe6 100644 --- a/src/AspNetCoreModuleV2/CommonLib/FileOutputManager.cpp +++ b/src/AspNetCoreModuleV2/CommonLib/FileOutputManager.cpp @@ -47,6 +47,8 @@ FileOutputManager::Start() SYSTEMTIME systemTime; SECURITY_ATTRIBUTES saAttr = { 0 }; STRU struPath; + FILETIME processCreationTime; + FILETIME dummyFileTime; // Concatenate the log file name and application path RETURN_IF_FAILED(FILE_UTILITY::ConvertPathToFullPath( @@ -56,18 +58,18 @@ FileOutputManager::Start() RETURN_IF_FAILED(FILE_UTILITY::EnsureDirectoryPathExist(struPath.QueryStr())); - // Get the module name and add it to the log file name - // as two log files will be created, one from the shim - // and one from the request handler. - WCHAR path[MAX_PATH]; - RETURN_LAST_ERROR_IF(!GetModuleFileName(g_hModule, path, sizeof(path))); - std::filesystem::path fsPath(path); // TODO fix string as it is incorrect - GetSystemTime(&systemTime); + RETURN_LAST_ERROR_IF(!GetProcessTimes( + GetCurrentProcess(), + &processCreationTime, + &dummyFileTime, + &dummyFileTime, + &dummyFileTime)); + RETURN_LAST_ERROR_IF(!FileTimeToSystemTime(&processCreationTime, &systemTime)); RETURN_IF_FAILED( - m_struLogFilePath.SafeSnwprintf(L"%s_%d%02d%02d%02d%02d%02d_%d_%s.log", + m_struLogFilePath.SafeSnwprintf(L"%s_%d%02d%02d%02d%02d%02d_%d.log", struPath.QueryStr(), systemTime.wYear, systemTime.wMonth, @@ -75,8 +77,7 @@ FileOutputManager::Start() systemTime.wHour, systemTime.wMinute, systemTime.wSecond, - GetCurrentProcessId(), - fsPath.filename().stem().c_str())); + GetCurrentProcessId())); saAttr.nLength = sizeof(SECURITY_ATTRIBUTES); saAttr.bInheritHandle = TRUE; diff --git a/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeployer.cs b/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeployer.cs index 743944d971..814ca5e14b 100644 --- a/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeployer.cs +++ b/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeployer.cs @@ -254,6 +254,9 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting.IIS } HostProcess = Process.GetProcessById(workerProcess.ProcessId); + // cache the process start time for verifying log file name. + var _ = HostProcess.StartTime; + Logger.LogInformation("Site has started."); }); } diff --git a/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISExpressDeployer.cs b/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISExpressDeployer.cs index 797c46dde9..8464088f48 100644 --- a/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISExpressDeployer.cs +++ b/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISExpressDeployer.cs @@ -249,6 +249,8 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting.IIS else { _hostProcess = process; + // cache the process start time for verifying log file name. + var _ = _hostProcess.StartTime; Logger.LogInformation("Started iisexpress successfully. Process Id : {processId}, Port: {port}", _hostProcess.Id, port); return (url: url, hostExitToken: hostExitTokenSource.Token); } diff --git a/test/Common.FunctionalTests/Inprocess/LoggingTests.cs b/test/Common.FunctionalTests/Inprocess/LoggingTests.cs index e530befc51..dd0ac8cf6c 100644 --- a/test/Common.FunctionalTests/Inprocess/LoggingTests.cs +++ b/test/Common.FunctionalTests/Inprocess/LoggingTests.cs @@ -9,7 +9,6 @@ using Microsoft.AspNetCore.Server.IIS.FunctionalTests.Utilities; using Microsoft.AspNetCore.Server.IntegrationTesting; using Microsoft.AspNetCore.Server.IntegrationTesting.IIS; using Microsoft.AspNetCore.Testing.xunit; -using Microsoft.Extensions.Logging; using Xunit; namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests @@ -18,12 +17,23 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests public class LoggingTests : IISFunctionalTestBase { private readonly PublishedSitesFixture _fixture; + private readonly string _logFolderPath; public LoggingTests(PublishedSitesFixture fixture) { + _logFolderPath = Path.Combine(Path.GetTempPath(), Guid.NewGuid().ToString()); _fixture = fixture; } + public override void Dispose() + { + base.Dispose(); + if (Directory.Exists(_logFolderPath)) + { + Directory.Delete(_logFolderPath, true); + } + } + [ConditionalTheory] [InlineData("CheckErrLogFile")] [InlineData("CheckLogFile")] @@ -31,35 +41,18 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests { var deploymentParameters = _fixture.GetBaseDeploymentParameters(publish: true); - deploymentParameters.WebConfigActionList.Add( - WebConfigHelpers.AddOrModifyAspNetCoreSection("stdoutLogEnabled", "true")); - - var pathToLogs = Path.Combine(Path.GetTempPath(), Guid.NewGuid().ToString()); - deploymentParameters.WebConfigActionList.Add( - WebConfigHelpers.AddOrModifyAspNetCoreSection("stdoutLogFile", Path.Combine(pathToLogs, "std"))); + deploymentParameters.EnableLogging(_logFolderPath); var deploymentResult = await DeployAsync(deploymentParameters); + + await Helpers.AssertStarts(deploymentResult, path); - try - { - await Helpers.AssertStarts(deploymentResult, path); + StopServer(); - StopServer(); + var contents = File.ReadAllText(Helpers.GetExpectedLogName(deploymentResult, _logFolderPath)); - var fileInDirectory = Directory.GetFiles(pathToLogs).Single(fileName => fileName.Contains("inprocess")); - var contents = File.ReadAllText(fileInDirectory); - - Assert.NotNull(contents); - Assert.Contains("TEST MESSAGE", contents); - } - finally - { - RetryHelper.RetryOperation( - () => Directory.Delete(pathToLogs, true), - e => Logger.LogWarning($"Failed to delete directory : {e.Message}"), - retryCount: 3, - retryDelayMilliseconds: 100); - } + Assert.NotNull(contents); + Assert.Contains("TEST MESSAGE", contents); } [ConditionalFact] @@ -77,6 +70,21 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests await Helpers.AssertStarts(deploymentResult, "HelloWorld"); } + [ConditionalFact] + public async Task OnlyOneFileCreatedWithProcessStartTime() + { + var deploymentParameters = _fixture.GetBaseDeploymentParameters(publish: true); + + deploymentParameters.EnableLogging(_logFolderPath); + + var deploymentResult = await DeployAsync(deploymentParameters); + await Helpers.AssertStarts(deploymentResult, "CheckLogFile"); + + StopServer(); + + Assert.Single(Directory.GetFiles(_logFolderPath), Helpers.GetExpectedLogName(deploymentResult, _logFolderPath)); + } + [ConditionalFact] public async Task StartupMessagesAreLoggedIntoDebugLogFile() { diff --git a/test/Common.FunctionalTests/Utilities/EventLogHelpers.cs b/test/Common.FunctionalTests/Utilities/EventLogHelpers.cs index c85a78bdd3..6d2393f187 100644 --- a/test/Common.FunctionalTests/Utilities/EventLogHelpers.cs +++ b/test/Common.FunctionalTests/Utilities/EventLogHelpers.cs @@ -46,15 +46,22 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests var eventLog = new EventLog("Application"); - // Perf: only get the last 20 events from the event log. // Eventlog is already sorted based on time of event in ascending time. - // Add results in reverse order. + // Check results in reverse order. var expectedRegexEventLog = new Regex(expectedRegexMatchString); var processIdString = $"Process Id: {deploymentResult.HostProcess.Id}."; - for (var i = eventLog.Entries.Count - 1; i >= eventLog.Entries.Count - 20; i--) + // Event log messages round down to the nearest second, so subtract a second + var processStartTime = deploymentResult.HostProcess.StartTime.AddSeconds(-1); + for (var i = eventLog.Entries.Count - 1; i >= 0; i--) { var eventLogEntry = eventLog.Entries[i]; + if (eventLogEntry.TimeGenerated < processStartTime) + { + // If event logs is older than the process start time, we didn't find a match. + break; + } + if (eventLogEntry.ReplacementStrings == null || eventLogEntry.ReplacementStrings.Length < 3) { diff --git a/test/Common.FunctionalTests/Utilities/Helpers.cs b/test/Common.FunctionalTests/Utilities/Helpers.cs index 9ff2fda815..27155effcc 100644 --- a/test/Common.FunctionalTests/Utilities/Helpers.cs +++ b/test/Common.FunctionalTests/Utilities/Helpers.cs @@ -142,5 +142,14 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests { return dictionary.Keys.Select(k => new[] { k }); } + + public static string GetExpectedLogName(IISDeploymentResult deploymentResult, string logFolderPath) + { + var startTime = deploymentResult.HostProcess.StartTime.ToUniversalTime(); + return Path.Combine(logFolderPath, $"std_{startTime.Year}{startTime.Month:D2}" + + $"{startTime.Day:D2}{startTime.Hour:D2}" + + $"{startTime.Minute:D2}{startTime.Second:D2}_" + + $"{deploymentResult.HostProcess.Id}.log"); + } } } diff --git a/test/IIS.FunctionalTests/Inprocess/StdOutRedirectionTests.cs b/test/IIS.FunctionalTests/Inprocess/StdOutRedirectionTests.cs index b97aaf46f5..49088180c1 100644 --- a/test/IIS.FunctionalTests/Inprocess/StdOutRedirectionTests.cs +++ b/test/IIS.FunctionalTests/Inprocess/StdOutRedirectionTests.cs @@ -73,8 +73,7 @@ namespace IIS.FunctionalTests.Inprocess StopServer(); - var fileInDirectory = Directory.GetFiles(_logFolderPath).Single(); - var contents = File.ReadAllText(fileInDirectory); + var contents = File.ReadAllText(Helpers.GetExpectedLogName(deploymentResult, _logFolderPath)); var expectedString = "The specified framework 'Microsoft.NETCore.App', version '2.9.9' was not found."; EventLogHelpers.VerifyEventLogEvent(deploymentResult, TestSink, expectedString); Assert.Contains(expectedString, contents); @@ -98,14 +97,10 @@ namespace IIS.FunctionalTests.Inprocess StopServer(); - var filesInDirectory = Directory.GetFiles(_logFolderPath); - Assert.Equal(2, filesInDirectory.Length); - foreach (var file in filesInDirectory) - { - var contents = File.ReadAllText(file); - EventLogHelpers.VerifyEventLogEvent(deploymentResult, TestSink, "Invoked hostfxr"); - Assert.Contains("Invoked hostfxr", contents); - } + var fileInDirectory = Directory.GetFiles(_logFolderPath).Single(); + var contents = File.ReadAllText(fileInDirectory); + EventLogHelpers.VerifyEventLogEvent(deploymentResult, TestSink, "Invoked hostfxr"); + Assert.Contains("Invoked hostfxr", contents); } [ConditionalTheory] diff --git a/version.props b/version.props index c71c500e63..ba47547330 100644 --- a/version.props +++ b/version.props @@ -1,6 +1,12 @@  - 3.0.0 + 3 + 0 + 0 + $(DotNetMajorVersion).$(DotNetMinorVersion).$(DotNetPatchVersion) + 13 + $(DotNetMajorVersion) + $(DotNetPatchVersion) alpha1 $(VersionPrefix) $(VersionPrefix)-$(VersionSuffix)-final @@ -8,9 +14,6 @@ a- $(FeatureBranchVersionPrefix)$(VersionSuffix)-$([System.Text.RegularExpressions.Regex]::Replace('$(FeatureBranchVersionSuffix)', '[^\w-]', '-')) $(VersionSuffix)-$(BuildNumber) - 13 - 0 - 0 2.0.0