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

Add Trace level for request events, allow logging to eventlog (#1337)

This commit is contained in:
Pavel Krymets 2018-09-05 17:15:04 -07:00 committed by GitHub
parent 5956300df7
commit 88d8571474
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
14 changed files with 170 additions and 150 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
src/AspNetCoreModuleV2/AspNetCore/applicationinfo.cpp
View File

@ -98,7 +98,7 @@ APPLICATION_INFO::ShutDownApplication(bool fServerInitiated)
if (m_pApplication) if (m_pApplication)
{ {
LOG_ERRORF(L"Stopping application '%ls'", QueryApplicationInfoKey().c_str()); LOG_INFOF(L"Stopping application '%ls'", QueryApplicationInfoKey().c_str());
m_pApplication ->Stop(fServerInitiated); m_pApplication ->Stop(fServerInitiated);
m_pApplication = nullptr; m_pApplication = nullptr;
m_pApplicationFactory = nullptr; m_pApplicationFactory = nullptr;

65
src/AspNetCoreModuleV2/CommonLib/EventLog.cpp
View File

@ -4,10 +4,46 @@
#include <array> #include <array>
#include "EventLog.h" #include "EventLog.h"
#include "debugutil.h" #include "debugutil.h"
#include "StringHelpers.h" #include "exceptions.h"
extern HANDLE g_hEventLog; extern HANDLE g_hEventLog;
bool
EventLog::LogEventNoTrace(
_In_ WORD dwEventInfoType,
_In_ DWORD dwEventId,
_In_ LPCWSTR pstrMsg
)
{
if (g_hEventLog == nullptr)
{
return true;
}
// Static locals to avoid getting the process ID and string multiple times.
// Effectively have the same semantics as global variables, except initialized
// on first occurence.
static const auto processIdString = GetProcessIdString();
static const auto versionInfoString = GetVersionInfoString();
std::array<LPCWSTR, 3> eventLogDataStrings
{
pstrMsg,
processIdString.c_str(),
versionInfoString.c_str()
};
return ReportEventW(g_hEventLog,
dwEventInfoType,
0, // wCategory
dwEventId,
NULL, // lpUserSid
static_cast<WORD>(eventLogDataStrings.size()), // wNumStrings
0, // dwDataSize,
eventLogDataStrings.data(),
NULL // lpRawData
);
}
VOID VOID
EventLog::LogEvent( EventLog::LogEvent(
_In_ WORD dwEventInfoType, _In_ WORD dwEventInfoType,
@ -15,32 +51,7 @@ EventLog::LogEvent(
_In_ LPCWSTR pstrMsg _In_ LPCWSTR pstrMsg
) )
{ {
// Static locals to avoid getting the process ID and string multiple times. LOG_LAST_ERROR_IF(!LogEventNoTrace(dwEventInfoType, dwEventId, pstrMsg));
// Effectively have the same semantics as global variables, except initialized
// on first occurence.
static const auto processIdString = GetProcessIdString();
static const auto versionInfoString = GetVersionInfoString();
std::array<LPCWSTR, 3> eventLogDataStrings
{
pstrMsg,
processIdString.c_str(),
versionInfoString.c_str()
};
if (g_hEventLog != NULL)
{
ReportEventW(g_hEventLog,
dwEventInfoType,
0, // wCategory
dwEventId,
NULL, // lpUserSid
3, // wNumStrings
0, // dwDataSize,
eventLogDataStrings.data(),
NULL // lpRawData
);
}
DebugPrintfW(dwEventInfoType == EVENTLOG_ERROR_TYPE ? ASPNETCORE_DEBUG_FLAG_ERROR : ASPNETCORE_DEBUG_FLAG_INFO, L"Event Log: '%ls' \r\nEnd Event Log Message.", pstrMsg); DebugPrintfW(dwEventInfoType == EVENTLOG_ERROR_TYPE ? ASPNETCORE_DEBUG_FLAG_ERROR : ASPNETCORE_DEBUG_FLAG_INFO, L"Event Log: '%ls' \r\nEnd Event Log Message.", pstrMsg);
} }

7
src/AspNetCoreModuleV2/CommonLib/EventLog.h
View File

@ -59,6 +59,13 @@ public:
_va_end(args); _va_end(args);
} }
static
bool
LogEventNoTrace(
_In_ WORD dwEventInfoType,
_In_ DWORD dwEventId,
_In_ LPCWSTR pstrMsg);
private: private:
static static
VOID VOID

6
src/AspNetCoreModuleV2/CommonLib/aspnetcore_msg.mc
View File

@ -201,6 +201,12 @@ Language=English
%1 %1
. .
Messageid=1036
SymbolicName=ASPNETCORE_EVENT_DEBUG_LOG
Language=English
%1
.
; ;
;#endif // _ASPNETCORE_MODULE_MSG_H_ ;#endif // _ASPNETCORE_MODULE_MSG_H_

52
src/AspNetCoreModuleV2/CommonLib/debugutil.cpp
View File

@ -3,17 +3,19 @@
#include "debugutil.h" #include "debugutil.h"
#include <array>
#include <string> #include <string>
#include "dbgutil.h" #include "dbgutil.h"
#include "stringu.h" #include "stringu.h"
#include "stringa.h" #include "stringa.h"
#include "dbgutil.h"
#include "Environment.h" #include "Environment.h"
#include "SRWExclusiveLock.h" #include "SRWExclusiveLock.h"
#include "exceptions.h" #include "exceptions.h"
#include "atlbase.h" #include "atlbase.h"
#include "config_utility.h" #include "config_utility.h"
#include "StringHelpers.h" #include "StringHelpers.h"
#include "aspnetcore_msg.h"
#include "EventLog.h"
inline HANDLE g_logFile = INVALID_HANDLE_VALUE; inline HANDLE g_logFile = INVALID_HANDLE_VALUE;
inline HMODULE g_hModule; inline HMODULE g_hModule;
@ -23,7 +25,7 @@ HRESULT
PrintDebugHeader() PrintDebugHeader()
{ {
// Major, minor are stored in dwFileVersionMS field and patch, build in dwFileVersionLS field as pair of 32 bit numbers // Major, minor are stored in dwFileVersionMS field and patch, build in dwFileVersionLS field as pair of 32 bit numbers
DebugPrintfW(ASPNETCORE_DEBUG_FLAG_INFO, L"Initializing logs for '%ls'. %ls. %ls.", LOG_INFOF(L"Initializing logs for '%ls'. %ls. %ls.",
GetModuleName().c_str(), GetModuleName().c_str(),
GetProcessIdString().c_str(), GetProcessIdString().c_str(),
GetVersionInfoString().c_str() GetVersionInfoString().c_str()
@ -92,26 +94,6 @@ GetModuleName()
void SetDebugFlags(const std::wstring &debugValue) void SetDebugFlags(const std::wstring &debugValue)
{ {
try
{
if (!debugValue.empty() && debugValue.find_first_not_of(L"0123456789") == std::wstring::npos)
{
const auto value = std::stoi(debugValue);
if (value >= 1) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_ERROR;
if (value >= 2) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_WARNING;
if (value >= 3) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_INFO;
if (value >= 4) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_CONSOLE;
if (value >= 5) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_FILE;
return;
}
}
catch (...)
{
// ignore
}
try try
{ {
std::wstringstream stringStream(debugValue); std::wstringstream stringStream(debugValue);
@ -122,14 +104,16 @@ void SetDebugFlags(const std::wstring &debugValue)
if (_wcsnicmp(flag.c_str(), L"error", wcslen(L"error")) == 0) DEBUG_FLAGS_VAR |= DEBUG_FLAGS_ERROR; if (_wcsnicmp(flag.c_str(), L"error", wcslen(L"error")) == 0) DEBUG_FLAGS_VAR |= DEBUG_FLAGS_ERROR;
if (_wcsnicmp(flag.c_str(), L"warning", wcslen(L"warning")) == 0) DEBUG_FLAGS_VAR |= DEBUG_FLAGS_WARN; if (_wcsnicmp(flag.c_str(), L"warning", wcslen(L"warning")) == 0) DEBUG_FLAGS_VAR |= DEBUG_FLAGS_WARN;
if (_wcsnicmp(flag.c_str(), L"info", wcslen(L"info")) == 0) DEBUG_FLAGS_VAR |= DEBUG_FLAGS_INFO; if (_wcsnicmp(flag.c_str(), L"info", wcslen(L"info")) == 0) DEBUG_FLAGS_VAR |= DEBUG_FLAGS_INFO;
if (_wcsnicmp(flag.c_str(), L"trace", wcslen(L"trace")) == 0) DEBUG_FLAGS_VAR |= DEBUG_FLAGS_TRACE;
if (_wcsnicmp(flag.c_str(), L"console", wcslen(L"console")) == 0) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_CONSOLE; if (_wcsnicmp(flag.c_str(), L"console", wcslen(L"console")) == 0) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_CONSOLE;
if (_wcsnicmp(flag.c_str(), L"file", wcslen(L"file")) == 0) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_FILE; if (_wcsnicmp(flag.c_str(), L"file", wcslen(L"file")) == 0) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_FILE;
if (_wcsnicmp(flag.c_str(), L"eventlog", wcslen(L"eventlog")) == 0) DEBUG_FLAGS_VAR |= ASPNETCORE_DEBUG_FLAG_EVENTLOG;
} }
// If file or console is enabled but level is not set, enable all levels // If file or console is enabled but level is not set, enable levels up to info
if (DEBUG_FLAGS_VAR != 0 && (DEBUG_FLAGS_VAR & DEBUG_FLAGS_ANY) == 0) if (DEBUG_FLAGS_VAR != 0 && (DEBUG_FLAGS_VAR & DEBUG_FLAGS_ANY) == 0)
{ {
DEBUG_FLAGS_VAR |= DEBUG_FLAGS_ANY; DEBUG_FLAGS_VAR |= DEBUG_FLAGS_INFO;
} }
} }
catch (...) catch (...)
@ -209,7 +193,7 @@ DebugInitialize(HMODULE hModule)
try try
{ {
SetDebugFlags(Environment::GetEnvironmentVariableValue(L"ASPNETCORE_MODULE_DEBUG").value_or(L"0")); SetDebugFlags(Environment::GetEnvironmentVariableValue(L"ASPNETCORE_MODULE_DEBUG").value_or(L""));
} }
catch (...) catch (...)
{ {
@ -344,6 +328,24 @@ DebugPrintW(
FlushFileBuffers(g_logFile); FlushFileBuffers(g_logFile);
} }
} }
if (IsEnabled(ASPNETCORE_DEBUG_FLAG_EVENTLOG))
{
WORD eventType;
switch (dwFlag)
{
case ASPNETCORE_DEBUG_FLAG_ERROR:
eventType = EVENTLOG_ERROR_TYPE;
break;
case ASPNETCORE_DEBUG_FLAG_WARNING:
eventType = EVENTLOG_WARNING_TYPE;
break;
default:
eventType = EVENTLOG_INFORMATION_TYPE;
break;
}
EventLog::LogEventNoTrace(eventType, ASPNETCORE_EVENT_DEBUG_LOG, strOutput.QueryStr());
}
} }
} }

9
src/AspNetCoreModuleV2/CommonLib/debugutil.h
View File

@ -8,11 +8,16 @@
#include <Windows.h> #include <Windows.h>
#include "dbgutil.h" #include "dbgutil.h"
#define ASPNETCORE_DEBUG_FLAG_TRACE DEBUG_FLAG_TRACE
#define ASPNETCORE_DEBUG_FLAG_INFO DEBUG_FLAG_INFO #define ASPNETCORE_DEBUG_FLAG_INFO DEBUG_FLAG_INFO
#define ASPNETCORE_DEBUG_FLAG_WARNING DEBUG_FLAG_WARN #define ASPNETCORE_DEBUG_FLAG_WARNING DEBUG_FLAG_WARN
#define ASPNETCORE_DEBUG_FLAG_ERROR DEBUG_FLAG_ERROR #define ASPNETCORE_DEBUG_FLAG_ERROR DEBUG_FLAG_ERROR
#define ASPNETCORE_DEBUG_FLAG_CONSOLE 0x00000008 #define ASPNETCORE_DEBUG_FLAG_CONSOLE 0x00000010
#define ASPNETCORE_DEBUG_FLAG_FILE 0x00000010 #define ASPNETCORE_DEBUG_FLAG_FILE 0x00000020
#define ASPNETCORE_DEBUG_FLAG_EVENTLOG 0x00000040
#define LOG_TRACE(...) DebugPrintW(ASPNETCORE_DEBUG_FLAG_TRACE, __VA_ARGS__)
#define LOG_TRACEF(...) DebugPrintfW(ASPNETCORE_DEBUG_FLAG_TRACE, __VA_ARGS__)
#define LOG_INFO(...) DebugPrintW(ASPNETCORE_DEBUG_FLAG_INFO, __VA_ARGS__) #define LOG_INFO(...) DebugPrintW(ASPNETCORE_DEBUG_FLAG_INFO, __VA_ARGS__)
#define LOG_INFOF(...) DebugPrintfW(ASPNETCORE_DEBUG_FLAG_INFO, __VA_ARGS__) #define LOG_INFOF(...) DebugPrintfW(ASPNETCORE_DEBUG_FLAG_INFO, __VA_ARGS__)

10
src/AspNetCoreModuleV2/IISLib/dbgutil.h
View File

@ -21,19 +21,21 @@
// Debug error levels for DEBUG_FLAGS_VAR. // Debug error levels for DEBUG_FLAGS_VAR.
// //
#define DEBUG_FLAG_INFO 0x00000001 #define DEBUG_FLAG_TRACE 0x00000001
#define DEBUG_FLAG_WARN 0x00000002 #define DEBUG_FLAG_INFO 0x00000002
#define DEBUG_FLAG_ERROR 0x00000004 #define DEBUG_FLAG_WARN 0x00000004
#define DEBUG_FLAG_ERROR 0x00000008
// //
// Predefined error level values. These are backwards from the // Predefined error level values. These are backwards from the
// windows definitions. // windows definitions.
// //
#define DEBUG_FLAGS_TRACE (DEBUG_FLAG_ERROR | DEBUG_FLAG_WARN | DEBUG_FLAG_INFO | DEBUG_FLAG_TRACE)
#define DEBUG_FLAGS_INFO (DEBUG_FLAG_ERROR | DEBUG_FLAG_WARN | DEBUG_FLAG_INFO) #define DEBUG_FLAGS_INFO (DEBUG_FLAG_ERROR | DEBUG_FLAG_WARN | DEBUG_FLAG_INFO)
#define DEBUG_FLAGS_WARN (DEBUG_FLAG_ERROR | DEBUG_FLAG_WARN) #define DEBUG_FLAGS_WARN (DEBUG_FLAG_ERROR | DEBUG_FLAG_WARN)
#define DEBUG_FLAGS_ERROR (DEBUG_FLAG_ERROR) #define DEBUG_FLAGS_ERROR (DEBUG_FLAG_ERROR)
#define DEBUG_FLAGS_ANY (DEBUG_FLAG_INFO | DEBUG_FLAG_WARN | DEBUG_FLAG_ERROR) #define DEBUG_FLAGS_ANY (DEBUG_FLAG_INFO | DEBUG_FLAG_WARN | DEBUG_FLAG_ERROR | DEBUG_FLAG_TRACE)
// //
// Global variables to control tracing. Generally per module // Global variables to control tracing. Generally per module

6
src/AspNetCoreModuleV2/OutOfProcessRequestHandler/dllmain.cpp
View File

@ -115,7 +115,7 @@ Finished:
// Global initialization routine for OutOfProcess // Global initialization routine for OutOfProcess
// //
HRESULT HRESULT
EnsureOutOfProcessInitializtion() EnsureOutOfProcessInitializtion(IHttpApplication *pHttpApplication)
{ {
DBG_ASSERT(g_pHttpServer); DBG_ASSERT(g_pHttpServer);
@ -202,6 +202,8 @@ EnsureOutOfProcessInitializtion()
FINISHED_IF_FAILED(ALLOC_CACHE_HANDLER::StaticInitialize()); FINISHED_IF_FAILED(ALLOC_CACHE_HANDLER::StaticInitialize());
FINISHED_IF_FAILED(FORWARDING_HANDLER::StaticInitialize(g_fEnableReferenceCountTracing)); FINISHED_IF_FAILED(FORWARDING_HANDLER::StaticInitialize(g_fEnableReferenceCountTracing));
FINISHED_IF_FAILED(WEBSOCKET_HANDLER::StaticInitialize(g_fEnableReferenceCountTracing)); FINISHED_IF_FAILED(WEBSOCKET_HANDLER::StaticInitialize(g_fEnableReferenceCountTracing));
DebugInitializeFromConfig(*g_pHttpServer, *pHttpApplication);
} }
Finished: Finished:
if (FAILED(hr)) if (FAILED(hr))
@ -255,7 +257,7 @@ CreateApplication(
RETURN_IF_FAILED(REQUESTHANDLER_CONFIG::CreateRequestHandlerConfig(pServer, pHttpApplication, &pConfig)); RETURN_IF_FAILED(REQUESTHANDLER_CONFIG::CreateRequestHandlerConfig(pServer, pHttpApplication, &pConfig));
std::unique_ptr<REQUESTHANDLER_CONFIG> pRequestHandlerConfig(pConfig); std::unique_ptr<REQUESTHANDLER_CONFIG> pRequestHandlerConfig(pConfig);
RETURN_IF_FAILED(EnsureOutOfProcessInitializtion()); RETURN_IF_FAILED(EnsureOutOfProcessInitializtion(pHttpApplication));
std::unique_ptr<OUT_OF_PROCESS_APPLICATION> pApplication = std::make_unique<OUT_OF_PROCESS_APPLICATION>(*pHttpApplication, std::move(pRequestHandlerConfig)); std::unique_ptr<OUT_OF_PROCESS_APPLICATION> pApplication = std::make_unique<OUT_OF_PROCESS_APPLICATION>(*pHttpApplication, std::move(pRequestHandlerConfig));

40
src/AspNetCoreModuleV2/OutOfProcessRequestHandler/forwardinghandler.cpp
View File

@ -48,10 +48,7 @@ FORWARDING_HANDLER::FORWARDING_HANDLER(
m_pW3Context(pW3Context), m_pW3Context(pW3Context),
m_pApplication(pApplication) m_pApplication(pApplication)
{ {
#ifdef DEBUG LOG_TRACE(L"FORWARDING_HANDLER::FORWARDING_HANDLER");
DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO,
"FORWARDING_HANDLER::FORWARDING_HANDLER");
#endif
m_fWebSocketSupported = m_pApplication->QueryWebsocketStatus(); m_fWebSocketSupported = m_pApplication->QueryWebsocketStatus();
InitializeSRWLock(&m_RequestLock); InitializeSRWLock(&m_RequestLock);
@ -65,10 +62,8 @@ FORWARDING_HANDLER::~FORWARDING_HANDLER(
// //
m_Signature = FORWARDING_HANDLER_SIGNATURE_FREE; m_Signature = FORWARDING_HANDLER_SIGNATURE_FREE;
#ifdef DEBUG LOG_TRACE(L"FORWARDING_HANDLER::~FORWARDING_HANDLER");
DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO,
"FORWARDING_HANDLER::~FORWARDING_HANDLER");
#endif
// //
// RemoveRequest() should already have been called and m_pDisconnect // RemoveRequest() should already have been called and m_pDisconnect
// has been freed or m_pDisconnect was never initialized. // has been freed or m_pDisconnect was never initialized.
@ -309,10 +304,9 @@ FORWARDING_HANDLER::OnExecuteRequestHandler()
reinterpret_cast<DWORD_PTR>(static_cast<PVOID>(this)))) reinterpret_cast<DWORD_PTR>(static_cast<PVOID>(this))))
{ {
hr = HRESULT_FROM_WIN32(GetLastError()); hr = HRESULT_FROM_WIN32(GetLastError());
#ifdef DEBUG
DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, LOG_TRACE(L"FORWARDING_HANDLER::OnExecuteRequestHandler, Send request failed");
"FORWARDING_HANDLER::OnExecuteRequestHandler, Send request failed");
#endif
// FREB log // FREB log
if (ANCMEvents::ANCM_REQUEST_FORWARD_FAIL::IsEnabled(m_pW3Context->GetTraceContext())) if (ANCMEvents::ANCM_REQUEST_FORWARD_FAIL::IsEnabled(m_pW3Context->GetTraceContext()))
{ {
@ -460,10 +454,8 @@ REQUEST_NOTIFICATION_STATUS
if (m_RequestStatus == FORWARDER_RECEIVED_WEBSOCKET_RESPONSE) if (m_RequestStatus == FORWARDER_RECEIVED_WEBSOCKET_RESPONSE)
{ {
#ifdef DEBUG LOG_TRACE(L"FORWARDING_HANDLER::OnAsyncCompletion, Send completed for 101 response");
DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO,
"FORWARDING_HANDLER::OnAsyncCompletion, Send completed for 101 response");
#endif
// //
// This should be the write completion of the 101 response. // This should be the write completion of the 101 response.
// //
@ -696,10 +688,7 @@ Finished:
// //
// Do not use this object after dereferencing it, it may be gone. // Do not use this object after dereferencing it, it may be gone.
// //
#ifdef DEBUG LOG_TRACEF(L"FORWARDING_HANDLER::OnAsyncCompletion Done %d", retVal);
DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO,
"FORWARDING_HANDLER::OnAsyncCompletion Done %d", retVal);
#endif
return retVal; return retVal;
} }
@ -1336,10 +1325,8 @@ None
dwInternetStatus); dwInternetStatus);
} }
#ifdef DEBUG LOG_TRACEF(L"FORWARDING_HANDLER::OnWinHttpCompletionInternal %x -- %d --%p\n", dwInternetStatus, GetCurrentThreadId(), m_pW3Context);
DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO,
"FORWARDING_HANDLER::OnWinHttpCompletionInternal %x -- %d --%p\n", dwInternetStatus, GetCurrentThreadId(), m_pW3Context);
#endif
// //
// Exclusive lock on the winhttp handle to protect from a client disconnect/ // Exclusive lock on the winhttp handle to protect from a client disconnect/
// server stop closing the handle while we are using it. // server stop closing the handle while we are using it.
@ -2751,10 +2738,7 @@ FORWARDING_HANDLER::TerminateRequest(
// a winhttp callback on the same thread and we donot want to // a winhttp callback on the same thread and we donot want to
// acquire the lock again // acquire the lock again
#ifdef DEBUG LOG_TRACEF(L"FORWARDING_HANDLER::TerminateRequest %d --%p\n", GetCurrentThreadId(), m_pW3Context);
DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO,
"FORWARDING_HANDLER::TerminateRequest %d --%p\n", GetCurrentThreadId(), m_pW3Context);
#endif // DEBUG
if (!m_fHttpHandleInClose) if (!m_fHttpHandleInClose)
{ {

78
src/AspNetCoreModuleV2/OutOfProcessRequestHandler/websockethandler.cpp
View File

@ -47,7 +47,7 @@ WEBSOCKET_HANDLER::WEBSOCKET_HANDLER() :
_fHandleClosed(FALSE), _fHandleClosed(FALSE),
_fReceivedCloseMsg(FALSE) _fReceivedCloseMsg(FALSE)
{ {
DebugPrintf (ASPNETCORE_DEBUG_FLAG_INFO, "WEBSOCKET_HANDLER::WEBSOCKET_HANDLER"); LOG_TRACE(L"WEBSOCKET_HANDLER::WEBSOCKET_HANDLER");
InitializeCriticalSectionAndSpinCount(&_RequestLock, 1000); InitializeCriticalSectionAndSpinCount(&_RequestLock, 1000);
InsertRequest(); InsertRequest();
@ -58,7 +58,7 @@ WEBSOCKET_HANDLER::Terminate(
VOID VOID
) )
{ {
DebugPrintf (ASPNETCORE_DEBUG_FLAG_INFO, "WEBSOCKET_HANDLER::Terminate"); LOG_TRACE(L"WEBSOCKET_HANDLER::Terminate");
if (!_fHandleClosed) if (!_fHandleClosed)
{ {
RemoveRequest(); RemoveRequest();
@ -212,8 +212,7 @@ WEBSOCKET_HANDLER::IndicateCompletionToIIS(
--*/ --*/
{ {
DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, LOG_TRACEF(L"WEBSOCKET_HANDLER::IndicateCompletionToIIS called %d", _dwOutstandingIo);
"WEBSOCKET_HANDLER::IndicateCompletionToIIS called %d", _dwOutstandingIo);
// //
// close Websocket handle. This will triger a WinHttp callback // close Websocket handle. This will triger a WinHttp callback
@ -223,8 +222,7 @@ WEBSOCKET_HANDLER::IndicateCompletionToIIS(
// //
if (_hWebSocketRequest != NULL && _dwOutstandingIo == 0) if (_hWebSocketRequest != NULL && _dwOutstandingIo == 0)
{ {
DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, LOG_TRACE(L"WEBSOCKET_HANDLER::IndicateCompletionToIIS");
"WEBSOCKET_HANDLER::IndicateCompletionToIIS");
_pHandler->SetStatus(FORWARDER_DONE); _pHandler->SetStatus(FORWARDER_DONE);
_fHandleClosed = TRUE; _fHandleClosed = TRUE;
@ -262,8 +260,7 @@ Routine Description:
_pHandler = pHandler; _pHandler = pHandler;
EnterCriticalSection(&_RequestLock); EnterCriticalSection(&_RequestLock);
DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, LOG_TRACEF(L"WEBSOCKET_HANDLER::ProcessRequest");
"WEBSOCKET_HANDLER::ProcessRequest");
// //
// Cache the points to IHttpContext3 // Cache the points to IHttpContext3
@ -359,8 +356,7 @@ Finished:
if (FAILED_LOG(hr)) if (FAILED_LOG(hr))
{ {
DebugPrintf (ASPNETCORE_DEBUG_FLAG_ERROR, LOG_ERRORF(L"Process Request Failed with HR=%08x", hr);
"Process Request Failed with HR=%08x", hr);
} }
return hr; return hr;
@ -385,8 +381,7 @@ Routine Description:
BOOL fFinalFragment; BOOL fFinalFragment;
BOOL fClose; BOOL fClose;
DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, LOG_TRACE(L"WEBSOCKET_HANDLER::DoIisWebSocketReceive");
"WEBSOCKET_HANDLER::DoIisWebSocketReceive");
IncrementOutstandingIo(); IncrementOutstandingIo();
@ -403,8 +398,7 @@ Routine Description:
if (FAILED_LOG(hr)) if (FAILED_LOG(hr))
{ {
DecrementOutstandingIo(); DecrementOutstandingIo();
DebugPrintf(ASPNETCORE_DEBUG_FLAG_ERROR, LOG_ERRORF(L"WEBSOCKET_HANDLER::DoIisWebSocketSend failed with %08x", hr);
"WEBSOCKET_HANDLER::DoIisWebSocketSend failed with %08x", hr);
} }
return hr; return hr;
@ -426,8 +420,7 @@ Routine Description:
HRESULT hr = S_OK; HRESULT hr = S_OK;
DWORD dwError = NO_ERROR; DWORD dwError = NO_ERROR;
DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, LOG_TRACE(L"WEBSOCKET_HANDLER::DoWinHttpWebSocketReceive");
"WEBSOCKET_HANDLER::DoWinHttpWebSocketReceive");
IncrementOutstandingIo(); IncrementOutstandingIo();
@ -442,8 +435,7 @@ Routine Description:
{ {
DecrementOutstandingIo(); DecrementOutstandingIo();
hr = HRESULT_FROM_WIN32(dwError); hr = HRESULT_FROM_WIN32(dwError);
DebugPrintf(ASPNETCORE_DEBUG_FLAG_ERROR, LOG_ERRORF(L"WEBSOCKET_HANDLER::DoWinHttpWebSocketReceive failed with %08x", hr);
"WEBSOCKET_HANDLER::DoWinHttpWebSocketReceive failed with %08x", hr);
} }
return hr; return hr;
@ -467,8 +459,7 @@ Routine Description:
BOOL fFinalFragment = FALSE; BOOL fFinalFragment = FALSE;
BOOL fClose = FALSE; BOOL fClose = FALSE;
DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, LOG_TRACEF(L"WEBSOCKET_HANDLER::DoIisWebSocketSend %d", eBufferType);
"WEBSOCKET_HANDLER::DoIisWebSocketSend %d", eBufferType);
if (eBufferType == WINHTTP_WEB_SOCKET_CLOSE_BUFFER_TYPE) if (eBufferType == WINHTTP_WEB_SOCKET_CLOSE_BUFFER_TYPE)
{ {
@ -558,8 +549,7 @@ Routine Description:
Finished: Finished:
if (FAILED_LOG(hr)) if (FAILED_LOG(hr))
{ {
DebugPrintf(ASPNETCORE_DEBUG_FLAG_ERROR, LOG_ERRORF(L"WEBSOCKET_HANDLER::DoIisWebSocketSend failed with %08x", hr);
"WEBSOCKET_HANDLER::DoIisWebSocketSend failed with %08x", hr);
} }
return hr; return hr;
@ -581,8 +571,7 @@ Routine Description:
DWORD dwError = NO_ERROR; DWORD dwError = NO_ERROR;
HRESULT hr = S_OK; HRESULT hr = S_OK;
DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, LOG_TRACEF(L"WEBSOCKET_HANDLER::DoWinHttpWebSocketSend, %d", eBufferType);
"WEBSOCKET_HANDLER::DoWinHttpWebSocketSend, %d", eBufferType);
if (eBufferType == WINHTTP_WEB_SOCKET_CLOSE_BUFFER_TYPE) if (eBufferType == WINHTTP_WEB_SOCKET_CLOSE_BUFFER_TYPE)
{ {
@ -627,8 +616,7 @@ Routine Description:
// Call will complete asynchronously, return. // Call will complete asynchronously, return.
// ignore error. // ignore error.
// //
DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, LOG_TRACE(L"WEBSOCKET_HANDLER::DoWinhttpWebSocketSend IO_PENDING");
"WEBSOCKET_HANDLER::DoWinhttpWebSocketSend IO_PENDING");
dwError = NO_ERROR; dwError = NO_ERROR;
} }
@ -639,8 +627,7 @@ Routine Description:
// //
// Call completed synchronously. // Call completed synchronously.
// //
DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, LOG_TRACE(L"WEBSOCKET_HANDLER::DoWinhttpWebSocketSend Shutdown successful.");
"WEBSOCKET_HANDLER::DoWinhttpWebSocketSend Shutdown successful.");
} }
} }
} }
@ -666,8 +653,7 @@ Routine Description:
Finished: Finished:
if (FAILED_LOG(hr)) if (FAILED_LOG(hr))
{ {
DebugPrintf(ASPNETCORE_DEBUG_FLAG_ERROR, LOG_ERRORF(L"WEBSOCKET_HANDLER::DoWinHttpWebSocketSend failed with %08x", hr);
"WEBSOCKET_HANDLER::DoWinHttpWebSocketSend failed with %08x", hr);
} }
return hr; return hr;
@ -755,8 +741,7 @@ Routine Description:
BOOL fLocked = FALSE; BOOL fLocked = FALSE;
CleanupReason cleanupReason = CleanupReasonUnknown; CleanupReason cleanupReason = CleanupReasonUnknown;
DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, LOG_TRACE(L"WEBSOCKET_HANDLER::OnWinHttpSendComplete");
"WEBSOCKET_HANDLER::OnWinHttpSendComplete");
if (_fCleanupInProgress) if (_fCleanupInProgress)
{ {
@ -792,8 +777,7 @@ Finished:
{ {
Cleanup (cleanupReason); Cleanup (cleanupReason);
DebugPrintf (ASPNETCORE_DEBUG_FLAG_ERROR, LOG_ERRORF(L"WEBSOCKET_HANDLER::OnWinsockSendComplete failed with HR=%08x", hr);
"WEBSOCKET_HANDLER::OnWinsockSendComplete failed with HR=%08x", hr);
} }
// //
@ -810,8 +794,7 @@ WEBSOCKET_HANDLER::OnWinHttpShutdownComplete(
VOID VOID
) )
{ {
DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, LOG_TRACEF(L"WEBSOCKET_HANDLER::OnWinHttpShutdownComplete --%p", _pHandler);
"WEBSOCKET_HANDLER::OnWinHttpShutdownComplete --%p", _pHandler);
DecrementOutstandingIo(); DecrementOutstandingIo();
@ -825,8 +808,7 @@ WEBSOCKET_HANDLER::OnWinHttpIoError(
{ {
HRESULT hr = HRESULT_FROM_WIN32(pCompletionStatus->AsyncResult.dwError); HRESULT hr = HRESULT_FROM_WIN32(pCompletionStatus->AsyncResult.dwError);
DebugPrintf(ASPNETCORE_DEBUG_FLAG_ERROR, LOG_ERRORF(L"WEBSOCKET_HANDLER::OnWinHttpIoError HR = %08x, Operation = %d",
"WEBSOCKET_HANDLER::OnWinHttpIoError HR = %08x, Operation = %d",
hr, pCompletionStatus->AsyncResult.dwResult); hr, pCompletionStatus->AsyncResult.dwResult);
Cleanup(ServerDisconnect); Cleanup(ServerDisconnect);
@ -858,8 +840,7 @@ Routine Description:
BOOL fLocked = FALSE; BOOL fLocked = FALSE;
CleanupReason cleanupReason = CleanupReasonUnknown; CleanupReason cleanupReason = CleanupReasonUnknown;
DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, LOG_TRACEF(L"WEBSOCKET_HANDLER::OnWinHttpReceiveComplete --%p", _pHandler);
"WEBSOCKET_HANDLER::OnWinHttpReceiveComplete --%p", _pHandler);
if (_fCleanupInProgress) if (_fCleanupInProgress)
{ {
@ -893,8 +874,7 @@ Finished:
{ {
Cleanup (cleanupReason); Cleanup (cleanupReason);
DebugPrintf (ASPNETCORE_DEBUG_FLAG_ERROR, LOG_ERRORF(L"WEBSOCKET_HANDLER::OnWinsockReceiveComplete failed with HR=%08x", hr);
"WEBSOCKET_HANDLER::OnWinsockReceiveComplete failed with HR=%08x", hr);
} }
// //
@ -929,7 +909,7 @@ Routine Description:
UNREFERENCED_PARAMETER(cbIo); UNREFERENCED_PARAMETER(cbIo);
DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, "WEBSOCKET_HANDLER::OnIisSendComplete"); LOG_TRACE(L"WEBSOCKET_HANDLER::OnIisSendComplete");
if (FAILED_LOG(hrCompletion)) if (FAILED_LOG(hrCompletion))
{ {
@ -974,8 +954,7 @@ Finished:
{ {
Cleanup (cleanupReason); Cleanup (cleanupReason);
DebugPrintf (ASPNETCORE_DEBUG_FLAG_ERROR, LOG_ERRORF(L"WEBSOCKET_HANDLER::OnIisSendComplete failed with HR=%08x", hr);
"WEBSOCKET_HANDLER::OnIisSendComplete failed with HR=%08x", hr);
} }
// //
@ -1014,8 +993,7 @@ Routine Description:
CleanupReason cleanupReason = CleanupReasonUnknown; CleanupReason cleanupReason = CleanupReasonUnknown;
WINHTTP_WEB_SOCKET_BUFFER_TYPE BufferType; WINHTTP_WEB_SOCKET_BUFFER_TYPE BufferType;
DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, LOG_TRACE(L"WEBSOCKET_HANDLER::OnIisReceiveComplete");
"WEBSOCKET_HANDLER::OnIisReceiveComplete");
if (FAILED_LOG(hrCompletion)) if (FAILED_LOG(hrCompletion))
{ {
@ -1065,8 +1043,7 @@ Finished:
{ {
Cleanup (cleanupReason); Cleanup (cleanupReason);
DebugPrintf (ASPNETCORE_DEBUG_FLAG_ERROR, LOG_ERRORF(L"WEBSOCKET_HANDLER::OnIisReceiveComplete failed with HR=%08x", hr);
"WEBSOCKET_HANDLER::OnIisReceiveComplete failed with HR=%08x", hr);
} }
// //
@ -1097,8 +1074,7 @@ Arguments:
--*/ --*/
{ {
BOOL fLocked = FALSE; BOOL fLocked = FALSE;
DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, LOG_TRACEF(L"WEBSOCKET_HANDLER::Cleanup Initiated with reason %d", reason);
"WEBSOCKET_HANDLER::Cleanup Initiated with reason %d", reason);
if (_fCleanupInProgress) if (_fCleanupInProgress)
{ {

2
src/AspNetCoreModuleV2/RequestHandlerLib/requesthandler_config.cpp
View File

@ -55,8 +55,6 @@ REQUESTHANDLER_CONFIG::CreateRequestHandlerConfig(
goto Finished; goto Finished;
} }
DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO,
"REQUESTHANDLER_CONFIG::GetConfig, set config to ModuleContext");
// set appliction info here instead of inside Populate() // set appliction info here instead of inside Populate()
// as the destructor will delete the backend process // as the destructor will delete the backend process
hr = pRequestHandlerConfig->QueryApplicationPath()->Copy(pHttpApplication->GetApplicationId()); hr = pRequestHandlerConfig->QueryApplicationPath()->Copy(pHttpApplication->GetApplicationId());

2
src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeployer.cs
View File

@ -88,7 +88,7 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting.IIS
!IISDeploymentParameters.HandlerSettings.ContainsKey("debugFile")) !IISDeploymentParameters.HandlerSettings.ContainsKey("debugFile"))
{ {
_debugLogFile = Path.GetTempFileName(); _debugLogFile = Path.GetTempFileName();
IISDeploymentParameters.HandlerSettings["debugLevel"] = "4"; IISDeploymentParameters.HandlerSettings["debugLevel"] = "file";
IISDeploymentParameters.HandlerSettings["debugFile"] = _debugLogFile; IISDeploymentParameters.HandlerSettings["debugFile"] = _debugLogFile;
} }

2
src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeploymentParameterExtensions.cs
View File

@ -12,7 +12,7 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting.IIS
{ {
public static void AddDebugLogToWebConfig(this IISDeploymentParameters parameters, string filename) public static void AddDebugLogToWebConfig(this IISDeploymentParameters parameters, string filename)
{ {
parameters.HandlerSettings["debugLevel"] = "4"; parameters.HandlerSettings["debugLevel"] = "file";
parameters.HandlerSettings["debugFile"] = filename; parameters.HandlerSettings["debugFile"] = filename;
} }

39
test/Common.FunctionalTests/Inprocess/LoggingTests.cs
View File

@ -200,17 +200,44 @@ namespace Microsoft.AspNetCore.Server.IISIntegration.FunctionalTests
} }
} }
private static void AssertLogs(string logPath) [ConditionalFact]
public async Task DebugLogsAreWrittenToEventLog()
{
var deploymentParameters = _fixture.GetBaseDeploymentParameters(publish: true);
deploymentParameters.HandlerSettings["debugLevel"] = "file,eventlog";
var deploymentResult = await StartAsync(deploymentParameters);
StopServer();
EventLogHelpers.VerifyEventLogEvent(deploymentResult, @"\[aspnetcorev2.dll\] Initializing logs for .*?Description: IIS ASP.NET Core Module V2");
}
[ConditionalFact]
public async Task OutOfProcessReadsLogConfiguration()
{
var deploymentParameters = _fixture.GetBaseDeploymentParameters(hostingModel:HostingModel.OutOfProcess, publish: true);
deploymentParameters.HandlerSettings["debugLevel"] = "file,trace";
deploymentParameters.HandlerSettings["debugFile"] = "";
var deploymentResult = await StartAsync(deploymentParameters);
var logContents = ReadLogs(Path.Combine(deploymentResult.ContentRoot, "aspnetcore-debug.log"));
Assert.Contains("FORWARDING_HANDLER::", logContents);
}
private static string ReadLogs(string logPath)
{ {
using (var stream = File.Open(logPath, FileMode.Open, FileAccess.Read, FileShare.ReadWrite)) using (var stream = File.Open(logPath, FileMode.Open, FileAccess.Read, FileShare.ReadWrite))
using (var streamReader = new StreamReader(stream)) using (var streamReader = new StreamReader(stream))
{ {
var logContents = streamReader.ReadToEnd(); return streamReader.ReadToEnd();
Assert.Contains("[aspnetcorev2.dll]", logContents);
Assert.Contains("[aspnetcorev2_inprocess.dll]", logContents);
Assert.Contains("Description: IIS ASP.NET Core Module V2. Commit:", logContents);
Assert.Contains("Description: IIS ASP.NET Core Module V2 Request Handler. Commit:", logContents);
} }
} }
private static void AssertLogs(string logPath)
{
var logContents = ReadLogs(logPath);
Assert.Contains("[aspnetcorev2.dll]", logContents);
Assert.Contains("[aspnetcorev2_inprocess.dll]", logContents);
Assert.Contains("Description: IIS ASP.NET Core Module V2. Commit:", logContents);
Assert.Contains("Description: IIS ASP.NET Core Module V2 Request Handler. Commit:", logContents);
}
} }
} }