Six Ways ILogger Silently Fails in Production

Six Ways ILogger Silently Fails in Production

I have spent half a day staring at a production incident wondering why I could not correlate any log entries across a single request. Everything looked fine. ILogger was there, BeginScope was called, the structured properties were in the templates. In development, the console showed exactly what I expected. In production: nothing. No correlation ID. No scope context. Just a flat stream of messages from parallel requests, interleaved, undifferentiated, useless.

The culprit was not a bug. It was me not understanding what ILogger actually is: a façade with a lot of opt-in behaviour that looks enabled by default.

That incident cost me half a day. I have seen variants of it in nearly every codebase I have worked in since. The patterns are always the same: a developer who trusts that logging works because it compiles, and finds out in production that it does not.

This is a tour of the ways ILogger lies to you, and by that I mean: the ways its defaults and abstractions let you believe things are working when they are not. These are not obscure edge cases. Most of them are the default configuration.

Lie 1: Your Log Message Is Evaluated Before the Level Check

This one is easy to miss because it never crashes. It just silently costs you.

_logger.LogDebug($"Processing order {order.Id} with {order.Items.Count} items totaling {order.Total:C}");

If Debug is filtered out (which it is, in every default production configuration), the string interpolation still runs. order.Items.Count is evaluated. The currency format is applied. Memory is allocated for the full interpolated string. Then the whole thing is thrown away.

You will not notice this until you profile something. And then you will find Debug-level log calls in your hot path costing you measurable throughput, silently, in production.

The fix is message templates, not because they are more readable, but because the parameters are not evaluated until after the level check:

_logger.LogDebug("Processing order {OrderId} with {ItemCount} items totaling {Total}", 
    order.Id, order.Items.Count, order.Total);

The structured fields are also preserved as separate properties rather than baked into a string, which matters for Lie 4.

For anything called frequently: LoggerMessage source generators. Zero allocation when filtered, correct property types, generated at compile time.

public static partial class LogMessages
{
    [LoggerMessage(Level = LogLevel.Debug, Message = "Processing order {OrderId} with {ItemCount} items totaling {Total}")]
    public static partial void ProcessingOrder(this ILogger logger, string orderId, int itemCount, decimal total);
}

This is what Microsoft.Extensions.Logging source generators exist for. If you are not using them in hot paths, you are paying for logging that is disabled.

Lie 2: Your Log Scopes Are Probably Not Appearing

This is the one that cost me half a day.

using (_logger.BeginScope("OrderId: {OrderId}", orderId))
{
    _logger.LogInformation("Starting payment processing");
    _logger.LogInformation("Sending confirmation email");
}

The premise is clean: every log call inside the using block carries OrderId. When you have hundreds of parallel requests hitting a service, this is how you keep them separate in your logs. Without it, you get an undifferentiated stream where tracing a single request means grepping for an ID you may or may not have logged consistently.

In development, the console shows the scope. You trust it. You ship it.

In production, BeginScope returns a disposable that does nothing. No error. No warning. The scope is dropped entirely.

The reason is that scope support is opt-in per provider. AddConsole() supports scopes but does not include them in output unless you enable it:

{
  "Logging": {
    "Console": {
      "IncludeScopes": true
    }
  }
}

And that is just the console. Every production sink (Application Insights, Seq, Elasticsearch) has its own scope configuration, its own opt-in. If your sink’s provider does not implement IExternalScopeConsumer, the SetScopeProvider call never happens, and every BeginScope you call is a no-op at the provider level.

I found this out by looking at the sink source code after half a day of adding increasingly desperate debug logging. The fix was one line in the sink configuration. The knowledge that I needed to add that line existed nowhere near the BeginScope documentation.

Before you depend on scope data for incident correlation: query your actual production logs for a scope property. Verify it is there as a separate field, not missing entirely.

Lie 3: Your Minimum Level Configuration Has Contradictions You Have Not Noticed

The default appsettings.json logging section looks sane enough:

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

The behavior is a longest-prefix match. Microsoft.Hosting.Lifetime beats Microsoft because it is more specific. The order inside the configuration object is irrelevant. Fine.

Now add Serilog (which most production .NET applications do at some point):

{
  "Serilog": {
    "MinimumLevel": {
      "Default": "Information",
      "Override": {
        "Microsoft": "Warning"
      }
    }
  }
}

You now have two independent filter systems. Both must pass. Your Microsoft.Hosting.Lifetime: Information override in Logging:LogLevel has no equivalent in Serilog, so Serilog’s Microsoft: Warning blocks it.

But here is the part that genuinely surprised me: when you use UseSerilog() in your host setup, the Logging section in appsettings.json is bypassed entirely. Serilog replaces the entire MEL provider. Your LogLevel configuration (the one you have been editing, the one that looks like it should be in charge) is not read at all. Only the Serilog section matters.

I have seen people spend significant time adjusting the Logging:LogLevel configuration in a codebase where UseSerilog() was in Program.cs. Every change had zero effect, and there was no indication why.

Pick one authoritative minimum level configuration and remove the other. Do not maintain both.

Lie 4: Your Structured Properties Are Not Structured

The whole point of ILogger with message templates, over plain Console.WriteLine, is that {OrderId} becomes a queryable property in your log aggregation system, not a substring buried in a flat string. That is the pitch for structured logging.

