Smart Logging Middleware for ASP.NET Core

Nicholas Blumhardt -

ASP.NET Core comes with request logging built-in. This is great for getting an app up-and-running, but the events are not as descriptive or efficient as hand-crafted request logging can be. Here is a typical trace from a single GET request to /about:

If the request fails because of an error, you'll see instead:

While these fine-grained events are sometimes useful, they take up storage space and bandwidth, and add noise to the log.

Spreading the information across many events also makes it harder to perform some analyses, for example, the HTTP method and elapsed time are on different events, making it hard to separate the timings of GET and POST requests to the same RequestPath.

In production we want:

  • One "infrastructure" event per normal request, with basic HTTP information attached
  • Extra information to help with debugging if a request fails due to a server-side (5xx) error
  • The same format and event type for all requests, so that logs from both successful and failed requests can be easily grouped, sorted and analyzed together

Here's the format we're aiming for, expanded so that you can see all of the attached properties:

Instead of five infrastructure events + one application event, just a single infrastructure event is logged. This makes the application's own "Hello" event much easier to spot.

This post includes the full source code for the middleware, so you can take it and modify it to include the information you find most useful.

Step 1: Install and Configure Serilog

ASP.NET Core includes some basic logging providers, but to get the most out of it you'll need to plug in a full logging framework like Serilog. If you haven't done that already, these instructions should have you up and running quickly.

The examples show events in Seq; to use it you'll need to install it and configure the appropriate Serilog sink. The middleware works with any Serilog sink, so you can alternatively use a log file, database, or one of the other log servers supported by Serilog.

Step 2: Turn off Information events from Microsoft and System

Where Serilog is configured, add level overrides for the Microsoft and System namespaces:

Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Override("Microsoft", LogEventLevel.Warning)
    .MinimumLevel.Override("System", LogEventLevel.Warning)
    // Other logger configuration

These can be turned back on for debugging when they're needed.

If you're using appsettings.json configuration, check out the level overrides example in the README.

Step 3: Add the SerilogMiddleware class

The SerilogMiddleware class hooks into the request processing pipeline to collect information about the requests:

using Microsoft.AspNetCore.Http;
using Serilog;
using Serilog.Events;
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Linq;
using System.Threading.Tasks;

namespace Datalust.SerilogMiddlewareExample.Diagnostics
{
    class SerilogMiddleware
    {
        const string MessageTemplate =
            "HTTP {RequestMethod} {RequestPath} responded {StatusCode} in {Elapsed:0.0000} ms";

        static readonly ILogger Log = Serilog.Log.ForContext<SerilogMiddleware>();

        readonly RequestDelegate _next;

        public SerilogMiddleware(RequestDelegate next)
        {
            if (next == null) throw new ArgumentNullException(nameof(next));
            _next = next;
        }

        public async Task Invoke(HttpContext httpContext)
        {
            if (httpContext == null) throw new ArgumentNullException(nameof(httpContext));

            var sw = Stopwatch.StartNew();
            try
            {
                await _next(httpContext);
                sw.Stop();

                var statusCode = httpContext.Response?.StatusCode;
                var level = statusCode > 499 ? LogEventLevel.Error : LogEventLevel.Information;

                var log = level == LogEventLevel.Error ? LogForErrorContext(httpContext) : Log;
                log.Write(level, MessageTemplate, httpContext.Request.Method, httpContext.Request.Path, statusCode, sw.Elapsed.TotalMilliseconds);
            }
            // Never caught, because `LogException()` returns false.
            catch (Exception ex) when (LogException(httpContext, sw, ex)) { }
        }

        static bool LogException(HttpContext httpContext, Stopwatch sw, Exception ex)
        {
            sw.Stop();

            LogForErrorContext(httpContext)
                .Error(ex, MessageTemplate, httpContext.Request.Method, httpContext.Request.Path, 500, sw.Elapsed.TotalMilliseconds);

            return false;
        }

        static ILogger LogForErrorContext(HttpContext httpContext)
        {
            var request = httpContext.Request;

            var result = Log
                .ForContext("RequestHeaders", request.Headers.ToDictionary(h => h.Key, h => h.Value.ToString()), destructureObjects: true)
                .ForContext("RequestHost", request.Host)
                .ForContext("RequestProtocol", request.Protocol);

            if (request.HasFormContentType)
                result = result.ForContext("RequestForm", request.Form.ToDictionary(v => v.Key, v => v.Value.ToString()));

            return result;
        }
    }
}

I've deliberately kept this to a single (somewhat ugly!) source file so that it's easy to copy, paste and modify. I'm hoping to use this code as the basis for a contribution to SerilogWeb, a collection of HTTP logging utilities for different flavors of ASP.NET that I've written about here previously.

There are a lot of design details and trade-offs involved. You can see that when a request is deemed to have failed, some additional information is attached, including the headers sent by the client, and the form data if any.

Step 4: Add the middleware to the pipeline

In your application's Startup.cs file, you can add the middleware either before or after the outermost exception handling components. If you add it before this, you won't get the full Exception information in any error events, but you will always be able to record the exact status code returned to the client. Adding the middleware into the pipeline inside the exception handling components (i.e., after them in the source code) will provide all exception detail but has to assume that the status code is 500 in this case.

public void Configure(IApplicationBuilder app, IHostingEnvironment env,
                      ILoggerFactory loggerFactory)
{
    loggerFactory.AddSerilog();

    if (env.IsDevelopment())
    {
        app.UseDeveloperExceptionPage();
        app.UseBrowserLink();
    }
    else
    {
        app.UseExceptionHandler("/Home/Error");
    }

    app.UseMiddleware<SerilogMiddleware>();

    app.UseStaticFiles();

    app.UseMvc(routes =>
    {
        routes.MapRoute(
            name: "default",
            template: "{controller=Home}/{action=Index}/{id?}");
    });
}

Step 5: Profit!

Now you have a stream of request log events each with paths, status codes, timings, and exceptions:

We've seen how a simple customized logging strategy can not only produce cleaner events, but also reduce the volume of infrastructure log events.

The full source code for the example is here on GitHub. It would be great to have your feedback on the implementation.