The Trace Id

Monday morning. Maria, who works the till, says: "I pressed Books at about ten and it said something went wrong." That is all she can tell you. She does not know what the error was, and she cannot say what she did before it.

You open the log from the last lesson. Monday's log has four thousand lines: every login, every report, every crash of every person in the shop. At about ten o'clock, forty requests came in. Which one was Maria's? You can see several crashes. You have no way to know which one belongs to her, and "about ten" is a guess.

The fix is a label that both sides hold. When a request crashes, the API gives it a short code and does two things with it: writes it in the log next to the crash, and sends it back to Maria in the error. Maria reads the code out. You search the log for it, and the one crash that carries it comes up. No guessing. This code is the trace id.

Our goal: every crash that the API answers carries a trace id, in the answer and in the log, so that a code a user reads out leads straight to the crash and its stack trace.

Here is the route:

1. Look at a crash as it is today, and see that nothing links the answer to the log.
2. Give the handler the trace id, in the log line and in the answer.
3. Crash again, take the id from the answer, and find the crash in the log with one search.
4. Read the stack trace that the search turns up, to see which part of our code broke.
5. Test it.

Left out: how the id is built inside (it follows a standard that is also used to follow one request across several servers), following a request across many services, and showing the id on the web pages.

Where we are

This is the solution from the end of logging. No file is added:

BookShop/
  src/
    BookShop.Api/
      GlobalExceptionHandler.cs           <- changes
  tests/
    BookShop.Api.Tests/
      GlobalExceptionHandlerTests.cs      <- changes

Only the files that change are listed. Run every command from the solution folder, BookShop/.

A crash today

To have something to look for, we crash the API on purpose, the way errors the professional way did: point the connection string at a database file that has no tables. Open src/BookShop.Api/appsettings.json and change the one line:

    "BookShop": "Data Source=empty.db"

(Your real bookshop.db is not touched. Put the line back when the lesson is done.) Start the API, saving the log in a file as in the last lesson:

dotnet run --project src/BookShop.Api 2>&1 | tee app.log

The books are locked now, so log in as bob first and use the token (bash; the PowerShell form is in protect endpoints and roles):

