Log Levels and Cost: Sampling, Buffering and Changing Log Levels Live in Production

Version note: The code in this post was built and run with .NET 10, Microsoft.Extensions.Telemetry 10.11, Microsoft.AspNetCore.Diagnostics.Middleware 10.11 and Serilog.AspNetCore 10.0.

Guess First

You add builder.Logging.AddTraceBasedSampler() to the Bookstore catalog API (Application Programming Interface). OpenTelemetry tracing isn't set up; there's only this one line. Then you send an ordinary request with no headers from the outside, and the request returns 503 because of a database timeout. Does the endpoint's LogError line reach the console?

Second question: you turn on sampling with a single rule, "Probability": 0.1, with neither a category nor a log level. 1000 requests produce 10 errors. How many Error lines do you see in the log?

Both answers are in the post, from real runs. Both are about losing the most valuable line while trying to make logging cheaper.

The Bill for Log Volume

The cost of logs has three parts. First, ingestion: most log tools charge for the amount of data they take in, or their license has a GB limit. Second, retention: keeping the same data for 30 or 90 days multiplies disk and bill directly. Third, querying: as volume grows, "errors in the last hour" gets slower, and every second you wait during an incident is expensive. On the application side, writing logs costs CPU (Central Processing Unit), memory and I/O (Input/Output).

Let's measure instead of guessing. In the sample app the /books/{id} endpoint writes two Debug lines and one Information line per request; every 50th book adds a Warning, every 100th book an Error:

public sealed class BookService(ILogger<BookService> logger)
{
    public Book GetBook(int id)
    {
        Log.CacheLookup(logger, id);
        Log.CacheMiss(logger, id);
        if (id % 100 == 0)
        {
            throw new TimeoutException($"Database query for book {id} timed out");
        }
        if (id % 50 == 0)
        {
            Log.PriceServiceSlow(logger, id, 1240);
        }
        Log.BookViewed(logger, id);
        return new Book(id, $"Book {id}", 30m + id % 7);
    }
}

The Log class is made of source-generated methods as in this series' "High-Performance Logging" post (EventIds 2001–2005). I started the app with the JSON (JavaScript Object Notation) console formatter under four level settings, sent 1000 requests each time and counted the output level by level:

dotnet Bookstore.Catalog.dll --Logging:Console:FormatterName=json \
    --Logging:LogLevel:Default=Debug --Logging:LogLevel:Microsoft.AspNetCore=Debug
./load.sh 17445 1000
python3 count.py vol2_A.log

There's a 25x difference between the first and the third row, and not a single line of code changed; only two configuration values did. For an API that receives 5 million requests a day, that's roughly the difference between 31 GB and 1.2 GB. To see where the bill comes from, I looked at the breakdown of the second row:

1000 ('Information', 'Microsoft.AspNetCore.Hosting.Diagnostics', 1)
1000 ('Information', 'Microsoft.AspNetCore.Routing.EndpointMiddleware', 0)
1000 ('Information', 'Microsoft.AspNetCore.Routing.EndpointMiddleware', 1)
1000 ('Information', 'Microsoft.AspNetCore.Hosting.Diagnostics', 2)
990 ('Information', 'Bookstore.Catalog.BookService', 2003)
990 ('Information', 'Microsoft.AspNetCore.Http.Result.OkObjectResult', 1)
990 ('Information', 'Microsoft.AspNetCore.Http.Result.OkObjectResult', 3)

Six of the seven Information lines per request come from the framework: "Request starting", "Executing endpoint", "Executed endpoint", "Request finished" and two lines about writing the result. Our business event, BookViewed, is one in seven. This table shows why the project template has the "Microsoft.AspNetCore": "Warning" line. If you still want a request summary, choose an alternative that writes one line per request: UseSerilogRequestLogging from this series' "Serilog in Depth" post, or CombineLogs from the post on logging HTTP (Hypertext Transfer Protocol) requests, "HTTP Logging".

