In previous posts in this series I have described how to configure Serilog's RequestLogging middleware to add additional properties to Serilog's request log summary such as the request hostname or the selected endpoint name. I have also showed how to add MVC or RazorPage-specific properties to the summary log using Filters.
In this post I show how to skip adding the summary log message completely for specific requests. This can be useful when you have an endpoint that is hit a lot, where logging every request is of little value.
Health checks are called a lot
The motivation for this post comes from behaviour we've seen when running applications in Kubernetes. Kubernetes uses two types of "health checks" (or "probes") for checking applications are running correctly - liveness probes and readiness probes. You can configure a probe to make an HTTP request to your application as an indicator that your application is running correctly.
As of Kubernetes version 1.16 there is a third type of probe, startup probes.
The Health Check endpoints available in ASP.NET Core 2.2+ are ideally suited for these probes. You can set up a simple, dumb, health check that returns a 200 OK response to every request, to let Kubernetes know your app hasn't crashed.
In ASP.NET Core 3.x, you can configure your health checks using endpoint routing. You must add the required services in Startup.cs by calling AddHealthChecks(), and add a health check endpoint using MapHealthChecks():
public class Startup
{
public void ConfigureServices(IServiceCollection services)
{
// ..other service configuration
services.AddHealthChecks(); // Add health check services
}
public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
{
// .. other middleware
app.UseRouting();
app.UseAuthorization();
app.UseEndpoints(endpoints =>
{
endpoints.MapHealthChecks("/healthz"); //Add health check endpoint
endpoints.MapControllers();
});
}
}
In the example above, sending a request to /healthz will invoke the health check endpoint. As I didn't configure any health checks to run, the endpoint will always return a 200 response, as long as the app is running:
The only problem with this is that Kubernetes will call this endpoint a lot. The exact frequency is up to you, but every 10s is common. You want a relatively high frequency so Kubernetes can restart faulty pods quickly.
That's not a problem in of itself; Kestrel can handle millions of requests a second, so it's not a performance concern. More irritating is the number of logs generated by each request. It's not as many as I showed for a request to the MVC infrastructure, but even 1 log per request (as we get with Serilog.AspNetCore) can get irritating.
The main problem is that the logs for successful health check requests don't actually tell us anything useful. They're not related to any business activities, they're purely infrastructural. It would be nice to be able to skip the Serilog request summary logs for these. In the next section I introduce the approach I came up with that relies on the changes from the previous posts in this series.
Customising the log level used for Serilog request logs
In a previous post I showed how to include the selected endpoint in your Serilog request logs. My approach was to provide a custom function to the RequestLoggingOptions.EnrichDiagnosticContext property when registering the Serilog middleware:
public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
{
// ... Other middleware
app.UseSerilogRequestLogging(opts
// EnrichFromRequest helper function is shown in the previous post
=> opts.EnrichDiagnosticContext = LogHelper.EnrichFromRequest);
app.UseRouting();
app.UseAuthorization();
app.UseEndpoints(endpoints =>
{
endpoints.MapHealthChecks("/healthz"); //Add health check endpoint
endpoints.MapControllers();
});
}
RequestLoggingOptions has another property, GetLevel, which is a Func<> used to decide the logging level that should be used for a given request log. By default, it's set to the following function:
public static class SerilogApplicationBuilderExtensions
{
static LogEventLevel DefaultGetLevel(HttpContext ctx, double _, Exception ex) =>
ex != null
? LogEventLevel.Error
: ctx.Response.StatusCode > 499
? LogEventLevel.Error
: LogEventLevel.Information;
}
This function checks if an exception was thrown for the request, or if the response code is a 5xx error. If so, it create an Error level summary log, otherwise it creates an Information level log.
Lets say you wanted the summary logs to be logged as Debug instead of Information. First, you would create a helper function like the following which has the required logic:
public static class LogHelper
{
public static LogEventLevel CustomGetLevel(HttpContext ctx, double _, Exception ex) =>
ex != null
? LogEventLevel.Error
: ctx.Response.StatusCode > 499
? LogEventLevel.Error
: LogEventLevel.Debug; //Debug instead of Information
}
Then you can set the level function when you call UseSerilogRequestLogging():
public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
{
// ... Other middleware
app.UseSerilogRequestLogging(opts => {
opts.EnrichDiagnosticContext = LogHelper.EnrichFromRequest;
opts.GetLevel = LogHelper.CustomGetLevel; // Use custom level function
});
//... other middleware
}
Now your request summary logs will all be logged as Debug, except when an error occurs (screenshot from Seq):
But how does this help our verbosity problem?
When you configure Serilog, you typically define the minimum request level. For example, the following simple configuration sets the default level to Debug(), and writes to a console Sink:
Log.Logger = new LoggerConfiguration()
.MinimumLevel.Debug()
.WriteTo.Console()
.CreateLogger();
So the simple way for a log to be filtered is for the log level to be lower than the MinimumLevel specified in the logger configuration. Generally speaking, if you use the lowest level available, Verbose, it will pretty much always be filtered out.
The difficulty is that we don't want to always use Verbose as the log level for our summary logs. If we do that, we won't get any request logs for non-errors, and the Serilog middleware becomes a bit pointless!
Instead, we want to set the log level to Verbose only for requests that hit the health check endpoint. In the next section I'll show how to identify those requests while leaving other requests unaffected.
Using a custom log level for Health Check endpoint requests
The key thing we need is the ability to identify a health-check request at the point the log is written. As shown previously, the GetLevel() method takes the current HttpContext as a parameter, so theoretically there's a few options. The most obvious choices to me are:
- Compare the
HttpContext.Requestpath to a known list of health-check paths - Use the selected Endpoint metadata to identify when a health-check endpoint was called
The first option is the most obvious, but it's not really worth the hassle. Once you get into the weeds of it, you find you have to start duplicating request paths around and handling various edge cases, so I'm going to skip over that one here.
The second option uses a similar approach to the one in my previous post where we obtain the IEndpointFeature that was selected by the EndpointRoutingMiddleware for a given request. This feature (if present) provides details such as the display name and route data for the selected Endpoint.
If we assume that health checks are registered using their default Display Name of "Health checks", then we can identify a "health check" request using the HttpContext as follows:
public static class LogHelper
{
private static bool IsHealthCheckEndpoint(HttpContext ctx)
{
var endpoint = ctx.GetEndpoint();
if (endpoint is object) // same as !(endpoint is null)
{
return string.Equals(
endpoint.DisplayName,
"Health checks",
StringComparison.Ordinal);
}
// No endpoint, so not a health check endpoint
return false;
}
}
We can use this function, combined with a custom version of the default GetLevel function to ensure that summary logs for health check requests use a Verbose level, while errors use Error and other requests use Information:
public static class LogHelper
{
public static LogEventLevel ExcludeHealthChecks(HttpContext ctx, double _, Exception ex) =>
ex != null
? LogEventLevel.Error
: ctx.Response.StatusCode > 499
? LogEventLevel.Error
: IsHealthCheckEndpoint(ctx) // Not an error, check if it was a health check
? LogEventLevel.Verbose // Was a health check, use Verbose
: LogEventLevel.Information;
}
}
This nested ternary has an extra level to it - for non-errors we check if an endpoint with the display name "Health check" was selected, and if it was, we use the level Verbose, otherwise we use Information.
You could generalise this code further, to allow passing in other display names, or customising the log levels used. I didn't do that here for simplicity, but the associated sample code on GitHub shows how you could do this.
All that remains is to update the Serilog middleware RequestLoggingOptions to use your new function:
public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
{
// ... Other middleware
app.UseSerilogRequestLogging(opts => {
opts.EnrichDiagnosticContext = LogHelper.EnrichFromRequest;
opts.GetLevel = LogHelper.ExcludeHealthChecks; // Use the custom level
});
//... other middleware
}
When you check your logs after running your application you'll see your normal request logs for standard requests, but no sign of your health checks (unless an error occurs!). In the following screenshot I configured Serilog to also record Verbose logs so you can see the health check requests - normally they will be filtered out!
Summary
In this post I showed how to provide a custom function to the Serilog middleware's RequestLoggingOptions that defines what LogEventLevel to use for a given request's log. I showed how this can be used to change the default level to Debug for example. If the level you choose is lower than the minimum level, it will be filtered out completely and not logged.
I showed that you could use this approach to filter out the common (but low-interest) request logs generated by calling health check endpoints. Generally speaking these requests are only interesting if they indicate a problem, but they will typically generate a request log when they succeed as well. As these endpoints are called very frequently they can significantly increase the number of logs written.
The approach in this post is to check the selected IEndpointFeature and check if it has the display name "Health checks". If it does, the request log is written with the Verbose level, which is commonly filtered out. For more flexibility you could customise the logs shown in this post to handle multiple endpoint names, or any other criteria you have.
Top comments (0)