Writing to the event log in .NET - the right way

As a DevOper, I spend a lot of time instrumenting code. This involves adding stuff like performance counters, tracing and logging.

One thing that constantly irks me when I go looking for ways or means to improve how I do my logging, is the complete and utter misinformation and misuse of the Windows Event Log. The problem relates to the canonical implementation of logging in .NET, log4net. Look at this method signature:

 void Info(object message);   

Note the lack of structure, the lack of context. Note the ability for a developer to put absolutely anything into the message object (which will be outputted as a string). When these types of messages are hooked up to an Event Log sink, the result is a generic message, usually in the Application log with a bit of free form text. Fairly useless for anyone to be able to filter and report on. The above style of logging is really more suited towards tracing and debug logging than actual operational logging,

Why you should write operational logs to the Windows Event Log
Note this applies to Vista/Windows 2008 and beyond

Structure - despite the standard usage of the event log in the .NET world, Windows Event Logging is based on structured event data and this is what you need and should be aiming for with your operational logging.

Reliability - The feature is tried and tested and built into Windows. There are no external dependencies (to say a database). And even if your event provider isn't installed, the underlying framework handles this and simply doesn't log - instead of throwing exceptions

Performance - In Vista/2008 and beyond, the Windows Event Log is actually based on Event Tracing for Windows. ETW is a high performance tracing engine that is used to instrument pretty much all of Windows these days and most server applications that Microsoft produce. It's what ProcMon uses to track file and registry access. It's basically the Windows version of DTrace. But enough about all of these - the important thing to note is that it does all the smart things for you to guarantee high performance.

For an overview of the structures behind Event Tracing for Windows, have a look at http://msdn.microsoft.com/en-us/magazine/cc163437.aspx. It is important to understand how the pieces fit together before forging ahead with the example at the bottom of this post.

Using the Windows Event Log

I shouldn't begrudge the misuse of the Windows Event Log in the .NET environment too much. After all, the built in framework classes have led you down the wrong path until version 4. Yes, that's right - System.Diagnostics.EventLog doesn't let you easily take advantage of the lovely structured nature of the event logs system. It simply allows you to write classic event logs, which was all you got back in the XP/2003 days.

The class you want to look at is actually System.Diagnostics.Eventing.EventProvider. But before we can use this wonderful class, we need to define the events we are going to write in an instrumentation manifest (http://msdn.microsoft.com/en-us/library/windows/desktop/dd996930(v=vs.85).aspx).

Write a Manifest


I can hear the groans now - why do I have to write a manifest. The reason is a) because a proper event log entry requires it and b) it makes you think about and document the structure of your operational logs. It forces you to overcome the laziness of just pumping out a message to ILog.Whatever(string). This is crucial, especially from an operations point of view, at least on the Windows platform, as it allows operators to use the extensive Windows Event log tools to monitor the application.

The process is actually quite simple once you have got the barebones manifest setup. It's basically

• Add an event with associated metadata (Id, severity, channel, task etc)
• Add a template, which defines the structure of the data you are logging
• Run it through MC.exe (message compiler) to generate a resource definition file and a C# code file
• Run the resource compiler , RC.exe to compile the resource definition
• Run the C# compiler to compile the code file and resource file into a library which contains a) helper methods to write event logs and b) the localised resources that will be display in the event viewer
• Run wevtutil im <manifest> to register your event provider and be able to write to the Windows Event  Log properly.

All of the tools mentioned in the above list come with the Windows SDK/Visual Studio and are all easily scriptable from the command line, so whilst it looks like an onerous set of steps, with a few batch files the actual work involved simply becomes "add your events to the manifest file".

Using your Manifest

Once you have done the above and installed your manifest, the easiest and fastest way to get going is to simply reference the C# assembly that was generated in the compilation step and use the methods to write structured event data to the provider you configured. However, the generated code assembly leaves a bit to be desired. For example, the naming is based on various symbols in the event manifest file and might not be suitable. You also get a method per event, which while it works, is a bit more annoying than simply ILog.Log.

Luckily, you don't have to use the generated assembly. There is an overload for TraceEvent on the System.Diagnostics.Eventing.EventProvider class which allows you to supply an EventDescriptor and an array of objects. You can simply pass an array of objects that match the template you have previously defined for your event in the manifest and ETW will magically take this and turn it into a structured event log.

An Example


I've no doubt the above is about as clear as mud. I'm not a great writer and if you are unfamiliar with ETW or the benefits of writing structured operational event logs then I'm sure the above words are baffling. Hopefully this walk through will help shed some light and encourage you to start using technology that is built into the operating system and has been proven over many years.

A Basic Event Manifest
A lot of the criticism around structured event logging is that you can't define all your loggable events at front. Well, you don't need to, but this particular criticism is usually around something like an logging unhandled exceptions. The key is to define a generic "Unhandled Exception" event, which takes the exception stack trace and some other relevant meta data.

