How to Add Logging to MVC4 WebApi

Question

I am trying to create a [LoggedApiCall] filter for a Get() on an ApiController According to this: ASP.NET Web API ActionFilter example

I have created a System.Web.HttpFilters.ActionFilterAttribute. The override allows for OnActionExecuted(HttpActionExecutedContext actionExecutedContext)

I cannot seem to find a way to get the IP of the caller from the HttpActionExecutedContext

Perhaps I am going about logging every API call the wrong way?

Answer 1

We use the following filter which we add to HttpConfiguration.Filters. Some code:

internal class LoggingFilter : IExceptionFilter, IActionFilter
{
    private readonly ILog log;

    public LoggingFilter(ILog log)
    {
        if (log == null)
        {
            throw new ArgumentNullException("log");
        }

        this.log = log;
    }

    public bool AllowMultiple
    {
        get { return false; }
    }

    Task IExceptionFilter.ExecuteExceptionFilterAsync(HttpActionExecutedContext actionContext, CancellationToken cancellationToken)
    {
        if (actionContext == null)
        {
            throw new ArgumentNullException("actionContext");
        }

        this.log.Error(string.Format("Unexpected error while executing {0}", this.BuildLogEntry(actionContext.ActionContext)), actionContext.Exception);
        return TaskHelpers.Completed();
    }

    Task<HttpResponseMessage> IActionFilter.ExecuteActionFilterAsync(HttpActionContext actionContext, CancellationToken cancellationToken, Func<Task<HttpResponseMessage>> continuation)
    {
        if (actionContext == null)
        {
            throw new ArgumentNullException("actionContext");
        }

        if (continuation == null)
        {
            throw new ArgumentNullException("continuation");
        }

        if (!this.log.IsDebugEnabled)
        {
            // no point running at all if logging isn't currently enabled
            return continuation();
        }

        string logEntry = this.BuildLogEntry(actionContext);
        IDisposable logContext = this.log.DebugTiming("Executing {0}", logEntry);

        Task<string> requestContent;
        if (actionContext.Request.Content != null)
        {
            requestContent = actionContext.Request.Content.ReadAsStringAsync().ContinueWith(requestResult => string.IsNullOrEmpty(requestResult.Result) ? "N/A" : requestResult.Result);
        }
        else
        {
            requestContent = TaskHelpers.FromResult("N/A");
        }

        return requestContent.ContinueWith(
            requestResult =>
                {
                    this.log.DebugFormat("{0}, Request = {1}", logEntry, requestResult.Result);

                    return continuation()
                        .ContinueWith(t =>
                            {
                                Task<string> responseContent;
                                if (t.IsCompleted && t.Result.Content != null)
                                {
                                    responseContent = t.Result.Content.ReadAsStringAsync().ContinueWith(responseResult => string.IsNullOrEmpty(responseResult.Result) ? "N/A" : responseResult.Result);
                                }
                                else
                                {
                                    responseContent = TaskHelpers.FromResult("N/A");
                                }

                                return responseContent.ContinueWith(
                                    responseResult =>
                                        {
                                            using (logContext)
                                            {
                                                this.log.DebugFormat("{0}, Status Code: {1}, Response = {2}", logEntry, t.Result.StatusCode, responseResult.Result);
                                            }

                                            return t.Result;
                                        });
                            }).Unwrap();
                }).Unwrap();
    }

    /// <summary>
    /// Builds log data about the request.
    /// </summary>
    /// <param name="actionContext">Data associated with the call</param>
    private string BuildLogEntry(HttpActionContext actionContext)
    {
        string route = actionContext.Request.GetRouteData().Route.RouteTemplate;
        string method = actionContext.Request.Method.Method;
        string url = actionContext.Request.RequestUri.AbsoluteUri;
        string controllerName = actionContext.ActionDescriptor.ControllerDescriptor.ControllerName;
        string actionName = actionContext.ActionDescriptor.ActionName;

        return string.Format("{0} {1}, route: {2}, controller:{3}, action:{4}", method, url, route, controllerName, actionName);
    }
}

We use log4net, you can replace the ILog implementation with whatever you see fit. ILog.DebugTiming is just an extension method that uses a Stopwatch to get elapsed time for each call.

Edit: This post Get the IP address of the remote host has details on how to get the IP address of the remote caller.

Cheers, Dean