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的日志范圍