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

Published Sunday, February 26, 2012 8:26 PM

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.

by Glav

Comments

# George said on Tuesday, February 28, 2012 10:52 AM

Although I understand that dependency injection will handle injecting into our constructor, I don't see how it gets registered as a messagehandler.  For example,

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

If I want to have an IRepository injected, how would I handle the line above.  I can't do

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

Thanks for any pointers you can give.

# Glav said on Tuesday, February 28, 2012 3:11 PM

Hi George,

Yes good catch. I was going to address DI in a separate post as there aresome nuances with the beta version and simply provided the 'Note' text as a default. My apologies and I will correct the text.

To answer your question, when adding to the MessageHandler collection, this is often done in the Global.asax.cs where you have access to your ServiceResolver if you are setting one up. So you can either pass that into the constructor of your delegating handler, or use it to create an instance o your handler when adding it to the collection. So something like:

config.MessageHandlers.Add(_container.Resolve<IUsageLogger>());

or

config.MessageHandler.Add(new ApiUsageLogger(_container));

I had this in my code originally, but as I statedI wanted to address DI in a separate post because of some nuancesin this beta.

You could also use the GlobalConfiguration.Configuration.ServiceResolver property to access the currently registered resolver but I dont think this is good practice.

# alex.gadea said on Tuesday, February 28, 2012 6:19 PM

I finally went with the GlobalConfiguration ServiceResolver.  We don't initialize in Globasl.asax because our app has a lot of bootstrap modules where we separate the startup requirements and I don't want to start passing around the container everywhere.

I feel dirty using the GlobalConfiguration serviceresolver as well, but what are the real world implications of why I would not want to use it?

Thanks.

# Glav said on Tuesday, February 28, 2012 8:04 PM

Hi Alex,

The implications of using the static property of the GlobalConfiguration is that lower levels/layers of the application then rely on this property which should have no real knowledge of anything MVC specific in addition to making it harder to test as the dependency on a ServiceResolver is not formally expressed nor obvious, yet the underlying classes do require it.

I dont think passing it around is too bad in the small amount of cases where it is required. Most other dependencies are resolved as per normal (controllers et al).

# Christian.Weyer said on Tuesday, March 6, 2012 4:23 PM

Wanna contribute your logging handler to github.com/.../Thinktecture.Web.Http

# Glav said on Tuesday, March 6, 2012 5:34 PM

Hi Christian,

Good idea. I'll get to that in the next few days. Thanks for pointing me in that direction.

# Christian.Weyer said on Wednesday, March 7, 2012 5:15 AM

Just get in touch with me... ;)

# Microsoft OEM Software said on Wednesday, March 7, 2012 7:08 AM

92vyw3 Major thankies for the blog article.Really looking forward to read more. Keep writing.

# David said on Tuesday, March 13, 2012 12:21 PM

Could you expand on why the deadlock can occur when reading the content? I'm finding that the call pipeline never completes even when I use ReadAsStreamAsync().ContinueWith(...). I see a thread stuck on a Task.Wait() call in System.Web.Http.SelfHost.Channels.HttpMessageEncoderFactory.HttpMessageEncoder.WriteMessage

Thanks

# dcstraw said on Tuesday, March 13, 2012 4:11 PM

My previous comment about seeing the deadlock turned out to be from a different issue. However I'm still curious about exactly how this deadlock can occur.

Also I found that if I implemented the continuation like you did where you just append the continuation without making it part of the higher-level task, the content stream would sometimes be disposed before I could use it. I had to place my continuation in-band with the rest of the call pipeline by returning the continuation in my message handler. Something like:

LogRequest(...).ContinueWith(t => base.SendAsync(...).ContinueWith(t2 => LogResponse(...)).Unwrap()).Unwrap()

# Glav said on Wednesday, March 14, 2012 7:32 AM

Hi dcstraw,

This recommendation came direct from the ASP.Net team. I don't know the internals of the implementation but at a guess, reading the .Result property directly before a task/thread is completed with the result, would need to introduce a synchronisation lock, so it can wait on the result to be populated. Other items in the pipeline may do this, and as tasks/threads are switched around to foster the asynchrony, multiple sync locks may be created and at some time, it is probably possible that a deadlock can manifest. Usually, this would be a result of some pretty specific timing and therefore not immediately obvious nor easily reproduceable, but possible, hence the recommendation.

In general, always ensure a task is complete before reading the .Result property, such as within the .ContinueWith(..) construct.

# google plus hangouts said on Thursday, March 22, 2012 5:37 AM

hd24Gg Thanks for sharing, this is a fantastic article. Really Great.

# Amol Gathale said on Monday, July 2, 2012 10:32 AM

hi thanks for this article. these article is nice. from these article can i handle the wrong body of json or xml.

Leave a Comment

(required) 
(required) 
(optional)
(required) 

This Blog

Syndication