Understanding ASP.NET Core - logging

Note: This article is part of the understanding ASP.NET Core series. Please check the top blog or Click here to view the full-text catalog

Get started quickly

Add log provider

In the article Host In, we talked about the Host.CreateDefaultBuilder method. By default, four logging providers (Logger Provider) including Console, Debug, EventSource and EventLog (Windows only) are added by calling the ConfigureLogging method. Then, during host Build, log related services are registered through AddLogging().

.ConfigureLogging((hostingContext, logging) =>
{
    bool isWindows = RuntimeInformation.IsOSPlatform(OSPlatform.Windows);

    if (isWindows)
    {
        logging.AddFilter<EventLogLoggerProvider>(level => level >= LogLevel.Warning);
    }

    // Add Logging configuration
    logging.AddConfiguration(hostingContext.Configuration.GetSection("Logging"));
    
    // ConsoleLoggerProvider
    logging.AddConsole();
    // DebugLoggerProvider
    logging.AddDebug();
    // EventSourceLoggerProvider
    logging.AddEventSourceLogger();

    if (isWindows)
    {
        // On Windows platform, add EventLogLoggerProvider
        logging.AddEventLog();
    }

    logging.Configure(options =>
    {
        options.ActivityTrackingOptions = ActivityTrackingOptions.SpanId
                                            | ActivityTrackingOptions.TraceId
                                            | ActivityTrackingOptions.ParentId;
    });
})

public class HostBuilder : IHostBuilder
{
    private void CreateServiceProvider()
    {
        var services = new ServiceCollection();
        
        // ...
        
        services.AddLogging();
    
        // ...
    }
}

If we don't want to use the log providers added by default, we can clear all the added log providers through ClearProviders, and then add what we want, such as Console:

public static IHostBuilder CreateHostBuilder(string[] args) =>
    Host.CreateDefaultBuilder(args)
        .ConfigureLogging(logging =>
        {
            logging.ClearProviders()
                .AddConsole();
        })
        .ConfigureWebHostDefaults(webBuilder =>
        {
            webBuilder.UseStartup<Startup>();
        });

Log

Logging providers implement the interface ILoggerProvider, which can create ILogger instances.

By injecting the service ilogger < tcategoryname >, you can easily log.

The service needs to specify the log category, which can be any string, but we agree to use the name of the class and reflect it through generics. For example, in ValuesController, the log category is the fully qualified type name of the ValuesController class.

public class ValuesController : ControllerBase
{
    private readonly ILogger<ValuesController> _logger;

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

    [HttpGet]
    public string Get()
    {
        _logger.LogInformation("ValuesController.Get");
        return "Ok";
    }
}

After requesting the get method, you can see the output "ValuesController.Get" in the console

If you want to explicitly specify the log category, you can use the ILoggerFactory.CreateLogger method:

public class ValuesController : ControllerBase
{
    private readonly ILogger _logger1;

    public ValuesController(ILoggerFactory loggerFactory)
    {
        _logger1 = loggerFactory.CreateLogger("MyCategory");
    }
}

Configuration log

In the default template, the log configuration is as follows (in the appsettings.{Environment}.json file):

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

Configure for all logging providers

LogLevel, as the name suggests, refers to the lowest level of logs to be recorded (i.e. logs greater than or equal to this level), which must be familiar to everyone. Log levels are described in detail below.

The fields in LogLevel, such as "Default" and "Microsoft" in the above example, represent the log category, that is, the generic parameters specified when we inject ILogger above. You can set the minimum logging level for each category, that is, the value corresponding to these categories.

The three log categories in the example are explained in detail below.

Default

By Default, if the classification is not specially configured (i.e. not configured in LogLevel), the Default configuration is applied.

Microsoft

All logs with categories beginning with Microsoft apply Microsoft's configuration. For example, this configuration is applied to logs of the Microsoft.AspNetCore.Routing.EndpointMiddleware category.

Microsoft.Hosting.Lifetime

