Log message Request and Response in ASP.NET WebAPI

Log message Request and Response in ASP.NET WebAPI

By logging both incoming and outgoing messages for services can be useful in many scenarios, such as debugging, tracing, inspection and helping customers with request problems etc.  I have a customer that need to have both incoming and outgoing messages to be logged. They use the information to see strange behaviors and also to help customers when they call in  for help (They can by looking in the log see if the customers sends in data in a wrong or strange way).

 

Concerns

Most loggings in applications are cross-cutting concerns and should not be  a core concern for developers. Logging messages like this:

 

// GET api/values/5
public string Get(int id)
{
//Cross-cutting concerns
Log(string.Format("Request: GET api/values/{0}", id));

//Core-concern
var response = DoSomething();

//Cross-cutting concerns
Log(string.Format("Reponse: GET api/values/{0}\r\n{1}", id, response));

return response;
}

will only result in duplication of code, and unnecessarily concerns for the developers to be aware of, if they miss adding the logging code, no logging will take place. Developers should focus on the core-concern, not the cross-cutting concerns. By just focus on the core-concern the above code will look like this:

// GET api/values/5
public string Get(int id)
{
return DoSomething();
}

The logging should then be placed somewhere else so the developers doesn’t need to focus care about the cross-concern.

Using Message Handler for logging

There are different ways we could place the cross-cutting concern of logging message when using WebAPI. We can for example create a custom ApiController and override the ApiController’s ExecutingAsync method, or add a ActionFilter, or use a Message Handler. The disadvantage with custom ApiController is that we need to make sure we inherit from it, the disadvantage of ActionFilter, is that we need to add the filter to the controllers, both will modify our ApiControllers. By using a Message Handler we don’t need to do any changes to our ApiControllers. So the best suitable place to add our logging would be in a custom Message Handler. A Message Handler will be used before the HttpControllerDispatcher (The part in the WepAPI pipe-line that make sure the right controller is used and called etc).

Note: You can read more about message handlers here, it will give you a good understanding of the WebApi pipe-line.

To create a Message Handle we can inherit from the DelegatingHandler class and override the SendAsync method:

public class MessageHandler : DelegatingHandler
{
protected override async Task SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
{
return base.SendAsync(request, cancellationToken);
}
}
 

If we skip the call to the base.SendAsync our ApiController’s methods will never be invoked, nor other Message Handlers. Everything placed before base.SendAsync will be called before the HttpControllerDispatcher (before WebAPI will take a look at the request which controller and method it should be invoke), everything after the base.SendAsync, will be executed after our ApiController method has returned a response. So a message handle will be a perfect place to add cross-cutting concerns such as logging.

To get the content of our response within a Message Handler we can use the request argument of the SendAsync method. The request argument is of type HttpRequestMessage and has a Content property (Content is of type HttpContent. The HttpContent has several method that can be used to read the incoming message, such as ReadAsStreamAsync, ReadAsByteArrayAsync and ReadAsStringAsync etc.

Something to be aware of is what will happen when we read from the HttpContent. When we read from the HttpContent, we read from a stream, once we read from it, we can’t be read from it again. So if we read from the Stream before the base.SendAsync, the next coming Message Handlers and the HttpControllerDispatcher can’t read from the Stream because it’s already read, so our ApiControllers methods will never be invoked etc. The only way to make sure we can do repeatable reads from the HttpContent is to copy the content into a buffer, and then read from that buffer. This can be done by using the HttpContent’s LoadIntoBufferAsync method. If we make a call to the LoadIntoBufferAsync method before the base.SendAsync, the incoming stream will be read in to a byte array, and then other HttpContent read operations will read from that buffer if it’s exists instead directly form the stream. There is one method on the HttpContent that will internally make a call to the  LoadIntoBufferAsync for us, and that is the ReadAsByteArrayAsync. This is the method we will use to read from the incoming and outgoing message.

public abstract class MessageHandler : DelegatingHandler
{
protected override async Task SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
{
var requestMessage = await request.Content.ReadAsByteArrayAsync();

var response = await base.SendAsync(request, cancellationToken);

var responseMessage = await response.Content.ReadAsByteArrayAsync();

return response;
}
}

The above code will read the content of the incoming message and then call the SendAsync and after that read from the content of the response message.
The following code will add more logic such as creating a correlation id to combine the request with the response, and create a log entry etc:

public abstract class MessageHandler : DelegatingHandler
{
protected override async Task SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
{
var corrId = string.Format("{0}{1}", DateTime.Now.Ticks, Thread.CurrentThread.ManagedThreadId);
var requestInfo = string.Format("{0} {1}", request.Method, request.RequestUri);

var requestMessage = await request.Content.ReadAsByteArrayAsync();

await IncommingMessageAsync(corrId, requestInfo, requestMessage);

var response = await base.SendAsync(request, cancellationToken);

var responseMessage = await response.Content.ReadAsByteArrayAsync();

await OutgoingMessageAsync(corrId, requestInfo, responseMessage);

return response;
}

protected abstract Task IncommingMessageAsync(string correlationId, string requestInfo, byte[] message);
protected abstract Task OutgoingMessageAsync(string correlationId, string requestInfo, byte[] message);
}

public class MessageLoggingHandler : MessageHandler
{
protected override async Task IncommingMessageAsync(string correlationId, string requestInfo, byte[] message)
{
await Task.Run(() =>
Debug.WriteLine(string.Format("{0} - Request: {1}\r\n{2}", correlationId, requestInfo, Encoding.UTF8.GetString(message))));
}

protected override async Task OutgoingMessageAsync(string correlationId, string requestInfo, byte[] message)
{
await Task.Run(() =>
Debug.WriteLine(string.Format("{0} - Response: {1}\r\n{2}", correlationId, requestInfo, Encoding.UTF8.GetString(message))));
}
}
 

The code above will show the following in the Visual Studio output window when the “api/values” service (One standard controller added by the default WepAPI template) is requested with a Get http method :

6347483479959544375 - Request: GET http://localhost:3208/api/values

6347483479959544375 - Response: GET http://localhost:3208/api/values
["value1","value2"]
 

Register a Message Handler

To register a Message handler we can use the Add method of the GlobalConfiguration.Configration.MessageHandlers in for example Global.asax:

public class WebApiApplication : System.Web.HttpApplication
{
protected void Application_Start()
{
GlobalConfiguration.Configuration.MessageHandlers.Add(new MessageLoggingHandler());

...
}
}
 

Summary

By using a Message Handler we can easily remove cross-cutting concerns like logging from our controllers.

You can also find the source code used in this blog post on ForkCan.com, feel free to make a fork or add comments, such as making the code better etc.

Feel free to follow me on twitter @fredrikn if you want to know when I will write other blog posts etc.