A very long time ago I wrote a post on this blog about interceptors.

The idea behind an interceptor is pretty straight forward; dynamically create a wrapper around some interface or class to either augment or alter its behaviour when used by the rest of the system, without actually having to implement the interface or override the class. For example, my original post was for an interceptor that slowed down requests heading to an API, simulating how that particular application would feel for a user with terrible internet.

I honestly haven’t touched the concept since, until recently that is.

I wanted to add some logging around usage of a third party API from our legacy application and conceptually the problem seemed like a perfect application for another interceptor. A quick implementation of a logging interceptor injected via Ninject and I’d have all the logging I could ever want, without having to mess around too much.

Reality had other ideas though.

Here’s Why I Came Here Tonight

Our legacy software is at that time in its life where it mostly just gets integrations. Its pretty feature complete as far as core functionality goes, so until the day we finally grant it Finis Rerum and it can rest, we look to add value to our users by integrating with third party services.

The most recent foray in this space integrated a payment provider into the software, which is quite useful considering its core value proposition is trust account management. From a technical point of view, the payment provider has an API and we wrote a client to access that API, with structured request and response objects. Pretty standard stuff.

As part of our development, we included various log events that allowed us to track the behaviour of parts of the system, mostly so that we could more easily support the application and get accurate metrics and feedback from users in the wild relating to performance. This is all well and good, but those events generally cover off combined parts of the application logic; for example, an operation that queries the local DB and then augments that information by calling into the third party API to display a screen to the user.

This makes it relatively easy to see when any users are experiencing performance issues, but it makes it hard to see whether or not the local DB, the actual programming logic or the internet call was the root cause.

An improvement to this would be to also log any outgoing API requests and their responses, along with the execution time. With that information we would be able to either blame or absolve the clients internet connection when it comes to performance questions.

Now, I’m an extremely lazy developer, so while we have a nice interface that I could implement to accomplish this (i.e. some sort of LoggingPaymentProviderClient), its got like twenty methods and I really don’t have the time, patience or motivation for that. Also, while its unlikely that the interface would change all that much over time, its still something of a maintenance nightmare.

Interceptors to the rescue!

But I Got The Feeling That Something Ain’t Right

As I explained in my original post all those years ago, the IInterceptor interface supplied by the Castle library allows you to implement logic via a proxy and slot it seamlessly into a call stack. Its usage is made easier by the presence of good dependency injection, but its definitely not required at all.

Thus enters the logging interceptor.

public class PaymentProviderClientMethodExecutionLoggingInterceptor : IInterceptor
{
    public PaymentProviderClientMethodExecutionLoggingInterceptor(ILogger logger)
    {
        _logger = logger;
    }

    private readonly ILogger _logger;

    public void Intercept(IInvocation invocation)
    {
        var stopwatch = Stopwatch.StartNew();
        try
        {
            invocation.Proceed();
            stopwatch.Stop();

            var log = new PaymentProviderMethodCallCompleted(invocation, stopwatch.Elapsed);
            _logger.Information(log);
        }
        catch (Exception ex)
        {
            stopwatch.Stop();

            var log = new PaymentProviderMethodCallFailed(invocation, stopwatch.Elapsed, ex);
            _logger.Warning(log);

            throw;
        }
    }
}

Its not an overly complicated class, and while its written to be specific, its actually quite generic.

Given a proxied class, all methods called on that class will be logged via Serilog, with the method name, its parameters and its return value (the structured logging being provided by the dedicated event classes).

Nothing ever works the first time though, and while I’m constantly being reminded of that, I’m always hopeful all the same. Denial is a powerful motivator.

The problem was that the IInterceptor interface is old enough that it doesn’t consider the existence of asynchronous methods. It does exactly what it says on the tin, starts a timer, proceeds with the method invocation and then because the method is asynchronous, immediately logs an event with the wrong execution time and no return value.

It has no idea that it has to wait for the invocation to complete because it thinks everything is synchronous.

Clowns To The Left Of Me, Jokers To The Right

This is where everything is going to get a little bit fuzzier than I would like, because I wrote this blog post before I had a working solution.

From what I can tell, the situation is quite complex.

