A Quick and Dirty tutorial on Event Tracing For Windows: Part 1 the Event Trace Session

[EDIT 4 September 2010]
Thanks to David M for pointing out an error in my code. When starting an ETW session you should pass in the session name not the log file name. See the correction (in bold) in the LoggingController::Start member function below.
[/EDIT]

So, Windows Events, its the new Logging API for Windows Vista+, it brings together Event Tracing for Windows (ETW) and Windows Event Log. The basic layout of ETW is that you have an Event Tracing Session, for which you enable providers. These providers write log messages into the session. You can enable the providers with various settings allowing you to filter the type and criticality of the log messages, and do all that fun sophisticated tracing stuff. If you use a “manifest-enabled” provider (more on that later) you get the Windows Event Log side of it for free. You can also create consumers of these sessions, to monitor the logs and stuff.

Right, so the bit I’m going to discuss now is the process of creating a session. You’ll find the sample code in the Windows SDK (you’ll need the windows 7 sdk installed for all of this by the way) heaps more useful than the documentation (which is only really good as a supplementary annex to the sample code). The particular sample is in sampleswinbaseEventingController

Now the sample code is a C program, with a whole lot of console stuff, which is nice, but I started off by writing a class which creates a default session, enables the provider from the simple C++ provider sample, and has member functions to disable it again, and end the session.

The definition is as follows:

#pragma once

class LoggingController
{
public:
	LoggingController(void);
	virtual ~LoggingController(void);

	virtual void Start();
	virtual void EnableProvider();
	virtual void DisableProvider();
	virtual void Stop();

private:
	ULONG hexToLong(__in TCHAR *String);
	VOID stringToGuid(__in TCHAR *String, __out LPGUID Guid);

	static TCHAR *defaultLogFileName;
	static TCHAR *defaultProviderGuid;
	static TCHAR *defaultLoggerName;

	LPTSTR loggerName;
	LPTSTR logFileName;
	GUID targetGuid;

	PEVENT_TRACE_PROPERTIES loggerInfo;
	TRACEHANDLE loggerHandle;
};

And the declaration is as follows:

#include "StdAfx.h"
#include "LoggingController.h"

using namespace std;

TCHAR *LoggingController::defaultLogFileName = _T(".\SuperNovaLogger.etl");
TCHAR *LoggingController::defaultProviderGuid = _T("21a9201e-73b0-43fe-9821-7e159a59bc6f");
TCHAR *LoggingController::defaultLoggerName = _T("SuperNovaLogger");

/**
* Constructs a new LoggingController.
* Sets up a new LoggingController, but does not start the session, or enable any providers.
*/
LoggingController::LoggingController(void)
{
	ULONG sizeNeeded = 0;
	this->loggerHandle = (TRACEHANDLE)0;

	// calculate the number of bytes needed for the EVENT_TRACE_PROPERTIES struct
	// NOTE(from[Windows API Documentation]): The memory you allocate for the EVENT_TRACE_PROPERTIES structure must be large
	// enough to also contain the session and log file names that follow the structure in memory. /NOTE
	// Thus we add two times the max string to the end of the memory block.
	sizeNeeded = sizeof(EVENT_TRACE_PROPERTIES) +
		2 * MAXSTR * sizeof(TCHAR);

	this->loggerInfo = (PEVENT_TRACE_PROPERTIES)malloc(sizeNeeded);
	// TODO: TEST TO SEE IF THE MALLOC SUCCEEDED

	RtlZeroMemory(this->loggerInfo, sizeNeeded);

	// Set up some proprerties of the event trace session
	this->loggerInfo->Wnode.BufferSize = sizeNeeded;
    this->loggerInfo->Wnode.Flags = WNODE_FLAG_TRACED_GUID;
    this->loggerInfo->LoggerNameOffset = sizeof(EVENT_TRACE_PROPERTIES);
    this->loggerInfo->LogFileNameOffset = this->loggerInfo->LoggerNameOffset +
                                    MAXSTR * sizeof(TCHAR);

	// Assign the default logger name, and log file name.
	this->loggerName = (LPTSTR)((PCHAR)(this->loggerInfo) + this->loggerInfo->LoggerNameOffset);
	this->logFileName = (LPTSTR)((PCHAR)(this->loggerInfo) + this->loggerInfo->LogFileNameOffset);

	// Copy default values into the logger name, and log file name values.
	// TODO: Make these parameterizeable so that we can have different sessions enabling the provider at different levels etc.
	_tcscpy_s(this->loggerName, MAXSTR, this->defaultLoggerName);
	_tcscpy_s(this->logFileName, MAXSTR, this->defaultLogFileName);

	this->stringToGuid(this->defaultProviderGuid, &(this->targetGuid));

}

/**
* Cleans up a LoggingController
*/
LoggingController::~LoggingController(void)
{
	// Free the EVENT_TRACE_PROPERTIES struct we allocated in the constructor;
	free(this->loggerInfo);

}

