Logging with ILogger in .NET: Recommendations and best practices

Published 2019-05-06 Updated 2022-01-31

This article describes recommendations and best practices for using the ILogger based logging system which has been introduced with .NET Core but is also available in all .NET Standard 2.0 supporting .NET frameworks.

Introduction

The logging interfaces provided by the Microsoft.Extensions.Logging.Abstractions NuGet package provide common logging abstractions with implementations for various logging backends and sinks.

A Logging backend is the place where logs are written to, e.g. files, Application Insights (AI), Seq, Kibana, etc. In the Serilog logging library they are called sinks.

ILogger vs ILoggerProvider vs ILoggerFactory

ILogger

The responsibility of the ILogger interface is to write a log message of a given log level and create logging scopes. The interface itself only exposes some generic log methods which are then used by “external” extension methods like LogInformation or LogError.

ILoggerProvider

A logger provider is an actual logging sink implementation, e.g. console, Application Insights, files or Serilog (an adapter to the Serilog logging abstraction). The ILoggerProvider’s only responsibility is to create ILogger instances which log to an actual sink. A logger instance which is created by a logger provider will only log to the associated logger provider.

ILoggerFactory

The ILoggerFactory logger factory instance is the boostrapper of the logging system: It is used to attach logger providers and create logger instances - either typed (ILogger<T>) or untyped (ILogger). These logger instances will log to all registered logger providers.

Log statements

Use structured logs

It is recommended to always use semantic/structured logs so that the logging backend receives the string with placeholders and its values separately. It is then able to just replace them in its UI on demand. This way each log statement preserves all associated properties and a template hash (in AI “MessageTemplate”) which allows the backend to apply advanced filtering or search for all logs of a given type.

logger.LogWarning("The person {PersonId} could not be found.", personId);

The previous statement will log the following properties to Application Insights:

Message: The person 5 could not be found.
MessageTemplate: The person {PersonId} could not be found.
PersonId: 5

Advantages of structured logs:

Properties are stored as seperate custom properties of the log entry and you can filter based on them in the logging backend
A message template/message hash is stored so that you can easily query for all logs of a given log statement type
Serialization of properties only happens if the log is actually written (not the case with string interpolation)

Disadvantages:

The order of the parameters in the C# log statement have to be correct and this cannot be statically checked by the compiler in the same way as it’s done in interpolated strings

Always pass exception as first parameter

To log an exception, always pass the exception object as first argument:

logger.LogWarning(exception, "An exception occured")

Otherwise it is treated as custom property and if it has no placeholder in the message it will not end up in the log. Also the formatting and storage is exception specific if you use the correct method overload.

Always use placeholders and avoid string interpolation

To ensure that a message template is correctly logged and properties are transferred as custom properties, you always need to log properties with placeholders in the correct order, e.g.

logger.LogWarning("The person {PersonId} could not be found.", personId);

Never use string interpolation because the replacement will be done in your application and the logging backend has no longer access to the message template and individual custom properties:

logger.LogWarning($"The person {personId} could not be found.");

Another downside of string interpolation is that objects are always serialized into text in your app even if the log is not actually written because there is a log level filter configured.

Do not use dots in property names

Avoid using dots in placeholder property names (e.g Device.ID) because some ILogger implementations (e.g. Serilog) do not support this. The main reason for this is that some logging backends cannot handle these property names and thus Serilog has to implement the lowest common denominator.

Scopes

Use scopes to add custom properties to multiple log entries

Use scopes to transparently add custom properties to all logs in a given execution context.

using (logger.BeginScope(
    new Dictionary<string, object> { {"PersonId", 5 } }))
{
    logger.LogInformation("Hello");
    logger.LogInformation("World");
}

Now both log statements will be logged with an additional PersonId property. Most scope implementations even work correctly in parallel code because they use async contexts.

You should create scopes for logical contexts, regions or per unit of work; for example:

Per HTTP request
Per event queue message
Per database transaction

In each of these scopes you should set the following properties if available:

Correlation ID (use the X-Request-ID HTTP header to read it in HTTP request scopes)
- Don’t forget to pass the correlation ID when calling other HTTP endpoints
- In Application Insights the property should be called operation_id
Transaction ID

Consider adding a scope identifier to filter logs by scope

