What to Log and What Not To: A Logging Strategy for .NET and the Anatomy of a Good Log Event

Version note: The code in this post was built and run with .NET 10.

Guess First

An order hits the Bookstore order endpoint asking for 3 copies of a book that has only 1 left in stock. The service catches the exception, logs it with LogError and rethrows it with throw;. The app also has a global exception handler. How many fail lines do you see in the log for this one failed request? And one more: on a machine with Turkish regional settings, how does logger.LogInformation($"Order {order.Id} created, total {order.Total}") write the total of a 91-lira order?

Both answers are in the middle of this post, with real output. First, let's step back and look at what a log is written for.

Who Reads the Log?

In the ASP.NET Core Web API (Application Programming Interface) series post "Logging in ASP.NET Core: ILogger, Log Levels, Structured Logging and Serilog" we set up ILogger<T>, categories, log levels, appsettings filters and message templates. This series builds on that foundation; I won't explain the mechanics again. This post asks a different question: what should you write with those mechanics?

A log line has three distinct readers, and each one is looking for something else:

• The developer (debugging): "Why was this order rejected, which book, how many copies were requested?" Wants detail, but only for the failing request.
• Operations (incidents): when the alert fires at 03:00, asks "how many orders failed payment in the last 15 minutes, all from the same gateway?" Wants fields that can be counted and filtered.
• Security (audit): "Who did what on this customer's account, and when?" Wants a complete, unchanging record; does not want to see a password or a card number.

If you ask "who will read this, and with what question?" while writing a log line, most of the unnecessary lines disappear on their own. None of these three readers wants an "Entering method X" line.

The log isn't the only tool either. Observability is made of three signals, and each answers a different question. A metric aggregates numbers over time: "how many orders per minute, what's the p99 duration in milliseconds?" It's cheap, because it stores aggregates, not individual events. A trace shows a single request's journey across services and how long each step took. A log tells the details of a single event: which customer, which book, what reason. If you're trying to answer "how many orders came in per minute?" by counting log lines, you're using the wrong tool; that's a metric. We leave metric and trace design to the upcoming DevOps › Observability series; this series stays on the log side.

Anatomy of Bad Log Lines

Let's start with a service I often see in real projects. It compiles, it runs, it even logs:

public sealed class BadOrderService(ILogger<BadOrderService> logger, Inventory inventory, PaymentGateway payments)
{
    public async Task<Order> PlaceOrderAsync(PlaceOrderRequest request, string cardLast4)
    {
        logger.LogInformation("Entering PlaceOrderAsync");
        logger.LogInformation($"Placing order for customer {request.CustomerId} with {request.Lines.Count} lines");
        try
        {
            foreach (OrderLine line in request.Lines)
            {
                inventory.Reserve(line.Isbn, line.Quantity);
            }

            decimal total = request.Lines.Sum(l => l.Quantity * l.UnitPrice);
            await payments.ChargeAsync(request.CustomerId, total, cardLast4);
            Order order = new(Guid.CreateVersion7(), request.CustomerId, total);

            logger.LogInformation($"Order {order.Id} created, total {order.Total}");
            logger.LogInformation("Exiting PlaceOrderAsync");
            return order;
        }
        catch (Exception ex)
        {
            logger.LogError(ex, $"Error: {ex.Message}");
            throw;
        }
    }
}

The four lines that reach the console for a successful order:

info: Bookstore.Orders.BadOrderService[0]
      Entering PlaceOrderAsync
info: Bookstore.Orders.BadOrderService[0]
      Placing order for customer 42 with 1 lines
info: Bookstore.Orders.BadOrderService[0]
      Order 01a1b8de-2cde-7e83-8821-26cda3b00925 created, total 91,0
info: Bookstore.Orders.BadOrderService[0]
      Exiting PlaceOrderAsync

Each of the five log calls has its own problem. The "Entering" and "Exiting" lines carry no information; the next line already proves the method was called. That's a trace's job, and in production it means two extra lines, double the storage, for every order. "Placing order" and "Order created" are the two ends of the same event; the first is redundant. The [0] in square brackets is the EventId: no line has an identity, so "give me all order-created events" can only be answered with text search. The sneakiest one is 91,0: interpolation formats the string with the current culture, and because the machine is Turkish, the decimal separator became a comma. The same code writes 91.0 in an English-locale container, and you can no longer search the logs of both environments with one query.

A Good Log Event: Constant Template, Meaningful Properties, EventId

Let's reduce the same flow to three events. Each event has a fixed identity, a fixed message template and queryable properties:

