From fac42c78a178866e5ad4638869e1026b4e8e7c52 Mon Sep 17 00:00:00 2001 From: Justin Kotalik Date: Tue, 26 Jun 2018 11:28:56 -0700 Subject: [PATCH] Re-enable flaky logging tests, add logs to output redirection providers, fix potential race condition in closing pipe output. (#971) --- .../RequestHandlerLib/FileOutputManager.cpp | 62 ++++++--------- .../RequestHandlerLib/PipeOutputManager.cpp | 48 ++++++------ .../RequestHandlerLib/PipeOutputManager.h | 6 +- .../Inprocess/LoggingTests.cs | 76 +++++++++---------- 4 files changed, 86 insertions(+), 106 deletions(-) diff --git a/src/AspNetCoreModuleV2/RequestHandlerLib/FileOutputManager.cpp b/src/AspNetCoreModuleV2/RequestHandlerLib/FileOutputManager.cpp index 9aca9ae0c3..28d3c47884 100644 --- a/src/AspNetCoreModuleV2/RequestHandlerLib/FileOutputManager.cpp +++ b/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))) - { - hr = m_wsStdOutLogFileName.Copy(pwzStdOutLogFileName); - } - - return hr; + return S_OK; } 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); - if (FAILED(hr)) - { - return hr; - } + &struPath)); - hr = UTILITY::EnsureDirectoryPathExist(struPath.QueryStr()); - if (FAILED(hr)) - { - return hr; - } + RETURN_IF_FAILED(UTILITY::EnsureDirectoryPathExist(struPath.QueryStr())); 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()); - if (FAILED(hr)) - { - return hr; - } + GetCurrentProcessId())); 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 hr; + return LOG_IF_FAILED(HRESULT_FROM_WIN32(GetLastError())); } // 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)) - { - 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_OUTPUT_HANDLE, m_hLogFileHandle)); + 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; } diff --git a/src/AspNetCoreModuleV2/RequestHandlerLib/PipeOutputManager.cpp b/src/AspNetCoreModuleV2/RequestHandlerLib/PipeOutputManager.cpp index d15f5b458b..79ec3e356f 100644 --- a/src/AspNetCoreModuleV2/RequestHandlerLib/PipeOutputManager.cpp +++ b/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*/)) - { - hr = HRESULT_FROM_WIN32(GetLastError()); - goto Finished; - } + RETURN_LAST_ERROR_IF(!CreatePipe(&hStdErrReadPipe, &hStdErrWritePipe, &saAttr, 0 /*nSize*/)); // TODO this still doesn't redirect calls in native, like wprintf - if (!SetStdHandle(STD_ERROR_HANDLE, hStdErrWritePipe)) - { - hr = HRESULT_FROM_WIN32(GetLastError()); - goto Finished; - } + RETURN_LAST_ERROR_IF(!SetStdHandle(STD_ERROR_HANDLE, hStdErrWritePipe)); - if (!SetStdHandle(STD_OUTPUT_HANDLE, hStdErrWritePipe)) - { - hr = HRESULT_FROM_WIN32(GetLastError()); - goto Finished; - } + RETURN_LAST_ERROR_IF(!SetStdHandle(STD_OUTPUT_HANDLE, hStdErrWritePipe)); 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) - { - hr = HRESULT_FROM_WIN32(GetLastError()); - goto Finished; - } + RETURN_LAST_ERROR_IF_NULL(m_hErrThread); -Finished: - return hr; + return S_OK; } VOID diff --git a/src/AspNetCoreModuleV2/RequestHandlerLib/PipeOutputManager.h b/src/AspNetCoreModuleV2/RequestHandlerLib/PipeOutputManager.h index 57081ea8cd..f51688197c 100644 --- a/src/AspNetCoreModuleV2/RequestHandlerLib/PipeOutputManager.h +++ b/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; }; diff --git a/test/IISIntegration.FunctionalTests/Inprocess/LoggingTests.cs b/test/IISIntegration.FunctionalTests/Inprocess/LoggingTests.cs index 60e39ceb35..defdf6a8a4 100644 --- a/test/IISIntegration.FunctionalTests/Inprocess/LoggingTests.cs +++ b/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"); - 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 { - try - { - contents = await File.ReadAllTextAsync(fileInDirectory); - break; - } - catch (IOException) - { - // File in use by IISExpress, delay a bit before rereading. - } - await Task.Delay(20); + Helpers.ModifyAspNetCoreSectionInWebConfig(deploymentResult, "stdoutLogEnabled", "true"); + 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; + + // 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); - - // Open the log file and see if there are any contents. - Assert.Contains("TEST MESSAGE", contents); - - RetryHelper.RetryOperation( - () => Directory.Delete(deploymentParameters.PublishedApplicationRootPath, true), - e => Logger.LogWarning($"Failed to delete directory : {e.Message}"), - retryCount: 3, - retryDelayMilliseconds: 100); + RetryHelper.RetryOperation( + () => Directory.Delete(deploymentParameters.PublishedApplicationRootPath, true), + e => Logger.LogWarning($"Failed to delete directory : {e.Message}"), + retryCount: 3, + retryDelayMilliseconds: 100); + } } } }