In order to be able to show all logs of a given custom scope, I implemented a simple extension method which automatically adds a scope identifier and uses value tuples to specify properties for all log entries in the scope:

public static IDisposable BeginNamedScope(this ILogger logger,
    string name, params ValueTuple<string, object>[] properties)
{
    var dictionary = properties.ToDictionary(p => p.Item1, p => p.Item2);
    dictionary[name + ".Scope"] = Guid.NewGuid();
    return logger.BeginScope(dictionary);
}

This exention method can be used like this:

foreach (var message in messages)
{
    using (logger.BeginNamedScope("Message", ("Message.Id", message.Id), ("Message.Length", message.Length)))
    {
        logger.LogInformation("Hello");
        logger.LogInformation("World");
    }
}

Both log entries will now have a Message.Scope property with the same value: Using this property you are now able to show all logs of a given scope in your logging backend.

Use scopes to add additional custom properties to a single entry

If you want to add additional properties to a log statement which should not be part of the message template, use a “short lived” scope:

using (logger.BeginPropertyScope(("UserId", "CurrentUserId")))
{
    logger.LogTrace("The message has been processed.");
}

The used extension method to use value tuples looks like this:

public static IDisposable BeginPropertyScope(this ILogger logger,
    params ValueTuple<string, object>[] properties)
{
    var dictionary = properties.ToDictionary(p => p.Item1, p => p.Item2);
    return logger.BeginScope(dictionary);
}

Organization

Use a list of conceptual property names

You should build up a list of constant log entry property names (usually set with scopes) for your domain so that always the same name is used for them. For example always use UserId instead of Message.UserId and Request.UserId so that it’s easier to filter by user id over all log entries.

Log levels

It is recommended to think about what available log level to use. With this differentiation you can automatically create alerts, reports and issues.

For more information about when to use which log level, head over to the official documentation.

Use correct log levels

Here is a summary of the available .NET log levels and their meaning:

Trace/Verbose: Logs that contain the most detailed messages. These messages may contain sensitive application data. These messages are disabled by default and should never be enabled in a production environment.
Debug: Logs that are used for interactive investigation during development. These logs should primarily contain information useful for debugging and have no long-term value.
Information: Logs that track the general flow of the application. These logs should have long-term value.
Warning: Logs that highlight an abnormal or unexpected event in the application flow, but do not otherwise cause the application execution to stop.
Error: Logs that highlight when the current flow of execution is stopped due to a failure. These should indicate a failure in the current activity, not an application-wide failure.
Critical: Logs that describe an unrecoverable application or system crash, or a catastrophic failure that requires immediate attention.

Log exceptions with full details

Exceptions should always be logged as exceptions (i.e. not only the exception message) so that the stacktrace and all other information is retained. Use the correct log level to distinguish crictial, erroneous and informational exceptions.

Logger implementation

Use concrete implementations only in the application root

Use concrete implementations (e.g. Serilog types, etc.) only in the root of the application (e.g. Startup.cs of your ASP.NET Core app). All services and “logger consumers” should only use the ILogger, ILogger<T> or ILoggerFactory interface via (constructor) dependency injection. This way everything except the application bootstrapper is independent of the actual logger implementation and changing the logging sink is a no-brainer.

Consider using Serilog for a stable ILogger implementation

The ILogger (and ILoggerFactory) are quite generic and open interfaces with a lot of room about how to actually implement them. To show the problem, let’s have a look at the BeginScope method:

IDisposable BeginScope<TState>(TState state)

As you can see, the state can be any object. The actual implementation has to deal with that somehow but each implementation might differ on how it handles them. If you pass a Dictionary<string, object> to Serilog’s ILogger implementation, then it adds all these key-value tuples as custom properties to all log statements in the scope.

That is why I recommend to use Serilog as an intermedate layer/abstraction between ILogger and the actual sink (e.g. Application Insights) and not directly use the Application Insights ILogger implementation. The reason for that is that the AI implementation might not support all features (e.g. scopes are not supported) and changing a sink will not change the behavior and feature set of the logger implementation.

Sample code to use Serilog and ILogger in an ASP.NET Core web app (UseSerilog() can be found in Serilog.AspNetCore):

public class Program
{
    public static void Main(string[] args)
    {
        Log.Logger = new LoggerConfiguration()
            .WriteTo.Seq("http://localhost:5341")
            .WriteTo.Console()
            .CreateLogger();

        CreateWebHostBuilder(args)
            .UseSerilog()
            .Build()
            .Run();
    }

