Logging and Trace Ids: Finding Out What Happened – Web API | Lesson 90
Introduction
Every SMS error already carries a traceId (Lesson 80), and the 500 handler already logs crashes under it.
But the rest of the API logs very little, and most of it is hard to search.
This lesson gives the SMS proper logs: a short list of deliberate messages, each with searchable properties, each linked to the request and the user. In production, they come out as JSON.
By the end of this lesson, you will be able to:
- Use
ILoggerwith log levels and message templates. - Explain structured logging, and why string interpolation spoils it.
- Write fast, typed log methods with
[LoggerMessage]. - Add the user to every log entry with a logging scope.
- Configure simple logs for development and JSON logs for production.
Why this matters
In production you cannot attach a debugger. When a fee payment fails at 9 in the morning, the logs are the only witness.
Good logs answer three questions fast: what happened, to which record, and for whom. Bad logs are either silent, or so noisy that the one useful line is lost. Both kinds cost hours on the day something goes wrong.
The concept
Think of the front office's daily diary. Each entry has a time, who, what, and a reference number, so "receipt 69" is found at once. A diary of loose notes cannot be searched.
Example: log levels
| Level | Use for | SMS example |
|---|---|---|
Trace, Debug | details for developers | off in production |
Information | normal events worth recording | a payment was recorded |
Warning | unusual but handled | a school rule refused a request; a slow request |
Error | a failure the user saw | an unhandled exception (Lesson 80) |
Critical | the app cannot work | the database is unreachable |
appsettings.json sets the minimum level per category (Lesson 70). "Microsoft.AspNetCore": "Warning" keeps the
framework quiet unless something is wrong.
Example: structured logging
A message template has named holes, and the logger keeps each value as a property:
logger.LogInformation("Payment {ReceiptNumber} recorded", receipt); // structured: ReceiptNumber is a property
logger.LogInformation($"Payment {receipt} recorded"); // interpolated: just text
Both print the same line. Only the first lets a log system search ReceiptNumber = RCP-2026-000069, or count
payments per invoice, without parsing text. String interpolation also builds the text even when the level is
switched off.
Example: scopes and trace ids
A scope is a set of properties that every log entry inside it carries. ASP.NET Core already opens scopes
with TraceId, SpanId, and RequestPath for each request. The SMS adds one more: UserId.
The TraceId in the logs is the middle part of the traceId that error responses show:
Response traceId | Log TraceId |
|---|---|
00-16964d4d17c0a8ad52435b6e19230ed9-1f0657bea746afb4-00 | 16964d4d17c0a8ad52435b6e19230ed9 |
Example: what to log, and what never to log
| Log | Never log |
|---|---|
| business events with ids: "payment RCP-2026-000069 on INV-2026-000003" | names, birthdays, phone numbers, addresses |
| refused requests: the rule number and the user id | passwords, access tokens, signing keys |
| slow requests and failures | whole request or response bodies |
| startup problems, such as a missing setting | every SELECT in production |
A useful test: could you show this log line to a visitor at the front office? If not, it does not belong in the logs.
Example: where the logs go
This course writes logs to the console. In a real deployment, something collects the console output and sends it to a log store that can search and alert. That can be a hosted log service, an Elasticsearch cluster, or a tool such as Seq.
That is why the format matters. A log store reads JSON fields directly, so InvoiceNumber, UserId, and
TraceId become columns you can filter on. Many teams now send logs, traces, and metrics together with
OpenTelemetry; the trace ids in this lesson are the same ones it uses.
Apply it to the SMS
Step 1: every deliberate message in one class
namespace SchoolApp.Api.Logging;
// Lesson 90: every log message the SMS writes on purpose, in one place.
// [LoggerMessage] makes the compiler write a fast logging method for each one. The {Names} in a message are
// properties: a log system can search "all payments on invoice INV-2026-000003" without parsing text.
// Ids only, never names, phone numbers, or passwords: logs are read by more people than the database is.
public static partial class SchoolLog
{
[LoggerMessage(EventId = 1001, Level = LogLevel.Information,
Message = "Payment {ReceiptNumber} of {Amount} recorded on invoice {InvoiceNumber}")]
public static partial void PaymentRecorded(ILogger logger, string receiptNumber, decimal amount, string invoiceNumber);
[LoggerMessage(EventId = 1002, Level = LogLevel.Information, Message = "Student {AdmissionNumber} removed")]
public static partial void StudentRemoved(ILogger logger, string admissionNumber);
[LoggerMessage(EventId = 1003, Level = LogLevel.Information,
Message = "Marks saved for paper {PaperId}, section {SectionId}: {Created} created, {Updated} updated")]
public static partial void MarksSaved(ILogger logger, int paperId, int sectionId, int created, int updated);
// The rule's message can contain a student's name, so only its number is logged. The user id is part of the
// message, because the exception handler runs outside UserLogScopeMiddleware's scope.
[LoggerMessage(EventId = 2001, Level = LogLevel.Warning,
Message = "School rule {ErrorCode} refused {Method} {Path} for user {UserId}")]
public static partial void SchoolRuleBroken(ILogger logger, int errorCode, string method, string path, string? userId);
[LoggerMessage(EventId = 2002, Level = LogLevel.Warning,
Message = "Slow request: {Method} {Path} took {ElapsedMs} ms")]
public static partial void SlowRequest(ILogger logger, string method, string path, long elapsedMs);
}
[LoggerMessage] makes the compiler write each method's body. The methods are typed, fast, and checked when
you build: a missing argument is a compile error, not a broken log line.
Each message has a fixed event id. Monitoring can alert on "more than 50 events 2001 in five minutes" without matching text.
The SMS numbers its events in blocks: 1000s for normal business events, 2000s for warnings. A new message gets the next free number in its block. A number is never reused for a different meaning, because dashboards and alerts depend on it.
Step 2: log where it happens
The controllers and the rule handler call these methods after the work is done:
FeePayment payment = await _payments.PayAsync(invoiceNumber, request.Amount, request.PaymentMode, cancellationToken);
SchoolLog.PaymentRecorded(_logger, payment.ReceiptNumber, payment.Amount, invoiceNumber); // Lesson 90
StudentsController logs a removal, ExamsController logs saved marks, and RequestTimingMiddleware adds a
warning for any request slower than one second.
The slow-request warning is cheap insurance. The dashboard took 65 ms in Lesson 84. If it ever takes two seconds after a data change, event 2002 shows it before parents start complaining.
The rule handler logs only the error number, never the rule's message. A message such as "Ishaan Kumar is already enrolled" would put a child's name in the logs, which more people can read than the database.
Step 3: the user in every entry
using System.Security.Claims;
namespace SchoolApp.Api.Middleware;
// Lesson 90: adds the signed-in user's id to every log message written while the request runs.
// A logging scope is extra properties that every log entry inside it carries, like a stamp on each page.
// It runs after UseAuthentication, so User is already filled in from the token.
public class UserLogScopeMiddleware
{
private readonly RequestDelegate _next;
private readonly ILogger<UserLogScopeMiddleware> _logger;
public UserLogScopeMiddleware(RequestDelegate next, ILogger<UserLogScopeMiddleware> logger)
{
_next = next;
_logger = logger;
}
public async Task InvokeAsync(HttpContext context)
{
string? userId = context.User.FindFirstValue("sub");
if (userId is null)
{
await _next(context); // not signed in: nothing to add
return;
}
// A message template, not a dictionary: the simple console format prints "UserId:3",
// and the JSON format stores UserId as a property.
using (_logger.BeginScope("UserId:{UserId}", userId))
{
await _next(context);
}
}
}
public static class UserLogScopeMiddlewareExtensions
{
public static IApplicationBuilder UseUserLogScope(this IApplicationBuilder app)
{
return app.UseMiddleware<UserLogScopeMiddleware>();
}
}
app.UseAuthentication(); // Lesson 85: who is calling? (reads and checks the token)
app.UseUserLogScope(); // Lesson 90: every log entry from here on carries the user's id
The first version used a Dictionary as the scope. The JSON format handled it, but the simple console format
printed System.Collections.Generic.Dictionary on every line. A message-template scope, "UserId:{UserId}",
prints UserId:3 and still becomes a property in JSON.
The rule handler runs in UseExceptionHandler, outside this scope, so its message includes the user id
itself.
Step 4: two formats
appsettings.json makes production logs JSON; appsettings.Development.json keeps them readable:
"Console": {
"FormatterName": "json",
"FormatterOptions": {
"IncludeScopes": true,
"UseUtcTimestamp": true,
"TimestampFormat": "yyyy-MM-ddTHH:mm:ss.fffZ"
}
}
In Development, signed in as Anitha (user 3), with request ids shortened:
12:32:13 warn: SchoolApp.Api.ErrorHandling.SchoolRuleExceptionHandler[2001] => SpanId:1f0657bea746afb4, TraceId:16964d4d17c0a8ad52435b6e19230ed9, ParentId:0000000000000000 => RequestPath:/api/sections/19/attendance School rule 50041 refused PUT /api/sections/19/attendance for user 3
12:32:14 info: SchoolApp.Api.Controllers.ExamsController[1003] => SpanId:d89c25a03ddbe7eb, TraceId:aabe94c15e3b358157bbaf744bf56807, ParentId:0000000000000000 => RequestPath:/api/exam-papers/20/marks => UserId:3 => SchoolApp.Api.Controllers.ExamsController.EnterMarks (SchoolApp.Api) Marks saved for paper 20, section 19: 0 created, 1 updated
The rule warning's TraceId matched the response's traceId, 00-16964d4d…-1f0657be…-00. Then the API ran as
Production, with the connection string and signing key from environment variables, because user secrets are a
development tool. One payment by the accountant (user 4) gave:
{
"Timestamp": "2026-10-08T12:33:01.937Z",
"EventId": 1001,
"LogLevel": "Information",
"Category": "SchoolApp.Api.Controllers.FeeInvoicesController",
"Message": "Payment RCP-2026-000069 of 500 recorded on invoice INV-2026-000003",
"State": { "ReceiptNumber": "RCP-2026-000069", "Amount": 500, "InvoiceNumber": "INV-2026-000003", ... },
"Scopes": [
{ "SpanId": "e47c994fa7dbb9a1", "TraceId": "e90799fe827dceb0d99ec7586b8e79ce", ... },
{ "ConnectionId": "0HNP5715AU465" },
{ "RequestPath": "/api/fee-invoices/INV-2026-000003/payments", ... },
{ "UserId": "4" },
{ "ActionName": "SchoolApp.Api.Controllers.FeeInvoicesController.Pay (SchoolApp.Api)", ... }
]
}
Every value is a separate field: receipt, amount, invoice, user, trace. All demo payments and marks were removed from SchoolDb afterwards.
Notice what is not there: no student name, no amount owed, no token. The accountant's actions can be traced
by user id. Only someone allowed to see the Users table can look up who user 4 is.
Example: more detail, without a restart
Log levels are read from configuration, and ASP.NET Core reloads appsettings.json when it changes. To
investigate a problem in one area, raise one category for a few minutes:
"LogLevel": {
"Default": "Information",
"SchoolApp.Api.Controllers.FeeInvoicesController": "Debug"
}
The running API picks it up, the same way ReadOnlyMode did in Lesson 89. We tried the opposite direction:
with the API running, SchoolApp.Api.Middleware.RequestTimingMiddleware was set to Warning in
appsettings.Development.json. The request before the change wrote its "responded 200" line; the request two
seconds after it wrote none.
Set it back afterwards. Detailed logs cost disk space and money, and every extra line is another place where data could leak.
Step 5: a test that reads the logs
Show tests/SchoolApp.Tests/Api/LoggingTests.cs
using System.Collections.Concurrent;
using System.Net;
using System.Net.Http.Headers;
using System.Net.Http.Json;
using Microsoft.AspNetCore.Hosting;
using Microsoft.Extensions.Logging;
using SchoolApp.Api.Security;
namespace SchoolApp.Tests.Api;
// Lesson 90: the API's own log messages, captured in memory while it runs.
[Collection("Api")]
public class LoggingTests
{
private readonly ApiFactory _factory;
public LoggingTests(ApiFactory factory)
{
_factory = factory;
}
// A tiny logger provider for tests: it keeps every entry in a list.
private sealed class ListLoggerProvider : ILoggerProvider
{
public ConcurrentQueue<(string Category, EventId EventId, LogLevel Level, string Message)> Entries { get; } = new();
public ILogger CreateLogger(string categoryName) => new ListLogger(categoryName, Entries);
public void Dispose()
{
}
private sealed class ListLogger(string category, ConcurrentQueue<(string, EventId, LogLevel, string)> entries) : ILogger
{
public IDisposable? BeginScope<TState>(TState state) where TState : notnull => null;
public bool IsEnabled(LogLevel logLevel) => true;
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception,
Func<TState, Exception?, string> formatter) =>
entries.Enqueue((category, eventId, logLevel, formatter(state, exception)));
}
}
[Fact]
public async Task BrokenRule_LogsAWarning_WithTheErrorCodeAndUser_ButNoNames()
{
ListLoggerProvider logs = new ListLoggerProvider();
HttpClient client = _factory.WithWebHostBuilder(builder =>
builder.ConfigureLogging(logging => logging.AddProvider(logs))).CreateClient();
client.DefaultRequestHeaders.Authorization = new AuthenticationHeaderValue("Bearer",
await ApiFactory.GetTokenAsync(client, ApiFactory.UserNameFor(Roles.Teacher)));
// Rahul is class teacher of 10-B (section 20); 2026-07-05 is a Sunday (rule 50041).
HttpResponseMessage response = await client.PutAsJsonAsync("/api/sections/20/attendance?date=2026-07-05",
new { entries = new[] { new { rollNumber = 1, status = "Present" } } });
Assert.Equal(HttpStatusCode.UnprocessableEntity, response.StatusCode);
var warning = Assert.Single(logs.Entries, e => e.EventId.Id == 2001);
Assert.Equal(LogLevel.Warning, warning.Level);
Assert.Contains("School rule 50041 refused PUT /api/sections/20/attendance for user ", warning.Message);
Assert.DoesNotContain("Sunday", warning.Message); // the rule's text stays out of the log
}
}
Logs are part of the API's behaviour, so they deserve tests too. If someone later "improves" the rule warning by adding the rule's text, this test fails before a child's name ever reaches production.
A tiny logger provider keeps every entry in a list. The test breaks a rule and checks for exactly one warning 2001, with the error code and the user, and without the rule's text. The suite has 137 tests, all passing.
Common mistakes
- String interpolation in log calls. The values become plain text and cannot be searched. Fix: message
templates, or
[LoggerMessage]. - Logging personal data. Names, phone numbers, tokens, and passwords end up in a system many people read. Fix: log ids only.
- Everything at
Information. The useful lines drown. Fix: choose levels, and keep framework categories atWarning. - Logs that cannot be linked to a request. Support cannot find the error a user reported. Fix: scopes with the trace id, shown in every error response.
- Text logs in production. Log systems must guess at fields. Fix: the JSON format.
In real projects
A school's API logged every request as one long line of text, including the full request body. Fee complaints took a day to investigate, because nobody could search the logs for an invoice number.
One day the team noticed the bodies included parents' phone numbers and, on the sign-in endpoint, passwords.
We removed body logging, added event-id messages with ids only, and switched production to JSON with trace ids. The next fee complaint took four minutes, from the trace id on the parent's screenshot to the exact request.
Best practices
- Log deliberate events with fixed event ids, in one class.
- Use message templates or
[LoggerMessage], never string interpolation. - Log ids, never names, contact details, tokens, or passwords.
- Put the trace id and the user in every entry with scopes.
- Use JSON logs in production, and readable logs in development.
Recap
ILoggerwrites at a level; settings decide which levels each category keeps.- Message templates keep values as properties;
[LoggerMessage]makes typed, fast log methods. - Scopes add
TraceIdandUserIdto every entry, matching the response'straceId. - Broken rules log their number and user, not their text.
- Production logs are JSON; a test captures entries in memory: 137 tests pass.
Homework
Library module task: Add structured logging to a single-file library API. Write two [LoggerMessage]
methods, BookIssued (event 3001, Information) and IssueRefused (event 3002, Warning), with ids only. Use
the JSON console format with scopes, and keep framework messages at Warning.
A correct result looks like (the log lines, read as JSON):
POST /api/book-issues {"isbn":"9780143039655","studentId":6} 200
POST /api/book-issues {"isbn":"9780141325293","studentId":3} 409 {"message":"Every copy of this book is issued."}
3001 Information Book 9780143039655 issued to student 6 | TraceId 174c278722494b559600461c72a10c58
3002 Warning Issue of 9780141325293 refused: every copy is issued | TraceId 2b3d1488766a07f3ae0d0ffdef3f4247
Show the solution
// Library homework, Lesson 90: structured logs. Two [LoggerMessage] methods (book issued, issue refused),
// ids only, and JSON console output with scopes, so each entry carries the request's TraceId.
// Run with: dotnet run library-assignment/090-library-logging.cs
#:sdk Microsoft.NET.Sdk.Web
#:property PublishAot=false
using Microsoft.AspNetCore.Mvc;
WebApplicationBuilder builder = WebApplication.CreateBuilder(args);
builder.Logging.ClearProviders();
builder.Logging.AddJsonConsole(options =>
{
options.IncludeScopes = true;
options.UseUtcTimestamp = true;
options.TimestampFormat = "yyyy-MM-ddTHH:mm:ss.fffZ";
});
builder.Logging.AddFilter("Microsoft", LogLevel.Warning); // only the library's own messages at Information
builder.Services.AddControllers();
WebApplication app = builder.Build();
app.MapControllers();
app.Run("http://localhost:5090");
public record IssueRequest(string Isbn, int StudentId);
public static partial class LibraryLog
{
[LoggerMessage(EventId = 3001, Level = LogLevel.Information, Message = "Book {Isbn} issued to student {StudentId}")]
public static partial void BookIssued(ILogger logger, string isbn, int studentId);
[LoggerMessage(EventId = 3002, Level = LogLevel.Warning, Message = "Issue of {Isbn} refused: {Reason}")]
public static partial void IssueRefused(ILogger logger, string isbn, string reason);
}
[ApiController]
[Route("api/book-issues")]
public class BookIssuesController : ControllerBase
{
private static readonly HashSet<string> OnLoan = ["9780141325293"]; // The Jungle Book is out
private readonly ILogger<BookIssuesController> _logger;
public BookIssuesController(ILogger<BookIssuesController> logger)
{
_logger = logger;
}
[HttpPost]
public IActionResult Issue(IssueRequest request)
{
if (!OnLoan.Add(request.Isbn))
{
LibraryLog.IssueRefused(_logger, request.Isbn, "every copy is issued");
return Conflict(new { message = "Every copy of this book is issued." });
}
LibraryLog.BookIssued(_logger, request.Isbn, request.StudentId);
return Ok(new { message = $"{request.Isbn} issued to student {request.StudentId}." });
}
}
Your trace ids will differ: a new one is made for every request.
Quiz
Why prefer a message template over string interpolation in a log call?
Show answer
Answer: B. The values stay separate properties that log systems can search Search ReceiptNumber = RCP-2026-000069, not text.
What does [LoggerMessage] do?
Show answer
Answer: B. Makes the compiler write a typed, fast logging method A missing argument becomes a build error.
How does a log entry get the request's TraceId and the user's id?
Show answer
Answer: B. Scopes: properties every entry inside them carries ASP.NET Core adds TraceId; UserLogScopeMiddleware adds UserId.
Why does the rule warning log the error number but not the rule's message?
Show answer
Answer: B. The message can contain a child's name, and logs are read by more people Log ids, never personal data.
Which part of the response traceId 00-16964d4d...-1f0657be...-00 appears in the logs as TraceId?
Show answer
Answer: B. The 32-character middle part The middle part is the trace id; the next part is the span id.
Interview questions
Questions are grouped by experience level. Click a question to see a model answer. All questions: Web API interview questions.
Fresher (0-2 yrs)
F What are log levels, and when would you use Warning instead of Error? concept
Levels rank how important an entry is: Trace, Debug, Information, Warning, Error, Critical. Warning is for something unusual that was handled, such as a school rule refusing a request or a slow request; Error is for a failure the user saw, such as an unhandled exception. Settings choose the minimum level per category.
F What is structured logging? concept
Writing log entries from a message template with named holes, such as "Payment {ReceiptNumber} recorded", so each value is kept as a separate property. Log systems can then search and count by property (ReceiptNumber = RCP-2026-000069) instead of parsing text.
F What should never be written to logs? concept
Passwords, access tokens, signing keys, and personal data such as names, birthdays, phone numbers, and addresses, and whole request or response bodies that may contain them. Logs are read by more people and kept in more places than the database. The SMS logs ids only.
Mid (3-5 yrs)
M Why is logger.LogInformation($"Payment {receipt}") a bad habit? coding
String interpolation turns the value into plain text, so it cannot be searched as a property, and the string is built even when the level is turned off. Use a message template, LogInformation("Payment {ReceiptNumber}", receipt), or a [LoggerMessage] method.
M What does the [LoggerMessage] attribute give you? coding
The compiler generates the body of a static partial logging method: fast (no boxing, the template parsed once), typed (a missing argument is a build error), with a fixed event id and level. The SMS keeps every deliberate message in one SchoolLog class this way.
M How do you add the current user to every log entry of a request? coding
Open a logging scope after authentication, for example in a small middleware: logger.BeginScope("UserId:{UserId}", userId). Every entry written inside the scope carries UserId, and the JSON formatter stores it as a property. Code that runs outside the scope, such as the exception handler, must add the user to its own message.
Senior (6-9 yrs)
S A parent sends a screenshot of an error with a trace id. How do you find what happened? scenario
Search the logs for the trace id. In ASP.NET Core it is the middle part of the response's traceId
(00-<TraceId>-<SpanId>-00), and every log entry of that request carries it as a scope. The matching
entries show the request path, the user, the rule or exception, and the timing.
How to answer: Explain how the trace id links the response to the logs, what the entries contain, and why logs must include scopes and be searchable for this to work.
S The team finds parents' phone numbers and passwords in the API logs. What do you do? scenario
Stop the leak first: remove request-body logging and any log line that includes personal data, and deploy. Then treat the stored logs as an incident: restrict access, delete or redact them according to policy, and ask affected users to change passwords. Prevent it returning with deliberate log messages that take ids only, and tests that check sensitive text never appears in logs.
How to answer: Order the response: contain, clean up existing data, notify, then prevent with design and tests.
Architect / Lead (10+ yrs)
A How would you design observability for an API that runs on many servers for many schools? design
Structured JSON logs with fixed event ids, sent to a central store; distributed traces with the same trace ids across services (OpenTelemetry); and metrics such as request rates, error rates, and response times per endpoint and school. Add the school and user ids as scopes, alert on symptoms (error rate, slow requests), keep personal data out, and set retention and access rules for each kind of data.
How to answer: Cover the three signals (logs, traces, metrics), how they are linked, what you alert on, and the privacy and cost limits.
Resources
- Code for this lesson: git tag
lesson-90-logging(code repository coming soon) - Files:
src/SchoolApp.Api/Logging/SchoolLog.cs,src/SchoolApp.Api/Middleware/UserLogScopeMiddleware.cs,src/SchoolApp.Api/appsettings.json,tests/SchoolApp.Tests/Api/LoggingTests.cs,library-assignment/090-library-logging.cs - Video: coming soon
What's next
The API can now explain itself. Next, caching: keeping answers that rarely change in memory, so the busiest screens stop asking SQL Server the same question. Lesson 91: Server-side caching
Want live sessions, code reviews, and interview preparation? Join the next batch at Sahasra Technologies.