Nov 30, 2024

.NET Logging

Logging abstractions in .NET

Abstractions

.NET supports high performance, structured logging via the ILogger API.

Logs can be written to different destinations. Abstraction that models this destination is a logging provider.

There are built-in logging providers (Console, EventSource, EventLog, …) and many more third party.

Usually logs are sent to multiple destinations, often to some third party ones where we can easily search and classify them for easier troubleshooting and monitoring.

Foundation for logging is included in Microsoft.Extensions.Logging NuGet package.

By pulling this package we automatically pull:

Microsoft.Extensions.DependencyInjection - default DI implementation
Microsoft.Extensions.Logging.Abstractions - abstractions for logging, such as ILoggerFactory, Logger<T>, Logger<TCategoryName>, LogLevel
Microsoft.Extensions.Options - provides a strongly typed way of specifying and accessing settings

We will be focusing on Microsoft.Extensions.Logging.Abstractions

After adding a package and having the following program written, the output will be empty because we didn’t configure any providers (destinations) where our logs will go.


// var logger = new Logger<Program>(new LoggerFactory());
var logger = new LoggerFactory().CreateLogger<Program>();

logger.LogDebug("Error has occurred!");

One of the built-in providers is a Console provider coming with Microsoft.Extensions.Logging.Console

To create a logger we use a factory of type ILoggerFactory.

Factory accepts a ILoggingBuilder that enable us to configure:

minimum logging level (filter out certain levels that we’re not interested in),
logging providers (destinations) where our logs will go
filters - another way of filtering out irrelevant logs

Logging configuration can be provided in-line or come from an external source (a file, environment variable…).

Later is the most common as we don’t need to rebuild the application to change configuration.

Log specifics

Every log has a log level associated and a category.

There are seven log levels supported, although None is not used for writing log messages. From lower to higher severity:

Trace 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.

And a special one:

None Not used for writing log messages. Specifies that a logging category should not write any messages.

Category is a string associated with the log (it can be whatever we set, but in practice is a fully qualified name of the class associated with the logger). Ideal for grouping and filtering of the logs.

Let’s get practical

For the sake of an example, let’s have our configuration stored in a JSON file:

// logging_config.json
{
  "Logging": {
    "Console": {
      "LogLevel": {
        "Default": "Debug",
        "Microsoft": "Warning",
        "Microsoft.Hosting.Lifetime": "Information",
        "Program": "Error"
      }
    }
  }
}

Console is an alias for a ConsoleProvider. If it happens that we have multiple providers this configuration will be applied only to a Console.

LogLevel is a property that we’re configuring in a form of key-value pairs. Key is a Category and a value is MinimumLogLevel for that category.

Microsoft, Microsoft.Hosting.Lifetime and Program are specific categories that we want to catch and filter.

Everything else falls under Default

Whatever MinimumLogLevel we set, that one and all with the higher severity will be logged, others will be filtered out as irrelevant (i.e. not passed to a provider).

If LogLevel is not specified, logging defaults to the Information level.

Let’s jump into an example where we configure a logger from the configuration file and log messages with different log levels.

using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.Logging;

var configuration =
    new ConfigurationBuilder()
    .AddJsonFile("logging_config.json", optional: false, reloadOnChange: true)
    .Build();

var logger = LoggerFactory
    .Create(builder => 
        builder
        .AddConsole()
        .AddConfiguration(configuration.GetSection("Logging")))
    .CreateLogger<Program>();

logger.LogTrace("Trace log!");
logger.LogDebug("Debug log!");
logger.LogInformation("Info log!");
logger.LogWarning("Warning log!");
logger.LogError("Error log!");
logger.LogCritical("Critical log!");

// Output:
// fail: Program[0]
//      Error log!
// crit: Program[0]
//      Critical log!

For a Category that starts with Program we specified minLogLevel to be an Error and since our category falls there, output makes sense.

CreateLogger<Program>(); is equivalent to CreateLogger(typeof(Program).AssemblyQualifiedName) in both ways we take class fully qualified name as a category.

If we create another logger with a different category than one specified in the configuration, it will fall under Default category rule.

...
var otherLogger = LoggerFactory
    .Create(builder =>
        builder
        .AddConsole()
        .AddConfiguration(configuration))
    .CreateLogger("OtherCategory");

otherLogger.LogTrace("Trace log!");
otherLogger.LogDebug("Debug log!");
otherLogger.LogInformation("Info log!");
otherLogger.LogWarning("Warning log!");
otherLogger.LogError("Error log!");
otherLogger.LogCritical("Critical log!");

Another way to filter out irrelevant log levels is via filters.

To add a filter we can use extension method on a builder AddFilter()

There are many overloads but in essence it enables us to filter based on the

provider type or alias
logger category
log level

Let’s filter out log levels with lesser importance than Critical for a category: OtherCategory

var otherLogger = LoggerFactory
    .Create(builder =>
        builder
        .AddConsole()
        .AddFilter("OtherCategory", LogLevel.Critical))
    .CreateLogger("OtherCategory");
    
    
