How to intercept all the ASP.NET WebApi controller action methods calls with Ninject interception for logging?

Question

Our company has the need to log certain things each time one of our action methods of our ASP.NET WebApi controllers gets called. Since we use Ninject for the DI right now, we'd like to use it also for this purpose. This is what I have tried so far.

I have Ninject, Ninject.Extensions.Interception and Ninject.Extensions.Interception.DynamicProxy installed through NuGet and I have the following module

public class InterceptAllModule : InterceptionModule
{
    public override void Load()
    {
        Kernel.Intercept(p => p.Request.Service.Name.EndsWith("Controller")).With(new TimingInterceptor());
    }
}

Where TimingInterceptor is

public class TimingInterceptor : SimpleInterceptor
{
    readonly Stopwatch _stopwatch = new Stopwatch();
    protected override void BeforeInvoke(IInvocation invocation)
    {
        _stopwatch.Start();
    }

    protected override void AfterInvoke(IInvocation invocation)
    {
        _stopwatch.Stop();
        string message = string.Format("[Execution of {0} took {1}.]",invocation.Request.Method,_stopwatch.Elapsed);
        Log.Info(message + "\n");
        _stopwatch.Reset();
    }
}

Now, when I try to hook the module up with ninject kernel, and run my site

var kernel = new StandardKernel(new InterceptAllModule());

However, whenever there is a call coming in to one of the action method, it throws an error saying

Cannot instantiate proxy of class: MyApiController.

Could someone with experience point out what I'm doing wrong please? Thanks.

Answer 1

Update

So using your Code and Remo's excellent point about needing the action methods to be virtual and putting in an empty default constructor (just to placate dynamic proxy, keep your other constructor still) I have got both the action filter and the interception approach working.

I would say that as it stands your code will intercept potentially unwanted methods on the ApiController so you will probably also need to put some code in place to filter these out e.g. ExecuteAsync and Dispose.

My only other point is performance. Huge disclaimer these are just very basic tests (using the action filter approach each time to log the stats), I invite you to do your own(!)... but using the DynamicProxy interceptor I was getting a time of around 4 milliseconds per get request

[Execution of Get took 00:00:00.0046615.]
[Execution of Get took 00:00:00.0041988.]
[Execution of Get took 00:00:00.0039383.]

Commenting out the Interception code and using an Action filter I was getting sub millisecond performance:

[Execution of Get took 00:00:00.0001146.]
[Execution of Get took 00:00:00.0001116.]
[Execution of Get took 00:00:00.0001364.]

It is up to you whether this is actually an issue or concern but I thought I would point this out.

Previous Response

Have you rulled out using ActionFilters? This is the natural extension point for AOP on an MVC action.

If you were interested in methods other than the actual action on the controller then I would understand but I thought I would post a suggestion anyway.

Inspired by Are ActionFilterAttributes reused across threads? How does that work? and Measure Time Invoking ASP.NET MVC Controller Actions.

Updated to show the exclusion of the timer when method tagged. Inspiration from core WebApi framework specifically AllowAnonymousAttribute and AuthorizeAttribute

Register this globally so that all actions are monitored by this:

GlobalConfiguration.Configuration.Filters.Add(new TimingActionFilter());

Then:

public class TimingActionFilter : ActionFilterAttribute
{
    private const string Key = "__action_duration__";

    public override void OnActionExecuting(HttpActionContext actionContext)
    {
        if (SkipLogging(actionContext))
        {
            return;
        }

        var stopWatch = new Stopwatch();
        actionContext.Request.Properties[Key] = stopWatch;
        stopWatch.Start();
    }

    public override void OnActionExecuted(HttpActionExecutedContext actionExecutedContext)
    {
        if (!actionExecutedContext.Request.Properties.ContainsKey(Key))
        {
            return;
        }

        var stopWatch = actionExecutedContext.Request.Properties[Key] as Stopwatch;
        if(stopWatch != null)
        {
            stopWatch.Stop();
            var actionName = actionExecutedContext.ActionContext.ActionDescriptor.ActionName;
            Debug.Print(string.Format("[Execution of {0} took {1}.]", actionName, stopWatch.Elapsed));
        }

    }

    private static bool SkipLogging(HttpActionContext actionContext)
    {
        return actionContext.ActionDescriptor.GetCustomAttributes<NoLogAttribute>().Any() ||
                actionContext.ControllerContext.ControllerDescriptor.GetCustomAttributes<NoLogAttribute>().Any();
    }
}

And

[AttributeUsage(AttributeTargets.Method | AttributeTargets.Class, Inherited = true)]
public class NoLogAttribute : Attribute
{

}

Now you can exclude the global filter using:

public class ExampleController : ApiController
{
    // GET api/example
    [NoLog]
    public Example Get()
    {
       //
    }
}

Answer 2

For anyone still lurking, the reason I wanted to use Ninject was so I could inject a logger (or anything else) into the interceptor, but I wanted to intercept all actions.

Mark's answer is perfect, but instead of registering globally using

GlobalConfiguration.Configuration.Filters.Add(new TimingActionFilter());

bind your filter with Ninject using

Kernal.BindHttpFilter<TimingActionFilter>(FilterScope.Action).

You'll need to create an appropriate contructor in the TimingActionFilter class.