Dependency Injection archive at Ivan Porto Carrero

Yesterday we had a little introduction to Ninject. Today I’d like to examine what’s involved in getting some AOP style logging going for your application. I find that there are only very few places where I’m logging something that steps out of the bounds of being called at the end of the method when things succeed. I’m generally more interested in what happens when things go wrong and that’s when I log the exception. In some cases I’ll be interested in the actual parameters.

The code I’m going to show you will take care of basic logging needs but if you want more information about what happens inside your method you’re either going to need to extend my implementation or log the call from within your method body. We’re going to implement logging that when run with the debug level turned on will tell us that a method is going to execute, whether it finished successfully or with an error and if there was an error it will also log the exception.

To get this thing on the road, on the LightSpeed road that is. We’re going to use NLog to get flexible routing of log messages. We’re first going to create a LightSpeedTarget that is a customized NLog target (route destination) for your log messages.

namespace LoggingDemo.UI.Integration
{
    /// 
    /// This class represents a NLog target that we can reference in the NLog.config file
    /// You can use this to use Lightspeed to log to the database just like a file target etc.
    /// 
    [Target("LightSpeedTarget")]
    public class LightSpeedTarget : TargetWithLayout
    {

        public LightSpeedTarget(){
            Layout = "${message}";
        }

        protected override void Write(LogEventInfo logEvent)
        {
            var logMessage = CompiledLayout.GetFormattedMessage(logEvent);

            var appEvent = new ApplicationEvent
            {
                Sequence = logEvent.SequenceID,
                EventTime = logEvent.TimeStamp,
                Level = logEvent.Level.Name,
                LoggerName = logEvent.LoggerName,
                Message = logMessage
            };

            if (logEvent.Exception != null) appEvent.Exception = logEvent.Exception.ToString();
            if (logEvent.StackTrace != null) appEvent.StackTrace = logEvent.StackTrace.ToString();
            if (logEvent.UserStackFrame != null) appEvent.UserStackFrame = logEvent.UserStackFrame.ToString();

            Repository.Add(appEvent);
            Repository.CompleteUnitOfWork();
        }
    }
}

The class above overrides the TargetWithLayout class from the NLog project. The attribute tells NLog how to find this target. In the constructor I override the default message layout because it was a bit too verbose to my liking.

We then override the Write method where we map the properties to our ApplicationEvent. And lastly we add the event to the repository and commit it.

Now if we want our application to use this we’re going to have to tell it how. Nlog does this by looking for an nlog.config file in your application directory. So let’s go ahead and add an nlog.config file to our project. I’ll show you the nlog.config file for the application. In my unit test project I’m using the console logger so I can see what’s going on

The NLog.config file for the application:

My NLog.config file for my test project:

This enables our application to use the target we just created. Moving on now to the Interceptor which is Ninject specific (You can do the same with other DI frameworks). In Ninject you can tell the kernel to intercept a method on a class and execute some logic before and after invocation of the method. We can tell Ninject to intercept all methods on a class, specific methods or when we say all methods we can still exclude some of them. For our logging example I chose to use all methods on a class. You can do this by decorating the class with an [Intercept] attribute. If you would want a method not to be intercepted you can by decorating that method with an [DoNotIntercept] attribute.

I took the liberty of inheriting of that attribute first.. that makes the rest of my code look a little bit prettier.

The LogMyCallsAttribute:

using Ninject.Core;

namespace LoggingDemo.UI.Interceptors
{
    public class LogMyCallsAttribute : InterceptAttribute
    {
        public LogMyCallsAttribute() : base(typeof(LoggingInterceptor))
        {
        }
    }
}

The LoggingInterceptor:

using System;
using Ninject.Core.Interception;
using Ninject.Core.Logging;

namespace LoggingDemo.UI.Interceptors
{
    public class LoggingInterceptor : SimpleFailureInterceptor
    {
        private readonly ILogger _logger;
        private bool _hasError;

        public LoggingInterceptor(ILogger logger)
        {
            _logger = logger;
            _hasError = false;
        }
        protected override void BeforeInvoke(IInvocation invocation)
        {
            _logger.Debug("About to invoke {0}", MethodNameFor(invocation));
        }

        protected override void OnError(IInvocation invocation, Exception exception)
        {
            _logger.Error(exception, "There was an error invoking {0}.\r\n", MethodNameFor(invocation));
            _hasError = true;
            base.OnError(invocation, exception);
        }

