Dynamic Method Interception with Autofac

WTF?

Dynamic Interception is a facet of AOP, in which by means of some magic, a call to a target object is intercepted by a proxy which can do things before and after the actual target invocation takes place. It’s some pretty awesome shite. We can use it to handle things like intrumentation and authentication etc; cross-cutting concerns which are a noisy otherwise. Note that AOP does bring with it some complexity and “magic” which would normally see me running for the hills; but I feel that the wins here are potentially so great that it’s worth knowing that you can do this.

How do you do it?

Everyone uses the Castle DynamicProxy to do it, because Krzysztof is insanely smart and it just works. My IOC container of choice is Autofac.

The first thing you need to do is create an Interceptor, which inherits from Castle.DynamicProxy.IInterceptor:

[sourcecode language=”csharp”]

public class InstrumentationInterceptor : IInterceptor
{
public void Intercept(IInvocation invocation)
{
var correlationId = Guid.NewGuid();
DateTime startDate = DateTime.Now;
UltimaTrace.TraceInformation("{0} {1} – {3}.{2} started", startDate, correlationId, invocation.Method.Name, invocation.TargetType.Name);
UltimaEventSource.Log.Message2("{0} {1} – {3}.{2} started", startDate, correlationId, invocation.Method.Name, invocation.TargetType.Name);

invocation.Proceed();

DateTime endDate = DateTime.Now;
UltimaTrace.TraceInformation("{0} {1} – {3}.{2} ended ({4}ms elapsed)", endDate, correlationId, invocation.Method.Name, invocation.TargetType.Name, (endDate – startDate).TotalMilliseconds);
UltimaEventSource.Log.Message2("{0} {1} – {3}.{2} ended ({4}ms elapsed)", endDate, correlationId, invocation.Method.Name, invocation.TargetType.Name, (endDate – startDate).TotalMilliseconds);
}
}

[/sourcecode]

In the code above, the interceptor, aptly named InstrumentationInterceptor, times the call to the target. The call to invocation.Proceed(); is where control is forwarded onto the original target object. I am simply recording the time taken to make the call.

Next, you need to wire up the interceptor:

[sourcecode language=”csharp”]

public class SharedModule : Module
{
protected override void Load(ContainerBuilder builder)
{
builder.Register(c => new InstrumentationInterceptor())
.Named<IInterceptor>("instrumentation-interceptor");
}
}

[/sourcecode]

The code above is of an Autofac Module, which is registering the component and naming it, so that we can refer to it later by name.

Now we need to get interception taking place for the components we care about instrumenting:

[sourcecode language=”csharp”]

public class DomainModule : Module
{
protected override void Load(ContainerBuilder builder)
{
builder.RegisterType<OrderDispatcher>().As<IOrderDispatcher>()
.SingleInstance()
.EnableInterfaceInterceptors()
.InterceptedBy("instrumentation-interceptor");

builder.RegisterType<OrderBook>().As<IOrderBook>();
}
}

[/sourcecode]

When we register the OrderDispatcher above, first we turn on interception with the call to EnableInterfaceInterceptors(), and we supply the interceptor to use by the name we provided before. You can skip doing this here and attribute the classes you want to intercept instead with the [Intercept(“instrumentation-interceptor”)] attribute.

I now have instrumentation tracing at the information level available available whenever I need to pay attention to it. Pretty damn awesome.

To complex for you?

An alternative would be to use the Decorator Pattern to decorate whatever you wanted to instrument with an “InstrumentationDecorator” or some such thing. I’ll blog that some other time.

Configuring and using the Trace subsystem in .Net

So, why?

Because it’s super quick, built into the .net framework already and it’s thread safe and production ready.

So, how?

There are two parts to production ready tracing:

  1. Configuring a Trace Source
  2. Writing the code to use it

1. Configuring a Trace Source

[sourcecode language=”xml”]

<system.diagnostics>
<sources>
<source name="UltimaSource"
switchName="SourceSwitch"
switchType="System.Diagnostics.SourceSwitch" >
<listeners>
<add name="MyTraceFile" />
<add name="ColouredConsole" />
<remove name ="Default" />
</listeners>
</source>
</sources>
<switches>
<add name="SourceSwitch" value="Information" />
</switches>
<sharedListeners>
<add name="MyTraceFile" type="System.Diagnostics.TextWriterTraceListener" initializeData="Trace.log" />
<add name="ColouredConsole" type="Ultima.Infrastructure.Logging.ColouredConsoleTraceLogger, Ultima.Infrastructure, Version=1.0.0.0, Culture=neutral" />
</sharedListeners>
</system.diagnostics>

[/sourcecode]

The code above configures a trace source called UltimaSource, which has two listeners wired up; a Coloured Console Listener (home brewed) and a Text Writer Trace Listener. A switch called SourceSwitch, of type  System.Diagnostics.SourceSwitch is wired up, which is used to control the level of output we get from the listeners. The level is controlled by changing the Value of the relevant switch in the switches element.

You should take note that there is no Trace element in the config above. It would look like thus:

[sourcecode language=”xml”]

<trace autoflush="true">
<listeners>
<add name="MyTraceFile" />
<add name="ColouredConsole" />
</listeners>
</trace>

[/sourcecode]

There is now way that I am aware of that you can control the level of output when you use a simple Trace configuration like this without a Trace Source. This is pretty nice however for your local machine config whilst coding. A simple config transform could remove it as required.

2. Writing the code to use it

In order to use a configured Trace Source, you need to fetch it by name. I have wrapped and abstracted some of the noise in the simple class below:

[sourcecode language=”csharp”]

public class UltimaTrace
{
private static readonly TraceSource Log = new TraceSource("UltimaSource");

public static void TraceInformation(string message)
{
Log.TraceInformation(message);
}

public static void TraceInformation(string format, params object[] message)
{
Log.TraceInformation(format, message);
}

public static void TraceError(string error)
{
Log.TraceEvent(TraceEventType.Error, 0, error);
}

public static void TraceError(string format, params object[] error)
{
Log.TraceEvent(TraceEventType.Error, 0, format, error);
}

public static void TraceException(params object[] data)
{
Log.TraceData(TraceEventType.Error, 0, data);
}
}

[/sourcecode]

Note the TraceEvent and TraceData functions available on the Trace Source, which you will not find on the basic Trace object. Hence the basic wrapper to give things feel closer to normal. The second parameter for the TraceEvent and TraceData functions is the event id, which maps to the Event ID column in the windows event log. You could of course have a whole bunch of standard ids for your app/domain and pass those along as required.

The calling code now looks like this:

[sourcecode language=”csharp”]

UltimaTrace.TraceInformation("Awaiting Orders");

UltimaTrace.TraceError("Could not persist order [{0}]: {1}", orderCommand, e);

[/sourcecode]