Decoding EventSource traces

In the previous post, I introduced an EventSource sample. If you run the sample app, the calculator client will continually try to connect to the service and perform random operations, tracing all the while. That’s nice, but how do you actually read and decode these traces?

First, you need to actually collect the traces. As usual, open an elevated command prompt and run logman.exe create trace SampleTrace -p {0745B9D3-BC9A-4C33-953C-77DE89336B0D} -o SampleTrace.etl (note that we use the ClientEventSource provider ID) to create the session and logman.exe start SampleTrace to start the session. Now run the app and let it go for 30 seconds or so. After you exit the app, run logman.exe stop SampleTrace to stop the session. You will now have a file SampleTrace_000001.etl (or similar). However, ETL is a binary format and a manifest is required to decode the trace data.

Conveniently, I have created a PowerShell script to invoke EventSource‘s method to generate the manifest file for types in a given assembly: GenerateManifests.cmd. To use it, pass in the assembly name and an optional output path (defaults to current directory). For the sample app, the command would be something like GenerateManifests.cmd EventSourceSample.Core.dll. The resulting file EventSourceSample-ClientEventSource.man can now be passed to tracerpt.exe to decode the events!

Let’s try converting to XML:
tracerpt.exe -l SampleTrace_000001.etl -import EventSourceSample-ClientEventSource.man -o SampleTrace.xml -of XML

Opening up SampleTrace.xml you should see output similar to the following:

<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
	<System>
		<Provider Name="ClientEventSource" Guid="{0745b9d3-bc9a-4c33-953c-77de89336b0d}" />
		<EventID>30</EventID>
		<Version>0</Version>
		<Level>4</Level>
		<Task>0</Task>
		<Opcode>1</Opcode>
		<Keywords>0xF00000000008</Keywords>
		<TimeCreated SystemTime="2014-01-24T12:00:20.612995800Z" />
		<Correlation ActivityID="{00000000-0000-0000-0000-000000000000}" />
		<Execution ProcessID="10824" ThreadID="1076" ProcessorID="0" KernelTime="0" UserTime="60" />
		<Channel />
		<Computer />
	</System>
	<EventData>
		<Data Name="id">{aeb41e37-cf40-4317-a989-7d5aa6a2dc87}</Data>
	</EventData>
	<RenderingInfo Culture="en-US">
		<Level>Information </Level>
		<Opcode>Start </Opcode>
		<Keywords>
			<Keyword>Connection </Keyword>
		</Keywords>
		<Message>Connection {aeb41e37-cf40-4317-a989-7d5aa6a2dc87} opening. </Message>
	</RenderingInfo>
</Event>

There it is, in all its glory — the event header (in the System element) containing process, thread, timestamp, etc. and the decoded message (in the RenderingInfo element).

This is a bit hard to read, so let’s try exporting to EVTX and using Event Viewer instead:
tracerpt.exe -l SampleTrace_000001.etl -import EventSourceSample-ClientEventSource.man -o SampleTrace.evtx -of EVTX

Typing the file name SampleTrace.evtx will launch Event Viewer to view the log. By default, the log will be sorted in descending timestamp order. In the upper pane, the table will show the event summary, e.g.:

The pane below this shows the decoded message and a detailed dump of the properties in the event. Within Event Viewer you can filter the log and resave it in different formats (e.g. CSV).

These are the basic in-box tools you can use for dealing with ETL files. If you’re looking for a programmatic solution, e.g. to do more detailed analysis, stay tuned for a future post.