Using NLog with Dependency Injection

Download the code for this blog post.

In my last post I blogged about using Dependency Injection to break tight coupling between application components.  This lets you to treat infrastructure pieces, such as data access or logging, as swappable entities, allowing your application to change with the times as new technology stacks replace obsolete or deprecated ones.

NLog

In this blog post I will share how I took an open-source logging framework, called NLog, and made it injectable by an DI (Ioc) container, such as Ninject.  There’s no reason you couldn’t apply this same technique with other logging frameworks, such as Log4Net, or DI containers, such as StructureMap.

ninject-logo

Before I set out, I searched for an existing solution and found Ninject.Extensions.Logging.nlog2 in the NuGet online gallery.  However, when I applied the solution I ran into a security exception that stopped me in my tracks. (The author as promised to fix it in the next version but has not set a timeline.)  In addition, I found some shortcomings in how NLog records exception details and ended up building a thin wrapper that provides richer information on exceptions, such as the assembly, class and method in which the exception occurred.

My first order of business was to create an ILoggingService interface, so as to decouple consumers from the actual logging framework.

public interface ILoggingService
{
    bool IsDebugEnabled { get; }
    bool IsErrorEnabled { get; }
    bool IsFatalEnabled { get; }
    bool IsInfoEnabled { get; }
    bool IsTraceEnabled { get; }
    bool IsWarnEnabled { get; }

    void Debug(Exception exception);
    void Debug(string format, params object[] args);
    void Debug(Exception exception, string format, params object[] args);
    void Error(Exception exception);
    void Error(string format, params object[] args);
    void Error(Exception exception, string format, params object[] args);
    void Fatal(Exception exception);
    void Fatal(string format, params object[] args);
    void Fatal(Exception exception, string format, params object[] args);
    void Info(Exception exception);
    void Info(string format, params object[] args);
    void Info(Exception exception, string format, params object[] args);
    void Trace(Exception exception);
    void Trace(string format, params object[] args);
    void Trace(Exception exception, string format, params object[] args);
    void Warn(Exception exception);
    void Warn(string format, params object[] args);
    void Warn(Exception exception, string format, params object[] args);
}

I then implemented the interface in a LoggingService class, placing it in a separate assembly than ILoggingService, so that consumers could reference the interface without referencing the implementation assembly, which included some custom layout renderers for UTC dates and web variables (borrowed from here).  I also had to call an overload of the Log method that accepts the custom logger type so that NLog would ignore the logger when analyzing the call stack.

public class LoggingService : NLog.Logger, ILoggingService
{
    private const string _loggerName = "NLogLogger";

    public static ILoggingService GetLoggingService()
    {
        ConfigurationItemFactory.Default.LayoutRenderers
            .RegisterDefinition("utc_date", typeof(UtcDateRenderer));
        ConfigurationItemFactory.Default.LayoutRenderers
            .RegisterDefinition("web_variables", typeof(WebVariablesRenderer));
        ILoggingService logger = (ILoggingService)LogManager.GetLogger("NLogLogger", typeof(LoggingService));
        return logger;
    }

    public void Debug(Exception exception, string format, params object[] args)
    {
        if (!base.IsDebugEnabled) return;
        var logEvent = GetLogEvent(_loggerName, LogLevel.Debug, exception, format, args);
        base.Log(typeof(LoggingService), logEvent);
    }

    public void Error(Exception exception, string format, params object[] args)
    {
        if (!base.IsErrorEnabled) return;
        var logEvent = GetLogEvent(_loggerName, LogLevel.Error, exception, format, args);
        base.Log(typeof(LoggingService), logEvent);
    }

    public void Fatal(Exception exception, string format, params object[] args)
    {
        if (!base.IsFatalEnabled) return;
        var logEvent = GetLogEvent(_loggerName, LogLevel.Fatal, exception, format, args);
        base.Log(typeof(LoggingService), logEvent);
    }

    public void Info(Exception exception, string format, params object[] args)
    {
        if (!base.IsInfoEnabled) return;
        var logEvent = GetLogEvent(_loggerName, LogLevel.Info, exception, format, args);
        base.Log(typeof(LoggingService), logEvent);
    }

    public void Trace(Exception exception, string format, params object[] args)
    {
        if (!base.IsTraceEnabled) return;
        var logEvent = GetLogEvent(_loggerName, LogLevel.Trace, exception, format, args);
        base.Log(typeof(LoggingService), logEvent);
    }

    public void Warn(Exception exception, string format, params object[] args)
    {
        if (!base.IsWarnEnabled) return;
        var logEvent = GetLogEvent(_loggerName, LogLevel.Warn, exception, format, args);
        base.Log(typeof(LoggingService), logEvent);
    }

