.NET Worker Service 添加 Serilog 日志記錄

前面我們了解了 .NET Worker Service 的入門(mén)知識(shí)^[1] 和 如何優(yōu)雅退出 Worker Service ^[2]，今天我們接著介紹一下如何為 Worker Service 添加 Serilog 日志記錄。

在實(shí)際的生產(chǎn)環(huán)境中，應(yīng)用程序中記錄日志是非常寶貴的。在許多情況下，開(kāi)發(fā)人員無(wú)法直接訪問(wèn)生產(chǎn)環(huán)境來(lái)調(diào)試問(wèn)題。高質(zhì)量的日志記錄為解決線上問(wèn)題提供了線索和依據(jù)。

日志記錄是將應(yīng)用程序操作和狀態(tài)記錄到輔助接口的過(guò)程。

.NET 日志記錄框架

.NET 中有很多默認(rèn)的日志記錄提供程序^[3]，它們可以將日志輸出到控制臺(tái)、Debug、EventSource 和 EventLog 等，例如在上一篇的示例中，默認(rèn)的實(shí)現(xiàn)是將日志記錄輸出到了控制臺(tái)窗口。

但是 .NET 中沒(méi)有可以幫我們將日志信息輸出到文件和數(shù)據(jù)庫(kù)的內(nèi)置提供程序，而這卻是我們?cè)谏a(chǎn)環(huán)境中十分常見(jiàn)的應(yīng)用場(chǎng)景。為了實(shí)現(xiàn)這一功能，我們需要為 .NET 實(shí)現(xiàn)自定義的日志記錄提供程序^[4]，這需要大量時(shí)間，因?yàn)樾枰紤]很多事情，比如讀寫(xiě)性能、存儲(chǔ)空間、配置等等。

幸運(yùn)的是，一些優(yōu)秀的第三方程序包可以為我們提供幫助，.NET 中三種最流行的日志框架分別是：log4net、NLog、Serilog，我們只需從 NuGet 包存儲(chǔ)庫(kù)中獲取它們，然后簡(jiǎn)單地配置一下便可以愉快地使用它們了。

§log4net

log4net^[5] 是一個(gè)始于 2001 年的領(lǐng)先的日志記錄框架，最初是 Java 框架 log4j 的端口。多年來(lái)，Apache Logging Services 項(xiàng)目持續(xù)進(jìn)行開(kāi)發(fā)，沒(méi)有其他框架能像 log4net 一樣久經(jīng)考驗(yàn)。log4net 是所有現(xiàn)代 .NET 日志記錄框架的鼻祖，在日志框架中，日志級(jí)別（log levels）、記錄器(logger)和輸出模塊(appenders/targets/sinks)等概念幾乎都是通用的^[6]。相信所有多年使用 .NET 編程的朋友對(duì) log4net 都相當(dāng)熟悉。

log4net 好用、穩(wěn)定且靈活，但是它的配置相對(duì)來(lái)說(shuō)比較復(fù)雜一些，而且很難實(shí)現(xiàn)結(jié)構(gòu)化的日志記錄。

§NLog

NLog^[7] 也是一個(gè)相當(dāng)老的項(xiàng)目，最早的版本發(fā)布于 2006 年，不過(guò)目前仍在積極開(kāi)發(fā)中。NLog 從 v4.5 版本開(kāi)始新增了對(duì)結(jié)構(gòu)化日志記錄的支持。

與 log4net 相比，NLog 的配置更加容易，并且基于代碼的配置也比較簡(jiǎn)潔。NLog 中的默認(rèn)設(shè)置比 log4net 中的默認(rèn)設(shè)置會(huì)更合理一些。需要注意的一點(diǎn)是，當(dāng)使用這兩個(gè)框架，您可能會(huì)遇到同一個(gè)問(wèn)題，那就是配置有問(wèn)題（比如忘記復(fù)制配置文件）時(shí)，不會(huì)得到任何提示，也不會(huì)輸出日志信息。假如您將應(yīng)用部署上線以后遇到這個(gè)情況，這將是致命的，因?yàn)樵S多問(wèn)題的檢查都是依賴于日志記錄的。當(dāng)然，這么設(shè)計(jì)的初衷是避免讓?xiě)?yīng)用程序因日志問(wèn)題而導(dǎo)致崩潰。

§Serilog