public sealed class OrderService(ILogger<OrderService> logger, Inventory inventory, PaymentGateway payments)
{
    private static readonly EventId OrderPlaced = new(1001, nameof(OrderPlaced));
    private static readonly EventId OrderRejected = new(1002, nameof(OrderRejected));
    private static readonly EventId PaymentRetried = new(1003, nameof(PaymentRetried));

    public async Task<Order?> PlaceOrderAsync(PlaceOrderRequest request, string cardLast4)
    {
        try
        {
            foreach (OrderLine line in request.Lines)
            {
                inventory.Reserve(line.Isbn, line.Quantity);
            }
        }
        catch (OutOfStockException ex)
        {
            // expected business outcome: Information, no stack trace, caller gets 409
            logger.LogInformation(OrderRejected,
                "Order rejected for customer {CustomerId}: {RejectReason} on {Isbn} (requested {Requested}, available {Available})",
                request.CustomerId, "OutOfStock", ex.Isbn, ex.Requested, ex.Available);
            return null;
        }

        decimal total = request.Lines.Sum(l => l.Quantity * l.UnitPrice);
        int attempts = await payments.ChargeAsync(request.CustomerId, total, cardLast4);
        if (attempts > 1)
        {
            // recovered on its own: Warning
            logger.LogWarning(PaymentRetried,
                "Payment for customer {CustomerId} succeeded after {PaymentAttempts} attempts",
                request.CustomerId, attempts);
        }

        Order order = new(Guid.CreateVersion7(), request.CustomerId, total);
        logger.LogInformation(OrderPlaced,
            "Order {OrderId} placed for customer {CustomerId}: {LineCount} lines, total {OrderTotal}",
            order.Id, order.CustomerId, request.Lines.Count, order.Total);
        return order;
    }
}

To see the value of a structured log, I ran the console with the JSON (JavaScript Object Notation) formatter (--Logging:Console:FormatterName=json). The real output of two successful orders and one stock rejection:

{"EventId":1001,"LogLevel":"Information","Category":"Bookstore.Orders.OrderService","Message":"Order 01a1b8de-8d15-7651-b472-6d4f3064e0f6 placed for customer 42: 1 lines, total 91.0","State":{"OrderId":"01a1b8de-8d15-7651-b472-6d4f3064e0f6","CustomerId":42,"LineCount":1,"OrderTotal":91.0,"{OriginalFormat}":"Order {OrderId} placed for customer {CustomerId}: {LineCount} lines, total {OrderTotal}"}}
{"EventId":1003,"LogLevel":"Warning","Category":"Bookstore.Orders.OrderService","Message":"Payment for customer 42 succeeded after 2 attempts","State":{"CustomerId":42,"PaymentAttempts":2,"{OriginalFormat}":"Payment for customer {CustomerId} succeeded after {PaymentAttempts} attempts"}}
{"EventId":1001,"LogLevel":"Information","Category":"Bookstore.Orders.OrderService","Message":"Order 01a1b8de-8d20-7a0a-98b7-bf4909171000 placed for customer 42: 1 lines, total 91.0","State":{"OrderId":"01a1b8de-8d20-7a0a-98b7-bf4909171000","CustomerId":42,"LineCount":1,"OrderTotal":91.0,"{OriginalFormat}":"Order {OrderId} placed for customer {CustomerId}: {LineCount} lines, total {OrderTotal}"}}
{"EventId":1002,"LogLevel":"Information","Category":"Bookstore.Orders.OrderService","Message":"Order rejected for customer 42: OutOfStock on 978-0321125217 (requested 3, available 1)","State":{"CustomerId":42,"RejectReason":"OutOfStock","Isbn":"978-0321125217","Requested":3,"Available":1,"{OriginalFormat}":"Order rejected for customer {CustomerId}: {RejectReason} on {Isbn} (requested {Requested}, available {Available})"}}

Four things to notice. First, every placeholder in State is a separate property: in Seq, Elasticsearch or any other log tool you can query CustomerId = 42 or OrderTotal > 500. Second, {OriginalFormat} is identical for every order; that's the key for grouping "events of the same kind". Third, on the same Turkish machine OrderTotal is now 91.0: message template formatting doesn't depend on the culture. Fourth, the EventId is now 1001, 1002, 1003; even if you change the template text, the event's identity stays the same.

Property names are a contract too. If you write CustomerId in one place, customerId in another and UserId in a third, the query "all logs for this customer" has to look at three different fields. Keep a shared vocabulary in the team: OrderId, CustomerId, Isbn spelled the same everywhere. In the next post we'll turn this vocabulary into an event catalog.

The practical meaning of "one event = one occurrence" is this: when someone reads a log line, the answer to "what happened?" should be one sentence. "Order placed" is an event. "Entering method" isn't an event, it's a code location.

Which Level for What?

