Custom Error Reporting with log4net

I recently started a new position where hunting for errors included logging into one of two active web servers, looking over a couple of directories that were logging via log4net, and also checking the Windows event log.  Needless to say this was a PITA.  I decided my first initiative was to try and improve the visibility into our application errors, to better understand our production issues.  To confound the issue we weren't getting context like server variables (browser, referring url, ect) or the user logged in, which can be very helpful in the discovery process and also for support.  Typically I would try to use something like Elmah, because the less work the better, but there are a few snags.  One, we are using a custom db session provider which helped to link the dying ASP pages to .NET.  Two, we use Fluorine and NHibernate, and they do alot of internal logging using log4net.  Additionally our existing app had log4net logging all over the place. So I decided to set out on a custom appender to consolidate.  There were a few configurations I thought of, but I settled on inserting all errors into the database and using an admin interface to view, datamine, and manage our exceptions.  First thing I had to do was insert a Global.asax in all 8 of our applications to catch all unmanaged exceptions. Each one had something like the following:

void Application_Error(object sender, EventArgs e) 
{ 
    // Code that runs when an unhandled error occurs 
    log4net.ILog log = log4net.LogManager.GetLogger("MyApp");
    if (log.IsErrorEnabled)
        log.Error("An uncaught exception occurred", this.Server.GetLastError());

}

void Application_Start(object sender, EventArgs e) 
{
    // Code that runs on application startup 
    log4net.Config.XmlConfigurator.Configure();
}

Next I wanted to find a decent database appender that wouldn't affect the performance of our app too much. Luckily I found Ayende's AsyncBulkInserAppender  which, as its name suggests, is both async and queues up inserts at a configurable queue length.  With some minor tweaks, I was able to get this to work with our app.  I added some additional context to get our user, ala cookie from current request, and I could also stuff server variables into a custom column I created.  I started by overriding the Append event for the appender.  Inside that event you can add custom context to the logging event.

protected override void Append (LoggingEvent loggingEvent)
{
    try
    {
        SetUrl(loggingEvent);             
    }
    catch (Exception ex)
    {
        ErrorHandler.Error("AsyncBulkInserterAppender ERROR", ex);
    }

    base.Append(loggingEvent);
}

protected virtual void SetUrl (LoggingEvent loggingEvent)
{
    if (IsInWebContext())
    {
        loggingEvent.Properties["url"] = HttpContext.Current.Request.Url.ToString();
    }
}

private bool IsInWebContext ()
{
    return HttpContext.Current != null;
}

Next I added the appender to a few configs and set them to log errors only.  I found out while doing this that you can cascade configs within the same directory, even if they are in different app pools.  So I simultaneously cleaned up alot of our redundant web.configs during this process.  One thing you'll need to know is how to add a custom column to your appender.  Here is an example of the column I used to store the url.

<mapping>
    <column value="Url" />
    <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%X{url}" />
    </layout>
</mapping>

Everything was going well, and I was ready to build my interface.  I tested each site by throwing an error and checking the log, then I realized that SOAP exceptions from web services were outside the normal pipeline, and thus weren't caught within the global.asax.  Shit.  I did a little more googlejerking and hacked together the following:

public class SoapExceptionHander : SoapExtension
{
    public override void ProcessMessage (System.Web.Services.Protocols.SoapMessage message)
    {
        if (message.Stage == SoapMessageStage.AfterSerialize)
        {
            if (message.Exception != null)
            {
                log4net.ILog log = log4net.LogManager.GetLogger("WebService");
                if (log.IsErrorEnabled)
                    log.Error("An uncaught web service exception occurred", message.Exception);
            }
        }
    }
    
    public override object GetInitializer(Type serviceType) 
    { 
        return null; 
    } 

    public override object GetInitializer(LogicalMethodInfo methodInfo, SoapExtensionAttribute attribute) 
    { 
        return null; 
    } 

    public override void Initialize(object initializer){ } 
    
}

Add added in this in the web.config:

.......
    <webServices> 
      <soapExtensionTypes> 
        <add type="YourNameSpace.SoapExceptionHander,YourDll" priority="1" group="High"/> 
      </soapExtensionTypes> 
    </webServices>    
</system.web>

One thing you *need* to know, is that you can't test this from the little test page that .Net creates. The best way to do this is call the web service from a test page, making sure the service is throwing an exception. Don't waste hours of your life trying to debug why your custom SoapExtension isn't working. Argggg.


So now I've got all errors from all applications logging into one place.  I built my interface, with a filter on just about everything.  I also added the ability to 'handle' exceptions as a means of managing errors that need attention.

Much better.  Now we are depressed at the amount of log4net errors and warnings we see, but atleast we can address them. :)  Next on my list is the ability to maintain and push a branch of svn for 'hotfixes' so we can address these bugs realtime without rolling out code that isn't ready for primetime.