Serilog^[8] 日志記錄框架發(fā)布于 2013 年，相對(duì)來(lái)說(shuō)是一個(gè)較新的框架。與其他日志框架不同的是，Serilog 在設(shè)計(jì)時(shí)考慮了強(qiáng)大的結(jié)構(gòu)化事件數(shù)據(jù)，提供了開(kāi)箱即用的結(jié)構(gòu)化日志實(shí)現(xiàn)。所以 Serilog 對(duì)結(jié)構(gòu)化日志的支持非常好，而且配置簡(jiǎn)潔。Serilog 中的日志可以發(fā)送到許多終端，Serilog 稱這些終端為“輸出模塊庫(kù)(sinks)”。您可以在 https://github.com/serilog/serilog/wiki/Provided-Sinks 頁(yè)面查看非常全面的列表。

Serilog 中還有一個(gè)功能強(qiáng)大的概念是Enricher，可以通過(guò)各種方式來(lái)豐富日志事件的屬性，從而向日志添加新的信息。NuGet 中提供了一些預(yù)建的 Enricher，您也可以通過(guò)實(shí)現(xiàn) ILogEventEnricher 構(gòu)建自己的 Enricher。

結(jié)構(gòu)化日志記錄

或許您已注意到了，前面我多次提到結(jié)構(gòu)化日志記錄，那么什么是結(jié)構(gòu)化日志記錄，為什么我要強(qiáng)調(diào)結(jié)構(gòu)化日志記錄呢？

通常情況下，您會(huì)發(fā)現(xiàn)日志信息基本上包含兩部分內(nèi)容：消息模板和值，而 .NET 通常只接受諸如 string.Format(...) 這樣的的輸入字符串。比如：

var position = new { Latitude = 25, Longitude = 134 };
var elapsedMs = 34;

log.Information("Processed Position, Latitude:{0}, Longitude: {1} in Elapsed:{2} ms.", position.Latitude, position.Longitude, elapsedMs);

這條日志只是簡(jiǎn)單地被轉(zhuǎn)換為文本輸出到日志文件中：

[INF] Processed Position, Latitude:25, Longitude: 134 in Elapsed:34 ms.

這看起來(lái)很好，但它可以更好！

當(dāng)我們遇到問(wèn)題的時(shí)候，我們需要根據(jù)一些已知的信息來(lái)檢索日志記錄。比如，假設(shè)我們已知 Latitude 為 25，Longitude 為 134，我們要查找這條日志的話，該怎么做呢？由于上面輸出的日志信息是簡(jiǎn)單的文本，有經(jīng)驗(yàn)的您可能立馬會(huì)想到使用正則表達(dá)式或者簡(jiǎn)單的字符串匹配，但這樣不僅不夠直觀，實(shí)現(xiàn)起來(lái)也比較麻煩。有沒(méi)有更好的方法呢？

如果我們?cè)诖鎯?chǔ)日志的時(shí)候，將其中包含值的部分作為特征提取出來(lái)，形成由鍵和值組成的有結(jié)構(gòu)的 JSON 對(duì)象，作為每條日志記錄的屬性(properties)：

{"Position": {"Latitude": 25, "Longitude": 134}, "Elapsed": 34}

然后，在我們檢索的時(shí)候只需要查找日志記錄的 properties 就可以了，它是結(jié)構(gòu)化的，檢索起來(lái)既方便又直觀。

Serilog 幫我們實(shí)現(xiàn)了這一點(diǎn)，您只需改動(dòng)一行代碼就可以了：

log.Information("Processed {@Position} in {Elapsed:000} ms.", position, elapsedMs);

Position 前面的 @ 是解構(gòu)操作符，它告訴 Serilog 需要將傳入的對(duì)象序列化，而不是調(diào)用 ToString() 轉(zhuǎn)換它。

Elapsed 之后的 :000 是一個(gè)標(biāo)準(zhǔn)的 .NET 格式字符串，它決定該屬性的呈現(xiàn)方式。

為 Worker Service 添加 Serilog 日志

現(xiàn)在，您已經(jīng)大概了解了 Serilog，以及為什么我會(huì)選用它的原因。下面我用一個(gè)實(shí)例來(lái)介紹一下它的用法。

需要用到的開(kāi)發(fā)工具：

