Selective enrichment

TL;DR: Serilog 2.9.0-* adds selective enrichment to help manage the trade-off between the value of additional event data, and the impact of collecting it.

Enrichers are one of the things that make Serilog more than just a logging API; since Serilog is designed to be an event processing pipeline from the ground up, it only takes a few lines of rather obvious code to add useful contextual information to Serilog events:

class WorkingSetEnricher : ILogEventEnricher
{
    public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
    {
        logEvent.AddPropertyIfAbsent(
            propertyFactory.CreateProperty("WorkingSet", Environment.WorkingSet));
    }
}

Enrichers, like the one above, are plugged into the logging pipeline during configuration:

Log.Logger = new LoggerConfiguration()
    .Enrich.With<WorkingSetEnricher>()
    .WriteTo.Console(
        // {Properties:j} added:
        outputTemplate: "[{Timestamp:HH:mm:ss} {Level:u3}] {Message:lj} " +
                        "{Properties:j}{NewLine}{Exception}")
    .CreateLogger();

Log.Information("This is information");

// -> [08:36:36 INF] This is information {"WorkingSet": 18141184}

Serilog and its ecosystem includes a whole stack of pre-built enrichers, added using extension methods on Enrich, like:

    .Enrich.FromLogContext()
    .Enrich.WithProperty("Application", "Selective Enrichment Demo")
    .Enrich.WithProperty("Environment", "Test")
    .Enrich.WithProperty("Version", typeof(Program).Assembly.Version)
    .Enrich.With<WorkingSetEnricher>()
    .Enrich.WithMachineName()
    .Enrich.WithThreadId()
    // And so on!

This raises questions: how much enrichment is too much? Logging is a study in compromise, and one of the central trade-offs is between the value of additional log information and the impact of collecting it. Because enrichment adds bytes and latency to every log event, it can add measurably to the cost of collecting logs. Just a few added properties can double the size of a log event!

Enrichers need to be selected carefully, but more often than not, ease of diagnostics wins over collection costs, and events still end up with a lot of additional properties.

The current Serilog 2.9.0 dev (pre-release) builds include a pair of very simple new APIs to make the trade-off a bit less biting. Enrich.AtLevel() will apply enrichers only to events at or above a specified LogEventLevel:

    .Enrich.FromLogContext()
    .Enrich.WithProperty("Application", "Selective Enrichment Demo")
    .Enrich.WithProperty("Environment", "Test")
    .Enrich.AtLevel(
        LogEventLevel.Warning,
        e => e.WithProperty("Version", typeof(Program).Assembly.Version))
    .Enrich.AtLevel(LogEventLevel.Error, e => e.With<WorkingSetEnricher>())
    .Enrich.AtLevel(LogEventLevel.Error, e => e.WithMachineName())
    .Enrich.AtLevel(LogEventLevel.Error, e => e.WithThreadId())
    // And so on!

Here, the Version property will only be attached to events at the Warning level or above (i.e. Error and Fatal), while the WorkingSet, MachineName and ThreadId properties will be attached to Error and Fatal events.

A slightly more flexible Enrich.When() option accounts for more sophisticated conditions:

    .Enrich.When(
        _evt => Configuration.IsCanaryChannel,
        e => e.WithProperty("ReleaseChannel", "Canary"))

Over many millions of events, careful use of selective enrichment has the potential to save gigabytes, reducing logging latency, storage costs, network traffic, log search time - and the energy required by all of these things.

To check this feature out you’ll need to dotnet add package Serilog -v 2.9.0-* or the equivalent for your package manager. Feedback and issue reports most welcome here or over at the Serilog GitHub project 🙂.