NHibernate and NLog

NHibernate 3 introduces new ILoggerFactory interface which allows it to integrate with NLog (and possibly any other logging framework). This is though a bit tricky. In this article I will provide fully working integration between NHibernate 3x and NLog

Update: More advanced version is available here

In order to allow NHibernate 3 to use NLog framework several steps should be achieved:

1. Custom ILoggerFactory implementation should be provided
2. App.config should be modified in order to force NHibernate using custom ILoggerFactory implementation
3. NLog should be properly configured

Let’s go through all these steps.

First of all let’s review ILoggerFactory interface itself:

#region Assembly NHibernate.dll, v2.0.50727
// D:\Projects\WMediaCatalog\Lib\NHibernate\NHibernate.dll
#endregion

namespace NHibernate
{
    public interface ILoggerFactory
    {
        IInternalLogger LoggerFor(string keyName);
        IInternalLogger LoggerFor(System.Type type);
    }
}

It is built-in into NHibernate.dll assembly so whenever new version of NHibernate library is released we should recompile our custom ILoggerFactory implementation. If NHibernate core developers would extracted ILoggerFactory into separate library the life would be much more easier. Anyways factory creates IInternalLogger product. Here it is:

#region Assembly NHibernate.dll, v2.0.50727
// D:\Projects\WMediaCatalog\Lib\NHibernate\NHibernate.dll
#endregion

namespace NHibernate
{
    public interface IInternalLogger
    {
        bool IsDebugEnabled { get; }
        bool IsErrorEnabled { get; }
        bool IsFatalEnabled { get; }
        bool IsInfoEnabled { get; }
        bool IsWarnEnabled { get; }

        void Debug(object message);
        void Debug(object message, Exception exception);
        void DebugFormat(string format, params object[] args);
        void Error(object message);
        void Error(object message, Exception exception);
        void ErrorFormat(string format, params object[] args);
        void Fatal(object message);
        void Fatal(object message, Exception exception);
        void Info(object message);
        void Info(object message, Exception exception);
        void InfoFormat(string format, params object[] args);
        void Warn(object message);
        void Warn(object message, Exception exception);
        void WarnFormat(string format, params object[] args);
    }
}

It is also built-in into NHibernate.dll assembly so it should be also extracted into separate assembly. Let’s provide custom implementation. Create new class library project within Visual Studio, add following class, reference NHibernate.dll and NLog.dll and finally compile the project:

using System;
using System.Collections.Specialized;
using System.Configuration;
using NLog;

namespace NHibernate.Logging
{
    public class NLogFactory : ILoggerFactory
    {
        #region ILoggerFactory Members

        public IInternalLogger LoggerFor(System.Type type)
        {
            return new NLogLogger();
        }

        public IInternalLogger LoggerFor(string keyName)
        {
            return new NLogLogger();
        }

        #endregion
    }

    public class NLogLogger : IInternalLogger
    {
        private static readonly NLog.Logger log = LogManager.GetCurrentClassLogger();

        private static readonly string ConfigSectionName = "nhibernate_nlog";

        private static readonly string DebugKey = "debug";
        private static readonly string ErrorKey = "error";
        private static readonly string FatalKey = "fatal";
        private static readonly string InfoKey = "info";
        private static readonly string WarnKey = "warn";

        public NLogLogger()
        {
            InitProperties();
        }

        #region IInternalLogger Members

        #region Properties

        public bool IsDebugEnabled { get; private set; }

        public bool IsErrorEnabled { get; private set; }

        public bool IsFatalEnabled { get; private set; }

        public bool IsInfoEnabled { get; private set; }

        public bool IsWarnEnabled { get; private set; }

        #endregion

        #region IInternalLogger Methods

        public void Debug(object message, Exception exception)
        {
            if (IsDebugEnabled)
                log.DebugException(message.ToString(), exception);
        }

        public void Debug(object message)
        {
            if (IsDebugEnabled)
                log.Debug(message.ToString());
        }

        public void DebugFormat(string format, params object[] args)
        {
            if (IsDebugEnabled)
                log.Debug(String.Format(format, args));
        }

        public void Error(object message, Exception exception)
        {
            if (IsErrorEnabled)
                log.ErrorException(message.ToString(), exception);
        }

        public void Error(object message)
        {
            if (IsErrorEnabled)
                log.Error(message.ToString());
        }

        public void ErrorFormat(string format, params object[] args)
        {
            if (IsErrorEnabled)
                log.Error(String.Format(format, args));
        }