    public static IWebHostBuilder CreateWebHostBuilder(string[] args) =>
        WebHost.CreateDefaultBuilder(args)
            .UseStartup<Startup>();
}

Sample code to use Serilog and ILogger in a console application (AddSerilog() can be found in Serilog.Extensions.Logging):

public class Program
{
    public static void Main(string[] args)
    {
        Log.Logger = new LoggerConfiguration()
            .WriteTo.Seq("http://localhost:5341")
            .WriteTo.Console()
            .CreateLogger();

        new HostBuilder()
            .ConfigureServices((hostContext, services) =>
            {
                services.AddHostedService<MyHostedService>();
            })
            .ConfigureLogging((hostContext, logging) =>
            {
                logging.AddSerilog();
            })
            .Build()
            .Run();
    }
}

Setup for Application Insights without dependency injection

Here you can see a simple setup code to initialize the Serilog logger with an Application Insights sink and then add this logger provider to the logger factory:

Packages:

Microsoft.Extensions.Logging
Microsoft.Extensions.Logging.Abstractions
Serilog.Extensions.Logging
Serilog.Sinks.Seq

TelemetryConfiguration.Active.InstrumentationKey = instrumentationKey;

var serilogLogger = new LoggerConfiguration()
    .MinimumLevel.Debug()
    .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
    .Enrich.FromLogContext()
    .WriteTo.ApplicationInsightsTraces(TelemetryConfiguration.Active)
    .CreateLogger();

var loggerFactory = (ILoggerFactory)new LoggerFactory();
loggerFactory.AddSerilog(serilogLogger);

Now you have a logger factory with which you can create new untyped loggers:

var logger = loggerFactory.CreateLogger();

… or typed loggers:

var logger = loggerFactory.CreateLogger<MyService>();

In this case, the type is used to add the SourceContext custom property in Application Insights for filtering.

Inject ILogger or ILogger<T>, avoid injecting ILoggerFactory

Prefer injecting the ILogger interface and if necessary the ILogger<T> interface. Ideally your class’ constructor requests an ILogger and the IoC framework creates an instance of an ILogger<T> where T is the requesting class.

Avoid injecting ILoggerFactory because it would violate the SRP (single responsibilty principle) if a service creates child instances (there are exceptions where you need to do this).

Libraries and logging

Try to avoid logging in libraries

Most libraries should not use logging but use regular control flow like return values, callbacks, events or exceptions. Consider using System.Diagnostics.Trace for debug logging.

Use logging via dependency injection in library code

.NET libraries which need to log, should only use the ILogger interface to communicate with the logging infrastructure. They should use it via (constructor) injection. Avoid using a static property/singleton because it would force all callers to use the same logging infrastructure.

Assume you have a library which has a MyHttpClient class to communicate with a backend. The signature of its constructor should look like this:

public class MyHttpClient
{
    private ILogger _logger;

    public MyHttpClient(string url, ILogger logger)
    {
        _logger = logger ?? NullLogger.Instance;
    }

    ...
}

Only use logging abstractions in libraries

In libraries you should only use the described logging abstractions and no concrete types because they are set up in the application root. This all implies that a .NET library should only have a dependency to Microsoft.Extensions.Logging.Abstractions for logging.

For more information about logging in libraries, I recommend reading Good citizenship - logging from .NET libraries

Testing

Use the null logger to ignore logs in tests

Use NullLogger.Instance as null object in tests to avoid lots of null checks just for testing.

Use Seq for local logging

I recommend to use the Seq as a local development logging backend. You can easily run it via Docker and write local development logs to it. This way you can better access and browse logs than with plain text files.

Just start a local Seq image:

docker run -d --restart unless-stopped --name seq -e ACCEPT_EULA=Y -p 5341:80 datalust/seq:latest

And add Seq as a Serilog logging sink:

var serilogLogger = new LoggerConfiguration()
    .WriteTo.Seq("http://localhost:5341")
    .CreateLogger();

var loggerFactory = (ILoggerFactory)new LoggerFactory();
loggerFactory.AddSerilog(serilogLogger);

var logger = loggerFactory.CreateLogger();

Now you can browse to http://localhost:5341 to access the local logging UI.