Happiness is good logging

• Download source - 1.53 MB

Introduction

Troubleshooting an error that has found its way into your tester's hand, or even worse, into production can be challenging to say the very least. This article presents an approach to both exception handling and logging that leverages Enterprise Library in a very simple but effective way, and adds a little custom code to really step it up. As an added feature, I will also present an approach that can use this same methodology to accomplish performance logging! Further bonus for the truly curious: It is ridiculously easy to create a Prism logger (implements ILoggerFacade) that just calls into SuperLogger to provide all the same value you see below. Contact me through comments or email if you would like to see this.

Goals

In attacking the problem of good logging and practices for exception handling, I wanted to keep a couple of very fundamental goals in mind (you can review these to see if you want to continue reading

• Have great logging and great ability to search/review logs
• Final location for logs will be a database for easy searching and reporting on logs
• Log from code into a message queue to achieve as close to asynchronous functionality as possible in Ent Lib
• Provide a very simple framework for developers to create good, full log entries without doing much work and having to worry about various EntLib references or how it works
• Be able to shield exception details across layer boundaries (client / server, etc) while providing a good way to correlate the cross-boundary errors
• Don't roll your own logging infrastructure -- leverage existing frameworks -- in this case, Enterprise Library
• Make sure that errors that could not get logged to the message queue or the database still get logged somewhere

Note: I am not using the EntLib ExceptionHandling block at all in the solution below. If you have complex handling and shielding rules, the solution here is probably not the right thing for you.

Explanation of Logging Setup

A *lot* of this framework is configuration-based, and a number of various decision points are available to you with the setup I lay out below. As much as possible, I will highlight those options and explain why I made the decisions that I did. Take them or leave them.

If you already have Enterprise Library database logging and message queuing set up, you can mostly skip this Setup section.

Enterprise Library setup

This section will go through the setup of Enterprise Library, Message Queuing, the Logging database, and the Distributor Service. I will not be going through each and every step in a very detailed way; instead I will highlight a couple of specific points beyond providing the places to look in the EntLib or other documentation

1. If you haven't already, get and install the latest distribution of Enterprise Library.
2. Create the logging database objects using the provided scripts. NOTE: You only really need to follow instructions 1 and 2 on this page. NOTE: This is an area that I have done some customization for, and I explain that customization below in the Database Customization section.
3. Create a private message queue called "superLogger" on your machine. You can use this TechNet page as a reference.
4. Install the msmqDistributor service. To do this, follow steps 4, 5, and 6 of the EntLib "Using the Distributor Service" page. Note: Step 4 calls you to manually edit the msmqDistributor.exe.config file for the name of you message queue. Make sure to use the name from the step above!
5. Copy the msmqDistributor.exe.config file from the attached solution over the same file in the directory from which you installed the msmqDistributor.exe service above. Modify the Logging database connection properties to match your database information from step 1 above. Note: If you renamed or provided different stored procedures for the WriteLog or AddCategory items, you will need to update the corresponding values in the Super Database Log target listener section.
6. Start (or restart) the Super Logger Distributor Service (EntLib). This will be in the "Services" section of your Control Panel.

After completing the setup above, you should have a message queue waiting for messages, and you should have a service running that is waiting to process any messages you put there!

Configuration and Setup Notes

Database Customization

In SuperLogger's implementation, I wanted to add a couple of custom columns into the Log database table, and use a database that we already had in place. I opted for the following customizations:

• Put all objects in an "EntLib" schema within an existing database, rather than have a separate Logging database
• Add custom columns for UserName, ErrorId (to support exception shielding), and PartitionNum (a numeric identifier of how we split up processing work)
• Use a custom insert stored proc to populate all columns, both the originally-created columns and my new custom columns
• Modify the insert proc to change the formatted message to EXCLUDE properties that we are logging elsewhere in the log table to reduce the clutter of a log entry

In the attached code, I reverted all settings in the msmqDistributor.exe.config file (the only file that has database information, since it's the only one that can put logs in the database) to the Ent Lib shipped settings, except the following:

• Database connection information on the Logging database entry
• The WriteLog proc for the Database Perf Log listener (this, by definition, cannot be the same as the WriteLog proc for the standard logs). More info on performance logging below.

My version of the WriteLog proc to do items 3 and 4 from my db customizations is in the StoredProcedures folder of the attached code. If you want to use something similar, go ahead -- just make sure to update the WriteLog setting in the Super Database Log listener

Distributor Service Notes

When you install msmqDistributor.exe as a service, it "remembers" where it was installed. That is where it will always run from. And if you want to uninstall it, the original executable still needs to be in the location from which it was installed.

The msmqDistributorSettings node in the config file cannot be edited by the handy Ent Lib Configuration Application Block Console. It has a serviceName attribute that defines the name of the service as it will appear in your list of services. Change at will.

<msmqDistributorSettings
  msmqPath=".\Private$\superLogger"
  queueTimerInterval="1000"
  serviceName="Super Logger Distributor Service (EntLib)" />

The last note on the Distributor Service is that you can have more than one version of the service running, so long as they have been installed from different directories, and have different names.

Logging configuration

There are two aspects of logging configuration -- one for the code to gets logs into the message queue (EntLib.config), and one that defines what the distributor service will do with them after it gets them (msmqDistributor.exe.config).

Logging config from code

I have adopted a pretty simple approach here -- put a General category out there, and make it the default for everything. Put that to the Message queue. Put the "Unprocessed" special category to the message queue. Then put the Logging Errors & Warnings to an Event Viewer listener. See the image below for a screenshot of the config seen in the Ent Lib config tool.

Distributor Service logging config

Again, I have adopted a pretty simple approach here: Put the "Unprocessed" special category to the database. Any specially-handled categories, like Performance, can go wherever you like. As with the code configuration, put Logging Errors & Warnings to an Event Viewer listener. Screen shot below included for reference.

By way of comment or explanation, I wanted the ability to create additional categories (basically done via an enum in my code below) as the need in the application code arose, without having to reconfigure any aspect of the logging. By default, I want everything going to the database via the standard logging mechanism. This default behavior is accomplished via the "Unprocessed" category -- namely, "when I don't say where to put it, put it here". In more rare and special cases, I may want to be writing to files and/or different places. In those circumstances, we can update the configuration of either side -- the msmqDistributor.exe.config or the EntLib.config to achieve our goal. Updating the EntLib.config for any specific category to go elsewhere also means that "elsewhere" will be written synchronously (and maybe slowly) to that listener.

The Logging Code

The first question that may occur to you is "why wrap the EntLib code at all??" That question certainly occurred to me. One factor relative to my situation is that we have a number of developers that share some common library functions. So it quickly became apparent to me that I wanted to wrap the EntLib code for a few reasons:

• I didn't want to see lots of different ways of calling Enterprise Library for each developer we have
• I didn't want the developers to be troubled by how to instantiate EntLib and worry about its configuration
• I wanted to limit the number of overloads that are available, and provide some standard categories for them to use
• I wanted to inject some common information and control the formatting of exceptions more than the out-of-the-box Ent Lib code does

The first code that you may be interested in is the enum defining the categories for the logging. Note that based on the config above, any category can be added and will log to the standard database table.

public enum SuperLoggingCategory
{
    // Customize these categories however you like 
    Batch,
    ConsoleApp,
    UserInterface,
    WcfService,
    Website,        
    Library,
    Diagnostic,
    Performance,
    WinService,
    General
}

You can review the code for yourself (the SuperLogger.cs file is less than 200 lines), but some of the "secret sauce" to the logging resides in the functions to format the exception message, shown below. Key features of the code:

• The "Title" of the log entry -- which will have its own column in the Log table on the database is either the method name throwing the exception, or the Stored Procedure name if it was a StoredProcedureException. This little trick enables us to report on which methods/procs are having the most trouble -- to create a "doghouse", if you will.
• Dump all possible information from the exception(s) to the log. The standard exception properties are dumped, and then reflection is used to see if there are any other properties available
• Recursion is used to format inner exception details in the same way for all exceptions, and each inner exception is indented with a tab (for each level). This makes sure we include all details from all exceptions that the app is throwing.

Note: If you have some low-level code that calls stored procedures, it is nice to catch a SqlException and wrap it in a StoredProcException to inject some of the parameter information. Just sayin'.

private static string FormatExceptionMessage(Exception exception, 
    ref string title, out string summary, string prepend = "\t")
{
    var exceptionMessage = new StringBuilder();

    var spe = exception as StoredProcException;
    if (string.IsNullOrEmpty(title))
    {
        title = spe != null ? spe.StoredProcName : exception.TargetSite.Name;
    }

    exceptionMessage.Append("\n" + prepend + "Exception:" + exception.GetType());
    exceptionMessage.Append("\n" + prepend + "Message:" + exception.Message);
    summary = exception.Message;

    exceptionMessage.Append(GetOtherExceptionProperties(exception, "\n" + prepend));

    exceptionMessage.Append("\n" + prepend + "Source:" + exception.Source);
    exceptionMessage.Append("\n" + prepend + "StackTrace:" + exception.StackTrace);
    if (exception.InnerException != null)
        exceptionMessage.Append("\n" + prepend + "InnerException: " +
                                FormatExceptionMessage(exception.InnerException, 
                                ref title, out summary, prepend + "\t"));

    return exceptionMessage.ToString();
}

private static string GetOtherExceptionProperties(Exception exception, string s)
{
    var allOtherProps = new StringBuilder();
    var exPropList = exception.GetType().GetProperties();

    var propertiesAlreadyHandled = new List<string> { "StackTrace", "Message", 
        "InnerException", "Data", "HelpLink", "Source", "TargetSite" };
    foreach (var prop in exPropList.Where(prop => !propertiesAlreadyHandled.Contains(prop.Name)))
    {
        allOtherProps.Append(s + string.Format("{0} : {1}", prop.Name, 
          exception.GetType().GetProperty(prop.Name).GetValue(exception, null)));
    }

    return allOtherProps.ToString();
}

Exception Shielding, or Handling Across Layers

A relatively simply extension to the above logging enables us to provide a means for application code to shield exception details from a calling layer of the application, while preserving the ability to correlate the items.

In the following code, we take an incoming exception (from the lower layer, like Wcf services or something), inject a GUID into it, log it -- all details, then pass a string back to the caller with the GUID and the name of the method that threw the exception, which can then be injected into a new Exception (like a FaultException). I'll show some sample code from both sides of a layer in the "Writing Application Code" section

public static string Handle(Exception ex, SuperLoggingCategory category, Dictionary<string, object> dict)
{
    var handlingInstance = Guid.NewGuid().ToString();
    dict.Add("ErrorId", handlingInstance);
    SuperLogger.WriteLog(ex, category, dict);
    return string.Format("An error occurred inside the service call [{0}]. --> ErrorId: {1}", 
                         ex.TargetSite.Name, handlingInstance);
}

Performance Logging

Based on the infrastructure already created, we can very simply extend it to log even more custom information!! In order to do this, we need a PerfLog table (again, I'm wanting to log information to a table for reporting purposes), a stored proc, and just a little bit of code.

The table information and stored procedure are in the attached zip file -- you would just need to promote the table and proc in your logging database and make sure the msqmDistributor.exe.config file's Performance category and listener are properly configured.

Once you've done that, consider the code below. It defines constructors which will start the performance tracking. You provide a name (e.g., "CustomerSearch") to it, and optionally a dictionary of parameters that would impact the performance you are tracking (e.g., a wildcard search may take more time than a key-based search). Then the Stop method logs everything using a standard call to the logger!

public PerfLogger(string name)
{
    _sw = Stopwatch.StartNew();
    PerfName = name;
    _beginTime = DateTime.Now;
    _details = new Dictionary<string, object>();
}

public PerfLogger(string name, Dictionary<string, object> perfParams) : this(name)
{
    foreach (var item in perfParams)
        _details.Add("input-" + item.Key, item.Value);
}

public void Stop()
{
    _sw.Stop();
    _details.Add("Started", _beginTime.ToString(CultureInfo.InvariantCulture));
    _details.Add("ElapsedMilliseconds", _sw.ElapsedMilliseconds.ToString(CultureInfo.InvariantCulture));
    _details.Add("PerfName", PerfName);

    SuperLogger.WriteLog("Performance captured for " + PerfName, 
                         SuperLoggingCategory.Performance, _details);
}

Writing Application Code

This is where it gets really cool. The code that calls into the SuperLogger.WriteLog function is really straightforward. For everything below, you will need a reference to SuperLogger and a using statement for CustomLogging. The ConsoleAppExample in the attached source code provides some working examples of this.

Just log a message (with or without categories)

SuperLogger.WriteLog("Just because....");
    // will go to the General category since one has not been specified.

Log a caught exception where a variable called currCustId will be helpful in troubleshooting the issue

Editorial Aside on when to catch exceptions: Only when you need to. This answer probably seems a bit trite, but I *have* spent some time thinking about it. In a console app, you should probably have one in the main function. In a WCF service library, you should probably have one in the method for an OperationContract. In a UI (including web stuff), you should probably have a global exception handler because it's tricky to ensure that all of the little places that can throw exceptions are caught and won't crash the ui. Beyond that, it comes down to when you can *add value* to the exception. This comes down to one of two things:

• Removing details. This is the case when you need to perform shielding at layer boundaries.
• Adding details. I see a best practice for this as throwing a new exception while including the original as the inner exception. My experience has brought two specific things to look for when considering whether to add details (wrap) an exception: (a) stored proc parameters, and (b) input parameters to your function. If you don't have any different information than places up the call stack would have, don't do anything to catch exceptions.

catch (Exception ex)
{
    SuperLogger.WriteLog(ex, SuperLoggingCategory.Batch, 
          new Dictionary<string, object> { {"CustomerId", currCustId}});
}

Logging an exception in a lower layer and shielding details from upper layer

Note: I am primarily dealing with shielding across WCF layers. The WcfExceptionHandler below (with code shown above for its Handle method) could easily be renamed LayeredExceptionHandler, or ExceptionSheilder.

catch (Exception ex)
{
    var fault = WcfExceptionHandler.Handle(ex);  /
    throw new FaultException(fault);
}

Catching and Logging the same exception from the upper layer

catch (FaultException ex)  // This will be a ThreadAbortException if you are doing async wcf calls
{
    SuperLogger.WriteLog(ex.Message, SuperLoggingCategory.UserInterface);
}

Performance Logging

var perfTracker = new PerfLogger("CustomerSearch", 
         new Dictionary<string, object> { { "CustomerID", customerId } } ;
// do customer search here....
perfTracker.Stop();

Reviewing the Logs

Creating log entries and getting them logged into the database is great, but part of the effectiveness of having good logs is making them easy to review and access. As my approach is definitely a little "classic," this is definitely an area in which you could really do whatever you want. My main point here is that it needs to be easy for people (and sometimes even business users and/or testers!!) to find or review the logs to make your job as a developer easier.

My approach for this is a bit antiquated but still works pretty well. Basically, I have a Classic ASP page that provides a search mechanism for the logs, then another page that actually performs a given search and renders the log details.

If you take a look at the screenshot below, you can see how quickly you can get to the "meat" of an entry pretty quickly. You can see the indentation of the InnerExceptions -- and note that I'm highlighting the Message property of each exception with a yellow background.

If you have an ASP server running somewhere, you can use the files in the ClassicAspViewer folder as a log viewer if you choose. The readme in that folder will help you get started. If you don't, you're on your own, but maybe the screenshot will give you some ideas....

Happy logging!!!

References/Sources

• Enterprise Library documentation
• John Sonmez's excellent PluralSight course on Enterprise Library Logging (and the one on Exception Handling
• Joe and Ben Albahari's C# In a Nutshell

History

• v1.0 Initial submission.
• v.1.01 Fixed some null ref issues and added the Exception.Data fields to the recursive exception formatting.