Scopes and Correlation

A logging scope attaches the same data, such as a request or job id, to every line written inside a block of code.

Syntaxusing (logger.BeginScope("job {JobId}", jobId)) { ... }

One request produces many log lines, and in a busy service those lines are interleaved with everyone else's. A scope fixes that. It is a block of code with data attached; every line logged inside it carries that data, including lines from methods it calls.

BeginScope returns an IDisposable?, and the scope lasts until that object is disposed. In practice you write it as a using block, so it ends when the block ends.

What ASP.NET Core already does

You rarely need a scope for the request itself. ASP.NET Core opens one per request holding the connection id, the request path and a request id. The logging libraries also add TraceId, SpanId and ParentId from the current activity, controlled by LoggerFactoryOptions.ActivityTrackingOptions. Add your own scope for the things the framework cannot know: a job id, a tenant, a batch number.

Following one request across services

The trace id is not local. When service A calls service B with HttpClient, the current trace id goes out in a traceparent request header, B picks it up, and B's log lines carry the same TraceId. Query one trace id in the log store and you get both services in order.

What trips people up

Both shapes of scope carry named fields. BeginScope("job {JobId}", jobId) hands the logger a FormattedLogValues state, which exposes JobId and {OriginalFormat} as key and value pairs, so a structured provider files JobId as its own field exactly as a message template does; a dictionary or a list of key and value pairs behaves the same way. What differs is the text: the simple console formatter prints each scope's ToString(), so the template form reads as => job 42 while a dictionary prints its type name.

Example

Example · csharp
// dotnet add package Microsoft.Extensions.Logging.Console
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Console;

using ILoggerFactory factory = LoggerFactory.Create(builder =>
{
    builder.SetMinimumLevel(LogLevel.Information);
    builder.AddSimpleConsole(options =>
    {
        options.IncludeScopes = true; // without this, scopes are dropped
        options.ColorBehavior = LoggerColorBehavior.Disabled;
    });
});

ILogger logger = factory.CreateLogger("Orders");

// BeginScope returns IDisposable?. Disposing it ends the scope.
using (logger.BeginScope("job {JobId}", 42))
{
    logger.LogInformation("loading orders");
    logger.LogInformation("finished");
}

logger.LogInformation("shutting down");

// Output:
// info: Orders[0]
//       => job 42
//       loading orders
// info: Orders[0]
//       => job 42
//       finished
// info: Orders[0]
//       shutting down

When to use it

  • Attach a job id to every line a background worker writes while handling one item.
  • Tag all logs for one tenant in a service that serves many customers.
  • Follow a single customer request through three services using one trace id.

More examples

A scope with named fields in a minimal API

Call GET /orders/7 and the response is the JSON body {"id":7}. The dictionary becomes a scope of named values, so a structured provider such as AddJsonConsole writes OrderId as its own field alongside the request scope ASP.NET Core opened for you. The simple console formatter is not structured: it writes each scope's ToString(), and Dictionary<string, object> does not override ToString, so the line reads => System.Collections.Generic.Dictionary`2[System.String,System.Object]. For console text you can read, use the template form, BeginScope("order {OrderId}", id), which carries the same named field and prints as => order 7.

Example · csharp
var builder = WebApplication.CreateBuilder(args);

// The web template already adds a console provider; replace it so the
// lines are not written twice.
builder.Logging.ClearProviders();
builder.Logging.AddSimpleConsole(options => options.IncludeScopes = true);

var app = builder.Build();

app.MapGet("/orders/{id:int}", (int id, ILogger<Program> logger) =>
{
    // A dictionary gives OrderId as its own field, not one blob of text.
    using (logger.BeginScope(new Dictionary<string, object> { ["OrderId"] = id }))
    {
        logger.LogInformation("looking up order");
        return Results.Ok(new { id });
    }
});

app.Run();

Carrying the trace id to the next service

GET /orders/7 returns JSON holding the id and whatever the inventory service answered. Both services now write TraceId into every line, so one search finds the whole journey. ActivityTrackingOptions is set explicitly here to show where it lives; the default host configuration already tracks TraceId, SpanId and ParentId.

Example · csharp
var builder = WebApplication.CreateBuilder(args);

builder.Logging.Configure(options =>
{
    options.ActivityTrackingOptions =
        ActivityTrackingOptions.TraceId | ActivityTrackingOptions.SpanId;
});
builder.Logging.ClearProviders();
builder.Logging.AddSimpleConsole(options => options.IncludeScopes = true);

builder.Services.AddHttpClient();

var app = builder.Build();

app.MapGet("/orders/{id:int}", async (int id, IHttpClientFactory httpClientFactory,
    ILogger<Program> logger) =>
{
    logger.LogInformation("fetching stock for order {OrderId}", id);

    HttpClient client = httpClientFactory.CreateClient();
    // HttpClient sends the current trace id in a traceparent header, so
    // the inventory service logs under the same TraceId.
    string stock = await client.GetStringAsync("http://inventory/stock");

    return Results.Ok(new { id, stock });
});

app.Run();

A scope around one item of work in a worker

Scopes nest, and the inner one adds to the outer one rather than replacing it. A background worker has no request scope from the framework, so this is where you add your own. Without it, the line "parsed" tells you nothing about which file in which batch.

Example · csharp
using Microsoft.Extensions.Logging;

public class ImportWorker
{
    private readonly ILogger<ImportWorker> _logger;

    public ImportWorker(ILogger<ImportWorker> logger)
    {
        _logger = logger;
    }

    public void ImportBatch(IReadOnlyList<string> fileNames, int batchId)
    {
        using (_logger.BeginScope(new Dictionary<string, object> { ["BatchId"] = batchId }))
        {
            _logger.LogInformation("importing {FileCount} files", fileNames.Count);

            foreach (string fileName in fileNames)
            {
                // Nested scope: lines inside carry BatchId and FileName.
                using (_logger.BeginScope(new Dictionary<string, object> { ["FileName"] = fileName }))
                {
                    _logger.LogInformation("parsed");
                }
            }
        }
    }
}

Related

dotnet iloggerdotnet structured loggingdotnet tracingdotnet opentelemetrydotnet background service

Discussion

  • Be the first to comment on this lesson.