All logs with categories beginning with Microsoft.Hosting.Lifetime shall be configured with Microsoft.Hosting.Lifetime. For example, classifying Microsoft.Hosting.Lifetime will apply this configuration instead of Microsoft, because Microsoft.Hosting.Lifetime is more specific than Microsoft.

OK, that's all for the above three log categories.

Returning to the example, you may not notice that there is no separate configuration for a logging provider (for example, Console only records logs of Error and above, while EventSource needs to record logs of all levels). Like this, if there is no configuration for a specific logging provider, the configuration will be applied to all logging providers.

Except Windows EventLog. EventLog must be explicitly configured, or its default LogLevel.Warning will be used.

Configure for the specified logging provider

Next, let's look at how to configure the specified logging provider. First, the above example:

{
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Microsoft": "Warning",
      "Microsoft.Hosting.Lifetime": "Information"
    },
    "Console": {
      "LogLevel": {
        "Default": "Error"
      }
    },
    "Debug": {
      "LogLevel": {
        "Microsoft": "None"
      }
    },
    "EventSource": {
      "LogLevel": {
        "Default": "Trace",
        "Microsoft": "Trace",
        "Microsoft.Hosting.Lifetime": "Trace"
      }
    }
  }
}

Just like the relationship between appsettings.{Environment}.json and appsettings.json, the configuration in Logging.{Provider}.LogLevel will overwrite the configuration in Logging.LogLevel.

For example, Logging.Console.LogLevel.Default will overwrite Logging.LogLevel.Default, and Console logger will record logs of Error and above by default.

As mentioned earlier, Windows EventLog is special. It does not inherit the configuration of Logging.LogLevel. The default log level of EventLog is LogLevel.Warning. If you want to modify it, you must explicitly specify it, such as:

{
  "Logging": {
    "EventLog": {
      "LogLevel": {
        "Default": "Information"
      }
    }
  }
}

Configured filtering principle

When creating an object instance of ilogger < tcategoryname >, ILoggerFactory will:

  1. Find a configuration that matches the logging provider. If it cannot be found, the common configuration is used.
  2. Then match the configuration category with the longest prefix. If not found, use Default configuration.
  3. If more than one configuration is matched, the last one is used.
  4. If no configuration is matched, MinimumLevel is used. This is a configuration item. The default is LogLevel.Information.

You can set the MinimumLevel using the SetMinimumLevel method in the ConfigureLogging extension.

Log Level

The log level indicates the severity of the log. It is divided into seven levels, from light to heavy (the last None is special):

log level value describe
Trace 0 Tracking level, including the most detailed information. This information may contain sensitive data, is disabled by default, and must never appear in the production environment.
Debug 1 Debug level, used by developers for development and debugging. The amount of information is generally large, so it must be used with caution in the production environment.
Information 2 Information level, which is often used.
Warning 3 Warning level, some unexpected events, but these events do not cause program errors.
Error 4 Error level, some unhandled errors or exceptions. These events will cause the current operation or request to fail, but will not cause errors in the whole application.
Critical 5 Fatal error level, which will cause errors in the whole application. For example, insufficient memory.
None 6 Indicates that no logs are logged

Logging provider

Console

The log is output to the console.

Debug

The log will be output through the System.Diagnostics.Debug class and can be viewed through the VS output window.

On Linux, it can be found under / var/log/message or / var/log/syslog

EventSource

Cross platform logging, ETW on Windows

Windows EventLog

It only works under Windows system, and the log can be viewed through "Event Viewer".

By default

  • LogName is "Application"
  • SourceName is "NET Runtime"
  • MachineName is the name of the local computer.

These fields can be modified through EventLogSettings:

public static IHostBuilder CreateHostBuilder(string[] args) =>
    Host.CreateDefaultBuilder(args)
        .ConfigureLogging(logging =>
        {
            logging.AddEventLog(settings =>
            {
                settings.LogName = "My App";
                settings.SourceName = "My Log";
                settings.MachineName = "My Computer";
            })
        })
        .ConfigureWebHostDefaults(webBuilder =>
        {
            webBuilder.UseStartup<Startup>();
        });