First, let's define the basic event manifest.

   
 <?xml version="1.0" encoding="UTF-16"?>  
 <instrumentationManifest xsi:schemaLocation="http://schemas.microsoft.com/win/2004/08/events eventman.xsd"   
              xmlns="http://schemas.microsoft.com/win/2004/08/events"   
              xmlns:win="http://manifests.microsoft.com/win/2004/08/windows/events"   
              xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"   
              xmlns:xs="http://www.w3.org/2001/XMLSchema"   
              xmlns:trace="http://schemas.microsoft.com/win/2004/08/events/trace">  
     <instrumentation>  
         <events>  
             <provider name="ExampleProvider"   
         symbol="ExampleProvider"  
         guid="{C2049A44-5BE8-4B88-A4CD-1E0EE4139F3B}"   
         resourceFileName="c:\temp.dll"   
         messageFileName="c:\temp.dll">  
                 <events>  
                     <event symbol="UnhandledExceptionEvent" value="10000" version="1" channel="ExampleProvider/Operational" level="win:Error"   
          template="UnhandledExceptionTemplate" message="$(string.ExampleProvider.event.10000.message)" />  
                 </events>  
     <levels/>  
     <tasks/>  
     <opcodes/>  
                 <channels>  
      <channel name="ExampleProvider/Operational" value="0x10" type="Operational" enabled="true" />  
                 </channels>  
                 <templates>  
                     <template tid="UnhandledExceptionTemplate">  
                         <data name="ExceptionType" inType="win:UnicodeString" outType="xs:string" />  
                         <data name="StackTrace" inType="win:UnicodeString" outType="xs:string" />  
                         <data name="NumOfErrors" inType="win:Int32" outType="xs:int"/>  
                     </template>  
                 </templates>  
             </provider>  
         </events>  
     </instrumentation>  
     <localization>  
         <resources culture="en-US">  
             <stringTable>  
                 <string id="ExampleProvider.event.10000.message" value="An unhandled exception of type %1 has occured" />  
             </stringTable>  
         </resources>  
     </localization>  
 </instrumentationManifest>  

This is the minimum event manifest that will compile. Once you have this in place, adding extra events is very easy. Note that I used the ManifestGenerator (EcManGen.exe) which comes with the Windows SDK to generate a base copy to work from and then edited it down to get the above. Anyway, let's go through it.

Start with the <provider> tag as this is the core piece of the puzzle. The name attribute defines the name of the provider as it will appear in things that use ETW providers, such as the event viewer. The symbol attribute is used by MC.exe to generate the methods to call this provider from code. The GUID is just that, an identifier to the provider in the ETW subsystem. The resourceFileName and messageFileName attributes should point to the assembly that contains the localised strings for any messages or custom levels/task defined in this manifest. It is used when the manifest is registered with the Event Viewer but there needs to be a value present for MC.exe - however this isn't validated so we just put a dummy path in for now.

Skipping ahead, you'll notice channel, levels, tasks and opcodes elements. These define metadata that can be referenced by the event itself. The only one we are initially going to populate is channel. This tells ETW where these events should show up and in our case we want to log to an operational channel called ExampleProvider/Operational. Operational channels are designed exactly for that - operationally significant events. For our example we don't need to define any extra levels, tasks or opcodes - the built in Windows ones are sufficient.

This brings us to the event itself which is the thing that ties it all together. In this example we have defined a single event called UnhandledExceptionEvent. The attributes in this element are as follows

• Symbol - used by MC.exe when generating the C# code to log this event
• Value - the Event ID as displayed in event viewer. Any structured logging worth its salt should have these and ETW indeed requires it
• Version - Underrated and underused, this allows us to version the event manifest. In particular, if we were to change the structure of events (by changing the template) we could copy this event and give it a new version which would allow all our existing events to still be usable and not affected by the structure change
• Channel - Where to log this event. This relates to the name in the channel element
• Level - The severity level of the event. Interesting to note that this is correctly defined at the time the event is defined and not left to the developer to infer at runtime. Results in much more consistency in operational logging. In our case, we are using the win:Error level, which is a built in level
• Template - Refers to the <template> section below which defines the structure of data that will be supplied and logged with the event
• Message - a localized string that shows up in the event viewer. It's defined in the string table in the <localization> section of the file and can reference data items in the template that is being used for the event

The <templates> section is where the real magic happens. As noted, the <event> points to a <template> based on its tid to define the list of data it expects to be logged with the event. Each data element takes a name and input type and an output type. In our examples I am logging the type of exception, the exception stack trace and the number of errors, which is just an example of using an integer more than anything I might actually log.

And finally, the <localization> and in particular the <stringTable>, which can be used to localize just about any string in the event manifest. In our example case, we have defined the message for the UnhandledExceptionEvent. There is nothing special here except the %1 in the string. What does this mean? This is simply a format string - %1 will take the value of the first data item defined in the template, which is ExceptionType and substitute it when logging the event. Note that it is a one-based indexing system.

For a complete description of the Event Manifest and the required and optional values, see http://msdn.microsoft.com/en-us/library/windows/desktop/dd996926(v=vs.85).aspx

Compiling the Event Manifest

