Tuesday, March 22, 2011

Unity and log4net

In my current project at TouchStar, I’ve had the opportunity to play with Unity, Microsoft’s Inversion-of-Control container. Previously I’ve used StructureMap, which is very popular, but I wanted to broaden my experience of different containers, and given that my project involved a WPF client, Unity seemed to be a good choice.

One of the first problems was how to configure log4net using Unity. Usually, log4net is called from within a class thusly:

   1: public class MyClassWithLogger()
   2: {
   3:     private static readonly ILog Logger = LogManager.GetLogger(typeof(this));
   5:     public void DoAction()
   6:     {
   7:         Logger.Debug("Hello world");
   8:         DoSomeOtherAction();
   9:     }
  11:     private void DoSomeOtherAction()
  12:     {
  13:         Logger.Debug("Still here");
  14:     }
  15: }

Which, depending on how you’ve configured your appenders, would produce an output something like this:

   1: MyClassWithLogger [DEBUG] - Hello world
   2: MyClassWithLogger [DEBUG] - Still here

So far, so vanilla, and the sort of code that anyone whose used log4net will have written thousands of times; but what happens if we want to apply good SOLID design principles and inject the log4net dependency into the class, rather than have the class create the instance itself. I prefer constructor injection for this, as it makes it very explicit what the dependencies are, and you can’t accidentally forget to set one without getting a compile-time error. The class would then become:

   1: public class MyClassWithLoggerDependency()
   2: {
   3:     private static readonly ILog Logger;
   5:     public MyClassWithLoggerDependency(ILog logger)
   6:     {
   7:         Logger = logger;
   8:     }
  10:     public void DoAction()
  11:     {
  12:         Logger.Debug("Hello world");
  13:         DoSomeOtherAction();
  14:     }
  16:     private void DoSomeOtherAction()
  17:     {
  18:         Logger.Debug("Still here");
  19:     }
  20: }

We’re now ready to apply some IoC magic with Unity to create the instance of ILog that our class will use. Since log4net uses its own factory class to instantiate itself, we have to jump through a hoop or two to get Unity to set things up properly:

   1: public class Program
   2: {
   3:     public static void Main(string[] args)
   4:     {
   5:         var container = new UnityContainer()
   6:             .Register<ILog>(new InjectionFactory(x => LogManager.GetLogger(typeof(this))));
   7:             .Register<MyClassWithLoggerDependency>()
   9:         var myClass = new container.Resolve<MyClassWithLoggerDependency>();
  10:         myClass.DoStuff();
  11:     }
  12: }

Which produces an output like this:

   1: Program [DEBUG] - Hello world
   2: Program [DEBUG] - Still here

See the problem? Now the logger is using the context of the code where Unity was configured to log from, rather than the context that the logger is being called from. I’ve seen plenty of questions asked about this, but it was only today that I stumbled upon the answer to this problem, hidden in a discussion on the Unity forums. A developer named Marco posted his solution, which was to create two extensions – the first being a BuildTracking extension, and the second being a LogCreation extension. The build tracking extension keeps tabs on what types are being built up, and then calls out to the log creation extension to create the logger component in the context of the class which is asking for it. Another developer, Scott, then posted his amendments that took care of some breaking API changes from the earlier version of Unity that Marco was using, together with an enhancement to improve detection of the calling class name when log4net is not being used with dependency injection.

My small contribution to the discussion was to provide the actual implementation code, which is as follows:

   1: public class Program
   2: {
   3:     public static void Main(string[] args)
   4:     {
   5:         var container = new UnityContainer()
   6:             .AddNewExtension<BuildTracking>()
   7:             .AddNewExtension<LogCreation>()
   8:             .Register<MyClassWithLoggerDependency>()
  10:         var myClass = new container.Resolve<MyClassWithLoggerDependency>();
  11:         myClass.DoStuff();
  12:     }
  13: }
Now that in my eyes is a much tidier piece of code. Gone is the explicit registration of the ILog type with its rather ungainly use of the InjectionFactory to create the appropriate implementation, and instead we have the two new extensions registered.

This is a great little bit of code, and big thanks go to Marco and Scott for sharing their contributions with us. I’m sure that many other developers will find this useful.


Madman said...

Good post, thanks!

Sietz0r said...

Interesting post!
I ran into the same problem yesterday.

I resolved it by wrapping log4net in my own Logger class, and let it resolve the type of the calling class by examing the StackTrace.

public class MyLogger : IMyLogger
private static ILog _logger;

...Some LogMethods here..

public void Info(string format, params object[] parameters)
var logger = GetLoggerInstance();
logger.InfoFormat(CultureInfo.InvariantCulture, format, parameters);

private ILog GetLoggerInstance()
var callingClassType =
from frame in new StackTrace().GetFrames()
let type = frame.GetMethod().DeclaringType
where type != typeof(MyLogger)
select type

_logger = LogManager.GetLogger(callingClassType);

return _logger;

Bruno Brant said...

Sadly, the links are dead.

David Keaveny said...

Sorry about that @Bruno; with Codeplex movie its content to GitHub, conversations appear to have disappeared. Maybe the internet archives will still have the original discussion?