Best Practices: Logging in .NET

Writing log files seems trivial at first glance. And at second glance too. But then at some point you’re sitting there debugging your own logging code while the log files stubbornly refuse to show the information you need to find the actual bug. To help you avoid that fate, I’ve put together some ideas, pitfalls, suggestions, and best practices for logging in .NET.

Introduction

Logging in .NET has evolved quite a bit since .NET Core and .NET 5/6 compared to what we knew from .NET Framework versions 1-4.

Our logger class now typically comes from dependency injection, and most importantly, we don’t have to drag a dependency on a specific logging library through our entire project — Microsoft provides its own abstraction for an ILogger.

The minimal example, using the new Minimal APIs in .NET 6, looks like this:

// Program.cs
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;

var services = new ServiceCollection()
    .AddLogging(o => o
        .SetMinimumLevel(LogLevel.Information)
        .AddDebug()
        .AddConsole()
    )
    .AddSingleton<MyClass>()
    .BuildServiceProvider();

var c = services.GetRequiredService<MyClass>();
c.DoSomething();

// Additional classes
public class MyClass
{
    private readonly ILogger _logger;

    public MyClass(ILogger<MyClass> logger)
    {
        _logger = logger;
    }

    public void DoSomething()
    {
        _logger.LogInformation("Doing something at {Time}", DateTimeOffset.UtcNow);
    }
}

All logging libraries can now integrate behind this unified ILogger facade, making them easily swappable through the DI system from a central point.

Available Libraries

Speaking of logging libraries: While NLog or Log4NET used to be popular choices, Serilog has established itself as the de-facto standard for logging libraries since the introduction of .NET Core and continuing through .NET 5 and 6.

Nevertheless, there are numerous alternative logging libraries. Some are very specific to certain centralized log collection systems, others have flexibly interchangeable targets that can serve just about any logging system. Here’s an alphabetical (non-ranking, certainly incomplete) list:

• elmah.io
• Graylog / GELF
• JSNLog
• Kisslog
• log4net (Apache)
• Microsoft.Extensions.Logging
• NLog
• NReco
• Sentry
• Serilog
• Stackdriver

Note: These alternative logging libraries sometimes use different LogLevel names than Microsoft.Extensions.Logging. For example, the Microsoft level Trace is called Verbose in Serilog, and the Microsoft level Critical is called Fatal in Serilog. In code, you always use the Microsoft levels with ILogger, but in the configuration of the specific logging system, you typically need to use the library-specific names.

This becomes particularly apparent when you configure Serilog in your appsettings.json with "minimumLevel": "Trace" — and then find nothing in your log because Serilog doesn’t understand Trace and therefore logs nothing at all.

Pitfalls

Let me first address some pitfalls I’ve encountered in daily use.

1. Strings Instead of Parameters / String Interpolation

Log entries are structured nowadays. This means they can contain context information beyond plain log text, as well as substitutable placeholders. Depending on the logging system that receives the entries, these placeholders can then be searched by their specific values. However, this doesn’t work if you just write plain strings to the log:

Log.Write("Doing something at " + DateTimeOffset.UtcNow.ToString() + " and ...");

Or equally bad, just more modern, with string interpolation:

Log.Write($"Doing something at {DateTimeOffset.UtcNow} and ...");

Apart from losing structured context information, this method allocates a new string object every time, which consumes memory and unnecessarily burdens the garbage collector.

Better is the example shown at the beginning with the placeholder and value as parameter:

_logger.LogInformation("Doing something at {Time} and ...", DateTimeOffset.UtcNow);

Now all logs can be searched and filtered. For example, I might want all log entries where the placeholder Time has a value between 12:00 and 12:05, narrowing down the entries accordingly. It’s also advisable to always use the same placeholder name for a specific value, so that value can be found in other log entries during a search.

But watch out: The log methods take a string messageTemplate as the first parameter (our string with placeholders), followed by a params object[] with the values. This has the disadvantage that every value type gets boxed into an object on every method call, allocating a new object that wraps the value each time. This is particularly wasteful when the log call doesn’t result in a log entry due to its level being disabled.

2. Logging When Not Necessary

If our logger is configured to only write warnings, errors, and critical messages, then it’s unnecessary to call it for information, debug, or trace entries.

We can prevent the log call when the desired log level isn’t needed:

if (_logger.IsEnabled(LogLevel.Information))
{
    _logger.LogInformation("Doing something at {Time} and ...", DateTimeOffset.UtcNow);
}

This check saves (on my machine) about 35 nanoseconds per call. That doesn’t seem like much at first glance, but consider that a web service runs 24/7, contains hundreds to thousands of classes (not just your own, but also from NuGet packages), each with dozens of methods that all have debug and info calls, and the service eventually comes under load — that can quickly add up to billions of log calls, each saving 35 nanoseconds. Over days and weeks, that sums up to a substantial amount of CPU time. And if you’re paying for that in the cloud, you can actually save quite a bit of money.

But yes, this check is inconvenient and therefore usually not done. I’ll show you a way later that includes this check automatically, so we can even skip the if-block.

3. Wrong Parameter Count

Let’s say we add another placeholder to our log entry but forget to provide the value:

public void DoSomethingWrong()
{
    _logger.LogInformation("Doing something at {Time} and {Date}", DateTimeOffset.UtcNow);
}

This compiles (unfortunately) just fine, but leads to a very ugly error at runtime:

Unhandled exception.
System.AggregateException: An error occurred while writing to logger(s).
(Index (zero based) must be greater than or equal to zero and less than
the size of the argument list.)
---> System.FormatException: Index (zero based) must be greater than or
equal to zero and less than the size of the argument list.

Some source code analyzers and/or IDE tools (ReSharper, Rider) can detect these errors and warn us, but as long as we use the “normal” logging methods, we have no other safeguards.

In short: Anyone who doesn’t want their application to crash at runtime due to such an exception — maybe even years later when some obscure code path is traversed for the first time due to a strange constellation of database entries (and thus that copied-but-not-properly-adjusted log call is invoked for the first time) — should pay meticulous attention to this. Or keep reading, because there’s a solution for this too.

Oh, and please don’t ask why such a strange example just spontaneously came to mind, something that “never happens” and “especially not when the application has been running and used daily for 4 years” 🙈.

4. Not Finishing Writing Logs

If at all possible, you should ensure that all entries actually make it to the logging system — meaning specifically for centralized systems that they’re sent over the network or at least written to a local file. Because the best logging in the world is useless if the service dies before flushing the file stream and you never get to see the error with the exception that could have helped you solve the problem.

Here again using Serilog as an example:

public async Task<int> Main(string[] args)
{
    try
    {
        // ... Setup of Host etc....
        await app.RunAsync();
        return 0;
    }
    catch (Exception ex)
    {
        Log.Logger.LogFatal(ex, "An error caused the service to crash");
        return 1;
    }
    finally
    {
        // Ensure the log is actually written!
        Log.Logger.CloseAndFlush();
    }
}

This doesn’t help if the process simply terminates and never reaches the catch/finally handler, but when that happens we usually have a different external problem that can potentially be investigated via the EventLog/system log.

5. Omitting the EventId

The logging methods from Microsoft.Extensions.Logging all accept an EventId parameter. This is simply a positive number (ushort) between 1 and 65536 that uniquely identifies the log entry. Unfortunately, most logging methods since .NET Core 2.0 allow omitting this EventId. You’ll rarely find it used in examples.

Assigning a (more or less) unique EventId has advantages though. It allows grouping log entries by their type. For example, all log entries related to saving a specific entity could get one ID, and all entries related to deleting a specific entity could get another ID. This makes it easier to filter the corresponding entries from the log. Alternatively, you can use number ranges and assign a truly unique ID within a specific range to each event. The range then indicates the source of the log message or its meaning.

Another huge advantage is that once an EventId is assigned, you don’t necessarily have to change it when you modify the log entry’s text in an application update. It’s generally easier to search logging systems for EventId = 4711 than for Text = "Did something with dataset {XZ} on {whatever}". This way, historical entries in a system can also be compared and found even when the message text was changed at some point in previous updates.

Because who hasn’t searched a log for a message and wondered why certain entries were missing — only to discover that the log entries contained “Orignal” instead of “Original” — and that’s why they weren’t found?

6. Implicit Category Parameter

Finally, the category is often not used efficiently either. The logging system introduced in .NET Core provides a logger factory so we can have an ILogger<TCategoryName> injected into our classes. The type specified is usually the class where the logger is used. The category name is then the full class name including namespace. So we get a logger whose category parameter in every log message carries the name of the class writing the log entry.

