Use OWIN middleware or a delegating MessgaeHandler to log api requests/responses?

Question

In my old non-OWIN APIs, I use a MessageHanlder to log all HttpRequests and HttpResponses. Here is the MessageHandler:

public class MessageHandler : DelegatingHandler
{
    private static readonly ILog RequestApiLogger = LogManager.GetLogger("RequestApiPacketLogger");
    private static readonly ILog ResponseApiLogger = LogManager.GetLogger("ResponseApiPacketLogger");

    protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
    {
        var correlationId = Guid.NewGuid();

        RequestApiLogger.LogHttpRequest(request, correlationId);

        return await base.SendAsync(request, cancellationToken).ContinueWith(
            task =>
            {
                var response = task.Result;
                response.Headers.Add("http-tracking-id", correlationId.ToString("D"));
                ResponseApiLogger.LogHttpResponse(response, correlationId);
                return response;

            }, cancellationToken);
    }
}

However, in my newer projects I could write custom OWIN middleware to do something similar using the OwinContext like this:

//use an alias for the OWIN AppFunc
using AppFunc = Func<IDictionary<string, object>, Task>;

public class LoggingMiddleware
{
    private readonly AppFunc _next;

    public LoggingMiddleware(AppFunc next)
    {
        _next = next;
    }

    public async Task Invoke(IDictionary<string, object> environment)
    {
        IOwinContext context = new OwinContext(environment);

        // Get the identity 
        var identity = (context.Request.User != null && context.Request.User.Identity.IsAuthenticated)
            ? context.Request.User.Identity.Name
            : "(anonymous)";

        // Buffer the request (body is a string, we can use this to log the request later
        var requestBody = new StreamReader(context.Request.Body).ReadToEnd();
        var requestData = Encoding.UTF8.GetBytes(requestBody);
        context.Request.Body = new MemoryStream(requestData);

        var apiPacket = new ApiPacket
        {
            CallerIdentity = identity,
            Request = requestBody,
            RequestLength = context.Request.Body.Length
        };

        // Buffer the response
        var responseBuffer = new MemoryStream();
        var responseStream = context.Response.Body;
        context.Response.Body = responseBuffer;

        // add the "http-tracking-id" response header so the user can correlate back to this entry
        var responseHeaders = (IDictionary<string, string[]>)environment["owin.ResponseHeaders"];
        responseHeaders["http-tracking-id"] = new[] { apiPacket.TrackingId.ToString("d") };

        await _next.Invoke(environment);

        responseBuffer.Seek(0, SeekOrigin.Begin);
        var reader = new StreamReader(responseBuffer);
        apiPacket.Response = await reader.ReadToEndAsync();
        apiPacket.ResponseLength = context.Response.ContentLength ?? 0;

        WriteRequestHeaders(context.Request, apiPacket);
        WriteResponseHeaders(context.Response, apiPacket);

        // You need to do this so that the response we buffered is flushed out to the client application.
        responseBuffer.Seek(0, SeekOrigin.Begin);
        await responseBuffer.CopyToAsync(responseStream);

        //TODO: persist the ApiPacket in the database
    }

    private static void WriteRequestHeaders(IOwinRequest request, ApiPacket packet)
    {
        packet.Verb = request.Method;
        packet.RequestUri = request.Uri;
        packet.RequestHeaders = "{\r\n" + string.Join(Environment.NewLine, request.Headers.Select(kv => "\t" + kv.Key + "=" + string.Join(",", kv.Value))) + "\r\n}";
    }

    private static void WriteResponseHeaders(IOwinResponse response, ApiPacket packet)
    {
        packet.StatusCode = response.StatusCode;
        packet.ReasonPhrase = response.ReasonPhrase;
        packet.ResponseHeaders = "{\r\n" + string.Join(Environment.NewLine, response.Headers.Select(kv => "\t" + kv.Key + "=" + string.Join(",", kv.Value))) + "\r\n}";
    }
}

I'm using log4net to write the information to a SQL2012 database. Both ways accomplish my goal. However, I'm looking for a reason to use one method over the other. Should I use custom OWIN middleware OR a MessageHandler, and why? Thanks in advance.

score 0 · Answer 1 · answered Feb 16 '16 at 21:51

Since you already have the MessageHandler implementations, I would recommend using that until you have a reason otherwise.

However, off the top of my head one valid reason to move logging to an OwinMiddleware would be if you have other OwinMiddleware components that require (or would benefit from) that logging functionality (assuming that you are using WebApi whereby the MessageHandlers will run after all of the OwinMiddleware in the request-pipeline).

score 0 · Accepted Answer · answered Feb 18 '16 at 14:27

Looks like I will be using OWIN middleware. I found that inside the MessageHandler the Principal.IIdentity has not yet been resolved. For example, if I put breakpoints in my message handler, an API controller's constructor, and in the API method, this is what I see (in order).

Using Message Handler

In MessageHandler > Principal.IIdentity not yet resolved.
In API controller's constructor > Principal.IIDentity not yet resolved.
In API controller's GET method, the Principal.IIdentity is finally resolved.

Thus, I can't pull out and log the authorized user's id in the MessageHandler.

However, when using the OWIN middleware, the Principal.IIdentity IS resolved there, so I can write the userId to my log table at that point. This is why I've decided to use the middleware.

Maybe someone can provide some clarity as to when the IIDentity is set in an API project though.

Use OWIN middleware or a delegating MessgaeHandler to log api requests/responses?

2 Answers2