Serilog 0.9.2 includes a new feature that I’ve been holding off on committing to for some time. Those familiar with the NDC (“Nested Diagnostic Context”) in log4net and similar features elsewhere will recognise the basic idea behind LogContext:

log.Information("No contextual properties");

using (LogContext.PushProperty("A", 1))
{
    log.Information("Carries property A = 1");

    using (LogContext.PushProperty("A", 2))
    using (LogContext.PushProperty("B", 1))
    {
        log.Information("Carries A = 2 and B = 1");
    }

    log.Information("Carries property A = 1, again");
}

An application can push properties onto the context to tag events associated with some unit of work, perhaps identifying a specific transaction, customer, message and so-on. The properties can later be used to find messages of interest.

Serilog is all about easier filtering and correlation of events, so, why hold off on adding this feature until now? The reason is that for flexibility and reliability, Serilog’s logging pipeline is essentially stateless and is completely free of static or ambient state. Making all loggers dependent on a global, shared context stack seemed like the wrong thing to do.

Fortunately, it turned out to be easy to reconcile this feature with Serilog’s goals. To use properties from the context, loggers opt-in via a simple configuration method:

var log = new LoggerConfiguration()
    .Enrich.FromLogContext()
    // ...

This way, only loggers that explicitly take interest in the LogContext are affected by it.

Why is this supported only on the full .NET 4.5 framework?

A useful diagnostic context, in today’s .NET, has to play nicely with async/await. Properties pushed onto the stack need to be preserved when an awaited call completes, as below:

async Task Handle(Message message)
{
    using (LogContext.PushProperty("MessageId", message.Id))
    {
        var items = await LoadDataAsync();
        
        Log.Information("Loaded {ItemCount} items", items.Count);
    }
}

In this example, the thread that executes the Log.Information() call may be different from the one that pushed the MessageId property on the stack, because of the awaited call.

Because the thread that resumes execution after awaiting may be a different one from the one that pushed the property onto the stack, [ThreadStatic] variables aren’t suitable for implementing a diagnostic context anymore. Only .NET 4.5 has an async-aware CallContext.LogicalGetData() suitable for this purpose. Stephen Cleary has written a useful article with more discussion of the topic.