Logging filter

The logging filter allows you to write complex logic to control whether you want to log.

public static IHostBuilder CreateHostBuilder(string[] args) =>
    Host.CreateDefaultBuilder(args)
        .ConfigureLogging(logging =>
        {
            logging
                // Set the Microsoft minimum log level for all loggerproviders. It is recommended to configure through the configuration file
                .AddFilter("Microsoft", LogLevel.Trace)
                // Setting the Microsoft minimum log level for the ConsoleLoggerProvider is recommended through the configuration file
                .AddFilter<ConsoleLoggerProvider>("Microsoft", LogLevel.Debug)
                // Filter configuration for all loggerproviders
                .AddFilter((provider, category, logLevel) =>
                {
                    // Since the filtering configuration is added separately for the ConsoleLoggerProvider below, the ConsoleLoggerProvider will not enter this method
                
                    if (provider == typeof(ConsoleLoggerProvider).FullName
                        && category == typeof(ValuesController).FullName
                        && logLevel <= LogLevel.Warning)
                    {
                        // false: do not log
                        return false;
                    }

                    // true: log
                    return true;
                })
                // Filter configuration for ConsoleLoggerProvider
                .AddFilter<ConsoleLoggerProvider>((category, logLevel) =>
                {
                    if (category == typeof(ValuesController).FullName
                        && logLevel <= LogLevel.Warning)
                    {
                        // false: do not log
                        return false;
                    }

                    // true: log
                    return true;
                });
        })
        .ConfigureWebHostDefaults(webBuilder =>
        {
            webBuilder.UseStartup<Startup>();
        });

Log message template

In the process of application development, for a certain type of logs, we hope that their message formats are consistent, but some parameters change. This requires the log message template.

for instance:

[HttpGet("{id}")]
public int Get(int id)
{
    _logger.LogInformation("Get {Id}", id);

    return id;
}

Get {Id} is a log message template, and {Id} is a template parameter (note that please write a name instead of a number in it, so it is easier to understand the meaning of the parameter).

However, it should be noted that the template parameter {Id} is only used to make it easy to understand its meaning. It has nothing to do with the following parameter names. The template value cares about the order of parameters. For example:

[HttpGet("{id}")]
public int Get(int id)
{
    _logger.LogInformation("Get {Id} at {Time}", DateTime.Now, id);

    return id;
}

Assuming the incoming id = 1, its output is: Get 11/02/2021 11:42:14 at 1

Log message template is a very important function, which is used in many open source log middleware.

Logging during host build

The ASP.NET Core framework does not directly support logging during host build. However, you can log through a separate logging provider, for example, using a third-party logging provider: Serilog

Install Nuget package: install package serilog.aspnetcore

public static void Main(string[] args)
{
    // Read the configuration from appsettings.json and command line parameters
    var config = new ConfigurationBuilder()
        .AddJsonFile("appsettings.json")
        .AddCommandLine(args)
        .Build();

    // Create Logger
    Log.Logger = new LoggerConfiguration()
        .WriteTo.Console()                          // Output to console
        .WriteTo.File(config["Logging:File:Path"])  // Output to specified file
        .CreateLogger();
    try
    {
        CreateHostBuilder(args).Build().Run();
    }
    catch(Exception ex)
    {
        Log.Fatal(ex, "Host terminated unexpectedly");

        throw;
    }
    finally
    {
        Log.CloseAndFlush();
    }
}

appsettings.json

{
  "Logging": {
    "File": {
      "Path": "logs/host.log"
    }
  }
}

Console log format configuration

Console logging provider is essential in our development process. We have learned from the above that it can be added through AddConsole(). However, it has great limitations. We can't customize the log format.

Therefore, in. NET 5, the console logging provider is extended and three log output formats are preset: Json, Simple and system D.

In fact, there were enumerations before. The ConsoleLoggerFormat provides Simple and system D formats, but it cannot be customized and has been discarded.

