NDC Oslo 2016

I år var nionde gången som NDC Oslo gick av stapeln och konferensen har under denna tiden vuxit till en av Europas största .NET konferenser. Den bjöd på 2 dagars workshops och 3 dagars konferens. Troy Hunt inledde konferensen med en rolig och tänkvärd keynote: “Yesterday’s Technology is Dead, Today’s is on Life Support”. Han […]

Read More

NDC London 2016 Onsdagen

Efter en briljant keynote av Scott Hanselman, så startade årets upplaga av NDC London. En utvecklarkonferens med primärt fokus på .NET och webbteknologier. För min egen del så hade jag valt ASP.NET 5 och .NET Core som ett stort fokus för första dagen. Jag blev inte besviken, med många riktigt bra föreläsningar från några av […]

Read More

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:

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

            <span>//Core-concern</span>
            var response = DoSomething();

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

            <span>return</span> 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:

        <span>// GET api/values/5</span>
        <span>public</span> <span>string</span> Get(<span>int</span> id)
        {
            <span>return</span> 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:

    <span>public</span> <span>class</span> MessageHandler : DelegatingHandler
    {
        <span>protected</span> <span>override</span> async Task&lt;HttpResponseMessage&gt; SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
        {
           <span>return</span> <span>base</span>.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.

    <span>public</span> <span>abstract</span> <span>class</span> MessageHandler : DelegatingHandler
    {
        <span>protected</span> <span>override</span> async Task&lt;HttpResponseMessage&gt; SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
        {
            var requestMessage = await request.Content.ReadAsByteArrayAsync();

            var response = await <span>base</span>.SendAsync(request, cancellationToken);

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

            <span>return</span> 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:

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

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

            await IncommingMessageAsync(corrId, requestInfo, requestMessage);

            var response = await <span>base</span>.SendAsync(request, cancellationToken);

            <span>byte</span>[] responseMessage;

            <span>if</span> (response.IsSuccessStatusCode)
                responseMessage = await response.Content.ReadAsByteArrayAsync();
            <span>else</span>
                responseMessage = Encoding.UTF8.GetBytes(response.ReasonPhrase);

            await OutgoingMessageAsync(corrId, requestInfo, responseMessage);

            <span>return</span> response;
        }

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

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

        <span>protected</span> <span>override</span> async Task OutgoingMessageAsync(<span>string</span> correlationId, <span>string</span> requestInfo, <span>byte</span>[] message)
        {
            await Task.Run(() =&gt;
                Debug.WriteLine(<span>string</span>.Format(<span>"{0} - Response: {1}\r\n{2}"</span>, 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:<span>//localhost:3208/api/values</span>

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

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:

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

            ...

        }
    }

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.

Read More

Intryck från SDC 2012

Här kommer mina något sena intryck från Scandinavian Developer Conference 2012 (SDC)  som hölls för några veckor sedan på Svenska Mässan i Göteborg. Tyckte mässan var välordnad, bra lokaler, bra mat och allt verkade fungera som det skulle. Har dock inte så mycket att jämföra med då detta var första gången jag deltog på en konferens. Det som jag tycker […]

Read More

3:e Maj – Åter en kväll att minnas!

Nu är det åter dags för en inspirationsafton av stora mått. Javaforum och nForum samkör sina teknikseminarier 3:e maj i Folkets hus vid Järntorget i Göteborg. Denna gång behandlas allt från modularitet på JVM’en och case-studies ur veckligheten till scenario-testning och säkerhetsaspekter på .net-plattformen. Agenda och anmälan hittar ni på respektive site. Som vanligt räcker […]

Read More