• Visual Studio Code：(https://code.visualstudio.com/)

• 最新的 .NET SDK：(https://dotnet.microsoft.com/download)

• DBeaver：(https://dbeaver.io/)

本示例基于上一篇文章中的 Worker Service 源碼^[9]修改，如果您安裝有 git，可以用下面的命令獲取它：

git clone [email protected]:ITTranslate/WorkerServiceGracefullyShutdown.git

然后，使用 Visual Studio Code 打開(kāi)此項(xiàng)目，運(yùn)行一下，以確保一切正常：

dotnet build
dotnet run

您在 Serilog 官方文檔中可以看到很多例子，不過(guò)大部分示例都是使用編碼的方式配置 Serilog，或者以 xml 的方式配置在老舊項(xiàng)目的 AppSettings 文件中。

在本文的示例中，我將以 JSON 的方式把 Serilog 的配置放置在現(xiàn)在流行的 appsettings.json 配置文件中。我們只需要修改 Program.cs 和 appsettings.json，不需要修改 Worker.cs。

§安裝依賴程序包

首先，安裝我們所需的程序包：

dotnet add package Serilog
dotnet add package Serilog.Settings.Configuration
dotnet add package Serilog.Extensions.Hosting
dotnet add package Serilog.Sinks.Console
dotnet add package Serilog.Sinks.RollingFile

§修改 Program

然后，修改 Program 中的 Main 方法，從 appsettings.json 讀取配置并根據(jù)配置構(gòu)建 Serilog 日志記錄器的實(shí)例：

public static void Main(string[] args)
{
    var configuration = new ConfigurationBuilder()
        .SetBasePath(Directory.GetCurrentDirectory())
        .AddJsonFile("appsettings.json")
        .AddJsonFile($"appsettings.{Environment.GetEnvironmentVariable("DOTNET_ENVIRONMENT") ?? "Production"}.json", true)
        .Build();

    // 全局共享的日志記錄器
    Log.Logger = new LoggerConfiguration()
        .ReadFrom.Configuration(configuration)
        .Enrich.FromLogContext()
        .CreateLogger();

    try
    {
        var separator = new string('-', 30);

        Log.Information($"{separator} Starting host {separator} ");

        CreateHostBuilder(args).Build().Run();

        Log.Information($"{separator} Exit host {separator} ");
    }
    catch (Exception ex)
    {
        Log.Fatal(ex, "Host terminated unexpectedly");
    }
    finally
    {
        Log.CloseAndFlush(); // 釋放資源
    }
}

修改 Program 中的 CreateHostBuilder 方法，將 Serilog 設(shè)置為日志提供程序：

public static IHostBuilder CreateHostBuilder(string[] args) =>
    Host.CreateDefaultBuilder(args)
        .ConfigureServices((hostContext, services) =>
        {
            services.AddHostedService<Worker>();
        })
        .UseSerilog(); //將 Serilog 設(shè)置為日志提供程序

§修改配置文件 appsettings.json

修改應(yīng)用程序配置文件 appsettings.json，添加 Serilog 節(jié)點(diǎn)(Section)。

Serilog 所需的配置節(jié)點(diǎn)名稱默認(rèn)為 Serilog；當(dāng)然，您也可以改變它，但要在讀取的時(shí)候指定節(jié)點(diǎn)名。

{
  "Serilog": {
    "Using": [
      "Serilog.Sinks.Console",
      "Serilog.Sinks.RollingFile"
    ],
    "MinimalLevel": {
      "Default": "Information",
      "Override": {
        "System": "Warning",
        "Microsoft": "Information"
      }
    },
    "WriteTo": [
      {
        "Name": "Console"
      },
      {
        "Name": "RollingFile",
        "Args": {
          "pathFormat": "Logs\\{Hour}.txt",
        }
      }
    ]
  }
}

看一下我們都配置了什么：

您可以在 Serilog.Settings.Configuration 包^[10] 的文檔中找到這些配置的說(shuō)明。

Using 節(jié)點(diǎn)

Using 節(jié)點(diǎn)包含了所需的程序集列表，用于自動(dòng)發(fā)現(xiàn) WriteTo 和 Enrich 等節(jié)點(diǎn)中配置的方法所屬的程序集。

對(duì)于 .NET Core 項(xiàng)目，構(gòu)建工具會(huì)生成 .deps.json 文件，并且 Serilog.Settings.Configuration 包使用 Microsoft.Extensions.DependencyModel 實(shí)現(xiàn)了一個(gè)約定，從而可以從名稱任意位置帶有Serilog 的依賴程序包中找出正確的包，并從中提取配置的方法。因此，上面示例中的 Using 節(jié)點(diǎn)是可以省略的。

MinimalLevel 節(jié)點(diǎn)

MinimumLevel 對(duì)象配置輸出日志的最低級(jí)別。添加 MinimalLevel.Override 項(xiàng)，可以覆蓋某些特定命名空間的最小級(jí)別。

WriteTo 節(jié)點(diǎn)

使用 WriteTo 對(duì)象配置輸出模塊(sinks)，可以同時(shí)配置并激活多個(gè)輸出模塊。本示例中我們配置了 Console 和 RollingFile，前者將日志輸出到控制臺(tái)，后者將日志輸出到滾動(dòng)文件中。

將日志輸出到文件，您還可以使用 Serilog.Sinks.File 程序包，它也支持滾動(dòng)文件。

Args 用于配置 Sink 的選項(xiàng)。本例中 pathFormat 配置了日志文件的存放位置，該項(xiàng)的值中 {Hour} 是滾動(dòng)日志文件的 文件名格式說(shuō)明符。該輸出模塊支持三種不同的文件名格式說(shuō)明符（區(qū)分大小寫(xiě)）：

• {Date}：每天創(chuàng)建一個(gè)文件。文件名使用 yyyyMMdd 格式。

• {Hour}：每小時(shí)創(chuàng)建一個(gè)文件。文件名使用 yyyyMMddHH 格式。

• {HalfHour}：每半小時(shí)創(chuàng)建一個(gè)文件。文件名使用 yyyyMMddHHmm 格式。

完成以上這些配置后，我們運(yùn)行應(yīng)用程序：

dotnet build
dotnet run

您會(huì)發(fā)現(xiàn)在應(yīng)用程序根目錄下多了一個(gè) Logs 文件夾，可以將日志信息正常輸出到文件了。同時(shí)，控制臺(tái)也有輸出日志。兩者的輸出格式略有不同，控制臺(tái)中的輸出更簡(jiǎn)潔一些。

§添加 Enricher 和格式化輸出

前文我提到過(guò) Serilog 中還有一個(gè)功能強(qiáng)大的概念是Enricher，這里我就以預(yù)建的 Enricher 來(lái)舉例說(shuō)明一下它的使用。

添加以下依賴程序包：

dotnet add package Serilog.Enrichers.Thread
dotnet add package Serilog.Enrichers.Environment
dotnet add package Serilog.Enrichers.Process

這三個(gè) Enricher 分別提供了不同的信息以豐富日志事件的屬性。

• Serilog.Enrichers.Environment 提供 WithMachineName() 和 WithEnvironmentUserName()

• Serilog.Enrichers.Process 提供 WithProcessId()

• Serilog.Enrichers.Thread 提供 WithThreadId()

修改 appsettings.json，向 Serilog 配置對(duì)象添加 Enrich 配置節(jié)點(diǎn)，以豐富日志事件的信息：

"Enrich": [
  "WithMachineName",
  "WithProcessId",
  "WithProcessName",
  "WithThreadId"
]

修改 appsettings.json，向 WriteTo 下的 RollingFile 對(duì)象節(jié)點(diǎn)的 Args 添加一個(gè) outputTemplate 選項(xiàng)，以自定義輸出消息模板：

{
  "Name": "RollingFile",
  "Args": {
    "pathFormat": "Logs\\{HalfHour}.txt",
    "outputTemplate": "{Timestamp:o} [{Level:u3}] ({MachineName}/{ProcessId}/{ProcessName}/{ThreadId}) {Message}{NewLine}{Exception}"
  }
}

修改好配置后，重新運(yùn)行應(yīng)用程序：

dotnet build
dotnet run

再查看一下日志文件，您會(huì)發(fā)現(xiàn)日志已經(jīng)按我們自定義的格式輸出了，并且多了一些我們使用 Enricher 獲得的信息：(計(jì)算機(jī)名/進(jìn)程ID/進(jìn)程名稱/線程ID)。

2021-05-27T18:15:40.2992230+08:00 [INF] (DESKTOP-6LTYU3O/54376/MyService/1) Worker running at: 05/27/2021 18:15:40 +08:00

將日志保存到數(shù)據(jù)庫(kù)

前文我提到過(guò)日志文件的屬性(properties)，為什么直到現(xiàn)在還沒(méi)有看到過(guò)它呢？

這是因?yàn)椋?dāng) Serilog 將日志事件寫(xiě)入文件或控制臺(tái)時(shí)，消息模板和屬性將僅會(huì)呈現(xiàn)為易于閱讀的友好文本。而當(dāng)我們將日志事件發(fā)送到基于云的日志服務(wù)器、數(shù)據(jù)庫(kù)和消息隊(duì)列等輸出模塊(sinks)時(shí)，就可以保存為結(jié)構(gòu)化的數(shù)據(jù)了。

為了簡(jiǎn)便起見(jiàn)，我以 SQLite 數(shù)據(jù)庫(kù)為例來(lái)介紹一下。

添加 SQLite 依賴程序包：

dotnet add package Serilog.Sinks.SQLite

修改 appsettings.json，在 Serilog 配置中的 WriteTo 節(jié)點(diǎn)下添加以下配置節(jié)點(diǎn)，以向 SQLite 輸出日志：

{
  "Name": "SQLite",
  "Args": {
    "sqliteDbPath": "Logs\\log.db",
    "tableName": "Logs",
    "maxDatabaseSize": 1,
    "rollOver": true
  }
}

解釋一下 Args 各個(gè)選項(xiàng)的作用：

• sqliteDbPath： SQLite 數(shù)據(jù)庫(kù)的路徑。

• tableName： 用于存儲(chǔ)日志的 SQLite 表的名稱。

• maxDatabaseSize： 數(shù)據(jù)庫(kù)的最大文件大小，可以以 MB 為單位增加。默認(rèn)為 10MB，最大為 20GB。為了方便測(cè)試，我在這里將其設(shè)置為 1MB。

• rollOver： 如果文件大小超過(guò)最大數(shù)據(jù)庫(kù)文件大小，則創(chuàng)建滾動(dòng)備份，默認(rèn)為 true。

此時(shí)，再次運(yùn)行應(yīng)用程序：

dotnet build
dotnet run

您將會(huì)在應(yīng)用程序目錄下的 Logs 文件夾中看到一個(gè) SQLite 數(shù)據(jù)庫(kù)文件 log.db。使用 DBeaver 打開(kāi)檢查一下：

可以看到，SQLite 輸出模塊自動(dòng)為我們創(chuàng)建了數(shù)據(jù)庫(kù)和表，日志記錄成功了。

我們配置了數(shù)據(jù)庫(kù)文件大于 1MB 時(shí)自動(dòng)滾動(dòng)備份，可以多輸出一些日志測(cè)試一下，看它是否有自動(dòng)滾動(dòng)備份。我的測(cè)試結(jié)果如下圖：

再看一下 Serilog 捕獲的日志事件的屬性(properties)：

Serilog 使用消息模板、以及命名和位置參數(shù)擴(kuò)展 .NET 的格式化字符串，不過(guò) Serilog 捕獲與每個(gè)命名參數(shù)相關(guān)聯(lián)的值，而不是直接將事件格式化為文本。我們添加幾行代碼，測(cè)試一下 Serilog 捕獲日志事件的情況：

var position = new { Latitude = 25, Longitude = 134 };
var elapsedMs = 34;
Log.Information("Processed {@Position} in {Elapsed:000} ms.", position, elapsedMs);

上面的示例在日志事件中記錄了兩個(gè)屬性：Position 和 Elapsed，Position 前面的 @ 操作符告訴 Serilog 要序列化傳入的對(duì)象。最終我們?cè)跀?shù)據(jù)庫(kù)中存儲(chǔ)的結(jié)構(gòu)化的 Properties 如下所示：

{"Position":{"Latitude":25,"Longitude":134},"Elapsed":34,"MachineName":"DESKTOP-6LVG1OL","ProcessId":54332,"ProcessName":"MyService","ThreadId":1}

Serilog 對(duì)結(jié)構(gòu)化事件數(shù)據(jù)深入且豐富的支持，開(kāi)創(chuàng)了原本使用傳統(tǒng)日志記錄器所沒(méi)有的巨大的診斷可能性。

總結(jié)

在本文中，我介紹了 .NET 中常用的結(jié)構(gòu)化事件日志框架 Serilog，以及使用它的原因和好處；并通過(guò)一個(gè) .NET Worker Service 實(shí)例，說(shuō)明如何將日志保存到滾動(dòng)文件和數(shù)據(jù)庫(kù)中。

Serilog 是一個(gè)穩(wěn)定的、配置簡(jiǎn)潔的、功能強(qiáng)大的、可擴(kuò)展的、支持結(jié)構(gòu)化日志事件的 .NET 日志記錄提供程序，值得我們?cè)趹?yīng)用中廣泛使用。

您可以從 GitHub 下載本文中的源碼^[11]。