ASP.NET Core 6框架揭秘实例演示[14]：日志的进阶用法

为了对各种日志框架进行整合，微软创建了一个用来提供统一的日志编程模式的日志框架。《日志的基本编程模式》以实例演示的方式介绍了日志的基本编程模式，现在我们来补充几种“进阶”用法。(本篇提供的实例已经汇总到《ASP.NET Core 6框架揭秘-实例演示版》）

[S808]利用配置定义日志过滤规则（源代码）
[S809]利用日志范围输出调用链（源代码）
[S810]LoggerMessage的应用（源代码）
[S812]基于Activity的日志范围（源代码）

[S808]利用配置定义日志过滤规则

通过Func<string, string, LogLevel, bool>对象表示的日志过滤规还可以采用配置的形式来定义。以配置的形式定义的过滤规则最终都体现为对最低等级的设置，设定的这个最低日志等级可以是一个全局的默认设置，也可以专门针对某个日志类别或者ILoggerProvider类型。下面演示针对配置形式的日志过滤规则。我们先创建一个名为logging.json的文件，并在其中定义如下这段配置，然后将“Copy to Output Directory”的属性设置为“Copy Always”。这段配置定义了两组日志过滤规则，第一组是默认规则，第二组则是专门为ConsoleLoggerProvider（别名为Console）定义的过滤规则。

{
    "LogLevel": {
        "Default"	: "Error",
        "Foo"		: "Debug"
    },
    "Console": {
        "LogLevel": {
            "Default"	: "Information",
            "Foo"	: "Warning",
            "Bar"	: "Error"
        }
    }
}

以配置形式定义的日志过滤规则最终会落实到对最低日志等级的设置上，其中Default表示默认设置，其他的则是针对具体日志类别的设置。上面定义的这段配置体现的过滤规则如下：对于ConsoleLoggerProvider来说，在默认情况下只有等级不低于Information的日志事件会被输出，而对日志类别“Foo”和“Bar”来说，对应的最低日志等级分别为Warning和Error。对于其他ILoggerProvider类型来说，如果日志类别为“Foo”，那么只有等级不低于Debug的日志才会被输出，其他日志类别则采用默认的等级Error。

为了检验最终是否会采用配置定义的规则对日志消息进行过滤，我们根据配置文件生成对应的IConfiguration对象，然后采用依赖注入的方式创建一个ILoggerFactory对象。我们将IConfiguration对象作为参数调用ILoggingBuilder接口的AddConfiguration扩展方法将配置承载的过滤规则应用到配置模型上。我们最终采用不同的类别（“Foo”、“Bar”和“Baz”）创建了三个ILogger对象，并利用它们记录了六条具有不同等级的日志。

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

var configuration = new ConfigurationBuilder()
    .SetBasePath(Directory.GetCurrentDirectory())
    .AddJsonFile("logging.json")
    .Build();

var loggerFactory = new ServiceCollection()
    .AddLogging(builder => builder
        .AddConfiguration(configuration)
        .AddConsole()
        .AddDebug())
    .BuildServiceProvider()
    .GetRequiredService<ILoggerFactory>();


Log(loggerFactory, "Foo");
Log(loggerFactory, "Bar");
Log(loggerFactory, "Baz");

Console.Read();

static void Log(ILoggerFactory loggerFactory, string category)
{
    var logger = loggerFactory.CreateLogger(category);
    var levels = (LogLevel[])Enum.GetValues(typeof(LogLevel));
    levels = levels.Where(it => it != LogLevel.None).ToArray();
    var eventId = 1;
    Array.ForEach(levels, level => logger.Log(level, eventId++, "This is a/an {0} log message.", level));

由于我们注册了两个不同的ILoggerProvider类型，创建了三种基于不同日志类别的ILogger对象，所以这里面涉及分发的36条日志消息。而图1是程序执行（以Debug模式进行编译）之后控制台和Visual Studio调试输出窗口的输出结果。

图1　针对配置文件的日志过滤

[S809]利用日志范围输出调用链

日志可以为针对某种目的（如纠错查错、系统优化和安全审核等）而进行的分析提供原始数据，所以孤立存在的一条日志消息对数据分析往往毫无用处，很多问题只有将多条相关的日志消息综合起来分析才能找到答案。日志框架为此引入了日志范围（Log Scope）的概念。所谓的日志范围是为日志记录创建的一个具有唯一标识的上下文，如果注册的ILoggerProvider对象支持这个特性，那么它提供的ILogger对象会感知到当前日志范围的存在，此时它可以将上下文信息一并记录下来。

在接下来演示的实例中，我们将一个包含多个处理步骤的事务作为日志范围，并将各个步骤的执行耗时记录下来。如下面的代码片段所示，我们利用依赖注入容器创建一个ILogger对象。在调用AddConsole扩展方法注册ConsoleLoggerProvider对象之后，我们接着调用AddSimpleConsole扩展方法为它注册了一个简单的格式化器，该方法接受一个Action<SimpleConsoleFormatterOptions>对象作为参数来对格式化器配置选项进行设置。我们利用传入的这个委托将配置选项的IncludeScopes属性设置为True。

using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;
using System.Diagnostics;

var logger = new ServiceCollection()
    .AddLogging(builder => builder
        .AddConsole()
        .AddSimpleConsole(options => options.IncludeScopes = true))
    .BuildServiceProvider()
    .GetRequiredService<ILogger<Program>>();

using (logger.BeginScope($"Foobar Transaction[{Guid.NewGuid()}]"))
{
    var stopwatch = Stopwatch.StartNew();
    await Task.Delay(500);
    logger.LogInformation("Operation foo completes at {0}", stopwatch.Elapsed);

    await Task.Delay(300);
    logger.LogInformation("Operation bar completes at {0}", stopwatch.Elapsed);

    await Task.Delay(800);
    logger.LogInformation("Operation baz completes at {0}", stopwatch.Elapsed);
}
Console.Read();

日志范围是通过调用ILogger对象的BeginScope方法创建的，我们在调用这个方法时指定一个携带请求ID的字符串来描述并标识创建日志范围。创建的日志范围上下文体现为一个IDisposable对象，范围因Dispose方法的调用而终结。对于支持日志范围的ILoggerProvider对象来说，它提供的ILogger对象自身能够感知到当前上下文的存在，所以我们演示程序并不需要作额外的修改。在我们演示的程序中，执行的事务包含三个操作（Foo、Bar和Baz）。我们将事务开始的那一刻作为基准，记录每个操作完成的时间。该程序启动后会将日志以图2所示的形式输出到控制台上，可以看出包含事务ID的日志范围上下文描述信息一并被记录下来。如果日志最终被写入海量存储中，只要知道请求ID，我们就能将相关的日志提取出来并利用它们构建出该请求的调用链。

图2　记录日志范围上下文

[S810]LoggerMessage的应用

前面演示的程序总是指定一个包含占位符（“{数字}”或者“{文本}”）的消息模板作为参数调用ILogger对象的Log方法来记录日志，所以该方法每次都需要对提供的消息模板进行解析。如果每次提供的都是相同的消息模板，那么这种对消息模板的重复解析就会显得多余。如果应用对性能要求比较高，这绝不是一种好的编程方式。为了解决这个问题，日志框架提供了一个名为LoggerMessage的静态类型，我们可以利用它根据某个具体的消息模板创建一个委托来记录日志。在如下所示的演示程序中，我们利用日志将针对FoobarAsync方法的“调用现场”记录先来，具体记录的内容包括输入参数、返回值和执行耗时。如代码片段所示，我们根据FoobarAsync的定义调用LoggerMessage类型的静态Define方法创建了一个Action<ILogger, int, long, double, TimeSpan, Exception>类型的委托对象来记录日志。

using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;
using System.Diagnostics;

var random = new Random();
var template = "Method FoobarAsync is invoked." +
    "\n\t\tArguments: foo={foo}, bar={bar}" +
    "\n\t\tReturn value: {returnValue}" +
    "\n\t\tTime:{time}";
var log = LoggerMessage.Define<int, long, double, TimeSpan>(
    logLevel: LogLevel.Trace,
    eventId: 3721,
    formatString: template);
var logger = new ServiceCollection()
    .AddLogging(builder => builder
        .SetMinimumLevel(LogLevel.Trace)
        .AddConsole())
    .BuildServiceProvider()
    .GetRequiredService<ILoggerFactory>()
.CreateLogger("App.Program");

await FoobarAsync(random.Next(), random.Next());
await FoobarAsync(random.Next(), random.Next());
Console.Read();

async Task<double> FoobarAsync(int foo, long bar)
{
    var stopwatch = Stopwatch.StartNew();
    await Task.Delay(random.Next(100, 900));
    var result = random.Next();
    log(logger, foo, bar, result, stopwatch.Elapsed, null);
    return result;
}

在调用Define方法构建对应的委托对象时，我们指定了日志等级（Information）、EventId（3721）和日志消息模板。我们在FoobarAsync中利用创建的这个委托对象将当前方法的参数、返回值和执行时间通过日志记录下来。FoobarAsync方法总共被调用了两次，所以程序执行后在控制台上输出的两组数据如图3所示。

图3　利用LoggerMessage记录日志

[S812]基于Activity的日志范围

S809开篇演示了通过调用ILogger的BeginScope<TState>方法的构建日志范围的方式，我们接下来演示一下基于Activity的日志范围构建。如下面的代码片段所示，在调用IServiceCollection接口的AddLogging扩展方法时，我们调用了ILoggingBuilder的Configure方法对LoggerFactoryOptions配置选项的ActivityTrackingOptions属性进行了设置，其目的在于Activity中提取TraceId、SpanId和ParentId来描述跟踪操作。

using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;
using System.Diagnostics;

var logger = new ServiceCollection()
    .AddLogging(builder => builder
        .Configure(options => options.ActivityTrackingOptions = ActivityTrackingOptions.TraceId | ActivityTrackingOptions.SpanId | ActivityTrackingOptions.ParentId)
        .AddConsole()
        .AddSimpleConsole(options => options.IncludeScopes = true))
    .BuildServiceProvider()
    .GetRequiredService<ILogger<Program >>();

ActivitySource.AddActivityListener(
    new ActivityListener { ShouldListenTo = _ => true, Sample = Sample });
var source = new ActivitySource("App");
using (source.StartActivity("Foo"))
{
    logger.Log(LogLevel.Information, "This is a log written in scope Foo.");
    using (source.StartActivity("Bar"))
    {
        logger.Log(LogLevel.Information, "This is a log written in scope Bar.");
        using (source.StartActivity("Baz"))
        {
            logger.Log(LogLevel.Information, "This is a log written in scope Baz.");
        }
    }
}

Console.Read();

static ActivitySamplingResult Sample(ref ActivityCreationOptions<ActivityContext> options)=> ActivitySamplingResult.AllData;

我们利用调用ActivitySource对象的StartActivity方法来创建和启动代表跟踪操作的Activity对象。我们知道只有具有匹配的ActivityListener，并且采样结果不为None的情况下，ActivitySource才会真正将Activity对象创建出来，所以我们人为注册了一个ActivityListener对象。程序运行之后，携带范围信息（调用堆栈信息）的日志会以图4的形式输出到控制台上。

图4　基于Activty的日志范围