In the Debug row, more than 10,000 of the 12,007 lines are Kestrel connection events and routing matches. That's where the bill for leaving Debug on "for a while" in production comes from.

Random Probabilistic Sampling

A filter either writes a log completely or not at all. Sampling lets you pick a rate in between: 10% of the BookViewed events is usually enough to see the trend. Sampling arrived during the .NET 9 timeframe with version 9.3 of the Microsoft.Extensions.Telemetry package. In the sample app I choose the demo modes from configuration:

WebApplicationBuilder builder = WebApplication.CreateBuilder(args);
string mode = builder.Configuration["Demo:Mode"] ?? "plain";

if (mode == "random")
{
    builder.Logging.AddRandomProbabilisticSampler(builder.Configuration);
}
else if (mode == "trace")
{
    builder.Logging.AddTraceBasedSampler();
}
else if (mode == "buffer")
{
    builder.Logging.AddPerIncomingRequestBuffer(builder.Configuration.GetSection("Logging"));
}

The rule lives in appsettings.json:

{
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Microsoft.AspNetCore": "Warning"
    }
  },
  "AllowedHosts": "*",
  "RandomProbabilisticSampler": {
    "Rules": [
      {
        "CategoryName": "Bookstore.Catalog",
        "LogLevel": "Information",
        "Probability": 0.1
      }
    ]
  }
}

The real result of 1000 requests:

Information      98 lines     24976 bytes
Warning          10 lines      3248 bytes
Error            10 lines      6563 bytes
Total           118 lines     34787 bytes

98 of the 990 BookViewed events were written; every Warning and Error line is still there. The rule's LogLevel field means "this level and below": because you wrote Information, Warning and Error fell outside the rule. If more than one rule matches a record, the longest category prefix wins, and on a tie the last rule in the list is chosen; if no rule matches, the record is written as usual.

I got stuck on one thing while writing this section. The "change at runtime" example on Microsoft Learn puts the RandomProbabilisticSampler section under the Logging section. I did that first and saw all 990 Information lines; the sampler never ran, and there was no error either. In version 10.11, AddRandomProbabilisticSampler(builder.Configuration) looks for the section at the root of the configuration. If you want to keep the section under Logging, pass builder.Configuration.GetSection("Logging") to the method. Because the configuration mistake is silent, I recommend counting once after you turn sampling on.

Trace-Based Sampling

Random sampling rolls a separate die for every log record. A request's BookViewed line can be written while the same request's Warning is dropped; you end up with half requests. The trace-based sampler leaves the decision not to the log record but to the current Activity: if the trace is being recorded (Activity.Recorded), all of the request's logs are written, otherwise none. That way you have logs and traces for the same requests.

Here is the answer to the first question. With AddTraceBasedSampler() on, I sent four requests: one with the sampled flag (-01) in the W3C (World Wide Web Consortium) traceparent header, one with the flag off (-00), and two without the header. The last one is book 100, which returns 503:

curl -H 'traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01' http://localhost:17445/books/7
curl -H 'traceparent: 00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-00' http://localhost:17445/books/8
curl http://localhost:17445/books/9
curl http://localhost:17445/books/100

The only line left from the requests in the console:

info: Bookstore.Catalog.BookService[2003]
      Book 7 viewed

The app's own startup logs (Microsoft.Hosting.Lifetime) were written, because they aren't inside an Activity. But for requests that arrive without the header, ASP.NET Core creates an Activity; since tracing isn't set up, nobody marks it as "to be recorded", and the sampler drops every log of that request. Book 100's Error line went too. So if your guess was "yes, errors are always written", the real answer is no. Turn on trace-based sampling only when OpenTelemetry tracing and its sampler are set up; the setup details are in the upcoming DevOps › Observability series, and traceparent itself is covered in this series' "Correlation IDs and Trace Context" post.

Buffering: Writing the History When Something Fails

