Configuring NHibernate logging

NHibernate has a very extensible logging mechanism, and provides a log4net log provider out of the box. The log4net library is a highly customizable, open source logging framework. In this recipe, we'll show you a simple log4net configuration to log important NHibernate events to the Visual Studio debug output window.

Getting ready

Complete the earlier Configuring NHibernate with App.config or Web.config recipe.

How to do it...

1. Install log4net using NuGet Package Manager.
2. Open your application configuration file.
3. Inside the configSections element, declare a section for the log4net configuration:

   <section name="log4net"
   type="log4net.Config.Log4NetConfigurationSectionHandler, log4net"/>

4. After the hibernate configuration element, add this log4net configuration:

   <log4net>
   <appender name="trace" 
         type="log4net.Appender.TraceAppender, log4net">
     <layout type="log4net.Layout.PatternLayout, log4net">
     <param name="ConversionPattern" 
          value=" %date %level %message%newline" />
     </layout>
   </appender>
   <root>
     <level value="ALL" />
     <appender-ref ref="trace" />
   </root>
   <logger name="NHibernate">
     <level value="INFO" />
   </logger>
   </log4net>

5. At the beginning of your Main function, insert the following code to configure log4net:

   log4net.Config.XmlConfigurator.Configure();

6. Run your application.
7. Watch Visual Studio's debug output window.

How it works...

The log4net framework uses appenders, layouts, and loggers to format and control log messages from our application, including log messages from NHibernate.

Appenders define the destination for log messages. In this recipe, we've defined a trace appender, which writes our log messages to System.Diagnostics.Trace. When we debug our application, Visual Studio listens to the trace and copies each message to the debug output window.

Loggers are the source of log messages. The root element defines values for all loggers, which can be overridden using the logger element. In our configuration, we've declared that all messages should be written to the appender named trace.

In log4net, the log messages have priorities. In ascending order, they are DEBUG, INFO, WARN, ERROR, and FATAL. In our configuration, we can define a log level with one of these priorities, or with ALL or OFF. A level includes its priority and all the priorities above it. For example, a level of WARN will also log ERROR and FATAL messages. ALL is equivalent to DEBUG: all messages will be logged, and OFF suppresses all messages.

With our configuration, log4net will write messages from NHibernate with a priority of INFO, WARN, ERROR, and FATAL, and ALL messages from other sources.

There's more...

We can use log4net in our own application. Here's a simple example of what some code might look like with log4net logging:

using System.IO;
using log4net;
namespace MyApp.Project.SomeNamespace
{

    public class Foo
    {
        private static ILog log = LogManager.GetLogger(typeof(Foo));

        public string DoSomething()
        {
            log.Debug("We're doing something.");
            try
            {
                return File.ReadAllText("cheese.txt");
            }
            catch (FileNotFoundException)
            {
                log.Error("Somebody moved my cheese.txt");
                throw;
            }
        }
    }
}

We've defined a simple class named Foo. In the DoSomething() method, we write the log message, "We're doing something.", with a priority of DEBUG. Then we return the contents of the file cheese.txt. If the file doesn't exist, we log an error and throw the exception.

Because we passed in typeof(Foo) when getting the logger, the Foo logger is named MyApp.Project.SomeNamespace.Foo, similar to the type. This is the typical naming convention when using log4net.

Suppose we were no longer concerned with debug level messages from Foo, but we still wanted to know about warnings and errors. We can then redefine the log level with this simple addition to our configuration, as shown in the following code:

<logger name="MyApp.Project.SomeNamespace.Foo">
  <level value="WARN" />
</logger>

Alternatively, we can set the log level for the entire namespace or even the entire project with this configuration, as follows:

<logger name="MyApp.Project">
  <level value="WARN" />
</logger>

Using logger to troubleshoot NHibernate

When we set NHibernate's show_sql configuration property to true, NHibernate will write all SQL statements to Console.Out. This is handy in some cases, but many applications don't use console output. With a properly configured logger, we can write the SQL statements to the trace output instead.

NHibernate also writes every SQL statement to a logger named NHibernate.SQL. These log messages have DEBUG priority. When we add the following snippet to our configuration, we can redefine the log level for this specific logger. We will get every SQL statement in the trace output, as follows:

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

Using other log providers

NHibernate also provides the IInternalLogger interface which facilitates logger abstraction. If you want to use other log providers you can provide an implementation for your favorite logger. There is also an NHibernate.Logging project which provides implementation for the Common.Logging logging abstraction framework. Common.Logging supports log4net, NLog, and Enterprise Library logging frameworks, so you can use any of them with NHibernate via this abstraction. Download NHibernate.Logging from https://github.com/mgernand/NHibernate.Logging or install it from NuGet.

To enable the log provider you have to add the following lines to your App.config or Web.config:

<appSettings>
  <add key="nhibernate-logger" 
       value = 
"NHibernate.Logging.CommonLogging.CommonLoggingLoggerFactory, NHibernate.Logging.CommonLogging"/>
</appSettings>

See also

• Configuring NHibernate with App.config or Web.config
• Using NHibernate Profiler