    public void Debug(Exception exception)
    {
        this.Debug(exception, string.Empty);
    }

    public void Error(Exception exception)
    {
        this.Error(exception, string.Empty);
    }

    public void Fatal(Exception exception)
    {
        this.Fatal(exception, string.Empty);
    }

    public void Info(Exception exception)
    {
        this.Info(exception, string.Empty);
    }

    public void Trace(Exception exception)
    {
        this.Trace(exception, string.Empty);
    }

    public void Warn(Exception exception)
    {
        this.Warn(exception, string.Empty);
    }

    private LogEventInfo GetLogEvent(string loggerName, LogLevel level, Exception exception, string format, object[] args)
    {
        string assemblyProp = string.Empty;
        string classProp = string.Empty;
        string methodProp = string.Empty;
        string messageProp = string.Empty;
        string innerMessageProp = string.Empty;

        var logEvent = new LogEventInfo
            (level, loggerName, string.Format(format, args));

        if (exception != null)
        {
            assemblyProp = exception.Source;
            classProp = exception.TargetSite.DeclaringType.FullName;
            methodProp = exception.TargetSite.Name;
            messageProp = exception.Message;

            if (exception.InnerException != null)
            {
                innerMessageProp = exception.InnerException.Message;
            }
        }

        logEvent.Properties["error-source"] = assemblyProp;
        logEvent.Properties["error-class"] = classProp;
        logEvent.Properties["error-method"] = methodProp;
        logEvent.Properties["error-message"] = messageProp;
        logEvent.Properties["inner-error-message"] = innerMessageProp;
            
        return logEvent;
    }
}

The Visual Studio solution includes a DependencyResolution project in the solution with a NinjectModule class that binds ILoggingService to the concrete LoggingService implementation. It turns out that the NLog.config file needs to be placed in the same directory as this assembly’s dll, by setting the “Copy to Output Directory” property of the file to “Copy Always.”  While I could have created a custom exception renderer, I simply used the convenient Event-context layout renderer.

<?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">

  <!-- make sure to set 'Copy To Output Directory' option for this file -->
  <!-- go to http://nlog-project.org/wiki/Configuration_file for more information -->

  <targets>
    <target name="console"
            xsi:type="ColoredConsole"
            layout="Server-Date: ${longdate}; UTC-Date: ${utc_date}; Level: ${level}; Log-Message: ${message}; Error-Source: ${event-context:item=error-source}; Error-Class: ${event-context:item=error-class}; Error-Method: ${event-context:item=error-method}; Error-Message: ${event-context:item=error-message}; Inner-Error-Message: ${event-context:item=inner-error-message}" />
    <target name="debug"
            xsi:type="Debugger"
            layout="Server-Date: ${longdate}; UTC-Date: ${utc_date}; Level: ${level}; Log-Message: ${message}; Error-Source: ${event-context:item=error-source}; Error-Class: ${event-context:item=error-class}; Error-Method: ${event-context:item=error-method}; Error-Message: ${event-context:item=error-message}; Inner-Error-Message: ${event-context:item=inner-error-message}" />
  </targets>

  <rules>
    <logger name="*" 
            minlevel="Trace" 
            writeTo="console,debug" />
  </rules>
</nlog>

I created a simple console app to test the logger by newing up a widget and calling a method that throws an exception.

class Program
{
    static void Main(string[] args)
    {
        IKernel kernel = new StandardKernel(new LoggingModule());

        var provider = kernel.Get<WidgetProvider>();

        var widget = new Widget();

        provider.UseWidget(widget);

        Console.WriteLine("Press Enter to Exit");
        Console.ReadLine();
    }
}

The UseWidget method catches an exception thrown by the Widget.Foo method, calling ILoggingService.Error and passing the exception.

public class WidgetProvider
{
    private readonly ILoggingService _logger;

    public WidgetProvider(ILoggingService logger)
    {
        _logger = logger;
    }

    public void UseWidget(Widget widget)
    {
        try
        {
            widget.Foo();
        }
        catch (Exception ex)
        {
            _logger.Error(ex);
        }
    }
}

Here is the exception thrown by Widget.Foo:

public class Widget
{
    public void Foo()
    {
        throw new Exception("Never divide by zero",
            new DivideByZeroException());
    }
}

Running the console app produces the following output from the “console” logging target:

console-err-log

The Debug window shows the output of the “debug” logging target:

debug-err-log

Application components can log messages or exceptions using the injected ILoggingService interface.  You can download the code for this blog post here.  Enjoy.

About Tony Sneed

Married with three children.
This entry was posted in Technical and tagged , , . Bookmark the permalink.

