From 2e89aa4aa6546d11aafe815928886d4439df8c2f Mon Sep 17 00:00:00 2001 From: Justin Kotalik Date: Fri, 17 May 2019 16:30:59 -0700 Subject: [PATCH] Log stdout to event log on failure to start process for ANCM out of process (#10123) --- .../CommonLib/StringHelpers.cpp | 11 +- .../CommonLib/StringHelpers.h | 5 +- .../AspNetCoreModuleV2/CommonLib/resources.h | 6 +- .../serverprocess.cpp | 139 +++++++++++++++--- .../serverprocess.h | 13 ++ .../Common.FunctionalTests/LogFileTests.cs | 30 +++- .../Utilities/EventLogHelpers.cs | 6 +- .../testassets/OutOfProcessWebSite/Program.cs | 11 ++ 8 files changed, 186 insertions(+), 35 deletions(-) diff --git a/src/Servers/IIS/AspNetCoreModuleV2/CommonLib/StringHelpers.cpp b/src/Servers/IIS/AspNetCoreModuleV2/CommonLib/StringHelpers.cpp index bff1dedd6b..ee36974014 100644 --- a/src/Servers/IIS/AspNetCoreModuleV2/CommonLib/StringHelpers.cpp +++ b/src/Servers/IIS/AspNetCoreModuleV2/CommonLib/StringHelpers.cpp @@ -26,22 +26,27 @@ int compare_ignore_case(const std::wstring& s1, const std::wstring& s2) } std::wstring to_wide_string(const std::string &source, const unsigned int codePage) +{ + return to_wide_string(source, static_cast(source.length()), codePage); +} + +std::wstring to_wide_string(const std::string& source, const int length, const unsigned int codePage) { // MultiByteToWideChar returns 0 on failure, which is also the same return value // for empty strings. Preemptive return. - if (source.length() == 0) + if (length == 0) { return L""; } std::wstring destination; - int nChars = MultiByteToWideChar(codePage, 0, source.data(), static_cast(source.length()), NULL, 0); + int nChars = MultiByteToWideChar(codePage, 0, source.data(), length, NULL, 0); THROW_LAST_ERROR_IF(nChars == 0); destination.resize(nChars); - nChars = MultiByteToWideChar(codePage, 0, source.data(), static_cast(source.length()), destination.data(), nChars); + nChars = MultiByteToWideChar(codePage, 0, source.data(), length, destination.data(), nChars); THROW_LAST_ERROR_IF(nChars == 0); return destination; diff --git a/src/Servers/IIS/AspNetCoreModuleV2/CommonLib/StringHelpers.h b/src/Servers/IIS/AspNetCoreModuleV2/CommonLib/StringHelpers.h index 285c9dfdbe..7cafcae3b1 100644 --- a/src/Servers/IIS/AspNetCoreModuleV2/CommonLib/StringHelpers.h +++ b/src/Servers/IIS/AspNetCoreModuleV2/CommonLib/StringHelpers.h @@ -15,7 +15,10 @@ bool equals_ignore_case(const std::wstring& s1, const std::wstring& s2); int compare_ignore_case(const std::wstring& s1, const std::wstring& s2); [[nodiscard]] -std::wstring to_wide_string(const std::string &source, const unsigned int codePage); +std::wstring to_wide_string(const std::string& source, const unsigned int codePage); + +[[nodiscard]] +std::wstring to_wide_string(const std::string &source, const int length, const unsigned int codePage); [[nodiscard]] std::string to_multi_byte_string(const std::wstring& text, const unsigned int codePage); diff --git a/src/Servers/IIS/AspNetCoreModuleV2/CommonLib/resources.h b/src/Servers/IIS/AspNetCoreModuleV2/CommonLib/resources.h index 502162eeb6..04ee2e0944 100644 --- a/src/Servers/IIS/AspNetCoreModuleV2/CommonLib/resources.h +++ b/src/Servers/IIS/AspNetCoreModuleV2/CommonLib/resources.h @@ -14,7 +14,7 @@ #define ASPNETCORE_EVENT_PROCESS_START_SUCCESS_MSG L"Application '%s' started process '%d' successfully and process '%d' is listening on port '%d'." #define ASPNETCORE_EVENT_RAPID_FAIL_COUNT_EXCEEDED_MSG L"Maximum rapid fail count per minute of '%d' exceeded." #define ASPNETCORE_EVENT_PROCESS_START_ERROR_MSG L"Application '%s' with physical root '%s' failed to start process with commandline '%s' at stage '%s', ErrorCode = '0x%x', assigned port %d, retryCounter '%d'." -#define ASPNETCORE_EVENT_PROCESS_START_FAILURE_MSG L"Application '%s' with physical root '%s' failed to start process with commandline '%s' with multiple retries. Failed to bind to port '%d'. See previous warnings for details." +#define ASPNETCORE_EVENT_PROCESS_START_FAILURE_MSG L"Application '%s' with physical root '%s' failed to start process with commandline '%s' with multiple retries. Failed to bind to port '%d'. First 30KB characters of captured stdout and stderr logs from multiple retries:\r\n%s" #define ASPNETCORE_EVENT_PROCESS_START_STATUS_ERROR_MSG L"Application '%s' with physical root '%s' failed to start process with commandline '%s', ErrorCode = '0x%x', processId '%d', processStatus '%d'." #define ASPNETCORE_EVENT_PROCESS_START_PORTSETUP_ERROR_MSG L"Application '%s' with physical root '%s' failed to choose listen port '%d' given port range '%d - %d', ErrorCode = '0x%x'. If environment variable 'ASPNETCORE_PORT' was set, try removing it such that a random port is selected instead." #define ASPNETCORE_EVENT_PROCESS_START_WRONGPORT_ERROR_MSG L"Application '%s' with physical root '%s' created process with commandline '%s' but failed to listen on the given port '%d'" @@ -30,7 +30,7 @@ #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_CONFIGURATION_LOAD_ERROR_MSG L"Could not load configuration. Exception message:\r\n%s" #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' has exited from Program.Main with exit code = '%d'. Last 30KB characters of captured stdout and stderr logs:\r\n%s" +#define ASPNETCORE_EVENT_INPROCESS_THREAD_EXIT_STDOUT_MSG L"Application '%s' with physical root '%s' has exited from Program.Main with exit code = '%d'. First 30KB characters of captured stdout and stderr logs:\r\n%s" #define ASPNETCORE_EVENT_INPROCESS_THREAD_EXIT_MSG L"Application '%s' with physical root '%s' has exited from Program.Main with exit code = '%d'. Please check the stderr logs for more information." #define ASPNETCORE_EVENT_RECYCLE_APPOFFLINE_MSG L"Application '%s' was recycled after detecting app_offline.htm." #define ASPNETCORE_EVENT_MONITOR_APPOFFLINE_ERROR_MSG L"Failed to monitor app_offline.htm for application '%s', ErrorCode '0x%x'. " @@ -41,7 +41,7 @@ #define ASPNETCORE_EVENT_HOSTFXR_DLL_UNABLE_TO_LOAD_MSG L"Unable to load '%s'. This might be caused by a bitness mismatch between IIS application pool and published application." #define ASPNETCORE_EVENT_HOSTFXR_FAILURE_MSG L"Unable to locate application dependencies. Ensure that the versions of Microsoft.NetCore.App and Microsoft.AspNetCore.App targeted by the application are installed." #define ASPNETCORE_EVENT_INPROCESS_THREAD_EXCEPTION_MSG L"Application '%s' with physical root '%s' hit unexpected managed exception, exception code = '0x%x'. Please check the stderr logs for more information." -#define ASPNETCORE_EVENT_INPROCESS_THREAD_EXCEPTION_STDOUT_MSG L"Application '%s' with physical root '%s' hit unexpected managed exception, exception code = '0x%x'. Last 30KB characters of captured stdout and stderr logs:\r\n%s" +#define ASPNETCORE_EVENT_INPROCESS_THREAD_EXCEPTION_STDOUT_MSG L"Application '%s' with physical root '%s' hit unexpected managed exception, exception code = '0x%x'. First 30KB characters of captured stdout and stderr logs:\r\n%s" #define ASPNETCORE_EVENT_INPROCESS_RH_ERROR_MSG L"Could not find 'aspnetcorev2_inprocess.dll'. Exception message:\r\n%s" #define ASPNETCORE_EVENT_INPROCESS_RH_REFERENCE_MSG L"Could not find the assembly '%s' referenced for the in-process application. Please confirm the Microsoft.AspNetCore.Server.IIS package is referenced in your application." #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." diff --git a/src/Servers/IIS/AspNetCoreModuleV2/OutOfProcessRequestHandler/serverprocess.cpp b/src/Servers/IIS/AspNetCoreModuleV2/OutOfProcessRequestHandler/serverprocess.cpp index 69b11cd15d..89f806dd45 100644 --- a/src/Servers/IIS/AspNetCoreModuleV2/OutOfProcessRequestHandler/serverprocess.cpp +++ b/src/Servers/IIS/AspNetCoreModuleV2/OutOfProcessRequestHandler/serverprocess.cpp @@ -523,6 +523,7 @@ SERVER_PROCESS::PostStartCheck( } dwTickCount = GetTickCount(); + do { DWORD processStatus = 0; @@ -535,14 +536,6 @@ SERVER_PROCESS::PostStartCheck( if (GetExitCodeProcess(m_hProcessHandle, &processStatus) && processStatus != STILL_ACTIVE) { hr = E_APPLICATION_ACTIVATION_EXEC_FAILURE; - strEventMsg.SafeSnwprintf( - ASPNETCORE_EVENT_PROCESS_START_STATUS_ERROR_MSG, - m_struAppFullPath.QueryStr(), - m_struPhysicalPath.QueryStr(), - m_struCommandLine.QueryStr(), - hr, - m_dwProcessId, - processStatus); goto Finished; } } @@ -956,12 +949,23 @@ SERVER_PROCESS::StartProcess( Finished: if (FAILED_LOG(hr) || m_fReady == FALSE) { + if (m_hStdErrWritePipe != NULL) + { + if (m_hStdErrWritePipe != INVALID_HANDLE_VALUE) + { + CloseHandle(m_hStdErrWritePipe); + } + + m_hStdErrWritePipe = NULL; + } + if (m_hStdoutHandle != NULL) { if (m_hStdoutHandle != INVALID_HANDLE_VALUE) { CloseHandle(m_hStdoutHandle); } + m_hStdoutHandle = NULL; } @@ -976,7 +980,8 @@ Finished: m_struAppFullPath.QueryStr(), m_struPhysicalPath.QueryStr(), m_struCommandLine.QueryStr(), - m_dwPort); + m_dwPort, + m_output.str().c_str()); } return hr; } @@ -1022,23 +1027,29 @@ SERVER_PROCESS::SetupStdHandles( DBG_ASSERT(pStartupInfo); + saAttr.nLength = sizeof(SECURITY_ATTRIBUTES); + saAttr.bInheritHandle = TRUE; + saAttr.lpSecurityDescriptor = NULL; + if (!m_fStdoutLogEnabled) { + CreatePipe(&m_hStdoutHandle, &m_hStdErrWritePipe, &saAttr, 0 /*nSize*/); + + // Read the stderr handle on a separate thread until we get 30Kb. + m_hReadThread = CreateThread( + nullptr, // default security attributes + 0, // default stack size + reinterpret_cast(ReadStdErrHandle), + this, // thread function arguments + 0, // default creation flags + nullptr); // receive thread identifier + pStartupInfo->dwFlags = STARTF_USESTDHANDLES; pStartupInfo->hStdInput = INVALID_HANDLE_VALUE; - pStartupInfo->hStdError = INVALID_HANDLE_VALUE; - pStartupInfo->hStdOutput = INVALID_HANDLE_VALUE; + pStartupInfo->hStdError = m_hStdErrWritePipe; + pStartupInfo->hStdOutput = m_hStdErrWritePipe; return hr; } - if (m_hStdoutHandle != NULL && m_hStdoutHandle != INVALID_HANDLE_VALUE) - { - if (!CloseHandle(m_hStdoutHandle)) - { - hr = HRESULT_FROM_WIN32(GetLastError()); - goto Finished; - } - m_hStdoutHandle = NULL; - } hr = FILE_UTILITY::ConvertPathToFullPath( m_struLogFile.QueryStr(), @@ -1070,10 +1081,6 @@ SERVER_PROCESS::SetupStdHandles( goto Finished; } - saAttr.nLength = sizeof(SECURITY_ATTRIBUTES); - saAttr.bInheritHandle = TRUE; - saAttr.lpSecurityDescriptor = NULL; - m_hStdoutHandle = CreateFileW(m_struFullLogFile.QueryStr(), FILE_WRITE_DATA, FILE_SHARE_READ, @@ -1118,6 +1125,57 @@ Finished: return hr; } + +void +SERVER_PROCESS::ReadStdErrHandle( + LPVOID pContext +) +{ + auto pLoggingProvider = static_cast(pContext); + DBG_ASSERT(pLoggingProvider != NULL); + pLoggingProvider->ReadStdErrHandleInternal(); +} + +void +SERVER_PROCESS::ReadStdErrHandleInternal() +{ + const size_t bufferSize = 4096; + size_t charactersLeft = 30000; + std::string tempBuffer; + + tempBuffer.resize(bufferSize); + + DWORD dwNumBytesRead = 0; + while (charactersLeft > 0) + { + if (ReadFile(m_hStdoutHandle, + tempBuffer.data(), + bufferSize, + &dwNumBytesRead, + nullptr)) + { + auto text = to_wide_string(tempBuffer, dwNumBytesRead, GetConsoleOutputCP()); + auto const writeSize = min(charactersLeft, text.size()); + m_output.write(text.c_str(), writeSize); + charactersLeft -= writeSize; + } + else + { + return; + } + } + + // Continue reading from console out until the program ends or the handle is invalid. + // Otherwise, the program may hang as nothing is reading stdout. + while (ReadFile(m_hStdoutHandle, + tempBuffer.data(), + bufferSize, + &dwNumBytesRead, + nullptr)) + { + } +} + HRESULT SERVER_PROCESS::CheckIfServerIsUp( _In_ DWORD dwPort, @@ -1795,6 +1853,7 @@ SERVER_PROCESS::CleanUp() SERVER_PROCESS::~SERVER_PROCESS() { + DWORD dwThreadStatus = 0; CleanUp(); @@ -1817,6 +1876,38 @@ SERVER_PROCESS::~SERVER_PROCESS() m_hStdoutHandle = NULL; } + // 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_hReadThread != nullptr) + { + LOG_INFO(L"Canceling standard stream pipe reader."); + CancelSynchronousIo(m_hReadThread); + } + + // GetExitCodeThread returns 0 on failure; thread status code is invalid. + if (m_hReadThread != nullptr && + !LOG_LAST_ERROR_IF(!GetExitCodeThread(m_hReadThread, &dwThreadStatus)) && + dwThreadStatus == STILL_ACTIVE) + { + // Wait for graceful shutdown, i.e., the exit of the background thread or timeout + if (WaitForSingleObject(m_hReadThread, PIPE_OUTPUT_THREAD_TIMEOUT) != WAIT_OBJECT_0) + { + // If the thread is still running, we need kill it first before exit to avoid AV + if (!LOG_LAST_ERROR_IF(GetExitCodeThread(m_hReadThread, &dwThreadStatus) == 0) && + dwThreadStatus == STILL_ACTIVE) + { + LOG_WARN(L"Thread reading stdout/err hit timeout, forcibly closing thread."); + TerminateThread(m_hReadThread, STATUS_CONTROL_C_EXIT); + } + } + } + + if (m_hReadThread != nullptr) + { + CloseHandle(m_hReadThread); + m_hReadThread = nullptr; + } + if (m_fStdoutLogEnabled) { m_Timer.CancelTimer(); diff --git a/src/Servers/IIS/AspNetCoreModuleV2/OutOfProcessRequestHandler/serverprocess.h b/src/Servers/IIS/AspNetCoreModuleV2/OutOfProcessRequestHandler/serverprocess.h index 36d6b6ab72..0d90dd47de 100644 --- a/src/Servers/IIS/AspNetCoreModuleV2/OutOfProcessRequestHandler/serverprocess.h +++ b/src/Servers/IIS/AspNetCoreModuleV2/OutOfProcessRequestHandler/serverprocess.h @@ -10,6 +10,7 @@ #define MAX_PORT 48000 #define MAX_RETRY 10 #define MAX_ACTIVE_CHILD_PROCESSES 16 +#define PIPE_OUTPUT_THREAD_TIMEOUT 2000 #define LOCALHOST "127.0.0.1" #define ASPNETCORE_PORT_STR L"ASPNETCORE_PORT" #define ASPNETCORE_PORT_ENV_STR L"ASPNETCORE_PORT=" @@ -135,6 +136,15 @@ public: VOID ); + static + void + ReadStdErrHandle( + LPVOID pContext + ); + + void + ReadStdErrHandleInternal(); + private: VOID CleanUp(); @@ -283,6 +293,9 @@ private: HANDLE m_hListeningProcessHandle; HANDLE m_hProcessWaitHandle; HANDLE m_hShutdownHandle; + HANDLE m_hReadThread; + HANDLE m_hStdErrWritePipe; + std::wstringstream m_output; // // m_hChildProcessHandle is the handle to process created by // m_hProcessHandle process if it does. diff --git a/src/Servers/IIS/IIS/test/Common.FunctionalTests/LogFileTests.cs b/src/Servers/IIS/IIS/test/Common.FunctionalTests/LogFileTests.cs index 5f7fdec604..2e640536b4 100644 --- a/src/Servers/IIS/IIS/test/Common.FunctionalTests/LogFileTests.cs +++ b/src/Servers/IIS/IIS/test/Common.FunctionalTests/LogFileTests.cs @@ -200,7 +200,7 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests } else { - EventLogHelpers.VerifyEventLogEvent(deploymentResult, EventLogHelpers.OutOfProcessFailedToStart(deploymentResult), Logger); + EventLogHelpers.VerifyEventLogEvent(deploymentResult, EventLogHelpers.OutOfProcessFailedToStart(deploymentResult, ""), Logger); } } @@ -220,6 +220,34 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests Assert.Single(Directory.GetFiles(_logFolderPath), Helpers.GetExpectedLogName(deploymentResult, _logFolderPath)); } + [ConditionalFact] + public async Task CaptureLogsForOutOfProcessWhenProcessFailsToStart() + { + var deploymentParameters = Fixture.GetBaseDeploymentParameters(HostingModel.OutOfProcess); + deploymentParameters.TransformArguments((a, _) => $"{a} ConsoleWrite"); + var deploymentResult = await DeployAsync(deploymentParameters); + + var response = await deploymentResult.HttpClient.GetAsync("Test"); + + StopServer(); + + EventLogHelpers.VerifyEventLogEvent(deploymentResult, EventLogHelpers.OutOfProcessFailedToStart(deploymentResult, "Wow!"), Logger); + } + + [ConditionalFact] + public async Task CaptureLogsForOutOfProcessWhenProcessFailsToStart30KbMax() + { + var deploymentParameters = Fixture.GetBaseDeploymentParameters(HostingModel.OutOfProcess); + deploymentParameters.TransformArguments((a, _) => $"{a} ConsoleWrite30Kb"); + var deploymentResult = await DeployAsync(deploymentParameters); + + var response = await deploymentResult.HttpClient.GetAsync("Test"); + + StopServer(); + + EventLogHelpers.VerifyEventLogEvent(deploymentResult, EventLogHelpers.OutOfProcessFailedToStart(deploymentResult, new string('a', 30000)), Logger); + } + private static string ReadLogs(string logPath) { using (var stream = File.Open(logPath, FileMode.Open, FileAccess.Read, FileShare.ReadWrite)) diff --git a/src/Servers/IIS/IIS/test/Common.FunctionalTests/Utilities/EventLogHelpers.cs b/src/Servers/IIS/IIS/test/Common.FunctionalTests/Utilities/EventLogHelpers.cs index 1c44e186d3..d2a94632c4 100644 --- a/src/Servers/IIS/IIS/test/Common.FunctionalTests/Utilities/EventLogHelpers.cs +++ b/src/Servers/IIS/IIS/test/Common.FunctionalTests/Utilities/EventLogHelpers.cs @@ -192,7 +192,7 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests { if (DeployerSelector.HasNewHandler) { - return $"Application '/LM/W3SVC/1/ROOT' with physical root '{EscapedContentRoot(deploymentResult)}' has exited from Program.Main with exit code = '{code}'. Last 30KB characters of captured stdout and stderr logs:\r\n{output}"; + return $"Application '/LM/W3SVC/1/ROOT' with physical root '{EscapedContentRoot(deploymentResult)}' has exited from Program.Main with exit code = '{code}'. First 30KB characters of captured stdout and stderr logs:\r\n{output}"; } else { @@ -217,13 +217,13 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests } } - public static string OutOfProcessFailedToStart(IISDeploymentResult deploymentResult) + public static string OutOfProcessFailedToStart(IISDeploymentResult deploymentResult, string output) { if (DeployerSelector.HasNewShim) { return $"Application '/LM/W3SVC/1/ROOT' with physical root '{EscapedContentRoot(deploymentResult)}' failed to start process with " + $"commandline '(.*)' with multiple retries. " + - $"Failed to bind to port '(.*)'. See previous warnings for details."; + $"Failed to bind to port '(.*)'. First 30KB characters of captured stdout and stderr logs from multiple retries:\r\n{output}"; } else { diff --git a/src/Servers/IIS/IIS/test/testassets/OutOfProcessWebSite/Program.cs b/src/Servers/IIS/IIS/test/testassets/OutOfProcessWebSite/Program.cs index c349510b26..b626839f62 100644 --- a/src/Servers/IIS/IIS/test/testassets/OutOfProcessWebSite/Program.cs +++ b/src/Servers/IIS/IIS/test/testassets/OutOfProcessWebSite/Program.cs @@ -1,8 +1,11 @@ // 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.Diagnostics; using System.IO; using System.Linq; +using System.Threading; using Microsoft.AspNetCore.Hosting; using Microsoft.Extensions.Logging; @@ -13,11 +16,19 @@ namespace TestSite public static int Main(string[] args) { var mode = args.FirstOrDefault(); + switch (mode) { case "CreateFile": File.WriteAllText(args[1], ""); return StartServer(); + case "ConsoleWrite": + Console.WriteLine("Wow!"); + return 0; + case "ConsoleWrite30Kb": + // Write over 30kb to make sure logs are truncated. + Console.WriteLine(new string('a', 40000)); + return 0; } return StartServer();