Tripping over logs: A story of Unity - Part 4

Robert MacLean

6 January 2009

Recap + Intro

In part 1 we looked at the problem with just adding logging code and how it quickly gets messy and we looked at how the more loosely coupled the code is, the easier it is to effect changes painlessly. Then in part 2 we took that code and added Unity which gave us control via a config file as to what class our logging should use. Then in part 3 we saw some benefits of dealing with this overhead, but now dear reader we get into the real issue I wanted to solve, having logging be more elegantly applied.

Note you can get Unity with the Enterprise Library from p&p group.

As I said in part 1

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. 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:

Works better than Vader’s interceptor

(Once again I shine my knowledge of Star Wars in a title… which maybe is why my friends and family think of me as a geek and I see myself as cool… anyway it’s not important to the post.)

The Mary Poppins bag like magic that is happening with Unity is NOT just limited to controlling the lifetime of objects, it is actually controlling the objects. There is an invisible layer there and this allows us to do something very smart called Interception. In this scenario we intercept calls to classes or methods and apply some other code to them! Important to note is that we can only do that to objects that Unity works with so for our example, we can’t do it to the main method or the DoSomething method directly. We can refactor DoSomething into it’s own interface and class and have Unity own it as below. The key changes from our previous code are:

I create a instance of IWorker and do the DoSomething method of it, passing it the logger - lines 14 and 15
I have a new interface called IWorker and a new class based on it, called Worker - Lines 43 to 55
I have removed our Lolzcat’s constructor in the logging (it’s not important to show that anymore)

        1: class Program

       2:     {

       3:         static IUnityContainer container = new UnityContainer();

       4:  

       5:         static void Main(string[] args)

       6:         {

       7:             UnityConfigurationSection section = (UnityConfigurationSection)ConfigurationManager.GetSection("unity");

       8:             section.Containers.Default.Configure(container);

       9:  

            ILogger logger = container.Resolve<ILogger>();

  

            logger.LogThis("Application started");

  

            IWorker worker = container.Resolve<IWorker>();

            worker.DoSomething("Robert", logger);

  

            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);

        }

    }

  

    interface IWorker

    {

        void DoSomething(string Username, ILogger logger);

    }

  

    public class Worker : IWorker

    {

        void IWorker.DoSomething(string Username, ILogger logger)

        {

            logger.LogThis("DoSomething Called with Username Parameter set to:" + Username);

            Console.WriteLine("Hello {0}", Username);

            logger.LogThis("DoSomething Completed");

        }

    }

So this runs nicely but we are still using this logger thing all the time and it isn’t much better than before.

Setup the Interception

So to fix this we will use interception and that means we need to add two more references to our solution:

Next we add a new using to our code:

    using Microsoft.Practices.Unity.InterceptionExtension;

    using System.Reflection;

Yes, that is System.Reflection there. We will use reflection to figure out values at runtime for us.

And now we will add in code to allow us to attribute our methods so that logging happens for us. For those who have no idea what I mean by attribute methods, I am talking about the Decorator Pattern, which will be familiar to those using WCF and/or LINQ at least in practice even if you didn’t know it was called that.

To do that we first need to create another new class, this time derived from HandlerAttribute and all it does is gives us the attribute to decorate the code with, lines 1 to 7 below. It returns a class of LoggingHandler (via the container) and LoggingHandler is the other new. In here we have a constructor which take an instance of ILogger (lines 13 to 16) and a Invoke method (starting on line 18). The invoke method is the brains of the operation as it is what will be run when we call our method. Note it starts with us using reflection to work out the parameters (lines 20 through 25) and then calls the logger to write the PRE method message (line 27). Next it calls getNext which gets the next handler in the stack (in our case there is none). Note you control the order of handlers via the Order parameter, line 34. After all the handlers have run their PRE methods the method actually runs, and after the getNext it starts to unwind so we can do our POST method logging, line 29.

       1: public class LoggingAttribute : HandlerAttribute

       2:     {

       3:         public override ICallHandler CreateHandler(IUnityContainer container)

       4:         {

       5:             return container.Resolve<LoggingHandler>();

       6:         }

       7:     }

       8:  

       9:     public class LoggingHandler : ICallHandler

    {

        ILogger _logger;

  

        public LoggingHandler(ILogger logger)

        {

            _logger = logger;

        }

  

        public IMethodReturn Invoke(IMethodInvocation input, GetNextHandlerDelegate getNext)

        {

            string parameters = string.Empty;

            for (int counter = 0; counter < input.Inputs.Count; counter++)

            {

                ParameterInfo parameterInfo = input.Inputs.GetParameterInfo(counter);

                parameters += parameterInfo.Name + " = " + input.Inputs[counter].ToString() + Environment.NewLine;

            }

  

            _logger.LogThis(String.Format("About to call {0} with the following parameters: {1}", input.MethodBase.Name, parameters));

            IMethodReturn msg = getNext()(input, getNext);

            _logger.LogThis(String.Format("Call completed to {0}", input.MethodBase.Name));

  

            return msg;

        }

  

        public int Order { get; set; }

    }