Sampling's core problem is that it's blind: it can't know in advance which request will be interesting. Yet the Debug lines you need most are exactly the lines of the failing request. Buffering resolves this dilemma: keep logs in memory, drop them if the request succeeds, write them if it fails. Buffering arrived with version 9.5 of the same package family; the ASP.NET Core-specific, per-request version lives in the Microsoft.AspNetCore.Diagnostics.Middleware package.

The rules are in appsettings.Buffer.json:

{
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Bookstore.Catalog": "Debug",
      "Microsoft.AspNetCore": "Warning"
    },
    "PerIncomingRequestLogBuffering": {
      "AutoFlushDuration": "00:00:00",
      "Rules": [
        {
          "CategoryName": "Bookstore.Catalog",
          "LogLevel": "Debug"
        }
      ]
    }
  }
}

Two details matter. First, I lowered the filter level for Bookstore.Catalog to Debug: buffering runs after filtering, and you can't buffer a record the filter has already dropped. Second, the rule buffers Debug and below; Information and above are written immediately as usual. When the endpoint catches an error, it flushes the buffer:

app.MapGet("/books/{id:int}", (int id, BookService books, ILogger<Program> logger, IServiceProvider services) =>
{
    using IDisposable? scope = logger.BeginScope("Catalog request from {Channel}", "web");
    try
    {
        return Results.Ok(books.GetBook(id));
    }
    catch (TimeoutException ex)
    {
        Log.BookLoadFailed(logger, ex, id);
        // something failed: write this request's buffered Debug logs now
        services.GetService<PerRequestLogBuffer>()?.Flush();
        return Results.Problem(statusCode: 503);
    }
});

I resolve PerRequestLogBuffer with GetService because in the demo app the buffer is registered only in buffer mode; in a normal project you inject it directly as a parameter. The console for the successful book 7 and the failing book 100:

info: Bookstore.Catalog.BookService[2003]
      Book 7 viewed
