Logging

It is Friday evening. bob phones the shop owner: "I could not get into the system this afternoon. It just said wrong password. Then it let me in. Did something break?"

The owner asks you. You open the API and everything works. You try bob's login: it works. What happened at three o'clock? Maybe bob mistyped the password once. Maybe the server was restarting. Maybe someone else tried bob's name. You have no way to tell, because the API did the work and kept no record of it. The only honest answer is "I don't know".

That is the problem logging solves. A log is the program's diary: one line for each thing worth remembering, with the time it happened. The program writes it as it goes. When someone phones on Friday evening, you read the diary instead of guessing.

Our goal: the API writes its own diary. By the end it records every failed login, every successful one and every look at the stock report, and you can choose how much it writes and where it goes.

Here is the route:

1. Look at what the API writes today, and notice that it says nothing about what we care about.
2. Add our own lines: a warning for a failed login, a note for a login and for a report view.
3. Learn the levels (how serious a line is), and use them to turn the noise down.
4. Learn why the lines carry named values such as {UserName}, and not just text.
5. Update the tests, which the new lines break.
6. Keep the diary in a file, and see where real teams send theirs.

Left out: finding one user's error in the middle of thousands of lines, which is the trace id. Also left out: log libraries and log services (named at the end, not built).

Where we are

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

BookShop/
  src/
    BookShop.Api/
      appsettings.json                      <- changes
      Controllers/
        AuthController.cs                   <- changes
        ReportsController.cs                <- changes
  tests/
    BookShop.Api.Tests/
      AuthControllerTests.cs                <- changes
      ReportsControllerTests.cs             <- changes

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

What the API writes today

You have already seen a log without calling it one. Every time you ran dotnet run, the lines that appeared in the terminal were the log: "Now listening on...", "Application started". ASP.NET writes them by itself. Our own code wrote one more kind of line, in errors the professional way: the global handler logs every crash, with its stack trace.

Let us see what the diary holds for the Friday story. Start the API with dotnet run --project src/BookShop.Api. Then do three things: bob logs in with a wrong password, alice logs in, and alice opens the stock report. In a second terminal (bash; in PowerShell the token goes into a variable in the same way as in protect endpoints and roles):

curl -X POST http://localhost:5101/auth/login -H "Content-Type: application/json" -d '{"userName":"bob","password":"guess"}'

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

The first command answers 401, the second pair answers with the report. Now look at the first terminal. Under the start-up lines, this is everything the API wrote:

warn: Microsoft.AspNetCore.HttpsPolicy.HttpsRedirectionMiddleware[3]
      Failed to determine the https port for redirect.
info: Microsoft.EntityFrameworkCore.Database.Command[20101]
      Executed DbCommand (18ms) [Parameters=[], CommandType='Text', CommandTimeout='30']
      SELECT "b"."Category", COUNT(*), COALESCE(SUM("b"."Stock"), 0), COALESCE(ef_sum(ef_multiply("b"."Price", CAST("b"."Stock" AS TEXT))), '0.0')
      FROM "Books" AS "b"
      GROUP BY "b"."Category"
      ORDER BY "b"."Category"

(The first warning appears because we start with http only and not https. Ignore it. Your SQL line may show a different time in milliseconds.)

The diary has the SQL that the report sent to the database, and nothing else. It says nothing about bob's failed login, nothing about alice logging in, nothing about who looked at the report. The framework wrote what it thinks is worth knowing. The things we care about, we have to write ourselves.

Write our own lines

Writing a line needs a logger: an object whose job is to take a message and put it in the diary. ASP.NET has one ready, ILogger<T>, and hands it to any class that asks for it through the constructor. That is the dependency injection from dependency injection basics again: the global handler already took an ILogger<GlobalExceptionHandler> the same way. The <T> is the class that is writing. It becomes the name on each line, so you can tell who wrote it.

Open src/BookShop.Api/Controllers/AuthController.cs. The whole file is:

using Microsoft.AspNetCore.Mvc;

[ApiController]
[Route("auth")]
public class AuthController : ControllerBase
{
    private readonly IUserService _userService;
    private readonly TokenService _tokenService;
    private readonly ILogger<AuthController> _logger;                                   // new

    public AuthController(IUserService userService, TokenService tokenService,
        ILogger<AuthController> logger)                                                 // new
    {
        _userService = userService;
        _tokenService = tokenService;
        _logger = logger;                                                               // new
    }