        protected override void AfterInvoke(IInvocation invocation)
        {
            _logger.Debug("invocation of {0} finished {1}.", MethodNameFor(invocation), (_hasError ? "with an error state" : "successfully"));
        }

        private static string MethodNameFor(IInvocation invocation)
        {
            return invocation.Request.Method.Name;
        }
    }
}

This class only overrides a couple of callbacks from its base class the SimpleFailureInterceptor. This is where the actual interception takes place.

using System;
using Ninject.Core;
using Ninject.Core.Interception;

namespace LoggingDemo.UI.Interceptors
{
    public abstract class SimpleFailureInterceptor : IInterceptor
    {

        #region IInterceptor Members

        public virtual void Intercept(IInvocation invocation)
        {
            try
            {
                BeforeInvoke(invocation);
                invocation.Proceed();
            }
            catch (Exception ex)
            {
                OnError(invocation, ex);
            }
            finally
            {
                AfterInvoke(invocation);
            }
        }

        #endregion

         protected virtual void BeforeInvoke(IInvocation invocation)
        {
        }

        protected virtual void AfterInvoke(IInvocation invocation)
        {
        }

        protected virtual void OnError(IInvocation invocation, Exception exception)
        {
            throw exception;
        }
    }
}

This is al the work that is involved in the actual implementation of our logger. Now I’d like to get some confirmation that things actually do work. Unit testing to the rescue I’d say

The first thing we’re going to need is way to verify that stuff actually got intercepted. I did that by subclassing the LoggingInterceptor with a LoggingCounterInterceptor in my unit test project.

    public class LoggingCounterInterceptor : LoggingInterceptor
    {
        public int Count { get; private set; }

        public int ErrorCount { get; private set; }

        public void Reset()
        {
            Count = ErrorCount = 0;
        }

        public LoggingCounterInterceptor(ILogger logger) : base(logger)
        {
        }

        protected override void BeforeInvoke(Ninject.Core.Interception.IInvocation invocation)
        {
            Count++;
            base.BeforeInvoke(invocation);
        }

        protected override void OnError(Ninject.Core.Interception.IInvocation invocation, System.Exception exception)
        {
            ErrorCount++;
            base.OnError(invocation, exception);
        }
    }

    //The attribute for testing
    public class LogMyCallsCounterAttribute : InterceptAttribute
    {
        public LogMyCallsCounterAttribute() : base(typeof(LoggingCounterInterceptor))
        {
        }
    }

In the code above we’re just adding 2 counter properties to the interceptor and adding their counts at the appropriate time. Next we’re going to need some kind of service class or something on which we can use our interceptor, enter the InterceptedServiceMock.

    public interface IInterceptedServiceMock
    {
        void MethodWithoutBody();
        void MethodThatThrowsAnException();
    }

    [LogMyCallsCounter]
    public class InterceptedServiceMock : IInterceptedServiceMock
    {
        public virtual void MethodWithoutBody()
        {
            // Nothing to do here
        }

        public virtual void MethodThatThrowsAnException()
        {
            throw new Exception("Because I can.");
        }
    }

