Re-enable flaky logging tests, add logs to output redirection providers, fix potential race condition in closing pipe output. (#971)

src/AspNetCoreModuleV2/RequestHandlerLib/FileOutputManager.cpp

@@ -4,6 +4,8 @@
 #include "stdafx.h"
 #include "sttimer.h"
 #include "utility.h"
+#include "exceptions.h"
+#include "debugutil.h"
 
 FileOutputManager::FileOutputManager()
 {
@@ -37,25 +39,23 @@ FileOutputManager::~FileOutputManager()
     if (m_fdPreviousStdOut >= 0)
     {
         _dup2(m_fdPreviousStdOut, _fileno(stdout));
+        LOG_INFOF("Restoring original stdout of stdout: %d", m_fdPreviousStdOut);
     }
 
     if (m_fdPreviousStdErr >= 0)
     {
         _dup2(m_fdPreviousStdErr, _fileno(stderr));
+        LOG_INFOF("Restoring original stdout of stdout: %d", m_fdPreviousStdOut);
     }
 }
 
 HRESULT
 FileOutputManager::Initialize(PCWSTR pwzStdOutLogFileName, PCWSTR pwzApplicationPath)
 {
-    HRESULT hr = S_OK;
+    RETURN_IF_FAILED(m_wsApplicationPath.Copy(pwzApplicationPath));
+    RETURN_IF_FAILED(m_wsStdOutLogFileName.Copy(pwzStdOutLogFileName));
 
-    if (SUCCEEDED(hr = m_wsApplicationPath.Copy(pwzApplicationPath)))
+    return S_OK;
-    {
-        hr = m_wsStdOutLogFileName.Copy(pwzStdOutLogFileName);
-    }
-
-    return hr;
 }
 
 void FileOutputManager::NotifyStartupComplete()
@@ -102,33 +102,28 @@ bool FileOutputManager::GetStdOutContent(STRA* struStdOutput)
         }
     }
 
+    LOG_INFOF("First 4KB captured by stdout: %s", pzFileContents);
+
     return fLogged;
 }
 
 HRESULT
 FileOutputManager::Start()
 {
-    HRESULT hr;
     SYSTEMTIME systemTime;
     SECURITY_ATTRIBUTES saAttr = { 0 };
     STRU struPath;
-    hr = UTILITY::ConvertPathToFullPath(
+
+    RETURN_IF_FAILED(UTILITY::ConvertPathToFullPath(
         m_wsStdOutLogFileName.QueryStr(),
         m_wsApplicationPath.QueryStr(),
-        &struPath);
+        &struPath));
-    if (FAILED(hr))
-    {
-        return hr;
-    }
 
-    hr = UTILITY::EnsureDirectoryPathExist(struPath.QueryStr());
+    RETURN_IF_FAILED(UTILITY::EnsureDirectoryPathExist(struPath.QueryStr()));
-    if (FAILED(hr))
-    {
-        return hr;
-    }
 
     GetSystemTime(&systemTime);
-    hr = m_struLogFilePath.SafeSnwprintf(L"%s_%d%02d%02d%02d%02d%02d_%d.log",
+    RETURN_IF_FAILED(
+        m_struLogFilePath.SafeSnwprintf(L"%s_%d%02d%02d%02d%02d%02d_%d.log",
         struPath.QueryStr(),
         systemTime.wYear,
         systemTime.wMonth,
@@ -136,11 +131,7 @@ FileOutputManager::Start()
         systemTime.wHour,
         systemTime.wMinute,
         systemTime.wSecond,
-        GetCurrentProcessId());
+        GetCurrentProcessId()));
-    if (FAILED(hr))
-    {
-        return hr;
-    }
 
     m_fdPreviousStdOut = _dup(_fileno(stdout));
     m_fdPreviousStdErr = _dup(_fileno(stderr));
@@ -155,8 +146,7 @@ FileOutputManager::Start()
 
     if (m_hLogFileHandle == INVALID_HANDLE_VALUE)
     {
-        hr = HRESULT_FROM_WIN32(GetLastError());
+        return LOG_IF_FAILED(HRESULT_FROM_WIN32(GetLastError()));
-        return hr;
     }
 
     // There are a few options for redirecting stdout/stderr,
@@ -173,21 +163,15 @@ FileOutputManager::Start()
     // Calling SetStdHandle works for redirecting managed logs, however you cannot
     // capture native logs (including hostfxr failures).
 
-    if (!SetStdHandle(STD_OUTPUT_HANDLE, m_hLogFileHandle))
+    RETURN_LAST_ERROR_IF(!SetStdHandle(STD_OUTPUT_HANDLE, m_hLogFileHandle));
-    {
-        hr = HRESULT_FROM_WIN32(GetLastError());
-        return hr;
-    }
-
-    if (!SetStdHandle(STD_ERROR_HANDLE, m_hLogFileHandle))
-    {
-        hr = HRESULT_FROM_WIN32(GetLastError());
-        return hr;
-    }
 
+    RETURN_LAST_ERROR_IF(!SetStdHandle(STD_ERROR_HANDLE, m_hLogFileHandle));
 
     // Periodically flush the log content to file
     m_Timer.InitializeTimer(STTIMER::TimerCallback, &m_struLogFilePath, 3000, 3000);
 
-    return hr;
+    WLOG_INFOF(L"Created log file for inprocess application: %s",
+        m_struLogFilePath.QueryStr());
+
+    return S_OK;
 }