    [HttpPost("login")]
    [ProducesResponseType<LoginResponse>(StatusCodes.Status200OK)]
    [ProducesResponseType(StatusCodes.Status400BadRequest)]
    [ProducesResponseType(StatusCodes.Status401Unauthorized)]
    public ActionResult<LoginResponse> Login(LoginRequest request)
    {
        var user = _userService.FindUser(request.UserName, request.Password);
        if (user == null)
        {
            _logger.LogWarning("Failed login for {UserName}", request.UserName);        // new
            return Problem(
                statusCode: StatusCodes.Status401Unauthorized,
                title: "Wrong user name or password.");
        }

        _logger.LogInformation("{UserName} logged in as {Role}", user.UserName, user.Role);   // new
        var token = _tokenService.CreateToken(user);
        return new LoginResponse(token, user.Role);
    }
}

Three new things:

• The field and the constructor parameter bring the logger in, like the other two services.
• LogWarning writes a line at the Warning level, for something that is not an error but someone may want to see. A wrong password is that: an ordinary outcome, and a pile of them in a short time could be somebody guessing.
• LogInformation writes a line at the Information level, for a normal event worth remembering.

The text has holes in it: {UserName} and {Role}. Each hole is filled by the value after the text, in order. Why not write the value into the text ourselves? That comes in its own section below.

⚠️ Never put a password or a token in a log line. A log is read by more people than the data is, and it is often kept for months. Our lines hold the user name and the role, nothing that can open a door.

Now the report. Open src/BookShop.Api/Controllers/ReportsController.cs. The whole file is:

using BookShop.Data;
using Microsoft.AspNetCore.Authorization;
using Microsoft.AspNetCore.Mvc;

[Authorize(Roles = "Manager")]
[ApiController]
[Route("reports")]
public class ReportsController : ControllerBase
{
    private readonly IStockReportService _reportService;
    private readonly ILogger<ReportsController> _logger;                                // new

    public ReportsController(IStockReportService reportService,
        ILogger<ReportsController> logger)                                              // new
    {
        _reportService = reportService;
        _logger = logger;                                                               // new
    }

    [HttpGet("stock")]
    public async Task<ActionResult<List<CategoryStock>>> GetStock()
    {
        _logger.LogInformation("Stock report viewed by {UserName}",
            User.FindFirst("name")?.Value);                                             // new
        var report = await _reportService.GetByCategoryAsync();
        return report;
    }
}

User is the person the request came from, which the authentication step filled in from the token (protect endpoints and roles). FindFirst("name") takes the claim called name that the token service put in, and ?.Value is its text. (The shorter User.Identity?.Name prints nothing here. We tried it: .NET looks for a claim with a long web-address name, and ours is called name.)

Stop the API (Ctrl+C), start it again, and repeat the same three requests. The diary now reads:

2026-10-31 18:29:37 warn: AuthController[0]
      Failed login for bob
2026-10-31 18:29:37 info: AuthController[0]
      alice logged in as Manager
2026-10-31 18:29:38 info: ReportsController[0]
      Stock report viewed by alice

That is the Friday-evening answer. (The date and time at the front come from a setting we add two sections down; yours will show your own clock. Without it, the lines have no time, and a diary without times is much less useful. Also, your first run will still show the framework's lines around these three. We deal with them next.)

Levels: how serious is this line?

Every line has a level: a word for how serious it is. There are six, from chattiest to most serious:

Why have levels at all, and not one kind of line? Because the same program is read in two moods. When you are building it, you want every detail. On the live server on a quiet Tuesday, you want a short list, and you want it to say loudly when something is wrong. Levels let one program serve both: the code writes every line it might ever need, and a setting decides which of them reach the diary.

That setting is a threshold: the lowest level that is let through. Everything at that level or above is written; everything below is dropped.

The words Information and Warning are choices you make for each line, and teams argue about them. A fair rule for a beginner: if you would want to read it on the day something goes wrong, make it Information; if it is a sign that something may be wrong, Warning; if a request failed, Error.

Turn the noise down

Where does the threshold live? In the Logging section of appsettings.json, the file the project template made. It is already there, with two lines:

"Logging": {
  "LogLevel": {
    "Default": "Information",
    "Microsoft.AspNetCore": "Warning"
  }
}

Read it as a rule list. Default is the threshold for everything. Microsoft.AspNetCore is an exception: lines written by code whose name starts with that (the framework's web part) must be Warning or above. That name is the category you saw in the diary: AuthController, Microsoft.Hosting.Lifetime. A category is the <T> of the logger. The longest matching rule wins, so you can quieten one noisy part and keep the rest chatty.

Which part is noisy now? The SQL that EF Core writes for every query, from the category Microsoft.EntityFrameworkCore. It is useful when you are learning, and a drowning sound on a busy server. Add a rule for it. While we are in the file, add the time to each line. Open src/BookShop.Api/appsettings.json. The whole file is:

{
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Microsoft.AspNetCore": "Warning",
      "Microsoft.EntityFrameworkCore": "Warning"
    },
    "Console": {
      "FormatterName": "simple",
      "FormatterOptions": {
        "TimestampFormat": "yyyy-MM-dd HH:mm:ss "
      }
    }
  },
  "AllowedHosts": "*",
  "ConnectionStrings": {
    "BookShop": "Data Source=bookshop.db"
  },
  "Jwt": {
    "Issuer": "BookShop.Api",
    "Audience": "BookShop",
    "MinutesValid": 60
  }
}

