Skip to main content
ANVISoftware Solutions
Lesson 15 of 23Intermediate16 min

Logging and Correlation

By the end of this lesson

Log requests with enough context to trace one call through the system.

A log is the record of what your service did. Its value is decided at the moment something goes wrong, which is always after the code was written, and usually when you cannot reproduce the problem.

So the question to ask while writing a log line is not whether it reads nicely. It is whether someone holding only this line, three weeks from now, could tell which request it belonged to and what happened.

Structured logging is what makes that possible. Instead of building a sentence, you write a message template with named placeholders and pass the values separately. The logging system stores each value as a field you can search on.

The two ways to write the same line, and why the difference matters more than it looks:

 Interpolated stringMessage template
The calllogger.LogInformation($"Created employee {id} in {dept}")logger.LogInformation("Created employee {EmployeeId} in {DepartmentId}", id, dept)
What is storedOne finished stringA template plus named fields
Finding every entry for employee 148Text search, and it also matches 1480 and department 148Query one field for an exact value
Grouping identical eventsHard. Every line is uniqueThe template is the same for all of them, so they group
Cost when the level is disabledThe string is built anyway, then thrown awayNothing is formatted unless the entry is written

Six levels exist, and choosing between them is a judgement about who needs to see the entry. Anything at Warning or above should be actionable:

Trace and Debug
Development detail. Values of variables, entry and exit of a method. Off in production, because the volume is high and it can contain more than you want stored.
Information
A thing happened that you would want to see in a normal timeline: a record was created, a background job ran. Keep this level deliberate, or it becomes unreadable.
Warning
Something unexpected that the service handled. A retry succeeded on the second attempt, a cache was unavailable and the code fell back to the database. Worth a look if it becomes frequent.
Error
One operation failed. A request did not complete, a message could not be processed. Someone should investigate. Always pass the exception object, not only its message.
Critical
The service itself cannot continue or is about to stop working. Reserve it, so that a Critical entry genuinely means wake someone up.
Structured logging in a service class
C#
public sealed class EmployeeService(
    HrDbContext db,
    ILogger<EmployeeService> logger) : IEmployeeService
{
    public async Task<EmployeeResponse> CreateAsync(
        CreateEmployeeRequest request,
        CancellationToken cancellationToken)
    {
        Employee employee = new()
        {
            FullName = request.FullName,
            WorkEmail = request.WorkEmail,
            DepartmentId = request.DepartmentId,
        };

        db.Employees.Add(employee);
        await db.SaveChangesAsync(cancellationToken);

        logger.LogInformation(
            "Created employee {EmployeeId} in department {DepartmentId}",
            employee.Id,
            employee.DepartmentId);

        return EmployeeResponse.From(employee);
    }

    public async Task<EmployeeResponse?> FindAsync(int id, CancellationToken cancellationToken)
    {
        Employee? employee = await db.Employees.FindAsync([id], cancellationToken);

        if (employee is null)
        {
            // Not an error. A caller asking for a record that is gone is normal.
            logger.LogDebug("Employee {EmployeeId} not found", id);
            return null;
        }

        return EmployeeResponse.From(employee);
    }
}
  • ILogger<EmployeeService> is injected, and the type argument becomes the log category. That is how you later filter to entries from this class alone.
  • The placeholders are named, not numbered, and the names become field names. Use PascalCase for them; it is the common convention and it keeps field names consistent across a codebase.
  • Arguments are matched to placeholders by position, left to right. The names do not have to match your variable names, but they should describe the value.
  • A missing record is logged at Debug, not Error. Nothing failed — the caller asked a reasonable question and got a truthful answer. Logging normal outcomes as errors is how an error dashboard becomes something people stop reading.
A correlation id, so one call can be followed across services
C#
public sealed class CorrelationIdMiddleware(RequestDelegate next)
{
    private const string HeaderName = "X-Correlation-Id";

    public async Task InvokeAsync(HttpContext context, ILogger<CorrelationIdMiddleware> logger)
    {
        // Reuse the caller's id if there is one, so a chain of calls shares it.
        string correlationId =
            context.Request.Headers.TryGetValue(HeaderName, out var supplied)
            && !string.IsNullOrWhiteSpace(supplied)
                ? supplied.ToString()
                : Activity.Current?.TraceId.ToString() ?? Guid.NewGuid().ToString("N");

        context.Response.Headers[HeaderName] = correlationId;

        // Everything logged inside this using block carries the id.
        using (logger.BeginScope(new Dictionary<string, object>
        {
            ["CorrelationId"] = correlationId,
            ["RequestPath"] = context.Request.Path.ToString(),
        }))
        {
            await next(context);
        }
    }
}

// Program.cs — early, so the scope covers as much of the request as possible
app.UseMiddleware<CorrelationIdMiddleware>();
  • A correlation id is one value that identifies a single logical operation, even when that operation crosses several services. Passing it in a header is how each service joins the same story.
  • Taking the caller's header when present is the important half. Generating a fresh id every hop would give you five unrelated ids for one user action.
  • BeginScope attaches those fields to every log entry written inside the using block, including entries from code that knows nothing about correlation. This is the mechanism that saves you from threading an id through every method signature.
  • Returning the id in the response header lets a client quote it in a support request. It is also what makes the trace identifier in your error responses useful.
  • Pass the id on outbound calls too, by adding the same header to your HttpClient requests. A correlation id that stops at your boundary only correlates half the journey.

Summary

  • Write message templates with named placeholders so values are stored as searchable fields rather than baked into a sentence
  • Levels are a judgement about who needs to act: Warning and above should mean something is worth attention
  • Always pass the exception object to LogError, because that is what carries the type and stack trace
  • A correlation id taken from the caller's header, attached with BeginScope, lets one operation be followed across services without threading it through every method
  • Log identifiers, not people. Credentials, tokens and personal data must never reach a log

Practice

Attempt each one before opening the solution. Getting it wrong first is how the idea sticks.

Try it yourself

Follow one request end to end

Add the correlation middleware to an API, then call an endpoint that logs in two different classes.

Confirm that both entries carry the same CorrelationId field, and that the value matches the X-Correlation-Id header on the response. Then send your own header value and confirm the service reuses it.

Show solution

Both entries carry the field because BeginScope applies to everything written while the scope is open, regardless of which class wrote it. Neither service class mentions correlation anywhere.

Reusing a supplied header is what makes this work across service boundaries. If your API calls a second API, and that one honours the same header, one query on the id returns the whole journey in order.

One caveat to note while testing: a scope only covers work that happens inside the using block. Work started with fire-and-forget continues after the block closes and loses the fields, which is one more reason to await what you start.

Think about it

Rewrite a useless log line

You find this in production code: logger.LogError("Update failed: " + ex.Message). An incident report says updates failed intermittently for one afternoon.

List everything you cannot determine from that line, then rewrite it.

Show solution

You cannot tell which employee, which caller, which request, or what the failure actually was — only the message survived, so there is no stack trace and no exception type.

A better version passes the exception as the first argument and names the values: logger.LogError(ex, "Failed to update employee {EmployeeId} for {User}", id, user). The exception object is what carries the type and stack trace into the log.

The wider point is that the original line was not too short, it was the wrong shape. Concatenating ex.Message discards the most useful part of the exception while looking like it captured it.

Knowledge check

Nothing is recorded and there is no score. The explanation appears either way.

What does a log scope give you that adding fields to each log call does not?
Why is a message template with named placeholders preferred over an interpolated string?

Saved in this browser only.