What’s this good for?

First, we can override the minimum LogLevel per category in the logging system configuration. Or more specifically: per beginning of a category name.

The logger configuration in the ASP.NET Core application project template generates this configuration, for example:

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

Here, the default level logged is Information, but the configuration for all entries whose category starts with Microsoft is more specific — these entries are only logged from Warning upward. Then the exception for entries in the Microsoft.Hosting.Lifetime category kicks in, which are set back to Information.

This allows very fine-grained control over which log entries you want to see from which areas of your own code. Especially when debugging, this lets you control much more efficiently what you need, without missing important entries but also without being flooded by masses of log entries irrelevant to the current problem.

Best Practices

Now that we’ve looked at the most common logging problems, let’s examine what we can do better — and how.

Option 1: Improve Performance with Pre-formatted Log Entries

When we use structured logging, the logging system must first parse the given log message, identify the placeholders, and then store the values for the placeholders in the structured log. If we also have output in an unstructured format like plain text on the console, it must also replace the placeholder and build the resulting string.

The logging system can cache the result of the parsed log entry. However, if we always cache everything, memory eventually fills up. The .NET logging system therefore limits the cache to 1024 entries. If we have more log messages and they’re frequently used in varying order so that old cache entries are often discarded, this too can become a performance problem.

With the helper LoggerMessage.Define, we can pre-format a log message. We get back an Action that we can call with a logger, our parameters, and an optional exception, and it contains our pre-formatted message template:

private static readonly Action<ILogger, DateTimeOffset, Exception?> _logSomething =
    LoggerMessage.Define<DateTimeOffset>(
        logLevel: LogLevel.Information,
        eventId: 1,
        formatString: "Doing something at {Time}");

public void DoSomething()
{
    _logSomething(_logger, DateTimeOffset.UtcNow, null);
}

The advantages are:

• The log message is parsed only once when we call LoggerMessage.Define. After that, we have the pre-formatted message and can call it as often as we want without cache eviction forcing re-parsing.
• The Action has an automatic _logger.IsEnabled() check built in. So the actual log call won’t happen if the used LogLevel isn’t configured.
• The Action can only be called with the correct number of typed parameters. However, this doesn’t help if we mess up the placeholders in the string.

The disadvantages are unfortunately also clear: It’s a lot of code, it’s tedious to write, and unfortunately very awkward to use. Even though this solves almost all our problems, this solution is so ugly that you’d rather not use it. And honestly, rightfully so.

Option 2: Use Source Generators

Fortunately, .NET 6 brings us a new way to automate these elaborate logging optimizations and let us focus on what matters: the actual logging. The source generator handles writing all that code for the Action and pre-formatting etc.

For those unfamiliar with source generators: Very simplified and brief, it’s a kind of plugin for the compiler. This allows your own code or code imported via NuGet packages to be executed in the compiler, directly during compilation, which can generate new code, for example.

But don’t worry: We don’t have to write anything ourselves here, because fortunately .NET 6 ships with a ready-made source generator for logging in the form of the [LoggerMessage()] attribute. The source generator implements both the pre-formatting of the message and the call with the check whether the log level is active or not.

Our log method looks like this with the source generator:

[LoggerMessage(0, LogLevel.Information, "Doing something at {Time}")]
partial void LogSomething(DateTimeOffset time);

public void DoSomething()
{
    LogSomething(DateTimeOffset.UtcNow);
}

To use the source generator, we need to keep one thing in mind: The generator needs somewhere to write the method code it generates. It does this during compilation in a temporary file that supplements our partial-marked method signature with the implementation code. And this (unfortunately) only works if our class is also marked as partial.

And yes, instead of a simple:

public void DoSomething()
{
    _logger.LogInformation("Doing something at {Time}", DateTimeOffset.UtcNow);
}

we have two more lines to write: the partial method signature with our parameters and the LoggerMessage attribute with the additional log message details.

However, this really solves all the problems we discussed above. Since the [LoggerMessage] source generator also includes an analyzer, the compiler now even tells us when a placeholder in our log message isn’t filled by a parameter in the log method.

Additional Info on Source Generators

When using LoggerMessage.Define, we had to pass the ILogger with every call. The source generator finds it automatically by looking for a field or property of type ILogger on our class and uses it in the generated method. If we don’t have one (e.g., on static classes), we can also include the logger in our log method definition and then pass it when calling:

