.Net Core Logging模块源码阅读

前言

在Asp.Net Core Webapi项目中经常会用到ILogger,于是在空闲的时候就clone了一下官方的源码库下来研究,这里记录一下。

核心类

日志模块中最核心的类其实就是三个: ILogger、ILoggerFactory、ILoggerProvider,三者的作用如下:

  1. ILogger:负责根据日志级别写入日志
  2. ILoggerProvider:负责创建ILogger(但不应该直接使用它来创建一个ILogger)
  3. ILoggerFactory:用于注册一个或者多个ILoggerProvider,然后工厂用所有的这些Provider来创建ILogger

下面我们从一个控制台应用开始逐步深入学习:

using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Console;

// A
LoggerFactory loggerFactory=new LoggerFactory();
// B  (注意这里是演示使用,实际上不能传default,应该传一个配置,后面给出能运行的示例)
loggerFactory.AddProvider(new ConsoleLoggerProvider(default));
// C
var logger=loggerFactory.CreateLogger("default");
// D
logger.LogInformation("Hello World");

上面四行代码我分别用ABCD标注,我们可以打开官方的源码来进行学习。

首先是A行,我们创建了一个LoggerFactory,我们先看一下这个类里面到底有什么重要的东西:

public interface ILoggerFactory : IDisposable
{
    /// <summary>
    /// Creates a new <see cref="ILogger"/> instance.
    /// </summary>
    /// <param name="categoryName">The category name for messages produced by the logger.</param>
    /// <returns>The <see cref="ILogger"/>.</returns>
    ILogger CreateLogger(string categoryName);

    /// <summary>
    /// Adds an <see cref="ILoggerProvider"/> to the logging system.
    /// </summary>
    /// <param name="provider">The <see cref="ILoggerProvider"/>.</param>
    void AddProvider(ILoggerProvider provider);
}
public class LoggerFactory : ILoggerFactory
{
    // 创建Logger时会添加对应Category的Logger
    private readonly Dictionary<string, Logger> _loggers = new Dictionary<string, Logger>(StringComparer.Ordinal);
    // 添加LoggingProvider的时候会加入到这个列表中
    private readonly List<ProviderRegistration> _providerRegistrations = new List<ProviderRegistration>();
    // 构造函数 默认没有任何Provider
    public LoggerFactory() : this(Array.Empty<ILoggerProvider>())
    {
    }
}

从上面的代码中可以看出在创建的时候其实啥也没干,只是创建了一个空的LoggerFactory,然后我们看一下B行,这里我们添加了一个ConsoleLoggerProvider,这个类是干嘛的呢?我们看一下它的代码:

