VOID
DumpEventHeader(
__in PEVENT_RECORD Event,
__in PTRACE_EVENT_INFO EventInfo,
__inout PPROCESSING_CONTEXT LogContext
)
/*++
Routine Description:
This routine dumps the metadata and the excecution parameters for the event.
Arguments:
Event - Supplies the event whose header will be dumped.
EventInfo - Supplies the information about the event whose header will be dumped.
LogContext - Supplies processing context for the event.
Return Value:
None.
--*/
{
ULONG Status = ERROR_SUCCESS;
PEVENT_HEADER Header = (PEVENT_HEADER)&Event->EventHeader;
LPGUID RelatedActivityID = NULL;
PEVENT_EXTENDED_ITEM_TS_ID SessionID = NULL;
PBYTE Sid = NULL;
PEVENT_EXTENDED_ITEM_INSTANCE Instance = NULL;
PULONG Stack32 = NULL;
PULONG64 Stack64 = NULL;
ULONG FrameCount = 0;
LPGUID Guid;
WCHAR GuidString[STRLEN_GUID];
WCHAR DateTimeString[STRLEN_UTC_DATETIME];
FILETIME FileTime;
ULONG GuidStringSize = STRLEN_GUID * sizeof(WCHAR);
ULONG DateTimeStringSize = STRLEN_UTC_DATETIME * sizeof(WCHAR);
USHORT Consumed;
ULONG DataLeft = ULONG_MAX;
for (ULONG i = 0; i < Event->ExtendedDataCount; i++) {
switch (Event->ExtendedData[i].ExtType) {
case EVENT_HEADER_EXT_TYPE_RELATED_ACTIVITYID:
RelatedActivityID = (LPGUID)(Event->ExtendedData[i].DataPtr);
break;
case EVENT_HEADER_EXT_TYPE_SID:
Sid = (PBYTE)(Event->ExtendedData[i].DataPtr);
break;
case EVENT_HEADER_EXT_TYPE_TS_ID:
SessionID = (PEVENT_EXTENDED_ITEM_TS_ID)(Event->ExtendedData[i].DataPtr);
break;
case EVENT_HEADER_EXT_TYPE_INSTANCE_INFO:
Instance = (PEVENT_EXTENDED_ITEM_INSTANCE)(Event->ExtendedData[i].DataPtr);
break;
case EVENT_HEADER_EXT_TYPE_STACK_TRACE32:
Stack32 = (PULONG)(Event->ExtendedData[i].DataPtr);
FrameCount = Event->ExtendedData[i].DataSize / 4;
break;
case EVENT_HEADER_EXT_TYPE_STACK_TRACE64:
Stack64 = (PULONG64)(Event->ExtendedData[i].DataPtr);
FrameCount = Event->ExtendedData[i].DataSize / 8;
break;
default:
break;
}
}
VPrintFToFile(FALSE, LogContext, L"\r\n\t<System>");
//
// Provider element: Name is not printed for Wbem events since it
// can be localized and, hence, belongs in the <RenderingInfo> element.
//
VPrintFToFile(FALSE, LogContext, L"\r\n\t\t<Provider");
if ((EventInfo != NULL) &&
(IS_WBEM_EVENT(EventInfo) == 0) &&
(TEI_PROVIDER_NAME(EventInfo) != NULL)) {
VPrintFToFile(FALSE, LogContext, L" Name=\"%s\"", TEI_PROVIDER_NAME(EventInfo));
}
Guid = &Event->EventHeader.ProviderId;
if (Event->EventHeader.Flags & EVENT_HEADER_FLAG_CLASSIC_HEADER) {
Guid = EventInfo ? &EventInfo->ProviderGuid : NULL;
}
if (Guid != NULL) {
Status = GuidToBuffer((PBYTE)Guid, DataLeft, (PBYTE)&GuidString, GuidStringSize, &Consumed);
if (Status == ERROR_SUCCESS) {
VPrintFToFile(FALSE, LogContext, L" Guid=\"%s", GuidString);
}
}
VPrintFToFile(FALSE, LogContext, L"\" />");
VPrintFToFile(FALSE,
LogContext,
L"\r\n\t\t<EventID>%u</EventID>"
L"\r\n\t\t<Version>%u</Version>"
L"\r\n\t\t<Level>%u</Level>"
L"\r\n\t\t<Task>%u</Task>"
L"\r\n\t\t<Opcode>%u</Opcode>"
L"\r\n\t\t<Keywords>0x%I64X</Keywords>",
Header->EventDescriptor.Id,
Header->EventDescriptor.Version,
Header->EventDescriptor.Level,
Header->EventDescriptor.Task,
Header->EventDescriptor.Opcode,
Header->EventDescriptor.Keyword);
Move64(&Header->TimeStamp, (PLARGE_INTEGER)&FileTime);
Status = FileTimeToBuffer((PBYTE)&FileTime, sizeof(FILETIME), (PBYTE)&DateTimeString[0], DateTimeStringSize, &Consumed);
if (Status == ERROR_SUCCESS) {
VPrintFToFile(FALSE, LogContext, L"\r\n\t\t<TimeCreated SystemTime=\"%s\" />", DateTimeString);
}
//
// ActivityId is in the event header.
// RelatedActivityID is the ExtendedData of the event.
//
VPrintFToFile(FALSE, LogContext, L"\r\n\t\t<Correlation ");
Status = GuidToBuffer((PBYTE)&Header->ActivityId, sizeof(GUID), (PBYTE)&GuidString, GuidStringSize, &Consumed);
if (Status == ERROR_SUCCESS) {
VPrintFToFile(FALSE, LogContext, L"ActivityID=\"%s\"", (PWSTR)GuidString);
}
if (RelatedActivityID != NULL) {
Status = GuidToBuffer((PBYTE)RelatedActivityID, sizeof(GUID), (PBYTE)&GuidString, ULONG_MAX, &Consumed);
if (Status == ERROR_SUCCESS) {
VPrintFToFile(FALSE, LogContext, L" RelatedActivityID=\"");
VPrintFToFile(FALSE, LogContext, L"%s\"", GuidString);
}
}
VPrintFToFile(FALSE, LogContext, L" />");
//
// Execution parameters
//
VPrintFToFile(FALSE,
LogContext,
L"\r\n\t\t<Execution"
L" ProcessID=\"%u\""
L" ThreadID=\"%u\""
L" ProcessorID=\"%u\" ",
Header->ProcessId,
Header->ThreadId,
Event->BufferContext.ProcessorNumber);
if (SessionID != NULL) {
VPrintFToFile(FALSE, LogContext, L" SessionID=\"%lu\"", SessionID->SessionId);
}
if (LogContext->IsPrivateLogger != FALSE) {
VPrintFToFile(FALSE, LogContext, L" KernelTime=\"%I64u\" />", Header->ProcessorTime);
} else {
VPrintFToFile(FALSE,
LogContext,
L" KernelTime=\"%lu\" UserTime=\"%lu\" />",
Header->KernelTime * LogContext->TimerResolution,
Header->UserTime * LogContext->TimerResolution);
}
//
// For simplicity, the eventual call stack is not dumped. The call stack
// structure can be either EVENT_EXTENDED_ITEM_STACK_TRACE32 or
// EVENT_EXTENDED_ITEM_STACK_TRACE64. These structures are pointed to by Stack32
// and Stack64 variables, respectively, depending on machine architecture.
//
VPrintFToFile(FALSE, LogContext, L"\r\n\t</System>");
}
static void WINAPI _HandleEvent(_In_ PEVENT_RECORD per)
{
if (!_s_fIsEnding)
{
PTRACE_EVENT_INFO ptei = nullptr;
// Populate ptei.
{
DWORD cbEventInfo = 0;
DWORD status = TdhGetEventInformation(per, 0, nullptr, nullptr, &cbEventInfo);
if (ERROR_INSUFFICIENT_BUFFER == status)
{
ptei = (TRACE_EVENT_INFO*)malloc(cbEventInfo);
if (ptei != nullptr)
{
status = TdhGetEventInformation(per, 0, nullptr, ptei, &cbEventInfo);
if (status != ERROR_SUCCESS)
{
free(ptei);
ptei = nullptr;
}
}
}
}
// Timestamp
{
FILETIME ft;
ft.dwHighDateTime = per->EventHeader.TimeStamp.HighPart;
ft.dwLowDateTime = per->EventHeader.TimeStamp.LowPart;
SYSTEMTIME st;
FileTimeToSystemTime(&ft, &st);
SystemTimeToTzSpecificLocalTime(nullptr, &st, &st);
wchar_t wszDate[100];
GetDateFormatEx(LOCALE_NAME_INVARIANT, NULL, &st, L"yyyyy-MM-dd", wszDate, ARRAYSIZE(wszDate), nullptr);
wchar_t wszTime[100];
GetTimeFormatEx(LOCALE_NAME_INVARIANT, NULL, &st, L"HH:mm:ss", wszTime, ARRAYSIZE(wszTime));
// yyyy-MM-dd HH:mm:ss:fffffff
// Windows refuses to give us milliseconds for free, let alone fractions of milliseconds
wprintf(L"%s ", wszDate);
wprintf(L"%s", wszTime);
wprintf(L".%07u, ", ft.dwLowDateTime % ((1000000000 /*nanoseconds per second*/) / (100 /* nanoseconds per interval */)));
}
// Thread ID
wprintf(L"Thread %lu, ", per->EventHeader.ThreadId);
// Provider name or GUID
{
const wchar_t* providerName = ptei ? TEI_PROVIDER_NAME(ptei) : nullptr;
if (providerName != nullptr)
{
wprintf(L"%s, ", (BYTE*)ptei + ptei->ProviderNameOffset);
}
else
{
BSTR bstrGuid;
if (SUCCEEDED(StringFromCLSID(per->EventHeader.ProviderId, &bstrGuid)))
{
wprintf(L"%s, ", bstrGuid);
::CoTaskMemFree(bstrGuid);
}
}
}
// Task name or id
{
const wchar_t* taskName = ptei ? TEI_TASK_NAME(ptei) : nullptr;
if (taskName != nullptr)
{
wprintf(L"%s, ", taskName);
}
else
{
// printf converts 8-bit chars to 16-bit ints, in case you don't know
wprintf(L"%hu, ", per->EventHeader.EventDescriptor.Task);
}
}
// Event ID
// wprintf(L"%hu, ", per->EventHeader.EventDescriptor.Id);
// Activity ID
//{
// BSTR bstrGuid;
// if (SUCCEEDED(StringFromCLSID(per->EventHeader.ActivityId, &bstrGuid)))
// {
// wprintf(L"%s, ", bstrGuid);
// ::CoTaskMemFree(bstrGuid);
// }
//}
// Opcode name or ID
{
wchar_t* opcodeName = ptei ? TEI_OPCODE_NAME(ptei) : nullptr;
if (opcodeName != nullptr)
{
wprintf(L"%s, ", (BYTE*)ptei + ptei->OpcodeNameOffset);
}
else
{
wprintf(L"%hu, ", per->EventHeader.EventDescriptor.Opcode);
}
}
// Payload
if (EVENT_HEADER_FLAG_STRING_ONLY == (per->EventHeader.Flags & EVENT_HEADER_FLAG_STRING_ONLY))
{
wprintf(L"%s", (LPWSTR)per->UserData);
}
else
{
for (USHORT i = 0; i < ptei->TopLevelPropertyCount; i++)
{
DWORD status = PrintProperties(per, ptei, i, nullptr, 0);
if (ERROR_SUCCESS != status)
{
wprintf(L"Printing top level properties failed.");
}
wprintf(L", ");
}
}
// endl
wprintf(L"\r\n");
// combat stdout buffering
_flushall();
if (ptei != nullptr)
{
free(ptei);
ptei = nullptr;
}
}
else
{
if (!_s_fIsClosed)
{
CloseTrace(*((TRACEHANDLE*)per->UserContext));
_s_fIsClosed = true;
}
}
}