Once you have an event manifest you're happy with, compiling it is really quite easy. Open up a Visual Studio command prompt and run the following

 mc -css Example.Namespace ExampleManifest.man  

MC.exe takes the filename of the manifest. I've also specified the -css flag to output a C# file with static methods for calling the event provider. The argument for the -css flag is simply the namespace you wish to have the generated class live in.

Provided there are no errors, a bunch of other files will be generated including a .cs and a .rc file. The next step is to compile the .rc file to get a proper Win32 resource.

 rc ExampleManifest.rc

This will output a .res file which contains the localised strings from the manifest. Now we've got a .cs file and a .res file, we can compile the library which will allow us to write to the event provider.

 csc /target:library /unsafe /win32res:ExampleManifest.res ExampleManifest.cs  

This is a basic C# compiler command line call. Note that we must compile as /unsafe due to the way MC.exe generates the .cs file. Further, we also included the .res file generated by RC.exe with the Win32Res flag which enables us to use the compiled assembly as the source for messageFileName and resourceFileName back in the <provider> section of the event manifest.

Take the output assembly and modifying your manifest with the path to the assembly - this allows the event viewer to show appropriate messages when events are viewed with it.

 <provider name="ExampleProvider"   
         symbol="ExampleProvider"  
         guid="{C2049A44-5BE8-4B88-A4CD-1E0EE4139F3B}"   
         resourceFileName="c:\ExampleManifest.dll"   
         messageFileName="c:\ExampleManifest.dll">  

Installing the Manifest


This step registers the provider with the ETW subsystem and if applicable, will show your event channel up in the windows event viewer.

 wevtutil im ExampleManifest.man  

You need to run this as a user with Administration privileges. The im argument stands for install manifest and the command simply takes the path (relative or absolute) to your event manifest. If the command runs without error, open (or close and re-open) the event viewer - you should see the operational channel you defined.

Writing to the Event Log (event provider)

We've now got our very own event channel registered in event viewer - but how do we write to it? Well, we actually must write to the event provider - it is what decides where the message should go, based on the event manifest. In our case however, the UnhandledExceptionEvent event we defined will be written to the ExampleProvider/Operational channel and thus will show up in the event viewer.

The first and probably easiest way is to reference the assembly that was compiled from the code generated by MC.exe and call the appropriate event logging methods, as demonstrated below.

 using System;  
 using System.Collections.Generic;  
 using System.Linq;  
 using System.Text;  
   
 namespace ETWDemo  
 {  
   class Program  
   {  
     static void Main(string[] args)  
     {  
       var wroteOk = Example.Namespace.ExampleProvider.EventWriteUnhandledExceptionEvent(  
         "ArgumentNullException",  
         "at Stack..Stack..Stack",  
         123);  
       Console.WriteLine(wroteOk);  
     }  
   }  
 }  

The above code results in the event being written to the event log. We can see that the method generated by MC.exe is a static method (due to the -css flag) which takes in 3 parameters that correspond to the data items in the template specified by the event manifest. The resultant event log entry looks as follows.

The Event ID and Level correspond with what we have put into the event manifest. And the message is as we put in the manifest, with the exception type string being substituted as appropriate. But where is the structured data - I mean, that was the whole point of me berating you to use the event log. Clicking the details tab reveals our structured data.

Nicely formatted on the Friendly View above but the XML reveals exactly how this data is stored and what is going on here.

Having data like this, correctly structured in the event log opens up so many more possibilities for querying and lookups.

One final thing - I mentioned that you don't need to use the generated assembly to log to the provider configured in the manifest. Instead, lets create our own EventDescriptor struct and call the appropriate EventProvider.WriteEvent method directly.

 using System;  
 using System.Collections.Generic;  
 using System.Linq;  
 using System.Text;  
 using System.Diagnostics.Eventing;  
   
 namespace ETWDemo  
 {  
   class Program  
   {  
     static void Main(string[] args)  
     {  
       var eventProvider = new EventProvider(new Guid("c2049a44-5be8-4b88-a4cd-1e0ee4139f3b"));  
       EventDescriptor eventDescriptor;  
       unchecked  
       {  
         eventDescriptor = new EventDescriptor(  
           0x2710, //EventId  
           0x1, //Version  
           0x10, //Channel Id  
           0x2, //Level  
           0x0, //OpCode  
           0x0, //Task  
           (long)0x8000000000000000); //Keywords  
       }  
         
       var wroteOk = eventProvider.WriteEvent(ref eventDescriptor, "InvalidOperationException", "at Stack..Stack..Stack", 645);  
       Console.WriteLine(wroteOk);  
     }  
   }  
 }  

Now, I definitely took some liberties from the generated code. You can do the same as well to discover how to build the event descriptor based on your event manifest. The critical bit is the overload method WriteEvent that is called. Note the array of objects passed in - this matches in order and number to the data items specified in the manifest. And it thus results in the following event being logged

In Conclusion


If you are doing operational style logging in .NET, you should definitely be looking log structured data. Event Tracing for Windows and the Event Viewer give you a high performance, flexible and self documenting method of logging structured data, which doesn't have any external dependencies like a database or even a socket.