Skip to main content

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.

Comments

  1. Thank you Daniel Gordon,
    I was looking for some help/examples regarding localization using Event Logging in .Net. This helps a lot. Much appreciated. You saved the day.

    ReplyDelete
  2. This comment has been removed by the author.

    ReplyDelete
  3. Thank you Daniel Gordon. You save my day ! Very helpful and clear understanding.

    ReplyDelete
  4. The blog gave me idea to create the event log my sincere thanks for sharing this post and please Continue to share This kind of Post
    Dot Net Training in Chennai

    ReplyDelete
    Replies
    1. IEEE Final Year projects Project Centers in Chennai are consistently sought after. Final Year Students Projects take a shot at them to improve their aptitudes, while specialists like the enjoyment in interfering with innovation. For experts, it's an alternate ball game through and through. Smaller than expected IEEE Final Year project centers ground for all fragments of CSE & IT engineers hoping to assemble. Final Year Project Domains for IT It gives you tips and rules that is progressively critical to consider while choosing any final year project point.

      JavaScript Training in Chennai

      JavaScript Training in Chennai

      Delete
  5. It's wonderful blog article.It's stunning performance of the blog. Your blog is great for anyone who wants to understand this subject more. Great stuff; please keep it up!Dot Net Training in Chennai.If want to do learning from Hadoop to reach us Besant technologies.They Provide at real-time Hadoop Training.Hadoop Training in Chennai

    ReplyDelete
  6. really nice blog had been shared by you. before i read this blog i didn't have any knowledge about this but now i got some knowledge about this.
    dot net training in chennai

    ReplyDelete
  7. I have read your blog its very attractive and impressive. And i would like to share your blog to my friends. Thanks for sharing. Cloud Computing Training in Chennai | Salesforce Training in Chennai

    ReplyDelete
  8. nice blog has been shared by you. before i read this blog i didn't have any knowledge about this but now i got some knowledge. so keep on sharing such kind of an interesting blogs.
    dot net training in chennai

    ReplyDelete
  9. I have read your blog its very attractive and impressive. it is good work.
    blue prism training in chennai | csharp training in chennai

    ReplyDelete
  10. If you want to learn Big data from us contact Orange TechnoMind with more practical session.. Big Data Hadoop Training in Chennai

    ReplyDelete
  11. The young boys ended up stimulated to read through them and now have unquestionably been having fun with these things.
    iosh course in chennai

    ReplyDelete
  12. Want to play casino? Come and do not expect a miracle, only here you can really get up I checked myself) best free online gambling Win in the best casino of the century.

    ReplyDelete
  13. Good,keep do posting
    All the ways that you suggested for find a new post was very good.
    hardware and networking course in hyderabad

    ReplyDelete
  14. Amazing Article ! I have bookmarked this article page as i received good information from this. All the best for the upcoming articles. I will be waiting for your new articles. Thank You ! Kindly Visit Us @ Coimbatore Travels | Ooty Travels | Coimbatore Airport Taxi | Coimbatore taxi

    ReplyDelete
  15. Современная диодная лента по всем стандартам отличного качества я обычно беру у компании Ekodio

    ReplyDelete
  16. This comment has been removed by the author.

    ReplyDelete
  17. This comment has been removed by the author.

    ReplyDelete
  18. Great post! I am actually getting ready to across this information, It’s very helpful for this blog. Also great with all of the valuable information you have Keep up the good work you are doing well.
    CRS Info Solutions Salesforce training for beginners

    ReplyDelete
  19. This article is really helpful for me. I am regular visitor to this blog. Share such kind of article more in future. Personally i like this article a lot and you can have a look at my services also: I was seriously search for a Salesforce training institutes in ameerpet which offer job assistance and Salesforce training institutes in Hyderabad who are providing certification material. It's worth to join Salesforce training institutes in India because of their real time projects material and 24x7 support from customer desk. You can easily find the best Salesforce training institutes in kukatpally kphb which are also a part of Pega training institutes in hyderabad. This is amazing to join Data science training institutes in ameerpet who are quire popular with Selenium training institutes in ameerpet and trending coureses like Java training institutes in ameerpet and data science related programming coures python training institutes in ameerpet If you want HCM course then this workday training institutes in ameerpet is best for you to get job on workday.

    ReplyDelete
  20. Thanks for Sharing This Article.It is very so much valuable content. I hope these Commenting lists will help to my website
    workday studio online training
    best workday studio online training
    top workday studio online training

    ReplyDelete
  21. It's very useful article with informative and insightful content and i had good experience with this information. We, at the CRS info solutions ,help candidates in acquiring certificates, master interview questions, and prepare brilliant resumes.Go through some helpful and rich content Salesforce Admin syllabus from learn in real time team. This Salesforce Development syllabus is 100% practical and highly worth reading. Recently i have gone through Salesforce Development syllabus and Salesforce Admin syllabus which includes Salesforce training in USA so practically designed.

    ReplyDelete

Post a comment

Popular posts from this blog

SCCM 2012 - SMSPXE Error

I write this to help all you technical warriors out there who get shitty advice from the Microsoft Forums and other profound idiots about the 0x80092002 error in SCCM - usually to do with PXE booting but can manifest in other ways around DP -> MP communications.

The tricky one about this error is that it happens even if you are only using HTTP communication and not HTTPS/TLS. So to get an error about certificates is somewhat confusing.

What the uneducated masses of the internet will tell you is to re-install the PXE role over an over. This will do nothing.

Then they will tell you to re-install your management point and effectively re-build your entire infrastructure. This will work, but only because it is the nuclear option and will run the step that actually makes a difference as a matter of course.

So, here it is folks. If you have these kinds of errors in your logs:

PXE::MP_InitializeTransport failed; 0x80092002SMSPXE22/03/2017 2:45:58 PM4144 (0x1030) PXE::MP_ReportStatus failed…

Log Reader Error On Adding Subscription

Ever tried to add a new subscription to an existing publication, using the "replication support only" or "initialize from backup" methods and go the following error?
The process could not execute 'sp_MSadd_replcmds' on <'Distribution Server>'. (Source: MSSQLServer, Error number: 1007) Conversion failed when converting the nvarchar value '.' to data type int. (Source: MSSQLServer, Error number: 1007) Batches were not committed to the Distributor. (Source: MSSQL_REPL, Error number: MSSQL_REPL22020) The last step did not log any message! (Source: MSSQL_REPL, Error number: MSSQL_REPL22037)
If so, you will know the internet is absolutely useless, filled with worthless workarounds or advice to just "rebuild replication"

Well, if you want an actual solution, just read on. Between SQL 2012 RTM and SQL 2012 SP4 there was a change made to the Distributor proc sp_MSadd_replcmds. This change was to facilitate a change in the format of l…