Practical .NET

Logging in .NET Core

.NET Core provides a framework that logging systems can be snapped into. However, what's most important about this framework is how you write your messages out. It's the quality of the message that will let you find where your problems are.

• By Peter Vogel
• 04/18/2019

When things go wrong in production what you need to do -- before doing anything else -- is gather information. The reason that most bugs don't get fixed is because of the assumptions we make early in the process about "what's gone wrong." An effective logging system is essential to ensure that, when things go horribly wrong, you have some idea of where to look for the cause.

Not surprisingly, then, .NET Core includes support for logging. In fact, it includes support for a variety of logging systems: If you like your existing logging system, then you can keep your existing logging system -- Stackify, Serilog and NLog, for example, all already have written providers that work with .NET Core's logging system. This column describes how to use the logging framework without caring which logging system you're using.

Accessing the Logging Infrastructure
According to the documentation, a default ASP.NET Version 3.0 project automatically loads five logging providers ("logging providers" are generally referred to as "loggers"). They are: DebugLoggerProvider, ConsoleLoggerProvider, EventSourceLoggerProvider, TraceSourceLoggerProvider and EventLog. In the Version 3.0 preview that I'm working with, the EventLog provider didn't seem to be loaded. Each logger writes log information to a different output using its own format.

In any component created by the ASP.NET framework (for example, Controllers, Razor Pages, objects loaded into the IServiceCollection object), you can retrieve a logger by adding an ILogger parameter to the component's constructor passing a reference to the logger you want. This code, for example, grabs the Debug logger in the CustomersController's constructor and stores the logger in a field:

public class CustomersControllers
{
   private ILogger<DebugLoggerProvider> loggerDebug;
   public CustomersControllers(ILogger<DebugLoggerProvider> loggerDebug)
   {
      this.loggerDebug = loggerDebug;
   }

Typing in the full provider name can be a pain, so there are aliases you can use for some of the default providers: EventSource can be used instead of EventSourceLoggerProvider and TraceSource instead of TraceSourceLoggerProvider (again, there are supposed to be aliases for the other providers, but they didn't seem to be available in the preview).

Like any other class in the IServices collection, you can also accept the IServiceProvider and extract a logger using the GetRequiredService method. This code grabs a ConsoleLogger in a Razor Page and stuffs it into a property:

public class IndexModel : PageModel
{
   private ILogger<ConsoleLoggerProvider> consoleLogger { get; }
   public IndexModel(IServiceProvider sp)
   {
      consoleLogger = sp.GetRequiredService<ILogger<ConsoleLoggerProvider>>();
   }

In an ASP.NET Core project, if you've added middleware to the processing pipeline, then you can retrieve loggers through the HttpContext object passed to the Invoke method:

public async Task Invoke(HttpContext ctx, IDataService svc2)
{
   ILogger<EventSourceLoggerProvider> loggerEvent = 
                       ctx.RequestServices.GetService<ILogger<EventSourceLoggerProvider>>();

If you prefer, you can use the HttpContext property in Razor Pages and Controllers the same way to retrieve a logger.

You probably don't need or want all those logging providers. Among other issues, the TraceSource provider targets the .NET Framework, and EventSource is aimed at C and C++ developers. Fortunately, you can configure what providers are loaded in your application's Program.cs file by extending the lambda expression put into the CreateWebHostBuilder method with the ConfigureLogging method.

The following code, for example, clears out all the default loggers using the ClearProviders method. It then adds in the DebugSourceLoggingProvider using an extension method provided with ASP.NET Core. In this example, the code only does this when the application is running in development mode:

public static IWebHostBuilder CreateWebHostBuilder(string[] args) =>
    WebHost.CreateDefaultBuilder(args)
        .UseStartup<Startup>()
        .ConfigureLogging(log =>
        {
           if (Environment.GetEnvironmentVariable("ASPNETCORE_ENVIRONMENT") 
                               == Microsoft.Extensions.Hosting.Environments.Development)
           {
              log.ClearProviders();
              log.AddDebug();
           }
        });

Do be aware that, at least in Version 3.0 preview, while ClearProviders removes loggers from the services collection, it doesn't stop you from accessing them elsewhere in your application. It's just that when you call the logging methods on those loggers, nothing happens.

Writing a Log Entry
Because all the loggers implement the ILogger interface, once you've retrieved a logger, they all look alike. The most general purpose method in the ILogger interface is the Log method, which accepts a logging level, a message and an array of values that will be merged into the message. Here's the simplest possible call to the Log method:

loggerEvent.Log(LogLevel.Critical, "Invalid customer");

The initial parameter (the LogLevel) can be set to seven values (including "none"). You can skip providing the LogLevel parameter by using the LogCritical, LogWarning or LogInformation methods, which set the LogLevel to the three most commonly used levels (as implied by their names). The various Log* methods can also be passed Exception objects.

The destination and format of your log output will typically be managed by configuration options that you set on your logger ... and those options will vary from one logger to another. Loggers typically follow the standard .NET Core configuration pattern of providing a configuration object to a lambda expression called when the object is created. The properties on that configuration object represent the logger's configuration options.

Here's a typical example for the AddConsole method that sets two options:

log.AddConsole(opt =>
                    {
                        opt.DisableColors = true;
                        opt.LogToStandardErrorThreshold = LogLevel.Error;
                    });

Again, following this pattern, loggers also typically support reading in a section from your appsettings.json file. That section will be a JSON object with properties that match the properties on the logger's configuration object. The standard is to include that information in the Logging section of the appsettings.json file (this is the section where the logging system keeps its own configuration options). To set the console logger's properties from a JSON file, I would add this to my appsettings.json file:

{
  "Logging": {
    //system level logging options
    "Console":
    {
      "disableColors": true,
      "LogToStandardErrorThreshold": LogLevel.Error
    }
  }
}

Supporting Analysis
When you go to process logging information you're going to find that your biggest problem is finding the messages relevant to your problem. The logging infrastructure provides a couple of tools to make it easier for you to find what's relevant. However, it's up to you to take advantage of them. And (again) my standard caveat for this article: How these tools are used will depend on your logging provider.

At the very least, you should organize your messages into categories. Often, the most useful category scheme is one that ties messages to the objects that make up your application. The logging infrastructure will provide you with a logger with a category set to an object, just by asking for it in your constructor. This code gives me a logger with its category set to the full name of my HomeController class:

public class HomeController
{
   ILogger<HomeController> hc;
   public HomeController(ILogger<HomeController> loggerController) 
   {
      hc = loggerController; 
   }

Alternatively, you can create a logger-with-a-category by asking for a LoggerFactory and using its CreateLogger method. This code does the same thing as my previous example but uses the ILoggerFactory object's CreateLogger method to create the "categorized logger":

public class HomeController
{
   ILogger<HomeController> hc;
   public HomeController(ILoggerFactory factory) 
   {
      hc = factory.CreateLogger<HomeController>(); 
   }

You still call the various Log* methods as you did before. Here's my simplest possible message:

hc.LogCritical("Invalid customer Id");

However, the output of this method now includes category information:

LoggerProject.Controllers.HomeController: Critical: Invalid customer Id

Another technique to help you track down the log messages is to pass an EventId object to your Log method. This example writes out a warning level message that includes an EventId with its Id property set to 1 and its name property set to CustomerManagement:

logger.LogCritical(new EventId(1, "CustomerManagement"), "Invalid customer Id");

Finally, you can include context-specific information in your log message. The message that you pass to a Log* method is treated as a template with placeholders that will be replaced with values before the message goes to the log.

Here's a typical example with a message with two placeholders ({0} and {1}) and two values to merge into the message:

logger.Log(LogLevel.Critical, "Processing customer {0}, {1}", cust.Id, cust.Name);

The DebugLoggerProvider will write this to Visual Studio's Output window like this:

Microsoft.Extensions.Logging.Debug.DebugLoggerProvider: Critical: Processing Customer A123, Vogel

For logging providers that support semantic logging, passing the context-specific values as separate parameters gives the logging system access to those values. You can then use those values, when searching the log files, to find the messages that matter to you.

You can also use string interpolation to skip passing values in a separate parameter. This code generates the same message as my previous example:

logger.Log(LogLevel.Critical, "Processing customer {cust.Id}, {cust.Name}");

This last example, by not breaking out the values to be included in the message, has a problem: It hides those values from the logging provider. The best practice is probably to use a combination of the two techniques: Include the values in a separate parameter, but use the name of the parameter as your placeholder. That's what this example does:

logger.Log(LogLevel.Critical, "Processing customer {cust.Id}, {cust.Name}", cust.Id, cust.Name);

Which brings me to the best advice I can give you: When you create your log messages always begin by asking two questions. The first is "How will I find this message when I need it?" and the second is "What will I need to know when I find it?".

When things go wrong, you'll probably find that you haven't answered those questions completely correctly (you never seem to have the right message in the right place to give you an absolutely correct answer). But you'll have a better log message than if you hadn't asked the questions at all.