How to use ActionFilterAttribute to log running times?

Question

I created an action filter for measuring running times of every action in an Web API v2.

public class RunningTimeAttribute : ActionFilterAttribute
    {
        private readonly ILogFactory _logFactory;
        private readonly ITimerFactory _timerFactory;
        private ITimer _timer;
        private ILogger _logger;

        public RunningTimeAttribute(ILogFactory logFactory, ITimerFactory timerFactory) {
            if(logFactory == null)
                throw new ArgumentNullException("logFactory");
            if(timerFactory == null)
                throw new ArgumentNullException("timerFactory");

            _logFactory = logFactory;
            _timerFactory = timerFactory;
        }

        public override void OnActionExecuting(HttpActionContext actionContext) {
            base.OnActionExecuting(actionContext);
            OnBeforeAction(actionContext);
        }

        public override void OnActionExecuted(HttpActionExecutedContext actionExecutedContext) {
            OnAfterAction(actionExecutedContext);
            base.OnActionExecuted(actionExecutedContext);
        }

        private void OnBeforeAction(HttpActionContext actionContext) {
            var controllerName = actionContext.ControllerContext.Controller.GetType().FullName;
            var actionName = actionContext.ActionDescriptor.ActionName;

            _logger = _logFactory.Create(controllerName);
            _logger.Trace("Action \"{0}\" begins execution", actionName);

            _timer = _timerFactory.Create();
            _timer.Start();
        }

        private void OnAfterAction(HttpActionExecutedContext actionExecutedContext) {
            var actionName = actionExecutedContext.ActionContext.ActionDescriptor.ActionName;

            _timer.Stop();
            _logger.Trace("Time elapsed for action \"{0}\": {1} msec", actionName, _timer.ElapsedMilliseconds);
        }

}

However, action filters act as singletons, so when OnActionExecuted runs, I cannot be sure that the _logger and _timer correspond to the ones created for the same action OnActionExecuting.

Eg.

1. Action Foo1 begins execution. _logger = "logger1", _timer = "timer1".
2. Action Foo2 begins execution. _logger = "logger2", _timer = "timer2" (they get overriden)
3. Action Foo1 ends execution. It stops timer and logs elapsed time which is nonsense (end1-start2).

Question: Is there a way I can know in OnActionExecuted to which OnActionExecuting it corresponds? If there was some unique identifier for actions, I could use it as a key to a Dictionary to store any action-related objects such as loggers and timers. Is there any? Or some other solution?

Answer 1

As far as Web API is concerned the System.Web.HttpContext.Current is not always guaranteed. It depends on whether you are using Web API Self hosted or not. That is the main reason that when overriding System.Web.Http.Filters.ActionFilterAttribute.OnActionExecuting you don't get an httpcontext property on the HttpActionContext parameter (In AspNet MVC you do).

The best way to do the same is the actionContext.Request.Properties dictionary.

check also this answer here

Answer 2

System.Web.HttpContext.Current.Items is a per-request cache store.
You can safely add the timer object in Items in OnBeforeAction method and retrieve this timer object from Items in OnAfterAction method