These formatters are inherited from the abstract class ConsoleFormatter. The constructor of the abstract class receives a "name" parameter, which requires that its implementation class must have a name. You can get the names of three built-in formats through the static class ConsoleFormatterNames.

public abstract class ConsoleFormatter
{
    protected ConsoleFormatter(string name)
    {
        Name = name ?? throw new ArgumentNullException(nameof(name));
    }

    public string Name { get; }

    public abstract void Write<TState>(in LogEntry<TState> logEntry, IExternalScopeProvider scopeProvider, TextWriter textWriter);
}

public static class ConsoleFormatterNames
{
    public const string Simple = "simple";

    public const string Json = "json";

    public const string Systemd = "systemd";
}

When using AddConsole(), you can configure the FormatterName property of ConsoleLoggerOptions to customize the format. Its default value is "simple". However, for ease of use, the. NET framework has encapsulated the three built-in formats for us.

The option classes of these formatters inherit from the option class ConsoleFormatterOptions, which contains the following three properties:

public class ConsoleFormatterOptions
{
    // Enable scope, false by default
    public bool IncludeScopes { get; set; }

    // Set the format of the time stamp and display it at the beginning of the log message
    // The default is null, and the timestamp is not displayed
    public string TimestampFormat { get; set; }

    // Whether to set the timestamp time zone to UTC. The default is false, that is, the local time zone
    public bool UseUtcTimestamp { get; set; }
}

SimpleConsoleFormatter

A console logging provider that supports Simple format can be added through the extension method AddSimpleConsole(). The default behavior is consistent with AddConsole().

