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.
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.
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.
