Consume IIS ETW tracing
Event Tracing for Windows (ETW) is wonderful mechanism to monitor, log and trouble shoot of your application. IIS is an ETW provider to help us out to do those activities. In this blog, I want to share how to retrieve events which IIS writes, from 1) IIS module and 2) out-of-module.
Before start, we need to know how IIS module writes events; Generating trace information in native modules. This very neat blog explains how you raise event from native module and see the result from Failed Request Tracing Rules (FRED). And, we can retrieve or consume those events from other channel.
1. Inside IIS module
If you want to retrieve event from your module, it is easy. You can write the native module registering GL_TRACE_EVENT and implementing CGlobalModule::OnGlobalTraceEvent(). Then, you will obtain HTTP_TRACE_EVENT from IGlobalTraceEventProvider:: GetTraceEvent() when someone raises event. HTTP_TRACE_EVENT should look familiar to you if you read the blog how to generate trace information. It is the same struct we use to raise event. Yes, if you're inside module, you can get what you write in the same format. Convenient, isn't it?
GLOBAL_NOTIFICATION_STATUS TestModule::OnGlobalTraceEvent(
IN IGlobalTraceEventProvider* pProvider ) {
HTTP_TRACE_EVENT* pHttp_trace_event = NULL;
HRESULT hr = pProvider->GetTraceEvent(&pHttp_trace_event);
...
2. Outside IIS module
OK, let's switch gear to see whether we can consume those events out of IIS. Basically, you need ETW consumer to consume events IIS writes. In this context, IIS is ETW provider, and your application is ETW consumer, and also you need start ETW session. Sounds a bit more complex than the previous case, but you need basic understanding of wonderful ETW mechanism. For detail about ETW, you can refer to MSDN and read article; Improve Debugging And Performance Tuning With ETW.
Let us write a simple real time ETW consumer console application to see how it works.
First, we need to initialize EVENT_TRACE_LOGFILE to call OpenTrace() which returns TRACEHANDLE.
...
#define IIS_WWW_SERVER L"iis_www_server"
static const GUID TraceProviderGuid =
{0x3a2a4e84,0x4c21,0x4981,{0xae,0x10,0x3f,0xda,0x0d,0x9b,0x0f,0x83}};
static const GUID TraceAreaGuid =
{0x528dbd54,0x1b68,0x4f58,{0xa8,0xc0,0xb3,0x92,0xdf,0x6d,0xf0,0xc9}};
...
HRESULT hResult = S_OK;
DWORD dwResult = ERROR_SUCCESS;
EVENT_TRACE_LOGFILE evtLogFile;
::ZeroMemory( &evtLogFile, sizeof(EVENT_TRACE_LOGFILE) );
TRACEHANDLE hTrace = NULL;
// Initialize
evtLogFile.LogFileName = NULL;
// Set ETW session name to consume
evtLogFile.LoggerName = IIS_WWW_SERVER;
evtLogFile.CurrentTime = 0;
evtLogFile.BuffersRead = 0;
// real time mode and use EventRecordCallback
evtLogFile.ProcessTraceMode = PROCESS_TRACE_MODE_REAL_TIME | PROCESS_TRACE_MODE_EVENT_RECORD;
// register buffer callback
evtLogFile.BufferCallback = BuffCallback;
evtLogFile.BufferSize = 0;
evtLogFile.Filled = 0;
evtLogFile.EventsLost = 0;
// register record callback function
evtLogFile.EventRecordCallback = EvtRecCallback;
// set context will get in the callback function if needed
evtLogFile.Context = NULL;
// obtain trace handle
hTrace = ::OpenTrace( &evtLogFile );
if( hTrace == (TRACEHANDLE)INVALID_HANDLE_VALUE ) {
wprintf(L"FAIL: OpenTrace() [%x]\n", ::GetLastError() );
hResult = HRESULT_FROM_WIN32( ::GetLastError() );
hTrace = NULL;
goto Finished;
}
This code snippet shows how to call OpenTrace() with real time mode and register EventRecordCallback function. If call successful, it return TRACEHANDLE which is required to call ProcessTrace(). To consume real time events, we need to set a specific session name which is created by Reliability and Performance Monitor tool. To create and start an IIS event session, you can refer to another nice blog; How to display URL Rewrite ETW Events in the Event Viewer.
Once we get TRACEHANDLE, the next step is to call ProcessTrace().
// start consuming events
dwResult = ::ProcessTrace(
&hTrace,
1,
NULL,
NULL);
if( dwResult != ERROR_SUCCESS ) {
wprintf(L"FAIL: ProcessTrace() [%x]\n", ::GetLastError() );
hResult = HRESULT_FROM_WIN32( ::GetLastError() );
goto Finished;
}
ProcessTrace() blocks current execution and sits there until session ends or BufferCallback returns FALSE. In meanwhile, your registered event call back function is invoked whenever event is available in session buffer.
OK, let's take a look the event call back function which requires the following function signature;
VOID WINAPI EvtRecCallback(
__in PEVENT_RECORD pEvtRecord);
As you can see, the callback function get EVENT_RECORD as a parameter and optionally you can get UserContext if you set it on OpenTrace(). We do not set context in this example. Implementation of EventRecordCallback consumes trace event. Unlike OnGlobalTraceEvent(), we won't get what we write in the same format. In other words, we created and populated HTTP_TRACE_EVENT to raise event, but we do not get the same struct when retrieves. We need a bit work using Trace Data Helper API (TDH). Let's implement the callback.
First, we need obtain TRACE_EVENT_INFO from EVENT_RECORD using TdhGetEventInformation().
ULONG ulResult = ERROR_SUCCESS;
const DWORD BUF_SIZE = 1024;
DWORD dwBufferSize = sizeof(TRACE_EVENT_INFO) + BUF_SIZE;
BYTE pBuffer[sizeof(TRACE_EVENT_INFO) + BUF_SIZE];
::ZeroMemory( pBuffer, dwBufferSize);
PTRACE_EVENT_INFO pTraceEventInfo = NULL;
pTraceEventInfo = reinterpret_cast<PTRACE_EVENT_INFO>(pBuffer);
// obtain TRACE_EVENT_INFO
ulResult = ::TdhGetEventInformation(
pEvtRecord,
0,
NULL,
pTraceEventInfo,
&dwBufferSize);
if( ulResult != ERROR_SUCCESS ) { // ignore error handling, retry etc for simplicity
wprintf(L"FAIL: TdhGetEventInformation() [%x]\n", ulResult );
goto Finished;
}
Once we get TRACE_EVENT_INFO, optionally we can filter out events we're not interested. Without filtering, you may get huge list of events depending on how you set Keywords when creates a session. For this example, we can take events only which our provider and area produces.
// check GUID to see whether it is interesting event
fResult =
::IsEqualGUID(
TraceProviderGuid,
pTraceEventInfo->ProviderGuid) &&
::IsEqualGUID(
TraceAreaGuid,
pTraceEventInfo->EventGuid);
if( !fResult ) {
wprintf(L"SKIP: Not our event\n" );
goto Finished;
}
You can also obtain other information from TRACE_EVENT_INFO, such as Event ID, verbosity, etc.
Note that getting property information means getting event data we set into HTTP_TRACE_EVENT_ITEM. Now, it is time to retrieve event data.
LPWSTR pszPropertyName = NULL;
PEVENT_PROPERTY_INFO pEventPropertyInfo = NULL;
BYTE pPropertyBuffer[BUF_SIZE];
PROPERTY_DATA_DESCRIPTOR propertyDataDesc;
// iterate thru each event data(HTTP_TRACE_EVENT_ITEM) and retrieve data
for (DWORD index = 0; index < pTraceEventInfo->TopLevelPropertyCount; index++) {
pEventPropertyInfo = &pTraceEventInfo->EventPropertyInfoArray[index];
wprintf(L"\t--- EVENT_PROPERTY_INFO ---\n");
// HTTP_TRACE_EVENT_ITEM.pszName
pszPropertyName = (LPWSTR)((PBYTE)pTraceEventInfo + pEventPropertyInfo->NameOffset);
wprintf(L"\tPropertyName: %ws\n", pszPropertyName);
// HTTP_TRACE_EVENT_ITEM.cbData
wprintf(L"\tLength: %d\n", pEventPropertyInfo->length);
// HTTP_TRACE_EVENT_ITEM.dwDataType
wprintf(L"\tInType: %u\n", pEventPropertyInfo->nonStructType.InType);
::ZeroMemory( pPropertyBuffer, BUF_SIZE);
propertyDataDesc.PropertyName = reinterpret_cast<ULONGLONG>(pszPropertyName);
propertyDataDesc.ArrayIndex = ULONG_MAX;
// // HTTP_TRACE_EVENT_ITEM. pbData
ulResult = ::TdhGetProperty(
pEvtRecord,
0,
NULL,
1,
&propertyDataDesc,
BUF_SIZE,
pPropertyBuffer);
if( ulResult != ERROR_SUCCESS ) { // ignore error handling and retry etc for simplicity
wprintf(L"FAIL: TdhGetProperty() [%x]\n", ulResult );
continue;
}
// now do whatever you want with pPropertyBuffer
// pEventPropertyInfo->nonStructType.InType provides type information for the buffer
// so, you need to cast it accodingly
}
To run this, you should start session first with real-mode, and then start your application, and then shoot the HTTP request.
If you installed Windows SDK 6.1, then you can find more ETW example code at %Program Files%\Microsoft SDKs\Windows\v6.1\Samples\WinBase\eventtrace.
Armed with this basic knowledge, you can write your own ETW logging/monitoring tool for your module.
There is also another blog consuming event you can refer to; How to consume ETW events from C#
Hope this helps. Thanks
Eok.