NHibernate and log4net

Here’s a quick trick for people using NHibernate and log4net within their .NET applications. (…and if you’re not using NHibernate or log4net, you should seriously think about it!)

Add the following to your log4net configuration to find out what’s going on inside NHibernate:

  <logger name="NHibernate">
    <level value="DEBUG" />
  </logger>
  <logger name="NHibernate.SQL">
    <level value="DEBUG" />
  </logger>

As those kind folks at NHibernate have already set up the loggers behind the scenes, everything just works. The SQL logger is especially useful as it’ll show you explicitly which SQL statements are being generated by NHibernate. You can adjust the levels of NHibernate logging independently of your normal application logging, which is useful as the NHibernate logs tend to be pretty verbose.

The full configuration will look something like this:

<log4net>
  <appender name="TraceAppender" type="log4net.Appender.TraceAppender" >
    <layout type="log4net.Layout.PatternLayout">
      <param name="ConversionPattern" value="%d %-5p- %m%n" />
    </layout>
  </appender>
  <appender name="RollingFileAppender" type="log4net.Appender.RollingFileAppender">
    <file value="Application.log"/>
    <appendToFile value="true"/>
    <rollingStyle value="Date"/>
    <datePattern value="yyyy-MM-dd'.log'"/>
    <layout type="log4net.Layout.PatternLayout">
      <conversionPattern value="%date [%thread] %-5level %logger [%property{NDC}] - %message%newline"/>
    </layout>
  </appender>
  <root>
    <level value="DEBUG"/>
    <appender-ref ref="TraceAppender"/>
    <appender-ref ref="RollingFileAppender"/>
  </root>
  <logger name="NHibernate">
    <level value="ERROR" />
  </logger>
  <logger name="NHibernate.SQL">
    <level value="ERROR" />
  </logger>
</log4net>

Basic Log4Net step-up

The following post explains how to get Log4Net working in a .NET console application.

The first step is create your console application and add references to Log4Net. The easiest way to add the correct references is via NuGet, where it is simply listed as log4net.

You’ll need to add a configuration file to tell Log4Net how you want it to log. A basic example would be:

<?xml version="1.0" encoding="utf-8" ?>
<configuration>
  
  <configSections>
    <section name="log4net" type="log4net.Config.Log4NetConfigurationSectionHandler,log4net" />
  </configSections>

  <log4net>
    <appender name="RollingFile" type="log4net.Appender.RollingFileAppender">
      <file value="Test.log" />
      <appendToFile value="true" />
      <maximumFileSize value="5000KB" />
      <maxSizeRollBackups value="50" />
      <layout type="log4net.Layout.PatternLayout">
        <conversionPattern value="%utcdate{yyyy-MM-dd HH:mm:ss.fffffff} - %level - %logger - %message%newline" />
      </layout>
    </appender>
    <root>
      <level value="DEBUG" />
      <appender-ref ref="RollingFile" />
    </root>
  </log4net>
  
</configuration>

This example simply adds a rolling log file. It’s called rolling because it starts a new log file at triggered intervals, allowing you to delete historical log files when you’ve finished with them. In this case, a new log file is started each time the current log file gets to 5000KB. It’s worth taking a look at the Log4Net documentation to find out about the different types of logging available. It is also possible to write your own appender if you want to do something not already built it to Log4Net.

In order to tell Log4Net to pick your configuration, you need to add the following to your application:

[assembly: XmlConfigurator]

The most obvious place for this is the AssemblyInfo.cs file.

This tells Log4Net to look in the default configuration file for the Log4Net configuration settings, but you can also tell Log4Net to look in another custom configuration file using the overloads available to the XmlConfigurator, although I prefer to keep all configuration in a single file.

Then it’s just a case of using the logger:

using System;
using log4net;

namespace Test
{
    public static class Program
    {
        public static void Main()
        {
            var log = LogManager.GetLogger(typeof(Program));
            log.Debug("Test console application started");

            Console.ReadLine();
        }
    }
}

