diff --git a/src/AspNetCoreModuleV2/InProcessRequestHandler/inprocessapplication.cpp b/src/AspNetCoreModuleV2/InProcessRequestHandler/inprocessapplication.cpp index bb56b01419..7e6f0ee433 100644 --- a/src/AspNetCoreModuleV2/InProcessRequestHandler/inprocessapplication.cpp +++ b/src/AspNetCoreModuleV2/InProcessRequestHandler/inprocessapplication.cpp @@ -277,10 +277,7 @@ IN_PROCESS_APPLICATION::LoadManagedApplication goto Finished; } - if (FAILED(hr = m_pLoggerProvider->Start())) - { - goto Finished; - } + LOG_IF_FAILED(m_pLoggerProvider->Start()); } if (m_status != APPLICATION_STATUS::STARTING) diff --git a/src/AspNetCoreModuleV2/InProcessRequestHandler/managedexports.cpp b/src/AspNetCoreModuleV2/InProcessRequestHandler/managedexports.cpp index 38c4cb6503..1db194bdbd 100644 --- a/src/AspNetCoreModuleV2/InProcessRequestHandler/managedexports.cpp +++ b/src/AspNetCoreModuleV2/InProcessRequestHandler/managedexports.cpp @@ -15,7 +15,8 @@ register_callbacks( _In_ PFN_SHUTDOWN_HANDLER shutdown_handler, _In_ PFN_ASYNC_COMPLETION_HANDLER async_completion_handler, _In_ VOID* pvRequstHandlerContext, - _In_ VOID* pvShutdownHandlerContext + _In_ VOID* pvShutdownHandlerContext, + _Out_ BOOL* pfResetStandardStreams ) { if (pInProcessApplication == NULL) @@ -30,6 +31,7 @@ register_callbacks( pvRequstHandlerContext, pvShutdownHandlerContext ); + *pfResetStandardStreams = !pInProcessApplication->QueryConfig()->QueryStdoutLogEnabled(); return S_OK; } diff --git a/src/AspNetCoreModuleV2/RequestHandlerLib/FileOutputManager.cpp b/src/AspNetCoreModuleV2/RequestHandlerLib/FileOutputManager.cpp index 3242f96227..358d0f79cd 100644 --- a/src/AspNetCoreModuleV2/RequestHandlerLib/FileOutputManager.cpp +++ b/src/AspNetCoreModuleV2/RequestHandlerLib/FileOutputManager.cpp @@ -10,8 +10,8 @@ FileOutputManager::FileOutputManager() : m_hLogFileHandle(INVALID_HANDLE_VALUE), - m_fdPreviousStdOut(0), - m_fdPreviousStdErr(0) + m_fdPreviousStdOut(-1), + m_fdPreviousStdErr(-1) { } @@ -40,14 +40,14 @@ FileOutputManager::~FileOutputManager() if (m_fdPreviousStdOut >= 0) { - _dup2(m_fdPreviousStdOut, _fileno(stdout)); - LOG_INFOF("Restoring original stdout of stdout: %d", m_fdPreviousStdOut); + LOG_LAST_ERROR_IF(SetStdHandle(STD_OUTPUT_HANDLE, (HANDLE)_get_osfhandle(m_fdPreviousStdOut))); + LOG_INFOF("Restoring original stdout: %d", m_fdPreviousStdOut); } if (m_fdPreviousStdErr >= 0) { - _dup2(m_fdPreviousStdErr, _fileno(stderr)); - LOG_INFOF("Restoring original stdout of stdout: %d", m_fdPreviousStdOut); + LOG_LAST_ERROR_IF(SetStdHandle(STD_ERROR_HANDLE, (HANDLE)_get_osfhandle(m_fdPreviousStdErr))); + LOG_INFOF("Restoring original stderr: %d", m_fdPreviousStdOut); } } @@ -60,10 +60,6 @@ FileOutputManager::Initialize(PCWSTR pwzStdOutLogFileName, PCWSTR pwzApplication return S_OK; } -void FileOutputManager::NotifyStartupComplete() -{ -} - bool FileOutputManager::GetStdOutContent(STRA* struStdOutput) { // diff --git a/src/AspNetCoreModuleV2/RequestHandlerLib/FileOutputManager.h b/src/AspNetCoreModuleV2/RequestHandlerLib/FileOutputManager.h index 7f44d92462..f9a617ccf9 100644 --- a/src/AspNetCoreModuleV2/RequestHandlerLib/FileOutputManager.h +++ b/src/AspNetCoreModuleV2/RequestHandlerLib/FileOutputManager.h @@ -19,7 +19,7 @@ public: virtual bool GetStdOutContent(STRA* struStdOutput) override; virtual HRESULT Start() override; - virtual void NotifyStartupComplete() override; + virtual void NotifyStartupComplete() override {}; private: HandleWrapper m_hLogFileHandle; diff --git a/src/AspNetCoreModuleV2/RequestHandlerLib/PipeOutputManager.cpp b/src/AspNetCoreModuleV2/RequestHandlerLib/PipeOutputManager.cpp index e8b61a962b..ade993f37b 100644 --- a/src/AspNetCoreModuleV2/RequestHandlerLib/PipeOutputManager.cpp +++ b/src/AspNetCoreModuleV2/RequestHandlerLib/PipeOutputManager.cpp @@ -14,7 +14,9 @@ PipeOutputManager::PipeOutputManager() : m_hErrReadPipe(INVALID_HANDLE_VALUE), m_hErrWritePipe(INVALID_HANDLE_VALUE), m_hErrThread(NULL), - m_fDisposed(FALSE) + m_fDisposed(FALSE), + m_fdPreviousStdOut(-1), + m_fdPreviousStdErr(-1) { InitializeSRWLock(&m_srwLock); } @@ -54,7 +56,7 @@ PipeOutputManager::StopOutputRedirection() if (m_fdPreviousStdOut >= 0) { - LOG_IF_DUPFAIL(_dup2(m_fdPreviousStdOut, _fileno(stdout))); + LOG_LAST_ERROR_IF(SetStdHandle(STD_OUTPUT_HANDLE, (HANDLE)_get_osfhandle(m_fdPreviousStdOut))); } else { @@ -63,7 +65,7 @@ PipeOutputManager::StopOutputRedirection() if (m_fdPreviousStdErr >= 0) { - LOG_IF_DUPFAIL(_dup2(m_fdPreviousStdErr, _fileno(stderr))); + LOG_LAST_ERROR_IF(SetStdHandle(STD_ERROR_HANDLE, (HANDLE)_get_osfhandle(m_fdPreviousStdErr))); } else { diff --git a/src/Microsoft.AspNetCore.Server.IIS/Core/IISNativeApplication.cs b/src/Microsoft.AspNetCore.Server.IIS/Core/IISNativeApplication.cs index 6d574867b4..44f9b40bef 100644 --- a/src/Microsoft.AspNetCore.Server.IIS/Core/IISNativeApplication.cs +++ b/src/Microsoft.AspNetCore.Server.IIS/Core/IISNativeApplication.cs @@ -2,6 +2,7 @@ // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. using System; +using System.IO; namespace Microsoft.AspNetCore.Server.IIS.Core { @@ -31,7 +32,39 @@ namespace Microsoft.AspNetCore.Server.IIS.Core IntPtr requestContext, IntPtr shutdownContext) { - NativeMethods.HttpRegisterCallbacks(_nativeApplication, requestHandler, shutdownHandler, onAsyncCompletion, requestContext, shutdownContext); + NativeMethods.HttpRegisterCallbacks( + _nativeApplication, + requestHandler, + shutdownHandler, + onAsyncCompletion, + requestContext, + shutdownContext, + out var resetStandardStreams); + + if (resetStandardStreams) + { + ResetStdOutHandles(); + } + } + + private static void ResetStdOutHandles() + { + // By using the PipeOutputRedirection, after calling RegisterCallbacks, + // stdout and stderr will be redirected to NULL. However, if something wrote + // to stdout before redirecting, (like a Console.WriteLine during startup), + // we need to call Console.Set* to pick up the modified consoles outputs. + Console.SetOut(CreateStreamWriter(Console.OpenStandardOutput())); + Console.SetError(CreateStreamWriter(Console.OpenStandardError())); + } + + private static StreamWriter CreateStreamWriter(Stream stdStream) + { + return new StreamWriter( + stdStream, + encoding: Console.OutputEncoding, + bufferSize: 256, + leaveOpen: true) + { AutoFlush = true }; } public void Dispose() diff --git a/src/Microsoft.AspNetCore.Server.IIS/NativeMethods.cs b/src/Microsoft.AspNetCore.Server.IIS/NativeMethods.cs index de7bcb0562..a21ddcbac5 100644 --- a/src/Microsoft.AspNetCore.Server.IIS/NativeMethods.cs +++ b/src/Microsoft.AspNetCore.Server.IIS/NativeMethods.cs @@ -53,7 +53,13 @@ namespace Microsoft.AspNetCore.Server.IIS private static extern void http_indicate_completion(IntPtr pInProcessHandler, REQUEST_NOTIFICATION_STATUS notificationStatus); [DllImport(AspNetCoreModuleDll)] - private static extern int register_callbacks(IntPtr pInProcessApplication, PFN_REQUEST_HANDLER requestCallback, PFN_SHUTDOWN_HANDLER shutdownCallback, PFN_ASYNC_COMPLETION asyncCallback, IntPtr pvRequestContext, IntPtr pvShutdownContext); + private static extern int register_callbacks(IntPtr pInProcessApplication, + PFN_REQUEST_HANDLER requestCallback, + PFN_SHUTDOWN_HANDLER shutdownCallback, + PFN_ASYNC_COMPLETION asyncCallback, + IntPtr pvRequestContext, + IntPtr pvShutdownContext, + out bool resetStandardStreams); [DllImport(AspNetCoreModuleDll)] private static extern unsafe int http_write_response_bytes(IntPtr pInProcessHandler, HttpApiTypes.HTTP_DATA_CHUNK* pDataChunks, int nChunks, out bool fCompletionExpected); @@ -135,9 +141,15 @@ namespace Microsoft.AspNetCore.Server.IIS Validate(http_set_completion_status(pInProcessHandler, rquestNotificationStatus)); } - public static void HttpRegisterCallbacks(IntPtr pInProcessApplication, PFN_REQUEST_HANDLER requestCallback, PFN_SHUTDOWN_HANDLER shutdownCallback, PFN_ASYNC_COMPLETION asyncCallback, IntPtr pvRequestContext, IntPtr pvShutdownContext) + public static void HttpRegisterCallbacks(IntPtr pInProcessApplication, + PFN_REQUEST_HANDLER requestCallback, + PFN_SHUTDOWN_HANDLER shutdownCallback, + PFN_ASYNC_COMPLETION asyncCallback, + IntPtr pvRequestContext, + IntPtr pvShutdownContext, + out bool resetStandardStreams) { - Validate(register_callbacks(pInProcessApplication, requestCallback, shutdownCallback, asyncCallback, pvRequestContext, pvShutdownContext)); + Validate(register_callbacks(pInProcessApplication, requestCallback, shutdownCallback, asyncCallback, pvRequestContext, pvShutdownContext, out resetStandardStreams)); } public static unsafe int HttpWriteResponseBytes(IntPtr pInProcessHandler, HttpApiTypes.HTTP_DATA_CHUNK* pDataChunks, int nChunks, out bool fCompletionExpected) diff --git a/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISApplication.cs b/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISApplication.cs index afa28dd4e3..d0c0bfb153 100644 --- a/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISApplication.cs +++ b/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISApplication.cs @@ -231,7 +231,6 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting pool.ProcessModel.IdentityType = ProcessModelIdentityType.LocalSystem; pool.ManagedRuntimeVersion = string.Empty; pool.StartMode = StartMode.AlwaysRunning; - AddEnvironmentVariables(contentRoot, pool); _logger.LogInformation($"Configured AppPool {AppPoolName}"); diff --git a/test/Common.FunctionalTests/Inprocess/LoggingTests.cs b/test/Common.FunctionalTests/Inprocess/LoggingTests.cs index 53009a969c..6384fd508e 100644 --- a/test/Common.FunctionalTests/Inprocess/LoggingTests.cs +++ b/test/Common.FunctionalTests/Inprocess/LoggingTests.cs @@ -19,55 +19,58 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests [ConditionalTheory] [InlineData("CheckErrLogFile")] [InlineData("CheckLogFile")] - public async Task CheckStdoutLogging(string path) + public async Task CheckStdoutLoggingToFile(string path) { var deploymentParameters = Helpers.GetBaseDeploymentParameters(); deploymentParameters.PublishApplicationBeforeDeployment = true; - deploymentParameters.PreservePublishedApplicationForDebugging = true; // workaround for keeping var deploymentResult = await DeployAsync(deploymentParameters); + var pathToLogs = Path.Combine(Path.GetTempPath(), Guid.NewGuid().ToString()); try { Helpers.ModifyAspNetCoreSectionInWebConfig(deploymentResult, "stdoutLogEnabled", "true"); - Helpers.ModifyAspNetCoreSectionInWebConfig(deploymentResult, "stdoutLogFile", @".\logs\stdout"); + Helpers.ModifyAspNetCoreSectionInWebConfig(deploymentResult, "stdoutLogFile", Path.Combine(pathToLogs, "std")); - var response = await deploymentResult.RetryingHttpClient.GetAsync(path); - - var responseText = await response.Content.ReadAsStringAsync(); - - Assert.Equal("Hello World", responseText); + await Helpers.AssertStarts(deploymentResult, path); StopServer(); - var folderPath = Path.Combine(deploymentResult.DeploymentResult.ContentRoot, @"logs"); + var fileInDirectory = Directory.GetFiles(pathToLogs).Single(); - var fileInDirectory = Directory.GetFiles(folderPath).Single(); - Assert.NotNull(fileInDirectory); - - string contents = null; - - // RetryOperation doesn't support async lambdas, call synchronous ReadAllText. - RetryHelper.RetryOperation( - () => contents = File.ReadAllText(fileInDirectory), - e => Logger.LogError($"Failed to read file: {e.Message}"), - retryCount: 10, - retryDelayMilliseconds: 100); + var contents = File.ReadAllText(fileInDirectory); Assert.NotNull(contents); Assert.Contains("TEST MESSAGE", contents); + Assert.DoesNotContain(TestSink.Writes, context => context.Message.Contains("TEST MESSAGE")); + // TODO we should check that debug logs are restored during graceful shutdown. + // The IIS Express deployer doesn't support graceful shutdown. + //Assert.Contains(TestSink.Writes, context => context.Message.Contains("Restoring original stdout: ")); } finally { RetryHelper.RetryOperation( - () => Directory.Delete(deploymentParameters.PublishedApplicationRootPath, true), + () => Directory.Delete(pathToLogs, true), e => Logger.LogWarning($"Failed to delete directory : {e.Message}"), retryCount: 3, retryDelayMilliseconds: 100); } } + [ConditionalFact] + public async Task InvalidFilePathForLogs_ServerStillRuns() + { + var deploymentParameters = Helpers.GetBaseDeploymentParameters(publish: true); + + var deploymentResult = await DeployAsync(deploymentParameters); + + Helpers.ModifyAspNetCoreSectionInWebConfig(deploymentResult, "stdoutLogEnabled", "true"); + Helpers.ModifyAspNetCoreSectionInWebConfig(deploymentResult, "stdoutLogFile", Path.Combine("Q:", "std")); + + await Helpers.AssertStarts(deploymentResult, "HelloWorld"); + } + [ConditionalFact] [RequiresIIS(IISCapability.PoolEnvironmentVariables)] public async Task StartupMessagesAreLoggedIntoDebugLogFile() @@ -96,6 +99,48 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests } } + [ConditionalTheory] + [InlineData("CheckErrLogFile")] + [InlineData("CheckLogFile")] + public async Task CheckStdoutLoggingToPipe_DoesNotCrashProcess(string path) + { + var deploymentParameters = Helpers.GetBaseDeploymentParameters(publish: true); + var deploymentResult = await DeployAsync(deploymentParameters); + + await Helpers.AssertStarts(deploymentResult, path); + + StopServer(); + + if (deploymentParameters.ServerType == ServerType.IISExpress) + { + Assert.Contains(TestSink.Writes, context => context.Message.Contains("TEST MESSAGE")); + } + } + + [ConditionalTheory] + [InlineData("CheckErrLogFile")] + [InlineData("CheckLogFile")] + public async Task CheckStdoutLoggingToPipeWithFirstWrite(string path) + { + var deploymentParameters = Helpers.GetBaseDeploymentParameters(publish: true); + + var deploymentResult = await DeployAsync(deploymentParameters); + var firstWriteString = path + path; + + Helpers.ModifyEnvironmentVariableCollectionInWebConfig(deploymentResult, "ASPNETCORE_INPROCESS_INITIAL_WRITE", firstWriteString); + + await Helpers.AssertStarts(deploymentResult, path); + + StopServer(); + + if (deploymentParameters.ServerType == ServerType.IISExpress) + { + // We can't read stdout logs from IIS as they aren't redirected. + Assert.Contains(TestSink.Writes, context => context.Message.Contains(firstWriteString)); + Assert.Contains(TestSink.Writes, context => context.Message.Contains("TEST MESSAGE")); + } + } + [ConditionalFact] [RequiresIIS(IISCapability.PoolEnvironmentVariables)] public async Task StartupMessagesLogFileSwitchedWhenLogFilePresentInWebConfig() diff --git a/test/Common.FunctionalTests/Utilities/Helpers.cs b/test/Common.FunctionalTests/Utilities/Helpers.cs index 0480351ce1..878ab06272 100644 --- a/test/Common.FunctionalTests/Utilities/Helpers.cs +++ b/test/Common.FunctionalTests/Utilities/Helpers.cs @@ -41,6 +41,22 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests config.Save(webConfigFile); } + public static void ModifyEnvironmentVariableCollectionInWebConfig(IISDeploymentResult deploymentResult, string key, string value) + { + var webConfigFile = GetWebConfigFile(deploymentResult); + var config = XDocument.Load(webConfigFile); + + var envVarElement = new XElement("environmentVariable"); + envVarElement.SetAttributeValue("name", key); + envVarElement.SetAttributeValue("value", value); + + config.Descendants("aspNetCore").Single() + .Descendants("environmentVariables").Single() + .Add(envVarElement); + + config.Save(webConfigFile); + } + public static void ModifyHandlerSectionInWebConfig(IISDeploymentResult deploymentResult, string handlerVersionValue) { var webConfigFile = GetWebConfigFile(deploymentResult); diff --git a/test/WebSites/InProcessWebSite/Program.cs b/test/WebSites/InProcessWebSite/Program.cs index 2e5e8f5d6a..ec9ed04f87 100644 --- a/test/WebSites/InProcessWebSite/Program.cs +++ b/test/WebSites/InProcessWebSite/Program.cs @@ -1,6 +1,7 @@ // Copyright (c) .NET Foundation. All rights reserved. // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. +using System; using Microsoft.AspNetCore.Hosting; using Microsoft.Extensions.Logging; @@ -10,6 +11,13 @@ namespace IISTestSite { public static void Main(string[] args) { + var envVariable = Environment.GetEnvironmentVariable("ASPNETCORE_INPROCESS_INITIAL_WRITE"); + if (!string.IsNullOrEmpty(envVariable)) + { + Console.WriteLine(envVariable); + Console.Error.WriteLine(envVariable); + } + var host = new WebHostBuilder() .ConfigureLogging((_, factory) => { diff --git a/test/WebSites/InProcessWebSite/Startup.cs b/test/WebSites/InProcessWebSite/Startup.cs index 2bf89384f8..f42e220751 100644 --- a/test/WebSites/InProcessWebSite/Startup.cs +++ b/test/WebSites/InProcessWebSite/Startup.cs @@ -753,6 +753,5 @@ namespace IISTestSite } await context.Response.WriteAsync("Response End"); } - } }