ASP.NET Web Api–Request/Response/Usage Logging

For part 1 of this series of blog posts on ASP.Net Web Api – see here.

Introduction

In Part 2 of this blog post series, we deal with the common requirement of logging, or recording the usage of your Web Api. That is, recording when an Api call was made, what information was passed in via the Api call, and what response was issued to the consumer.

My new Api is awesome – but is it being used?

So you have a shiny new Api all built on the latest bits from Microsoft, the ASP.Net Web Api that shipped with the Beta of MVC 4. A common need for a lot of Api’s is to log usage of each call, to record what came in as part of the request, to also record what response was sent to the consumer. This kind of information is really handy for debugging.Not just for you, but also for your customers as well. Being able to backtrack over the history of Api calls to determine the full context of some problem for a consumer can save a lot of time and guesswork.

So, how do we do this with the Web Api?

Glad you asked.

Determining what kind of injection point to utilise

We have a few options when it comes to determining where to inject our custom classes/code to best intercept incoming and outgoing data. To log all incoming and outgoing data, the most applicable interception point is a System.Net.Http.DelegatingHandler. These classes are message handlers that apply to all messages for all requests and can be chained together to have multiple handlers registered within the message handling pipeline. For example, in addition to Api usage logging, you may want to provide a generic authentication handler that checks for the presence of some authentication key. I could have chosen to use filters however these are typically more scoped to the action itself. I could potentially use model binders but these are relatively late in the processing cycle and not generic enough (plus it would take some potentially unintuitive code to make it work as we would want)..

Enough with theory, show me some code

So, our initial Api usage logger will inherit from the DelegatingHandler class (in the System.Net.Http namespace) and provide its own implementation.

public class ApiUsageLogger : DelegatingHandler
{
    protected override System.Threading.Tasks.Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, System.Threading.CancellationToken cancellationToken)
    {
        //your stuff goes here...
    }
}

We only really need to override one method, the ‘SendAsync' method which returns a Task. Task objects play heavily in the new Web Api and allow asynchronous processing to be used as the primary processing paradigm allowing better scalability and processing utilisation.

Since everything is asynchronous via the use of Tasks, we need to ensure we play by the right rules and utilise the asynchronous capabilities of the Task class. A more fleshed out version of our method is shown below:

protected override System.Threading.Tasks.Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, System.Threading.CancellationToken cancellationToken)
{
    // Extract the request logging information
    var requestLoggingInfo = ExtractLoggingInfoFromRequest(request);

    // Execute the request, this does not block
    var response = base.SendAsync(request, cancellationToken);

    // Log the incoming data to the database
    WriteLoggingInfo(requestLoggingInfo);

    // Once the response is processed asynchronously, log the response data
    // to the database
    response.ContinueWith((responseMsg) =>
    {
        // Extract the response logging info then persist the information
        var responseLoggingInfo = ExtractResponseLoggingInfo(requestLoggingInfo, responseMsg.Result);
        WriteLoggingInfo(responseLoggingInfo);
    });
    return response;
}

To step through the code:

1. First, we extract relevant information from the request message.
2. We execute the request asynchronously via the base class SendAsync method passing in what we received.
3. We log the request information (perhaps to a database). Note that this operation could be performed asynchronously as well.
4. We then define an anonymous function that the asynchronous request task should execute once it has completed.This is done using the ‘ContinueWith’ construct, and passing in an instance of the response message
5. We return the ‘response’, which is really just a Task object that will process the request asynchronously and execute our response logging code once the request has completed processing. .

Registering our Handler

We have created our custom DelegatingHandler, so we need to tell the framework about it.

The registration is done at application startup through access to the GlobalConfiguration object provided by the framework. In the global.asax.cs file, you will find the Application_Start method looking something like this:

protected void Application_Start()
{
    RouteTable.Routes.IgnoreRoute("{resource}.axd/{*pathInfo}");
    RouteTable.Routes.IgnoreRoute("{resource}.ico");

    RegisterApis(GlobalConfiguration.Configuration);
}

You can see the GlobalConfiguration.Configuration object (which is of type System.Web.Http.HttpConfiguration) being passed to the RegisterApis method. We then simply register our DelegatingHandler into the list of MessageHandler from the configuration object as in the following code:

public static void RegisterApis(HttpConfiguration config)
{
    config.MessageHandlers.Add(new ApiUsageLogger());
}

Note: If you have dependency injection setup for your Web Api project, you can either pass in the service resolver as a constructor argument when registering this handler (in the global.asax.cs for example ) like:

config.MessageHandlers.Add(new ApiUsageLogger(_myContainer));

or you can use that same resolver to resolve an instance of this DelegatingHandler when adding to the MessageHandler collection as in:

config.MessageHandlers.Add(_myContainer.Resolve<IApiUsageLogger>());

I shall address some of the nuances of DI in a separate post.

And that is it. Well, that is all that is required to register a new handler that will get called for each request coming into your Api. Actually logging the information requires a little more work to ensure we play correctly in this nice asynchronous world of the WebApi.

But wait, there’s more

Playing nice in the asynchronous world of the WebApi requires a little bit of care. For example, to extract out request information, particularly the body of the request message, you might write a method like the following:

private ApiLoggingInfo ExtractLoggingInfoFromRequest(HttpRequestMessage request)
{
    var info = new ApiLoggingInfo();
    info.HttpMethod = request.Method.Method;
    info.UriAccessed = request.RequestUri.AbsoluteUri;
    info.IPAddress = HttpContext.Current != null ? HttpContext.Current.Request.UserHostAddress : "0.0.0.0";

    ExtractMessageHeadersIntoLoggingInfo(info, request.Headers.ToList());
    if (request.Content != null)
    {
        var byteResponse = request.Content.ReadAsByteArrayAsync().Result;
        info.BodyContent = System.Text.UTF8Encoding.UTF8.GetString(byteResponse);
    }
    return info;
}

Notice the line that reads:

var byteResponse = request.Content.ReadAsByteArrayAsync().Result;

Here we are accessing the Result property from an asynchronous task in an attempt to make this code procedural and work in a synchronous manner. It is an easy thing to do, and looks like it makes sense. However, do not do this.

Generally, you should never access the ‘Result’ property of a Task unless you know that the task has completed as this can cause deadlocks in ASP.Net. Yes it is true.Sometimes this code may work but, if you don’t want to waste hours debugging deadlock issues in ASP.Net, I would advise against it.

So how do we know when it is complete? With the ‘ContinueWith’ construct of course. So your code may change to look more like this:

private ApiLoggingInfo ExtractLoggingInfoFromRequest(HttpRequestMessage request)
{
    var info = new ApiLoggingInfo();
    info.HttpMethod = request.Method.Method;
    info.UriAccessed = request.RequestUri.AbsoluteUri;
    info.IPAddress = HttpContext.Current != null ? HttpContext.Current.Request.UserHostAddress : "0.0.0.0";

    ExtractMessageHeadersIntoLoggingInfo(info, request.Headers.ToList());
    if (request.Content != null)
    {
        request.Content.ReadAsByteArrayAsync()
            .ContinueWith((task) =>
                            {
                                info.BodyContent = System.Text.UTF8Encoding.UTF8.GetString(task.Result);
                                return info;

                            });
    }
    return info;
}

In the above example, we can safely use the ‘Result’ property of the task since the method within the ‘ContinueWith’ block is only executed once the initial task is completed.

Wrap up

The above code fragments provide a simple and basic way of registering a custom interception point within the WebApi pipeline to perform a custom task, in this case usage logging.

The next series of posts will look at items such as the use of model binding, security and much more.