Note that the LogManager returns an object implementing the ILog interface.

If you’re using dependency injection, you should wire up the dependency injector to return your ILog instance. The following shows how to do this if you’re using Castle Windsor:

using Castle.MicroKernel.Registration;
using Castle.Windsor;
using Castle.Windsor.Installer;
using log4net;

namespace Test
{
    public static class Injector
    {
        private static readonly object InstanceLock = new object();

        private static IWindsorContainer instance;

        public static IWindsorContainer Instance
        {
            get
            {
                lock (InstanceLock)
                {
                    return instance ?? (instance = GetInjector());
                }
            }
        }

        private static IWindsorContainer GetInjector()
        {
            var container = new WindsorContainer();

            container.Install(FromAssembly.This());

            RegisterInjector(container);
            RegisterLog(container);

            return container;
        }

        private static void RegisterInjector(WindsorContainer container)
        {
            container.Register(
                Component.For<IWindsorContainer>()
                    .Instance(container));
        }

        private static void RegisterLog(WindsorContainer container)
        {
            container.Register(
                Component.For<ILog>()
                    .Instance(LogManager.GetLogger(typeof(Injector)))
                    .LifestyleSingleton());
        }
    }
}

The following statement will return an ILog instance as expected:

var log = Injector.Instance.Resolve();

There you have it!

Exception extension method to show full exception details

While I think the exception model in .NET is very good, there are two aspects which can make diagnosing issues awkward, particularly when you are reading exception messages that have been written using logging components such as log4net. These are:

1. Strongly typed exceptions that inherit from the Exception base class may contain extra properties that hold vital information. These are not shown by default.
2. Exceptions can contain inner exceptions, and often these are more informative than the outer exception. Sometimes this can go three or four levels deep.

I’ve experienced aspect 1 when using a number of the Google APIs, and aspect 2 with NHibernate.

The Exception extension method given below solves these issues respectively by:

1. Using reflection to write out all properties.
2. Iterating through all exception levels.

Here’s the code:

using System;
using System.Linq;
using System.Text;

namespace ExtensionMethods
{
    public static class ExceptionExtensionMethods
    {
        public static string GetFullExceptionDetails(this Exception exception, string customMessage = null)
        {
            var message = new StringBuilder();
            var exceptionLevel = 0;
            var currentException = exception;

            if (string.IsNullOrEmpty(customMessage))
            {
                message.AppendLine(customMessage);
            }

            // Loop over exceptions and inner exceptions:
            while (currentException != null)
            {
                exceptionLevel++;

                var title = string.Format("Exception Level {0}", exceptionLevel);

                message.AppendLine(new string('=', title.Length));
                message.AppendLine(title);
                message.AppendLine(new string('=', title.Length));

                // Read all properties associated with the exception:
                message.AppendLine(currentException.GetExceptionProperties());
                message.AppendLine();

                // Get the next leve of exception:
                currentException = currentException.InnerException;
            }

            return message.ToString();
        }

        private static string GetExceptionProperties(this Exception exception)
        {
            var properties = exception.GetType().GetProperties();

            var fields = properties.Select(
                property =>
                String.Format("{0}: {1}", property.Name, (property.GetValue(exception, null) ?? String.Empty)));

            return String.Join(Environment.NewLine, fields);
        }
    }
}

…which can be demonstrated using the following console application:

using System;

namespace ExtensionMethods
{
    public static class Program
    {
        public static void Main()
        {
            try
            {
                var argumentException = new ArgumentException("Level 2", "parameter");
                var invalidOperationException = new InvalidOperationException("Level 1", argumentException);
                throw invalidOperationException;
            }
            catch (Exception exception)
            {
                Console.WriteLine(exception.GetFullExceptionDetails("An error occurred"));
                Console.ReadLine();
            }
        }
    }
}

This outputs:

Exception Extension Method

There is still room for improvement, particularly in dealing with properties that contain collections, but the extra information could prove invaluable so it’s well worth the effort.