fail: Program[2005]
      Failed to load book 100
      System.TimeoutException: Database query for book 100 timed out
         at Bookstore.Catalog.BookService.GetBook(Int32 id) in /src/Bookstore.Catalog/BookService.cs:line 13
         at Program.<>c.<<Main>$>b__0_0(Int32 id, BookService books, ILogger`1 logger, IServiceProvider services) in /src/Bookstore.Catalog/Program.cs:line 27
dbug: Bookstore.Catalog.BookService[2001]
      Cache lookup for book 100
dbug: Bookstore.Catalog.BookService[2002]
      Cache miss for book 100, loading from database

The successful request's two Debug lines were dropped with the buffer when the request ended. The failing request's lines were written after the Error. Watch the order: buffered records are written at flush time, and the documentation says the order isn't preserved, only the original timestamp is. In a later section we'll see that the timestamp has a surprise too.

For places without an HTTP request, such as a BackgroundService, the same package has a global version: register it with AddGlobalBuffer, inject GlobalLogBuffer and call Flush() when something fails. The global buffer is a ring buffer: when MaxBufferSizeInBytes is full, the oldest records are silently dropped. Flushing the per-request buffer also flushes the global buffer; a log outside a request goes to the global buffer even if it matches a per-request rule.

Changing the Level Without a Restart

While investigating a production issue, you want to turn on Debug for one category for ten minutes; that shouldn't require a deploy or a restart. Microsoft.Extensions.Logging watches appsettings.json changes by default (reloadOnChange). With the app running, I requested book 7, then added "Bookstore.Catalog": "Debug" to the file and requested book 8:

info: Bookstore.Catalog.BookService[2003]
      Book 7 viewed
dbug: Bookstore.Catalog.BookService[2001]
      Cache lookup for book 8
dbug: Bookstore.Catalog.BookService[2002]
      Cache miss for book 8, loading from database
info: Bookstore.Catalog.BookService[2003]
      Book 8 viewed

Sampling and buffering rules are read through IOptionsMonitor<T> too, so they change live the same way. I started the rule with Probability: 1, sent 500 requests, changed the value in the file to 0.1 and sent 500 more:

phase1 viewed=495
phase2 viewed=45

495 BookViewed events in the first 500 requests (five requests failed), 45 in the second 500. Here I edited the file by hand; in real life the value comes from a configuration provider that supports reload, such as Azure App Configuration. Don't forget that changing a file inside a container is rarely practical.

If you use Serilog, LoggingLevelSwitch does the same job. I register the switch as a singleton and change it from an admin endpoint:

LoggingLevelSwitch levelSwitch = new(LogEventLevel.Information);
builder.Services.AddSingleton(levelSwitch);
builder.Services.AddSerilog(lc => lc
    .MinimumLevel.ControlledBy(levelSwitch)
    .MinimumLevel.Override("Microsoft.AspNetCore", LogEventLevel.Warning)
    .WriteTo.Console());

// in a real project this endpoint must sit behind authorization
app.MapPut("/admin/log-level/{level}", (LogEventLevel level, LoggingLevelSwitch sw, ILogger<Program> logger) =>
{
    LogEventLevel previous = sw.MinimumLevel;
    sw.MinimumLevel = level;
    logger.LogWarning("Minimum log level changed from {PreviousLevel} to {NewLevel}", previous, level);
    return Results.Ok(new { previous, current = level });
});

First book 7, then the switch to Debug and book 8, then back to Information and book 9:

[05:06:40 INF] Book 7 viewed
[05:06:40 WRN] Minimum log level changed from Information to Debug
[05:06:40 DBG] Cache lookup for book 8
[05:06:40 DBG] Cache miss for book 8, loading from database
[05:06:40 INF] Book 8 viewed
[05:06:40 WRN] Minimum log level changed from Debug to Information
[05:06:40 INF] Book 9 viewed

I log the level change itself as a Warning, so the answer to "why did log volume triple after this time?" lives inside the log. The endpoint responds with {"previous":2,"current":1}; enums are serialized as numbers, and you may want strings in your own API. Don't ship this endpoint to production without putting it behind a policy, as in the ASP.NET Core Web API series post "Authorization: Roles, Policies and Resource-Based Authorization"; anyone who can change the log level can change your log volume, and therefore your bill.

In Production

Measure volume regularly by level and by EventId. Writing the counting script above in your log tool's query language is a five-minute job; we do it with group by in this series' "Reading Structured Logs with Seq" post. Choosing a sampling rate without knowing which event makes up half the bill is just guessing.

Microsoft's sampling guidance gives a clear recommendation per level: apply sampling to Information, consider it for Warning, never apply it to Error and Critical, and Debug and Trace should be off in production anyway. Always put a LogLevel, and a CategoryName where possible, in your rules.

Buffering isn't free: records stay in process memory until they're flushed. Don't rely on the default limits; set MaxBufferSizeInBytes and MaxLogRecordSizeInBytes by measuring under a load test. AutoFlushDuration sets how long buffering is suspended after a flush, meaning all logs are written immediately. I set it to zero for the demo; in a system where errors cluster, a value of a few seconds lets you see the logs that come right after the error too.

Give a live level change an end time. "I turned on Debug, I'll turn it off later" means a Debug that gets noticed on the bill three weeks later. Adding a duration parameter to the admin endpoint and a small timer that sets the switch back to its previous value when the time is up removes that risk.

Common Pitfalls

First, forgetting Debug on in production. As the table shows, the same traffic produces 25 times the volume, and most of it is framework lines nobody will read.

Second, writing the sampling rule too broadly. That was the second opening question: I sent 1000 requests with "Rules": [{ "Probability": 0.1 }].

Information     111 lines     28281 bytes
Error             4 lines      2627 bytes
Total           115 lines     30908 bytes

4 of the 10 Error lines and none of the 10 Warning lines survived. A rule without a level covers every level. Your error-rate alert now sees a tenth of the real rate, and nobody notices, because the numbers look "reasonable".

Third, assuming records that come from the buffer are the same as live records. I ran the buffering example again with the JSON formatter, IncludeScopes and a timestamp. The real lines (I shortened the stack trace in the first line to ...):

{"Timestamp":"05:05:39.797 ","EventId":2005,"LogLevel":"Error","Category":"Program","Message":"Failed to load book 100","Exception":"...","State":{"Message":"Microsoft.Extensions.Logging.ExtendedLogger+ModernTagJoiner","exception.type":"System.TimeoutException","BookId":100,"{OriginalFormat}":"Failed to load book {BookId}"},"Scopes":[{"Message":"SpanId:6b0f467e2ea05d1c, TraceId:a9d712d8bcf4c9352b882554c9618821, ParentId:0000000000000000","SpanId":"6b0f467e2ea05d1c","TraceId":"a9d712d8bcf4c9352b882554c9618821","ParentId":"0000000000000000"},{"Message":"ConnectionId:0HNPT7J4NSF9J","ConnectionId":"0HNPT7J4NSF9J"},{"Message":"RequestPath:/books/100 RequestId:0HNPT7J4NSF9J:00000001","RequestId":"0HNPT7J4NSF9J:00000001","RequestPath":"/books/100"},{"Message":"Catalog request from web","Channel":"web","{OriginalFormat}":"Catalog request from {Channel}"}]}
{"Timestamp":"02:05:39.796 ","EventId":2001,"LogLevel":"Debug","Category":"Bookstore.Catalog.BookService","Message":"Cache lookup for book 100","Exception":"","State":{"Message":null,"BookId":"100","{OriginalFormat}":"Cache lookup for book {BookId}"}}
{"Timestamp":"02:05:39.797 ","EventId":2002,"LogLevel":"Debug","Category":"Bookstore.Catalog.BookService","Message":"Cache miss for book 100, loading from database","Exception":"","State":{"Message":null,"BookId":"100","{OriginalFormat}":"Cache miss for book {BookId}, loading from database"}}

The live Error line has four scopes: TraceId, SpanId, RequestPath and our Channel. The two Debug lines from the buffer have no Scopes at all. The documentation says so explicitly: buffering doesn't support scopes, and ActivityTraceId and ActivitySpanId are always empty on flushed records. In practice this means the query "all logs for this TraceId" in your log tool won't return exactly the Debug lines you wanted to see. If you don't want to lose the context, put the TraceId or OrderId into the event's own parameters, not into a scope.

The same output has two more surprises. Timestamps: the live line shows local time 05:05:39.797, the buffered ones 02:05:39.796; the machine is in the UTC (Coordinated Universal Time) +3 time zone, so they're exactly three hours behind, meaning UTC was written. That happens even with UseUtcTimestamp off in the console formatter. Second, BookId is a number (100) in the live line and a string ("100") in the buffered ones: records are serialized when they enter the buffer. A numeric query such as BookId > 50 in your log tool can miss these lines.

Fourth, confusing the filter with the buffer. If the Default level is Information and you write a buffer rule for Debug, the buffer always stays empty, because the record is dropped by the filter before it reaches the buffer. If you flush and still see no Debug lines, check the filter level first.

A Small Experiment

★☆☆ Start the sample app with --Logging:LogLevel:Microsoft.AspNetCore=Information and send 100 requests. Calculate what percentage of the total bytes comes from framework lines.

★★☆ Split the sampling rule into two rules: 0.1 for the Information level of the Bookstore.Catalog category, 1.0 for everything else. Verify with 1000 requests that all Warning and Error lines are kept. Does the result change if you swap the order of the rules?

★★★ In the buffering example, add a traceId parameter to the Debug events in BookService (Activity.Current?.TraceId.ToString()). Show in the JSON output that the flushed lines now keep the trace information, and measure how many bytes it adds per log line.

With this post we've finished Block A, the core structure on .NET 10. In the last post we'll look back: what arrived on the logging side from .NET 8 to .NET 11, in which version enrichment, redaction, FakeLogger, buffering and generic LoggerMessage were added, and how to read an old project when you run into a Serilog 2/3-style Startup configuration.