Tripping over logs: A story of Unity - Part 1

Submitted by Robert MacLean on Tue, 01/06/2009 - 18:45

Welcome to the first part in my series on using Unity, which is a Dependency Injection or Inversion of Control tool/framework/thing from the p&p group. It’s a big and (over) complicated topic so if what I have just said means nothing, fear not for it will all make sense soon. I have broken this into a series to make it easier to digest. What I am going to do is look at a practical approach to using Unity, I will not be going into DI or IoC those topics as people smarter than me have done a much better job (part 6 has links). If you want the theory look somewhere else, if you want to get running with Unity this is for you.

This is a multi-part series as such here is the series guide in case you are looking for the rest of the series:

The Problem

A few years back I was developing an enterprise solution for a bank which integrated MSCRM into a number of systems, and so I needed to make sure I did logging (that’s what enterprise apps have, right?). Initially I had a simple “write to text file” logging system, which worked fine on my machine (if you can see what the problem is in that sentence you been developing too long). That is until we started testing and we ramped up the usage and I hit concurrency and locking issues. That prompted me to rip out all the logging and use the logging within System.Diagnostics.Trace as it seemed like it would work better, and it did for a long time. At some point I was pulled back to project (I left it for a long time) and needed to change the logging to use the p&p Enterprise Library logging. It was only at this point did I stop calling the System.Diagnostics.Trace code directly in each place for logging and start calling a custom method. This is what it sort of looked liked, excepted I had lots more parameters on the logging (level of message, source component etc…) and we logged every time something changed not just entry and exit:

public void DoSomething()
{
    LogThis("Do Something Start");
     ...
    LogThis("Do Something End");
}

When I changed it out I did some number crunching and realised that 40% of all the lines of code was these calls to logging! I remember thinking that was well done and how proud I was of my logging skills. Now days I look back at that as ridiculous. Not the fact I did logging, just how much code was spent on it and how tightly bound it was. So how could I do it better now days, well through a principal called Dependency Injection and an implementation of it called Unity (from the p&p team in their Enterprise Library).

Note: I am using the example of logging as the problem to solve, but really DI can be used for anything.

I must admit that Unity though is anything but simple, it is one of the hardest things I have had to learn in a while. What made it tough was understanding the documentation which enables you to learn Unity, but you need to understand Unity first to understand the documentation, talk about catch 22. It’s odd because the other blocks in EntLib are easy to get up and running but with Unity the samples are confusing and the help more so. In the end, some search kung fu + luck + patience seems to be what is needed to get through it. That said I feel a simple series of blog posts may help others out, which is what this is ;)

Starting Block

A special note is that this series is HEAVY with code and makes the articles look long, but actually I am repeating the code each time so you can compare the changes easily.

So lets start with a simple application as our base which will make it clear what we have and what we will change to get Unity working. As those who attend any of my sessions know I love console apps so I’ve whipped up a simple on that writes to the screen. The code looks like this:

using System;
 
namespace BigSystem
{
    class Program
    {
        static void DoSomething(string Username)
        {
            Console.WriteLine("Hello {0}", Username);
        }
 
        static void Main(string[] args)
        {
            DoSomething("Robert");
            Console.ReadKey();
        }
    }
}

And the solution like this (note the references - super clean):

image

Now using my “Enterprise Skills” from earlier, we add some logging like so:

static void LogThis(string Message)
{
    System.Diagnostics.Debug.WriteLine(String.Format("{0}: {1}", DateTime.Now, Message));
}
 
static void DoSomething(string Username)
{
    LogThis("DoSomething Called with Username Parameter set to:" + Username);
    Console.WriteLine("Hello {0}", Username);
    LogThis("DoSomething Completed");
}
 
static void Main(string[] args)
{
    LogThis("Application started");
    DoSomething("Robert");
    Console.ReadKey();
    LogThis("Application Completed");
}

Right, so that code is not bad. It works which makes the (imaginary) customer is happy. This code is not good either, because if we want to change anything it’s a big issue, likely “solved” by a find and replace. A better route would be to take the logging out and define it in a separate class that inherits from an interface. This means when we create the class we can change that one place and all the code is effected.  So that would look like this:

class Program
{
    static ILogger logger = new DebugLogger();
 
    static void DoSomething(string Username)
    {
        logger.LogThis("DoSomething Called with Username Parameter set to:" + Username);
        Console.WriteLine("Hello {0}", Username);
        logger.LogThis("DoSomething Completed");
    }
 
    static void Main(string[] args)
    {
        logger.LogThis("Application started");
        DoSomething("Robert");
        Console.ReadKey();
        logger.LogThis("Application Completed");
    }
}
 
public interface ILogger
{
    void LogThis(string Message);
}
 
public class DebugLogger : ILogger
{
    public void LogThis(string Message)
    {
        System.Diagnostics.Debug.WriteLine(String.Format("{0}: {1}", DateTime.Now, Message));
    }
}

Note the constructor for logger and the interface and class below. The reason this is powerful is if I wanted to change this to output to the console I could spin up a new class, and just change the constructor for logger, as in below:

class Program
{
    static ILogger logger = new ConsoleLogger();
 
    static void DoSomething(string Username)
    {
        logger.LogThis("DoSomething Called with Username Parameter set to:" + Username);
        Console.WriteLine("Hello {0}", Username);
        logger.LogThis("DoSomething Completed");
    }
 
    static void Main(string[] args)
    {
        logger.LogThis("Application started");
        DoSomething("Robert");
        Console.ReadKey();
        logger.LogThis("Application Completed");
    }
}
 
public interface ILogger
{
    void LogThis(string Message);
}
 
public class DebugLogger : ILogger
{
    public void LogThis(string Message)
    {
        System.Diagnostics.Debug.WriteLine(String.Format("{0}: {1}", DateTime.Now, Message));
    }
}
 
public class ConsoleLogger : ILogger
{
    public void LogThis(string Message)
    {
        Console.WriteLine("{0}: {1}", DateTime.Now, Message);
    }
}

This is great, except to change the type of logger I need to change the code. Wouldn’t it be better to

  1. Be able to specify in a configuration file what should be used?
  2. Instead of instantiating a logger (like with the constructor), I could have a bag where code could reach into and ask for a logger?

This is what Unity provides at a basic level and we will implement in the next post, but trust me it goes much further and becomes much more powerful.