Correlationid in .net

What is it?

One of the worst things I can be asked to do is look at logs. Usually they come in a large text dump with time stamps and vauge messages. Trying to match up the time stamps and try and suss out what log is relevant to me.

Ignore poor logging practices for a second, one quick fix we can add to our application is correlation id logging. I'm going to be using serilog (along with serilog context logging) in this example, but you can google how other logging providers can use correlation ids / context logging. I'll also be using a nuget package "CorrelationId by stevejgordon". We can look at a simple hand rolled approach at the end.

Getting Started

var builder = WebApplication.CreateSlimBuilder(args);

// Setup serilog
Log.Logger = new LoggerConfiguration()
    .Enrich.FromLogContext()
    .WriteTo.Console(outputTemplate:
        "[{Timestamp:HH:mm:ss} {Level:u3}] ({CorrelationId}) {Message:lj}{NewLine}{Exception}")
    .CreateLogger();

builder.Host.UseSerilog();

// Add Correlation ID services
builder.Services.AddDefaultCorrelationId(options =>
{
    options.AddToLoggingScope = true; // Adds CorrelationId to log context
    options.RequestHeader = "X-Correlation-ID"; // Incoming header name
    options.ResponseHeader = "X-Correlation-ID"; // Outgoing header name
    options.IncludeInResponse = true; // Return it in response
});

...

var app = builder.Build();

app.UseCorrelationId();

...

Using the power of other peoples code, this is pretty much it. Now it's as simple as logging information. For that we have a simple endpoint

var todosApi = app.MapGroup("/todos");

todosApi.MapGet("/{id}", (int id, ILogger<Program> logger) =>
{
    logger.LogInformation("Fetching todo with ID {Id}", id);

    return Results.Ok();
});

If we look at the logs we should see something like the following

Each log entry now has a guid and this can be used to track the request. In a simple system like this with one request coming in, it might be hard to see the value, but imagine a api handling hundreds requests a second.

This Id can be passed to other services using http headers or be passed back to a client which can be handed over given to the support team when bugs are raised.

Hand Rolling

For those people who like to implement their own thing rather than use another third party dependency, it really does not take much.

The Middleware

First thing first, we want to create some middleware to check if we've been passed a new CorrelationId, if not we want to create a new one. We also want a class we can DI to access the CorrelationId.

public interface ICorrelationIdAccessor
{
    string CorrelationId { get; set; }
}

public class CorrelationIdAccessor : ICorrelationIdAccessor
{
    public string CorrelationId { get; set; } = string.Empty;
}

public static IApplicationBuilder UseCorrelationId(this IApplicationBuilder app)
    {
        return app.Use(async (context, next) =>
        {
            var accessor = context.RequestServices.GetRequiredService<ICorrelationIdAccessor>();

            if (!context.Request.Headers.TryGetValue(correlationIdHeader, out var correlationId) ||
                string.IsNullOrWhiteSpace(correlationId))
            {
                correlationId = Guid.NewGuid().ToString();
            }

            context.TraceIdentifier = correlationId;
            accessor.CorrelationId = correlationId;

            context.Response.OnStarting(() =>
            {
                context.Response.Headers[correlationIdHeader] = correlationId;
                return Task.CompletedTask;
            });

            // Push into Serilog's LogContext for this request
            using (LogContext.PushProperty("CorrelationId", correlationId))
            {
                await next.Invoke();
            }
        });
    }

Now we just need to register our middleware and CorrelationAccessor

var builder = WebApplication.CreateBuilder(args);

Log.Logger = new LoggerConfiguration()
    .Enrich.FromLogContext()
    .WriteTo.Console(outputTemplate:
        "[{Timestamp:HH:mm:ss} {Level:u3}] ({CorrelationId}) {Message:lj}{NewLine}{Exception}")
    .CreateLogger();

builder.Services.AddScoped<ICorrelationIdAccessor, CorrelationIdAccessor>();

...

var app = builder.Build();

app.UseCorrelationId();

Now we should be getting logs like the following