From e3d3b088aee20bd238ef256825dfe30dfe685f3d Mon Sep 17 00:00:00 2001 From: pan-wang Date: Wed, 21 Feb 2018 10:58:34 -0800 Subject: [PATCH] adding logging for outprocess start and application recycle (#573) adding logging for outprocess start and application recycle --- src/AspNetCore/Src/applicationmanager.cxx | 20 ++ src/CommonLib/aspnetcore_msg.mc | 11 + src/CommonLib/resources.h | 8 +- .../outofprocess/processmanager.cxx | 4 +- .../outofprocess/serverprocess.cxx | 279 ++++++++++-------- .../outofprocess/serverprocess.h | 4 +- 6 files changed, 203 insertions(+), 123 deletions(-) diff --git a/src/AspNetCore/Src/applicationmanager.cxx b/src/AspNetCore/Src/applicationmanager.cxx index e51e36078f..374c4675a8 100644 --- a/src/AspNetCore/Src/applicationmanager.cxx +++ b/src/AspNetCore/Src/applicationmanager.cxx @@ -196,6 +196,7 @@ APPLICATION_MANAGER::RecycleApplication( { HRESULT hr = S_OK; APPLICATION_INFO_KEY key; + DWORD dwPreviousCounter = 0; hr = key.Initialize(pszApplicationId); if (FAILED(hr)) @@ -203,13 +204,32 @@ APPLICATION_MANAGER::RecycleApplication( goto Finished; } AcquireSRWLockExclusive(&m_srwLock); + dwPreviousCounter = m_pApplicationInfoHash->Count(); + m_pApplicationInfoHash->DeleteKey(&key); + if(dwPreviousCounter != m_pApplicationInfoHash->Count()) + { + // Application got recycled. Log an event + STACK_STRU(strEventMsg, 256); + if (SUCCEEDED(strEventMsg.SafeSnwprintf( + ASPNETCORE_EVENT_RECYCLE_CONFIGURATION_MSG, + pszApplicationId))) + { + UTILITY::LogEvent(g_hEventLog, + EVENTLOG_INFORMATION_TYPE, + ASPNETCORE_EVENT_RECYCLE_CONFIGURATION, + strEventMsg.QueryStr()); + } + + } + if (m_pApplicationInfoHash->Count() == 0) { m_hostingModel = HOSTING_UNKNOWN; } + if (g_fAspnetcoreRHLoadedError) { // We had assembly loading failure diff --git a/src/CommonLib/aspnetcore_msg.mc b/src/CommonLib/aspnetcore_msg.mc index b3c0b198a7..795503fb70 100644 --- a/src/CommonLib/aspnetcore_msg.mc +++ b/src/CommonLib/aspnetcore_msg.mc @@ -146,6 +146,17 @@ Language=English %1 . +Messageid=1020 +SymbolicName=ASPNETCORE_EVENT_PROCESS_START_FAILURE +Language=English +%1 +. + +Messageid=1021 +SymbolicName=ASPNETCORE_EVENT_RECYCLE_CONFIGURATION +Language=English +%1 +. ; ;#endif // _ASPNETCORE_MODULE_MSG_H_ diff --git a/src/CommonLib/resources.h b/src/CommonLib/resources.h index 5e375a2db6..2660644625 100644 --- a/src/CommonLib/resources.h +++ b/src/CommonLib/resources.h @@ -12,9 +12,10 @@ #define ASPNETCORE_EVENT_MSG_BUFFER_SIZE 256 #define ASPNETCORE_EVENT_PROCESS_START_SUCCESS_MSG L"Application '%s' started process '%d' successfully and 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_INTERNAL_ERROR_MSG L"Application '%s' failed to parse processPath and arguments due to internal error, ErrorCode = '0x%x'." -#define ASPNETCORE_EVENT_PROCESS_START_POSTCREATE_ERROR_MSG L"Application '%s' with physical root '%s' created process with commandline '%s'but failed to get its status, ErrorCode = '0x%x', retryCounter '%d'." -#define ASPNETCORE_EVENT_PROCESS_START_ERROR_MSG L"Application '%s' with physical root '%s' failed to start process with commandline '%s', ErrorCode = '0x%x', retryCounter '%d'." +#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', 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. The last try of listening port is '%d'. See pervious warnings for details." +#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', 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 rang '%d - %d', EorrorCode = '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'" #define ASPNETCORE_EVENT_PROCESS_START_NOTREADY_ERROR_MSG L"Application '%s' with physical root '%s' created process with commandline '%s' but either crashed or did not respond or did not listen on the given port '%d', ErrorCode = '0x%x'" #define ASPNETCORE_EVENT_INVALID_STDOUT_LOG_FILE_MSG L"Warning: Could not create stdoutLogFile %s, ErrorCode = '0x%x'." @@ -28,6 +29,7 @@ #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_RECYCLE_APPOFFLINE_MSG L"Application '%s' is recycled due to app_offline file was detected." +#define ASPNETCORE_EVENT_RECYCLE_CONFIGURATION_MSG L"Application '%s' is recycled due to configuration changed" #define ASPNETCORE_EVENT_MODULE_DISABLED_MSG L"AspNetCore Module is disabled" #define ASPNETCORE_EVENT_INPROCESS_FULL_FRAMEWORK_APP_MSG L"Application '%s' was compiled for .NET Framework. Please compile for .NET core to run the inprocess application or change the process mode to out of process. ErrorCode = '0x%x'." #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'." diff --git a/src/RequestHandler/outofprocess/processmanager.cxx b/src/RequestHandler/outofprocess/processmanager.cxx index 9c9ceb449d..88fc771b16 100644 --- a/src/RequestHandler/outofprocess/processmanager.cxx +++ b/src/RequestHandler/outofprocess/processmanager.cxx @@ -173,9 +173,7 @@ PROCESS_MANAGER::GetProcess( // terminate existing process that is not ready // before creating new one. // - - //todo: - //ShutdownProcessNoLock( m_ppServerProcessList[dwProcessIndex] ); + ShutdownProcessNoLock( m_ppServerProcessList[dwProcessIndex] ); } else { diff --git a/src/RequestHandler/outofprocess/serverprocess.cxx b/src/RequestHandler/outofprocess/serverprocess.cxx index 97243d8bc2..9ed0e997e2 100644 --- a/src/RequestHandler/outofprocess/serverprocess.cxx +++ b/src/RequestHandler/outofprocess/serverprocess.cxx @@ -133,6 +133,8 @@ SERVER_PROCESS::SetupListenPort( { HRESULT hr = S_OK; ENVIRONMENT_VAR_ENTRY *pEntry = NULL; + STACK_STRU(strEventMsg, 256); + pEnvironmentVarTable->FindKey(ASPNETCORE_PORT_ENV_STR, &pEntry); if (pEntry != NULL) { @@ -190,6 +192,25 @@ Finished: pEntry->Dereference(); pEntry = NULL; } + + if (FAILED(hr)) + { + if (SUCCEEDED(strEventMsg.SafeSnwprintf( + ASPNETCORE_EVENT_PROCESS_START_PORTSETUP_ERROR_MSG, + m_struAppFullPath.QueryStr(), + m_struPhysicalPath.QueryStr(), + m_dwPort, + MIN_PORT, + MAX_PORT, + hr))) + { + UTILITY::LogEvent(g_hEventLog, + EVENTLOG_INFORMATION_TYPE, + ASPNETCORE_EVENT_PROCESS_START_SUCCESS, + strEventMsg.QueryStr()); + } + } + return hr; } @@ -503,6 +524,9 @@ SERVER_PROCESS::OutputEnvironmentVariables DBG_ASSERT(pEnvironmentVarTable); // We added some startup variables DBG_ASSERT(pEnvironmentVarTable->Count() >0); + // cleanup, as we may in retry logic + pmszOutput->Reset(); + pszEnvironmentVariables = GetEnvironmentStringsW(); if (pszEnvironmentVariables == NULL) { @@ -575,6 +599,13 @@ SERVER_PROCESS::SetupCommandLine( DBG_ASSERT(pstrCommandLine); + if (!m_struCommandLine.IsEmpty() && + pstrCommandLine == (&m_struCommandLine)) + { + // already set up the commandline string, skip + goto Finished; + } + pszPath = m_ProcessPath.QueryStr(); if ((wcsstr(pszPath, L":") == NULL) && (wcsstr(pszPath, L"%") == NULL)) @@ -638,6 +669,7 @@ SERVER_PROCESS::PostStartCheck( DWORD dwTimeDifference = 0; DWORD dwActualProcessId = 0; INT iChildProcessIndex = -1; + STACK_STRU(strEventMsg, 256); if (CheckRemoteDebuggerPresent(m_hProcessHandle, &fDebuggerAttached) == 0) { @@ -654,14 +686,14 @@ SERVER_PROCESS::PostStartCheck( // make sure the process is still running if (processStatus != STILL_ACTIVE) { - hr = E_FAIL; - /*pStruErrorMessage->SafeSnwprintf( - ASPNETCORE_EVENT_PROCESS_START_ERROR_MSG, + hr = E_APPLICATION_ACTIVATION_EXEC_FAILURE; + strEventMsg.SafeSnwprintf( + ASPNETCORE_EVENT_PROCESS_START_STATUS_ERROR_MSG, m_struAppFullPath.QueryStr(), - m_pszRootApplicationPath.QueryStr(), - m_pStruCommandline->QueryStr(), + m_struPhysicalPath.QueryStr(), + m_struCommandLine.QueryStr(), hr, - processStatus);*/ + processStatus); goto Finished; } } @@ -680,6 +712,11 @@ SERVER_PROCESS::PostStartCheck( } while (fReady == FALSE && ((dwTimeDifference < m_dwStartupTimeLimitInMS) || fDebuggerAttached)); + if (!fReady) + { + hr = E_APPLICATION_ACTIVATION_TIMED_OUT; + } + // register call back with the created process if (FAILED(hr = RegisterProcessWait(&m_hProcessWaitHandle, m_hProcessHandle))) { @@ -750,14 +787,14 @@ SERVER_PROCESS::PostStartCheck( // on the port we specified. // fReady = FALSE; - //pStruErrorMessage->SafeSnwprintf( - // ASPNETCORE_EVENT_PROCESS_START_WRONGPORT_ERROR_MSG, - // m_struAppFullPath.QueryStr(), - // m_pszRootApplicationPath.QueryStr(), - // m_struCommandline.QueryStr(), - // m_dwPort, - // hr); hr = HRESULT_FROM_WIN32(ERROR_CREATE_FAILED); + strEventMsg.SafeSnwprintf( + ASPNETCORE_EVENT_PROCESS_START_WRONGPORT_ERROR_MSG, + m_struAppFullPath.QueryStr(), + m_struPhysicalPath.QueryStr(), + m_struCommandLine.QueryStr(), + m_dwPort, + hr); goto Finished; } } @@ -770,13 +807,13 @@ SERVER_PROCESS::PostStartCheck( if (dwTimeDifference >= m_dwStartupTimeLimitInMS) { hr = HRESULT_FROM_WIN32(ERROR_TIMEOUT); - /*pStruErrorMessage->SafeSnwprintf( + strEventMsg.SafeSnwprintf( ASPNETCORE_EVENT_PROCESS_START_NOTREADY_ERROR_MSG, m_struAppFullPath.QueryStr(), - m_pszRootApplicationPath.QueryStr(), - pStruCommandline->QueryStr(), + m_struPhysicalPath.QueryStr(), + m_struCommandLine.QueryStr(), m_dwPort, - hr);*/ + hr); } goto Finished; } @@ -794,13 +831,13 @@ SERVER_PROCESS::PostStartCheck( if ((FAILED(hr) || fReady == FALSE)) { - //pStruErrorMessage->SafeSnwprintf( - // ASPNETCORE_EVENT_PROCESS_START_NOTREADY_ERROR_MSG, - // m_struAppFullPath.QueryStr(), - // m_pszRootApplicationPath.QueryStr(), - // pStruCommandline->QueryStr(), - // m_dwPort, - // hr); + strEventMsg.SafeSnwprintf( + ASPNETCORE_EVENT_PROCESS_START_NOTREADY_ERROR_MSG, + m_struAppFullPath.QueryStr(), + m_struPhysicalPath.QueryStr(), + m_struCommandLine.QueryStr(), + m_dwPort, + hr); goto Finished; } } @@ -845,6 +882,12 @@ Finished: m_pForwarderConnection->DereferenceForwarderConnection(); m_pForwarderConnection = NULL; } + + UTILITY::LogEvent( + g_hEventLog, + EVENTLOG_WARNING_TYPE, + ASPNETCORE_EVENT_PROCESS_START_ERROR, + strEventMsg.QueryStr()); } return hr; } @@ -862,6 +905,7 @@ SERVER_PROCESS::StartProcess( STACK_STRU( strEventMsg, 256); MULTISZ mszNewEnvironment; ENVIRONMENT_VAR_HASH *pHashTable = NULL; + PWSTR pStrStage = NULL; GetStartupInfoW(&startupInfo); @@ -871,20 +915,22 @@ SERVER_PROCESS::StartProcess( // SetupStdHandles(&startupInfo); - // - // generate process command line. - // - if (FAILED(hr = SetupCommandLine(&m_struCommandLine))) - { - goto Finished; - } - while (dwRetryCount > 0) { dwRetryCount--; + // + // generate process command line. + // + if (FAILED(hr = SetupCommandLine(&m_struCommandLine))) + { + pStrStage = L"SetupCommanLine"; + goto Failure; + } + if (FAILED(hr = InitEnvironmentVariablesTable(&pHashTable))) { - goto Finished; + pStrStage = L"InitEnvironmentVariablesTable"; + goto Failure; } // @@ -892,7 +938,8 @@ SERVER_PROCESS::StartProcess( // if (FAILED(hr = SetupListenPort(pHashTable))) { - goto Finished; + pStrStage = L"SetupListenPort"; + goto Failure; } // @@ -900,7 +947,8 @@ SERVER_PROCESS::StartProcess( // if (FAILED(hr = SetupAppPath(pHashTable))) { - goto Finished; + pStrStage = L"SetupAppPath"; + goto Failure; } // @@ -908,7 +956,8 @@ SERVER_PROCESS::StartProcess( // if (FAILED(hr = SetupAppToken(pHashTable))) { - goto Finished; + pStrStage = L"SetupAppToken"; + goto Failure; } // @@ -916,7 +965,8 @@ SERVER_PROCESS::StartProcess( // if (FAILED(hr = OutputEnvironmentVariables(&mszNewEnvironment, pHashTable))) { - goto Finished; + pStrStage = L"OutputEnvironmentVariables"; + goto Failure; } dwCreationFlags = CREATE_NO_WINDOW | @@ -936,16 +986,9 @@ SERVER_PROCESS::StartProcess( &startupInfo, &processInformation)) { + pStrStage = L"CreateProcessW"; hr = HRESULT_FROM_WIN32(GetLastError()); - // don't the check return code as we already in error report - strEventMsg.SafeSnwprintf( - ASPNETCORE_EVENT_PROCESS_START_ERROR_MSG, - m_struAppFullPath.QueryStr(), - m_struPhysicalPath.QueryStr(), - m_struCommandLine.QueryStr(), - hr, - dwRetryCount); - goto Finished; + goto Failure; } m_hProcessHandle = processInformation.hProcess; @@ -958,15 +1001,17 @@ SERVER_PROCESS::StartProcess( hr = HRESULT_FROM_WIN32(GetLastError()); if (hr != HRESULT_FROM_WIN32(ERROR_NOT_SUPPORTED)) { - goto Finished; + pStrStage = L"AssignProcessToJobObject"; + goto Failure; } } } if (ResumeThread(processInformation.hThread) == -1) { + pStrStage = L"ResumeThread"; hr = HRESULT_FROM_WIN32(GetLastError()); - goto Finished; + goto Failure; } // @@ -974,7 +1019,8 @@ SERVER_PROCESS::StartProcess( // if (FAILED(hr = PostStartCheck())) { - goto Finished; + pStrStage = L"PostStartCheck"; + goto Failure; } // Backend process starts successfully. Set retry counter to 0 @@ -992,7 +1038,24 @@ SERVER_PROCESS::StartProcess( strEventMsg.QueryStr()); } - Finished: + goto Finished; + + Failure: + if (SUCCEEDED(strEventMsg.SafeSnwprintf( + ASPNETCORE_EVENT_PROCESS_START_ERROR_MSG, + m_struAppFullPath.QueryStr(), + m_struPhysicalPath.QueryStr(), + m_struCommandLine.QueryStr(), + pStrStage, + hr, + dwRetryCount))) + { + UTILITY::LogEvent(g_hEventLog, + EVENTLOG_WARNING_TYPE, + ASPNETCORE_EVENT_PROCESS_START_ERROR, + strEventMsg.QueryStr()); + } + if (processInformation.hThread != NULL) { CloseHandle(processInformation.hThread); @@ -1006,29 +1069,11 @@ SERVER_PROCESS::StartProcess( pHashTable = NULL; } - if (FAILED(hr)) - { - if (strEventMsg.IsEmpty()) - { - strEventMsg.SafeSnwprintf( - ASPNETCORE_EVENT_PROCESS_START_POSTCREATE_ERROR_MSG, - m_struAppFullPath.QueryStr(), - m_struPhysicalPath.QueryStr(), - m_struCommandLine.QueryStr(), - hr, - dwRetryCount); - } + CleanUp(); - if (!strEventMsg.IsEmpty()) - { - UTILITY::LogEvent(g_hEventLog, - EVENTLOG_ERROR_TYPE, - ASPNETCORE_EVENT_PROCESS_START_ERROR, - strEventMsg.QueryStr()); - } - } } +Finished: if (FAILED(hr) || m_fReady == FALSE) { if (m_hStdoutHandle != NULL) @@ -1045,23 +1090,17 @@ SERVER_PROCESS::StartProcess( m_Timer.CancelTimer(); } - if (m_hListeningProcessHandle != NULL) + if (SUCCEEDED(strEventMsg.SafeSnwprintf( + ASPNETCORE_EVENT_PROCESS_START_FAILURE_MSG, + m_struAppFullPath.QueryStr(), + m_struCommandLine.QueryStr(), + m_dwPort))) { - if (m_hListeningProcessHandle != INVALID_HANDLE_VALUE) - { - CloseHandle(m_hListeningProcessHandle); - } - m_hListeningProcessHandle = NULL; + UTILITY::LogEvent(g_hEventLog, + EVENTLOG_ERROR_TYPE, + ASPNETCORE_EVENT_PROCESS_START_FAILURE, + strEventMsg.QueryStr()); } - - if (m_hProcessWaitHandle != NULL) - { - UnregisterWait(m_hProcessWaitHandle); - m_hProcessWaitHandle = NULL; - } - - StopProcess(); - StopAllProcessesInJobObject(); } return hr; } @@ -1807,7 +1846,8 @@ SERVER_PROCESS::SERVER_PROCESS() : } } -SERVER_PROCESS::~SERVER_PROCESS() +VOID +SERVER_PROCESS::CleanUp() { if (m_hProcessWaitHandle != NULL) { @@ -1815,7 +1855,7 @@ SERVER_PROCESS::~SERVER_PROCESS() m_hProcessWaitHandle = NULL; } - for (INT i=0; iDereferenceForwarderConnection(); + m_pForwarderConnection = NULL; + } + +} + +SERVER_PROCESS::~SERVER_PROCESS() +{ + + CleanUp(); + + m_pEnvironmentVarTable = NULL; + // no need to free m_pEnvironmentVarTable, as it references to + // the same hash table hold by configuration. + // the hashtable memory will be freed once onfiguration got recycled + + if (m_pProcessManager != NULL) + { + m_pProcessManager->DereferenceProcessManager(); + m_pProcessManager = NULL; + } + if (m_hStdoutHandle != NULL) { if (m_hStdoutHandle != INVALID_HANDLE_VALUE) @@ -1883,34 +1958,6 @@ SERVER_PROCESS::~SERVER_PROCESS() DeleteFile(m_struFullLogFile.QueryStr()); } } - - if (m_hJobObject != NULL) - { - if (m_hJobObject != INVALID_HANDLE_VALUE) - { - CloseHandle(m_hJobObject); - } - m_hJobObject = NULL; - } - - if (m_pProcessManager != NULL) - { - m_pProcessManager->DereferenceProcessManager(); - m_pProcessManager = NULL; - } - - if (m_pForwarderConnection != NULL) - { - m_pForwarderConnection->DereferenceForwarderConnection(); - m_pForwarderConnection = NULL; - } - - m_pEnvironmentVarTable = NULL; - // no need to free m_pEnvironmentVarTable, as it references to - // the same hash table hold by configuration. - // the hashtable memory will be freed once onfiguration got recycled - -// InterlockedDecrement(&g_dwActiveServerProcesses); } //static diff --git a/src/RequestHandler/outofprocess/serverprocess.h b/src/RequestHandler/outofprocess/serverprocess.h index 04579fc372..e0998c160e 100644 --- a/src/RequestHandler/outofprocess/serverprocess.h +++ b/src/RequestHandler/outofprocess/serverprocess.h @@ -131,6 +131,8 @@ public: ); private: + VOID + CleanUp(); BOOL IsDebuggerIsAttached( @@ -279,4 +281,4 @@ private: PROCESS_MANAGER *m_pProcessManager; ENVIRONMENT_VAR_HASH *m_pEnvironmentVarTable ; -}; \ No newline at end of file +};