[LoggerMessage(0, LogLevel.Information, "Doing something at {Time}")]
static partial void LogSomething(ILogger logger, DateTimeOffset time);

public static void DoSomething(ILogger logger)
{
    LogSomething(logger, DateTimeOffset.UtcNow);
}

Using Log Levels and Context Information Correctly

This isn’t a technical topic, but it’s important.

We log so that the log provides value during development and in production. The value we expect is to better understand and trace error cases and their history. So we can find bugs faster and fix them better.

For this, it’s important to use log levels sensibly and, above all, consistently. Unfortunately, there are no universally applicable best practices for this, but I’ve had very good experiences with the following rules of thumb over the years:

Trace (Serilog: Verbose)

Traces are terrible. The log becomes very, very much larger when you turn them on, and you literally drown in information. When you really need them, you have a massive problem (e.g., concurrency in multithreading). Normally, I don’t write trace log messages. Only when there’s a really extremely hard nut to crack at a particular spot do I mark with trace logs, for example, every entry into affected methods (with all parameters and their values) and the exit (again with all inputs and the return value). As additional context information, I also like to log the thread ID (e.g., with Serilog’s Thread enricher) to better trace the flow. Most of my trace statements also end up behind an #if DEBUG compiler directive so they’re not included in the release build.

The fundamental rule above all: Parameter values don’t belong in a production log.

Debug

Named as it should be used: During debugging. When do I call something? With what values? What did I get back?

Caution: But please also make absolutely sure that no data ends up in the log that could be problematic from a data protection perspective. Log those with Trace and only in the debug build.

Info

At this level, I personally like to log everything that happens at system boundaries and when actions are started. Everything a user triggers gets a log line (who did what when?), and regularly running processes also get a start marker.

Warning

Everything that could later become a problem should be logged as a warning: The database call that took longer than expected — if this escalates, a system can collapse because it’s just waiting for the database. An in-memory cache that fills up and discards old entries — if this happens frequently and/or during peak times, performance can massively degrade due to too many cache misses.

Error

Says what it is: An error. A database access that didn’t work. A network call to another API that returns an error. When someone wants to delete something that no longer exists or create something that already exists. Or when a user calls an API they’re not authorized for and the intended client application should actually prevent this. That indicates either a bug in the client application or someone trying to manipulate our API.

Critical (Serilog: Fatal)

From my perspective, there’s only one place for a Fatal log message: In Program.cs in the global exception handler (or in the global exception handler monitoring every self-created thread). Critical should exclusively accompany a program crash. When a service can’t get the port it should work on and therefore can’t start. When a service finds its database missing or in an invalid state at startup (e.g., non-matching database schema) and therefore aborts or must abort startup.

As mentioned at the beginning: This isn’t an industry-standard approach. This is my personal opinion that I’ve formed over many years of experience with various software systems. Different requirements certainly make different classifications necessary. However, if you haven’t given much thought to this topic yet (understandable: logging is more of a necessary evil than our hoped-for and desired life goal as developers), then what I’ve written above is probably a solid foundation where you can’t go terribly wrong.

When and What

So when should what be logged?

During development and debugging? For me, clearly: As much as possible. Unless you’re being overwhelmed by an unfilterable flood of useless information (e.g., in text-based log files). Then: As little as necessary so the amount remains somehow manageable.

Personally, during development I like to have the free Individual/Developer version of Seq (pronounced “Seek”) running in its own Docker container per customer, and I log everything (and I mean everything: Trace) into it. When I then need to look at the logs, I can easily and quickly filter for the important info, narrow down by time, search, etc. — across all services/applications.

At runtime? That depends entirely on the circumstances and the volume of logs. If I have a centralized logging system with lots of storage, I can easily have debug logs written at runtime and then discard them after 24 hours (or at the end of the next business day), keeping only Info and more important messages longer. The key is finding a sensible balance between retention time, required space, and any desired statistics (e.g., warnings/time). Though deriving statistics from logs already moves into the monitoring topic.

If I don’t (yet) have a central logging system and am writing files, but use Serilog with a dynamic LogLevelSwitch, for example, then it’s sufficient for a program to initially log only warnings. When those occur, the log level can be automatically raised to Info or even Debug for a certain time at runtime, and when the problematic situation occurs again afterward, I have more information to trace it.

