Understanding log scopes

For some time now Microsoft has offered an extension library for structured logging for .NET, and it has a feature known as 'log scopes'. According to the documentation:

A scope groups a set of logical operations. This grouping can be used to attach the same data to each log that's created as part of a set. For example, every log created as part of processing a transaction can include the transaction ID.

The 'magic' of a log scope is that it can be created in one method, and it then automagically applies to log events created in methods called within the scope, and any methods called from those methods, and so on, until the scope is disposed.

In the example below, any log event created in the handler object's Invoke method will have the value of transactionId 'attached' to it. This manifests as an item in an array of objects, the array being the value of a property added to the log event called Scope.

using (_logger.BeginScope(transactionId))
{
    await handler.Invoke(request);
}

However, the scope itself cannot be accessed. The handler object's Invoke method cannot discover what is in the current scope.

Understanding current scope

There are three aspects to log scopes that we should understand:

1. the proper mental model;
2. how they are applied to log events;
3. and how they are stored.

Let's start with the first.

Current scope as a trail of breadcrumbs

The ILogger interface declares the IDisposable BeginScope<TState>(TState state) method. You need to create a using block to ensure the scope gets properly disposed of. When this method is called again inside the using block, the current scope is extended. You can think of this as a trail of breadcrumbs. Perhaps you first add the customer number, then the order number, and finally the product ID. In this example, log events can have 1, 2 or 3 values applied to them, depending on the level of nesting at which they were created.

using (_logger.BeginScope(customerNumber))
{
    using (_logger.BeginScope(orderNumber))
    {
        // etc.
    }
}

However, this is not 100% true. Depending on the type of state, the semantics may differ. This becomes important when applying the current scope to a log event.

Applying the current scope to a log event

When a log event is created, the logger can inspect the current scope, and apply it to the log event in any way it sees fit.

The ILogger interface declares the BeginScope<TState>(TState state) method. Since it is generic, any type of state can be added to the current scope. In his article, The semantics of ILogger.BeginScope(), Nicholas Blumhardt, author of Serilog, describes how state is interpreted depending on its type.

1. If TState is IEnumerable<KeyValuePair<string, object>>, then each item is attached to the log event as a property, using the key as its name and the value as its value.
2. Otherwise, the object (for example, the transaction ID, or the customer number) is simply added to the Scope property (the array of objects mentioned earlier).
3. There is also an extension method on ILogger<T>, BeginScope(string messageFormat, params object?[] args), which parses messageFormat, finds placeholders for each arg in args, and builds an IEnumerable<KeyValuePair<string, object>> using that information. messageFormat itself is added to that using the key {OriginalFormat} (beware, that is an implementation detail, and could change without notice). The items are attached to the log event (as in 1), and the formatted message is added to the Scope property (as in 2).

Storing current scope

For storing the current scope, the logging library provides a default implementation of IExternalScopeProvider. When your logger provider implements ISupportExternalScope, then this default external scope provider will be assigned to it. All the logger need to do is 'forward' state to the provider, and it will handle the rest.

When it is time to create a log event, you can ask the external scope provider for the scope using its ForEachScope method, which accepts a callback.

The default external scope provider is LoggerExternalScopeProvider, and its implementation is where we can find the 'magic' that makes log scopes work.

The default external scope provider has a Scope class that acts as a singly linked list, every state object that it is given results in a new Scope object, whose Parent property points to the previous Scope object. When this provider's ForEachScope method is called, it simply uses the current Scope object, then its parent, then its parent's parent and so on, until it reaches the first Scope object, which has no parent.

The Scope object is what implements IDisposable, and when it gets disposed, it simply changes the provider's current scope to point to the scope's parent, thereby removing itself from the linked list.

The default external scope provider uses a private readonly AsyncLocal<Scope?> field to maintain the linked list of scopes. This ensures the current scope is maintained after any continuations of an async method.

Testing BeginScope

If you want to test if your code adds to the current scope correctly, you should use Microsoft's FakeLoggerProvider (in Microsoft.Extensions.Diagnostics.Testing), and set its external scope provider to the default LoggerExternalScopeProvider:

var fakeLoggerProvider = new FakeLoggerProvider();
fakeLoggerProvider.SetScopeProvider(new LoggerExternalScopeProvider());
hostBuilder.ConfigureLogging(loggingBuilder =>
{
    loggingBuilder.AddProvider(loggerProvider);
})

Now any ILogger<T> will be a FakeLogger<T>, and they will share the same LoggerExternalScopeProvider. You should have a consistent scope shared between multiple loggers that are active within the boundary of your test.

Summary

Log scope is stored by default as a linked list of Scope objects in an AsyncLocal<T> field. Logger providers can simply accept an external scope provider and delegate the storage of scope objects to the provider. Applying scope as a trail of breadcrumbs and/or a list of additional properties attached to each log event, is up to the logger implementation, but that is how Microsoft did it, so it's likely 3rd-party logger providers do the same.