The code above has one method that should execute and one method that throws an exception so we can verify things get picked up accordingly. Now all that’s left to do is write the appropriate specs for them and see if they pass

    [Context(Description = "Specifies the behavior for the LogMyCallsInterceptor")]
    public class LogMyCallsInterceptorSpec
    {
        private IKernel _kernel;

        [BeforeEach]
        public void Before()
        {
            var inlineModule = new InlineModule(m => m.Bind<IInterceptedServiceMock>().To<InterceptedServiceMock>());

            _kernel = new StandardKernel(new LinFuModule(), new NLogModule(), inlineModule);
        }

        [AfterEach]
        public void After()
        {
            _kernel.Dispose();
        }

        [Specification("All this should do is show the calls in the test runner. It should log to the console")]
        public void ShouldShowCallsInConsole()
        {
            var service = _kernel.Get<IInterceptedServiceMock>();
            IContext context = new StandardContext(_kernel, typeof(IInterceptedServiceMock));

            IRequest request = new StandardRequest(
                context,
                service,
                typeof(InterceptedServiceMock).GetMethod("MethodWithoutBody"),
                new object[0]
            );

            var interceptors = _kernel.GetComponent<IInterceptorRegistry>().GetInterceptors(request);

            var enumerator = interceptors.GetEnumerator();
            enumerator.MoveNext();

            Specify.That(interceptors.Count).Must.Equal(1, "There should be 1 interceptor registered");
            Specify.That(enumerator.Current).Must.Be.InstanceOf(typeof(LoggingCounterInterceptor));

            var interceptor = enumerator.Current as LoggingCounterInterceptor;

            service.MethodWithoutBody();

            Specify.That(interceptor).Must.Not.Be.Null();
            Specify.That(interceptor.Count).Must.Equal(1, "There should be 1 invocation counted.");
        }

        [Specification("Should show valid counts for a number of invocations")]
        public void Should_Show_Correct_Counts_For_Number_Of_Invocations()
        {
            var service = _kernel.Get<IInterceptedServiceMock>();
            IContext context = new StandardContext(_kernel, typeof(IInterceptedServiceMock));

            IRequest request = new StandardRequest(
                context,
                service,
                typeof(InterceptedServiceMock).GetMethod("MethodWithoutBody"),
                new object[0]
            );

            var interceptors = _kernel.GetComponent<IInterceptorRegistry>().GetInterceptors(request);

            var enumerator = interceptors.GetEnumerator();
            enumerator.MoveNext();

            Specify.That(interceptors.Count).Must.Equal(1, "There should be 1 interceptor registered");
            Specify.That(enumerator.Current).Must.Be.InstanceOf(typeof(LoggingCounterInterceptor));

            var interceptor = enumerator.Current as LoggingCounterInterceptor;

            service.MethodWithoutBody();
            service.MethodWithoutBody();
            service.MethodWithoutBody();

            Specify.That(interceptor).Must.Not.Be.Null();
            Specify.That(interceptor.Count).Must.Equal(3, "There should be 3 invocations counted.");
            Specify.That(interceptor.ErrorCount).Must.Equal(0, "There should be no errors counted.");
        }

        [Specification("Should have the correct count of invocations and the correct error count.")]
        public void Should_Have_Correct_Invocation_And_Error_Count()
        {
            var service = _kernel.Get<IInterceptedServiceMock>();
            var context = new StandardContext(_kernel, typeof(IInterceptedServiceMock));

            var request = new StandardRequest(
                context,
                service,
                typeof(InterceptedServiceMock).GetMethod("MethodWithoutBody"),
                new object[0]
            );

            var errorRequest = new StandardRequest(
                context,
                service,
                typeof (InterceptedServiceMock).GetMethod("MethodThatThrowsAnException"),
                new object[0]
            );

            var interceptors = _kernel.GetComponent<IInterceptorRegistry>().GetInterceptors(request);
            var errorInterceptors = _kernel.GetComponent<IInterceptorRegistry>().GetInterceptors(errorRequest);

            var enumerator = interceptors.GetEnumerator();
            enumerator.MoveNext();
            var errorEnumerator = errorInterceptors.GetEnumerator();
            errorEnumerator.MoveNext();

            Specify.That(interceptors.Count).Must.Equal(1, "There should be 1 interceptor registered");
            Specify.That(enumerator.Current).Must.Be.InstanceOf(typeof(LoggingCounterInterceptor));
            Specify.That(errorInterceptors.Count).Must.Equal(1, "There should be 1 error interceptor registered");
            Specify.That(errorEnumerator.Current).Must.Be.InstanceOf(typeof(LoggingCounterInterceptor));

            var interceptor = enumerator.Current as LoggingCounterInterceptor;
            var errorInterceptor = errorEnumerator.Current as LoggingCounterInterceptor;

            service.MethodWithoutBody();
            service.MethodWithoutBody();
            service.MethodWithoutBody();

            try
            {
                service.MethodThatThrowsAnException();
            }
            catch
            {
            }

            Specify.That(interceptor).Must.Not.Be.Null();
            Specify.That(interceptor.Count).Must.Equal(3, "There should be 3 invocations counted.");
            Specify.That(errorInterceptor.Count).Must.Equal(1, "There should be 1 invocation counted.");
            Specify.That(errorInterceptor.ErrorCount).Must.Equal(1, "There should be 1 error counted.");
        }
    }

Testing this got a little messy I have to admit that. Now for a concrete example of how that looks in my application:

    [Service(typeof(IBlogService))]
    [LogMyCalls]
    public class BlogService : DataServiceBase<Blog>, IBlogService

And that’s how I implemented logging for my application Needless to say it was the testing that took me the longest to write. And from now on I don’t have to worry anymore about forgetting that logger call. I always have minimal logging going. AOP is usefull in a lot more cases but this seemed like a good and easy example.