src/AspNetCoreModuleV2/RequestHandlerLib/PipeOutputManager.cpp

@@ -2,6 +2,8 @@
 // Licensed under the MIT License. See License.txt in the project root for license information.
 
 #include "stdafx.h"
+#include "exceptions.h"
+#include "SRWExclusiveLock.h"
 
 PipeOutputManager::PipeOutputManager() :
     m_dwStdErrReadTotal(0),
@@ -10,6 +12,7 @@ PipeOutputManager::PipeOutputManager() :
     m_hErrThread(INVALID_HANDLE_VALUE),
     m_fDisposed(FALSE)
 {
+    InitializeSRWLock(&m_srwLock);
 }
 
 PipeOutputManager::~PipeOutputManager()
@@ -23,6 +26,12 @@ PipeOutputManager::StopOutputRedirection()
     DWORD    dwThreadStatus = 0;
     STRA     straStdOutput;
 
+    if (m_fDisposed)
+    {
+        return;
+    }
+    SRWExclusiveLock lock(m_srwLock);
+
     if (m_fDisposed)
     {
         return;
@@ -38,17 +47,20 @@ PipeOutputManager::StopOutputRedirection()
         m_hErrWritePipe = INVALID_HANDLE_VALUE;
     }
 
+    // GetExitCodeThread returns 0 on failure; thread status code is invalid.
     if (m_hErrThread != NULL &&
         m_hErrThread != INVALID_HANDLE_VALUE &&
-        GetExitCodeThread(m_hErrThread, &dwThreadStatus) != 0 &&
+        !LOG_LAST_ERROR_IF(GetExitCodeThread(m_hErrThread, &dwThreadStatus) == 0) &&
         dwThreadStatus == STILL_ACTIVE)
     {
-        // wait for gracefullshut down, i.e., the exit of the background thread or timeout
+        // wait for graceful shutdown, i.e., the exit of the background thread or timeout
         if (WaitForSingleObject(m_hErrThread, PIPE_OUTPUT_THREAD_TIMEOUT) != WAIT_OBJECT_0)
         {
             // if the thread is still running, we need kill it first before exit to avoid AV
-            if (GetExitCodeThread(m_hErrThread, &dwThreadStatus) != 0 && dwThreadStatus == STILL_ACTIVE)
+            if (!LOG_LAST_ERROR_IF(GetExitCodeThread(m_hErrThread, &dwThreadStatus) == 0) &&
+                dwThreadStatus == STILL_ACTIVE)
             {
+                LOG_WARN("Thread reading stdout/err hit timeout, forcibly closing thread.");
                 TerminateThread(m_hErrThread, STATUS_CONTROL_C_EXIT);
             }
         }
@@ -68,11 +80,13 @@ PipeOutputManager::StopOutputRedirection()
     if (m_fdPreviousStdOut != -1)
     {
         _dup2(m_fdPreviousStdOut, _fileno(stdout));
+        LOG_INFOF("Restoring original stdout of stdout: %d", m_fdPreviousStdOut);
     }
 
     if (m_fdPreviousStdErr != -1)
     {
         _dup2(m_fdPreviousStdErr, _fileno(stderr));
+        LOG_INFOF("Restoring original stdout of stderr: %d", m_fdPreviousStdErr);
     }
 
     if (GetStdOutContent(&straStdOutput))
@@ -85,7 +99,6 @@ PipeOutputManager::StopOutputRedirection()
 
 HRESULT PipeOutputManager::Start()
 {
-    HRESULT hr = S_OK;
     SECURITY_ATTRIBUTES     saAttr = { 0 };
     HANDLE                  hStdErrReadPipe;
     HANDLE                  hStdErrWritePipe;
@@ -93,24 +106,12 @@ HRESULT PipeOutputManager::Start()
     m_fdPreviousStdOut = _dup(_fileno(stdout));
     m_fdPreviousStdErr = _dup(_fileno(stderr));
 
-    if (!CreatePipe(&hStdErrReadPipe, &hStdErrWritePipe, &saAttr, 0 /*nSize*/))
+    RETURN_LAST_ERROR_IF(!CreatePipe(&hStdErrReadPipe, &hStdErrWritePipe, &saAttr, 0 /*nSize*/));
-    {
-        hr = HRESULT_FROM_WIN32(GetLastError());
-        goto Finished;
-    }
 
     // TODO this still doesn't redirect calls in native, like wprintf
-    if (!SetStdHandle(STD_ERROR_HANDLE, hStdErrWritePipe))
+    RETURN_LAST_ERROR_IF(!SetStdHandle(STD_ERROR_HANDLE, hStdErrWritePipe));
-    {
-        hr = HRESULT_FROM_WIN32(GetLastError());
-        goto Finished;
-    }
 
-    if (!SetStdHandle(STD_OUTPUT_HANDLE, hStdErrWritePipe))
+    RETURN_LAST_ERROR_IF(!SetStdHandle(STD_OUTPUT_HANDLE, hStdErrWritePipe));
-    {
-        hr = HRESULT_FROM_WIN32(GetLastError());
-        goto Finished;
-    }
 
     m_hErrReadPipe = hStdErrReadPipe;
     m_hErrWritePipe = hStdErrWritePipe;
@@ -124,14 +125,9 @@ HRESULT PipeOutputManager::Start()
         0,          // default creation flags
         NULL);      // receive thread identifier
 
-    if (m_hErrThread == NULL)
+    RETURN_LAST_ERROR_IF_NULL(m_hErrThread);
-    {
-        hr = HRESULT_FROM_WIN32(GetLastError());
-        goto Finished;
-    }
 
-Finished:
+    return S_OK;
-    return hr;
 }
 
 VOID

