Instrumentation with Decorators and Interceptors by Mark Seemann
One of my readers recently asked me an interesting question. It relates to my book's chapter about Interception (chapter 9) and Decorators and how they can be used for instrumentation-like purposes.
In an earlier blog post we saw how we can use Decorators to implement Cross-Cutting Concerns, but the question relates to how a set of Decorators can be used to log additional information about code execution, such as the time before and after a method is called, the name of the method and so on.
A Decorator can excellently address such a concern as well, as we will see here. Let us first define an IRegistrar interface and create an implementation like this:
public class ConsoleRegistrar : IRegistrar { public void Register(Guid id, string text) { var now = DateTimeOffset.Now; Console.WriteLine("{0}\t{1:s}.{2}\t{3}", id, now, now.Millisecond, text); } }
Although this implementation ‘logs' to the Console, I'm sure you can imagine other implementations. The point is that given this interface, we can add all sorts of ambient information such as the thread ID, the name of the current principal, the current culture and whatnot, while the text string variable still gives us an option to log more information. If we want a more detailed API, we can just make it more detailed - after all, the IRegistrar interface is just an example.
We now know how to register events, but are seemingly no nearer to instrumenting an application. How do we do that? Let us see how we can instrument the OrderProcessor class that I have described several times in past posts.
At the place I left off, the OrderProcessor class uses Constructor Injection all the way down. Although I would normally prefer using a DI Container to auto-wire it, here's a manual composition using Pure DI just to remind you of the general structure of the class and its dependencies:
var sut = new OrderProcessor( new OrderValidator(), new OrderShipper(), new OrderCollector( new AccountsReceivable(), new RateExchange(), new UserContext()));
All the dependencies injected into the OrderProcessor instance implement interfaces on which OrderProcessor relies. This means that we can decorate each concrete dependency with an implementation that instruments it.
Here's an example that instruments the IOrderProcessor interface itself:
public class InstrumentedOrderProcessor : IOrderProcessor { private readonly IOrderProcessor orderProcessor; private readonly IRegistrar registrar; public InstrumentedOrderProcessor( IOrderProcessor processor, IRegistrar registrar) { if (processor == null) { throw new ArgumentNullException("processor"); } if (registrar == null) { throw new ArgumentNullException("registrar"); } this.orderProcessor = processor; this.registrar = registrar; } #region IOrderProcessor Members public SuccessResult Process(Order order) { var correlationId = Guid.NewGuid(); this.registrar.Register(correlationId, string.Format("Process begins ({0})", this.orderProcessor.GetType().Name)); var result = this.orderProcessor.Process(order); this.registrar.Register(correlationId, string.Format("Process ends ({0})", this.orderProcessor.GetType().Name)); return result; } #endregion }
That looks like quite a mouthful, but it's really quite simple - the cyclomatic complexity of the Process method is as low as it can be: 1. We really just register the Process method call before and after invoking the decorated IOrderProcessor.
Without changing anything else than the composition itself, we can now instrument the IOrderProcessor interface:
var registrar = new ConsoleRegistrar(); var sut = new InstrumentedOrderProcessor( new OrderProcessor( new OrderValidator(), new OrderShipper(), new OrderCollector( new AccountsReceivable(), new RateExchange(), new UserContext())), registrar);
However, imagine implementing an InstrumentedXyz for every IXyz and compose the application with them. It's possible, but it's going to get old really fast - not to mention that it massively violates the DRY principle.
Fortunately we can solve this issue with any DI Container that supports dynamic interception. Castle Windsor does, so let's see how that could work.
Instead of implementing the same code ‘template' over and over again to instrument an interface, we can do it once and for all with an interceptor. Imagine that we delete the InstrumentedOrderProcessor; instead, we create this:
public class InstrumentingInterceptor : IInterceptor { private readonly IRegistrar registrar; public InstrumentingInterceptor(IRegistrar registrar) { if (registrar == null) { throw new ArgumentNullException("registrar"); } this.registrar = registrar; } #region IInterceptor Members public void Intercept(IInvocation invocation) { var correlationId = Guid.NewGuid(); this.registrar.Register(correlationId, string.Format("{0} begins ({1})", invocation.Method.Name, invocation.TargetType.Name)); invocation.Proceed(); this.registrar.Register(correlationId, string.Format("{0} ends ({1})", invocation.Method.Name, invocation.TargetType.Name)); } #endregion }
If you compare this to the Process method of InstrumentedOrderProcessor (that we don't need anymore), you should be able to see that they are very similar. In this version, we just use the invocation argument to retrieve information about the decorated method.
We can now add InstrumentingInterceptor to a WindsorContainer and enable it for all appropriate components. When we do that and invoke the Process method on the resolved IOrderProcessor, we get a result like this:
bbb9724e-0fad-4b06-9bb0-b8c1c460cded 2010-09-20T21:01:16.744 Process begins (OrderProcessor) 43349d42-a463-463b-8ddf-e569e3170c97 2010-09-20T21:01:16.745 Validate begins (TrueOrderValidator) 43349d42-a463-463b-8ddf-e569e3170c97 2010-09-20T21:01:16.745 Validate ends (TrueOrderValidator) 44fdccc8-f12d-4057-ae03-791225686504 2010-09-20T21:01:16.746 Collect begins (OrderCollector) 8bbb1a0c-6134-4652-a4af-cd8c0c7184a0 2010-09-20T21:01:16.746 GetCurrentUser begins (UserContext) 8bbb1a0c-6134-4652-a4af-cd8c0c7184a0 2010-09-20T21:01:16.747 GetCurrentUser ends (UserContext) d54359ff-8c32-487f-8728-b19ff0bf4942 2010-09-20T21:01:16.747 GetCurrentUser begins (UserContext) d54359ff-8c32-487f-8728-b19ff0bf4942 2010-09-20T21:01:16.747 GetCurrentUser ends (UserContext) c54c4506-23a8-4553-ba9a-066fc64252d2 2010-09-20T21:01:16.748 GetSelectedCurrency begins (UserContext) c54c4506-23a8-4553-ba9a-066fc64252d2 2010-09-20T21:01:16.748 GetSelectedCurrency ends (UserContext) b3dba76b-6b4e-44fa-aca5-52b2d8509db3 2010-09-20T21:01:16.750 Convert begins (RateExchange) b3dba76b-6b4e-44fa-aca5-52b2d8509db3 2010-09-20T21:01:16.751 Convert ends (RateExchange) e07765bd-fe07-4486-96f1-f74d77241343 2010-09-20T21:01:16.751 Collect begins (AccountsReceivable) e07765bd-fe07-4486-96f1-f74d77241343 2010-09-20T21:01:16.752 Collect ends (AccountsReceivable) 44fdccc8-f12d-4057-ae03-791225686504 2010-09-20T21:01:16.752 Collect ends (OrderCollector) 231055d3-4ebb-425d-8d69-fb9c85d9a860 2010-09-20T21:01:16.752 Ship begins (OrderShipper) 231055d3-4ebb-425d-8d69-fb9c85d9a860 2010-09-20T21:01:16.753 Ship ends (OrderShipper) bbb9724e-0fad-4b06-9bb0-b8c1c460cded 2010-09-20T21:01:16.753 Process ends (OrderProcessor)
Notice how we care easily see where and when method calls begin and end using the descriptive text as well as the correlation id. I will leave it as an exercise for the reader to come up with an API that provides better parsing options etc.
As a final note it's worth pointing out that this way of instrumenting an application (or part of it) can be done following the Open/Closed Principle. I never changed the original implementation of any of the components.