(JSON has no comments, so the marks for new lines are left off. The new lines are the Microsoft.EntityFrameworkCore rule, with the comma on the line above it, and the whole Console block with the comma before it.)

• "Microsoft.EntityFrameworkCore": "Warning" drops the SQL lines. Errors from EF Core still get through, as the next lesson shows.
• Console configures the console logger, the part that prints to the terminal. "FormatterName": "simple" picks the usual look, and has to be written for the options under it to apply. TimestampFormat puts the date and time in front of each line. The time is your machine's. A server would normally log in UTC so that logs from several machines line up ("UseUtcTimestamp": true does that).

Restart and repeat the three requests. The framework's SQL line is gone, and ours stay.

The file that wins

Now try the threshold. Change "Default": "Information" to "Default": "Warning" in appsettings.json, restart, and repeat the requests. Nothing changes: alice's login line is still there.

That is not a mistake in the setting. There are two settings files, and the second one wins. Creating the solution made appsettings.Development.json, and ASP.NET reads it after appsettings.json, only when the app runs in the Development environment. It has its own Logging section, with "Default": "Information", and that replaces yours.

So the threshold for your machine is changed in the Development file, and the one for the live server in appsettings.json. That is a useful split: chatty while building, quiet in production. Put appsettings.json back to "Default": "Information", then open src/BookShop.Api/appsettings.Development.json and change its Default to Warning. The whole file is:

{
  "Logging": {
    "LogLevel": {
      "Default": "Warning",
      "Microsoft.AspNetCore": "Warning"
    }
  },
  "Jwt": {
    "Key": "development-only-key-replace-me-at-least-32-bytes"
  }
}

Restart and repeat the requests. Now only warnings and worse get through:

2026-10-31 18:28:39 warn: Microsoft.AspNetCore.HttpsPolicy.HttpsRedirectionMiddleware[3]
      Failed to determine the https port for redirect.
2026-10-31 18:28:39 warn: AuthController[0]
      Failed login for bob

The failed login is still there, because it is a Warning. alice's login and the report view, both Information, are dropped. Even the "Application started" line is gone, because it is Information too. That is the quiet mood.

Put "Default" back to "Information" in the Development file, so the rest of the course keeps seeing the lines we added.

Why {UserName} and not the name itself

There is a tempting way to write the failed-login line:

_logger.LogWarning($"Failed login for {request.UserName}");

The $ string puts the name into the text before the logger ever sees it. The diary looks the same: Failed login for bob. So why does the course use the version with the hole?

Because the hole keeps the value as a separate named piece. Ask the console to print each line as JSON instead of text (a temporary change, shown only to look inside; one setting, "FormatterName": "json" in the Console block). The same request now writes this, on one line (we split it here to read it):

{
  "EventId": 0,
  "LogLevel": "Warning",
  "Category": "AuthController",
  "Message": "Failed login for bob",
  "State": {
    "UserName": "bob",
    "{OriginalFormat}": "Failed login for {UserName}"
  }
}

The line carries UserName as its own field, and the template Failed login for {UserName} is kept as well. A tool that collects logs can then answer "show me every failed login for bob" by looking at the field, or "how many failed logins per user today" by counting. With the $ string, all it has is the text Failed login for bob, and it must guess where the name starts. A log with named pieces is called structured. It costs nothing extra to write, so it is the habit to have from the first line.

Remove the JSON setting again if you tried it. The lessons that follow read the text form.

The tests