We saw the definitions of the levels in the Web API series. Here let's look at the decision itself, because a wrong level means both noise and missed alerts:

The most common mistake is logging a business rule violation as Error. Insufficient stock isn't an error; it's a situation the app expects and answers with a 409. If you make it Error, the error-rate alert fires on every campaign day, and after a while the team starts ignoring the alert. Ask yourself: "Should this line wake someone up at 03:00?" If the answer is no, it's not an Error.

The boundary of Warning matters too. A payment succeeding on the second attempt isn't a problem by itself, but if the rate goes up, something is getting worse at the gateway. Warning means "no action needed now, but look if the count grows".

Log an Exception Once

Back to the first question. When I send an out-of-stock order to BadOrderService, this is what reaches the console (paths shortened with PathMap):

info: Bookstore.Orders.BadOrderService[0]
      Entering PlaceOrderAsync
info: Bookstore.Orders.BadOrderService[0]
      Placing order for customer 42 with 1 lines
fail: Bookstore.Orders.BadOrderService[0]
      Error: Not enough stock for 978-0321125217: requested 3, available 1
      Bookstore.Orders.OutOfStockException: Not enough stock for 978-0321125217: requested 3, available 1
         at Bookstore.Orders.Inventory.Reserve(String isbn, Int32 quantity) in /src/Bookstore.Orders/Domain.cs:line 32
         at Bookstore.Orders.BadOrderService.PlaceOrderAsync(PlaceOrderRequest request, String cardLast4) in /src/Bookstore.Orders/BadOrderService.cs:line 13
fail: Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware[1]
      An unhandled exception has occurred while executing the request.
      Bookstore.Orders.OutOfStockException: Not enough stock for 978-0321125217: requested 3, available 1
         at Bookstore.Orders.Inventory.Reserve(String isbn, Int32 quantity) in /src/Bookstore.Orders/Domain.cs:line 32
         at Bookstore.Orders.BadOrderService.PlaceOrderAsync(PlaceOrderRequest request, String cardLast4) in /src/Bookstore.Orders/BadOrderService.cs:line 13
         at Program.<>c.<<<Main>$>b__0_0>d.MoveNext() in /src/Bookstore.Orders/Program.cs:line 14

The answer is two: two fail lines and two stack traces for a single failed request. The number grows with the number of layers; if the repository, the service and the controller each do "log and throw", one error shows up four times in the log. The error-rate dashboard shows four times the truth, the alert threshold becomes meaningless, and during an incident you waste time on "are these four errors or one?". On top of that, the real issue in this example isn't an Error at all: insufficient stock should have been answered with 409, not 500.

The rule is simple: either log an exception and handle it there, or throw it without logging and log it in a single place at the top. The global handler we built in the Web API series post "Global Error Handling: Exception Middleware and ProblemDetails" is that single place. When the payment gateway fails in OrderService, the service logs nothing and lets the exception bubble up:

fail: Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware[1]
      An unhandled exception has occurred while executing the request.
      Bookstore.Orders.PaymentGatewayException: Payment gateway timed out after 3 attempts
         at Bookstore.Orders.PaymentGateway.ChargeAsync(Int32 customerId, Decimal amount, String cardLast4) in /src/Bookstore.Orders/Domain.cs:line 47
         at Bookstore.Orders.OrderService.PlaceOrderAsync(PlaceOrderRequest request, String cardLast4) in /src/Bookstore.Orders/OrderService.cs:line 28
         at Program.<>c.<<<Main>$>b__0_1>d.MoveNext() in /src/Bookstore.Orders/Program.cs:line 17

One line, one stack trace. What about context, though; whose payment failed? We solve that not by logging the exception again, but with a scope or a trace id attached to every log of the request. We'll build the full version in this series' "Correlation IDs and Trace Context" post.

There's one exception: if you catch and handle the exception, meaning you don't rethrow, logging at that point is right. OrderService does exactly that when it catches OutOfStockException and returns 409, and it does so without a stack trace, because the stack trace of an expected situation tells nobody anything.

String Interpolation and CA2254

When you write $"Order {order.Id} created", the compiler builds the string first, and the logger receives finished text. Since the template is different for every order, grouping becomes impossible and the properties are lost. Here's the counterpart in the JSON output of the bad service above:

{"EventId":0,"LogLevel":"Information","Category":"Bookstore.Orders.BadOrderService","Message":"Order 01a1b8de-8d2c-7918-a521-d500730598b6 created, total 91,0","State":{"{OriginalFormat}":"Order 01a1b8de-8d2c-7918-a521-d500730598b6 created, total 91,0"}}

There's no OrderId in State, and {OriginalFormat} is a different text for every order. This line kills every benefit of structured logging.

