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.

Fro

Perhaps this suggestion is a too big shift in the design, but when you abstract all business operations behind a generic abstraction and inject that into the controllers, you would be able to easily decorate or intercept those abstractions to add cross-cutting concerns such as your timing aspect. Take a look at the command/handler pattern to get an idea what I'm talking about. – Eatable

Do you have an additional parameterless constructor and are all action methods virtual? – Thirlage

Thanks Remo, I added virtual to all the action method, but for the parameterless constructor I have a problem because our service object is being injected there and used in the controller. With a parameterless constructor the service object is null. How do you get around this problem? Thanks a lot! – Fro

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()
    {
       //
    }
}

Thurible

+1 Hi Mark, I appreciated your answer. But my manager does not want to use action filter attribute. He wants all action methods to be logged except on the ones where we label an attribute [nolog]. – Fro

@ray247, thanks for letting me make the suggestion. In for a penny, in for a pound I have updated to show the NoLog ability using this approach too. I will also update the answer with some Ninject examples shortly. – Thurible

Thanks a bunch Mark. I haven't tried your code yet but I absolutely agree with the code you showed above. GlobalConfiguration.Configuration.Filters.Add will make it happen for every action, and NoLog attribute will filter out the ones we don't want. A colleague has come with a solution with HttpModule that intercepts every request. But yours is more natural to an MVC project. Thanks and Happy New Year to you. Marked as answer! – Fro

@MarkJones please do you think you could help me with this question #24236117 – Vaasa

Sounds like a good case for OWIN middleware if you can go that route. – Conduction

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.

Aesthesia