The new constructor parameters break the tests that build these two controllers. Run them:

dotnet test

The build stops with errors like CS7036: There is no argument given that corresponds to the required parameter 'logger' for new AuthController(...) and new ReportsController(...). The tests must hand over a logger. They already have one: the hand-written FakeLogger<T> from errors the professional way, which writes every level it receives into a list. So the fix is also a chance to test the new promise: a failed login is logged as a warning.

Open tests/BookShop.Api.Tests/AuthControllerTests.cs. The whole file is:

using Microsoft.AspNetCore.Mvc;
using Microsoft.Extensions.Logging;                                                     // new

namespace BookShop.Api.Tests;

[TestClass]
public class AuthControllerTests
{
    private FakeLogger<AuthController> _logger = null!;                                 // new
    private AuthController _controller = null!;

    [TestInitialize]
    public void Setup()
    {
        var settings = new JwtSettings
        {
            Issuer = "BookShop.Api",
            Audience = "BookShop",
            Key = "a-test-key-that-is-long-enough-for-hs256",
            MinutesValid = 60
        };
        _logger = new FakeLogger<AuthController>();                                     // new
        _controller = new AuthController(new DemoUserService(), new TokenService(settings), _logger);   // new
    }

    [TestMethod]
    public void Login_RightPassword_ReturnsATokenAndTheRole()
    {
        var result = _controller.Login(new LoginRequest("alice", "alice-pass-1"));

        Assert.IsNotNull(result.Value);
        Assert.IsFalse(string.IsNullOrEmpty(result.Value.Token));
        Assert.AreEqual("Manager", result.Value.Role);
    }

    [TestMethod]
    public void Login_WrongPassword_Returns401()
    {
        var result = _controller.Login(new LoginRequest("alice", "guess"));

        var answer = result.Result as ObjectResult;
        Assert.IsNotNull(answer);
        Assert.AreEqual(401, answer.StatusCode);
    }

    [TestMethod]                                                                        // new
    public void Login_WrongPassword_LogsAWarning()                                      // new
    {                                                                                   // new
        _controller.Login(new LoginRequest("alice", "guess"));                          // new
                                                                                        // new
        Assert.HasCount(1, _logger.Levels);                                             // new
        Assert.AreEqual(LogLevel.Warning, _logger.Levels[0]);                           // new
    }                                                                                   // new
}

The new test checks the level and not the words. The words may be improved one day; "a failed login is a warning" is the promise.

The report controller test needs a second step, and this one we met by running it. Give ReportsControllerTests only the logger and the two older tests fail, with NullReferenceException inside GetStock. The reason: the new line reads User, and in a test nobody is logged in, because no request was ever made. The controller has no HttpContext, so User does not exist. The test has to supply a pretend request with a pretend user. ASP.NET has a ready-made one for tests, DefaultHttpContext, the same class the handler tests used.

Open tests/BookShop.Api.Tests/ReportsControllerTests.cs. The whole file is:

using System.Security.Claims;                                                           // new
using BookShop.Data;
using Microsoft.AspNetCore.Http;                                                        // new
using Microsoft.AspNetCore.Mvc;                                                         // new
using Microsoft.Extensions.Logging;                                                     // new

namespace BookShop.Api.Tests;

[TestClass]
public class ReportsControllerTests
{
    private FakeStockReportService _fakeService = null!;
    private FakeLogger<ReportsController> _logger = null!;                              // new
    private ReportsController _controller = null!;

    [TestInitialize]
    public void Setup()
    {
        _fakeService = new FakeStockReportService();
        _logger = new FakeLogger<ReportsController>();                                  // new
        _controller = new ReportsController(_fakeService, _logger)                      // new
        {                                                                               // new
            ControllerContext = new ControllerContext                                   // new
            {                                                                           // new
                HttpContext = new DefaultHttpContext                                    // new
                {                                                                       // new
                    User = new ClaimsPrincipal(new ClaimsIdentity([new Claim("name", "alice")]))   // new
                }                                                                       // new
            }                                                                           // new
        };                                                                              // new
    }

    [TestMethod]
    public async Task GetStock_TwoCategories_ReturnsBothLines()
    {
        _fakeService.Report.Add(new CategoryStock("Cooking", 2, 6, 181.00m));
        _fakeService.Report.Add(new CategoryStock("Programming", 3, 22, 852.30m));

        var result = await _controller.GetStock();

        Assert.IsNotNull(result.Value);
        Assert.HasCount(2, result.Value);
        Assert.AreEqual("Cooking", result.Value[0].Category);
        Assert.AreEqual(852.30m, result.Value[1].StockValue);
    }

