NHibernate logging and removing NLog direct reference

In my previous post I’ve provided draft implementation of bridge between NHibernate and NLog. Bridge assembly was “hard” referenced against both NHibernate and NLog assemblies. In this post I’ll provide more advanced bridge implementation which won’t be referenced against NLog assembly at all

The idea was inspired by mechanism that NHibernate uses to avoid direct reference against Log4Net assembly.

First of all let’s review modified NLogFactory:

    public class NLogFactory : ILoggerFactory
    {
        private static readonly System.Type LogManagerType = System.Type.GetType("NLog.LogManager, NLog");
        private static readonly string NHibernateLoggerName = "nhibernate";

        private static Func<string, object> CreateLoggerInstanceFunc;

        static NLogFactory()
        {
            CreateLoggerInstanceFunc = CreateLoggerInstance();
        }

        #region ILoggerFactory Members

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

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

        #endregion

        private static Func<string, object> CreateLoggerInstance()
        {
            var method = LogManagerType.GetMethod("GetLogger", new[] { typeof(string) });
            ParameterExpression nameParam = Expression.Parameter(typeof(string));
            MethodCallExpression methodCall = Expression.Call(null, method, new Expression[] { nameParam });

            return Expression.Lambda<Func<string, object>>(methodCall, new[] { nameParam }).Compile();
        }
    }

As you can see we’re using compiled expression which is used to create Logger instance. LogManager is now stored as indirect type reference and resolved by string type name – “NLog.LogManager, NLog”.

Now let’s review NLogLogger implementation:

  public class NLogLogger : IInternalLogger
    {
        private static readonly System.Type LoggerType = System.Type.GetType("NLog.Logger, NLog");

        private static readonly Func<object, bool> DebugPropertyGetter;
        private static readonly Func<object, bool> ErrorPropertyGetter;
        private static readonly Func<object, bool> FatalPropertyGetter;
        private static readonly Func<object, bool> InfoPropertyGetter;
        private static readonly Func<object, bool> WarnPropertyGetter;

        private static readonly Action<object, string> DebugAction;
        private static readonly Action<object, string> ErrorAction;
        private static readonly Action<object, string> WarnAction;
        private static readonly Action<object, string> InfoAction;
        private static readonly Action<object, string> FatalAction;

        private static readonly Action<object, string, Exception> DebugExceptionAction;
        private static readonly Action<object, string, Exception> ErrorExceptionAction;
        private static readonly Action<object, string, Exception> WarnExceptionAction;
        private static readonly Action<object, string, Exception> InfoExceptionAction;
        private static readonly Action<object, string, Exception> FatalExceptionAction;

        private object log;

        static NLogLogger()
        {
            DebugPropertyGetter = CreatePropertyGetter("IsDebugEnabled");
            ErrorPropertyGetter = CreatePropertyGetter("IsErrorEnabled");
            FatalPropertyGetter = CreatePropertyGetter("IsFatalEnabled");
            InfoPropertyGetter = CreatePropertyGetter("IsInfoEnabled");
            WarnPropertyGetter = CreatePropertyGetter("IsWarnEnabled");

            DebugAction = CreateSimpleAction("Debug");
            ErrorAction = CreateSimpleAction("Error");
            WarnAction = CreateSimpleAction("Warn");
            InfoAction = CreateSimpleAction("Info");
            FatalAction = CreateSimpleAction("Fatal");

            DebugExceptionAction = CreateExceptionAction("Debug");
            ErrorExceptionAction = CreateExceptionAction("Error");
            WarnExceptionAction = CreateExceptionAction("Warn");
            InfoExceptionAction = CreateExceptionAction("Info");
            FatalExceptionAction = CreateExceptionAction("Fatal");
        }

        public NLogLogger(object log)
        {
            this.log = log;
        }

        #region IInternalLogger Members

        #region Properties

        public bool IsDebugEnabled
        {
            get
            {
                return DebugPropertyGetter(log);
            }
        }

        public bool IsErrorEnabled
        {
            get
            {
                return ErrorPropertyGetter(log);
            }
        }

        public bool IsFatalEnabled
        {
            get
            {
                return FatalPropertyGetter(log);
            }
        }

        public bool IsInfoEnabled
        {
            get
            {
                return InfoPropertyGetter(log);
            }
        }

        public bool IsWarnEnabled
        {
            get
            {
                return WarnPropertyGetter(log);
            }
        }

        #endregion

        #region IInternalLogger Methods

        public void Debug(object message, Exception exception)
        {
            if (message == null || exception == null)
                return;

            DebugExceptionAction(log, message.ToString(), exception);
        }

        public void Debug(object message)
        {
            if (message == null)
                return;

            DebugAction(log, message.ToString());
        }

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

        public void Error(object message, Exception exception)
        {
            if (message == null || exception == null)
                return;

            ErrorExceptionAction(log, message.ToString(), exception);
        }

        public void Error(object message)
        {
            if (message == null)
                return;

            ErrorAction(log, message.ToString());
        }

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

        public void Fatal(object message, Exception exception)
        {
            if (message == null || exception == null)
                return;

            FatalExceptionAction(log, message.ToString(), exception);
        }

        public void Fatal(object message)
        {
            if (message == null)
                return;

            FatalAction(log, message.ToString());
        }

        public void Info(object message, Exception exception)
        {
            if (message == null || exception == null)
                return;

            InfoExceptionAction(log, message.ToString(), exception);
        }

        public void Info(object message)
        {
            if (message == null)
                return;

            InfoAction(log, message.ToString());
        }

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

        public void Warn(object message, Exception exception)
        {
            if (message == null || exception == null)
                return;

            WarnExceptionAction(log, message.ToString(), exception);
        }

        public void Warn(object message)
        {
            if (message == null)
                return;

            WarnAction(log, message.ToString());
        }

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

        #endregion

        #endregion

        #region Private methods

        private static Func<object, bool> CreatePropertyGetter(string propertyName)
        {
            ParameterExpression paramExpr = Expression.Parameter(typeof(object), "pv");
            Expression convertedExpr = Expression.Convert(paramExpr, LoggerType);
            Expression property = Expression.Property(convertedExpr, propertyName);

            return Expression.Lambda<Func<object, bool>>(property, new[] { paramExpr }).Compile();
        }

        private static Action<object, string> CreateSimpleAction(string methodName)
        {
            MethodInfo methodInfo = GetMethodInfo(methodName, new[] { typeof(string) });
            ParameterExpression instanceParam = Expression.Parameter(typeof(object), "i");
            var converterInstanceParam = Expression.Convert(instanceParam, LoggerType);
            ParameterExpression messageParam = Expression.Parameter(typeof(string), "m");

            MethodCallExpression methodCall = Expression.Call(converterInstanceParam, methodInfo, new Expression[] { messageParam });

            return (Action<object, string>)Expression.Lambda(methodCall, new[] { instanceParam, messageParam }).Compile();
        }

        private static Action<object, string, Exception> CreateExceptionAction(string methodName)
        {
            MethodInfo methodInfo = GetMethodInfo(methodName, new[] { typeof(string), typeof(Exception) });

            ParameterExpression messageParam = Expression.Parameter(typeof(string), "m");
            ParameterExpression instanceParam = Expression.Parameter(typeof(object), "i");
            ParameterExpression exceptionParam = Expression.Parameter(typeof(Exception), "e");
            var convertedParam = Expression.Convert(instanceParam, LoggerType);

            MethodCallExpression methodCall = Expression.Call(convertedParam, methodInfo, new Expression[] { messageParam, exceptionParam });

            return (Action<object, string, Exception>)Expression.Lambda(methodCall, new[] { instanceParam, messageParam, exceptionParam }).Compile();
        }

        private static MethodInfo GetMethodInfo(string methodName, System.Type[] parameters)
        {
            return LoggerType.GetMethod(methodName, parameters);
        }

        #endregion
    }

