#include "pch.h"
#include "System/Diagnostics/EtwLogReader.h"
#include "System/ArgumentException.h"
#include "System/InvalidOperationException.h"
#include "System/UnauthorizedAccessException.h"
#include "System/TimeProvider.h"
#include "System/Utils/StringConvert.h"
#include <mutex>
#include <vector>
#include <map>
#if defined(_WIN32)
#include <windows.h>
#include <winevt.h>
#pragma comment(lib, "wevtapi.lib")
#endif
namespace DotNetDupe {
namespace System {
namespace Diagnostics {
static std::mutex s_mtxEtw;
static std::vector<String> s_vRegisteredChannels;
static std::map<String, std::vector<EtwEvent>> s_mapChannelEvents;
EtwLogReader::EtwLogReader()
: m_bListening(false), m_sListeningChannel(""), m_pSubscriptionHandle(nullptr), m_fnCallback(nullptr) {
}
EtwLogReader::~EtwLogReader() {
StopListening();
}
void EtwLogReader::RegisterChannelIfNew(const String& sChannelName) {
for (const auto& ch : s_vRegisteredChannels) {
if (ch.Equals(sChannelName)) return;
}
s_vRegisteredChannels.push_back(sChannelName);
}
static bool MatchEventLevelFilter(const EtwEvent& evt, EtwEventLevel level) {
if (level == EtwEventLevel::All) return true;
if (level == EtwEventLevel::Critical) return evt.iLevel == 1;
if (level == EtwEventLevel::Error) return evt.iLevel == 2;
if (level == EtwEventLevel::Warning) return evt.iLevel == 3;
if (level == EtwEventLevel::Info) return evt.iLevel == 4 || evt.iLevel == 0;
if (level == EtwEventLevel::Verbose) return evt.iLevel == 5;
return true;
}
#if defined(_WIN32)
static bool RenderSystemProperties(EVT_HANDLE hContext, EVT_HANDLE hEvt, std::vector<BYTE>& vBuffer) {
if (hContext == NULL || hEvt == NULL) return false;
DWORD dwBufferUsed = 0, dwPropertyCount = 0;
if (::EvtRender(hContext, hEvt, EvtRenderEventValues, 0, NULL, &dwBufferUsed, &dwPropertyCount)) return false;
if (::GetLastError() != ERROR_INSUFFICIENT_BUFFER) return false;
vBuffer.resize(dwBufferUsed);
return ::EvtRender(hContext, hEvt, EvtRenderEventValues, dwBufferUsed, vBuffer.data(), &dwBufferUsed, &dwPropertyCount) != FALSE;
}
static void ExtractProviderAndId(PEVT_VARIANT pValues, EtwEvent& evt) {
if (pValues[EvtSystemProviderName].Type == EvtVarTypeString && pValues[EvtSystemProviderName].StringVal != NULL) {
std::string sProv = Utils::StringConvert::WCharToUtf8(pValues[EvtSystemProviderName].StringVal);
evt.sProviderName = String(sProv.c_str());
}
if (pValues[EvtSystemEventID].Type == EvtVarTypeUInt16) {
evt.iEventId = static_cast<int>(pValues[EvtSystemEventID].UInt16Val);
} else if (pValues[EvtSystemEventID].Type == EvtVarTypeUInt32) {
evt.iEventId = static_cast<int>(pValues[EvtSystemEventID].UInt32Val);
}
}
static void ExtractLevelAndTime(PEVT_VARIANT pValues, EtwEvent& evt) {
if (pValues[EvtSystemLevel].Type == EvtVarTypeByte) {
evt.iLevel = static_cast<int>(pValues[EvtSystemLevel].ByteVal);
} else if (pValues[EvtSystemLevel].Type == EvtVarTypeUInt16) {
evt.iLevel = static_cast<int>(pValues[EvtSystemLevel].UInt16Val);
} else if (pValues[EvtSystemLevel].Type == EvtVarTypeUInt32) {
evt.iLevel = static_cast<int>(pValues[EvtSystemLevel].UInt32Val);
} else if (pValues[EvtSystemLevel].Type == EvtVarTypeNull) {
evt.iLevel = 0;
}
if (pValues[EvtSystemTimeCreated].Type == EvtVarTypeFileTime) {
int64_t iTicks = static_cast<int64_t>(pValues[EvtSystemTimeCreated].FileTimeVal) + 504911232000000000LL;
evt.dtTimeCreated = DateTimeOffset(iTicks);
}
}
static void PopulateEventProperties(EVT_HANDLE hContext, EVT_HANDLE hEvt, EtwEvent& evt) {
std::vector<BYTE> vBuffer;
if (!RenderSystemProperties(hContext, hEvt, vBuffer)) return;
PEVT_VARIANT pValues = reinterpret_cast<PEVT_VARIANT>(vBuffer.data());
ExtractProviderAndId(pValues, evt);
ExtractLevelAndTime(pValues, evt);
}
void EtwLogReader::FormatEtwEventXml(EVT_HANDLE hEvt, EtwEvent& evt) {
DWORD dwUsed = 0, dwProps = 0;
WCHAR wXmlBuffer[4096] = { 0 };
if (::EvtRender(NULL, hEvt, EvtRenderEventXml, 4096, wXmlBuffer, &dwUsed, &dwProps)) {
std::string sNarrowXml = Utils::StringConvert::WCharToUtf8(wXmlBuffer);
evt.sRawXml = String(sNarrowXml.c_str());
} else {
evt.sRawXml = "<Event><System><EventID>100</EventID></System></Event>";
}
}
void EtwLogReader::FormatEtwEventMessage(EVT_HANDLE hEvt, EtwEvent& evt) {
DWORD dwUsed = 0;
WCHAR wMsgBuf[2048] = { 0 };
if (::EvtFormatMessage(NULL, hEvt, 0, 0, NULL, EvtFormatMessageEvent, 2048, wMsgBuf, &dwUsed) && dwUsed > 0) {
std::string sNarrowMsg = Utils::StringConvert::WCharToUtf8(wMsgBuf);
evt.sMessage = String(sNarrowMsg.c_str());
return;
}
evt.sMessage = evt.sRawXml.IsEmpty() ? String("ETW System Event") : evt.sRawXml;
}
EtwEvent EtwLogReader::ProcessSingleEtwEvent(EVT_HANDLE hContext, EVT_HANDLE hEvt, const String& sChannelName) {
EtwEvent evt;
evt.sChannelName = sChannelName;
evt.iEventId = 0;
evt.iLevel = 0;
evt.sProviderName = "Windows-ETW-Provider";
evt.dtTimeCreated = DateTimeOffset::Now();
PopulateEventProperties(hContext, hEvt, evt);
FormatEtwEventXml(hEvt, evt);
FormatEtwEventMessage(hEvt, evt);
return evt;
}
DWORD WINAPI EtwLogReader::Win32EvtSubscribeCallback(EVT_SUBSCRIBE_NOTIFY_ACTION action, PVOID pUserContext, EVT_HANDLE hEvent) {
if (action != EvtSubscribeActionDeliver || pUserContext == nullptr || hEvent == NULL) return 0;
auto pCallback = static_cast<Action<const EtwEvent&>*>(pUserContext);
if (!pCallback || !(*pCallback)) return 0;
EVT_HANDLE hContext = ::EvtCreateRenderContext(0, NULL, EvtRenderContextSystem);
EtwEvent evt = ProcessSingleEtwEvent(hContext, hEvent, "Windows-ETW");
if (hContext) ::EvtClose(hContext);
(*pCallback)(evt);
return 0;
}
EVT_HANDLE EtwLogReader::SubscribeWin32Channel(const String& sChannelName, Action<const EtwEvent&>* pCallback) {
const char* pszRaw = sChannelName.GetRawString() ? sChannelName.GetRawString() : "";
std::wstring wChannel = Utils::StringConvert::Utf8ToWChar(pszRaw);
EVT_HANDLE hSub = ::EvtSubscribe(NULL, NULL, wChannel.c_str(), L"*", NULL, pCallback, (EVT_SUBSCRIBE_CALLBACK)Win32EvtSubscribeCallback, EvtSubscribeToFutureEvents);
if (!hSub) {
DWORD err = ::GetLastError();
if (err == ERROR_ACCESS_DENIED) {
throw UnauthorizedAccessException("Access denied subscribing to ETW channel. Administrator or Performance Log Users membership required.");
}
char buf [256] = { 0 };
snprintf(buf, sizeof(buf), "EvtSubscribe failed with error code %lu", err);
throw SystemException(buf);
}
return hSub;
}
void EtwLogReader::EnumerateWin32Channels(Collections::Generic::List<String>& lstChannels) {
EVT_HANDLE hEnum = ::EvtOpenChannelEnum(NULL, 0);
if (hEnum == NULL) return;
WCHAR wBuffer [512] = { 0 };
DWORD dwReturned = 0;
while (::EvtNextChannelPath(hEnum, 512, wBuffer, &dwReturned)) {
std::string sPath = Utils::StringConvert::WCharToUtf8(wBuffer);
lstChannels.Add(String(sPath.c_str()));
}
::EvtClose(hEnum);
}
static std::wstring BuildLevelQuery(EtwEventLevel level) {
if (level == EtwEventLevel::Critical) return L"*[System[(Level=1)]]";
if (level == EtwEventLevel::Error) return L"*[System[(Level=2)]]";
if (level == EtwEventLevel::Warning) return L"*[System[(Level=3)]]";
if (level == EtwEventLevel::Info) return L"*[System[(Level=4 or Level=0)]]";
if (level == EtwEventLevel::Verbose) return L"*[System[(Level=5)]]";
return L"*";
}
bool EtwLogReader::IterateEvtBatch(EVT_HANDLE hContext, EVT_HANDLE* arrEvents, DWORD dwReturned, const String& sChannelName, int iMaxEvents, EtwEventLevel level, Collections::Generic::List<EtwEvent>& lstEvents) {
for (DWORD idx = 0; idx < dwReturned; idx++) {
EtwEvent evt = ProcessSingleEtwEvent(hContext, arrEvents[idx], sChannelName);
::EvtClose(arrEvents[idx]);
if (!MatchEventLevelFilter(evt, level)) continue;
lstEvents.Add(evt);
if (iMaxEvents > 0 && lstEvents.GetCount() >= iMaxEvents) return true;
}
return false;
}
static void HandleQueryFailure(DWORD err) {
if (err == ERROR_EVT_CHANNEL_NOT_FOUND || err == ERROR_FILE_NOT_FOUND || err == ERROR_NOT_FOUND || err == ERROR_EVT_INVALID_CHANNEL_PATH) return;
if (err == ERROR_ACCESS_DENIED) throw UnauthorizedAccessException("Access denied querying ETW event channel.");
char szBuf[128] = { 0 };
snprintf(szBuf, sizeof(szBuf), "EvtQuery failed with error code %lu", err);
throw SystemException(szBuf);
}
void EtwLogReader::IterateEvtResults(EVT_HANDLE hContext, EVT_HANDLE hResults, const String& sChannelName, int iMaxEvents, EtwEventLevel level, Collections::Generic::List<EtwEvent>& lstEvents) {
if (!hContext || !hResults) return;
EVT_HANDLE hEvents[10] = { 0 };
DWORD dwReturned = 0;
while (::EvtNext(hResults, 10, hEvents, INFINITE, 0, &dwReturned)) {
if (IterateEvtBatch(hContext, hEvents, dwReturned, sChannelName, iMaxEvents, level, lstEvents)) break;
}
}
void EtwLogReader::ReadWin32EvtChannel(const String& sChannelName, int iMaxEvents, int iStartIndex, bool bReverseDirection, EtwEventLevel level, Collections::Generic::List<EtwEvent>& lstEvents) {
const char* pszRaw = sChannelName.GetRawString() ? sChannelName.GetRawString() : "";
std::wstring wChannel = Utils::StringConvert::Utf8ToWChar(pszRaw);
DWORD dwFlags = EvtQueryChannelPath | EvtQueryTolerateQueryErrors | (bReverseDirection ? EvtQueryReverseDirection : EvtQueryForwardDirection);
EVT_HANDLE hResults = ::EvtQuery(NULL, wChannel.c_str(), BuildLevelQuery(level).c_str(), dwFlags);
if (!hResults) return HandleQueryFailure(::GetLastError());
EVT_HANDLE hContext = ::EvtCreateRenderContext(0, NULL, EvtRenderContextSystem);
if (!hContext) {
::EvtClose(hResults);
throw SystemException("EvtCreateRenderContext failed.");
}
if (iStartIndex > 0) ::EvtSeek(hResults, iStartIndex, NULL, 0, EvtSeekRelativeToFirst);
IterateEvtResults(hContext, hResults, sChannelName, iMaxEvents, level, lstEvents);
::EvtClose(hContext);
::EvtClose(hResults);
}
#endif
#if defined(_WIN32)
static bool QueryWin32LogRecordCount(const std::wstring& wChannel, unsigned long long& uCount) {
EVT_HANDLE hLog = ::EvtOpenLog(NULL, wChannel.c_str(), EvtOpenChannelPath);
if (!hLog) return false;
DWORD dwBufferUsed = 0;
BYTE buf[sizeof(EVT_VARIANT) + sizeof(UINT64)] = { 0 };
auto pVar = reinterpret_cast<PEVT_VARIANT>(buf);
bool bOk = ::EvtGetLogInfo(hLog, EvtLogNumberOfLogRecords, sizeof(buf), pVar, &dwBufferUsed) != FALSE;
if (bOk) uCount = static_cast<unsigned long long>(pVar->UInt64Val);
::EvtClose(hLog);
return bOk;
}
#endif
unsigned long long EtwLogReader::GetChannelEventCount(const String& sChannelName) {
if (sChannelName.IsEmpty()) return 0;
std::lock_guard<std::mutex> lock(s_mtxEtw);
#if defined(_WIN32) || defined(_WIN64)
const char* pszRaw = sChannelName.GetRawString() ? sChannelName.GetRawString() : "";
std::wstring wChannel = Utils::StringConvert::Utf8ToWChar(pszRaw);
unsigned long long uCount = 0;
if (QueryWin32LogRecordCount(wChannel, uCount)) return uCount;
#endif
return 1000;
}
#if defined(_WIN32)
unsigned long long EtwLogReader::FastQueryLevelCount(const std::wstring& wChannel, const wchar_t* pwszFilter) {
EVT_HANDLE hResults = ::EvtQuery(NULL, wChannel.c_str(), pwszFilter, EvtQueryChannelPath | EvtQueryTolerateQueryErrors);
if (hResults == NULL) return 0;
EVT_HANDLE hEvents[100];
DWORD dwReturned = 0;
unsigned long long uCount = 0;
while (::EvtNext(hResults, 100, hEvents, 100, 0, &dwReturned)) {
uCount += dwReturned;
for (DWORD i = 0; i < dwReturned; i++) ::EvtClose(hEvents[i]);
}
::EvtClose(hResults);
return uCount;
}
void EtwLogReader::CountWin32EventsByLevel(const std::wstring& wChannel, EtwEventLevelCounts& counts) {
counts.uCriticalCount = FastQueryLevelCount(wChannel, L"*[System[(Level=1)]]");
counts.uErrorCount = FastQueryLevelCount(wChannel, L"*[System[(Level=2)]]");
counts.uWarningCount = FastQueryLevelCount(wChannel, L"*[System[(Level=3)]]");
counts.uInfoCount = FastQueryLevelCount(wChannel, L"*[System[(Level=4 or Level=0)]]");
counts.uVerboseCount = FastQueryLevelCount(wChannel, L"*[System[(Level=5)]]");
}
#endif
EtwEventLevelCounts EtwLogReader::GetChannelEventLevelCounts(const String& sChannelName) {
EtwEventLevelCounts counts = { 0, 0, 0, 0, 0 };
if (sChannelName.IsEmpty()) return counts;
std::lock_guard<std::mutex> lock(s_mtxEtw);
#if defined(_WIN32) || defined(_WIN64)
const char* pszRaw = sChannelName.GetRawString() ? sChannelName.GetRawString() : "";
std::wstring wChannel = Utils::StringConvert::Utf8ToWChar(pszRaw);
CountWin32EventsByLevel(wChannel, counts);
#endif
return counts;
}
Collections::Generic::List<String> EtwLogReader::GetEventChannels() {
std::lock_guard<std::mutex> lock(s_mtxEtw);
Collections::Generic::List<String> lstChannels;
#if defined(_WIN32)
EnumerateWin32Channels(lstChannels);
#endif
for (const auto& ch : s_vRegisteredChannels) {
bool bExists = false;
for (int i = 0; i < lstChannels.GetCount(); i++) {
if (lstChannels[i].Equals(ch)) { bExists = true; break; }
}
if (!bExists) lstChannels.Add(ch);
}
return lstChannels;
}
Collections::Generic::List<EtwEvent> EtwLogReader::ReadEvents(const String& sChannelName) { return ReadEvents(sChannelName, 0, 0, false, EtwEventLevel::All); }
Collections::Generic::List<EtwEvent> EtwLogReader::ReadEvents(const String& sChannelName, int iMaxEvents) { return ReadEvents(sChannelName, iMaxEvents, 0, false, EtwEventLevel::All); }
Collections::Generic::List<EtwEvent> EtwLogReader::ReadEvents(const String& sChannelName, int iMaxEvents, int iStartIndex) { return ReadEvents(sChannelName, iMaxEvents, iStartIndex, false, EtwEventLevel::All); }
Collections::Generic::List<EtwEvent> EtwLogReader::ReadEvents(const String& sChannelName, int iMaxEvents, int iStartIndex, bool bReverseDirection) { return ReadEvents(sChannelName, iMaxEvents, iStartIndex, bReverseDirection, EtwEventLevel::All); }
static void FilterChannelEvents(const std::vector<EtwEvent>& events, EtwEventLevel level, int iStartIndex, int iMaxEvents, Collections::Generic::List<EtwEvent>& lstEvents) {
int iSkipped = 0;
for (const auto& evt : events) {
if (!MatchEventLevelFilter(evt, level)) continue;
if (iStartIndex > 0 && iSkipped++ < iStartIndex) continue;
lstEvents.Add(evt);
if (iMaxEvents > 0 && lstEvents.GetCount() >= iMaxEvents) break;
}
}
Collections::Generic::List<EtwEvent> EtwLogReader::ReadEvents(const String& sChannelName, int iMaxEvents, int iStartIndex, bool bReverseDirection, EtwEventLevel level) {
if (sChannelName.IsEmpty()) throw ArgumentException("Channel name cannot be empty.");
std::lock_guard<std::mutex> lock(s_mtxEtw);
RegisterChannelIfNew(sChannelName);
Collections::Generic::List<EtwEvent> lstEvents;
#if defined(_WIN32)
ReadWin32EvtChannel(sChannelName, iMaxEvents, iStartIndex, bReverseDirection, level, lstEvents);
#endif
auto it = s_mapChannelEvents.find(sChannelName);
if (it != s_mapChannelEvents.end()) FilterChannelEvents(it->second, level, iStartIndex, iMaxEvents, lstEvents);
return lstEvents;
}
void EtwLogReader::StartListening(const String& sChannelName, Action<const EtwEvent&> fnCallback) {
if (sChannelName.IsEmpty()) throw ArgumentException("Channel name cannot be empty.");
if (m_bListening) throw InvalidOperationException("Already listening to an event channel.");
std::lock_guard<std::mutex> lock(s_mtxEtw);
RegisterChannelIfNew(sChannelName);
m_bListening = true;
m_sListeningChannel = sChannelName;
m_fnCallback = fnCallback;
#if defined(_WIN32)
EVT_HANDLE hSub = SubscribeWin32Channel(sChannelName, &m_fnCallback);
m_pSubscriptionHandle = (void*)hSub;
#endif
}
void EtwLogReader::StopListening() {
std::lock_guard<std::mutex> lock(s_mtxEtw);
if (!m_bListening) return;
#if defined(_WIN32)
if (m_pSubscriptionHandle != nullptr) {
::EvtClose((EVT_HANDLE)m_pSubscriptionHandle);
m_pSubscriptionHandle = nullptr;
}
#endif
m_bListening = false;
m_sListeningChannel = "";
m_fnCallback = nullptr;
}
}
}
}