    [TestMethod]
    public async Task GetStock_NoBooks_ReturnsAnEmptyList()
    {
        var result = await _controller.GetStock();

        Assert.IsNotNull(result.Value);
        Assert.IsEmpty(result.Value);
    }

    [TestMethod]                                                                        // new
    public async Task GetStock_AnyRequest_LogsThatTheReportWasViewed()                  // new
    {                                                                                   // new
        await _controller.GetStock();                                                   // new
                                                                                        // new
        Assert.HasCount(1, _logger.Levels);                                             // new
        Assert.AreEqual(LogLevel.Information, _logger.Levels[0]);                       // new
    }                                                                                   // new
}

The pretend user is a ClaimsPrincipal holding one claim, name, set to alice: the same shape the token gives a real request. Run the tests again:

dotnet test

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

Two new tests and every older one still green. (14 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. The point is none fail.)

Keep the diary in a file

So far the diary scrolls past in the terminal and is gone when the window closes. A diary must be kept. The simplest way needs no new code. The program writes to the console, and the shell can copy everything it prints into a file. Stop the API and start it like this:

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

tee is a small program that passes its input on to the screen and also writes it to a file, like a T-shaped pipe. 2>&1 makes the error messages travel the same road. (In PowerShell: dotnet run --project src/BookShop.Api 2>&1 | Tee-Object app.log.) Repeat the three requests, stop the API, and open app.log in an editor. It holds the same lines the screen showed. A text file can be searched. To see only the lines from the login code and the line under each:

grep -A1 AuthController app.log

2026-10-31 18:29:37 warn: AuthController[0]
      Failed login for bob
2026-10-31 18:29:37 info: AuthController[0]
      alice logged in as Manager

grep finds the lines that contain a word, and -A1 adds the one line after each. (Windows PowerShell: Select-String -Context 0,1 AuthController app.log.) This is also the file that the next lesson searches.

That is fine on your machine. On a live server nobody types tee. Real teams choose one of these, and which one depends on where the app runs:

• The host keeps the console output. Most places that run a server (a container platform, a service manager, a hosting company's panel) already capture what a program prints and keep it. Then the console logger we use is all the app needs. This is the common case.
• A logging library writes the files. .NET has no built-in file logger. The well-known library is Serilog, which plugs in as a package and can write files, start a new one each day and drop the old ones. Use it when the host does not keep the output for you.
• A log service collects them. When there are several servers, someone wants one place to search them all. Services exist for that, and the app is set up to send its lines there.

We name them and build none: the step from "lines in the console" to any of them is a package and a few lines in Program.cs, and the lines we write in the code do not change.

Where we ended

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

BookShop/
  src/
    BookShop.Api/
      appsettings.json                      EF Core rule at Warning, console format with date and time
      Controllers/
        AuthController.cs                   logs failed and successful logins
        ReportsController.cs                logs who viewed the report
  tests/
    BookShop.Api.Tests/
      AuthControllerTests.cs                passes a FakeLogger, one new test
      ReportsControllerTests.cs             pretend user and FakeLogger, one new test

Recap

• A log is the program's diary, one line per event, with the time. It is for the team, never for the user.
• A live server needs one because the program cannot be watched all day. Without it, a question about last Tuesday gets "I don't know".
• ASP.NET gives every class a logger, ILogger<T>, through the constructor. The <T> becomes the category on each line.
• Every line has a level: Trace, Debug, Information, Warning, Error, Critical. A threshold in appsettings.json drops every level below it.
• The Logging section sets the threshold for everything (Default) and for any category. appsettings.Development.json is read second in Development, so it wins there.
• Write "{UserName}" holes and pass the value separately. The value stays a named field that tools can search, which a $"..." string loses.
• Never log a password, a token or any secret.
• The console is the default place. tee keeps it in a file; libraries such as Serilog and log services are the next step, left for when the app needs them.

Questions to think about

Try to answer each one before you open the answer.

1. Why does a live server need a log?

2. Why does every log line have a level?

3. You set Default to Warning in appsettings.json, and the Information lines still appear on your machine. Why?

4. Why write "Failed login for {UserName}" and pass the name, instead of putting the name into the text?

5. The report is only for managers. How would you find out who looked at it last week?

Next lesson: the trace id, a short code in every error that lets you find one person's problem in a log of thousands of lines.