src/AspNetCoreModuleV2/RequestHandlerLib/PipeOutputManager.h

@@ -23,15 +23,17 @@ public:
     static
     VOID ReadStdErrHandle(LPVOID pContext);
 
-    VOID StopOutputRedirection();
 private:
+    VOID StopOutputRedirection();
+
     HANDLE                          m_hErrReadPipe;
     HANDLE                          m_hErrWritePipe;
     STRU                            m_struLogFilePath;
     HANDLE                          m_hErrThread;
     CHAR                            m_pzFileContents[MAX_PIPE_READ_SIZE] = { 0 };
-    BOOL                            m_fDisposed;
     DWORD                           m_dwStdErrReadTotal;
+    BOOL                            m_fDisposed;
+    SRWLOCK                         m_srwLock;
     int                             m_fdPreviousStdOut;
     int                             m_fdPreviousStdErr;
 };

test/IISIntegration.FunctionalTests/Inprocess/LoggingTests.cs

@@ -13,7 +13,7 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests
 {
     public class LoggingTests : IISFunctionalTestBase
     {
-        [Theory(Skip = "See: https://github.com/aspnet/IISIntegration/issues/897")]
+        [Theory]
         [InlineData("CheckErrLogFile")]
         [InlineData("CheckLogFile")]
         public async Task CheckStdoutLogging(string path)
@@ -24,47 +24,45 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests
 
             var deploymentResult = await DeployAsync(deploymentParameters);
 
-            Helpers.ModifyAspNetCoreSectionInWebConfig(deploymentResult, "stdoutLogEnabled", "true");
+            try
-            Helpers.ModifyAspNetCoreSectionInWebConfig(deploymentResult, "stdoutLogFile", @".\logs\stdout");
-
-            var response = await deploymentResult.RetryingHttpClient.GetAsync(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(folderPath).Single();
-            Assert.NotNull(fileInDirectory);
-
-            string contents = null;
-            for (var i = 0; i < 20; i++)
             {
-                try
+                Helpers.ModifyAspNetCoreSectionInWebConfig(deploymentResult, "stdoutLogEnabled", "true");
-                {
+                Helpers.ModifyAspNetCoreSectionInWebConfig(deploymentResult, "stdoutLogFile", @".\logs\stdout");
-                    contents = await File.ReadAllTextAsync(fileInDirectory);
+
-                    break;
+                var response = await deploymentResult.RetryingHttpClient.GetAsync(path);
-                }
+
-                catch (IOException)
+                var responseText = await response.Content.ReadAsStringAsync();
-                {
+
-                    // File in use by IISExpress, delay a bit before rereading.
+                Assert.Equal("Hello World", responseText);
-                }
+
-                await Task.Delay(20);
+                StopServer();
+
+                var folderPath = Path.Combine(deploymentResult.DeploymentResult.ContentRoot, @"logs");
+
+                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);
+
+                Assert.NotNull(contents);
+                Assert.Contains("TEST MESSAGE", contents);
             }
+            finally
+            {
 
-            Assert.NotNull(contents);
+                RetryHelper.RetryOperation(
-
+                    () => Directory.Delete(deploymentParameters.PublishedApplicationRootPath, true),
-            // Open the log file and see if there are any contents.
+                    e => Logger.LogWarning($"Failed to delete directory : {e.Message}"),
-            Assert.Contains("TEST MESSAGE", contents);
+                    retryCount: 3,
-
+                    retryDelayMilliseconds: 100);
-            RetryHelper.RetryOperation(
+            }
-                () => Directory.Delete(deploymentParameters.PublishedApplicationRootPath, true),
-                e => Logger.LogWarning($"Failed to delete directory : {e.Message}"),
-                retryCount: 3,
-                retryDelayMilliseconds: 100);
         }
     }
 }