        public void Fatal(object message, Exception exception)
        {
            if (IsFatalEnabled)
                log.FatalException(message.ToString(), exception);
        }

        public void Fatal(object message)
        {
            if (IsFatalEnabled)
                log.Fatal(message.ToString());
        }

        public void Info(object message, Exception exception)
        {
            if (IsInfoEnabled)
                log.InfoException(message.ToString(), exception);
        }

        public void Info(object message)
        {
            if (IsInfoEnabled)
                log.Info(message.ToString());
        }

        public void InfoFormat(string format, params object[] args)
        {
            if (IsInfoEnabled)
                log.Info(String.Format(format, args));
        }

        public void Warn(object message, Exception exception)
        {
            if (IsWarnEnabled)
                log.WarnException(message.ToString(), exception);
        }

        public void Warn(object message)
        {
            if (IsWarnEnabled)
                log.Warn(message.ToString());
        }

        public void WarnFormat(string format, params object[] args)
        {
            if (IsWarnEnabled)
                log.Warn(String.Format(format, args));
        }

        #endregion

        #endregion

        #region Private methods

        private void InitProperties()
        {
            IsErrorEnabled = true;
            IsFatalEnabled = true;
            IsWarnEnabled = true;

            //System.Diagnostics.Debug.WriteLine("Finding section");
            var section = ConfigurationManager.GetSection(ConfigSectionName) as NameValueCollection;

            //System.Diagnostics.Debug.WriteLine(section != null ? "Section found" : "Section not found");

            if (section != null)
            {
                bool flag = false;

                if (section[DebugKey] != null && Boolean.TryParse(section[DebugKey], out flag))
                    IsDebugEnabled = flag;
                if (section[ErrorKey] != null && Boolean.TryParse(section[ErrorKey], out flag))
                    IsErrorEnabled = flag;
                if (section[FatalKey] != null && Boolean.TryParse(section[FatalKey], out flag))
                    IsFatalEnabled = flag;
                if (section[InfoKey] != null && Boolean.TryParse(section[InfoKey], out flag))
                    IsInfoEnabled = flag;
                if (section[WarnKey] != null && Boolean.TryParse(section[WarnKey], out flag))
                    IsWarnEnabled = flag;
            }
        }

        #endregion
    }
}

The tricky point is that we allow users to create custom configuration section nhibernate_nlog inside app.config and tune what should be written into log file. After you’ve got the compiled assembly our first step (and the major one) is complete.
Now let’s tell to NHibernate that we want to use our custom NLogFactory and NLogLogger. Current implementation of NHibernate (3.1) looks for nhibernate-logger key inside appSettings section. Let’s add these lines into app.config:

<?xml version="1.0"?>
<configuration>
  <configSections>
    <section name="nhibernate_nlog" type="System.Configuration.NameValueSectionHandler"/>
  </configSections>
  <nhibernate_nlog>
    <add key="debug" value="false"/>
    <add key="info" value="false"/>
  </nhibernate_nlog>
  <appSettings>
    <add key="nhibernate-logger"
              value="NHibernate.Logging.NLogFactory, NHibernate.Logging"/>
  </appSettings>
</configuration>

As you can see we ask NHibernate to use our custom NLogFactory for logging. Factory itself will create NLogLogger product for actual logging. In nhibernate_nlog section we specify that NHbiernate shouldn’t write debug and info levels’ messages. You can use following keys in order to tune logging behavior:

1. debug
2. error
3. fatal
4. info
5. warn

Our second step is now complete. Finally let’s finish our third (and last step) – configure NLog itself. Personally I really like the idea of separated configurations. That’s why I’ve created separate NLog.config:

<?xml version="1.0" encoding="utf-8" ?>
<nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
  <targets>
    <target name="asyncFileError" xsi:type="AsyncWrapper">
      <target name="file"  xsi:type="File" layout="${date:format=dd/MM/yyyy HH\:mm\:ss.mmm}${newline}${level} ${logger} - ${exception:format=tostring} [${callsite}]${newline}"
            fileName="Log.log"
            archiveFileName="Log.{#####}.log"
            archiveAboveSize="100240"
            archiveNumbering="Sequence"
            maxArchiveFiles="10" encoding="UTF-8"  createDirs="true" />
    </target>
    <target name="asyncFileNHibernate" xsi:type="AsyncWrapper">
      <target name="file"  xsi:type="File" layout="${date:format=dd/MM/yyyy HH\:mm\:ss.mmm}${newline}${level} ${logger} ${message} ${newline}"
            fileName="NHibernate.log"
            archiveFileName="NHibernate.{#####}.log"
            archiveAboveSize="100240"
            archiveNumbering="Sequence"
            maxArchiveFiles="10" encoding="UTF-8"  createDirs="true" />
    </target>
  </targets>
  <rules>
    <logger name="NHibernate.Logging.NLogLogger" writeTo="asyncFileNHibernate" final="true"/>
    <logger name="*" writeTo="asyncFileError"/>
  </rules>