TOKEN=$(curl -s -X POST http://localhost:5101/auth/login -H "Content-Type: application/json" -d '{"userName":"bob","password":"bob-pass-1"}' | python3 -c 'import sys,json;print(json.load(sys.stdin)["token"])')
curl -H "Authorization: Bearer $TOKEN" http://localhost:5101/books

The API answers 500. The body is one line; here it is one field per line:

{
  "type": "https://tools.ietf.org/html/rfc9110#section-15.6.1",
  "title": "Something went wrong on our side.",
  "status": 500,
  "detail": "The error has been logged."
}

Maria would see this. Nothing in it points to the log. And the log line that our handler wrote says only which request it was:

2026-10-31 18:31:50 fail: GlobalExceptionHandler[0]
      Unhandled exception on GET /books

So the answer and the log line cannot be matched. Stop the API with Ctrl+C.

Where the id comes from

ASP.NET already gives every request an id, before our code runs. You have seen it without asking: the errors that ASP.NET builds itself carry a traceId field, such as the 401 of a wrong password in the login endpoint. Ours is the one error that does not, because we wrote the handler by hand and left it out on purpose until it had a use. Now it has one.

The id has a fixed shape, 00- and some letters and digits, like 00-8fc6c22f9e83576f908dc27a660b9881-3bd07700398df123-00. You never need to read it. It is a random label, made fresh for each request. Two things follow:

• It is safe to show. It says nothing about our code, our data or our server, and it cannot be turned into anything. The only thing it can do is be looked up in our log, by us.
• It is the same everywhere in the request. The answer, the log line and any other line written during that request carry the same one.

In code, getting it is one line:

var traceId = Activity.Current?.Id ?? httpContext.TraceIdentifier;

ASP.NET tracks each request as an activity, and Activity.Current is the one in progress. Its Id is the id above. The ?. says "if there is no current activity, give nothing instead of crashing", and ?? says "if the left side gave nothing, use the right side": ASP.NET's own plain per-request id, TraceIdentifier. In a real request the first one is always there. The second is a safety net.

Give the handler the id

The handler needs to do the same thing in two places: put the id in the log line, and put it in the answer. Open src/BookShop.Api/GlobalExceptionHandler.cs. The whole file is:

using System.Diagnostics;                                                           // new
using Microsoft.AspNetCore.Diagnostics;
using Microsoft.AspNetCore.Mvc;

public class GlobalExceptionHandler : IExceptionHandler
{
    private readonly ILogger<GlobalExceptionHandler> _logger;

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

    public async ValueTask<bool> TryHandleAsync(
        HttpContext httpContext, Exception exception, CancellationToken cancellationToken)
    {
        var traceId = Activity.Current?.Id ?? httpContext.TraceIdentifier;          // new

        _logger.LogError(exception, "Unhandled exception on {Method} {Path}, trace {TraceId}",   // new
            httpContext.Request.Method, httpContext.Request.Path, traceId);         // new
        // _logger.LogError(exception, "Unhandled exception on {Method} {Path}",    // replaced
        //     httpContext.Request.Method, httpContext.Request.Path);               // replaced

        var problem = new ProblemDetails
        {
            Type = "https://tools.ietf.org/html/rfc9110#section-15.6.1",
            Title = "Something went wrong on our side.",
            Status = StatusCodes.Status500InternalServerError,
            Detail = "The error has been logged. If you report it, quote the trace id."   // new
            // Detail = "The error has been logged."                                // replaced
        };
        problem.Extensions["traceId"] = traceId;                                    // new

        httpContext.Response.StatusCode = StatusCodes.Status500InternalServerError;
        await httpContext.Response.WriteAsJsonAsync(
            problem, options: null, contentType: "application/problem+json", cancellationToken);
        return true;
    }
}

(The commented lines are only for this page, to show where the old code went. They can be deleted, and real projects keep that history in git.)

Four changes:

• var traceId = ... gets the id once, at the top, so the log and the answer are sure to hold the same one.
• trace {TraceId} adds a named hole to the log line, the structured habit from the last lesson. The id becomes a field that a log tool could search by.
• problem.Extensions["traceId"] adds a field to the answer. ProblemDetails has Type, Title, Status and Detail as properties, and a dictionary called Extensions for any extra fields; the standard allows them. The field is named traceId, the same name ASP.NET uses in its own errors, so a page needs only one way to read it.
• Detail now tells the reader what to do with it.

Crash again and follow the id

Start the API again with tee, log in, and ask for the books, exactly as before. The answer:

{
  "type": "https://tools.ietf.org/html/rfc9110#section-15.6.1",
  "title": "Something went wrong on our side.",
  "status": 500,
  "detail": "The error has been logged. If you report it, quote the trace id.",
  "traceId": "00-8fc6c22f9e83576f908dc27a660b9881-3bd07700398df123-00"
}

(Your id is different: it is new for every request.) This is what Maria would read out. Here is how a page could show it. This is a drawing of an idea; our pages do not show the id yet, and the lesson leaves that out:

Now you are the developer, with app.log and the id. Search for it. Let it show the line before (the level and the name) and three lines after:

grep -B1 -A3 00-8fc6c22f9e83576f908dc27a660b9881-3bd07700398df123-00 app.log

2026-10-31 18:32:13 fail: GlobalExceptionHandler[0]
      Unhandled exception on GET /books, trace 00-8fc6c22f9e83576f908dc27a660b9881-3bd07700398df123-00
      Microsoft.Data.Sqlite.SqliteException (0x80004005): SQLite Error 1: 'no such table: Books'.
         at Microsoft.Data.Sqlite.SqliteException.ThrowExceptionForRC(Int32 rc, sqlite3 db)
         at Microsoft.Data.Sqlite.SqliteCommand.PrepareAndEnumerateStatements()+MoveNext()

(grep -B1 adds the line before each match, as -A3 adds three after. PowerShell: Select-String -Context 1,3 <the id> app.log.) In a log of four thousand lines, one crash comes up: the time, which request it was (GET /books), and what went wrong (no such table: Books). Out of everything, that is Maria's.

(EF Core wrote two more lines for this crash a moment earlier, and they do not carry the id. Ours is the one to search for, because it is the one the user can quote.)

Which part of the code broke

The id found the log entry. It does not know anything about the code; the stack trace in the entry does. Exceptions and stack traces taught how to read one: from the top, look for the first line that is our code. The framework's lines come first, and they only say how the failure travelled. To skip them, print the lines of our own namespaces after the match:

grep -A40 00-8fc6c22f9e83576f908dc27a660b9881-3bd07700398df123-00 app.log | grep -E "at BookShop|at BooksController"

         at BookShop.Data.BookService.GetAllAsync() in src/BookShop.Data/BookService.cs:line 17
         at BooksController.GetAll() in src/BookShop.Api/Controllers/BooksController.cs:line 22

(The real lines start with the full path of your machine; we shortened them. The line numbers are the ones in our solution and yours may differ.) That is the answer to "which part broke": the list of books, in GetAllAsync of BookService.cs, called from GetAll in the controller. Together with no such table: Books, the cause is clear: the database the API opened has no tables.

So the two halves of the work are separate on purpose. The id finds the entry. The stack trace in the entry shows where. The id is small enough for a person to say over the phone. The stack trace is long and would be useless to say.

Put the connection string in appsettings.json back to Data Source=bookshop.db, and delete the empty.db file that SQLite made in src/BookShop.Api/.

The test

The handler has tests from errors the professional way. Add one that checks the new promise: the answer carries the id. Open tests/BookShop.Api.Tests/GlobalExceptionHandlerTests.cs. The whole file is:

using System.Text.Json;
using Microsoft.AspNetCore.Http;
using Microsoft.Extensions.Logging;

namespace BookShop.Api.Tests;

[TestClass]
public class GlobalExceptionHandlerTests
{
    private FakeLogger<GlobalExceptionHandler> _logger = null!;
    private GlobalExceptionHandler _handler = null!;
    private DefaultHttpContext _context = null!;

    [TestInitialize]
    public void Setup()
    {
        _logger = new FakeLogger<GlobalExceptionHandler>();
        _handler = new GlobalExceptionHandler(_logger);
        _context = new DefaultHttpContext();
        _context.Response.Body = new MemoryStream();
    }

    private async Task<string> ReadBodyAsync()
    {
        _context.Response.Body.Position = 0;
        return await new StreamReader(_context.Response.Body).ReadToEndAsync();
    }

    [TestMethod]
    public async Task TryHandleAsync_AnyException_Answers500AsProblemDetails()
    {
        var handled = await _handler.TryHandleAsync(
            _context, new InvalidOperationException("boom"), CancellationToken.None);

        Assert.IsTrue(handled);
        Assert.AreEqual(500, _context.Response.StatusCode);
        Assert.StartsWith("application/problem+json", _context.Response.ContentType);
        var body = JsonDocument.Parse(await ReadBodyAsync());
        Assert.AreEqual(500, body.RootElement.GetProperty("status").GetInt32());
    }

    [TestMethod]
    public async Task TryHandleAsync_ExceptionWithSecret_DoesNotLeakItToTheClient()
    {
        var exception = new InvalidOperationException("Cannot open Data Source=secret.db");

        await _handler.TryHandleAsync(_context, exception, CancellationToken.None);

        var body = await ReadBodyAsync();
        Assert.DoesNotContain("secret.db", body);
        Assert.DoesNotContain("InvalidOperationException", body);
    }

    [TestMethod]
    public async Task TryHandleAsync_AnyException_LogsItAsAnError()
    {
        var exception = new InvalidOperationException("boom");

        await _handler.TryHandleAsync(_context, exception, CancellationToken.None);

        Assert.HasCount(1, _logger.Levels);
        Assert.AreEqual(LogLevel.Error, _logger.Levels[0]);
        Assert.AreSame(exception, _logger.Exceptions[0]);
    }

    [TestMethod]                                                                    // new
    public async Task TryHandleAsync_AnyException_PutsTheTraceIdInTheBody()         // new
    {                                                                               // new
        _context.TraceIdentifier = "test-trace-id";                                 // new
                                                                                    // new
        await _handler.TryHandleAsync(                                              // new
            _context, new InvalidOperationException("boom"), CancellationToken.None);   // new
                                                                                    // new
        var body = JsonDocument.Parse(await ReadBodyAsync());                       // new
        Assert.AreEqual("test-trace-id", body.RootElement.GetProperty("traceId").GetString());   // new
    }                                                                               // new
}

In a test no real request is running, so Activity.Current is empty and the handler falls back to TraceIdentifier. The test sets that to a known text and checks that the same text comes back in the body. Run the tests:

dotnet test

Passed!  - Failed:     0, Passed:    15, Skipped:     0, Total:    15, Duration: 2 s - BookShop.Api.Tests.dll (net10.0)

(15 is the count in the scratch solution we ran these files in, which holds only the tests this part of the course touches; yours is higher. None should fail.)

Where we ended

Compare with your solution. No file was added, two changed:

BookShop/
  src/
    BookShop.Api/
      GlobalExceptionHandler.cs             gets the trace id, logs it and sends it back
  tests/
    BookShop.Api.Tests/
      GlobalExceptionHandlerTests.cs        one new test: the id is in the answer

Recap

• A trace id is a short random code that ASP.NET gives every request. It identifies one request and nothing else.
• Without it, a user's report ("about ten, it broke") cannot be matched with one crash in a log of thousands of lines.
• The handler writes the id in the log line and sends it in the answer, as the traceId field of the Problem Details. The user reads it out, and you search the log for it.
• The id finds the entry. The stack trace in the entry says where the code broke.
• It is safe to show: it is random and says nothing about the system.

Questions to think about

Try to answer each one before you open the answer.

1. Why does the answer to the user carry the trace id, and not just the log?

2. Does the trace id tell you what broke?

3. Is it safe to show the trace id to a user?

4. The id is a random code, so why does the handler get it once at the top and not twice, once for the log and once for the answer?

Next lesson: CORS, an optional lesson on what happens when the web pages are served from a different place than the API.