Our next post will deal with initializing the modules in your application and their respective behaviors.

Technorati Tags: LightSpeed,Ninject,NLog,Dependency Injection,IoC

del.icio.us Tags: LightSpeed,Ninject,NLog,Dependency Injection,IoC

I have a new project I started and I could reevaluate my toolset I decided to take a closer look at Ninject, Moq and NSpecify. Moq has been talked about enough I think, a really nice way of mocking and I will definitely be using more of it. My original plan was to write one big blog post.. but it is going to be far too long, so I’m breaking it up in smaller bite size pieces.

What I did was download the code, have it rest on my pc for about a week, updated again when I really got round to using it. I read the wiki which gives a short introduction on what’s what in Ninject and everybodies jobs. Decided that the wiki was cool for some more theoretical knowledge but I really needed to see more code.

I opened the project and something rare happened: I was actually very happy with the code I found, not always the case I can tell you . Anyway the gold is in the unit tests, it’s got great test coverage and it shows lots of the possibilities of Ninject. It’s like a great big manual for you to get really advanced with it really quickly. I was slightly disappointed to see that there was no NLog support for Ninject, that disappointment quickly turned in to joy when I figured out it only took me 20 minutes to plug NLog in. And it was added to the trunk the same day.

Now I don’t want to make this post about which DI framework is better Windsor, Spring, Structuremap or Ninject. I just know that Ninject and I will become good friends over the next couple of months I like it. Ninject outsources its proxy generation to either Castle’s DynamicProxy2 or to LinFu DynamicProxy. LinFu seemed like an interesting choice after reading this codeproject article. It’s supposedly faster than castle’s dynamic proxy. Luckily Ayende is there to put this in perspective. And I can confirm that the error messages etc castle’s dynamic proxy generates are a lot more useful than LinFu.

Screenshot - LinFuGraph.png

Anyway I’m using LinFu at the moment as the proxy generator for Ninject. I will walk you through a sample application I built that will deal with the following subjects of Ninject, Lightspeed and NLog. For Ninject we will use the dependency injection and it’s interceptor possibilities to implement AOP style logging. For Lightspeed we will create our own logger to plug into the context so that we can log what Lightspeed does too. And we want NLog to log through Lightspeed to our database so we’ll be creating a custom target for NLog as well.

But let’s start at the beginning doing DI with Ninject .

The most important thing to remember: MAKE YOUR METHODS VIRTUAL. Once again make your methods virtual otherwise Ninject has a hard time generating proxies for your classes.

Ninject is different from most other DI Containers in that it doesn’t have XML-configuration, its configuration is done through code (wouldn’t be hard to add an XML configuration for it tho but what’s the point). No XML ?? Suits me fine, everybody that ever worked with me will agree : Ivan no like XML editing. Ninject takes a modular approach by using modules that you pass to a kernel. This is pretty nice that means that an assembly can have a couple of different sets of Modules and all the caller of that assembly needs to do is add the module with the appropriate configuration to their kernel.

Ninject supports DI on constructors, properties, methods and fields: http://dojo.ninject.org/wiki/display/NINJECT/Injection+Patterns.
It basically boils down to decorating the item you want to inject with the attribute [Inject]

Ninject allows you to do a lot of configuration through the use of attributes. But I think I’ll leave it at that for today and continue this tomorrow.
Let’s look at a concrete class from what we’ve seen so far. The class below is the Logger implementation to plug into the LightSpeedContext. We will finish this later on but for now this will be enough to summarize today’s post.

using Ninject.Core;
using Ninject.Core.Logging;

using ILightSpeedLogger = Mindscape.LightSpeed.Logging.ILogger;
using INinjectLogger = Ninject.Core.Logging.ILogger;

namespace LoggingDemo.UI.Integration
{
///
/// This class intercepts logging messages from the LightSpeed context and
/// sends them to our NLog logger.
///
public class LightSpeedLogger : ILightSpeedLogger
{
private readonly INinjectLogger logger = NullLogger.Instance;

public LightSpeedLogger()
{
}

[Inject]
public LightSpeedLogger(INinjectLogger logger)
{
this.logger = logger;
}

#region ILogger Members

public virtual void LogSql(object sql)
{
logger.Info(sql.ToString());
}

public virtual void LogDebug(object text)
{
logger.Debug(text.ToString());
}

#endregion
}
}

Let me know what you think