How do we log authentication token requests in ASP.NET Web API

Question

We have an ASP.NET Web Api application which uses OAuth Bearer Tokens for authentication, for which we are trying to implement Request/Response logging.

Basically it works like this:
1. User sends request to "/authenticate" and receives an authentication token
2. User then uses this authentication token for requests to the exposed API methods

For logging requests to the exposed API methods, we use a DelegatingHandler which works perfectly fine.

However, requests made to "/authenticate" are not captured by the DelegatingHandler implementation.

Is there a different approach required for logging requests for tokens?

public abstract class MessageHandler : DelegatingHandler
{
    protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
    {
        var correlationId = Guid.NewGuid();

        var requestInfo = string.Format("{0} {1}", request.Method, request.RequestUri);

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

        var context = ((HttpContextBase)request.Properties["MS_HttpContext"]);

        await IncomingMessageAsync(correlationId, request.Method, request.RequestUri, request.Headers, requestContent, 
            context.Request.UserHostAddress, context.Request.IsAuthenticated, context.User.Identity.Name);

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

        byte[] responseMessage;

        responseMessage = await response.Content.ReadAsByteArrayAsync();

        await OutgoingMessageAsync(correlationId, response.StatusCode, response.Headers, responseMessage);

        return response;
    }

    protected abstract Task IncomingMessageAsync(Guid correlationId, HttpMethod requestMethod, Uri requestUri, HttpRequestHeaders requestHeaders, byte[] messageContent, string ipAddress, bool isAuthenticated, string requestMadeByUserName);
    protected abstract Task OutgoingMessageAsync(Guid correlationId, HttpStatusCode statusCode, HttpResponseHeaders responseHeaders, byte[] messageContent);
}

EDIT w/ OAuth Code

[assembly: OwinStartup(typeof(MyApp.Infrastructure.IdentityConfig))]
namespace MyApp.Infrastructure
{
    public class IdentityConfig
    {
        public void Configuration(IAppBuilder app)
        {
            app.CreatePerOwinContext<ApplicationIdentityDbContext>(() => ApplicationIdentityDbContext.Create(ConfigurationDataProvider.MYDBCONNSTRING));
            app.CreatePerOwinContext<ApplicationUserManager>(ApplicationUserManager.Create);
            app.CreatePerOwinContext<ApplicationRoleManager>(ApplicationRoleManager.Create);

            app.UseOAuthBearerTokens(new OAuthAuthorizationServerOptions
            {
                 Provider = new ApplicationAuthProvider(),
                 AllowInsecureHttp = true,
                 TokenEndpointPath = new PathString("/Authenticate")
            });
        }
    }
}

Answer 1

You are installing OWIN middleware to issue tokens before the WebAPI middleware.

 app.UseOAuthBearerTokens(new OAuthAuthorizationServerOptions
     {
         Provider = new ApplicationAuthProvider(),
         AllowInsecureHttp = true,
         TokenEndpointPath = new PathString("/Authenticate")
     });

The DelegatingHandler you try to use to log the request is part of the Web API middeware and is never reached because the token issuing middleware handles the request and does not call middleware further in the pipeline.

Instead of using DelegatingHandler, use the following middleware and install it before the token middleware.

public class RequestLoggerMiddleware
{
    private readonly Func<IDictionary<string, object>, Task> _next;
    private readonly ILogger _logger;

    public RequestLoggerMiddleware(
        Func<IDictionary<string, object>, Task> next, 
        ILogger logger)
    {
        _next = next;
        _logger = logger;
    }

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

        _logger.Write($"{context.Request.Method} {context.Request.Uri.AbsoluteUri}");
        var result = _next.Invoke(environment);
        _logger.Write($"Status code: {context.Response.StatusCode}");

        return result;
    }
}

To install the middleware, just insert the statement: app.Use(typeof (RequestLoggerMiddleware)); before the app.UseOAuthBearerTokens statement in your Startup.cs.