Backend Notes 6: Structured Logging with Serilog in ASP.NET Core

Backend Notes 6: Structured Logging with Serilog in ASP.NET Core

In the previous note I said production had taught me the value of logging that answers the question you will have at three in the morning. This note is about what that logging looks like in an ASP.NET Core service, and about the small decisions that decide whether a log is evidence or noise.

I introduced Serilog at Gozine2 in 2021, while I was still working full-stack there, and structured logging stayed part of the standard setup, next to Docker and CI/CD, after I moved to senior backend work. The goal was a shorter path from "a student says the exam froze" to the request that failed, the user and exam it belonged to, how long each step took and which exception ended it. Installing the package was the small part; most of the work was agreeing on what every event should carry.

Message templates, not strings

The single most important habit is also the smallest one. Compare these two calls:

// Interpolated: the values are baked into the text, so every call is a different message
logger.LogWarning($"Answer save took {elapsed.TotalMilliseconds} ms for session {sessionId}");

// Template: one event type with two properties you can query
logger.LogWarning("Answer save took {ElapsedMs} ms for session {SessionId}",
    elapsed.TotalMilliseconds, sessionId);

The first line produces a string. The second produces an event with a fixed template and two named properties, so a log store can answer "show me every slow save above 500 ms" or "group warnings by template" without regular expressions. The interpolated version also builds its string before the logger checks whether Warning is enabled. The .NET analyzers flag it as CA2254, "Template should be a static expression", and I treat that warning as an error in code review.

Two details are easy to get wrong. With the ILogger extension methods such as LogWarning, placeholders are matched to arguments by position, not by name, so {SessionId} receives whatever comes second. And the @ operator, as in {@Request}, tells Serilog to serialize the whole object. That is convenient and dangerous: you log every public property, including the ones added next year. I prefer naming the few properties I need.

For hot paths, the [LoggerMessage] source generator produces the same structured event without boxing or parsing the template on each call, and it works with Serilog because Serilog sits behind the same ILogger abstraction:

public static partial class ExamLog
{
    [LoggerMessage(EventId = 1001, Level = LogLevel.Warning,
        Message = "Answer save took {ElapsedMs} ms for session {SessionId}")]
    public static partial void SlowAnswerSave(ILogger logger, double elapsedMs, Guid sessionId);
}

Exceptions have their own slot, and it should be used. Write logger.LogError(ex, "Saving answers for session {SessionId} failed", sessionId), with the exception as the first argument. Putting ex.Message into the text throws away the exception type, the stack trace and the inner exceptions, and turns every distinct message into a new template. Log an exception once, at the place that actually handles it. Logging and rethrowing at every layer produces five copies of the same stack trace, and the error count stops meaning anything.

Wiring Serilog into ASP.NET Core

I use the two-stage setup from the Serilog.AspNetCore documentation. A bootstrap logger exists from the first line of Program.cs, so a crash while reading configuration is still logged, and it is replaced by the real logger once the host is built:

using Serilog;
using Serilog.Formatting.Compact;

Log.Logger = new LoggerConfiguration()
    .WriteTo.Console()
    .CreateBootstrapLogger();

try
{
    var builder = WebApplication.CreateBuilder(args);

    builder.Services.AddSerilog((services, lc) => lc
        .ReadFrom.Configuration(builder.Configuration)
        .ReadFrom.Services(services)
        .Enrich.FromLogContext()
        .Enrich.WithProperty("Service", "exam-api")
        .WriteTo.Console(new CompactJsonFormatter()));

    var app = builder.Build();
    app.UseSerilogRequestLogging();
    // ... the rest of the pipeline and the endpoints
    app.Run();
}
catch (Exception ex)
{
    Log.Fatal(ex, "Host terminated unexpectedly");
}
finally
{
    Log.CloseAndFlush();
}

AddSerilog routes every ILogger<T> call in the application and the framework through Serilog, so existing code does not change. Minimum levels live in configuration, which means they can differ per environment without a rebuild:

"Serilog": {
  "MinimumLevel": {
    "Default": "Information",
    "Override": {
      "Microsoft.AspNetCore": "Warning",
      "Microsoft.EntityFrameworkCore": "Warning",
      "System.Net.Http.HttpClient": "Warning"
    }
  }
}

One event per request, and the context on every event

By default ASP.NET Core writes several Information events per request. UseSerilogRequestLogging() replaces them with a single completion event that carries the method, path, status code and elapsed time, which is why the override above turns Microsoft.AspNetCore down to Warning. That one event is the backbone of most investigations, so it is worth enriching:

app.UseSerilogRequestLogging(options =>
{
    options.GetLevel = (http, elapsedMs, ex) =>
        ex is not null || http.Response.StatusCode >= 500 ? LogEventLevel.Error
        : http.Request.Path.StartsWithSegments("/health") ? LogEventLevel.Verbose
        : elapsedMs > 1000 ? LogEventLevel.Warning
        : LogEventLevel.Information;
});

app.UseAuthentication();

// after authentication, so the user and tenant are known
app.Use(async (http, next) =>
{
    var userId = http.User.FindFirst("sub")?.Value;
    var tenantId = http.User.FindFirst("tenant_id")?.Value;

    var diagnostics = http.RequestServices.GetRequiredService<IDiagnosticContext>();
    diagnostics.Set("UserId", userId);          // for the completion event
    diagnostics.Set("TenantId", tenantId);

    using (LogContext.PushProperty("UserId", userId))     // for every event inside the request
    using (LogContext.PushProperty("TenantId", tenantId))
    {
        await next(http);
    }
});

