Custom Web Api asynchronous filter implementation

Question

Following the tutorial from Filip W's blog, I've ended up creating my own implementation for a custom ActionFilter.

This logs the execution name, action, parameters and elapsed time of every ApiController in my solution.

The post is a bit old (2013), that's why I'm still thinking it must be a better/simpler way to do this, any suggestion? improvements?

public sealed class LogActionFilter : FilterAttribute, IActionFilter
{
    private readonly Stopwatch _stopwatch = new Stopwatch();

    public bool AllowMultiple => false;

    public async Task<HttpResponseMessage> ExecuteActionFilterAsync(HttpActionContext actionContext,
        CancellationToken cancellationToken, Func<Task<HttpResponseMessage>> continuation)
    {
        await InternalActionExecuting(actionContext);

        if (actionContext.Response != null)
            return actionContext.Response;

        HttpActionExecutedContext executedContext;
        try
        {
            var response = await continuation();
            executedContext = new HttpActionExecutedContext(actionContext, null)
            {
                Response = response
            };
        }
        catch (Exception exception)
        {
            executedContext = new HttpActionExecutedContext(actionContext, exception);
        }

        await InternalActionExecuted(executedContext);
        _stopwatch.Reset();

        return executedContext.Response;
    }

    private Task InternalActionExecuting(HttpActionContext actionContext)
    {
        _stopwatch.Start();
        return Log("Executing", actionContext, 0);
    }

    private Task InternalActionExecuted(HttpActionExecutedContext actionExecutedContext)
    {
        _stopwatch.Stop();
        return Log("Executed", actionExecutedContext.ActionContext, _stopwatch.ElapsedMilliseconds);
    }

    private Task Log(string action, HttpActionContext actionContext, long elapsedTime)
    {
        return Task.Run(() =>
        {
            var controllerName = actionContext.ControllerContext.ControllerDescriptor.ControllerName;
            var actionName = actionContext.ActionDescriptor.ActionName;
            var parameters = string.Join(", ", actionContext.ActionArguments.Values.Select(x => x).ToArray());

            var message = $"{action}: ctrl: {controllerName}, act: {actionName}, params: {parameters}" +
                          $"{(elapsedTime > 0 ? "took (ms): " + elapsedTime : string.Empty) }";

            Trace.WriteLine(message, "Action filter log");
        });
    }
}

Answer 1

Here is couple of things that I could done;

• Implement a logger class, Logging with "Trace.WriteLine" is not usefull for everycase.
• Override allow multiple; public override bool AllowMultiple => false;

• Log the error...

  public sealed class LogActionFilter : FilterAttribute, IActionFilter
  {
      private readonly ILogManager _logManager;
  
      public LogActionFilter(ILogManager logManager)
      {
          _logManager = logManager;
      }
  
      private readonly Stopwatch _stopwatch = new Stopwatch();
  
      public override bool AllowMultiple => false;
  
      public async Task<HttpResponseMessage> ExecuteActionFilterAsync(HttpActionContext actionContext,
                                                                      CancellationToken cancellationToken,
                                                                      Func<Task<HttpResponseMessage>> continuation)
      {
          await InternalActionExecuting(actionContext);
  
          if (actionContext.Response != null)
          {
              return actionContext.Response;
          }
  
          HttpActionExecutedContext executedContext;
  
          try
          {
              var response = await continuation();
  
              executedContext = new HttpActionExecutedContext(actionContext, null)
                                {
                                    Response = response
                                };
          }
          catch (Exception exception)
          {
              executedContext = new HttpActionExecutedContext(actionContext, exception);
              _logManager.Error(exception, "LogAction recorded an error");
          }
  
          await InternalActionExecuted(executedContext);
          _stopwatch.Reset();
  
          return executedContext.Response;
      }
  
      private Task InternalActionExecuting(HttpActionContext actionContext)
      {
          _stopwatch.Start();
          return Log("Executing", actionContext, 0);
      }
  
      private Task InternalActionExecuted(HttpActionExecutedContext actionExecutedContext)
      {
          _stopwatch.Stop();
          return Log("Executed", actionExecutedContext.ActionContext, _stopwatch.ElapsedMilliseconds);
      }
  
      private Task Log(string action, HttpActionContext actionContext, long elapsedTime)
      {
          return Task.Run(() =>
                          {
                              var controllerName = actionContext.ControllerContext.ControllerDescriptor.ControllerName;
                              var actionName = actionContext.ActionDescriptor.ActionName;
                              var parameters = string.Join(", ", actionContext.ActionArguments.Values.Select(x => x).ToArray());
  
                              var message = $"{action}: ctrl: {controllerName}, act: {actionName}, params: {parameters}" +
                                            $"{(elapsedTime > 0 ? "took (ms): " + elapsedTime : string.Empty)}";
  #if (DEBUG)
                              Trace.WriteLine(message, "Action filter log");
  #elif (RELEASE)
                              _logManager.Debug(null, message, "Action filter log");
  #endif
  
                          });
      }
  }