Should we capture infrastructure logs?

The latest ASPNET Core has some amazing diagnostics and logging capabilities built in, and Serilog has a great way to capture these logs so they can be sent to the same destinations (sinks) as your application is configured. When you are diagnosing or understanding how the framework is impacting the behavior of your software, this feature can be a real life saver.

However, in my recent experience, this is the not the normal situation. Most of the issues I’m dealing with are related to my own application’s code; the application I’m working on. Only occasionally do the issues with my application seem to overlap with ASPNET Core enough that I feel the need to dive into the ASPNET Core logs. In fact, collecting these ASPNET Core logs was actually hindering my abilty to spot other issues in the logs.

This means I typically don’t want to capture and store the vast amounts of diagnostic logs produced by ASPNET Core or other components that use MEL (like EntityFrameworkCore).

On the other hand, when something does go wrong, I do want to be able to capture and analyse these logs!

Too much information

The volume of logs generated by ASPNET Core can be quite large. If you have them turned on full, they would typically drown out the logs generated by your own application. A great way (and the most common way) to dial down the volume of logging generated from ASPNET Core is to use Microsoft.Extensions.Logging.Filter:

var factory = new LoggerFactory()
    .UseConfiguration(loggingConfiguration.GetSection("Logging"))
    .AddFilter(new Dictionary<string, LogLevel>
    {
        { "Microsoft", LogLevel.Warning },
        { "System", LogLevel.Warning },
        { "SampleApp.Program", LogLevel.Debug }
    });

In Serilog, we can achieve something similar by using MimimumLevel.Override:

Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Information()
    .MinimumLevel.Override("Microsoft", LogEventLevel.Warning)
    .WriteTo.Sink(new MyFancySink())
    .CreateLogger();

This ensures that any logs with a source (aka Log category) of "Microsoft" is ignored unless it is at minimum LogEventLevel.Warning. This is a really simple and flexible approach; it allows you to zero in on the Loggers that come from the Microsoft category, or even go deeper.

Let’s say that I am using EF Core, and I suspect there’s an issue with one of the SQL queries it has translated from LINQ into SQL. I can enable verbose logging only for the EF Core sources:

Log.Logger = new LoggerConfiguration()
    .MinimumLevel.Verbose()
    .MinimumLevel.Override("Microsoft", LogEventLevel.Warning)
    .MinimumLevel.Override("Microsoft.EntityFrameworkCore", LogEventLevel.Verbose)
    .WriteTo.LiterateConsole(
        outputTemplate: "[{Timestamp:HH:mm:ss} {Level:u3}] {Message} [{SourceContext}]{NewLine}{Exception}")
    .CreateLogger();

The amount of information I am presented with is far less than if I had enabled Verbose for everything instead of just "Microsoft.EntityFrameworkCore".

Remotely controlling the log level with Seq

Seq provides one of the best experiences for dealing with logs generated by Serilog and ASPNET Core / Microsoft.Extensions.Logging.

Serilog provides the ability to dynamically change the log level, and Seq can make use of this feature. Using the Seq admin screens

Seq Dynamic Level Control Unfortunately, at the time of writing, Seq doesn’t yet have the ability to remotely control the verbosity at individual source/context levels.

What we can do now is to use a separate Serilog Logger with a separate Seq API Key for our major log sources. This allows using the existing Seq and Serilog dynamic level control features to control our ASPNET Core logging, without impacting the logs generated by our application explicitly.

For example, during our ASPNET Core Startup, we can do the following:

public void Configure(IApplicationBuilder app, IHostingEnvironment env, ILoggerFactory loggerFactory)
{
    var infrastructureLevelSwitch = new LoggingLevelSwitch(
        SeqConfig.AspNetInfrastructureSeqMinimumLevel);

    loggerFactory.AddSerilog(new LoggerConfiguration()
        .MinimumLevel.ControlledBy(infrastructureLevelSwitch)
        .Enrich.FromLogContext()
        .WriteTo.Seq(
            serverUrl: SeqConfig.AspNetInfrastructureSeqServerUrl,
            apiKey: SeqConfig.AspNetInfrastructureSeqApiKey,
            controlLevelSwitch: infrastructureLevelSwitch)
        .CreateLogger(), dispose: true);

    // ...
}

Notice that we created an entirely new Logger, and did not assign it to the shared static Serilog Log.Logger. All we did was pass it into the the ASPNET Core loggerFactory and the Serilog.Extensions.Logging AddSerilog extension method.

That’s it! Now that you have a separate API Key, you can use Seq to control the log level as usual: image

Some things to keep in mind

  • If you start using MEL for your own application logging you may need to tweak or entirely rethink this strategy.
  • It can take anywhere from seconds to minutes for the log level change in Seq to be propagated out to the Serilog.Sinks.Seq clients, so keep this in mind.
  • You will need to be sure that in the event you need to enable this logging, that you are prepared for the deluge of additional log events. Turning on full (default) ASPNET core and EF logging on a busy production system might give you some different headaches!