huahaofeng
/
aspnetcore
1
0
Fork 0
Code Issues Pull Requests Projects Releases Wiki Activity

adding logging for outprocess start and application recycle (#573) 

adding logging for outprocess start and application recycle
This commit is contained in:
pan-wang 2018-02-21 10:58:34 -08:00 committed by GitHub
parent ff496ca580
commit e3d3b088ae
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
6 changed files with 203 additions and 123 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

20
src/AspNetCore/Src/applicationmanager.cxx
View File

@ -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

11
src/CommonLib/aspnetcore_msg.mc
View File

@ -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_

8
src/CommonLib/resources.h
View File

@ -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'."

4
src/RequestHandler/outofprocess/processmanager.cxx
View File

@ -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
{

279
src/RequestHandler/outofprocess/serverprocess.cxx
View File

@ -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; i<MAX_ACTIVE_CHILD_PROCESSES; ++i)
for (INT i = 0; i<MAX_ACTIVE_CHILD_PROCESSES; ++i)
{
if (m_hChildProcessWaitHandles[i] != NULL)
{
@ -1828,6 +1868,7 @@ SERVER_PROCESS::~SERVER_PROCESS()
{
if (m_hProcessHandle != INVALID_HANDLE_VALUE)
{
TerminateProcess(m_hProcessHandle, 1);
CloseHandle(m_hProcessHandle);
}
m_hProcessHandle = NULL;
@ -1842,12 +1883,13 @@ SERVER_PROCESS::~SERVER_PROCESS()
m_hListeningProcessHandle = NULL;
}
for (INT i=0; i<MAX_ACTIVE_CHILD_PROCESSES; ++i)
for (INT i = 0; i<MAX_ACTIVE_CHILD_PROCESSES; ++i)
{
if (m_hChildProcessHandles[i] != NULL)
{
if (m_hChildProcessHandles[i] != INVALID_HANDLE_VALUE)
{
TerminateProcess(m_hChildProcessHandles[i], 1);
CloseHandle(m_hChildProcessHandles[i]);
}
m_hChildProcessHandles[i] = NULL;
@ -1855,6 +1897,39 @@ SERVER_PROCESS::~SERVER_PROCESS()
}
}
if (m_hJobObject != NULL)
{
if (m_hJobObject != INVALID_HANDLE_VALUE)
{
CloseHandle(m_hJobObject);
}
m_hJobObject = NULL;
}
if (m_pForwarderConnection != NULL)
{
m_pForwarderConnection->DereferenceForwarderConnection();
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

4
src/RequestHandler/outofprocess/serverprocess.h
View File

@ -131,6 +131,8 @@ public:
);
private:
VOID
CleanUp();
BOOL
IsDebuggerIsAttached(
@ -279,4 +281,4 @@ private:
PROCESS_MANAGER *m_pProcessManager;
ENVIRONMENT_VAR_HASH *m_pEnvironmentVarTable ;
};
};