One point I want to make here, and I think it is super cool, is note I never specify what to pass into LoggingHandler’s constructor (it needs an ILogger parameter)! Unity is smart enough to know it has an ILogger in the container and a constructor with needs one and puts them together automatically for you ;)

Right that’s a lot of code to do this, so how does it effect our other code? We’ll now our DoSomething method just looks like this below. Note the [Logging] attribute tag on line 1 which enables the logging for this method.

       1: [Logging]

       2: void IWorker.DoSomething(string Username)

       3: {

       4:     Console.WriteLine("Hello {0}", Username);

       5: }

If you think that in a massive system the fact we can just annotate methods to get functionality is great, it cleans the code up and means that developer X who is working on logging can change it WITHOUT any code changes :) Rock On!

Configuration for Interception

Our code does not run at this point :( Because we need to add some details the app.config for the system to use configuration. First we add an alias for our chosen method of interception on line 14, then we extend the unity config (similar concept to how we extended the .NET config with a config section) on lines 28 to 30, and lastly we configure the extension we added. The most important part here is how we link an interceptor to a class (lines 35 and 36). This means we can enable/disable interception via configuration.

       1: <?xml version="1.0" encoding="utf-8" ?>

       2: <configuration>

       3:     <configSections>

       4:         <section name="unity" type="Microsoft.Practices.Unity.Configuration.UnityConfigurationSection, Microsoft.Practices.Unity.Configuration" />

       5:     </configSections>

       6:  

       7:     <unity>

       8:         <typeAliases>

       9:             <typeAlias alias="Logger" type="BigSystem.ConsoleLogger, BigSystem"/>

            <typeAlias alias="ILogger" type="BigSystem.ILogger, BigSystem"/>

            <typeAlias alias="singleton" type="Microsoft.Practices.Unity.ContainerControlledLifetimeManager, Microsoft.Practices.Unity" />

            <typeAlias alias="Worker" type="BigSystem.Worker, BigSystem"/>

            <typeAlias alias="IWorker" type="BigSystem.IWorker, BigSystem"/>

            <typeAlias alias="transparentProxy" type="Microsoft.Practices.Unity.InterceptionExtension.TransparentProxyInterceptor, Microsoft.Practices.Unity.Interception" />

        </typeAliases>

  

        <containers>

            <container>

                <types>

                    <type type="ILogger" mapTo="Logger">

                        <lifetime type="singleton" />

                    </type>

                    <type type="IWorker" mapTo="Worker">

                        <lifetime type="singleton" />

                    </type>

                </types>

  

                <extensions>

                    <add type="Microsoft.Practices.Unity.InterceptionExtension.Interception, Microsoft.Practices.Unity.Interception" />

                </extensions>

  

                <extensionConfig>

                    <add  name="interception" type="Microsoft.Practices.Unity.InterceptionExtension.Configuration.InterceptionConfigurationElement, Microsoft.Practices.Unity.Interception.Configuration">

                        <interceptors>

                            <interceptor type="transparentProxy">

                                <default type="IWorker"/>

                            </interceptor>

                        </interceptors>

                    </add>

                </extensionConfig>

            </container>

        </containers>

    </unity>

</configuration>

And that is it! It’s been a long post so I won’t go into any specific of the interception type etc… I’ll do a supplementary post on that next.

Search

Recap + Intro

Works better than Vader’s interceptor

Setup the Interception

Configuration for Interception