The same is here — NLogLogger now stores indirect type reference for NLog.Logger type and all it’s methods are invoked using compiled expressions. Now you don’t need to recompile bridge every time NLog.dll assembly is changed. Also performance is really good if compared to direct delegate invocation. Actually there is almost no difference between compiled expressions and direct method calls in our scenario. I’ll provide perforemance measurements ASAP.

In order to use this bridge you should compile code into assembly and edit your main app.config:

<?xml version="1.0"?>
<configuration>
  <appSettings>
    <add key="nhibernate-logger"
              value="NHibernate.Logging.NLogFactory, NHibernate.Logging"/>
  </appSettings>
</configuration>

I’m assuming that your assembly is called NHibernate.Logging.dll.

Finally let’s review 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="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 name="asyncFileNHibernate"  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" />
  </targets>
  <rules>
    <logger name="nhibernate" writeTo="asyncFileNHibernate" final="true"/>
    <logger name="*" writeTo="asyncFileError"/>
  </rules>
</nlog>

There are two rules there. One is called nhibernate. This is must-have rule if you want our bridge working. Make target of this rule whatever you want (in our case this is file target). Second rule is for everything not connected to NHibernate logging.

You can download code from here

Sadly but I’ve got no time at all to create nuget package as José F. Romaniello did here with previous version.

Advertisements

5 Responses to “NHibernate logging and removing NLog direct reference”

  1. Tiendq Says:

    Hi,

    Thanks for your code but I couldn’t have it works, there was no log file created at all. Am I missing any configuration?

  2. Tiendq Says:

    Just accidentally found out it needs ${basedir} in fileName, that not existed in your configuration file (and it still works for you?), great trick!.

  3. Someone Says:

    This nukes the $(callsite) information… .lambda_method is all it can come up with. Not always a terrible thing, considering the dependancies, but it does make it impossible to push the log entries to a different file for all NHibernate.* or NHibernate.SQL

  4. Casey Says:

    Hi, I have tried to use your code to use NLog with NHibernate. Am I right to say that once I added the appsettings and the NHibernate.Logging.dll, i should be all set and ready to go?

    However, this isn’t working for me. I’m not sure where I’m going wrong. Is it possible if you can provide a working example where I can try out? I’m already at my wits end. I’ve tried both Common Logging and your bridge. Would much prefer your approach. Common logging is not working for me either, as I don’t understand how to go about configuring it.

    Thanks!


Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: