Fix Console invalid handle issues. (#1029)

src/AspNetCoreModuleV2/InProcessRequestHandler/inprocessapplication.cpp

@@ -277,10 +277,7 @@ IN_PROCESS_APPLICATION::LoadManagedApplication
                 goto Finished;
             }
 
-            if (FAILED(hr = m_pLoggerProvider->Start()))
+            LOG_IF_FAILED(m_pLoggerProvider->Start());
-            {
-                goto Finished;
-            }
         }
 
         if (m_status != APPLICATION_STATUS::STARTING)

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;
 }

src/AspNetCoreModuleV2/RequestHandlerLib/FileOutputManager.cpp

@@ -10,8 +10,8 @@
 
 FileOutputManager::FileOutputManager() :
     m_hLogFileHandle(INVALID_HANDLE_VALUE),
-    m_fdPreviousStdOut(0),
+    m_fdPreviousStdOut(-1),
-    m_fdPreviousStdErr(0)
+    m_fdPreviousStdErr(-1)
 {
 }
 
@@ -40,14 +40,14 @@ FileOutputManager::~FileOutputManager()
 
     if (m_fdPreviousStdOut >= 0)
     {
-        _dup2(m_fdPreviousStdOut, _fileno(stdout));
+        LOG_LAST_ERROR_IF(SetStdHandle(STD_OUTPUT_HANDLE, (HANDLE)_get_osfhandle(m_fdPreviousStdOut)));
-        LOG_INFOF("Restoring original stdout of stdout: %d", m_fdPreviousStdOut);
+        LOG_INFOF("Restoring original stdout: %d", m_fdPreviousStdOut);
     }
 
     if (m_fdPreviousStdErr >= 0)
     {
-        _dup2(m_fdPreviousStdErr, _fileno(stderr));
+        LOG_LAST_ERROR_IF(SetStdHandle(STD_ERROR_HANDLE, (HANDLE)_get_osfhandle(m_fdPreviousStdErr)));
-        LOG_INFOF("Restoring original stdout of stdout: %d", m_fdPreviousStdOut);
+        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)
 {
     //

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<InvalidHandleTraits> m_hLogFileHandle;

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
     {

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()

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)

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}");

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);
+                await Helpers.AssertStarts(deploymentResult, path);
-
-                var responseText = await response.Content.ReadAsStringAsync();
-
-                Assert.Equal("Hello World", responseText);
 
                 StopServer();
 
-                var folderPath = Path.Combine(deploymentResult.DeploymentResult.ContentRoot, @"logs");
+                var fileInDirectory = Directory.GetFiles(pathToLogs).Single();
 
-                var fileInDirectory = Directory.GetFiles(folderPath).Single();
+                var contents = File.ReadAllText(fileInDirectory);
-                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);
 
                 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()

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);

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) =>
                 {

test/WebSites/InProcessWebSite/Startup.cs

@@ -753,6 +753,5 @@ namespace IISTestSite
             }
             await context.Response.WriteAsync("Response End");
         }
-
     }
 }