From 2778570f0b2bbf29308f8a6fa4f96e0937f3b1d3 Mon Sep 17 00:00:00 2001 From: Justin Kotalik Date: Tue, 21 Aug 2018 14:03:26 -0700 Subject: [PATCH] Redirect native logs into stdout and pipe (#1154) --- .../AspNetCore/HandlerResolver.cpp | 49 ++++- .../AspNetCore/aspnetcore_shim_config.cpp | 10 +- .../AspNetCore/aspnetcore_shim_config.h | 17 +- .../CommonLib/CommonLib.vcxproj | 10 + src/AspNetCoreModuleV2/CommonLib/EventLog.cpp | 2 +- .../CommonLib/FileOutputManager.cpp | 190 +++++++++++++++++ .../FileOutputManager.h | 14 +- .../CommonLib/HandleWrapper.h | 1 + .../IOutputManager.h | 6 +- .../LoggingHelpers.cpp | 18 +- .../LoggingHelpers.h | 4 +- .../NullOutputManager.h | 0 .../PipeOutputManager.cpp | 175 +++++++++------- .../PipeOutputManager.h | 28 ++- .../CommonLib/StdWrapper.cpp | 148 +++++++++++++ src/AspNetCoreModuleV2/CommonLib/StdWrapper.h | 25 +++ .../CommonLib/aspnetcore_msg.mc | 6 +- src/AspNetCoreModuleV2/CommonLib/resources.h | 8 +- src/AspNetCoreModuleV2/CommonLib/sttimer.h | 1 + .../inprocessapplication.cpp | 40 ++-- .../inprocessapplication.h | 2 +- .../RequestHandlerLib/FileOutputManager.cpp | 195 ------------------ .../RequestHandlerLib.vcxproj | 8 - .../IISDeployer.cs | 7 + .../IISDeployerBase.cs | 2 + .../IISDeploymentParameterExtensions.cs | 10 + .../IISDeploymentParameters.cs | 3 - .../IISExpressDeployer.cs | 9 +- .../Inprocess/EventLogTests.cs | 6 +- .../Inprocess/LoggingTests.cs | 11 +- .../MultiApplicationTests.cs | 1 + .../Utilities/EventLogHelpers.cs | 15 +- .../Utilities/FunctionalTestsBase.cs | 10 +- .../Utilities/SkipIfDebugAttribute.cs | 22 ++ .../CommonLibTests/FileOutputManagerTests.cpp | 55 +++-- .../CommonLibTests/PipeOutputManagerTests.cpp | 103 ++++++++- .../Inprocess/StdOutRedirectionTests.cs | 171 +++++++++++++++ .../InProcess/ShutdownTests.cs | 7 +- 38 files changed, 989 insertions(+), 400 deletions(-) create mode 100644 src/AspNetCoreModuleV2/CommonLib/FileOutputManager.cpp rename src/AspNetCoreModuleV2/{RequestHandlerLib => CommonLib}/FileOutputManager.h (70%) rename src/AspNetCoreModuleV2/{RequestHandlerLib => CommonLib}/IOutputManager.h (94%) rename src/AspNetCoreModuleV2/{RequestHandlerLib => CommonLib}/LoggingHelpers.cpp (62%) rename src/AspNetCoreModuleV2/{RequestHandlerLib => CommonLib}/LoggingHelpers.h (81%) rename src/AspNetCoreModuleV2/{RequestHandlerLib => CommonLib}/NullOutputManager.h (100%) rename src/AspNetCoreModuleV2/{RequestHandlerLib => CommonLib}/PipeOutputManager.cpp (50%) rename src/AspNetCoreModuleV2/{RequestHandlerLib => CommonLib}/PipeOutputManager.h (53%) create mode 100644 src/AspNetCoreModuleV2/CommonLib/StdWrapper.cpp create mode 100644 src/AspNetCoreModuleV2/CommonLib/StdWrapper.h delete mode 100644 src/AspNetCoreModuleV2/RequestHandlerLib/FileOutputManager.cpp create mode 100644 test/Common.FunctionalTests/Utilities/SkipIfDebugAttribute.cs create mode 100644 test/IIS.FunctionalTests/Inprocess/StdOutRedirectionTests.cs diff --git a/src/AspNetCoreModuleV2/AspNetCore/HandlerResolver.cpp b/src/AspNetCoreModuleV2/AspNetCore/HandlerResolver.cpp index 6c78cc16a6..49d1a29093 100644 --- a/src/AspNetCoreModuleV2/AspNetCore/HandlerResolver.cpp +++ b/src/AspNetCoreModuleV2/AspNetCore/HandlerResolver.cpp @@ -10,6 +10,8 @@ #include "GlobalVersionUtility.h" #include "HandleWrapper.h" #include "file_utility.h" +#include "LoggingHelpers.h" +#include "resources.h" const PCWSTR HandlerResolver::s_pwzAspnetcoreInProcessRequestHandlerName = L"aspnetcorev2_inprocess.dll"; const PCWSTR HandlerResolver::s_pwzAspnetcoreOutOfProcessRequestHandlerName = L"aspnetcorev2_outofprocess.dll"; @@ -46,6 +48,7 @@ HandlerResolver::LoadRequestHandlerAssembly(IHttpApplication &pApplication, STRU if (pConfiguration->QueryHostingModel() == APP_HOSTING_MODEL::HOSTING_IN_PROCESS) { std::unique_ptr options; + std::unique_ptr outputManager; RETURN_IF_FAILED(HOSTFXR_OPTIONS::Create( NULL, @@ -56,14 +59,35 @@ HandlerResolver::LoadRequestHandlerAssembly(IHttpApplication &pApplication, STRU RETURN_IF_FAILED(location.Copy(options->GetExeLocation())); - if (FAILED_LOG(hr = FindNativeAssemblyFromHostfxr(options.get(), pstrHandlerDllName, &struFileName))) - { - EventLog::Error( - ASPNETCORE_EVENT_INPROCESS_RH_MISSING, - ASPNETCORE_EVENT_INPROCESS_RH_MISSING_MSG, - struFileName.IsEmpty() ? s_pwzAspnetcoreInProcessRequestHandlerName : struFileName.QueryStr()); + RETURN_IF_FAILED(LoggingHelpers::CreateLoggingProvider( + pConfiguration->QueryStdoutLogEnabled(), + !m_pServer.IsCommandLineLaunch(), + pConfiguration->QueryStdoutLogFile()->QueryStr(), + pApplication.GetApplicationPhysicalPath(), + outputManager)); + + outputManager->Start(); + + hr = FindNativeAssemblyFromHostfxr(options.get(), pstrHandlerDllName, &struFileName); + outputManager->Stop(); + + if (FAILED(hr) && m_hHostFxrDll != NULL) + { + STRA content; + STRU struStdMsg; + + outputManager->GetStdOutContent(&content); + if (content.QueryCCH() > 0) + { + struStdMsg.CopyA(content.QueryStr()); + } + + EventLog::Error( + ASPNETCORE_EVENT_GENERAL_ERROR, + ASPNETCORE_EVENT_INPROCESS_RH_ERROR_MSG, + struFileName.IsEmpty() ? s_pwzAspnetcoreInProcessRequestHandlerName : struFileName.QueryStr(), + struStdMsg.QueryStr()); - return hr; } } else @@ -188,12 +212,23 @@ HandlerResolver::FindNativeAssemblyFromHostfxr( BOOL fFound = FALSE; DWORD dwBufferSize = 1024 * 10; DWORD dwRequiredBufferSize = 0; + STRA output; + DBG_ASSERT(struFilename != NULL); RETURN_LAST_ERROR_IF_NULL(m_hHostFxrDll = LoadLibraryW(hostfxrOptions->GetHostFxrLocation())); auto pFnHostFxrSearchDirectories = reinterpret_cast(GetProcAddress(m_hHostFxrDll, "hostfxr_get_native_search_directories")); + if (pFnHostFxrSearchDirectories == nullptr) + { + EventLog::Error( + ASPNETCORE_EVENT_GENERAL_ERROR, + ASPNETCORE_EVENT_HOSTFXR_DLL_INVALID_VERSION_MSG, + hostfxrOptions->GetHostFxrLocation() + ); + RETURN_IF_FAILED(E_FAIL); + } RETURN_LAST_ERROR_IF_NULL(pFnHostFxrSearchDirectories); RETURN_IF_FAILED(struNativeSearchPaths.Resize(dwBufferSize)); diff --git a/src/AspNetCoreModuleV2/AspNetCore/aspnetcore_shim_config.cpp b/src/AspNetCoreModuleV2/AspNetCore/aspnetcore_shim_config.cpp index 10adc6e2b4..bdd76953ac 100644 --- a/src/AspNetCoreModuleV2/AspNetCore/aspnetcore_shim_config.cpp +++ b/src/AspNetCoreModuleV2/AspNetCore/aspnetcore_shim_config.cpp @@ -29,7 +29,7 @@ ASPNETCORE_SHIM_CONFIG::Populate( CS_ASPNETCORE_PROCESS_EXE_PATH, &m_struProcessPath)); - // Swallow this error for backward compatability + // Swallow this error for backward compatibility // Use default behavior for empty string GetElementStringProperty(pAspNetCoreElement, CS_ASPNETCORE_HOSTING_MODEL, @@ -62,5 +62,13 @@ ASPNETCORE_SHIM_CONFIG::Populate( RETURN_IF_FAILED(ConfigUtility::FindHandlerVersion(pAspNetCoreElement, m_struHandlerVersion)); } + + RETURN_IF_FAILED(GetElementBoolProperty(pAspNetCoreElement, + CS_ASPNETCORE_STDOUT_LOG_ENABLED, + &m_fStdoutLogEnabled)); + RETURN_IF_FAILED(GetElementStringProperty(pAspNetCoreElement, + CS_ASPNETCORE_STDOUT_LOG_FILE, + &m_struStdoutLogFile)); + return S_OK; } diff --git a/src/AspNetCoreModuleV2/AspNetCore/aspnetcore_shim_config.h b/src/AspNetCoreModuleV2/AspNetCore/aspnetcore_shim_config.h index 1ae97f79af..e80071b1c9 100644 --- a/src/AspNetCoreModuleV2/AspNetCore/aspnetcore_shim_config.h +++ b/src/AspNetCoreModuleV2/AspNetCore/aspnetcore_shim_config.h @@ -12,6 +12,8 @@ #define CS_ASPNETCORE_PROCESS_EXE_PATH L"processPath" #define CS_ASPNETCORE_PROCESS_ARGUMENTS L"arguments" #define CS_ASPNETCORE_HOSTING_MODEL L"hostingModel" +#define CS_ASPNETCORE_STDOUT_LOG_ENABLED L"stdoutLogEnabled" +#define CS_ASPNETCORE_STDOUT_LOG_FILE L"stdoutLogFile" enum APP_HOSTING_MODEL { @@ -56,6 +58,18 @@ public: return &m_struHandlerVersion; } + BOOL + QueryStdoutLogEnabled() + { + return m_fStdoutLogEnabled; + } + + STRU* + QueryStdoutLogFile() + { + return &m_struStdoutLogFile; + } + ASPNETCORE_SHIM_CONFIG() : m_hostingModel(HOSTING_UNKNOWN) { @@ -67,5 +81,6 @@ private: STRU m_struProcessPath; APP_HOSTING_MODEL m_hostingModel; STRU m_struHandlerVersion; + BOOL m_fStdoutLogEnabled; + STRU m_struStdoutLogFile; }; - diff --git a/src/AspNetCoreModuleV2/CommonLib/CommonLib.vcxproj b/src/AspNetCoreModuleV2/CommonLib/CommonLib.vcxproj index 12e6ff1691..47a5373ee1 100644 --- a/src/AspNetCoreModuleV2/CommonLib/CommonLib.vcxproj +++ b/src/AspNetCoreModuleV2/CommonLib/CommonLib.vcxproj @@ -200,6 +200,7 @@ + @@ -207,7 +208,12 @@ + + + + + @@ -220,11 +226,15 @@ + + + + diff --git a/src/AspNetCoreModuleV2/CommonLib/EventLog.cpp b/src/AspNetCoreModuleV2/CommonLib/EventLog.cpp index 7d10a8abf9..24992232de 100644 --- a/src/AspNetCoreModuleV2/CommonLib/EventLog.cpp +++ b/src/AspNetCoreModuleV2/CommonLib/EventLog.cpp @@ -27,7 +27,7 @@ EventLog::LogEvent( ); } - DebugPrintf(dwEventInfoType == EVENTLOG_ERROR_TYPE ? ASPNETCORE_DEBUG_FLAG_ERROR : ASPNETCORE_DEBUG_FLAG_INFO, "Event Log: %S", pstrMsg); + DebugPrintf(dwEventInfoType == EVENTLOG_ERROR_TYPE ? ASPNETCORE_DEBUG_FLAG_ERROR : ASPNETCORE_DEBUG_FLAG_INFO, "Event Log: %S \r\nEnd Event Log Message.", pstrMsg); } VOID diff --git a/src/AspNetCoreModuleV2/CommonLib/FileOutputManager.cpp b/src/AspNetCoreModuleV2/CommonLib/FileOutputManager.cpp new file mode 100644 index 0000000000..6e16ac2acd --- /dev/null +++ b/src/AspNetCoreModuleV2/CommonLib/FileOutputManager.cpp @@ -0,0 +1,190 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the MIT License. See License.txt in the project root for license information. + +#include "stdafx.h" +#include "FileOutputManager.h" +#include "sttimer.h" +#include "exceptions.h" +#include "debugutil.h" +#include "SRWExclusiveLock.h" +#include "file_utility.h" +#include "StdWrapper.h" + +extern HINSTANCE g_hModule; + +FileOutputManager::FileOutputManager() : + FileOutputManager(/* fEnableNativeLogging */ true) { } + +FileOutputManager::FileOutputManager(bool fEnableNativeLogging) : + m_hLogFileHandle(INVALID_HANDLE_VALUE), + m_disposed(false), + stdoutWrapper(nullptr), + stderrWrapper(nullptr), + m_fEnableNativeRedirection(fEnableNativeLogging) +{ + InitializeSRWLock(&m_srwLock); +} + +FileOutputManager::~FileOutputManager() +{ + FileOutputManager::Stop(); +} + +HRESULT +FileOutputManager::Initialize(PCWSTR pwzStdOutLogFileName, PCWSTR pwzApplicationPath) +{ + RETURN_IF_FAILED(m_wsApplicationPath.Copy(pwzApplicationPath)); + RETURN_IF_FAILED(m_wsStdOutLogFileName.Copy(pwzStdOutLogFileName)); + + return S_OK; +} + +// Start redirecting stdout and stderr into the file handle. +// Uses sttimer to continuously flush output into the file. +HRESULT +FileOutputManager::Start() +{ + SYSTEMTIME systemTime; + SECURITY_ATTRIBUTES saAttr = { 0 }; + STRU struPath; + + // Concatenate the log file name and application path + RETURN_IF_FAILED(FILE_UTILITY::ConvertPathToFullPath( + m_wsStdOutLogFileName.QueryStr(), + m_wsApplicationPath.QueryStr(), + &struPath)); + + 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_IF_FAILED( + m_struLogFilePath.SafeSnwprintf(L"%s_%d%02d%02d%02d%02d%02d_%d_%s.log", + struPath.QueryStr(), + systemTime.wYear, + systemTime.wMonth, + systemTime.wDay, + systemTime.wHour, + systemTime.wMinute, + systemTime.wSecond, + GetCurrentProcessId(), + fsPath.filename().stem().c_str())); + + saAttr.nLength = sizeof(SECURITY_ATTRIBUTES); + saAttr.bInheritHandle = TRUE; + saAttr.lpSecurityDescriptor = NULL; + + // Create the file with both READ and WRITE. + m_hLogFileHandle = CreateFileW(m_struLogFilePath.QueryStr(), + FILE_READ_DATA | FILE_WRITE_DATA, + FILE_SHARE_READ, + &saAttr, + CREATE_ALWAYS, + FILE_ATTRIBUTE_NORMAL, + nullptr); + + RETURN_LAST_ERROR_IF(m_hLogFileHandle == INVALID_HANDLE_VALUE); + + stdoutWrapper = std::make_unique(stdout, STD_OUTPUT_HANDLE, m_hLogFileHandle, m_fEnableNativeRedirection); + stderrWrapper = std::make_unique(stderr, STD_ERROR_HANDLE, m_hLogFileHandle, m_fEnableNativeRedirection); + + stdoutWrapper->StartRedirection(); + stderrWrapper->StartRedirection(); + + return S_OK; +} + + +HRESULT +FileOutputManager::Stop() +{ + STRA straStdOutput; + CHAR pzFileContents[MAX_FILE_READ_SIZE] = { 0 }; + DWORD dwNumBytesRead; + LARGE_INTEGER li = { 0 }; + DWORD dwFilePointer = 0; + HANDLE handle = NULL; + WIN32_FIND_DATA fileData; + + if (m_disposed) + { + return S_OK; + } + + SRWExclusiveLock lock(m_srwLock); + + if (m_disposed) + { + return S_OK; + } + + m_disposed = true; + + if (m_hLogFileHandle == INVALID_HANDLE_VALUE) + { + return HRESULT_FROM_WIN32(ERROR_FILE_NOT_FOUND); + } + + FlushFileBuffers(m_hLogFileHandle); + + if (stdoutWrapper != nullptr) + { + RETURN_IF_FAILED(stdoutWrapper->StopRedirection()); + } + + if (stderrWrapper != nullptr) + { + RETURN_IF_FAILED(stderrWrapper->StopRedirection()); + } + + // delete empty log file + handle = FindFirstFile(m_struLogFilePath.QueryStr(), &fileData); + if (handle != INVALID_HANDLE_VALUE && + handle != NULL && + fileData.nFileSizeHigh == 0 && + fileData.nFileSizeLow == 0) // skip check of nFileSizeHigh + { + FindClose(handle); + LOG_LAST_ERROR_IF(!DeleteFile(m_struLogFilePath.QueryStr())); + } + + // Read the first 30Kb from the file and store it in a buffer. + // By doing this, we can close the handle to the file and be done with it. + RETURN_LAST_ERROR_IF(!GetFileSizeEx(m_hLogFileHandle, &li)); + + if (li.LowPart == 0 || li.HighPart > 0) + { + RETURN_IF_FAILED(HRESULT_FROM_WIN32(ERROR_FILE_INVALID)); + } + + dwFilePointer = SetFilePointer(m_hLogFileHandle, 0, NULL, FILE_BEGIN); + + RETURN_LAST_ERROR_IF(dwFilePointer == INVALID_SET_FILE_POINTER); + + RETURN_LAST_ERROR_IF(!ReadFile(m_hLogFileHandle, pzFileContents, MAX_FILE_READ_SIZE, &dwNumBytesRead, NULL)); + + m_straFileContent.Copy(pzFileContents, dwNumBytesRead); + + // printf will fail in in full IIS + if (printf(m_straFileContent.QueryStr()) != -1) + { + // Need to flush contents for the new stdout and stderr + _flushall(); + } + + return S_OK; +} + +bool FileOutputManager::GetStdOutContent(STRA* struStdOutput) +{ + struStdOutput->Copy(m_straFileContent); + return m_straFileContent.QueryCCH() > 0; +} diff --git a/src/AspNetCoreModuleV2/RequestHandlerLib/FileOutputManager.h b/src/AspNetCoreModuleV2/CommonLib/FileOutputManager.h similarity index 70% rename from src/AspNetCoreModuleV2/RequestHandlerLib/FileOutputManager.h rename to src/AspNetCoreModuleV2/CommonLib/FileOutputManager.h index b1a43e6b0d..94f6e19176 100644 --- a/src/AspNetCoreModuleV2/RequestHandlerLib/FileOutputManager.h +++ b/src/AspNetCoreModuleV2/CommonLib/FileOutputManager.h @@ -6,12 +6,17 @@ #include "sttimer.h" #include "IOutputManager.h" #include "HandleWrapper.h" +#include "StdWrapper.h" +#include "stringa.h" +#include "stringu.h" class FileOutputManager : public IOutputManager { #define FILE_FLUSH_TIMEOUT 3000 + #define MAX_FILE_READ_SIZE 30000 public: FileOutputManager(); + FileOutputManager(bool fEnableNativeLogging); ~FileOutputManager(); HRESULT @@ -27,9 +32,10 @@ private: STRU m_wsStdOutLogFileName; STRU m_wsApplicationPath; STRU m_struLogFilePath; - int m_fdPreviousStdOut; - int m_fdPreviousStdErr; + STRA m_straFileContent; BOOL m_disposed; - SRWLOCK m_srwLock; + BOOL m_fEnableNativeRedirection; + SRWLOCK m_srwLock{}; + std::unique_ptr stdoutWrapper; + std::unique_ptr stderrWrapper; }; - diff --git a/src/AspNetCoreModuleV2/CommonLib/HandleWrapper.h b/src/AspNetCoreModuleV2/CommonLib/HandleWrapper.h index 6764f4c14d..d6b50f2381 100644 --- a/src/AspNetCoreModuleV2/CommonLib/HandleWrapper.h +++ b/src/AspNetCoreModuleV2/CommonLib/HandleWrapper.h @@ -4,6 +4,7 @@ #pragma once #include +#include struct InvalidHandleTraits { diff --git a/src/AspNetCoreModuleV2/RequestHandlerLib/IOutputManager.h b/src/AspNetCoreModuleV2/CommonLib/IOutputManager.h similarity index 94% rename from src/AspNetCoreModuleV2/RequestHandlerLib/IOutputManager.h rename to src/AspNetCoreModuleV2/CommonLib/IOutputManager.h index b7e04df059..6b733dd0e6 100644 --- a/src/AspNetCoreModuleV2/RequestHandlerLib/IOutputManager.h +++ b/src/AspNetCoreModuleV2/CommonLib/IOutputManager.h @@ -1,9 +1,11 @@ // Copyright (c) .NET Foundation. All rights reserved. // Licensed under the MIT License. See License.txt in the project root for license information. -#include "stdafx.h" - #pragma once + +#include "stdafx.h" +#include "stringa.h" + class IOutputManager { public: diff --git a/src/AspNetCoreModuleV2/RequestHandlerLib/LoggingHelpers.cpp b/src/AspNetCoreModuleV2/CommonLib/LoggingHelpers.cpp similarity index 62% rename from src/AspNetCoreModuleV2/RequestHandlerLib/LoggingHelpers.cpp rename to src/AspNetCoreModuleV2/CommonLib/LoggingHelpers.cpp index a133172db4..69de017e7f 100644 --- a/src/AspNetCoreModuleV2/RequestHandlerLib/LoggingHelpers.cpp +++ b/src/AspNetCoreModuleV2/CommonLib/LoggingHelpers.cpp @@ -7,14 +7,18 @@ #include "FileOutputManager.h" #include "PipeOutputManager.h" #include "NullOutputManager.h" +#include "debugutil.h" +#include +#include +#include "ntassert.h" HRESULT LoggingHelpers::CreateLoggingProvider( bool fIsLoggingEnabled, - bool fEnablePipe, + bool fEnableNativeLogging, PCWSTR pwzStdOutFileName, PCWSTR pwzApplicationPath, - _Out_ IOutputManager** outputManager + std::unique_ptr& outputManager ) { HRESULT hr = S_OK; @@ -25,17 +29,17 @@ LoggingHelpers::CreateLoggingProvider( { if (fIsLoggingEnabled) { - FileOutputManager* manager = new FileOutputManager; + auto manager = std::make_unique(fEnableNativeLogging); hr = manager->Initialize(pwzStdOutFileName, pwzApplicationPath); - *outputManager = manager; + outputManager = std::move(manager); } - else if (fEnablePipe) + else if (!GetConsoleWindow()) { - *outputManager = new PipeOutputManager; + outputManager = std::make_unique(fEnableNativeLogging); } else { - *outputManager = new NullOutputManager; + outputManager = std::make_unique(); } } catch (std::bad_alloc&) diff --git a/src/AspNetCoreModuleV2/RequestHandlerLib/LoggingHelpers.h b/src/AspNetCoreModuleV2/CommonLib/LoggingHelpers.h similarity index 81% rename from src/AspNetCoreModuleV2/RequestHandlerLib/LoggingHelpers.h rename to src/AspNetCoreModuleV2/CommonLib/LoggingHelpers.h index f11a4ff5f5..0c06f759cf 100644 --- a/src/AspNetCoreModuleV2/RequestHandlerLib/LoggingHelpers.h +++ b/src/AspNetCoreModuleV2/CommonLib/LoggingHelpers.h @@ -13,10 +13,10 @@ public: HRESULT CreateLoggingProvider( bool fLoggingEnabled, - bool fEnablePipe, + bool fEnableNativeLogging, PCWSTR pwzStdOutFileName, PCWSTR pwzApplicationPath, - _Out_ IOutputManager** outputManager + std::unique_ptr& outputManager ); }; diff --git a/src/AspNetCoreModuleV2/RequestHandlerLib/NullOutputManager.h b/src/AspNetCoreModuleV2/CommonLib/NullOutputManager.h similarity index 100% rename from src/AspNetCoreModuleV2/RequestHandlerLib/NullOutputManager.h rename to src/AspNetCoreModuleV2/CommonLib/NullOutputManager.h diff --git a/src/AspNetCoreModuleV2/RequestHandlerLib/PipeOutputManager.cpp b/src/AspNetCoreModuleV2/CommonLib/PipeOutputManager.cpp similarity index 50% rename from src/AspNetCoreModuleV2/RequestHandlerLib/PipeOutputManager.cpp rename to src/AspNetCoreModuleV2/CommonLib/PipeOutputManager.cpp index 6fdcdb078b..54fb162fe4 100644 --- a/src/AspNetCoreModuleV2/RequestHandlerLib/PipeOutputManager.cpp +++ b/src/AspNetCoreModuleV2/CommonLib/PipeOutputManager.cpp @@ -5,63 +5,74 @@ #include "PipeOutputManager.h" #include "exceptions.h" #include "SRWExclusiveLock.h" +#include "StdWrapper.h" +#include "ntassert.h" #define LOG_IF_DUPFAIL(err) do { if (err == -1) { LOG_IF_FAILED(HRESULT_FROM_WIN32(_doserrno)); } } while (0, 0); #define LOG_IF_ERRNO(err) do { if (err != 0) { LOG_IF_FAILED(HRESULT_FROM_WIN32(_doserrno)); } } while (0, 0); -PipeOutputManager::PipeOutputManager() : - m_dwStdErrReadTotal(0), +PipeOutputManager::PipeOutputManager() + : PipeOutputManager( /* fEnableNativeLogging */ true) +{ +} + +PipeOutputManager::PipeOutputManager(bool fEnableNativeLogging) : m_hErrReadPipe(INVALID_HANDLE_VALUE), m_hErrWritePipe(INVALID_HANDLE_VALUE), - m_hErrThread(NULL), + m_hErrThread(nullptr), + m_dwStdErrReadTotal(0), m_disposed(FALSE), - m_fdPreviousStdOut(-1), - m_fdPreviousStdErr(-1) + m_fEnableNativeRedirection(fEnableNativeLogging), + stdoutWrapper(nullptr), + stderrWrapper(nullptr) { InitializeSRWLock(&m_srwLock); } PipeOutputManager::~PipeOutputManager() { - Stop(); + PipeOutputManager::Stop(); } +// Start redirecting stdout and stderr into a pipe +// Continuously read the pipe on a background thread +// until Stop is called. HRESULT PipeOutputManager::Start() { SECURITY_ATTRIBUTES saAttr = { 0 }; HANDLE hStdErrReadPipe; HANDLE hStdErrWritePipe; - m_fdPreviousStdOut = _dup(_fileno(stdout)); - LOG_IF_DUPFAIL(m_fdPreviousStdOut); - - m_fdPreviousStdErr = _dup(_fileno(stderr)); - LOG_IF_DUPFAIL(m_fdPreviousStdErr); - RETURN_LAST_ERROR_IF(!CreatePipe(&hStdErrReadPipe, &hStdErrWritePipe, &saAttr, 0 /*nSize*/)); - // TODO this still doesn't redirect calls in native, like wprintf - RETURN_LAST_ERROR_IF(!SetStdHandle(STD_ERROR_HANDLE, hStdErrWritePipe)); - - RETURN_LAST_ERROR_IF(!SetStdHandle(STD_OUTPUT_HANDLE, hStdErrWritePipe)); - m_hErrReadPipe = hStdErrReadPipe; m_hErrWritePipe = hStdErrWritePipe; - // Read the stderr handle on a separate thread until we get 4096 bytes. + stdoutWrapper = std::make_unique(stdout, STD_OUTPUT_HANDLE, hStdErrWritePipe, m_fEnableNativeRedirection); + stderrWrapper = std::make_unique(stderr, STD_ERROR_HANDLE, hStdErrWritePipe, m_fEnableNativeRedirection); + + LOG_IF_FAILED(stdoutWrapper->StartRedirection()); + LOG_IF_FAILED(stderrWrapper->StartRedirection()); + + // Read the stderr handle on a separate thread until we get 30Kb. m_hErrThread = CreateThread( - NULL, // default security attributes + nullptr, // default security attributes 0, // default stack size - (LPTHREAD_START_ROUTINE)ReadStdErrHandle, + reinterpret_cast(ReadStdErrHandle), this, // thread function arguments 0, // default creation flags - NULL); // receive thread identifier + nullptr); // receive thread identifier RETURN_LAST_ERROR_IF_NULL(m_hErrThread); return S_OK; } +// Stop redirecting stdout and stderr into a pipe +// This closes the background thread reading from the pipe +// and prints any output that was captured in the pipe. +// If more than 30Kb was written to the pipe, that output will +// be thrown away. HRESULT PipeOutputManager::Stop() { DWORD dwThreadStatus = 0; @@ -71,57 +82,53 @@ HRESULT PipeOutputManager::Stop() { return S_OK; } + SRWExclusiveLock lock(m_srwLock); if (m_disposed) { return S_OK; } + m_disposed = true; - fflush(stdout); - fflush(stderr); - - // Restore the original stdout and stderr handles of the process, - // as the application has either finished startup or has exited. - - // If stdout/stderr were not set, we need to set it to NUL: - // such that other calls to Console.WriteLine don't use an invalid handle - FILE *stream; - - if (m_fdPreviousStdOut >= 0) - { - LOG_LAST_ERROR_IF(SetStdHandle(STD_OUTPUT_HANDLE, (HANDLE)_get_osfhandle(m_fdPreviousStdOut))); - } - else - { - LOG_IF_ERRNO(freopen_s(&stream, "NUL:", "w", stdout)); - } - - if (m_fdPreviousStdErr >= 0) - { - LOG_LAST_ERROR_IF(SetStdHandle(STD_ERROR_HANDLE, (HANDLE)_get_osfhandle(m_fdPreviousStdErr))); - } - else - { - LOG_IF_ERRNO(freopen_s(&stream, "NUL:", "w", stderr)); - } - + // Both pipe wrappers duplicate the pipe writer handle + // meaning we are fine to close the handle too. if (m_hErrWritePipe != INVALID_HANDLE_VALUE) { + // Flush the pipe writer before closing to capture all output + RETURN_LAST_ERROR_IF(!FlushFileBuffers(m_hErrWritePipe)); CloseHandle(m_hErrWritePipe); m_hErrWritePipe = INVALID_HANDLE_VALUE; } + // Tell each pipe wrapper to stop redirecting output and restore the original values + if (stdoutWrapper != nullptr) + { + LOG_IF_FAILED(stdoutWrapper->StopRedirection()); + } + + if (stderrWrapper != nullptr) + { + LOG_IF_FAILED(stderrWrapper->StopRedirection()); + } + + // Forces ReadFile to cancel, causing the read loop to complete. + // Don't check return value as IO may or may not be completed already. + if (m_hErrThread != nullptr) + { + CancelSynchronousIo(m_hErrThread); + } + // GetExitCodeThread returns 0 on failure; thread status code is invalid. - if (m_hErrThread != NULL && + if (m_hErrThread != nullptr && !LOG_LAST_ERROR_IF(GetExitCodeThread(m_hErrThread, &dwThreadStatus) == 0) && dwThreadStatus == STILL_ACTIVE) { - // wait for graceful shutdown, 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 the thread is still running, we need kill it first before exit to avoid AV if (!LOG_LAST_ERROR_IF(GetExitCodeThread(m_hErrThread, &dwThreadStatus) == 0) && dwThreadStatus == STILL_ACTIVE) { @@ -131,42 +138,38 @@ HRESULT PipeOutputManager::Stop() } } - if (m_hErrThread != NULL) + if (m_hErrThread != nullptr) { CloseHandle(m_hErrThread); - m_hErrThread = NULL; + m_hErrThread = nullptr; } - if (m_hErrReadPipe != INVALID_HANDLE_VALUE) { CloseHandle(m_hErrReadPipe); m_hErrReadPipe = INVALID_HANDLE_VALUE; } + // If we captured any output, relog it to the original stdout + // Useful for the IIS Express scenario as it is running with stdout and stderr if (GetStdOutContent(&straStdOutput)) { - printf(straStdOutput.QueryStr()); - // Need to flush contents for the new stdout and stderr - _flushall(); + // printf will fail in in full IIS + if (printf(straStdOutput.QueryStr()) != -1) + { + // Need to flush contents for the new stdout and stderr + _flushall(); + } } return S_OK; } -VOID -PipeOutputManager::ReadStdErrHandle( - LPVOID pContext -) -{ - PipeOutputManager *pLoggingProvider = (PipeOutputManager*)pContext; - DBG_ASSERT(pLoggingProvider != NULL); - pLoggingProvider->ReadStdErrHandleInternal(); -} - bool PipeOutputManager::GetStdOutContent(STRA* straStdOutput) { bool fLogged = false; + + // TODO consider returning the file contents rather than copying. if (m_dwStdErrReadTotal > 0) { if (SUCCEEDED(straStdOutput->Copy(m_pzFileContents, m_dwStdErrReadTotal))) @@ -178,15 +181,29 @@ bool PipeOutputManager::GetStdOutContent(STRA* straStdOutput) return fLogged; } -VOID -PipeOutputManager::ReadStdErrHandleInternal( - VOID +void +PipeOutputManager::ReadStdErrHandle( + LPVOID pContext ) { + auto pLoggingProvider = static_cast(pContext); + DBG_ASSERT(pLoggingProvider != NULL); + pLoggingProvider->ReadStdErrHandleInternal(); +} + +void +PipeOutputManager::ReadStdErrHandleInternal() +{ + // If ReadFile ever returns false, exit the thread DWORD dwNumBytesRead = 0; while (true) { - if (ReadFile(m_hErrReadPipe, &m_pzFileContents[m_dwStdErrReadTotal], MAX_PIPE_READ_SIZE - m_dwStdErrReadTotal, &dwNumBytesRead, NULL)) + // Fill a maximum of MAX_PIPE_READ_SIZE into a buffer. + if (ReadFile(m_hErrReadPipe, + &m_pzFileContents[m_dwStdErrReadTotal], + MAX_PIPE_READ_SIZE - m_dwStdErrReadTotal, + &dwNumBytesRead, + nullptr)) { m_dwStdErrReadTotal += dwNumBytesRead; if (m_dwStdErrReadTotal >= MAX_PIPE_READ_SIZE) @@ -194,19 +211,21 @@ PipeOutputManager::ReadStdErrHandleInternal( break; } } - else if (GetLastError() == ERROR_BROKEN_PIPE) + else { return; } } - char tempBuffer[MAX_PIPE_READ_SIZE]; + // Using std::string as a wrapper around new char[] so we don't need to call delete + // Also don't allocate on stack as stack size is 128KB by default. + std::string tempBuffer; + tempBuffer.resize(MAX_PIPE_READ_SIZE); + + // After reading the maximum amount of data, keep reading in a loop until Stop is called on the output manager. while (true) { - if (ReadFile(m_hErrReadPipe, tempBuffer, MAX_PIPE_READ_SIZE, &dwNumBytesRead, NULL)) - { - } - else if (GetLastError() == ERROR_BROKEN_PIPE) + if (!ReadFile(m_hErrReadPipe, tempBuffer.data(), MAX_PIPE_READ_SIZE, &dwNumBytesRead, nullptr)) { return; } diff --git a/src/AspNetCoreModuleV2/RequestHandlerLib/PipeOutputManager.h b/src/AspNetCoreModuleV2/CommonLib/PipeOutputManager.h similarity index 53% rename from src/AspNetCoreModuleV2/RequestHandlerLib/PipeOutputManager.h rename to src/AspNetCoreModuleV2/CommonLib/PipeOutputManager.h index 3a15c2e68e..0b51ff4038 100644 --- a/src/AspNetCoreModuleV2/RequestHandlerLib/PipeOutputManager.h +++ b/src/AspNetCoreModuleV2/CommonLib/PipeOutputManager.h @@ -4,35 +4,41 @@ #pragma once #include "IOutputManager.h" +#include "StdWrapper.h" +#include "stringu.h" class PipeOutputManager : public IOutputManager { + // Timeout to be used if a thread never exits #define PIPE_OUTPUT_THREAD_TIMEOUT 2000 - #define MAX_PIPE_READ_SIZE 4096 + + // Max event log message is ~32KB, limit pipe size just below that. + #define MAX_PIPE_READ_SIZE 30000 public: PipeOutputManager(); + PipeOutputManager(bool fEnableNativeLogging); ~PipeOutputManager(); - virtual HRESULT Start() override; - virtual HRESULT Stop() override; - virtual bool GetStdOutContent(STRA* struStdOutput) override; + HRESULT Start() override; + HRESULT Stop() override; + bool GetStdOutContent(STRA* straStdOutput) override; // Thread functions - VOID ReadStdErrHandleInternal(VOID); + void ReadStdErrHandleInternal(); - static - VOID ReadStdErrHandle(LPVOID pContext); + static void ReadStdErrHandle(LPVOID pContext); private: + HANDLE m_hErrReadPipe; HANDLE m_hErrWritePipe; STRU m_struLogFilePath; HANDLE m_hErrThread; CHAR m_pzFileContents[MAX_PIPE_READ_SIZE] = { 0 }; DWORD m_dwStdErrReadTotal; - SRWLOCK m_srwLock; - int m_fdPreviousStdOut; - int m_fdPreviousStdErr; + SRWLOCK m_srwLock {}; BOOL m_disposed; + BOOL m_fEnableNativeRedirection; + std::unique_ptr stdoutWrapper; + std::unique_ptr stderrWrapper; }; - diff --git a/src/AspNetCoreModuleV2/CommonLib/StdWrapper.cpp b/src/AspNetCoreModuleV2/CommonLib/StdWrapper.cpp new file mode 100644 index 0000000000..dffaa491c5 --- /dev/null +++ b/src/AspNetCoreModuleV2/CommonLib/StdWrapper.cpp @@ -0,0 +1,148 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the MIT License. See License.txt in the project root for license information. + +#include "stdafx.h" +#include "StdWrapper.h" +#include "exceptions.h" +#include "LoggingHelpers.h" +#include +#include + +StdWrapper::StdWrapper(FILE* stdStream, DWORD stdHandleNumber, HANDLE handleToRedirectTo, BOOL fEnableNativeRedirection) + : m_previousFileDescriptor(0), + m_stdStream(stdStream), + m_stdHandleNumber(stdHandleNumber), + m_fEnableNativeRedirection(fEnableNativeRedirection), + m_handleToRedirectTo(handleToRedirectTo), + m_redirectedFile(nullptr) +{ +} + +StdWrapper::~StdWrapper() = default; + +// Redirects stdout/stderr to the provided handle. +// Example: +// If the handleToRedirecTo = 0x24 +// Before: +// _fileno(stdout) = 1 +// GetStdHandle(STD_OUTPUT_HANDLE) = 0x20 +// After: +// _fileno(stdout) = 3 +// GetStdHandle(STD_OUTPUT_HANDLE) = 0x28 <- Duplicated from 0x24 +HRESULT +StdWrapper::StartRedirection() +{ + HANDLE stdHandle; + + // In IIS, stdout and stderr are set to null as w3wp is created with DETACHED_PROCESS, + // so fileno(m_stdStream) returns -2. + // Open a null file such that undoing the redirection succeeds and _dup2 works. + // m_previousFileDescriptor will be used for restoring stdout/stderr + if (_fileno(m_stdStream) == -2) + { + freopen_s((FILE**)&m_stdStream, "nul", "w", m_stdStream); + m_previousFileDescriptor = _dup(_fileno(m_stdStream)); + } + else + { + m_previousFileDescriptor = _dup(_fileno(m_stdStream)); + } + + if (!m_fEnableNativeRedirection) + { + RETURN_LAST_ERROR_IF(!SetStdHandle(m_stdHandleNumber, m_handleToRedirectTo)); + + return S_OK; + } + // After setting the std handle, we need to set stdout/stderr to the current + // output/error handle. + + // Duplicate the handle before opening the handle and associating a file pointer. + // If we don't by calling close on the file, the same handle value will be closed + // multiple times. + // Note, by calling duplicate handle, the new handle returned will have a different value + // than the original, but point to the same underlying file object. + RETURN_LAST_ERROR_IF(!DuplicateHandle( + /* hSourceProcessHandle*/ GetCurrentProcess(), + /* hSourceHandle */ m_handleToRedirectTo, + /* hTargetProcessHandle */ GetCurrentProcess(), + /* lpTargetHandle */&stdHandle, + /* dwDesiredAccess */ 0, // dwDesired is ignored if DUPLICATE_SAME_ACCESS is specified + /* bInheritHandle */ TRUE, + /* dwOptions */ DUPLICATE_SAME_ACCESS)); + + RETURN_LAST_ERROR_IF(!SetStdHandle(m_stdHandleNumber, stdHandle)); + + // _open_osfhandle will associate a filedescriptor with the handle. + const auto fileDescriptor = _open_osfhandle(reinterpret_cast(stdHandle), _O_WTEXT | _O_TEXT); + + if (fileDescriptor == -1) + { + RETURN_IF_FAILED(HRESULT_FROM_WIN32(ERROR_FILE_INVALID)); + } + + m_redirectedFile = _fdopen(fileDescriptor, "w"); + + if (m_redirectedFile == nullptr) + { + RETURN_IF_FAILED(HRESULT_FROM_WIN32(ERROR_FILE_INVALID)); + } + + // Set stdout/stderr to the newly created file. + const auto dup2Result = _dup2(_fileno(m_redirectedFile), _fileno(m_stdStream)); + + if (dup2Result != 0) + { + RETURN_IF_FAILED(HRESULT_FROM_WIN32(ERROR_FILE_INVALID)); + } + + // Removes buffering from the output + if (setvbuf(m_stdStream, nullptr, _IONBF, 0) != 0) + { + RETURN_IF_FAILED(HRESULT_FROM_WIN32(ERROR_FILE_INVALID)); + } + + return S_OK; +} + +// Redirects stdout/stderr back to the original stdout/stderr. +// Note, this will not restore the original handle values returned by GetStdHandle, +// rather a duplicated number. This is because the original handle value is invalid +// due to dup2 closing the file originally in stdout/stderr +HRESULT +StdWrapper::StopRedirection() const +{ + // After setting the std handle, we need to set stdout/stderr to the current + // output/error handle. + FILE * file = _fdopen(m_previousFileDescriptor, "w"); + if (file == nullptr) + { + RETURN_IF_FAILED(HRESULT_FROM_WIN32(ERROR_FILE_INVALID)); + } + + RETURN_LAST_ERROR_IF(!SetStdHandle(m_stdHandleNumber, reinterpret_cast(_get_osfhandle(m_previousFileDescriptor)))); + + if (!m_fEnableNativeRedirection) + { + return S_OK; + } + + // Set stdout/stderr to the newly created file output. + const auto dup2Result = _dup2(_fileno(file), _fileno(m_stdStream)); + if (dup2Result != 0) + { + RETURN_IF_FAILED(HRESULT_FROM_WIN32(ERROR_FILE_INVALID)); + } + + if (setvbuf(m_stdStream, nullptr, _IONBF, 0) != 0) + { + RETURN_IF_FAILED(HRESULT_FROM_WIN32(ERROR_FILE_INVALID)); + } + + if (fclose(m_redirectedFile) != 0) + { + RETURN_IF_FAILED(HRESULT_FROM_WIN32(ERROR_FILE_INVALID)); + } + + return S_OK; +} diff --git a/src/AspNetCoreModuleV2/CommonLib/StdWrapper.h b/src/AspNetCoreModuleV2/CommonLib/StdWrapper.h new file mode 100644 index 0000000000..f03b2ff060 --- /dev/null +++ b/src/AspNetCoreModuleV2/CommonLib/StdWrapper.h @@ -0,0 +1,25 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the MIT License. See License.txt in the project root for license information. + +#pragma once + +#include + +// Wraps stdout/stderr stream, modifying them to redirect to the given handle +class StdWrapper +{ +public: + StdWrapper(FILE* stdStream, DWORD stdHandleNumber, HANDLE handleToRedirectTo, BOOL fEnableNativeRedirection); + ~StdWrapper(); + HRESULT StartRedirection(); + HRESULT StopRedirection() const; + +private: + int m_previousFileDescriptor; + FILE* m_stdStream; + DWORD m_stdHandleNumber; + BOOL m_fEnableNativeRedirection; + HANDLE m_handleToRedirectTo; + FILE* m_redirectedFile; +}; + diff --git a/src/AspNetCoreModuleV2/CommonLib/aspnetcore_msg.mc b/src/AspNetCoreModuleV2/CommonLib/aspnetcore_msg.mc index c71cbfeee2..5b4c244c63 100644 --- a/src/AspNetCoreModuleV2/CommonLib/aspnetcore_msg.mc +++ b/src/AspNetCoreModuleV2/CommonLib/aspnetcore_msg.mc @@ -177,19 +177,19 @@ Language=English . Messageid=1025 -SymbolicName=ASPNETCORE_EVENT_GENERAL_INFO_MSG +SymbolicName=ASPNETCORE_EVENT_GENERAL_INFO Language=English %1 . Messageid=1026 -SymbolicName=ASPNETCORE_EVENT_GENERAL_WARNING_MSG +SymbolicName=ASPNETCORE_EVENT_GENERAL_WARNING Language=English %1 . Messageid=1027 -SymbolicName=ASPNETCORE_EVENT_GENERAL_ERROR_MSG +SymbolicName=ASPNETCORE_EVENT_GENERAL_ERROR Language=English %1 . diff --git a/src/AspNetCoreModuleV2/CommonLib/resources.h b/src/AspNetCoreModuleV2/CommonLib/resources.h index cf5aa90f1e..82f22c52c0 100644 --- a/src/AspNetCoreModuleV2/CommonLib/resources.h +++ b/src/AspNetCoreModuleV2/CommonLib/resources.h @@ -31,8 +31,8 @@ #define ASPNETCORE_EVENT_MIXED_HOSTING_MODEL_ERROR_MSG L"Mixed hosting model is not supported. Application '%s' configured with different hostingModel value '%d' other than the one of running application(s)." #define ASPNETCORE_EVENT_UNKNOWN_HOSTING_MODEL_ERROR_MSG L"Unknown hosting model '%s'. Please specify either hostingModel=\"inprocess\" or hostingModel=\"outofprocess\" in the web.config file." #define ASPNETCORE_EVENT_ADD_APPLICATION_ERROR_MSG L"Failed to start application '%s', ErrorCode '0x%x'." -#define ASPNETCORE_EVENT_INPROCESS_THREAD_EXIT_STDOUT_MSG L"Application '%s' with physical root '%s' hit unexpected managed background thread exit, ErrorCode = '0x%x. Last 4KB characters of captured stdout and stderr logs:\r\n%s" -#define ASPNETCORE_EVENT_INPROCESS_THREAD_EXIT_MSG L"Application '%s' with physical root '%s' hit unexpected managed background thread exit, ErrorCode = '0x%x. Please check the stderr logs for more information." +#define ASPNETCORE_EVENT_INPROCESS_THREAD_EXIT_STDOUT_MSG L"Application '%s' with physical root '%s' hit unexpected managed background thread exit, ErrorCode = '0x%x'. Last 4KB characters of captured stdout and stderr logs:\r\n%s" +#define ASPNETCORE_EVENT_INPROCESS_THREAD_EXIT_MSG L"Application '%s' with physical root '%s' hit unexpected managed background thread exit, ErrorCode = '0x%x'. Please check the stderr logs for more information." #define ASPNETCORE_EVENT_APP_IN_SHUTDOWN_MSG L"Application shutting down." #define ASPNETCORE_EVENT_RECYCLE_APPOFFLINE_MSG L"Application '%s' was recycled after detecting the app_offline file." #define ASPNETCORE_EVENT_MONITOR_APPOFFLINE_ERROR_MSG L"Monitoring app_offline.htm failed for application '%s', ErrorCode '0x%x'. " @@ -43,9 +43,11 @@ #define ASPNETCORE_EVENT_PORTABLE_APP_DOTNET_MISSING_MSG L"Could not find dotnet.exe on the system PATH environment variable for portable application '%s'. Check that a valid path to dotnet is on the PATH and the bitness of dotnet matches the bitness of the IIS worker process. ErrorCode = '0x%x'." #define ASPNETCORE_EVENT_HOSTFXR_DIRECTORY_NOT_FOUND_MSG L"Could not find the hostfxr directory '%s' in the dotnet directory. ErrorCode = '0x%x'." #define ASPNETCORE_EVENT_HOSTFXR_DLL_NOT_FOUND_MSG L"Could not find hostfxr.dll in '%s'. ErrorCode = '0x%x'." +#define ASPNETCORE_EVENT_HOSTFXR_DLL_INVALID_VERSION_MSG L"Hostfxr version used does not support 'hostfxr_get_native_search_directories', update the version of hostfxr to a higher version. Path to hostfxr: '%s'." +#define ASPNETCORE_EVENT_APPLICATION_EXE_NOT_FOUND_LEVEL EVENTLOG_ERROR_TYPE #define ASPNETCORE_EVENT_APPLICATION_EXE_NOT_FOUND_MSG L"Could not find application executable in '%s'. ErrorCode = '0x%x'." #define ASPNETCORE_EVENT_INPROCESS_THREAD_EXCEPTION_MSG L"Application '%s' with physical root '%s' hit unexpected managed exception, ErrorCode = '0x%x. Please check the stderr logs for more information." #define ASPNETCORE_EVENT_INVALID_PROCESS_PATH_MSG L"Invalid or unknown processPath provided in web.config: processPath = '%s', ErrorCode = '0x%x'." -#define ASPNETCORE_EVENT_INPROCESS_RH_MISSING_MSG L"Could not find the assembly '%s' for in-process application. Please confirm the Microsoft.AspNetCore.Server.IIS package is referenced in your application." +#define ASPNETCORE_EVENT_INPROCESS_RH_ERROR_MSG L"Could not find the assembly '%s' for in-process application. Please confirm the Microsoft.AspNetCore.Server.IIS package is referenced in your application. Captured output: %s" #define ASPNETCORE_EVENT_OUT_OF_PROCESS_RH_MISSING_MSG L"Could not find the assembly '%s' for out-of-process application. Please confirm the assembly is installed correctly for IIS or IISExpress." #define ASPNETCORE_EVENT_INPROCESS_START_SUCCESS_MSG L"Application '%s' started the coreclr in-process successfully." diff --git a/src/AspNetCoreModuleV2/CommonLib/sttimer.h b/src/AspNetCoreModuleV2/CommonLib/sttimer.h index 0ebbdbd822..26d79d0737 100644 --- a/src/AspNetCoreModuleV2/CommonLib/sttimer.h +++ b/src/AspNetCoreModuleV2/CommonLib/sttimer.h @@ -6,6 +6,7 @@ #ifndef _STTIMER_H #define _STTIMER_H +#include "stringu.h" class STTIMER { diff --git a/src/AspNetCoreModuleV2/InProcessRequestHandler/inprocessapplication.cpp b/src/AspNetCoreModuleV2/InProcessRequestHandler/inprocessapplication.cpp index 352ec7b093..43a4071cf5 100644 --- a/src/AspNetCoreModuleV2/InProcessRequestHandler/inprocessapplication.cpp +++ b/src/AspNetCoreModuleV2/InProcessRequestHandler/inprocessapplication.cpp @@ -102,12 +102,6 @@ IN_PROCESS_APPLICATION::StopInternal(bool fServerInitiated) } } - if (m_pLoggerProvider != NULL) - { - delete m_pLoggerProvider; - m_pLoggerProvider = NULL; - } - Finished: if (FAILED(hr)) @@ -256,24 +250,7 @@ IN_PROCESS_APPLICATION::LoadManagedApplication } { - // Set up stdout redirect - SRWExclusiveLock lock(m_stateLock); - if (m_pLoggerProvider == NULL) - { - hr = LoggingHelpers::CreateLoggingProvider( - m_pConfig->QueryStdoutLogEnabled(), - !GetConsoleWindow(), - m_pConfig->QueryStdoutLogFile()->QueryStr(), - m_pConfig->QueryApplicationPhysicalPath()->QueryStr(), - &m_pLoggerProvider); - if (FAILED(hr)) - { - goto Finished; - } - - LOG_IF_FAILED(m_pLoggerProvider->Start()); - } if (m_status != MANAGED_APPLICATION_STATUS::STARTING) { @@ -461,6 +438,20 @@ IN_PROCESS_APPLICATION::ExecuteApplication( FINISHED_IF_FAILED(SetEnvironementVariablesOnWorkerProcess()); } + LOG_INFO("Starting managed application"); + + if (m_pLoggerProvider == NULL) + { + FINISHED_IF_FAILED(hr = LoggingHelpers::CreateLoggingProvider( + m_pConfig->QueryStdoutLogEnabled(), + !m_pHttpServer.IsCommandLineLaunch(), + m_pConfig->QueryStdoutLogFile()->QueryStr(), + m_pConfig->QueryApplicationPhysicalPath()->QueryStr(), + m_pLoggerProvider)); + + LOG_IF_FAILED(m_pLoggerProvider->Start()); + } + // There can only ever be a single instance of .NET Core // loaded in the process but we need to get config information to boot it up in the // first place. This is happening in an execute request handler and everyone waits @@ -482,7 +473,7 @@ Finished: // m_status = MANAGED_APPLICATION_STATUS::SHUTDOWN; m_fShutdownCalledFromManaged = TRUE; - FreeLibrary(hModule); + m_pLoggerProvider->Stop(); if (!m_fShutdownCalledFromNative) @@ -545,7 +536,6 @@ IN_PROCESS_APPLICATION::RunDotnetApplication(DWORD argc, CONST PCWSTR* argv, hos __try { - LOG_INFO("Starting managed application"); m_ProcessExitCode = pProc(argc, argv); if (m_ProcessExitCode != 0) { diff --git a/src/AspNetCoreModuleV2/InProcessRequestHandler/inprocessapplication.h b/src/AspNetCoreModuleV2/InProcessRequestHandler/inprocessapplication.h index 8993d7fc8e..10149cf3f3 100644 --- a/src/AspNetCoreModuleV2/InProcessRequestHandler/inprocessapplication.h +++ b/src/AspNetCoreModuleV2/InProcessRequestHandler/inprocessapplication.h @@ -150,7 +150,7 @@ private: static IN_PROCESS_APPLICATION* s_Application; - IOutputManager* m_pLoggerProvider; + std::unique_ptr m_pLoggerProvider; static const LPCSTR s_exeLocationParameterName; diff --git a/src/AspNetCoreModuleV2/RequestHandlerLib/FileOutputManager.cpp b/src/AspNetCoreModuleV2/RequestHandlerLib/FileOutputManager.cpp deleted file mode 100644 index 29041f7ab5..0000000000 --- a/src/AspNetCoreModuleV2/RequestHandlerLib/FileOutputManager.cpp +++ /dev/null @@ -1,195 +0,0 @@ -// Copyright (c) .NET Foundation. All rights reserved. -// Licensed under the MIT License. See License.txt in the project root for license information. - -#include "stdafx.h" -#include "FileOutputManager.h" -#include "sttimer.h" -#include "exceptions.h" -#include "debugutil.h" -#include "SRWExclusiveLock.h" -#include "file_utility.h" - -FileOutputManager::FileOutputManager() : - m_hLogFileHandle(INVALID_HANDLE_VALUE), - m_fdPreviousStdOut(-1), - m_fdPreviousStdErr(-1), - m_disposed(false) -{ - InitializeSRWLock(&m_srwLock); -} - -FileOutputManager::~FileOutputManager() -{ - Stop(); -} - -HRESULT -FileOutputManager::Initialize(PCWSTR pwzStdOutLogFileName, PCWSTR pwzApplicationPath) -{ - RETURN_IF_FAILED(m_wsApplicationPath.Copy(pwzApplicationPath)); - RETURN_IF_FAILED(m_wsStdOutLogFileName.Copy(pwzStdOutLogFileName)); - - return S_OK; -} - -bool FileOutputManager::GetStdOutContent(STRA* struStdOutput) -{ - // - // Ungraceful shutdown, try to log an error message. - // This will be a common place for errors as it means the hostfxr_main returned - // or there was an exception. - // - CHAR pzFileContents[4096] = { 0 }; - DWORD dwNumBytesRead; - LARGE_INTEGER li = { 0 }; - BOOL fLogged = FALSE; - DWORD dwFilePointer = 0; - - if (m_hLogFileHandle != INVALID_HANDLE_VALUE) - { - if (GetFileSizeEx(m_hLogFileHandle, &li) && li.LowPart > 0 && li.HighPart == 0) - { - if (li.LowPart > 4096) - { - dwFilePointer = SetFilePointer(m_hLogFileHandle, -4096, NULL, FILE_END); - } - else - { - dwFilePointer = SetFilePointer(m_hLogFileHandle, 0, NULL, FILE_BEGIN); - } - - if (dwFilePointer != INVALID_SET_FILE_POINTER) - { - // Read file fails. - if (ReadFile(m_hLogFileHandle, pzFileContents, 4096, &dwNumBytesRead, NULL)) - { - if (SUCCEEDED(struStdOutput->Copy(pzFileContents, dwNumBytesRead))) - { - fLogged = TRUE; - } - } - } - } - } - - return fLogged; -} - -HRESULT -FileOutputManager::Start() -{ - SYSTEMTIME systemTime; - SECURITY_ATTRIBUTES saAttr = { 0 }; - STRU struPath; - - RETURN_IF_FAILED(FILE_UTILITY::ConvertPathToFullPath( - m_wsStdOutLogFileName.QueryStr(), - m_wsApplicationPath.QueryStr(), - &struPath)); - - RETURN_IF_FAILED(FILE_UTILITY::EnsureDirectoryPathExist(struPath.QueryStr())); - - GetSystemTime(&systemTime); - - RETURN_IF_FAILED( - m_struLogFilePath.SafeSnwprintf(L"%s_%d%02d%02d%02d%02d%02d_%d.log", - struPath.QueryStr(), - systemTime.wYear, - systemTime.wMonth, - systemTime.wDay, - systemTime.wHour, - systemTime.wMinute, - systemTime.wSecond, - GetCurrentProcessId())); - - m_fdPreviousStdOut = _dup(_fileno(stdout)); - m_fdPreviousStdErr = _dup(_fileno(stderr)); - - m_hLogFileHandle = CreateFileW(m_struLogFilePath.QueryStr(), - FILE_READ_DATA | FILE_WRITE_DATA, - FILE_SHARE_READ, - &saAttr, - CREATE_ALWAYS, - FILE_ATTRIBUTE_NORMAL, - NULL); - - if (m_hLogFileHandle == INVALID_HANDLE_VALUE) - { - return LOG_IF_FAILED(HRESULT_FROM_WIN32(GetLastError())); - } - - // There are a few options for redirecting stdout/stderr, - // but there are issues with most of them. - // AllocConsole() - // *stdout = *m_pStdFile; - // *stderr = *m_pStdFile; - // Calling _dup2 on stderr fails on IIS. IIS sets stderr to -2 - // _dup2(_fileno(m_pStdFile), _fileno(stdout)); - // _dup2(_fileno(m_pStdFile), _fileno(stderr)); - // If we were okay setting stdout and stderr to separate files, we could use: - // _wfreopen_s(&m_pStdFile, struLogFileName.QueryStr(), L"w+", stdout); - // _wfreopen_s(&m_pStdFile, struLogFileName.QueryStr(), L"w+", stderr); - // Calling SetStdHandle works for redirecting managed logs, however you cannot - // capture native logs (including hostfxr failures). - - 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); - - LOG_INFOF("Created log file for inprocess application: %S", - m_struLogFilePath.QueryStr()); - - return S_OK; -} - - -HRESULT -FileOutputManager::Stop() -{ - if (m_disposed) - { - return S_OK; - } - SRWExclusiveLock lock(m_srwLock); - if (m_disposed) - { - return S_OK; - } - m_disposed = true; - - HANDLE handle = NULL; - WIN32_FIND_DATA fileData; - - if (m_hLogFileHandle != INVALID_HANDLE_VALUE) - { - m_Timer.CancelTimer(); - } - - // delete empty log file - handle = FindFirstFile(m_struLogFilePath.QueryStr(), &fileData); - if (handle != INVALID_HANDLE_VALUE && - handle != NULL && - fileData.nFileSizeHigh == 0 && - fileData.nFileSizeLow == 0) // skip check of nFileSizeHigh - { - FindClose(handle); - LOG_LAST_ERROR_IF(!DeleteFile(m_struLogFilePath.QueryStr())); - } - - if (m_fdPreviousStdOut >= 0) - { - 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) - { - LOG_LAST_ERROR_IF(!SetStdHandle(STD_ERROR_HANDLE, (HANDLE)_get_osfhandle(m_fdPreviousStdErr))); - LOG_INFOF("Restoring original stderr: %d", m_fdPreviousStdOut); - } - - return S_OK; -} diff --git a/src/AspNetCoreModuleV2/RequestHandlerLib/RequestHandlerLib.vcxproj b/src/AspNetCoreModuleV2/RequestHandlerLib/RequestHandlerLib.vcxproj index 56025b071a..a2c89e2b40 100644 --- a/src/AspNetCoreModuleV2/RequestHandlerLib/RequestHandlerLib.vcxproj +++ b/src/AspNetCoreModuleV2/RequestHandlerLib/RequestHandlerLib.vcxproj @@ -193,22 +193,14 @@ - - - - - - - - diff --git a/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeployer.cs b/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeployer.cs index 8c07bec312..743944d971 100644 --- a/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeployer.cs +++ b/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeployer.cs @@ -44,6 +44,11 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting.IIS } public override void Dispose() + { + Dispose(gracefulShutdown: false); + } + + public override void Dispose(bool gracefulShutdown) { Stop(); @@ -128,6 +133,8 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting.IIS } } + + private void GetLogsFromFile() { try diff --git a/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeployerBase.cs b/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeployerBase.cs index be6f39edec..d0745b4f01 100644 --- a/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeployerBase.cs +++ b/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeployerBase.cs @@ -151,5 +151,7 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting.IIS .GetOrAdd("add", "name", ancmVersion) .SetAttributeValue("image", GetAncmLocation(DeploymentParameters.AncmVersion)); } + + public abstract void Dispose(bool gracefulShutdown); } } diff --git a/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeploymentParameterExtensions.cs b/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeploymentParameterExtensions.cs index f1e90f1a24..485c61cf4c 100644 --- a/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeploymentParameterExtensions.cs +++ b/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeploymentParameterExtensions.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; using System.Linq; using System.Xml.Linq; @@ -50,5 +51,14 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting.IIS .SetAttributeValue("enabled", "true"); }); } + + public static void EnableLogging(this IISDeploymentParameters deploymentParameters, string path) + { + deploymentParameters.WebConfigActionList.Add( + WebConfigHelpers.AddOrModifyAspNetCoreSection("stdoutLogEnabled", "true")); + + deploymentParameters.WebConfigActionList.Add( + WebConfigHelpers.AddOrModifyAspNetCoreSection("stdoutLogFile", Path.Combine(path, "std"))); + } } } diff --git a/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeploymentParameters.cs b/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeploymentParameters.cs index 30e3f13c25..3b2dfc4804 100644 --- a/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeploymentParameters.cs +++ b/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeploymentParameters.cs @@ -37,7 +37,6 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting.IIS ServerConfigActionList = tempParameters.ServerConfigActionList; WebConfigBasedEnvironmentVariables = tempParameters.WebConfigBasedEnvironmentVariables; HandlerSettings = tempParameters.HandlerSettings; - GracefulShutdown = tempParameters.GracefulShutdown; } } @@ -49,7 +48,5 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting.IIS public IDictionary HandlerSettings { get; set; } = new Dictionary(); - public bool GracefulShutdown { get; set; } - } } diff --git a/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISExpressDeployer.cs b/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISExpressDeployer.cs index fd2aca9b4c..797c46dde9 100644 --- a/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISExpressDeployer.cs +++ b/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISExpressDeployer.cs @@ -28,7 +28,7 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting.IIS private const string FailedToInitializeBindingsMessage = "Failed to initialize site bindings"; private const string UnableToStartIISExpressMessage = "Unable to start iisexpress."; private const int MaximumAttempts = 5; - private readonly TimeSpan ShutdownTimeSpan = TimeSpan.FromSeconds(60); + private readonly TimeSpan ShutdownTimeSpan = Debugger.IsAttached ? TimeSpan.FromMinutes(60) : TimeSpan.FromMinutes(1); private static readonly Regex UrlDetectorRegex = new Regex(@"^\s*Successfully registered URL ""(?[^""]+)"" for site.*$"); private Process _hostProcess; @@ -381,10 +381,15 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting.IIS } public override void Dispose() + { + Dispose(gracefulShutdown: false); + } + + public override void Dispose(bool gracefulShutdown) { using (Logger.BeginScope("Dispose")) { - if (IISDeploymentParameters.GracefulShutdown) + if (gracefulShutdown) { GracefullyShutdownProcess(_hostProcess); } diff --git a/test/Common.FunctionalTests/Inprocess/EventLogTests.cs b/test/Common.FunctionalTests/Inprocess/EventLogTests.cs index 3139f3b251..77abc90190 100644 --- a/test/Common.FunctionalTests/Inprocess/EventLogTests.cs +++ b/test/Common.FunctionalTests/Inprocess/EventLogTests.cs @@ -23,8 +23,9 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests public async Task CheckStartupEventLogMessage() { var deploymentParameters = _fixture.GetBaseDeploymentParameters(publish: true); + var deploymentResult = await DeployAsync(deploymentParameters); - await Helpers.AssertStarts(deploymentResult); + await deploymentResult.AssertStarts(); StopServer(); @@ -35,9 +36,8 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests public async Task CheckShutdownEventLogMessage() { var deploymentParameters = _fixture.GetBaseDeploymentParameters(publish: true); - deploymentParameters.GracefulShutdown = true; var deploymentResult = await DeployAsync(deploymentParameters); - await Helpers.AssertStarts(deploymentResult); + await deploymentResult.AssertStarts(); StopServer(); diff --git a/test/Common.FunctionalTests/Inprocess/LoggingTests.cs b/test/Common.FunctionalTests/Inprocess/LoggingTests.cs index 0a19a90133..7ef360a487 100644 --- a/test/Common.FunctionalTests/Inprocess/LoggingTests.cs +++ b/test/Common.FunctionalTests/Inprocess/LoggingTests.cs @@ -2,7 +2,6 @@ // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. using System; -using System.Collections.Generic; using System.IO; using System.Linq; using System.Threading.Tasks; @@ -47,20 +46,14 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests StopServer(); - var fileInDirectory = Directory.GetFiles(pathToLogs).Single(); - + var fileInDirectory = Directory.GetFiles(pathToLogs).Single(fileName => fileName.Contains("inprocess")); 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(pathToLogs, true), e => Logger.LogWarning($"Failed to delete directory : {e.Message}"), @@ -132,7 +125,6 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests public async Task CheckStdoutLoggingToPipe_DoesNotCrashProcess(string path) { var deploymentParameters = _fixture.GetBaseDeploymentParameters(publish: true); - deploymentParameters.GracefulShutdown = true; var deploymentResult = await DeployAsync(deploymentParameters); await Helpers.AssertStarts(deploymentResult, path); @@ -151,7 +143,6 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests public async Task CheckStdoutLoggingToPipeWithFirstWrite(string path) { var deploymentParameters = _fixture.GetBaseDeploymentParameters(publish: true); - deploymentParameters.GracefulShutdown = true; var firstWriteString = path + path; diff --git a/test/Common.FunctionalTests/MultiApplicationTests.cs b/test/Common.FunctionalTests/MultiApplicationTests.cs index 009c61f373..e0adccfc54 100644 --- a/test/Common.FunctionalTests/MultiApplicationTests.cs +++ b/test/Common.FunctionalTests/MultiApplicationTests.cs @@ -44,6 +44,7 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests { var parameters = _fixture.GetBaseDeploymentParameters(HostingModel.InProcess, publish: true); parameters.ServerConfigActionList.Add(DuplicateApplication); + var result = await DeployAsync(parameters); var result1 = await result.HttpClient.GetAsync("/app1/HelloWorld"); var result2 = await result.HttpClient.GetAsync("/app2/HelloWorld"); diff --git a/test/Common.FunctionalTests/Utilities/EventLogHelpers.cs b/test/Common.FunctionalTests/Utilities/EventLogHelpers.cs index 9d8d79fb6c..c449863e4b 100644 --- a/test/Common.FunctionalTests/Utilities/EventLogHelpers.cs +++ b/test/Common.FunctionalTests/Utilities/EventLogHelpers.cs @@ -1,6 +1,8 @@ // 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.Linq; +using System.Text; using System.Text.RegularExpressions; using Microsoft.AspNetCore.Server.IntegrationTesting.IIS; using Microsoft.Extensions.Logging.Testing; @@ -14,17 +16,16 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests { Assert.True(deploymentResult.HostProcess.HasExited); - var eventLogRegex = new Regex($"Event Log: {expectedRegexMatchString}"); + var builder = new StringBuilder(); - int count = 0; foreach (var context in testSink.Writes) { - if (eventLogRegex.IsMatch(context.Message)) - { - count++; - } + builder.Append(context.Message); } - Assert.Equal(1, count); + + var eventLogRegex = new Regex($"Event Log: (.*?){expectedRegexMatchString}(.*?)End Event Log Message.", RegexOptions.Singleline); + + Assert.Matches(eventLogRegex, builder.ToString()); } } } diff --git a/test/Common.FunctionalTests/Utilities/FunctionalTestsBase.cs b/test/Common.FunctionalTests/Utilities/FunctionalTestsBase.cs index a9b6b3a4fe..b9e80dd27f 100644 --- a/test/Common.FunctionalTests/Utilities/FunctionalTestsBase.cs +++ b/test/Common.FunctionalTests/Utilities/FunctionalTestsBase.cs @@ -18,7 +18,7 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting { } - protected ApplicationDeployer _deployer; + protected IISDeployerBase _deployer; protected ApplicationDeployer CreateDeployer(IISDeploymentParameters parameters) { @@ -38,18 +38,18 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting protected virtual async Task DeployAsync(IISDeploymentParameters parameters) { - _deployer = CreateDeployer(parameters); + _deployer = (IISDeployerBase)CreateDeployer(parameters); return (IISDeploymentResult)await _deployer.DeployAsync(); } public override void Dispose() { - StopServer(); + StopServer(false); } - public void StopServer() + public void StopServer(bool gracefulShutdown = true) { - _deployer?.Dispose(); + _deployer?.Dispose(gracefulShutdown); _deployer = null; } } diff --git a/test/Common.FunctionalTests/Utilities/SkipIfDebugAttribute.cs b/test/Common.FunctionalTests/Utilities/SkipIfDebugAttribute.cs new file mode 100644 index 0000000000..6cdd725392 --- /dev/null +++ b/test/Common.FunctionalTests/Utilities/SkipIfDebugAttribute.cs @@ -0,0 +1,22 @@ +// 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.Server.IntegrationTesting; +using Microsoft.AspNetCore.Testing.xunit; + +namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests +{ + [AttributeUsage(AttributeTargets.Assembly | AttributeTargets.Class | AttributeTargets.Method)] + public sealed class SkipIfDebugAttribute : Attribute, ITestCondition + { + public bool IsMet => + #if DEBUG + false; + #else + true; + #endif + + public string SkipReason => "Test cannot be run in Debug mode."; + } +} diff --git a/test/CommonLibTests/FileOutputManagerTests.cpp b/test/CommonLibTests/FileOutputManagerTests.cpp index ae1085408c..bba9e22704 100644 --- a/test/CommonLibTests/FileOutputManagerTests.cpp +++ b/test/CommonLibTests/FileOutputManagerTests.cpp @@ -34,6 +34,7 @@ namespace FileOutManagerStartupTests auto tempDirectory = TempDirectory(); FileOutputManager* pManager = new FileOutputManager; + pManager->Initialize(fileNamePrefix.c_str(), tempDirectory.path().c_str()); { FileManagerWrapper wrapper(pManager); @@ -47,19 +48,17 @@ namespace FileOutManagerStartupTests ASSERT_EQ(filename.substr(0, fileNamePrefix.size()), fileNamePrefix); std::wstring content = Helpers::ReadFileContent(std::wstring(p.path())); - ASSERT_EQ(content.length(), DWORD(4)); - ASSERT_STREQ(content.c_str(), expected); } } }; - TEST_F(FileOutputManagerTest, DISABLED_WriteToFileCheckContentsWritten) + TEST_F(FileOutputManagerTest, WriteToFileCheckContentsWritten) { Test(L"", stdout); Test(L"log", stdout); } - TEST_F(FileOutputManagerTest, DISABLED_WriteToFileCheckContentsWrittenErr) + TEST_F(FileOutputManagerTest, WriteToFileCheckContentsWrittenErr) { Test(L"", stderr); Test(L"log", stderr); @@ -68,8 +67,7 @@ namespace FileOutManagerStartupTests namespace FileOutManagerOutputTests { - - TEST(FileOutManagerOutputTest, DISABLED_StdErr) + TEST(FileOutManagerOutputTest, StdOut) { PCSTR expected = "test"; @@ -80,7 +78,9 @@ namespace FileOutManagerOutputTests { FileManagerWrapper wrapper(pManager); - printf(expected, stderr); + fprintf(stdout, expected); + pManager->Stop(); + STRA straContent; ASSERT_TRUE(pManager->GetStdOutContent(&straContent)); @@ -88,7 +88,7 @@ namespace FileOutManagerOutputTests } } - TEST(FileOutManagerOutputTest, DISABLED_CheckFileOutput) + TEST(FileOutManagerOutputTest, StdErr) { PCSTR expected = "test"; @@ -99,7 +99,9 @@ namespace FileOutManagerOutputTests { FileManagerWrapper wrapper(pManager); - printf(expected); + fprintf(stderr, expected); + pManager->Stop(); + STRA straContent; ASSERT_TRUE(pManager->GetStdOutContent(&straContent)); @@ -107,9 +109,9 @@ namespace FileOutManagerOutputTests } } - TEST(FileOutManagerOutputTest, DISABLED_CapAt4KB) + TEST(FileOutManagerOutputTest, CapAt30KB) { - PCSTR expected = "test"; + PCSTR expected = "hello world"; auto tempDirectory = TempDirectory(); @@ -118,16 +120,39 @@ namespace FileOutManagerOutputTests { FileManagerWrapper wrapper(pManager); - for (int i = 0; i < 1200; i++) + for (int i = 0; i < 3000; i++) { printf(expected); } - + pManager->Stop(); STRA straContent; ASSERT_TRUE(pManager->GetStdOutContent(&straContent)); - ASSERT_EQ(straContent.QueryCCH(), 4096); + ASSERT_EQ(straContent.QueryCCH(), 30000); + } + } + + + TEST(FileOutManagerOutputTest, StartStopRestoresCorrectly) + { + PCSTR expected = "test"; + + auto tempDirectory = TempDirectory(); + + for (int i = 0; i < 10; i++) + { + FileOutputManager* pManager = new FileOutputManager; + pManager->Initialize(L"", tempDirectory.path().c_str()); + { + FileManagerWrapper wrapper(pManager); + + printf(expected); + pManager->Stop(); + STRA straContent; + ASSERT_TRUE(pManager->GetStdOutContent(&straContent)); + + ASSERT_STREQ(straContent.QueryStr(), expected); + } } } } - diff --git a/test/CommonLibTests/PipeOutputManagerTests.cpp b/test/CommonLibTests/PipeOutputManagerTests.cpp index 6cc09e7678..20609adf72 100644 --- a/test/CommonLibTests/PipeOutputManagerTests.cpp +++ b/test/CommonLibTests/PipeOutputManagerTests.cpp @@ -23,14 +23,58 @@ public: namespace PipeOutputManagerTests { - TEST(PipeManagerOutputTest, NotifyStartupCompleteCallsDispose) + TEST(PipeManagerOutputTest, StdOut) { PCWSTR expected = L"test"; + STRA output; + + PipeOutputManager* pManager = new PipeOutputManager(true); - PipeOutputManager* pManager = new PipeOutputManager(); ASSERT_EQ(S_OK, pManager->Start()); + fwprintf(stdout, expected); + + ASSERT_EQ(S_OK, pManager->Stop()); + + pManager->GetStdOutContent(&output); + ASSERT_STREQ(output.QueryStr(), "test"); + delete pManager; } + TEST(PipeManagerOutputTest, StdErr) + { + PCWSTR expected = L"test"; + STRA output; + + PipeOutputManager* pManager = new PipeOutputManager(); + + ASSERT_EQ(S_OK, pManager->Start()); + fwprintf(stderr, expected); + ASSERT_EQ(S_OK, pManager->Stop()); + + pManager->GetStdOutContent(&output); + ASSERT_STREQ(output.QueryStr(), "test"); + delete pManager; + } + + TEST(PipeManagerOutputTest, CheckMaxPipeSize) + { + std::wstring test; + STRA output; + for (int i = 0; i < 3000; i++) + { + test.append(L"hello world"); + } + + PipeOutputManager* pManager = new PipeOutputManager(); + + ASSERT_EQ(S_OK, pManager->Start()); + wprintf(test.c_str()); + ASSERT_EQ(S_OK, pManager->Stop()); + + pManager->GetStdOutContent(&output); + ASSERT_EQ(output.QueryCCH(), (DWORD)30000); + delete pManager; + } TEST(PipeManagerOutputTest, SetInvalidHandlesForErrAndOut) { auto m_fdPreviousStdOut = _dup(_fileno(stdout)); @@ -50,6 +94,61 @@ namespace PipeOutputManagerTests // Test will fail if we didn't redirect stdout back to a file descriptor. // This is because gtest relies on console output to know if a test succeeded or failed. // If the output still points to a file/pipe, the test (and all other tests after it) will fail. + delete pManager; + } + + TEST(PipeManagerOutputTest, CreateDeleteMultipleTimesStdOutWorks) + { + for (int i = 0; i < 10; i++) + { + auto stdoutBefore = _fileno(stdout); + auto stderrBefore = _fileno(stderr); + PCWSTR expected = L"test"; + STRA output; + + PipeOutputManager* pManager = new PipeOutputManager(); + + ASSERT_EQ(S_OK, pManager->Start()); + fwprintf(stdout, expected); + + ASSERT_EQ(S_OK, pManager->Stop()); + + pManager->GetStdOutContent(&output); + ASSERT_STREQ(output.QueryStr(), "test"); + ASSERT_EQ(stdoutBefore, _fileno(stdout)); + ASSERT_EQ(stderrBefore, _fileno(stderr)); + delete pManager; + } + // When this returns, we get an AV from gtest. + } + + TEST(PipeManagerOutputTest, CreateDeleteKeepOriginalStdErr) + { + for (int i = 0; i < 10; i++) + { + auto stdoutBefore = _fileno(stdout); + auto stderrBefore = _fileno(stderr); + auto stdoutHandle = GetStdHandle(STD_OUTPUT_HANDLE); + auto stderrHandle = GetStdHandle(STD_ERROR_HANDLE); + PCWSTR expected = L"test"; + STRA output; + + PipeOutputManager* pManager = new PipeOutputManager(); + + ASSERT_EQ(S_OK, pManager->Start()); + fwprintf(stderr, expected); + ASSERT_EQ(S_OK, pManager->Stop()); + + pManager->GetStdOutContent(&output); + ASSERT_STREQ(output.QueryStr(), "test"); + ASSERT_EQ(stdoutBefore, _fileno(stdout)); + + ASSERT_EQ(stderrBefore, _fileno(stderr)); + + delete pManager; + } + + wprintf(L"Hello!"); } } diff --git a/test/IIS.FunctionalTests/Inprocess/StdOutRedirectionTests.cs b/test/IIS.FunctionalTests/Inprocess/StdOutRedirectionTests.cs new file mode 100644 index 0000000000..e0cb1cef5d --- /dev/null +++ b/test/IIS.FunctionalTests/Inprocess/StdOutRedirectionTests.cs @@ -0,0 +1,171 @@ +// 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 System.IO; +using System.Linq; +using System.Threading.Tasks; +using Microsoft.AspNetCore.Server.IIS.FunctionalTests.Utilities; +using Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests; +using Microsoft.AspNetCore.Server.IntegrationTesting; +using Microsoft.AspNetCore.Server.IntegrationTesting.IIS; +using Microsoft.AspNetCore.Testing.xunit; +using Newtonsoft.Json; +using Xunit; + +namespace IIS.FunctionalTests.Inprocess +{ + [Collection(PublishedSitesCollection.Name)] + public class StdOutRedirectionTests : IISFunctionalTestBase + { + private readonly PublishedSitesFixture _fixture; + private readonly string _logFolderPath; + + public StdOutRedirectionTests(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); + } + } + + [ConditionalFact] + [SkipIfDebug] + public async Task FrameworkNotFoundExceptionLogged_Pipe() + { + var deploymentParameters = _fixture.GetBaseDeploymentParameters(_fixture.StartupExceptionWebsite, publish: true); + + var deploymentResult = await DeployAsync(deploymentParameters); + + InvalidateRuntimeConfig(deploymentResult); + + var response = await deploymentResult.HttpClient.GetAsync("/"); + Assert.False(response.IsSuccessStatusCode); + + StopServer(); + + EventLogHelpers.VerifyEventLogEvent(deploymentResult, TestSink, + "The specified framework 'Microsoft.NETCore.App', version '2.9.9' was not found."); + } + + [ConditionalFact] + [SkipIfDebug] + public async Task FrameworkNotFoundExceptionLogged_File() + { + var deploymentParameters = + _fixture.GetBaseDeploymentParameters(_fixture.StartupExceptionWebsite, publish: true); + + deploymentParameters.EnableLogging(_logFolderPath); + + var deploymentResult = await DeployAsync(deploymentParameters); + + InvalidateRuntimeConfig(deploymentResult); + + var response = await deploymentResult.HttpClient.GetAsync("/"); + Assert.False(response.IsSuccessStatusCode); + + StopServer(); + + var fileInDirectory = Directory.GetFiles(_logFolderPath).Single(); + var contents = File.ReadAllText(fileInDirectory); + var expectedString = "The specified framework 'Microsoft.NETCore.App', version '2.9.9' was not found."; + EventLogHelpers.VerifyEventLogEvent(deploymentResult, TestSink, expectedString); + Assert.Contains(expectedString, contents); + } + + [ConditionalFact] + [SkipIfDebug] + public async Task EnableCoreHostTraceLogging_TwoLogFilesCreated() + { + var deploymentParameters = + _fixture.GetBaseDeploymentParameters(_fixture.StartupExceptionWebsite, publish: true); + deploymentParameters.EnvironmentVariables["COREHOST_TRACE"] = "1"; + + deploymentParameters.EnableLogging(_logFolderPath); + + var deploymentResult = await DeployAsync(deploymentParameters); + + var response = await deploymentResult.HttpClient.GetAsync("/"); + Assert.False(response.IsSuccessStatusCode); + + 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); + } + } + + [ConditionalTheory] + [SkipIfDebug] + [InlineData("CheckLargeStdErrWrites")] + [InlineData("CheckLargeStdOutWrites")] + [InlineData("CheckOversizedStdErrWrites")] + [InlineData("CheckOversizedStdOutWrites")] + public async Task EnableCoreHostTraceLogging_PipeCaptureNativeLogs(string path) + { + var deploymentParameters = _fixture.GetBaseDeploymentParameters(_fixture.StartupExceptionWebsite, publish: true); + deploymentParameters.EnvironmentVariables["COREHOST_TRACE"] = "1"; + deploymentParameters.WebConfigBasedEnvironmentVariables["ASPNETCORE_INPROCESS_STARTUP_VALUE"] = path; + + var deploymentResult = await DeployAsync(deploymentParameters); + + var response = await deploymentResult.HttpClient.GetAsync("/"); + + Assert.False(response.IsSuccessStatusCode); + + StopServer(); + + EventLogHelpers.VerifyEventLogEvent(deploymentResult, TestSink, "Invoked hostfxr"); + } + + [ConditionalTheory] + [SkipIfDebug] + [InlineData("CheckLargeStdErrWrites")] + [InlineData("CheckLargeStdOutWrites")] + [InlineData("CheckOversizedStdErrWrites")] + [InlineData("CheckOversizedStdOutWrites")] + public async Task EnableCoreHostTraceLogging_FileCaptureNativeLogs(string path) + { + var deploymentParameters = + _fixture.GetBaseDeploymentParameters(_fixture.StartupExceptionWebsite, publish: true); + deploymentParameters.EnvironmentVariables["COREHOST_TRACE"] = "1"; + deploymentParameters.WebConfigBasedEnvironmentVariables["ASPNETCORE_INPROCESS_STARTUP_VALUE"] = path; + + deploymentParameters.EnableLogging(_logFolderPath); + + var deploymentResult = await DeployAsync(deploymentParameters); + + var response = await deploymentResult.HttpClient.GetAsync("/"); + Assert.False(response.IsSuccessStatusCode); + + StopServer(); + + var fileInDirectory = Directory.GetFiles(_logFolderPath).First(); + var contents = File.ReadAllText(fileInDirectory); + + EventLogHelpers.VerifyEventLogEvent(deploymentResult, TestSink, "Invoked hostfxr"); + Assert.Contains("Invoked hostfxr", contents); + } + + private static void InvalidateRuntimeConfig(IISDeploymentResult deploymentResult) + { + var path = Path.Combine(deploymentResult.ContentRoot, "StartupExceptionWebSite.runtimeconfig.json"); + dynamic depsFileContent = JsonConvert.DeserializeObject(File.ReadAllText(path)); + depsFileContent["runtimeOptions"]["framework"]["version"] = "2.9.9"; + var output = JsonConvert.SerializeObject(depsFileContent); + File.WriteAllText(path, output); + } + } +} diff --git a/test/IISExpress.FunctionalTests/InProcess/ShutdownTests.cs b/test/IISExpress.FunctionalTests/InProcess/ShutdownTests.cs index d9dbcd2b6e..1e5af7c13f 100644 --- a/test/IISExpress.FunctionalTests/InProcess/ShutdownTests.cs +++ b/test/IISExpress.FunctionalTests/InProcess/ShutdownTests.cs @@ -42,22 +42,21 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests public async Task GracefulShutdown_DoesNotCrashProcess() { var parameters = _fixture.GetBaseDeploymentParameters(publish: true); - parameters.GracefulShutdown = true; var result = await DeployAsync(parameters); var response = await result.HttpClient.GetAsync("/HelloWorld"); - StopServer(); + StopServer(gracefulShutdown: true); Assert.True(result.HostProcess.ExitCode == 0); } [ConditionalFact] - public async Task ForcefulShutdown_DoesrashProcess() + public async Task ForcefulShutdown_DoesCrashProcess() { var parameters = _fixture.GetBaseDeploymentParameters(publish: true); var result = await DeployAsync(parameters); var response = await result.HttpClient.GetAsync("/HelloWorld"); - StopServer(); + StopServer(gracefulShutdown: false); Assert.True(result.HostProcess.ExitCode == 1); } }