The simplest solution appears to be to leverage the existing interface and simply check for the presence of a Task (or Task<T>) return value. If detected, append a continuation to that Task to perform the desired functionality. For me this would be a continuation on both faulted and success (and maybe cancelled?) that would log the completion of the method. It seems like it would work, but I do have some concerns about the scheduling of the continuation and how that makes the code harder to reason about.

Luckily, someone has already written a reusable library together that allows for asynchronous interceptors via a slightly different interface.

This is attractive because its code that I don’t have to write (remember, I’m lazy), but it not being built into the core Castle library does make me question its legitimacy. Surely if it was that critical the maintainers would have updated Castle.Core?

Regardless, I explored using the library first, but in order to use it I had to go on an adventure to upgrade a bunch of our Nuget dependencies (because it relied on the latest version of Castle.Core), which meant updates to Castle, Ninject and Ninject’s extension libraries. This caused knock on effects because the Ninject.MockingKernel.NSubstitute library was not available for .NET 4.5 (even though all the others were), so I had to temporarily copy that particular implementation into our codebase.

Once everything was compiling, a full test run showed some failing tests that weren’t failing before the library upgrades, so I kind of stopped there.

For now.

Conclusion

Unfortunately this is one of those blog posts that comes off feeling a little hollow. I didn’t actually get to my objective (seamless per method logging for a third-party dependency), but I did learn a lot on the way, so I think it was still useful to write about.

Probably should have waited a little longer though, I jumped the gun a bit.

Its not the only time in recent memory that asynchronous behaviour has made things more difficult than they would have been otherwise. In an unrelated matter, some of our automated tests have been flakey recently, and the core of the issue seems to be asynchronous behaviour that is either a.) not being correctly overridden to be synchronous for testing purposes or b.) not correctly being waited for before tests proceed.

Its not hard to write tests that are purely async of course (NUnit supports tests marked with the async keyword), but when you’re testing a view model and the commands are “synchronous” it gets a bit more challenging.

That’s probably a topic for another day though.

I have an interface.

I’m sure you have some interfaces as well. If you don’t use interfaces you’re probably doing it wrong anyway.

My interface is a bit of a monolith, which happens sometimes. It’s not so big that I can justify investing the time in splitting it apart, but it’s large enough that its hard to implement and just kind of feels wrong. I don’t need to implement this interface manually very often (yay for mocking frameworks like NSubstitute) so I can live with it for now. Not everything can be perfect alas.

This particular  interface allows a user to access a RESTful web service, and comes with some supporting data transfer objects.

I recently had the desire/need to see what would happen to the user experience of an application using this interface (and its default implementation) if the internet connection was slow, i.e. the calls to the service were delayed or timed out.

Obviously I could have implemented the interface with a wrapper and manually added slowdown/timeout functionality. As I mentioned previously though, there were enough methods in this interface that that sounded like a time consuming proposition. Not only that, but it would mean I would be tightly coupled to the interface, just to introduce some trivial slowdown code. If the interface changed, I would need to change my slowdown code. That’s bad, as the functionality of my code is distinctly separate from the functionality of the interface, and should be able to reuse that (admittedly trivial) code anywhere I like.

Plus I’m a lazy programmer. I’ll always go out of my way to write as little code as possible.

Aspect Oriented Programming

What I wanted to do was to be able to describe some behaviour about all of the calls on my interface, without actually having to manually write the code myself.

Luckily this concept has already been invented by people much smarter than me. Its generally referred to as Aspect Oriented Programming (AOP). There’s a lot more to AOP than just adding functionality unobtrusively to calls through an interface, but fundamentally it is about supporting cross cutting concerns (logging, security, throttling, auditing, etc) without having to rewrite the same code over and over again.

In this particular case I leveraged the IInterceptor interface supplied by the Castle.DynamicProxy framework. Castle.DynamicProxy is included in the Castle.Core package, and is part of the overarching Castle Project. It is a utility library for generating proxies for abstract classes and interfaces and is used by Ninject and NSubstitute, as well as other Dependency Injection and mocking/substitution frameworks.

Castle.DynamicProxy provides an interface called IInterceptor.

public interface IInterceptor
{
    void Intercept(IInvocation invocation);
}

Of course, that definition doesn’t make a lot of sense without the IInvocation interface (trimmed of all comments for brevity).