The analyzer rule that catches it is CA2254 ("Template should be a static expression"). In .NET 10 it's enabled by default only as a suggestion, so it doesn't show up in a command-line build. I put an .editorconfig in the project root to raise its severity, and add CA1848 and CA1873 next to it:

root = true
[*.cs]
dotnet_diagnostic.CA2254.severity = warning
dotnet_diagnostic.CA1848.severity = warning
dotnet_diagnostic.CA1873.severity = warning

The three warnings for line 8 of BadOrderService in the dotnet build output:

BadOrderService.cs(8,9): warning CA1848: For improved performance, use the LoggerMessage delegates instead of calling 'LoggerExtensions.LogInformation(ILogger, string?, params object?[])' (https://learn.microsoft.com/dotnet/fundamentals/code-analysis/quality-rules/ca1848)
BadOrderService.cs(8,31): warning CA1873: Evaluation of this argument may be expensive and unnecessary if logging is disabled (https://learn.microsoft.com/dotnet/fundamentals/code-analysis/quality-rules/ca1873)
BadOrderService.cs(8,31): warning CA2254: The logging message template should not vary between calls to 'LoggerExtensions.LogInformation(ILogger, string?, params object?[])' (https://learn.microsoft.com/dotnet/fundamentals/code-analysis/quality-rules/ca2254)

CA2254 shows up only on lines with interpolation or concatenation; it wasn't reported for OrderService at all. CA1848 and CA1873, however, were reported for OrderService too: both are about performance and say "use a source-generated LoggerMessage instead of the LogInformation extension method". Evaluating arguments, boxing and the params object[] allocation even when the level is off are the topic of the next post. So I recommend making at least CA2254 a warning in your team; consider CA1848 for code on hot paths.

In Production

Logs have a cost, and that cost is proportional to the number of lines. The bad service wrote four lines for every successful order; the good service writes one. At 200,000 orders a day, that's the difference between 800,000 and 200,000 lines; if your log tool charges by ingestion, it goes straight to the bill. We'll measure log volume and cost in detail in this series' "Log Levels and Cost" post.

EventId is the best tool for knowing how often each event is written. Run a "top 10 EventIds" query once a week; if you see an "Entering" or "Cache hit" line at the top of the list, it's time to lower its level.

Controlling what goes into the log is a responsibility too. Card numbers, passwords, tokens, national ID numbers and full addresses should never enter the log. Here we didn't even log cardLast4; it's enough to notice that the value answers none of the readers' questions. On the security side, what should be logged (failed logins, authorization denials, critical business operations) was covered in the post "OWASP A09: Security Logging and Alerting Failures" of the Web Security series built on the OWASP (Open Worldwide Application Security Project) Top 10; I won't repeat it here. The technical side of masking sensitive data, meaning redaction and data classification, is in the seventh post of this series.

Common Pitfalls

First, logging everything at Information. Without a level distinction there's no filter either; in production you see either everything or nothing. "Cache hit" and "Order placed" shouldn't be at the same level.

Second, burying the exception in the message: logger.LogError($"Error: {ex.Message}"). The stack trace is lost, and so is the exception type. Always pass the exception as the first argument: logger.LogError(ex, "Payment failed for order {OrderId}", orderId).

Third, using the same placeholder name with different meanings. If {Id} is the order id in one event and the customer id in another, your query results are meaningless. Instead of generic names (Id, Name, Value), use names that carry context, such as OrderId and CustomerId.

Fourth, logging the whole request object: logger.LogInformation("Request: {@Request}", request). The request has three fields today; tomorrow someone adds an email and a phone number, and you start logging personal data without noticing. Choose explicitly what you log.

Fifth, using logs for control flow. If a reporting job is built on "if this line is in the log, the order is complete", the business logic breaks when the log level changes. Logs are for observation; business data lives in the database.

A Small Experiment

★☆☆ Remove the Placing order line from the bad service, turn the Order created line into a message template and write OrderId and OrderTotal as properties. Verify in the JSON console output that State contains two properties and that the total is written with a dot.

★★☆ Add an OrderCancelled event (EventId 1004) to OrderService. Decide which level it should have and write down your reasoning. Should a cancellation by the customer and a cancellation by the system because of a payment timeout be at the same level?

★★★ Put a controller and a repository layer in front of BadOrderService; make every layer "log and throw". Count how many fail lines appear for an out-of-stock order. Then leave logging only to the global handler and compare the count again.

In this post we decided what to log. In the next one we'll talk about writing the same events cheaply: the LoggerMessage source generator, the IsEnabled check, the boxing and allocations that happen even when the level is off, differences measured with BenchmarkDotNet, and collecting this post's three events into a single event catalog.