Skip to content

Commit 2e89aa4

Browse files
jkotalikjkotalik
authored
Log stdout to event log on failure to start process for ANCM out of process (#10123)
1 parent b9546df commit 2e89aa4

File tree

8 files changed

+186
-35
lines changed

8 files changed

+186
-35
lines changed

‎src/Servers/IIS/AspNetCoreModuleV2/CommonLib/StringHelpers.cpp

Lines changed: 8 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -26,22 +26,27 @@ int compare_ignore_case(const std::wstring& s1, const std::wstring& s2)
2626
}
2727

2828
std::wstring to_wide_string(const std::string &source, const unsigned int codePage)
29+
{
30+
return to_wide_string(source, static_cast<int>(source.length()), codePage);
31+
}
32+
33+
std::wstring to_wide_string(const std::string& source, const int length, const unsigned int codePage)
2934
{
3035
// MultiByteToWideChar returns 0 on failure, which is also the same return value
3136
// for empty strings. Preemptive return.
32-
if (source.length() == 0)
37+
if (length == 0)
3338
{
3439
return L"";
3540
}
3641

3742
std::wstring destination;
3843

39-
int nChars = MultiByteToWideChar(codePage, 0, source.data(), static_cast<int>(source.length()), NULL, 0);
44+
int nChars = MultiByteToWideChar(codePage, 0, source.data(), length, NULL, 0);
4045
THROW_LAST_ERROR_IF(nChars == 0);
4146

4247
destination.resize(nChars);
4348

44-
nChars = MultiByteToWideChar(codePage, 0, source.data(), static_cast<int>(source.length()), destination.data(), nChars);
49+
nChars = MultiByteToWideChar(codePage, 0, source.data(), length, destination.data(), nChars);
4550
THROW_LAST_ERROR_IF(nChars == 0);
4651

4752
return destination;

‎src/Servers/IIS/AspNetCoreModuleV2/CommonLib/StringHelpers.h

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -15,7 +15,10 @@ bool equals_ignore_case(const std::wstring& s1, const std::wstring& s2);
1515
int compare_ignore_case(const std::wstring& s1, const std::wstring& s2);
1616

1717
[[nodiscard]]
18-
std::wstring to_wide_string(const std::string &source, const unsigned int codePage);
18+
std::wstring to_wide_string(const std::string& source, const unsigned int codePage);
19+
20+
[[nodiscard]]
21+
std::wstring to_wide_string(const std::string &source, const int length, const unsigned int codePage);
1922

2023
[[nodiscard]]
2124
std::string to_multi_byte_string(const std::wstring& text, const unsigned int codePage);

‎src/Servers/IIS/AspNetCoreModuleV2/CommonLib/resources.h

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -14,7 +14,7 @@
1414
#define ASPNETCORE_EVENT_PROCESS_START_SUCCESS_MSG L"Application '%s' started process '%d' successfully and process '%d' is listening on port '%d'."
1515
#define ASPNETCORE_EVENT_RAPID_FAIL_COUNT_EXCEEDED_MSG L"Maximum rapid fail count per minute of '%d' exceeded."
1616
#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'."
17-
#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."
17+
#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"
1818
#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'."
1919
#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."
2020
#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 @@
3030
#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)."
3131
#define ASPNETCORE_CONFIGURATION_LOAD_ERROR_MSG L"Could not load configuration. Exception message:\r\n%s"
3232
#define ASPNETCORE_EVENT_ADD_APPLICATION_ERROR_MSG L"Failed to start application '%s', ErrorCode '0x%x'."
33-
#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"
33+
#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"
3434
#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."
3535
#define ASPNETCORE_EVENT_RECYCLE_APPOFFLINE_MSG L"Application '%s' was recycled after detecting app_offline.htm."
3636
#define ASPNETCORE_EVENT_MONITOR_APPOFFLINE_ERROR_MSG L"Failed to monitor app_offline.htm for application '%s', ErrorCode '0x%x'. "
@@ -41,7 +41,7 @@
4141
#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."
4242
#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."
4343
#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."
44-
#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"
44+
#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"
4545
#define ASPNETCORE_EVENT_INPROCESS_RH_ERROR_MSG L"Could not find 'aspnetcorev2_inprocess.dll'. Exception message:\r\n%s"
4646
#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."
4747
#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."

‎src/Servers/IIS/AspNetCoreModuleV2/OutOfProcessRequestHandler/serverprocess.cpp

Lines changed: 115 additions & 24 deletions
Original file line numberDiff line numberDiff line change
@@ -523,6 +523,7 @@ SERVER_PROCESS::PostStartCheck(
523523
}
524524

525525
dwTickCount = GetTickCount();
526+
526527
do
527528
{
528529
DWORD processStatus = 0;
@@ -535,14 +536,6 @@ SERVER_PROCESS::PostStartCheck(
535536
if (GetExitCodeProcess(m_hProcessHandle, &processStatus) && processStatus != STILL_ACTIVE)
536537
{
537538
hr = E_APPLICATION_ACTIVATION_EXEC_FAILURE;
538-
strEventMsg.SafeSnwprintf(
539-
ASPNETCORE_EVENT_PROCESS_START_STATUS_ERROR_MSG,
540-
m_struAppFullPath.QueryStr(),
541-
m_struPhysicalPath.QueryStr(),
542-
m_struCommandLine.QueryStr(),
543-
hr,
544-
m_dwProcessId,
545-
processStatus);
546539
goto Finished;
547540
}
548541
}
@@ -956,12 +949,23 @@ SERVER_PROCESS::StartProcess(
956949
Finished:
957950
if (FAILED_LOG(hr) || m_fReady == FALSE)
958951
{
952+
if (m_hStdErrWritePipe != NULL)
953+
{
954+
if (m_hStdErrWritePipe != INVALID_HANDLE_VALUE)
955+
{
956+
CloseHandle(m_hStdErrWritePipe);
957+
}
958+
959+
m_hStdErrWritePipe = NULL;
960+
}
961+
959962
if (m_hStdoutHandle != NULL)
960963
{
961964
if (m_hStdoutHandle != INVALID_HANDLE_VALUE)
962965
{
963966
CloseHandle(m_hStdoutHandle);
964967
}
968+
965969
m_hStdoutHandle = NULL;
966970
}
967971

@@ -976,7 +980,8 @@ SERVER_PROCESS::StartProcess(
976980
m_struAppFullPath.QueryStr(),
977981
m_struPhysicalPath.QueryStr(),
978982
m_struCommandLine.QueryStr(),
979-
m_dwPort);
983+
m_dwPort,
984+
m_output.str().c_str());
980985
}
981986
return hr;
982987
}
@@ -1022,23 +1027,29 @@ SERVER_PROCESS::SetupStdHandles(
10221027

10231028
DBG_ASSERT(pStartupInfo);
10241029

1030+
saAttr.nLength = sizeof(SECURITY_ATTRIBUTES);
1031+
saAttr.bInheritHandle = TRUE;
1032+
saAttr.lpSecurityDescriptor = NULL;
1033+
10251034
if (!m_fStdoutLogEnabled)
10261035
{
1036+
CreatePipe(&m_hStdoutHandle, &m_hStdErrWritePipe, &saAttr, 0 /*nSize*/);
1037+
1038+
// Read the stderr handle on a separate thread until we get 30Kb.
1039+
m_hReadThread = CreateThread(
1040+
nullptr, // default security attributes
1041+
0, // default stack size
1042+
reinterpret_cast<LPTHREAD_START_ROUTINE>(ReadStdErrHandle),
1043+
this, // thread function arguments
1044+
0, // default creation flags
1045+
nullptr); // receive thread identifier
1046+
10271047
pStartupInfo->dwFlags = STARTF_USESTDHANDLES;
10281048
pStartupInfo->hStdInput = INVALID_HANDLE_VALUE;
1029-
pStartupInfo->hStdError = INVALID_HANDLE_VALUE;
1030-
pStartupInfo->hStdOutput = INVALID_HANDLE_VALUE;
1049+
pStartupInfo->hStdError = m_hStdErrWritePipe;
1050+
pStartupInfo->hStdOutput = m_hStdErrWritePipe;
10311051
return hr;
10321052
}
1033-
if (m_hStdoutHandle != NULL && m_hStdoutHandle != INVALID_HANDLE_VALUE)
1034-
{
1035-
if (!CloseHandle(m_hStdoutHandle))
1036-
{
1037-
hr = HRESULT_FROM_WIN32(GetLastError());
1038-
goto Finished;
1039-
}
1040-
m_hStdoutHandle = NULL;
1041-
}
10421053

10431054
hr = FILE_UTILITY::ConvertPathToFullPath(
10441055
m_struLogFile.QueryStr(),
@@ -1070,10 +1081,6 @@ SERVER_PROCESS::SetupStdHandles(
10701081
goto Finished;
10711082
}
10721083

1073-
saAttr.nLength = sizeof(SECURITY_ATTRIBUTES);
1074-
saAttr.bInheritHandle = TRUE;
1075-
saAttr.lpSecurityDescriptor = NULL;
1076-
10771084
m_hStdoutHandle = CreateFileW(m_struFullLogFile.QueryStr(),
10781085
FILE_WRITE_DATA,
10791086
FILE_SHARE_READ,
@@ -1118,6 +1125,57 @@ SERVER_PROCESS::SetupStdHandles(
11181125
return hr;
11191126
}
11201127

1128+
1129+
void
1130+
SERVER_PROCESS::ReadStdErrHandle(
1131+
LPVOID pContext
1132+
)
1133+
{
1134+
auto pLoggingProvider = static_cast<SERVER_PROCESS*>(pContext);
1135+
DBG_ASSERT(pLoggingProvider != NULL);
1136+
pLoggingProvider->ReadStdErrHandleInternal();
1137+
}
1138+
1139+
void
1140+
SERVER_PROCESS::ReadStdErrHandleInternal()
1141+
{
1142+
const size_t bufferSize = 4096;
1143+
size_t charactersLeft = 30000;
1144+
std::string tempBuffer;
1145+
1146+
tempBuffer.resize(bufferSize);
1147+
1148+
DWORD dwNumBytesRead = 0;
1149+
while (charactersLeft > 0)
1150+
{
1151+
if (ReadFile(m_hStdoutHandle,
1152+
tempBuffer.data(),
1153+
bufferSize,
1154+
&dwNumBytesRead,
1155+
nullptr))
1156+
{
1157+
auto text = to_wide_string(tempBuffer, dwNumBytesRead, GetConsoleOutputCP());
1158+
auto const writeSize = min(charactersLeft, text.size());
1159+
m_output.write(text.c_str(), writeSize);
1160+
charactersLeft -= writeSize;
1161+
}
1162+
else
1163+
{
1164+
return;
1165+
}
1166+
}
1167+
1168+
// Continue reading from console out until the program ends or the handle is invalid.
1169+
// Otherwise, the program may hang as nothing is reading stdout.
1170+
while (ReadFile(m_hStdoutHandle,
1171+
tempBuffer.data(),
1172+
bufferSize,
1173+
&dwNumBytesRead,
1174+
nullptr))
1175+
{
1176+
}
1177+
}
1178+
11211179
HRESULT
11221180
SERVER_PROCESS::CheckIfServerIsUp(
11231181
_In_ DWORD dwPort,
@@ -1795,6 +1853,7 @@ SERVER_PROCESS::CleanUp()
17951853

17961854
SERVER_PROCESS::~SERVER_PROCESS()
17971855
{
1856+
DWORD dwThreadStatus = 0;
17981857

17991858
CleanUp();
18001859

@@ -1817,6 +1876,38 @@ SERVER_PROCESS::~SERVER_PROCESS()
18171876
m_hStdoutHandle = NULL;
18181877
}
18191878

1879+
// Forces ReadFile to cancel, causing the read loop to complete.
1880+
// Don't check return value as IO may or may not be completed already.
1881+
if (m_hReadThread != nullptr)
1882+
{
1883+
LOG_INFO(L"Canceling standard stream pipe reader.");
1884+
CancelSynchronousIo(m_hReadThread);
1885+
}
1886+
1887+
// GetExitCodeThread returns 0 on failure; thread status code is invalid.
1888+
if (m_hReadThread != nullptr &&
1889+
!LOG_LAST_ERROR_IF(!GetExitCodeThread(m_hReadThread, &dwThreadStatus)) &&
1890+
dwThreadStatus == STILL_ACTIVE)
1891+
{
1892+
// Wait for graceful shutdown, i.e., the exit of the background thread or timeout
1893+
if (WaitForSingleObject(m_hReadThread, PIPE_OUTPUT_THREAD_TIMEOUT) != WAIT_OBJECT_0)
1894+
{
1895+
// If the thread is still running, we need kill it first before exit to avoid AV
1896+
if (!LOG_LAST_ERROR_IF(GetExitCodeThread(m_hReadThread, &dwThreadStatus) == 0) &&
1897+
dwThreadStatus == STILL_ACTIVE)
1898+
{
1899+
LOG_WARN(L"Thread reading stdout/err hit timeout, forcibly closing thread.");
1900+
TerminateThread(m_hReadThread, STATUS_CONTROL_C_EXIT);
1901+
}
1902+
}
1903+
}
1904+
1905+
if (m_hReadThread != nullptr)
1906+
{
1907+
CloseHandle(m_hReadThread);
1908+
m_hReadThread = nullptr;
1909+
}
1910+
18201911
if (m_fStdoutLogEnabled)
18211912
{
18221913
m_Timer.CancelTimer();

‎src/Servers/IIS/AspNetCoreModuleV2/OutOfProcessRequestHandler/serverprocess.h

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -10,6 +10,7 @@
1010
#define MAX_PORT 48000
1111
#define MAX_RETRY 10
1212
#define MAX_ACTIVE_CHILD_PROCESSES 16
13+
#define PIPE_OUTPUT_THREAD_TIMEOUT 2000
1314
#define LOCALHOST "127.0.0.1"
1415
#define ASPNETCORE_PORT_STR L"ASPNETCORE_PORT"
1516
#define ASPNETCORE_PORT_ENV_STR L"ASPNETCORE_PORT="
@@ -135,6 +136,15 @@ class SERVER_PROCESS
135136
VOID
136137
);
137138

139+
static
140+
void
141+
ReadStdErrHandle(
142+
LPVOID pContext
143+
);
144+
145+
void
146+
ReadStdErrHandleInternal();
147+
138148
private:
139149
VOID
140150
CleanUp();
@@ -283,6 +293,9 @@ class SERVER_PROCESS
283293
HANDLE m_hListeningProcessHandle;
284294
HANDLE m_hProcessWaitHandle;
285295
HANDLE m_hShutdownHandle;
296+
HANDLE m_hReadThread;
297+
HANDLE m_hStdErrWritePipe;
298+
std::wstringstream m_output;
286299
//
287300
// m_hChildProcessHandle is the handle to process created by
288301
// m_hProcessHandle process if it does.

‎src/Servers/IIS/IIS/test/Common.FunctionalTests/LogFileTests.cs

Lines changed: 29 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -200,7 +200,7 @@ public async Task CheckUTF8File(TestVariant variant)
200200
}
201201
else
202202
{
203-
EventLogHelpers.VerifyEventLogEvent(deploymentResult, EventLogHelpers.OutOfProcessFailedToStart(deploymentResult), Logger);
203+
EventLogHelpers.VerifyEventLogEvent(deploymentResult, EventLogHelpers.OutOfProcessFailedToStart(deploymentResult, ""), Logger);
204204
}
205205
}
206206

@@ -220,6 +220,34 @@ public async Task OnlyOneFileCreatedWithProcessStartTime(TestVariant variant)
220220
Assert.Single(Directory.GetFiles(_logFolderPath), Helpers.GetExpectedLogName(deploymentResult, _logFolderPath));
221221
}
222222

223+
[ConditionalFact]
224+
public async Task CaptureLogsForOutOfProcessWhenProcessFailsToStart()
225+
{
226+
var deploymentParameters = Fixture.GetBaseDeploymentParameters(HostingModel.OutOfProcess);
227+
deploymentParameters.TransformArguments((a, _) => $"{a} ConsoleWrite");
228+
var deploymentResult = await DeployAsync(deploymentParameters);
229+
230+
var response = await deploymentResult.HttpClient.GetAsync("Test");
231+
232+
StopServer();
233+
234+
EventLogHelpers.VerifyEventLogEvent(deploymentResult, EventLogHelpers.OutOfProcessFailedToStart(deploymentResult, "Wow!"), Logger);
235+
}
236+
237+
[ConditionalFact]
238+
public async Task CaptureLogsForOutOfProcessWhenProcessFailsToStart30KbMax()
239+
{
240+
var deploymentParameters = Fixture.GetBaseDeploymentParameters(HostingModel.OutOfProcess);
241+
deploymentParameters.TransformArguments((a, _) => $"{a} ConsoleWrite30Kb");
242+
var deploymentResult = await DeployAsync(deploymentParameters);
243+
244+
var response = await deploymentResult.HttpClient.GetAsync("Test");
245+
246+
StopServer();
247+
248+
EventLogHelpers.VerifyEventLogEvent(deploymentResult, EventLogHelpers.OutOfProcessFailedToStart(deploymentResult, new string('a', 30000)), Logger);
249+
}
250+
223251
private static string ReadLogs(string logPath)
224252
{
225253
using (var stream = File.Open(logPath, FileMode.Open, FileAccess.Read, FileShare.ReadWrite))

‎src/Servers/IIS/IIS/test/Common.FunctionalTests/Utilities/EventLogHelpers.cs

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -192,7 +192,7 @@ public static string InProcessThreadExitStdOut(IISDeploymentResult deploymentRes
192192
{
193193
if (DeployerSelector.HasNewHandler)
194194
{
195-
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}";
195+
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}";
196196
}
197197
else
198198
{
@@ -217,13 +217,13 @@ public static string ConfigurationLoadError(IISDeploymentResult deploymentResult
217217
}
218218
}
219219

220-
public static string OutOfProcessFailedToStart(IISDeploymentResult deploymentResult)
220+
public static string OutOfProcessFailedToStart(IISDeploymentResult deploymentResult, string output)
221221
{
222222
if (DeployerSelector.HasNewShim)
223223
{
224224
return $"Application '/LM/W3SVC/1/ROOT' with physical root '{EscapedContentRoot(deploymentResult)}' failed to start process with " +
225225
$"commandline '(.*)' with multiple retries. " +
226-
$"Failed to bind to port '(.*)'. See previous warnings for details.";
226+
$"Failed to bind to port '(.*)'. First 30KB characters of captured stdout and stderr logs from multiple retries:\r\n{output}";
227227
}
228228
else
229229
{

0 commit comments

Comments
 (0)