27 March 2012

Creating a Comprehensive Event Logger

Would you rather try to decipher the meaning of an error in the Windows application event log, or ram a fork into the back of your hand?  I thought so.

The problem with the event logs is they are notoriously uninformative.  It seems that their purpose is to taunt IT personnel, by suggesting some helpful information is available. Yeah, right.  There are entire Web sites dedicated to deciphering event identification numbers mean.  The necessity for such sites is just plain sad.  Apparently, leaving what happened a mystery is a better alternative to including actual WORDS that describe the problem, in human language.

I implore you: do not be that kind of developer!  I always insist on making everything human readable, and easy to understand.  By leveraging the extensible nature of .NET, we can easily log useful and meaningful information to the event log, which will help the user or IT administrator fix the problem, and/or help the developer debug the issue.

Here's how you can use a single method, to alleviate the IT admin's urge to strangle you.


Functionality

When we "extend" a code base, we are adding to the existing functionality of that code.  What we are about to do is add a new method to the System.Diagnostics.EventLog class.  We want this new method to write the details of any Exception object to the application event log, including:
  • A custom message, that describes what happened, in plain terms  (system admins should be able to use this information, to correct the issue, when possible)
  • The exception message
  • The exception stack trace
  • The message and stack trace of all inner exceptions
  • Format all of this information in such a way that makes it easy to read
NOTE: This functionality is best suited for in-house development, where you generally don't care if somebody sees your stack trace.  If shipping software to clients, it is wise to include a switch to turn stack trace logging on, to temporarily capture a stack trace, making debugging client issues easier.

Code
The following extension method generated nice, friendly messages that are well-formatted.

using System;
using System.Diagnostics;
using System.Text;
 
namespace DCFieldService.Model
{
  public class Extensions
  {
    public static void WriteExceptionToEventLog(
        this EventLog log,
        string customMessage,
        Exception exception,
        int eventId)
    {
      if (log == null)
        throw new ArgumentNullException("log", "log is null.");
      if (exception == null)
        throw new ArgumentNullException("exception", "exception is null.");
 
      string seperator = new String('-', 50);
      StringBuilder builder = new StringBuilder(customMessage);
 
      Exception exc = exception;
      do
      {
        builder.AppendLine();
        builder.AppendLine(seperator);
        builder.AppendLine(exc.Message);
        builder.AppendLine();
        builder.AppendLine("STACK TRACE:");
        builder.AppendLine(exception.StackTrace);
        exc = exc.InnerException;
      } while (exc != null);
 
      log.WriteEntry(builder.ToString(),
        EventLogEntryType.Error,
        eventId);
    }
  }
}

To keep all of the event ids easily managed, I typically create an enumeration.  I like these, because an enumeration is easily converted to and from an integer.  See the example code, below.


Usage and Common Sense

Obviously, this method is used when an exception is thrown.  Using this method is only as helpful to users and administrator as the custom message you write.  This is also true of ANY event message you write.  Please consider the following, when making any type of entry in the event log:
  1. Does the message make sense to me?
  2. Will the message make sense to somebody that is unfamiliar with the application?
  3. Is it actually important to let somebody know that this event occurred?
  4. Does the message tell the reader what happened, in plain words?
  5. Does the message tell the reader how to correct the issue?
  6. Are Event ID numbers logically grouped, for general identification? (e.g. all database errors are between 1000-1999, all IO errors are between 2000-2999, etc.)
  7. Does the message tell the reader where to get more help with the issue?


Example

NOTE: I was lazy and simply wrote a .NET Runtime error 1022, so I didn't have to register a new log source.


using System;
using System.Diagnostics;
 
namespace ConsoleApplication1
{
  public enum EventIds
  {
    BuildingIdParserFailed = 1020,
    EmployeIdParserFailed = 1021,
    EmployeeIdParserFailed = 1022
  }
 
  class Program
  {
    static EventLog _log = new EventLog("Application""."".NET Runtime");
 
    static void Main(string[] args)
    {
      string badNumber = "123abc";
      int value = 0;
      try
      {
        value = Int32.Parse(badNumber);
      }
      catch (Exception ex)
      {
        _log.WriteExceptionToEventLog(
            String.Format("Conversion of value \"{0}\" to Int32 failed." +
            "  Invalid strings should not be allowed, but this one " +
            "somehow got through.  Please report this bug to the developer."
            , badNumber),
        ex,
        (int)EventIds.EmployeeIdParserFailed);
      }
    }
  }


Notice the highlighted cast from an enumeration to Int32.  Here's the event log, written by the extension method:

[Click image, to enbiggenate]

Now, THAT'S something that makes sense to a system administrator, and is also useful to a developer.  Why try to reproduce the problem, when you can capture the data when it happens the first time, with real data, out in the field?  Again, clients will probably not want to risk exposing data, and you don;t want to expose the internal workings of the application; so, this is usually good for internal applications.


Happy coding!

No comments:

Post a Comment

Please provide details, when posting technical comments. If you find an error in sample code or have found bad information/misinformation in a post, please e-mail me details, so I can make corrections as quickly as possible.