public interface IInvocation
{
    object[] Arguments { get; }
    Type[] GenericArguments { get; }
    object InvocationTarget { get; }
    MethodInfo Method { get; }
    MethodInfo MethodInvocationTarget { get; }
    object Proxy { get; }
    object ReturnValue { get; set; }
    Type TargetType { get; }
    object GetArgumentValue(int index);
    MethodInfo GetConcreteMethod();
    MethodInfo GetConcreteMethodInvocationTarget();
    void Proceed();
    void SetArgumentValue(int index, object value);
}

You can see from the above definition that the IInvocation provides information about the method that is being called, along with a mechanism to actually call the method (Proceed).

You can implement this interface to do whatever you want, so I implemented an interceptor that slowed down all method calls by some configurable amount. You can then use your interceptor whenever you create a proxy class.

public class DelayingInterceptor : IInterceptor
{
    private static readonly TimeSpan _Delay = TimeSpan.FromSeconds(5);

    public DelayingInterceptor(ILog log)
    {
        _Log = log;
    }

    private readonly ILog _Log;

    public void Intercept(IInvocation invocation)
    {
        _Log.DebugFormat("Slowing down invocation of [{0}] by [{1}] milliseconds.", invocation.Method.Name, _Delay.TotalMilliseconds);
        Thread.Sleep(_Delay);
        invocation.Proceed();
    }
}

Proxy classes are fantastic. Essentially they are automatically implemented wrappers for an interface, often with a concrete implementation to wrap supplied during construction. When you create a proxy you can choose to supply an interceptor that will be automatically executed whenever a method call is made on the interface.

This example code shows how easy it is to setup a proxy for the fictitious IFoo class, and delay all calls made to its methods by the amount described above.

IFoo toWrap = new Foo();

var generator = new ProxyGenerator();
var interceptor = new DelayingInterceptor(log4net.LogManager.GetLogger("TEST"));
var proxy = generator.CreateInterfaceProxyWithTarget(toWrap, interceptor);

As long as you are talking in interfaces (or at the very least abstract classes) you can do just about anything!

Stealthy Interception

If you use Ninject, it offers the ability to add interceptors to any binding automatically using the optional Ninject.Extensions.Interception library.

You still have to implement IInterceptor, but you don’t have to manually create a proxy yourself.

In my case, I wasn’t able to leverage Ninject (even though the application was already using it), as I was already using a Factory that had some logic in it. This stopped me from simply using Ninject bindings for the places where I was using the interface. I can see Ninjects support for interception being very useful though, now that I understand how interceptors work. In fact, since my slowdown interceptor is very generic, I could conceivably experiment with slowdowns at various levels in the application, from disk writes to background processes, just to see what happens. Its always nice to have that sort of power to see how your application will actually react when things are going wrong.

Other Ways

I’m honestly not entirely sure if Interceptors fit the classic definition of Aspect Oriented Programming. They do allow you to implement cross cutting concerns (like my slowdown), but I generally see AOP referred to in the context of code-weaving.

Code-weaving is where code is automatically added into your classes at compile time. You can use this to automatically add boilerplate code like null checking on constructor arguments as whatnot without having to write the code yourself. Just describe that you want the parameters to be null checked and the code will be added at compile time. I’m not overly fond of this approach personally, as I like having the code in source control represent reality. I can imagine using code-weaving might lead to situations where it is more difficult to debug the code because the source doesn’t line up with the compiled artefacts.

I don’t have any experience here, I’m just mentioning it for completeness.

Conclusion

In cases where you need to be able to describe some generic piece of code that occurs for all method calls of an interface, Interceptors are fantastic. They raise the level that you are coding at in my opinion, moving beyond writing code that directly tells the computer what to do and into describing the behaviour that you want. This leads to less code that needs to be maintained and less hard couplings the interfaces (as you would get if you implemented the wrapper yourself). Kind of like using an IoC container with your tests (enabling you to freely change your constructor without getting compile errors) you can freely change your interface and not have it impact your interceptors.

I’m already thinking of other ways in which I can leverage interceptors. One that immediately comes to mind is logging calls to the service, and timing how long they take, which is invaluable when investigating issues at the users end and for monitoring performance.

Interceptors provide great modular and decoupled way to accomplish certain cross cutting concerns, and I’m going to try and find more ways to leverage them in the future now that I know they exist.

You should to.

Unless you aren’t using interfaces.

Then you’ve got bigger problems.