</nlog>

If you like to mix all things in one place (nothing personal) then you can keep NLog config inside app.config. Anyways let’s analize NLog.config:

1. We’ve got two rules NHibernate.Logging.NLogLogger and *
2. NHibernate.Logging.NLogLogger rule is marked as final. This means that when HNibernate will want to write something into log it will use appropriative method of NLogLogger  Warn(), Error(), Debug() etc. (depending on level) log messages will be handled by first rule and due-to it’s final mark nothing NHibernate related stuff will be handled by second rule
3. Second rule will handle all other logging for your application

Now we’ve finished. You can safely remove log4net.dll assembly from your application and our bridge assembly will be used by NHibernate instead of it. Here is the sample log:

03/05/2011 18:56:13.56
Debug NHibernate.Logging.NLogLogger Obtaining IDbConnection from Driver

03/05/2011 18:56:13.56
Debug NHibernate.Logging.NLogLogger ExecuteReader took 4 ms

03/05/2011 18:56:13.56
Debug NHibernate.Logging.NLogLogger Opened IDataReader, open IDataReaders: 1

03/05/2011 18:56:13.56
Debug NHibernate.Logging.NLogLogger result row:

03/05/2011 18:56:13.56
Debug NHibernate.Logging.NLogLogger returning '0' as column: y0_

03/05/2011 18:56:13.56
Debug NHibernate.Logging.NLogLogger running NHybridDataReader.Dispose()

03/05/2011 18:56:13.56
Debug NHibernate.Logging.NLogLogger Closed IDataReader, open IDataReaders :0

03/05/2011 18:56:13.56
Debug NHibernate.Logging.NLogLogger DataReader was closed after 6 ms

03/05/2011 18:56:13.56
Debug NHibernate.Logging.NLogLogger Closed IDbCommand, open IDbCommands: 0

03/05/2011 18:56:13.56
Debug NHibernate.Logging.NLogLogger aggressively releasing database connection

03/05/2011 18:56:13.56
Debug NHibernate.Logging.NLogLogger Closing connection

03/05/2011 18:56:13.56
Debug NHibernate.Logging.NLogLogger total objects hydrated: 0

03/05/2011 18:56:13.56
Debug NHibernate.Logging.NLogLogger closing session

03/05/2011 18:56:13.56
Debug NHibernate.Logging.NLogLogger running BatcherImpl.Dispose(true)

03/05/2011 18:56:13.56
Debug NHibernate.Logging.NLogLogger [session-id=7226e8aa-0d24-4993-835b-478b1ddb92e7] opened session at timestamp: 634400457737, for session factory: [/d7387edcdecf448f881bb9faf099b644]

03/05/2011 18:56:13.56
Debug NHibernate.Logging.NLogLogger put criteria=in  (Name ilike %%) alias=this0_

03/05/2011 18:56:13.56
Debug NHibernate.Logging.NLogLogger searching for Album

03/05/2011 18:56:13.56
Debug NHibernate.Logging.NLogLogger returning entity name=DataLayer.Entities.AlbumEntity for path=Album class=EntityCriteriaInfoProvider

03/05/2011 18:56:13.56
Debug NHibernate.Logging.NLogLogger put criteria=Name ilike %% alias=this0_

03/05/2011 18:56:13.56
Debug NHibernate.Logging.NLogLogger put criteria=NHibernate.Impl.CriteriaImpl+Subcriteria alias=albumentit1_

Post scriptum.

The real bad thing is that key logging extensibility interfaces are defined inside NHibernate.dll. This way our NLog bridge assembly directly references NHibernate.dll and every time new NHibernate is released we should recompile bridge against it. Separate assembly from NHibernate developers will really help.

Another thing is that we directly reference NLog assembly. We can use reflection and some caching/activation magic here though, but that’s a big bunch of work and possible material for another article.

Advertisement