_logger.LogWarning("Payment failed for {CustomerId} with error {ErrorCode}", customerId, errorCode);

With a correctly configured structured sink, you can query ErrorCode == "INSUFFICIENT_FUNDS". That query is indexed. It is fast. It works across millions of entries.

With a plain text sink (or a structured sink with default formatting), you get "Payment failed for cust-123 with error INSUFFICIENT_FUNDS". That is a string. You search it with a substring match. Under load, across millions of entries, you wait.

Three things must all be true for structured properties to actually be structured:

  1. You use message templates, not string interpolation
  2. Your sink supports structured output
  3. Your sink is configured to output properties as separate fields

That third point is the one that bites you. Application Insights, by default, maps everything into customDimensions under a single composite key in some configurations. File sinks writing plain text give you a formatted message and nothing else. The console in default mode renders the template as a string.

The practical test is simple: take a log entry from your production aggregation system that uses a structured parameter. Check whether the parameter appears as its own field. If it is embedded in the message string, your structured logging is decorative. It looks right in code and does nothing useful at query time.

Lie 5: Exception Logging Loses the Inner Exception Chain

catch (Exception ex)
{
    _logger.LogError(ex, "Order processing failed for {OrderId}", orderId);
}

This is correct usage. ILogger accepts an exception as the first parameter, serializes it, attaches it to the log event. You did everything right.

What you get in your logs depends entirely on what the sink does with Exception.ToString() versus a structured exception decomposition.

The problem is AggregateException and friends. AggregateException: One or more errors occurred. is the most useless log entry in the .NET ecosystem. It tells you exactly nothing about what actually failed. The real exception is in InnerException, one or more levels deep.

Application Insights handles this well, serializing the full exception chain into separate telemetry entries. A plain JSON file sink with default settings often gives you just the outer exception type and message. You stare at AggregateException and go spelunking through stack traces.

If you cannot configure your sink’s exception serialization depth, make the root cause explicit:

catch (Exception ex)
{
    var innermost = ex;
    while (innermost.InnerException != null)
        innermost = innermost.InnerException;

    _logger.LogError(ex, "Order processing failed for {OrderId}. Root cause: {RootCause}", 
        orderId, innermost.Message);
}

This is defensive. It makes the useful information explicit in the log message rather than relying on the sink to dig it out of the exception chain.

Lie 6: Your Log Timestamps Are Potentially Wrong

ILogger does not add timestamps. The sink does. The sink decides what “now” means and in which timezone it records it.

Three places this goes wrong:

UTC vs local time confusion. Your application runs in UTC. Your sink records local time based on the server’s system clock. Your aggregation system converts to UTC. Depending on timezone offsets and Daylight Saving Time (DST), you end up with timestamps that are consistently wrong by hours. Correlating logs across services (one in UTC, one in local) means doing timezone arithmetic during an incident.

Clock skew in distributed systems. Multiple services writing to the same aggregation endpoint. Each server’s Network Time Protocol (NTP) sync is slightly different, maybe 50ms, maybe 500ms. Log entries that should be sequential appear out of order when sorted by timestamp. You lose the ability to reconstruct event sequences across service boundaries.

Buffered writes with stale timestamps. Some sinks batch writes for throughput. The timestamp attached to the log event is the time of the sink write, not the time of the log call. Under load, that drift can be seconds. You cannot trust the timestamp order to represent the call order.

For Serilog, be explicit about timestamp format and timezone:

Log.Logger = new LoggerConfiguration()
    .WriteTo.Console(outputTemplate: 
        "[{Timestamp:yyyy-MM-dd HH:mm:ss.fff zzz}] ...")
    .CreateLogger();

And verify that Timestamp is captured at call time, not write time. For buffered sinks, use a custom enricher to capture DateTimeOffset.UtcNow at the point the log method is called if ordering matters to you.

What Actually Works

The pattern across all six of these is the same: ILogger compiles, runs, produces no errors, and silently does something different from what you expected. None of these are bugs. They are documentation you did not read, or opt-in behaviour that looks like a default.

I am not being harsh about Microsoft here — this is mostly a user problem. The documentation exists. The configuration options are there. But the defaults are not conservative defaults that fail loudly when misconfigured. They are optimistic defaults that look like they are working until you need them to actually work.

A correctly configured logging pipeline:

  1. Use message templates everywhere. No string interpolation in log calls.
  2. Use [LoggerMessage] source generators for any log call in a hot path.
  3. Use BeginScope for correlation context (request ID, user ID, operation ID) — and verify scope support for your specific sink in your specific configuration before you depend on it.
  4. Configure one authoritative minimum level source. Either Logging:LogLevel or Serilog’s MinimumLevel. Not both.
  5. Write at least one integration test that queries actual log output and verifies structured properties appear as separate fields, not embedded in message strings.
  6. Verify exception serialization depth for your sink with a deliberately thrown AggregateException. Look at what you get.

The only way to know what your logs actually contain is to look at them in production, under real conditions. Development logging lies to you in the opposite direction — it shows you scopes, structured properties, and correct timestamps because the console provider actually works.

Production is where the assumptions fail. Look there.

ILogger is a façade over a pipeline you did not configure. The pipeline does not care that you trusted the façade.

Comments

VG Wort