From 88d857147454cf739d43b2676cb8ff1dce23b1f2 Mon Sep 17 00:00:00 2001 From: Pavel Krymets Date: Wed, 5 Sep 2018 17:15:04 -0700 Subject: [PATCH] Add Trace level for request events, allow logging to eventlog (#1337) --- .../AspNetCore/applicationinfo.cpp | 2 +- src/AspNetCoreModuleV2/CommonLib/EventLog.cpp | 65 +++++++++------- src/AspNetCoreModuleV2/CommonLib/EventLog.h | 7 ++ .../CommonLib/aspnetcore_msg.mc | 6 ++ .../CommonLib/debugutil.cpp | 52 +++++++------ src/AspNetCoreModuleV2/CommonLib/debugutil.h | 9 ++- src/AspNetCoreModuleV2/IISLib/dbgutil.h | 10 ++- .../OutOfProcessRequestHandler/dllmain.cpp | 6 +- .../forwardinghandler.cpp | 40 +++------- .../websockethandler.cpp | 78 +++++++------------ .../requesthandler_config.cpp | 2 - .../IISDeployer.cs | 2 +- .../IISDeploymentParameterExtensions.cs | 2 +- .../Inprocess/LoggingTests.cs | 39 ++++++++-- 14 files changed, 170 insertions(+), 150 deletions(-) diff --git a/src/AspNetCoreModuleV2/AspNetCore/applicationinfo.cpp b/src/AspNetCoreModuleV2/AspNetCore/applicationinfo.cpp index fb558e52d0..225a82bdec 100644 --- a/src/AspNetCoreModuleV2/AspNetCore/applicationinfo.cpp +++ b/src/AspNetCoreModuleV2/AspNetCore/applicationinfo.cpp @@ -98,7 +98,7 @@ APPLICATION_INFO::ShutDownApplication(bool fServerInitiated) 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 = nullptr; m_pApplicationFactory = nullptr; diff --git a/src/AspNetCoreModuleV2/CommonLib/EventLog.cpp b/src/AspNetCoreModuleV2/CommonLib/EventLog.cpp index c3a3608820..e5ee8c1708 100644 --- a/src/AspNetCoreModuleV2/CommonLib/EventLog.cpp +++ b/src/AspNetCoreModuleV2/CommonLib/EventLog.cpp @@ -4,10 +4,46 @@ #include #include "EventLog.h" #include "debugutil.h" -#include "StringHelpers.h" +#include "exceptions.h" 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 eventLogDataStrings + { + pstrMsg, + processIdString.c_str(), + versionInfoString.c_str() + }; + + return ReportEventW(g_hEventLog, + dwEventInfoType, + 0, // wCategory + dwEventId, + NULL, // lpUserSid + static_cast(eventLogDataStrings.size()), // wNumStrings + 0, // dwDataSize, + eventLogDataStrings.data(), + NULL // lpRawData + ); +} + VOID EventLog::LogEvent( _In_ WORD dwEventInfoType, @@ -15,32 +51,7 @@ EventLog::LogEvent( _In_ LPCWSTR pstrMsg ) { - // 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 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 - ); - } + LOG_LAST_ERROR_IF(!LogEventNoTrace(dwEventInfoType, dwEventId, pstrMsg)); DebugPrintfW(dwEventInfoType == EVENTLOG_ERROR_TYPE ? ASPNETCORE_DEBUG_FLAG_ERROR : ASPNETCORE_DEBUG_FLAG_INFO, L"Event Log: '%ls' \r\nEnd Event Log Message.", pstrMsg); } diff --git a/src/AspNetCoreModuleV2/CommonLib/EventLog.h b/src/AspNetCoreModuleV2/CommonLib/EventLog.h index fa2cde1947..4bb72b623a 100644 --- a/src/AspNetCoreModuleV2/CommonLib/EventLog.h +++ b/src/AspNetCoreModuleV2/CommonLib/EventLog.h @@ -59,6 +59,13 @@ public: _va_end(args); } + static + bool + LogEventNoTrace( + _In_ WORD dwEventInfoType, + _In_ DWORD dwEventId, + _In_ LPCWSTR pstrMsg); + private: static VOID diff --git a/src/AspNetCoreModuleV2/CommonLib/aspnetcore_msg.mc b/src/AspNetCoreModuleV2/CommonLib/aspnetcore_msg.mc index 7289b85ce6..547192d0df 100644 --- a/src/AspNetCoreModuleV2/CommonLib/aspnetcore_msg.mc +++ b/src/AspNetCoreModuleV2/CommonLib/aspnetcore_msg.mc @@ -201,6 +201,12 @@ Language=English %1 . +Messageid=1036 +SymbolicName=ASPNETCORE_EVENT_DEBUG_LOG +Language=English +%1 +. + ; ;#endif // _ASPNETCORE_MODULE_MSG_H_ diff --git a/src/AspNetCoreModuleV2/CommonLib/debugutil.cpp b/src/AspNetCoreModuleV2/CommonLib/debugutil.cpp index 964c411bf9..cbf48a3b20 100644 --- a/src/AspNetCoreModuleV2/CommonLib/debugutil.cpp +++ b/src/AspNetCoreModuleV2/CommonLib/debugutil.cpp @@ -3,17 +3,19 @@ #include "debugutil.h" +#include #include #include "dbgutil.h" #include "stringu.h" #include "stringa.h" -#include "dbgutil.h" #include "Environment.h" #include "SRWExclusiveLock.h" #include "exceptions.h" #include "atlbase.h" #include "config_utility.h" #include "StringHelpers.h" +#include "aspnetcore_msg.h" +#include "EventLog.h" inline HANDLE g_logFile = INVALID_HANDLE_VALUE; inline HMODULE g_hModule; @@ -23,7 +25,7 @@ HRESULT PrintDebugHeader() { // 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(), GetProcessIdString().c_str(), GetVersionInfoString().c_str() @@ -92,26 +94,6 @@ GetModuleName() 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 { 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"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"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"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) { - DEBUG_FLAGS_VAR |= DEBUG_FLAGS_ANY; + DEBUG_FLAGS_VAR |= DEBUG_FLAGS_INFO; } } catch (...) @@ -209,7 +193,7 @@ DebugInitialize(HMODULE hModule) try { - SetDebugFlags(Environment::GetEnvironmentVariableValue(L"ASPNETCORE_MODULE_DEBUG").value_or(L"0")); + SetDebugFlags(Environment::GetEnvironmentVariableValue(L"ASPNETCORE_MODULE_DEBUG").value_or(L"")); } catch (...) { @@ -344,6 +328,24 @@ DebugPrintW( 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()); + } } } diff --git a/src/AspNetCoreModuleV2/CommonLib/debugutil.h b/src/AspNetCoreModuleV2/CommonLib/debugutil.h index f8c7a9b7c9..24446dbd80 100644 --- a/src/AspNetCoreModuleV2/CommonLib/debugutil.h +++ b/src/AspNetCoreModuleV2/CommonLib/debugutil.h @@ -8,11 +8,16 @@ #include #include "dbgutil.h" +#define ASPNETCORE_DEBUG_FLAG_TRACE DEBUG_FLAG_TRACE #define ASPNETCORE_DEBUG_FLAG_INFO DEBUG_FLAG_INFO #define ASPNETCORE_DEBUG_FLAG_WARNING DEBUG_FLAG_WARN #define ASPNETCORE_DEBUG_FLAG_ERROR DEBUG_FLAG_ERROR -#define ASPNETCORE_DEBUG_FLAG_CONSOLE 0x00000008 -#define ASPNETCORE_DEBUG_FLAG_FILE 0x00000010 +#define ASPNETCORE_DEBUG_FLAG_CONSOLE 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_INFOF(...) DebugPrintfW(ASPNETCORE_DEBUG_FLAG_INFO, __VA_ARGS__) diff --git a/src/AspNetCoreModuleV2/IISLib/dbgutil.h b/src/AspNetCoreModuleV2/IISLib/dbgutil.h index 60365faad2..9b714e9bbf 100644 --- a/src/AspNetCoreModuleV2/IISLib/dbgutil.h +++ b/src/AspNetCoreModuleV2/IISLib/dbgutil.h @@ -21,19 +21,21 @@ // Debug error levels for DEBUG_FLAGS_VAR. // -#define DEBUG_FLAG_INFO 0x00000001 -#define DEBUG_FLAG_WARN 0x00000002 -#define DEBUG_FLAG_ERROR 0x00000004 +#define DEBUG_FLAG_TRACE 0x00000001 +#define DEBUG_FLAG_INFO 0x00000002 +#define DEBUG_FLAG_WARN 0x00000004 +#define DEBUG_FLAG_ERROR 0x00000008 // // Predefined error level values. These are backwards from the // 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_WARN (DEBUG_FLAG_ERROR | DEBUG_FLAG_WARN) #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 diff --git a/src/AspNetCoreModuleV2/OutOfProcessRequestHandler/dllmain.cpp b/src/AspNetCoreModuleV2/OutOfProcessRequestHandler/dllmain.cpp index 451221255b..b5f2014bf2 100644 --- a/src/AspNetCoreModuleV2/OutOfProcessRequestHandler/dllmain.cpp +++ b/src/AspNetCoreModuleV2/OutOfProcessRequestHandler/dllmain.cpp @@ -115,7 +115,7 @@ Finished: // Global initialization routine for OutOfProcess // HRESULT -EnsureOutOfProcessInitializtion() +EnsureOutOfProcessInitializtion(IHttpApplication *pHttpApplication) { DBG_ASSERT(g_pHttpServer); @@ -202,6 +202,8 @@ EnsureOutOfProcessInitializtion() FINISHED_IF_FAILED(ALLOC_CACHE_HANDLER::StaticInitialize()); FINISHED_IF_FAILED(FORWARDING_HANDLER::StaticInitialize(g_fEnableReferenceCountTracing)); FINISHED_IF_FAILED(WEBSOCKET_HANDLER::StaticInitialize(g_fEnableReferenceCountTracing)); + + DebugInitializeFromConfig(*g_pHttpServer, *pHttpApplication); } Finished: if (FAILED(hr)) @@ -255,7 +257,7 @@ CreateApplication( RETURN_IF_FAILED(REQUESTHANDLER_CONFIG::CreateRequestHandlerConfig(pServer, pHttpApplication, &pConfig)); std::unique_ptr pRequestHandlerConfig(pConfig); - RETURN_IF_FAILED(EnsureOutOfProcessInitializtion()); + RETURN_IF_FAILED(EnsureOutOfProcessInitializtion(pHttpApplication)); std::unique_ptr pApplication = std::make_unique(*pHttpApplication, std::move(pRequestHandlerConfig)); diff --git a/src/AspNetCoreModuleV2/OutOfProcessRequestHandler/forwardinghandler.cpp b/src/AspNetCoreModuleV2/OutOfProcessRequestHandler/forwardinghandler.cpp index 881c6393ad..b0fa1aa03f 100644 --- a/src/AspNetCoreModuleV2/OutOfProcessRequestHandler/forwardinghandler.cpp +++ b/src/AspNetCoreModuleV2/OutOfProcessRequestHandler/forwardinghandler.cpp @@ -48,10 +48,7 @@ FORWARDING_HANDLER::FORWARDING_HANDLER( m_pW3Context(pW3Context), m_pApplication(pApplication) { -#ifdef DEBUG - DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, - "FORWARDING_HANDLER::FORWARDING_HANDLER"); -#endif + LOG_TRACE(L"FORWARDING_HANDLER::FORWARDING_HANDLER"); m_fWebSocketSupported = m_pApplication->QueryWebsocketStatus(); InitializeSRWLock(&m_RequestLock); @@ -65,10 +62,8 @@ FORWARDING_HANDLER::~FORWARDING_HANDLER( // m_Signature = FORWARDING_HANDLER_SIGNATURE_FREE; -#ifdef DEBUG - DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, - "FORWARDING_HANDLER::~FORWARDING_HANDLER"); -#endif + LOG_TRACE(L"FORWARDING_HANDLER::~FORWARDING_HANDLER"); + // // RemoveRequest() should already have been called and m_pDisconnect // has been freed or m_pDisconnect was never initialized. @@ -309,10 +304,9 @@ FORWARDING_HANDLER::OnExecuteRequestHandler() reinterpret_cast(static_cast(this)))) { hr = HRESULT_FROM_WIN32(GetLastError()); -#ifdef DEBUG - DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, - "FORWARDING_HANDLER::OnExecuteRequestHandler, Send request failed"); -#endif + + LOG_TRACE(L"FORWARDING_HANDLER::OnExecuteRequestHandler, Send request failed"); + // FREB log if (ANCMEvents::ANCM_REQUEST_FORWARD_FAIL::IsEnabled(m_pW3Context->GetTraceContext())) { @@ -460,10 +454,8 @@ REQUEST_NOTIFICATION_STATUS if (m_RequestStatus == FORWARDER_RECEIVED_WEBSOCKET_RESPONSE) { -#ifdef DEBUG - DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, - "FORWARDING_HANDLER::OnAsyncCompletion, Send completed for 101 response"); -#endif + LOG_TRACE(L"FORWARDING_HANDLER::OnAsyncCompletion, Send completed for 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. // -#ifdef DEBUG - DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, - "FORWARDING_HANDLER::OnAsyncCompletion Done %d", retVal); -#endif + LOG_TRACEF(L"FORWARDING_HANDLER::OnAsyncCompletion Done %d", retVal); return retVal; } @@ -1336,10 +1325,8 @@ None dwInternetStatus); } -#ifdef DEBUG - DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, - "FORWARDING_HANDLER::OnWinHttpCompletionInternal %x -- %d --%p\n", dwInternetStatus, GetCurrentThreadId(), m_pW3Context); -#endif + LOG_TRACEF(L"FORWARDING_HANDLER::OnWinHttpCompletionInternal %x -- %d --%p\n", dwInternetStatus, GetCurrentThreadId(), m_pW3Context); + // // Exclusive lock on the winhttp handle to protect from a client disconnect/ // 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 // acquire the lock again -#ifdef DEBUG - DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, - "FORWARDING_HANDLER::TerminateRequest %d --%p\n", GetCurrentThreadId(), m_pW3Context); -#endif // DEBUG + LOG_TRACEF(L"FORWARDING_HANDLER::TerminateRequest %d --%p\n", GetCurrentThreadId(), m_pW3Context); if (!m_fHttpHandleInClose) { diff --git a/src/AspNetCoreModuleV2/OutOfProcessRequestHandler/websockethandler.cpp b/src/AspNetCoreModuleV2/OutOfProcessRequestHandler/websockethandler.cpp index 5eac6001e9..ecd97737fe 100644 --- a/src/AspNetCoreModuleV2/OutOfProcessRequestHandler/websockethandler.cpp +++ b/src/AspNetCoreModuleV2/OutOfProcessRequestHandler/websockethandler.cpp @@ -47,7 +47,7 @@ WEBSOCKET_HANDLER::WEBSOCKET_HANDLER() : _fHandleClosed(FALSE), _fReceivedCloseMsg(FALSE) { - DebugPrintf (ASPNETCORE_DEBUG_FLAG_INFO, "WEBSOCKET_HANDLER::WEBSOCKET_HANDLER"); + LOG_TRACE(L"WEBSOCKET_HANDLER::WEBSOCKET_HANDLER"); InitializeCriticalSectionAndSpinCount(&_RequestLock, 1000); InsertRequest(); @@ -58,7 +58,7 @@ WEBSOCKET_HANDLER::Terminate( VOID ) { - DebugPrintf (ASPNETCORE_DEBUG_FLAG_INFO, "WEBSOCKET_HANDLER::Terminate"); + LOG_TRACE(L"WEBSOCKET_HANDLER::Terminate"); if (!_fHandleClosed) { RemoveRequest(); @@ -212,8 +212,7 @@ WEBSOCKET_HANDLER::IndicateCompletionToIIS( --*/ { - DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, - "WEBSOCKET_HANDLER::IndicateCompletionToIIS called %d", _dwOutstandingIo); + LOG_TRACEF(L"WEBSOCKET_HANDLER::IndicateCompletionToIIS called %d", _dwOutstandingIo); // // close Websocket handle. This will triger a WinHttp callback @@ -223,8 +222,7 @@ WEBSOCKET_HANDLER::IndicateCompletionToIIS( // if (_hWebSocketRequest != NULL && _dwOutstandingIo == 0) { - DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, - "WEBSOCKET_HANDLER::IndicateCompletionToIIS"); + LOG_TRACE(L"WEBSOCKET_HANDLER::IndicateCompletionToIIS"); _pHandler->SetStatus(FORWARDER_DONE); _fHandleClosed = TRUE; @@ -262,8 +260,7 @@ Routine Description: _pHandler = pHandler; EnterCriticalSection(&_RequestLock); - DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, - "WEBSOCKET_HANDLER::ProcessRequest"); + LOG_TRACEF(L"WEBSOCKET_HANDLER::ProcessRequest"); // // Cache the points to IHttpContext3 @@ -359,8 +356,7 @@ Finished: if (FAILED_LOG(hr)) { - DebugPrintf (ASPNETCORE_DEBUG_FLAG_ERROR, - "Process Request Failed with HR=%08x", hr); + LOG_ERRORF(L"Process Request Failed with HR=%08x", hr); } return hr; @@ -385,8 +381,7 @@ Routine Description: BOOL fFinalFragment; BOOL fClose; - DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, - "WEBSOCKET_HANDLER::DoIisWebSocketReceive"); + LOG_TRACE(L"WEBSOCKET_HANDLER::DoIisWebSocketReceive"); IncrementOutstandingIo(); @@ -403,8 +398,7 @@ Routine Description: if (FAILED_LOG(hr)) { DecrementOutstandingIo(); - DebugPrintf(ASPNETCORE_DEBUG_FLAG_ERROR, - "WEBSOCKET_HANDLER::DoIisWebSocketSend failed with %08x", hr); + LOG_ERRORF(L"WEBSOCKET_HANDLER::DoIisWebSocketSend failed with %08x", hr); } return hr; @@ -426,8 +420,7 @@ Routine Description: HRESULT hr = S_OK; DWORD dwError = NO_ERROR; - DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, - "WEBSOCKET_HANDLER::DoWinHttpWebSocketReceive"); + LOG_TRACE(L"WEBSOCKET_HANDLER::DoWinHttpWebSocketReceive"); IncrementOutstandingIo(); @@ -442,8 +435,7 @@ Routine Description: { DecrementOutstandingIo(); hr = HRESULT_FROM_WIN32(dwError); - DebugPrintf(ASPNETCORE_DEBUG_FLAG_ERROR, - "WEBSOCKET_HANDLER::DoWinHttpWebSocketReceive failed with %08x", hr); + LOG_ERRORF(L"WEBSOCKET_HANDLER::DoWinHttpWebSocketReceive failed with %08x", hr); } return hr; @@ -467,8 +459,7 @@ Routine Description: BOOL fFinalFragment = FALSE; BOOL fClose = FALSE; - DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, - "WEBSOCKET_HANDLER::DoIisWebSocketSend %d", eBufferType); + LOG_TRACEF(L"WEBSOCKET_HANDLER::DoIisWebSocketSend %d", eBufferType); if (eBufferType == WINHTTP_WEB_SOCKET_CLOSE_BUFFER_TYPE) { @@ -558,8 +549,7 @@ Routine Description: Finished: if (FAILED_LOG(hr)) { - DebugPrintf(ASPNETCORE_DEBUG_FLAG_ERROR, - "WEBSOCKET_HANDLER::DoIisWebSocketSend failed with %08x", hr); + LOG_ERRORF(L"WEBSOCKET_HANDLER::DoIisWebSocketSend failed with %08x", hr); } return hr; @@ -581,8 +571,7 @@ Routine Description: DWORD dwError = NO_ERROR; HRESULT hr = S_OK; - DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, - "WEBSOCKET_HANDLER::DoWinHttpWebSocketSend, %d", eBufferType); + LOG_TRACEF(L"WEBSOCKET_HANDLER::DoWinHttpWebSocketSend, %d", eBufferType); if (eBufferType == WINHTTP_WEB_SOCKET_CLOSE_BUFFER_TYPE) { @@ -627,8 +616,7 @@ Routine Description: // Call will complete asynchronously, return. // ignore error. // - DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, - "WEBSOCKET_HANDLER::DoWinhttpWebSocketSend IO_PENDING"); + LOG_TRACE(L"WEBSOCKET_HANDLER::DoWinhttpWebSocketSend IO_PENDING"); dwError = NO_ERROR; } @@ -639,8 +627,7 @@ Routine Description: // // Call completed synchronously. // - DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, - "WEBSOCKET_HANDLER::DoWinhttpWebSocketSend Shutdown successful."); + LOG_TRACE(L"WEBSOCKET_HANDLER::DoWinhttpWebSocketSend Shutdown successful."); } } } @@ -666,8 +653,7 @@ Routine Description: Finished: if (FAILED_LOG(hr)) { - DebugPrintf(ASPNETCORE_DEBUG_FLAG_ERROR, - "WEBSOCKET_HANDLER::DoWinHttpWebSocketSend failed with %08x", hr); + LOG_ERRORF(L"WEBSOCKET_HANDLER::DoWinHttpWebSocketSend failed with %08x", hr); } return hr; @@ -755,8 +741,7 @@ Routine Description: BOOL fLocked = FALSE; CleanupReason cleanupReason = CleanupReasonUnknown; - DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, - "WEBSOCKET_HANDLER::OnWinHttpSendComplete"); + LOG_TRACE(L"WEBSOCKET_HANDLER::OnWinHttpSendComplete"); if (_fCleanupInProgress) { @@ -792,8 +777,7 @@ Finished: { Cleanup (cleanupReason); - DebugPrintf (ASPNETCORE_DEBUG_FLAG_ERROR, - "WEBSOCKET_HANDLER::OnWinsockSendComplete failed with HR=%08x", hr); + LOG_ERRORF(L"WEBSOCKET_HANDLER::OnWinsockSendComplete failed with HR=%08x", hr); } // @@ -810,8 +794,7 @@ WEBSOCKET_HANDLER::OnWinHttpShutdownComplete( VOID ) { - DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, - "WEBSOCKET_HANDLER::OnWinHttpShutdownComplete --%p", _pHandler); + LOG_TRACEF(L"WEBSOCKET_HANDLER::OnWinHttpShutdownComplete --%p", _pHandler); DecrementOutstandingIo(); @@ -825,8 +808,7 @@ WEBSOCKET_HANDLER::OnWinHttpIoError( { HRESULT hr = HRESULT_FROM_WIN32(pCompletionStatus->AsyncResult.dwError); - DebugPrintf(ASPNETCORE_DEBUG_FLAG_ERROR, - "WEBSOCKET_HANDLER::OnWinHttpIoError HR = %08x, Operation = %d", + LOG_ERRORF(L"WEBSOCKET_HANDLER::OnWinHttpIoError HR = %08x, Operation = %d", hr, pCompletionStatus->AsyncResult.dwResult); Cleanup(ServerDisconnect); @@ -858,8 +840,7 @@ Routine Description: BOOL fLocked = FALSE; CleanupReason cleanupReason = CleanupReasonUnknown; - DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, - "WEBSOCKET_HANDLER::OnWinHttpReceiveComplete --%p", _pHandler); + LOG_TRACEF(L"WEBSOCKET_HANDLER::OnWinHttpReceiveComplete --%p", _pHandler); if (_fCleanupInProgress) { @@ -893,8 +874,7 @@ Finished: { Cleanup (cleanupReason); - DebugPrintf (ASPNETCORE_DEBUG_FLAG_ERROR, - "WEBSOCKET_HANDLER::OnWinsockReceiveComplete failed with HR=%08x", hr); + LOG_ERRORF(L"WEBSOCKET_HANDLER::OnWinsockReceiveComplete failed with HR=%08x", hr); } // @@ -929,7 +909,7 @@ Routine Description: UNREFERENCED_PARAMETER(cbIo); - DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, "WEBSOCKET_HANDLER::OnIisSendComplete"); + LOG_TRACE(L"WEBSOCKET_HANDLER::OnIisSendComplete"); if (FAILED_LOG(hrCompletion)) { @@ -974,8 +954,7 @@ Finished: { Cleanup (cleanupReason); - DebugPrintf (ASPNETCORE_DEBUG_FLAG_ERROR, - "WEBSOCKET_HANDLER::OnIisSendComplete failed with HR=%08x", hr); + LOG_ERRORF(L"WEBSOCKET_HANDLER::OnIisSendComplete failed with HR=%08x", hr); } // @@ -1014,8 +993,7 @@ Routine Description: CleanupReason cleanupReason = CleanupReasonUnknown; WINHTTP_WEB_SOCKET_BUFFER_TYPE BufferType; - DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, - "WEBSOCKET_HANDLER::OnIisReceiveComplete"); + LOG_TRACE(L"WEBSOCKET_HANDLER::OnIisReceiveComplete"); if (FAILED_LOG(hrCompletion)) { @@ -1065,8 +1043,7 @@ Finished: { Cleanup (cleanupReason); - DebugPrintf (ASPNETCORE_DEBUG_FLAG_ERROR, - "WEBSOCKET_HANDLER::OnIisReceiveComplete failed with HR=%08x", hr); + LOG_ERRORF(L"WEBSOCKET_HANDLER::OnIisReceiveComplete failed with HR=%08x", hr); } // @@ -1097,8 +1074,7 @@ Arguments: --*/ { BOOL fLocked = FALSE; - DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, - "WEBSOCKET_HANDLER::Cleanup Initiated with reason %d", reason); + LOG_TRACEF(L"WEBSOCKET_HANDLER::Cleanup Initiated with reason %d", reason); if (_fCleanupInProgress) { diff --git a/src/AspNetCoreModuleV2/RequestHandlerLib/requesthandler_config.cpp b/src/AspNetCoreModuleV2/RequestHandlerLib/requesthandler_config.cpp index 0af41d0f1c..1a087d5c95 100644 --- a/src/AspNetCoreModuleV2/RequestHandlerLib/requesthandler_config.cpp +++ b/src/AspNetCoreModuleV2/RequestHandlerLib/requesthandler_config.cpp @@ -55,8 +55,6 @@ REQUESTHANDLER_CONFIG::CreateRequestHandlerConfig( goto Finished; } - DebugPrintf(ASPNETCORE_DEBUG_FLAG_INFO, - "REQUESTHANDLER_CONFIG::GetConfig, set config to ModuleContext"); // set appliction info here instead of inside Populate() // as the destructor will delete the backend process hr = pRequestHandlerConfig->QueryApplicationPath()->Copy(pHttpApplication->GetApplicationId()); diff --git a/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeployer.cs b/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeployer.cs index 814ca5e14b..0e6b1cc932 100644 --- a/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeployer.cs +++ b/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeployer.cs @@ -88,7 +88,7 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting.IIS !IISDeploymentParameters.HandlerSettings.ContainsKey("debugFile")) { _debugLogFile = Path.GetTempFileName(); - IISDeploymentParameters.HandlerSettings["debugLevel"] = "4"; + IISDeploymentParameters.HandlerSettings["debugLevel"] = "file"; IISDeploymentParameters.HandlerSettings["debugFile"] = _debugLogFile; } diff --git a/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeploymentParameterExtensions.cs b/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeploymentParameterExtensions.cs index 3cb2d40c3a..2d45f036a7 100644 --- a/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeploymentParameterExtensions.cs +++ b/src/Microsoft.AspNetCore.Server.IntegrationTesting.IIS/IISDeploymentParameterExtensions.cs @@ -12,7 +12,7 @@ namespace Microsoft.AspNetCore.Server.IntegrationTesting.IIS { public static void AddDebugLogToWebConfig(this IISDeploymentParameters parameters, string filename) { - parameters.HandlerSettings["debugLevel"] = "4"; + parameters.HandlerSettings["debugLevel"] = "file"; parameters.HandlerSettings["debugFile"] = filename; } diff --git a/test/Common.FunctionalTests/Inprocess/LoggingTests.cs b/test/Common.FunctionalTests/Inprocess/LoggingTests.cs index dd0ac8cf6c..e574d4f96f 100644 --- a/test/Common.FunctionalTests/Inprocess/LoggingTests.cs +++ b/test/Common.FunctionalTests/Inprocess/LoggingTests.cs @@ -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 streamReader = new StreamReader(stream)) { - var logContents = 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); + return streamReader.ReadToEnd(); } } + + 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); + } } }