This post continues a series covering the fundamentals of structured logging in .NET.

The subject of this instalment is how to write log events that are easier to navigate when collected for analysis and diagnostics. Starting with a simple structured logging statement:

Log.Information("Adding {Item} to cart {CartId}", item, cart.Id);

And the corresponding event created by it:

Bare log event

You can see the captured Item and CartId properties, which will both be useful to work with when the event is one among thousands or millions.

But, when we find the event among those we’ve collected, there are a few more needs to consider.

How do we know that this event happened in production, and not in some test or development environment?

This is the kind of requirement that structured data is ideally placed to solve. Let’s attach some properties recording the origin of the event:

Added machine name

Ignoring for the moment how these properties are added, MachineName and Environment identify where the event came from, and help us to find others like it.

How do we know which of our many applications created it?

The same technique applies; let’s attach an Application property:

Added application

Did the unit of work actually succeed, or was there a later problem with processing the request that caused the operation to fail?

Adding a RequestId to the event allows us to pivot and find other events raised by the same request:

AddedRequestId

These pieces of additional information give us the context that we need to fully understand and work with the event. There are a few more that I’ve seen frequently in the wild: the class name that generated the event; the id of the thread that the event was created on; the id of the message being handled, if the application is messaging-based, and others.

Logging exists for the benefit of applications, and not vice-versa. Adding all of these properties manually to each event would be an undesirable burden to carry. Happily, a range of techniques are available for adding this contextual information with minimal overhead. In the remainder of this post we’ll look at the most common ones.

(Deciding which properties to attach to an event is another topic worth looking into. I’ve written previously about the strategy I use - once you’ve read this post, you might find that this article makes a useful follow-up.)

Contextual loggers

The simplest and most direct way to attach contextual properties to a log event is explicitly:

Log.ForContext("Source", typeof(CartController).FullName)
    .Information("Adding {Item} to cart {CartId}", item, cart.Id);

Serilog’s ForContext() method returns an ILogger that attaches a specified property to all of the events logged through it. The ILogger can be used multiple times, for example by storing it in a variable or field:

var cartLog = Log.ForContext("Source", typeof(CartController).FullName);

cartLog.Information("Adding {Item} to cart {CartId}", item, cart.Id);
cartLog.Information("Cart value is {CartTotal}", cart.Total);

This example attaches a property holding the name of the class generating the log event. This is such a common pattern that Serilog provides an overload of ForContext() accepting a Type directly:

var cartLog = Log.ForContext<CartController>();

Using Microsoft.Extensions.Logging in conjunction with dependency injection in ASP.NET Core, classes can specify a dependency on ILogger<T> for the same effect:

public CartController(ILogger<CartController> cartLog)
{
    // ...
}

In this case the infrastructure will inject a contextual logger for the CartController class.

Contextual loggers are useful for one-off, or local contextual information like the source type name.

Ambient logging contexts

Within a unit of work such as a single HTTP request, or processing a message from a message queue, it’s useful to tag all events with a correlation identifier unique to the unit of work. Properties like RequestId or MessageId fit this pattern.

We could use an explicit contextual logger for this:

var requestLog = Log.ForContext("RequestId", Request.Id);
// Process request, logging through `requestLog`

But, we then have to account for passing the ILogger instance throughout request processing and make sure that all logging goes through it. This can result in a lot of ILogger parameters on the various methods used during request processing. If you do prefer a very explicit style of propagating logging state this is fine, but for me it’s a bit too invasive.

As a less invasive alternative, Serilog supports this use case through the ambient LogContext:

using (LogContext.PushProperty("RequestId", Request.Id))
{
    // Process request; all logged events will carry `RequestId`
    Log.Information("Adding {Item} to cart {CartId}", item, cart.Id);
}

Within the using block, all loggers that have opted-in to the LogContext will attach the RequestId automatically. Opting-in is done at configuration time using Enrich.FromLogContext():

Log.Logger = new LoggerConfiguration()
    .Enrich.FromLogContext()
    // Other configuration

Similar functionality is provided by Microsoft.Extensions.Logging through ILogger.BeginScope().

Ambient logging contexts are most useful for unit-of-work scenarios. While they’re common to see in application code, frameworks with logging integration like ASP.NET Core often add these automatically, as is the case with RequestId in new ASP.NET Core apps.

Globally-attached properties

In some cases we would like every event created by a logger to carry the same, fixed, property value. The Application example is one of these.

Serilog provides Enrich.WithProperty() at the level of a LoggerConfiguration for this:

Log.Logger = new LoggerConfiguration()
    .Enrich.WithProperty("Application", "e-Commerce")
    .Enrich.WithProperty("Environment", ConfigurationManager.AppSettings["Environment"])
    // Other logger configuration

There are a few pre-built helpers for Serilog that add common properties. With the Serilog.Enrichers.Environment package installed, Enrich.WithMachineName() will add the MachineName property collected in a platform-independent manner:

    .Enrich.WithMachineName()

Remember, when configuring properties at this level, that each added property will contribute to the payload size of every log event. We might be tempted to add a Version property as well, but since the Application and MachineName properties are already attached, just logging the version in a single message at start-up is sufficient in most cases:

Log.Information("Application version {Version} starting up",
                typeof(Program).Assembly.GetName().Version);

Depending on how you are collecting logs, you might also be able to save some logging bandwidth by attaching the properties on the server-side, at the collector. Seq’s API keys allow properties like Application and Environment to be set on a per-API key basis, for example.

Globally-attached properties are mostly used when multiple logging sources are being collected at the same point. Along with the few examples we’ve talked about, it’s common to see global properties like InstallId from desktop applications, or TenantId in a multi-tenant or SaaS app.

Programmatic enrichment

So far we’ve looked at how to attach properties to events explicitly with contextual loggers, by creating ambient logging contexts, and by configuring globally-attached properties. A few scenarios don’t fit easily into any of these models. For these, Serilog allows code to be plugged into the logging pipeline to inspect and add properties to each event programmatically.

The interface these plug-ins implement is ILogEventEnricher, and the example implementation below will add a ThreadId property based on the currently-executing thread:

class ThreadIdEnricher : ILogEventEnricher
{
    public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
    {
        logEvent.AddPropertyIfAbsent(
            propertyFactory.CreateProperty("ThreadId", Thread.CurrentThread.ManagedThreadId, false));
    }
}

Enrichers are plugged in at configuration time:

Log.Logger = new LoggerConfiguration()
    .Enrich.With(new ThreadIdEnricher())
    // Other logger configuration

Thread ids are a common enough requirement that the Serilog.Enrichers.Thread package provides Enrich.WithThreadId(), but you can see from the implementation here that creating your own enrichers is straightforward.

Programmatic enrichment is the Swiss-army-knife technique that enables all kinds of interesting scenarios. In Serilog, enrichers can remove and modify event properties as well as add them, so some creative possibilities exist.

Concluding notes

In this post we’ve examined four basic techniques for adding contextual information to a log event:

  • Contextual loggers
  • Ambient logging contexts
  • Globally-attached properties
  • Programmatic enrichment

Getting just the right amount of information onto each event is something you’ll need to fine-tune for your application and environment, but well worth it because of the improved analytic and diagnostic capabilities you’ll gain as a result. Read Tagging log events for effective correlation for one view of how these techniques can be combined to create highly-navigable logs.

Next in this series we’ll investigate how more complex data can be attached to log events through serialization. Happy logging, until next time!