Logging Aspect

In a previous post I talked about my approach to Aspect Oriented Programming (AOP) in Castle Windsor.  In this one I’m going to chat a bit about how I used this for logging.

My goal is simple:  I want to write a log entry for method calls to functions, log inputs and outputs and log exceptions.  I wanted logging to be on an ‘opt out’ basis (i.e. logging is on by default and you say you don’t want it).  I also wanted to be able to turn it on and off globally (yes his is pretty easy to do with log4net but I didn’t want to apply the aspect unless it’s on, why incur the cost of the proxy (however small they are) at all if logging is of…).

My reason for doing this is I really don’t like seeing in code log.Write(“Getting customer information for {0}”, customerId);   Especially when the next line of code is customerService.GetCustomerById(customerId);  Sometimes you even get a comment // get customers by ID (plus logging plus the method call).  DRY – don’t repeat yourself.  It’s more to read and more to maintain.  This is all covered in a fair bit of detail in clean code.  How many times have you seen in code stuff like this:

log.Write(“Getting customer information {0}”, customerId); 
productService.GetProductsForCustomer(customerId);

It’s a lot like comments getting old and stale, log entries which are wrong cause more hassle than no log entry at all (I recon anyway).

Now, don’t get me wrong – there is a time and a place for proper logging (which won’t be done by the aspect).  I’m by no means suggesting that you rely on the aspect for all the logging.  I also think that in production most of the time this logging will be turned off, just turned on when the excrement collides with said fan.

So, the aspect itself:

public class LoggingAspect : MethodInvocationAspect
{
    private readonly ILoggingFactory loggingFactory;
 
    public LoggingAspect(ILoggingFactory loggingFactory)
    {
        if (loggingFactory == null) throw new ArgumentNullException("loggingFactory");
        this.loggingFactory = loggingFactory;
    }
 
    public override MethodVoteOptions PreCall(MethodInvocationContext invocation)
    {
        var logger = CreateLogger(invocation);
        logger.Debug(GetCallLogInfo(invocation));
 
        return MethodVoteOptions.Continue;
    }
 
    public override void PostCall(MethodInvocationContext invocation)
    {
        invocation.GetStateItem<ILogger>().Debug(GetPostCallLog(invocation));
    }
 
    public override void OnException(MethodInvocationContext invocation, Exception e)
    {
        if (LoggingConfiguration.LoggingOutputOptions.LogErrors)
        {
            invocation.GetStateItem<ILogger>().Error(GetCallLogInfo(invocation), e);
        }
    }
 
    private static string GetCallLogInfo(MethodInvocationContext invocationContext)
    {
        var logBuilder = new MethodCallLogBuilder(invocationContext);
        logBuilder.AddMethodCall();
        if (LoggingConfiguration.LoggingOutputOptions.LogParameterValues)
        {
            logBuilder.AddParameters();
        }
        return logBuilder.GetLogOutput();
    }
 
    private static string GetPostCallLog(MethodInvocationContext invocationContext)
    {
        var logBuilder = new MethodCallLogBuilder(invocationContext);
        logBuilder.AddMethodCall();
        logBuilder.AddMethodExecutionTime();
        if (LoggingConfiguration.LoggingOutputOptions.LogReturnValue)
        {
            logBuilder.AddReturnValue();
        }
 
        return logBuilder.GetLogOutput();
    }
 
    private ILogger CreateLogger(MethodInvocationContext invocation)
    {
        var logger = loggingFactory.CreateLogger(invocation.Invocation.TargetType);
        invocation.AddStateItem(logger);
        return logger;
    }
}

The entry point to the AOP framework is the aspect selector and that is:

public class LoggingAspectSelector : IAspectSelector
{
    public bool Enabled
    {
        get
        {
            return LoggingConfiguration.LoggingOutputOptions.Enabled;
        }
    }
 
    public bool IsMatch(Type service)
    {
        return LoggingConfiguration.ShouldLogForType(service);
    }
 
    public Type AspectType
    {
        get { return typeof (LoggingAspect); }
    }
}

I added some configuration so you can globally opt out by namespace or by specific service.  At the moment you configure input / output logging globally.  This seems to be working OK.  I’ve never turned exception logging on because I log those explicitly at the service boundary, but I guess it would be nice to be able to say that this service you should log errors for…  This’ll no doubt evolve as our demands change, but I’m all for keeping it simple right now.

Here are some examples of opting in / out of logging.

[TestMethod]
public void Can_Confiure_By_Extenstion_When_Registering_Using_ComponentFor()
{
    var container = new WindsorContainer();
    container.Register(
        Component.For<ITestService>()
            .ImplementedBy<TestServiceImpl>()
            .IgnoreLogging());
 
    Assert.IsFalse(LoggingConfiguration.ShouldLogForType(typeof(ITestService)));
}
 
[TestMethod]
public void Can_Restrict_To_Types_Only_In_Namespace()
{
    LoggingConfiguration.ConfigureWith().RestrictedLoggingToTypesInNamespace("IE.*");
 
    Assert.IsTrue(LoggingConfiguration.ShouldLogForType(typeof(ITestService)));
    Assert.IsFalse(LoggingConfiguration.ShouldLogForType(typeof(string)));
}
 
[TestMethod]
public void Can_Configure_LoggingOptions_From_AppConfig()
{
    LoggingConfiguration.ConfigureWith().LoggingOptionsFromAppConfig();
 
    AssertLoggingOptionsAreAllTrue();
    Assert.AreEqual(@"c:\logs\test.log", LoggingConfiguration.LoggingOutputOptions.LogFilePath);
}
 
[TestMethod]
public void Can_Configure_LoggingOptions_In_Code()
{
    LoggingConfiguration.ConfigureWith().LoggingOptions(o =>
                                                            {
                                                                o.Enabled = true;
                                                                o.LogParameterValues = true;
                                                                o.LogReturnValue = true;
                                                            });
 
    AssertLoggingOptionsAreAllTrue();
}

Here’s how it’s used.

var container = new WindsorContainer()
    .WithAspects(new LoggingAspectSelector())
    .WithLog4NetLogging()
    .Register(Component.For<ITestService>().ImplementedBy<TestServiceImpl>());
 
var instance = container.Resolve<ITestService>();
 
instance.DoSomething();

I hope this shows my intent…  I haven’t posted all the code for brevity.  I want to get to grips with git so I may try uploading this (and other code on this blog) there, but in the likely event I never do and you’d like all of it email me or something 🙂

Again, feedback greatly appreciated.

Advertisements

About Tom Peplow

C# .Net developer based in London and the South Coast
This entry was posted in Uncategorized and tagged , . Bookmark the permalink.

One Response to Logging Aspect

  1. Pingback: Caching Aspect | pep => lowdown

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