/// <summary>
/// Adds the given provider to those used in creating <see cref="ILogger"/> instances.
/// </summary>
/// <param name="provider">The <see cref="ILoggerProvider"/> to add.</param>
public void AddProvider(ILoggerProvider provider)
{
    lock (_sync)
    {
        // 添加对应的provider,第二个参数dispose的意思是当LogFactory被销毁时是否也同时销毁这个Provider,这个参数在使用IOC容器时非常重要
        AddProviderRegistration(provider, dispose: true);
        // 下面这段代码的逻辑是:当添加了一个新的LogProvider时,更新所有已经创建的Logger,让它们也能够使用新的Provider
        foreach (KeyValuePair<string, Logger> existingLogger in _loggers)
        {
            Logger logger = existingLogger.Value;
            LoggerInformation[] loggerInformation = logger.Loggers;

            int newLoggerIndex = loggerInformation.Length;
            Array.Resize(ref loggerInformation, loggerInformation.Length + 1);
            loggerInformation[newLoggerIndex] = new LoggerInformation(provider, existingLogger.Key);

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

当第一次阅读上面这段代码时,LoggerInformation类我们是没见过的,先看一下类的定义:

internal readonly struct LoggerInformation
{
    public LoggerInformation(ILoggerProvider provider, string category) : this()
    {
        ProviderType = provider.GetType();
        Logger = provider.CreateLogger(category);
        Category = category;
        // 这个涉及到IOC容器中多Scope的问题,如果一个Provider继承了这个接口,表示可以消费外部Scope的日志消息,这里不过多介绍
        ExternalScope = provider is ISupportExternalScope;
    }

    public ILogger Logger { get; }

    public string Category { get; }

    public Type ProviderType { get; }

    public bool ExternalScope { get; }
}

可以看出其实LoggerInformation就是一个包含了ILoggerProviderILogger的结构体,用于表示一个Logger的日志信息

好了我们回到B行代码继续看,ConsoleLoggerProvider是官方提供的控制台日志输出Provider,我们也可以从源码中看到,这里不继续讲,看C行的代码内部做了什么:

/// <summary>
/// Creates an <see cref="ILogger"/> with the given <paramref name="categoryName"/>.
/// </summary>
/// <param name="categoryName">The category name for messages produced by the logger.</param>
/// <returns>The <see cref="ILogger"/> that was created.</returns>
public ILogger CreateLogger(string categoryName)
{
    lock (_sync)
    {
        // 尝试从已经创建的Logger中获取 没获取到则创建一个对应category的Logger
        if (!_loggers.TryGetValue(categoryName, out Logger logger))
        {
            logger = new Logger
            {
                // CreateLoggers获取到的就是我们上面说的LoggerInformation,该函数代码在下面
                Loggers = CreateLoggers(categoryName),
            };
            // 使用过滤规则过滤
            (logger.MessageLoggers, logger.ScopeLoggers) = ApplyFilters(logger.Loggers);

            _loggers[categoryName] = logger;
        }

        return logger;
    }
}

// 这个函数几行代码的逻辑是根据所有的Provider创建一个对应category的LoggerInformation数组
private LoggerInformation[] CreateLoggers(string categoryName)
{
    var loggers = new LoggerInformation[_providerRegistrations.Count];
    for (int i = 0; i < _providerRegistrations.Count; i++)
    {
        loggers[i] = new LoggerInformation(_providerRegistrations[i].Provider, categoryName);
    }
    return loggers;
}

好了,到了这一步我们的Logger终于创建出来了,可以写日志了,继续看D行代码打印日志是怎么实现的:

// 第一步进入这个函数
public static void LogInformation(this ILogger logger, string? message, params object?[] args)
{
    logger.Log(LogLevel.Information, message, args);
}

// 第二步进入这个函数
public static void Log(this ILogger logger, LogLevel logLevel, string? message, params object?[] args)
{
    logger.Log(logLevel, 0, null, message, args);
}

// 第三步进入这个函数
public static void Log(this ILogger logger, LogLevel logLevel, EventId eventId, Exception? exception, string? message, params object?[] args)
{
    if (logger == null)
    {
        throw new ArgumentNullException(nameof(logger));
    }

    logger.Log(logLevel, eventId, new FormattedLogValues(message, args), exception, _messageFormatter);
}

// 第四步进入这个函数
void ILogger.Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
{
    _logger.Log(logLevel, eventId, state, exception, formatter);
}

public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
{
    // 这里的logger就是从所有prodiver中生成出来的
    MessageLogger[] loggers = MessageLoggers;
    
    for (int i = 0; i < loggers.Length; i++)
    {
        ref readonly MessageLogger loggerInfo = ref loggers[i];
        if (!loggerInfo.IsEnabled(logLevel))
        {
            continue;
        }

        LoggerLog(logLevel, eventId, loggerInfo.Logger, exception, formatter, ref exceptions, state);
    }
    // 调用所有Provider生成出来的logger,使用相应实现的Log函数从而达到输出到不同地方的目的
    static void LoggerLog(LogLevel logLevel, EventId eventId, ILogger logger, Exception exception, Func<TState, Exception, string> formatter, ref List<Exception> exceptions, in TState state)
    {
        try
        {
            logger.Log(logLevel, eventId, state, exception, formatter);
        }
        catch (Exception ex)
        {
            if (exceptions == null)
            {
                exceptions = new List<Exception>();
            }

            exceptions.Add(ex);
        }
    }
}

上面这段代码中其实有一个非常重要的地方还没说,那就是ILogger的实现其实是不止一个的,有一个普通的Logger类,还有一个泛型类Logger<T>:

internal sealed class Logger : ILogger
{

}
public interface ILogger<out TCategoryName> : ILogger
{

}
public class Logger<T> : ILogger<T>
{
    private readonly ILogger _logger;
    public Logger(ILoggerFactory factory)
    {
        _logger = factory.CreateLogger(TypeNameHelper.GetTypeDisplayName(typeof(T), includeGenericParameters: false, nestedTypeDelimiter: '.'));
    }
}

平时我们使用的都是泛型的Logger,因为Logger是internal级别的,也就是内部使用,也就是说泛型的Logger就是一个包装类,包装了一个普通的Logger,这个普通的Logger是从所有Provider中生成出来的,而泛型的Logger只是把泛型的类型名传给了普通的Logger,这样就实现了泛型的Logger的功能。

好了,到这一步我们已经可以大概明白.NET官方的日志模块是怎么个流程了,下面我们举一反三,看看Logger和IOC是怎么集成的

IOC

上来就先来一个示例:

ServiceCollection serviceCollection = new();
serviceCollection.AddLogging(configure =>
{
    configure.AddConsole();
});
using var sp=serviceCollection.BuildServiceProvider();
var logger = sp.GetRequiredService<ILogger<Program>>();
logger.LogInformation("hello world");

相信经常写.NET的对ServiceCollectionServiceProvider都不陌生,这里我们就不多说了,直接看看日志模块是怎么集成的。这里最重要的其实就一行——AddLogging,我们直接看源码:

public static IServiceCollection AddLogging(this IServiceCollection services, Action<ILoggingBuilder> configure)
{
    // 注入Option相关的类
    services.AddOptions();
    // 下面两句是核心 注入LoggerFactory和ILogger<>
    services.TryAdd(ServiceDescriptor.Singleton<ILoggerFactory, LoggerFactory>());
    services.TryAdd(ServiceDescriptor.Singleton(typeof(ILogger<>), typeof(Logger<>)));

    services.TryAddEnumerable(ServiceDescriptor.Singleton<IConfigureOptions<LoggerFilterOptions>>(
        new DefaultLoggerLevelConfigureOptions(LogLevel.Information)));
    // 新东西 下面介绍
    configure(new LoggingBuilder(services));
    return services;
}

上面这段代码中只有一个新的类,那就是LoggingBuilder,还是看源码:

internal sealed class LoggingBuilder : ILoggingBuilder
{
    public LoggingBuilder(IServiceCollection services)
    {
        Services = services;
    }

    public IServiceCollection Services { get; }
}

这个类本身看起来很简单,其实是官方把相应的逻辑都写在扩展函数里了:

public static class LoggingBuilderExtensions
{
    public static ILoggingBuilder SetMinimumLevel(this ILoggingBuilder builder, LogLevel level)
    {
        builder.Services.Add(ServiceDescriptor.Singleton<IConfigureOptions<LoggerFilterOptions>>(
            new DefaultLoggerLevelConfigureOptions(level)));
        return builder;
    }
    
    public static ILoggingBuilder AddProvider(this ILoggingBuilder builder, ILoggerProvider provider)
    {
        builder.Services.AddSingleton(provider);
        return builder;
    }
   
    public static ILoggingBuilder ClearProviders(this ILoggingBuilder builder)
    {
        builder.Services.RemoveAll<ILoggerProvider>();
        return builder;
    }

    public static ILoggingBuilder Configure(this ILoggingBuilder builder, Action<LoggerFactoryOptions> action)
    {
        builder.Services.Configure(action);
        return builder;
    }
}

好了,使用依赖注入后,所有的类都不需要自己new了,在调用GetRequiredService时,由于ILogger<T>依赖了ILoggerFactory,所以会先调用ILoggerFactory的构造函数,然后再调用ILogger<T>的构造函数,这样就实现了日志模块的注入。

官方的控制台Provider

这里属于扩展介绍,我们看一下官方的ConsoleProvider里面有什么东西:

public class ConsoleLoggerProvider : ILoggerProvider, ISupportExternalScope
{
    private readonly IOptionsMonitor<ConsoleLoggerOptions> _options;
    private readonly ConcurrentDictionary<string, ConsoleLogger> _loggers;
    private ConcurrentDictionary<string, ConsoleFormatter> _formatters;
    private readonly ConsoleLoggerProcessor _messageQueue;

    
    public ConsoleLoggerProvider(IOptionsMonitor<ConsoleLoggerOptions> options)
        : this(options, Array.Empty<ConsoleFormatter>()) { }
    public ILogger CreateLogger(string name)
    {
        if (_options.CurrentValue.FormatterName == null || !_formatters.TryGetValue(_options.CurrentValue.FormatterName, out ConsoleFormatter? logFormatter))
        {
            logFormatter = _options.CurrentValue.Format switch
            {
                ConsoleLoggerFormat.Systemd => _formatters[ConsoleFormatterNames.Systemd],
                _ => _formatters[ConsoleFormatterNames.Simple],
            };

            if (_options.CurrentValue.FormatterName == null)
            {
                UpdateFormatterOptions(logFormatter, _options.CurrentValue);
            }
        }
        return _loggers.TryGetValue(name, out ConsoleLogger? logger) ?
            logger :
            _loggers.GetOrAdd(name, new ConsoleLogger(name, _messageQueue, logFormatter, _scopeProvider, _options.CurrentValue));
    }

    public void Dispose()
    {
        _optionsReloadToken?.Dispose();
        _messageQueue.Dispose();
    }
}

上面其实最重要的东西就是两个,一个是ConsoleLoggerProcessor,还有一个就是ConsoleLogger

  1. ConsoleLoggerProcessor类里面也比较简单,就是在后台开启一个线程专门用于输出日志,这样就不会阻塞主线程了,这个类的代码就不贴了,感兴趣的可以自己看一下。
  2. ConsoleLogger就是对应记录日志类,用于实现在控制台输出日志的逻辑,如果是输出到数据库,可以自己实现一个DBLogger

此处有一个我觉得比较重要的地方要提,就是如果程序意外退出,这些没输出的日志就直接丢失了,或者日志队列里日志实在是太多了,也不一定保证能在退出时全部输出,我们可以看下代码:

internal class ConsoleLoggerProcessor : IDisposable
{
    private readonly Queue<LogMessageEntry> _messageQueue;
    public ConsoleLoggerProcessor(IConsole console, IConsole errorConsole, ConsoleLoggerQueueFullMode fullMode, int maxQueueLength)
    {
        _messageQueue = new Queue<LogMessageEntry>();
        _outputThread = new Thread(ProcessLogQueue)
        {
            IsBackground = true,
            Name = "Console logger queue processing thread"
        };
        _outputThread.Start();
    }

    public void Dispose()
    {
        CompleteAdding();

        try
        {
            _outputThread.Join(1500); // with timeout in-case Console is locked by user input
        }
        catch (ThreadStateException) { }
    }
    private void CompleteAdding()
    {
        lock (_messageQueue)
        {
            _isAddingCompleted = true;
            Monitor.PulseAll(_messageQueue);
        }
    }
}

在Dispose中有这段代码:_outputThread.Join(1500),也就是说1.5秒内日志如果没有输出完,这些日志就没有了

提一嘴Serilog

现在.NET中的日志框架很多,比如nlog,serilog,当然第二个目前更加好用(个人体验),我们注入Serilog其实也就一句话:


serviceCollection.AddLogging(configure =>
{
    configure.AddSerilog();
});

public static ILoggingBuilder AddSerilog(
      this ILoggingBuilder builder,
      ILogger logger = null,
      bool dispose = false)
{
    if (builder == null)
    throw new ArgumentNullException(nameof (builder));
    if (dispose)
    ServiceCollectionServiceExtensions.AddSingleton<ILoggerProvider, SerilogLoggerProvider>(builder.Services, (Func<IServiceProvider, SerilogLoggerProvider>) (services => new SerilogLoggerProvider(logger, true)));
    else
    builder.AddProvider((ILoggerProvider) new SerilogLoggerProvider(logger));
    builder.AddFilter<SerilogLoggerProvider>((string) null, LogLevel.Trace);
    return builder;
}

可以看到其实非常简单,其实就是把Serilog的LoggerProvider注入到DI容器中了,然后LogFactory会用这个Provider了

自己实现一个简单的Provider

我们可以自己实现一个简单Provider来加深自己的理解,其实官方也有相应的示例代码:https://github.com/dotnet/docs/tree/main/docs/core/extensions/snippets/configuration/console-custom-logging,这里也提供一个简单的示例:


public class CustomConsoleLogger:ILogger
{
    public CustomConsoleLogger(string categoryName)
    {
        CategoryName = categoryName;
    }

    public string CategoryName { get; set; }

    public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
    {
        ConsoleColor originalColor = Console.ForegroundColor;
        Console.ForegroundColor = ConsoleColor.Red;
        Console.WriteLine($"{formatter(state, exception)}");
    }

    public bool IsEnabled(LogLevel logLevel)
    {
        //默认所有级别记录
        return true;
    }

    public IDisposable BeginScope<TState>(TState state)  => default!;
}

public class CustomConsoleProvider:ILoggerProvider
{
    private readonly ConcurrentDictionary<string, CustomConsoleLogger> _loggers =
        new(StringComparer.OrdinalIgnoreCase);
    public void Dispose()
    {
        _loggers.Clear();
    }

    public ILogger CreateLogger(string categoryName)
    {
        return _loggers.GetOrAdd(categoryName, name => new CustomConsoleLogger(name));
    }
}


// 调用
ServiceCollection serviceCollection = new();
serviceCollection.AddLogging(configure =>
{
    configure.AddConsole();
    // configure.AddSerilog();
    configure.AddProvider(new CustomConsoleProvider());
});
using var sp=serviceCollection.BuildServiceProvider();
var logger = sp.GetRequiredService<ILogger<Program>>();
logger.LogInformation("测试此条日志颜色是否改变为红色");

运行后就可以看到同时输出了两种日志

参考文章

  1. ILogger、ILoggerFactory、ILoggerProvider三者关系 https://stackoverflow.com/questions/51345161/should-i-take-ilogger-iloggert-iloggerfactory-or-iloggerprovider-for-a-libra
  2. 官方文档 https://learn.microsoft.com/zh-cn/dotnet/core/extensions/custom-logging-provider
  3. 官方示例自定义一个日志提供类 https://github.com/dotnet/docs/tree/main/docs/core/extensions/snippets/configuration/console-custom-logging
01-12 11:16