/**
* Converts an Hexadecimal string to a long.
* This method is used to convert the components of a string representation of a GUID xxxxxxxx-xxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx
* to a long. The results can then be used to populate a GUID struct.
* @param String a TCHAR* which points to the string to convert
* @return a ULONG which holds the value of the HEX string
*/
ULONG LoggingController::hexToLong(TCHAR *String)
{
	ULONG HexDigit = 0;
	ULONG Base = 1;
	ULONG HexValue = 0;
	INT Length = (INT)_tcslen(String);

	while (--Length >= 0)
	{
		if ((String[Length] == 'x' || String[Length] == 'X') &&	(String[Length - 1] == '0'))
		{
			break;
		}

		if ((String[Length] >= '0') && (String[Length] <= '9'))
		{
			HexDigit = String[Length] - '0';
		}
		else if ((String[Length] >= 'a') && (String[Length] <= 'f'))
		{
			HexDigit = (String[Length] - 'a') + 10;
		}
		else if ((String[Length] >= 'A') && (String[Length] <= 'F'))
		{
			HexDigit = (String[Length] - 'A') + 10;
		}
		else
		{
			continue;
		}

		HexValue |= HexDigit * Base;
		Base <<= 4;
	}

	return HexValue;
}

/**
* Converts a string representation of a guid (xxxxxxxx-xxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx) to a GUID.
* Takes the string representation of a guid and breaks it into its 6 components which are then parsed
* into ULONGs, and then assembled into a guid struct.
* @param String the TCHAR which contains the string representation of the GUID
* @param Guid a pointer to the Guid struct which we will assemle the components of the string into
*/
VOID LoggingController::stringToGuid(TCHAR *String, LPGUID Guid)
{
	TCHAR Temp[10];
	INT Index;

	_tcsncpy_s(Temp, 10, String, 8);
	Temp[8] = 0;
	Guid->Data1 = hexToLong(Temp);

	_tcsncpy_s(Temp, 10, &String[9], 4);
	Temp[4] = 0;
	Guid->Data2 = (USHORT)hexToLong(Temp);

	_tcsncpy_s(Temp, 10, &String[14], 4);
	Temp[4] = 0;
	Guid->Data3 = (USHORT)hexToLong(Temp);

	for (Index = 0; Index < 2; Index++)
	{
		_tcsncpy_s(Temp, 10, &String[19 + Index * 2], 2);
		Temp[2] = 0;
		Guid->Data4[Index] = (UCHAR)hexToLong(Temp);
	}

	for (Index = 2; Index < 8; Index++)
	{
		_tcsncpy_s(Temp, 10, &String[20 + Index * 2], 2);
		Temp[2] = 0;
		Guid->Data4[Index] = (UCHAR)hexToLong(Temp);
	}
}

/**
 * Starts the Event Trace for Windows Session.
 */
void LoggingController::Start()
{
	wcout << "Attempting to start ETW Session: " << this->loggerName << "...";

	ULONG status = StartTrace(&(this->loggerHandle), this->loggerName, this->loggerInfo);
	if ( status != ERROR_SUCCESS )
	{
		cout << "Failed with error: " << status << "." << endl;
		return;
	}

	cout << "Success." << endl;
}

/**
 * Stops the Event Trace for Windows Session.
 */
void LoggingController::Stop()
{
	wcout << "Attempting to stop ETW Session: " << this->loggerName << "...";
	this->loggerHandle = (TRACEHANDLE)0;
	ULONG status = ControlTrace(this->loggerHandle, this->loggerName, this->loggerInfo, EVENT_TRACE_CONTROL_STOP);
	if ( status != ERROR_SUCCESS )
	{
		cout << "Failed with error: " << status << "." << endl;
		return;
	}
	cout << "Success." << endl;
}

/**
 * Enables the default provider for the ETW Session in progress
 */
void LoggingController::EnableProvider()
{
	cout << "Attempting to enable default provider...";
	/*if ( this->loggerHandle == (TRACEHANDLE)0 )
	{
		cout << "Can not enable default provider because no session is active." << endl;
		return;
	}*/

	//ULONG status = EnableTrace(TRUE, 0, 0, &(this->targetGuid), this->loggerHandle);

	ULONG status = EnableTraceEx( &(this->targetGuid), NULL, this->loggerHandle, TRUE, TRACE_LEVEL_VERBOSE, 0, 0, 0, NULL );
	if ( status != ERROR_SUCCESS )
	{
		cout << "Failed with error: " << status << "." << endl;
		return;
	}

	cout << "Success." << endl;
}

/**
 * Disables the default provider for the ETW Session in progress
 */
void LoggingController::DisableProvider()
{
	cout << "Attempting to disable default provider...";
	if ( this->loggerHandle == (TRACEHANDLE)0 )
	{
		cout << "Can not disable default provider because no session is active." << endl;
		return;
	}

	//ULONG status = EnableTrace(FALSE, 0, 0, &(this->targetGuid), this->loggerHandle);
	ULONG status = EnableTraceEx( &(this->targetGuid), NULL, this->loggerHandle, FALSE, TRACE_LEVEL_VERBOSE, 0, 0, 0, NULL );
	if ( status != ERROR_SUCCESS )
	{
		cout << "Failed with error: " << status << "." << endl;
		return;
	}

	cout << "Success." << endl;
}

The most important thing to note is that the struct we fill out in the constructor (EVENT_TRACE_PROPERTIES) needs to be allocated with malloc because you have to leave room at the end of it for the logger name, and log-file name (hence the whole sizeNeeded variable thing).

Also, when you use this logging controller, DON’T under any circumstances forget to disable the provider and then stop the session, otherwise you’ll need to reboot your computer before you can restart the session successfully.

That’s about all for now. I know, its not much of an article, but it’ll suffice. I’ll hopefully do a provider next weekend, and then a consumer some time after that.

Enjoy.

Almost forgot… the documentation is here.