The two mechanisms look redundant, but each covers events the other misses. LogContext.PushProperty attaches a property to every event written inside the using block, but the request logging middleware writes its completion event after that block has ended. IDiagnosticContext exists for exactly that event. With both in place, every line of a request, including the summary, can be filtered by user and tenant.

The claim names depend on your identity provider. The rule I hold to is that these are identifiers, not people: an opaque user id, never a phone number or a name. In the multi-tenant platform I am building, the tenant id is resolved once per request and is allowed in logs and traces, but not as a metric label, where it would multiply the number of time series by the number of tenants.

Levels mean something only if the team agrees on them

The definitions I push for in review are short. Error means someone should look at this. Warning means something degraded but was handled: a retry succeeded, a fallback was used, a request was slow. Information records business events and the one summary per request. Debug and Verbose are off in production and are switched on for one namespace at a time, through configuration, when an investigation needs them. When even a configuration change is too slow, a LoggingLevelSwitch passed to MinimumLevel.ControlledBy(...) can be flipped at runtime from an authenticated admin endpoint, and flipped back when the investigation is over.

Sampling is where people overspend or lose evidence. I do not sample errors, and I do not sample the request summary for real user traffic, because those are the events an investigation starts from. What I do drop is known noise: health checks (the GetLevel rule above sends them to Verbose, below the minimum), readiness probes, and chatty framework categories. When a filter has to be more specific, Serilog.Expressions lets you write it as text, for example Filter.ByExcluding("RequestPath like '/health%'"). Statistical sampling belongs to traces, where the OpenTelemetry tooling is built for it.

Sinks: where the events go

In containers I write compact JSON to standard output and let the platform collect it. The application stays unaware of the log backend, and changing that backend is an operations decision. For a small team, Seq is a pleasant place to read structured events during development and in modest production setups; its sink sends events in batches, so a slow network does not slow requests.

A SQL table can be a reasonable home for errors only, especially when the team already lives in SQL Server and has nothing else. A sub-sink with a minimum level keeps the volume small:

.WriteTo.Console(new CompactJsonFormatter())
.WriteTo.MSSqlServer(
    connectionString: builder.Configuration.GetConnectionString("Logs"),
    sinkOptions: new MSSqlServerSinkOptions { TableName = "ErrorLog", AutoCreateSqlTable = true },
    restrictedToMinimumLevel: LogEventLevel.Error)

Two cautions. Use a separate database, or at least a separate connection string, so that logging cannot compete with the workload it is describing. And remember that during an outage errors arrive in bursts, precisely when the database is under the most pressure. A table is a convenience, not an observability platform.

Correlating logs with traces

Logs tell you what happened inside one process; traces tell you how a request moved between processes. They become far more useful when they share an id. Since Serilog 3.1, every event captures the trace and span ids of Activity.Current, and the compact JSON formatter writes them as @tr and @sp. Turn on OpenTelemetry tracing and the ids are real W3C trace ids, shared with every service the request touches:

builder.Services.AddOpenTelemetry()
    .ConfigureResource(r => r.AddService("exam-api"))
    .WithTracing(t => t
        .AddAspNetCoreInstrumentation()
        .AddHttpClientInstrumentation()
        .AddOtlpExporter());

This closes a loop from the Minimal APIs note. The traceId that the ProblemDetails setup puts in every error response is the same id that sits on every log event of that request. A user, or a support colleague, sends you the error body; you paste the trace id into the log search and see the whole request, across services. If you want logs to travel over OTLP too, Serilog.Sinks.OpenTelemetry exports them to the same collector as the traces.

Personal data and secrets

Logs are copied more widely than databases and kept with less care, so I treat them as a place where sensitive data should never arrive. The list I check in review:

  • Never log passwords, tokens, Authorization or Cookie headers, connection strings, API keys or one-time codes.
  • Avoid phone numbers, email addresses, national ids and full names. Log the internal id and look the person up when you need to, with the access controls that apply to the database.
  • Do not log whole request or response bodies by default. When a body is needed for a specific investigation, log a reduced shape for a limited time.
  • Keep EnableSensitiveDataLogging() in EF Core for development only; it puts SQL parameter values into the logs.
  • Destructure deliberately. If a type must be logged, Destructure.ByTransforming<T>(...) decides once which fields are safe.

Retention is part of the same decision. Keep detailed logs as long as you actually investigate with them, and no longer.

What logs cost

Logging has a bill: CPU and allocations in the process, network, storage, indexing and the time people spend reading. When tens of thousands of students are active at once, even one Information event per request is a lot of data, and a single LogInformation inside a loop can outweigh everything else. Every so often I count events by template, which structured logs make trivial, and look at the top ten. The usual findings are a framework category left at Information, a debug line that slipped into a hot loop, and a large object destructured on every call. Fixing those three usually does more than any sampling scheme.

If your logs feel noisy and still do not answer the questions you have during an incident, that is the kind of backend work I take on. The next note moves from what a service reports to what it must never mix up: tenants in a shared PostgreSQL database, guarded by EF Core filters and row-level security.

This note is also available in Persian: read the Persian version.

Back to all notes