.ConfigureLogging(logging =>
{
    logging.ClearProviders()
        .AddSimpleConsole();
}

Sample output:

info: Microsoft.Hosting.Lifetime[0]
      Now listening on: http://localhost:5000
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Development
info: Microsoft.Hosting.Lifetime[0]
      Content root path: C:\Repos\WebApplication

In addition, you can make some custom configurations through simpleconconsoleformatteroptions:

.ConfigureLogging(logging =>
{
    logging.ClearProviders()
        .AddSimpleConsole(options => 
        {
            // A log message is displayed on the same line
            options.SingleLine = true;
            options.IncludeScopes = true;
            options.TimestampFormat = "yyyy-MM-dd HH:mm:ss ";
            options.UseUtcTimestamp = false;
        });
}

Sample output:

2021-11-02 15:53:33 info: Microsoft.Hosting.Lifetime[0] Now listening on: http://localhost:5000
2021-11-02 15:53:33 info: Microsoft.Hosting.Lifetime[0] Application started. Press Ctrl+C to shut down.
2021-11-02 15:53:33 info: Microsoft.Hosting.Lifetime[0] Hosting environment: Development
2021-11-02 15:53:33 info: Microsoft.Hosting.Lifetime[0] Content root path: C:\Repos\WebApplication

SystemdConsoleFormatter

A console logging provider that supports the system D format can be added through the extension method addsystemdcontrol(). If you are familiar with Linux, you must be no stranger to it.

.ConfigureLogging(logging =>
{
    logging.ClearProviders()
        .AddSystemdConsole();
}

Sample output:

<6>Microsoft.Hosting.Lifetime[0] Now listening on: http://localhost:5000
<6>Microsoft.Hosting.Lifetime[0] Application started. Press Ctrl+C to shut down.
<6>Microsoft.Hosting.Lifetime[0] Hosting environment: Development
<6>Microsoft.Hosting.Lifetime[0] Content root path: C:\Repos\WebApplication

The previous < 6 > indicates the log level info. If you are interested in understanding Systemd, you can visit Mr. Ruan Yifeng's Introduction to system D: commands

JsonConsoleFormatter

A console logging provider that supports the Json format can be added through the extension method AddJsonConsole().

.ConfigureLogging(logging =>
{
    logging.ClearProviders()
        .AddJsonConsole(options =>
        {
            options.JsonWriterOptions = new JsonWriterOptions
            {
                // Enable indentation to look more comfortable
                Indented = true
            };
        });
}

Sample output:

{
  "EventId": 0,
  "LogLevel": "Information",
  "Category": "Microsoft.Hosting.Lifetime",
  "Message": "Now listening on: http://localhost:5000",
  "State": {
    "Message": "Now listening on: http://localhost:5000",
    "address": "http://localhost:5000",
    "{OriginalFormat}": "Now listening on: {address}"
  }
}
{
  "EventId": 0,
  "LogLevel": "Information",
  "Category": "Microsoft.Hosting.Lifetime",
  "Message": "Application started. Press Ctrl\u002BC to shut down.",
  "State": {
    "Message": "Application started. Press Ctrl\u002BC to shut down.",
    "{OriginalFormat}": "Application started. Press Ctrl\u002BC to shut down."
  }
}
{
  "EventId": 0,
  "LogLevel": "Information",
  "Category": "Microsoft.Hosting.Lifetime",
  "Message": "Hosting environment: Development",
  "State": {
    "Message": "Hosting environment: Development",
    "envName": "Development",
    "{OriginalFormat}": "Hosting environment: {envName}"
  }
}
{
  "EventId": 0,
  "LogLevel": "Information",
  "Category": "Microsoft.Hosting.Lifetime",
  "Message": "Content root path: C:\\Repos\\WebApplication",
  "State": {
    "Message": "Content root path: C:\\Repos\\WebApplication",
    "contentRoot": "C:\\Repos\\WebApplication",
    "{OriginalFormat}": "Content root path: {contentRoot}"
  }
}

If you add multiple formats of console recorder at the same time, only the last one will take effect.

The above introduction is to set the console logging provider through code, but I think you should prefer to set the logging provider through configuration. Here is a simple configuration example:

{
  "Logging": {
    "LogLevel": {
      "Default": "Information",
      "Microsoft": "Warning",
      "Microsoft.Hosting.Lifetime": "Information"
    },
    "Console": {
      "FormatterName": "json",
      "FormatterOptions": {
        "SingleLine": true,
        "IncludeScopes": true,
        "TimestampFormat": "yyyy-MM-dd HH:mm:ss ",
        "UseUtcTimestamp": false,
        "JsonWriterOptions": {
          "Indented": true
        }
      }
    }
  }
}

Creation of ilogger < tcategoryname > object instance

At this point, I wonder if you have any doubts about the creation of ilogger < tcategoryname > object instance: how is it new?

To solve this problem, let's start with the AddLogging() extension method:

public static class LoggingServiceCollectionExtensions
{
    public static IServiceCollection AddLogging(this IServiceCollection services)
    {
        return AddLogging(services, builder => { });
    }

    public static IServiceCollection AddLogging(this IServiceCollection services, Action<ILoggingBuilder> configure)
    {
        services.AddOptions();

        // Registering a singleton ILoggerFactory
        services.TryAdd(ServiceDescriptor.Singleton<ILoggerFactory, LoggerFactory>());
        // Registered singleton ilogger < >
        services.TryAdd(ServiceDescriptor.Singleton(typeof(ILogger<>), typeof(Logger<>)));

        // Batch registration singleton iconfigureoptions < loggerfilteroptions >
        services.TryAddEnumerable(ServiceDescriptor.Singleton<IConfigureOptions<LoggerFilterOptions>>(
            new DefaultLoggerLevelConfigureOptions(LogLevel.Information)));

        configure(new LoggingBuilder(services));
        return services;
    }
}

As you may have guessed, this logger < > is not created by LoggerFactory? Why else sign up for this thing?

Don't worry. Let's first check the implementation class logger of ilogger < > Service:

public interface ILogger
{
    void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter);

    // Check whether logs of this log level can be recorded
    bool IsEnabled(LogLevel logLevel);

    IDisposable BeginScope<TState>(TState state);
}

public interface ILogger<out TCategoryName> : ILogger
{
}
    
public class Logger<T> : ILogger<T>
{
    // This instance is used for operation inside the interface implementation
    private readonly ILogger _logger;

    // Sure enough, the ILoggerFactory instance is injected
    public Logger(ILoggerFactory factory)
    {
        // Remember? When explicitly specifying the log category mentioned above, the ILogger instance is created in the same way
        _logger = factory.CreateLogger(TypeNameHelper.GetTypeDisplayName(typeof(T), includeGenericParameters: false, nestedTypeDelimiter: '.'));
    }
    
    // ...
}

Yes, you guessed right. Let's take a look at the LoggerFactory (just list the core code):

public interface ILoggerFactory : IDisposable
{
    ILogger CreateLogger(string categoryName);

    void AddProvider(ILoggerProvider provider);
}

public class LoggerFactory : ILoggerFactory
{
    // Logger for singleton < >
    private readonly Dictionary<string, Logger> _loggers = new Dictionary<string, Logger>(StringComparer.Ordinal);
    // Store ILoggerProviderRegistrations
    private readonly List<ProviderRegistration> _providerRegistrations = new List<ProviderRegistration>();
    private readonly object _sync = new object();

    public LoggerFactory(IEnumerable<ILoggerProvider> providers, IOptionsMonitor<LoggerFilterOptions> filterOption, IOptions<LoggerFactoryOptions> options = null)
    {
        // ...

        // Register ILoggerProviders
        foreach (ILoggerProvider provider in providers)
        {
            AddProviderRegistration(provider, dispose: false);
        }

        // ...
    }

    public ILogger CreateLogger(string categoryName)
    {
        lock (_sync)
        {
            // If it does not exist, new
            if (!_loggers.TryGetValue(categoryName, out Logger logger))
            {
                logger = new Logger
                {
                    Loggers = CreateLoggers(categoryName),
                };

                (logger.MessageLoggers, logger.ScopeLoggers) = ApplyFilters(logger.Loggers);

                // Singleton logger < >
                _loggers[categoryName] = logger;
            }

            return logger;
        }
    }
    
    private void AddProviderRegistration(ILoggerProvider provider, bool dispose)
    {
        _providerRegistrations.Add(new ProviderRegistration
        {
            Provider = provider,
            ShouldDispose = dispose
        });
        
        // ...
    }
    
    private LoggerInformation[] CreateLoggers(string categoryName)
    {
        var loggers = new LoggerInformation[_providerRegistrations.Count];
        // Loop through all iloggerproviders
        for (int i = 0; i < _providerRegistrations.Count; i++)
        {
            loggers[i] = new LoggerInformation(_providerRegistrations[i].Provider, categoryName);
        }
        return loggers;
    }
}

be careful

  • To log in the Startup.Configure method, simply inject ilogger < startup > into the parameter.
  • The use of ILogger in the Startup.ConfigureServices method is not supported because the DI container has not been configured at this time.
  • There is no asynchronous logging method. Logging actions should be performed quickly, and it is not worth using asynchronous methods at the expense of performance. If logging is time-consuming, such as logging to MSSQL, please do not write to MSSQL directly. You should consider first writing the log to a fast storage medium, such as a memory queue, and then dumping it from memory to MSSQL through a background worker thread.
  • The logging configuration cannot be changed while the application is running using the logging API. However, some configuration providers, such as file configuration providers, can reload the configuration, which can immediately update the logging configuration.

Summary

  • In the Host.CreateDefaultBuilder method, four logging providers (Logger Provider) are added by default: Console, Debug, EventSource and EventLog (Windows only).
  • Logging can be easily performed by injecting the service ilogger < tcategoryname >.
  • Logging providers can be set through code or configuration, such as LogLevel, FormatterName, etc.
  • You can add a logging filter through the extension method AddFilter, which allows you to write complex logic to control whether to log or not.
  • Log message templates are supported.
  • For the console logging program, the. NET framework has built-in three log output formats: Simple (default), Systemd and Json.
  • A new function called "compile time logging source generation" is added in the. NET 6 preview. This function is very practical. Those who are interested can go first Find out.
  • Finally, I'll give you some common log open source middleware:

Tags: ASP.NET .NET logging

Posted on Mon, 08 Nov 2021 20:20:58 -0500 by The Swedish Tower