Benchmark Results

Now I’ve claimed multiple times that it would be better or faster to actually log with source generators. But of course I can claim a lot when the day is long. Much more exciting is the question of whether I can prove it.

So I built a small benchmark and had the different methods compete against each other. Each method produces the same log message with the same parameters, once at LogLevel.Trace and once at LogLevel.Critical. The logger writes to an active dummy target that only increments a counter and is configured to LogLevel.Information. This means the Trace calls aren’t written and the Critical calls are all executed.

The methods are:

• InterpolatedLog[Trace/Critical]: Using string interpolation.
• CommonLog[Trace/Critical]: The ordinary _logger.LogXXX("Message", params); call.
• ActionLog[Trace/Critical]: Logging with an Action pre-formatted by LoggerMessage.Define().
• SourceGenLog[Trace/Critical]: Calling the log method implemented by the source generator.

Additionally, each method (except the source generator) exists in a Checked... variant that includes the if-block with the Logger.IsEnabled() check for the respective level.

The Results

BenchmarkDotNet gives us the following results after running the different methods:

Method	Mean	Error	StdDev	Gen 0	Allocated
InterpolatedLogCritical	586.689 ns	11.4315 ns	16.7562 ns	0.0887	1,120 B
CheckedInterpolatedLogTrace	5.234 ns	0.1181 ns	0.1213 ns	–	–
CheckedInterpolatedLogCritical	610.778 ns	12.0039 ns	11.2284 ns	0.0887	1,120 B
CommonLoggingTrace	79.181 ns	1.3277 ns	1.2419 ns	0.0082	104 B
CommonLoggingCritical	86.153 ns	1.7055 ns	1.8249 ns	0.0082	104 B
CheckedCommonLoggingTrace	4.804 ns	0.1037 ns	0.1153 ns	–	–
CheckedCommonLoggingCritical	92.950 ns	1.8736 ns	2.0825 ns	0.0082	104 B
ActionLoggingTrace	6.018 ns	0.1430 ns	0.1757 ns	–	–
ActionLoggingCritical	39.357 ns	0.6841 ns	0.6399 ns	–	–
CheckedActionLoggingTrace	4.485 ns	0.1106 ns	0.1656 ns	–	–
CheckedActionLoggingCritical	45.367 ns	0.8984 ns	1.1033 ns	–	–
SourceGenLogTrace	5.319 ns	0.1289 ns	0.1676 ns	–	–
SourceGenLogCritical	38.375 ns	0.7734 ns	0.8906 ns	–	–

Analysis

First off: The fastest variant is of course the one where we don’t log and catch that beforehand with the Logger.IsEnabled() check. As you can see, this if-query is always around 5 nanoseconds “expensive” on my machine.

Otherwise, you can clearly see: Interpolated strings are by far the slowest variant and also bring substantial allocations. So: hands off!

The usual, “normal” logging also brings allocations. It’s somewhat faster but still relatively slow at just under 100ns.

The variants with the pre-formatted Action and the source generator are on par speed-wise at around 40ns and require zero additional allocations, which greatly relieves our garbage collection in the long run. As I mentioned, the Action method also already has the IsEnabled check built in, so the Checked variant adds the 5ns of the additional if-query on top when we do log.

Conclusion

The “normal” logging with direct logger.LogXXX() calls is undoubtedly the most widespread but not necessarily the optimal variant. Regarding performance, there’s no difference between pre-formatted Actions and the source generator approach. This should be obvious since the source generator does nothing other than generate the same code we wrote directly for the Actions. However, we don’t have to write this complicated Action code ourselves, which is a big advantage. Of course, only under the premise that we can live with marking our classes that log as partial.

Even though it’s two more lines per log entry: Using the [LoggerMessage] source generator is about twice as fast or half as expensive as the familiar direct logger call, saves a few bytes of memory on every call, additionally includes the Logger.IsEnabled() check, and with the built-in analyzer ensures at compile time that the parameters match exactly to the placeholders in the message template. It’s therefore the ideal solution for applications that log a lot and continuously.

Oh, and please don’t forget: The EventId is good, costs nothing, and really helps when searching for specific entries in the logging system without needing to know the exact text for a full-text search. 😉

---

Original (in German — published at my employer): Best Practices: Logging in .NET