14 Responses to Using NLog with Dependency Injection

  1. Price says:

    Thanks for the post. After reading it the following things came to my mind. I’d love to hear your thoughts on this.

    - I’d rename “ILoggingService” to “ILog” to better describe the role of the object. ILoggingService as well as ILogger seem to be based on a procedural way of thinking. The implementation would be called “ConsoleLog” or “ConsoleNLog” if you want to make it clear its about NLog.

    - Injecting services like the ILoggingService seem to be very comfortable. Doesn’t it introduce a coupling problem if you have 25 classes though? What if you make a breaking change in the ILoggingService interface? Now you have to change 25 classes. I was thinking about assigning the logging responsibility to a select amount of classes.

    - Giving the object the responsibility of creating itself seems weird. Things usually don’t create themselves. What about moving the LoggingService.GetLoggingService() code to the LoggingModule?

    - I have seen code in the wild using an extension method called “Log” on the “object” type which gives universal access to the logging facilities. What’s your take on this?

    - Also encountered in the wild is an implementation of LoggingService as a Singleton which is accessed in the entire application. What in your opinion are the advantages of using dependency injection over this singleton approach or the aforementioned “object”-extension-method approach?

    • Tony Sneed says:

      @price: Appreciate the questions. I’m not partial to one name over another for ILoggingService. I went with service, but ILog is fine too. The idea, however, is not to have a whole bunch of loggers that you are interchanging constantly. It’s more to future-proof your app by separating interface from implementation (see my post on the Onion Architecture). Loggers already have the ability to write to different targets (debug, files, databases, etc). That said, maybe you decide you like another logger that has some different features and you need to modify the ILog interface. In that case, I would recommend standard versioning practices, such as extending the interface, something like ILog2.

      Good point about refactoring out the GetLoggingService method and putting it in the LoggingModule. There are a few things I want to improve in the code now that I’ve put it out there. ;-)

      Not a big fan of extending object with logging methods (via extension methods). I want to inject it where needed. In the MVC app, it’s done in the startup code.

      A lot of times loggers are implemented as static or singleton. Not a great practice, in my opinion. But that is why you see solutions that wrap the logger in a class that implements an interface, so that different loggers can be injected by the DI container. Again, it’s about future-proofing your app.

      Cheers,
      Tony

  2. Mike says:

    Thanks. A solution I can use today!

  3. Nice solution I don’t know if you were aware of this but there is a extension on ninject that do what you where trying to acheive here. Take a look at https://github.com/ninject/ninject.extensions.logging

    • Tony Sneed says:

      Yes, I mentioned in the post that I had looked at the Ninject extension for NLog. I ran into a security exception which, at the time, had not yet been fixed. That was a show-stopper for me.

      However, there’s another issue. NLog itself (and consequently the Ninject.Extensions.Logging.NLog2) does not have very good support for logging exceptions. Basically, it does not record the location where the exception occurred (assembly, class, method) but rather where it was handled and logged. So I added that capability to my implementation.

      Cheers,
      Tony

  4. Stuart says:

    Great article. Never used NLog before today and this has got me off to a great start. Much appreciated.

  5. Guy Harwood says:

    very useful, wasn’t particularly looking forward to spending the afternoon writing a logging interface, but you’ve already done it. Thanks :)

  6. Johan says:

    You really should not use ninject seeing as it’s the most inefficient ioc there is to choose.

  7. Jerori says:

    Hi Tony, thanks for this post, I’m trying to implement this to my project with Onion Architecture and SimpleInjector, I had some issues before: https://simpleinjector.codeplex.com/discussions/433233 ; but it’s working fine now; however my log file is not being created, if you have a clue I’d really appreciate any feedback.
    Thanks.
    – JR

  8. Jerori says:

    Thanks Tony, I made a mistake, I had a second .config file in UI layer, but it’s working fine now. However what do you suggest about to know what class is the source of logging a messages ?, something like: LogManager.GetCurrentClassLogger(); which returns back the class name as the logger source, so how could be done with dependency injection based on your proposal ?

  9. Ram says:

    Dear Tony.Happy to say that its an immense pleasure,i got after read this article.However i got a requirement now saying .a component/interface has to design to switch multiple logging components Nlog,Log4net,..Consumer will know only know that component/interface which we sharing,he never know about the events,logging type(Nlog/log4net) which we are implementing in our end.Please help how to implement this one?

    • Tony Sneed says:

      @Ram, Glad you liked the article! Switching between different logging components is simply a matter of configuring the IoC container with the selected component. That’s the advantage of using the logging interface. The application doesn’t care which component is used. Configuring the IoC container takes place at what is called the “composition root.” For a Web API project, this would be app startup. Concretely, you might want to drive that from a config file, so that the IoC configuration takes place at runtime based on config entries.

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