otherLogger.LogTrace("Trace log!");
otherLogger.LogDebug("Debug log!");
otherLogger.LogInformation("Info log!");
otherLogger.LogWarning("Warning log!");
otherLogger.LogError("Error log!");
otherLogger.LogCritical("Critical log!");

Only Critical level message will be logged.

Using filters we can override configuration values.

In the following example we also configure our logging via external configuration and filter will override configuration for a OtherCategory category


var otherLogger = LoggerFactory
    .Create(builder =>
        builder
        .AddConsole()
        .AddConfiguration(configuration)
        .AddFilter("OtherCategory", LogLevel.Critical))
    .CreateLogger("OtherCategory");

For messages that go under OtherCategory only those with Critical severity will be logged.

Logged message specifics

So far we just logged plain text messages. To utilize a full potential of logging, especially if we’re integrating with some third party provider that does structured logging we should think about the format of our messages.

.NET supports structured logging. In the message format we can specify parameters and their values.

logger.LogDebug("Message arrived from {ExternalSystemId}", "OrderingSystem");

// Output:
// Message arrived from OrderingSystem

In this format our parameter is ExternalSystemId with the value of OrderingSystem

If we have messages coming from other systems as well, this would make sense. We would be able to filter based on the ExternalSystemId parameter.

Formatter

Another concept wroth mentioning. It goes hand in hand with the logging provider.

If ConsoleLoggingProvidertells us that the destination of our logs is console, JsonConsoleFormattertells us in which format messages will be logged to a console.

By default when using extension method AddConsole we have three formatters setup:

JsonConsoleFormatter
SystemdConsoleFormatter
SimpleConsoleFormatter

SimpleConsoleFormatter is the one that’s set.

To set the other ones we can use extension methods:

AddJsonConsole
AddSystemdConsole

Log scopes

A way for us to group different logically connected logs and adding to them some contextual information.

I believe you already know where this might be useful. For instance if we want to connect multiple logs with the same Id (correlationRequestId, transactionId …) or more popular term for a concept tracing .

To create a scope we just need to run BeginScope on the ILogger and provide it with the context that we want to be shared within the scope.

All the messages logged within the scope will have this contextual information.

To build up on top of this context we would build our own abstraction that will take control over the information shared within scope and be responsible of disposing it.

In an essence it looks like this:

var consoleLogger = LoggerFactory
    .Create(builder =>
        builder
        .SetMinimumLevel(LogLevel.Trace)
        .AddConsole(o => o.IncludeScopes = true))
    .CreateLogger<Program>();

using (var scope = consoleLogger.BeginScope(correlationRequestId))
{
    consoleLogger.LogDebug("Log1");
}

// Output
// dbug: Program[0]
//      => 27e0cac5-f1ee-4244-9456-0dacbf10882d
//      Log1

In case when we would pass something more complex we would need a proper formatter or use some already built-in ones

using (logger.BeginScope(new KeyValuePair<string, object>[]
{
   new("CorrelationRequestId", correlationRequestId)
}))
{
    logger.LogDebug("Log1");
}

// Output
// dbug: Program[0]
//      => System.Collections.Generic.KeyValuePair`2[System.String,System.Object][]
//      Log1

Then if we take built-in JsonConsoleFormatter:

 var logger = LoggerFactory
     .Create(builder =>
         builder
         .SetMinimumLevel(LogLevel.Trace)
         .AddJsonConsole(options =>
         {
             options.IncludeScopes = true;
             options.JsonWriterOptions = new()
             {
                 Indented = true,
             };
         }))
     .CreateLogger<Program>();
     
     ...

// Output
{
  "EventId": 0,
  "LogLevel": "Debug",
  "Category": "Program",
  "Message": "Log1",
  "State": {
    "Message": "Log1",
    "{OriginalFormat}": "Log1"
  },
  "Scopes": [
    {
      "Message": "System.Collections.Generic.KeyValuePair\u00602[System.String,System.Object][]",
      "CorrelationRequestId": "8a9d5795-fc26-4532-9dfc-dbc41754e39c"
    }
  ]
}

You can think of a use-case where we would send this logs to some third party sink that supports structure logging and get all these information there as well.

Once we create the scope, we can hold it’s reference inside of a variable.

i.e. var scope = logger.BeginScope(..)

and this is what we can find inside of it:

Log Scope

Only providers that inherit from ISupportExternalScope support scopes, at this moment that would be ConsoleLoggerProvider and EventLogLoggerProvider.

If you’re interested into this concept following blog posts might give you some insights:

Conclusion

The abstractions that Microsoft provides are powerful and there are tons of third party ones built on top of those that can probably serve all our needs. Logging is an important concept and a small building block on which other powerful concepts such as Tracing, Monitoring, Observability are built on.

Since we now understand the foundations of Logging we can build our understanding of other concepts.

See you in the next one :)