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
  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. This comment has been removed by the author.

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

    ReplyDelete
  13. This information is impressive..I am inspired with your post writing style & how continuously you describe this topic.
    Python Training In Pune
    python training institute in pune

    ReplyDelete
  14. Go through their clients who are running a similar business scale as that of yours and also check the number of clients they have dealt with so far Salesforce training in Hyderabad

    ReplyDelete
  15. Nice post brother, I have been surfing online more than 3 hours today, yet I never found any interesting article like yours. It is pretty worth enough for me. In my view, if all web owners and bloggers made good content as you did, the internet will be much more useful than ever before. There is certainly a lot to know about this issue.I love all of the points you’ve made. I am sure this post has touched all the internet viewers.
    hướng dẫn đi máy bay từ mỹ về việt nam

    vé máy bay khứ hồi từ đức về việt nam

    chuyến bay từ anh về việt nam

    khi nào có chuyến bay từ úc về việt nam

    Săn vé máy bay 0 đồng tu Dai Loan ve Viet Nam

    lịch bay từ canada về việt nam

    ReplyDelete

  16. This blog is very useful it include very knowledgeable information. Thankyou for sharing this blog with us. If anyone want to experience certificate in bangalore can call at 9599119376 or can visit https://experiencecertificates.com/experience-certificate-provider-in-bangalore.html

    ReplyDelete
  17. Thanks for sharing this post , if anyone looking his/her career in sas so join with High technologies solutions Contact Here-+91-9311002620 Or Visit Website- https://www.htsindia.com/Courses/business-analytics/sas-training-institute-in-delhi

    ReplyDelete
  18. This blog is very useful for me it gives me the very knowledgeable information to me. Dreamsoft is the 20years old consultancy providing the experience certificate in many status of the India. the interested may contact at the 9599119376 or can visit our website for the
    Career Boosting Genuine Experience Certificate In Mumbai
    https://experiencecertificates.com/experience-certificate-provider-in-mumbai.html
    Career Boosting Genuine Experience Certificate In Gurugram
    https://experiencecertificates.com/experience-certificate-provider-in-Gurgaon.html
    Career Bosting Genuine Experience Certificate In Delhi
    https://experiencecertificates.com/experience-certificate-provider-in-delhi.html
    Career Boosting Experience Certificate In Noida
    https://experiencecertificates.com/experience-certificate-provider-in-Noida.html
    Career Boosting Genuine Experience Certificate In Bangalore
    https://experiencecertificates.com/experience-certificate-provider-in-bangalore.html
    Career Boosting Genuine Experience Certificate Hyderabad
    https://experiencecertificates.com/experience-certificate-provider-in-Hyderabad.html

    ReplyDelete
  19. Thank you for your excellent work! Your post provides an in-depth info of all the steps. bus rental Dubai

    ReplyDelete
  20. We've noticed that this article is well-informed, in my opinion. The essay is beneficial to us, and your writing is exceptional. We appreciate you sharing this content.hire coldfusion developers

    ReplyDelete

Post a Comment

Popular posts from this blog

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

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; 0x80092002 SMSPXE 22/03/2017 2:45:58 PM 4144 (0x1030) PXE::MP_