.NET Worker Service 添加 Serilog 日誌記錄

2021 年 5 月 31 日
筆記
csharp, dotnet

前面我們了解了 .NET Worker Service 的入門知識^[1] 和如何優雅退出 Worker Service ^[2]，今天我們接著介紹一下如何為 Worker Service 添加 Serilog 日誌記錄。

在實際的生產環境中，應用程式中記錄日誌是非常寶貴的。在許多情況下，開發人員無法直接訪問生產環境來調試問題。高品質的日誌記錄為解決線上問題提供了線索和依據。

日誌記錄是將應用程式操作和狀態記錄到輔助介面的過程。

.NET 日誌記錄框架

.NET 中有很多默認的日誌記錄提供程式^[3]，它們可以將日誌輸出到控制台、Debug、EventSource 和 EventLog 等，例如在上一篇的示例中，默認的實現是將日誌記錄輸出到了控制台窗口。

但是 .NET 中沒有可以幫我們將日誌資訊輸出到文件和資料庫的內置提供程式，而這卻是我們在生產環境中十分常見的應用場景。為了實現這一功能，我們需要為 .NET 實現自定義的日誌記錄提供程式^[4]，這需要大量時間，因為需要考慮很多事情，比如讀寫性能、存儲空間、配置等等。

幸運的是，一些優秀的第三方程式包可以為我們提供幫助，.NET 中三種最流行的日誌框架分別是：log4net、NLog、Serilog，我們只需從 NuGet 包存儲庫中獲取它們，然後簡單地配置一下便可以愉快地使用它們了。

log4net

log4net^[5] 是一個始於 2001 年的領先的日誌記錄框架，最初是 Java 框架 log4j 的埠。多年來，Apache Logging Services 項目持續進行開發，沒有其他框架能像 log4net 一樣久經考驗。log4net 是所有現代 .NET 日誌記錄框架的鼻祖，在日誌框架中，日誌級別（log levels）、記錄器(logger)和輸出模組(appenders/targets/sinks)等概念幾乎都是通用的^[6]。相信所有多年使用 .NET 編程的朋友對 log4net 都相當熟悉。

log4net 好用、穩定且靈活，但是它的配置相對來說比較複雜一些，而且很難實現結構化的日誌記錄。

NLog

NLog^[7] 也是一個相當老的項目，最早的版本發佈於 2006 年，不過目前仍在積極開發中。NLog 從 v4.5 版本開始新增了對結構化日誌記錄的支援。

與 log4net 相比，NLog 的配置更加容易，並且基於程式碼的配置也比較簡潔。NLog 中的默認設置比 log4net 中的默認設置會更合理一些。需要注意的一點是，當使用這兩個框架，您可能會遇到同一個問題，那就是配置有問題（比如忘記複製配置文件）時，不會得到任何提示，也不會輸出日誌資訊。假如您將應用部署上線以後遇到這個情況，這將是致命的，因為許多問題的檢查都是依賴於日誌記錄的。當然，這麼設計的初衷是避免讓應用程式因日誌問題而導致崩潰。

Serilog

Serilog^[8] 日誌記錄框架發佈於 2013 年，相對來說是一個較新的框架。與其他日誌框架不同的是，Serilog 在設計時考慮了強大的結構化事件數據，提供了開箱即用的結構化日誌實現。所以 Serilog 對結構化日誌的支援非常好，而且配置簡潔。Serilog 中的日誌可以發送到許多終端，Serilog 稱這些終端為「輸出模組庫(sinks)」。您可以在 //github.com/serilog/serilog/wiki/Provided-Sinks 頁面查看非常全面的列表。

Serilog 中還有一個功能強大的概念是Enricher，可以通過各種方式來豐富日誌事件的屬性，從而向日誌添加新的資訊。NuGet 中提供了一些預建的 Enricher，您也可以通過實現 ILogEventEnricher 構建自己的 Enricher。

結構化日誌記錄

或許您已注意到了，前面我多次提到結構化日誌記錄，那麼什麼是結構化日誌記錄，為什麼我要強調結構化日誌記錄呢？

通常情況下，您會發現日誌資訊基本上包含兩部分內容：消息模板和值，而 .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);

這條日誌只是簡單地被轉換為文本輸出到日誌文件中：

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

這看起來很好，但它可以更好！

當我們遇到問題的時候，我們需要根據一些已知的資訊來檢索日誌記錄。比如，假設我們已知 Latitude 為 25，Longitude 為 134，我們要查找這條日誌的話，該怎麼做呢？由於上面輸出的日誌資訊是簡單的文本，有經驗的您可能立馬會想到使用正則表達式或者簡單的字元串匹配，但這樣不僅不夠直觀，實現起來也比較麻煩。有沒有更好的方法呢？

如果我們在存儲日誌的時候，將其中包含值的部分作為特徵提取出來，形成由鍵和值組成的有結構的 JSON 對象，作為每條日誌記錄的屬性(properties)：

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

然後，在我們檢索的時候只需要查找日誌記錄的 properties 就可以了，它是結構化的，檢索起來既方便又直觀。

Serilog 幫我們實現了這一點，您只需改動一行程式碼就可以了：

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

Position 前面的 @ 是解構操作符，它告訴 Serilog 需要將傳入的對象序列化，而不是調用 ToString() 轉換它。

Elapsed 之後的 :000 是一個標準的 .NET 格式字元串，它決定該屬性的呈現方式。

為 Worker Service 添加 Serilog 日誌

現在，您已經大概了解了 Serilog，以及為什麼我會選用它的原因。下面我用一個實例來介紹一下它的用法。

需要用到的開發工具：

Visual Studio Code：(//code.visualstudio.com/)
最新的 .NET SDK：(//dotnet.microsoft.com/download)
DBeaver：(//dbeaver.io/)

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

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

然後，使用 Visual Studio Code 打開此項目，運行一下，以確保一切正常：

dotnet build
dotnet run

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

在本文的示例中，我將以 JSON 的方式把 Serilog 的配置放置在現在流行的 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 讀取配置並根據配置構建 Serilog 日誌記錄器的實例：

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 設置為日誌提供程式：

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

修改配置文件 appsettings.json

修改應用程式配置文件 appsettings.json，添加 Serilog 節點(Section)。

Serilog 所需的配置節點名稱默認為 Serilog；當然，您也可以改變它，但要在讀取的時候指定節點名。

{
  "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] 的文檔中找到這些配置的說明。

Using 節點

Using 節點包含了所需的程式集列表，用於自動發現 WriteTo 和 Enrich 等節點中配置的方法所屬的程式集。

對於 .NET Core 項目，構建工具會生成 .deps.json 文件，並且 Serilog.Settings.Configuration 包使用 Microsoft.Extensions.DependencyModel 實現了一個約定，從而可以從名稱任意位置帶有Serilog 的依賴程式包中找出正確的包，並從中提取配置的方法。因此，上面示例中的 Using 節點是可以省略的。

MinimalLevel 節點

MinimumLevel 對象配置輸出日誌的最低級別。添加 MinimalLevel.Override 項，可以覆蓋某些特定命名空間的最小級別。

WriteTo 節點

使用 WriteTo 對象配置輸出模組(sinks)，可以同時配置並激活多個輸出模組。本示例中我們配置了 Console 和 RollingFile，前者將日誌輸出到控制台，後者將日誌輸出到滾動文件中。

將日誌輸出到文件，您還可以使用 Serilog.Sinks.File 程式包，它也支援滾動文件。

Args 用於配置 Sink 的選項。本例中 pathFormat 配置了日誌文件的存放位置，該項的值中 {Hour} 是滾動日誌文件的 文件名格式說明符。該輸出模組支援三種不同的文件名格式說明符（區分大小寫）：

{Date}：每天創建一個文件。文件名使用 yyyyMMdd 格式。
{Hour}：每小時創建一個文件。文件名使用 yyyyMMddHH 格式。
{HalfHour}：每半小時創建一個文件。文件名使用 yyyyMMddHHmm 格式。

完成以上這些配置後，我們運行應用程式：

dotnet build
dotnet run

您會發現在應用程式根目錄下多了一個 Logs 文件夾，可以將日誌資訊正常輸出到文件了。同時，控制台也有輸出日誌。兩者的輸出格式略有不同，控制台中的輸出更簡潔一些。

添加 Enricher 和格式化輸出

前文我提到過 Serilog 中還有一個功能強大的概念是Enricher，這裡我就以預建的 Enricher 來舉例說明一下它的使用。

添加以下依賴程式包：

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

這三個 Enricher 分別提供了不同的資訊以豐富日誌事件的屬性。

Serilog.Enrichers.Environment 提供 WithMachineName() 和 WithEnvironmentUserName()
Serilog.Enrichers.Process 提供 WithProcessId()
Serilog.Enrichers.Thread 提供 WithThreadId()

修改 appsettings.json，向 Serilog 配置對象添加 Enrich 配置節點，以豐富日誌事件的資訊：

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

修改 appsettings.json，向 WriteTo 下的 RollingFile 對象節點的 Args 添加一個 outputTemplate 選項，以自定義輸出消息模板：

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

修改好配置後，重新運行應用程式：

dotnet build
dotnet run

再查看一下日誌文件，您會發現日誌已經按我們自定義的格式輸出了，並且多了一些我們使用 Enricher 獲得的資訊：(電腦名/進程ID/進程名稱/執行緒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

將日誌保存到資料庫

前文我提到過日誌文件的屬性(properties)，為什麼直到現在還沒有看到過它呢？

這是因為，當 Serilog 將日誌事件寫入文件或控制台時，消息模板和屬性將僅會呈現為易於閱讀的友好文本。而當我們將日誌事件發送到基於雲的日誌伺服器、資料庫和消息隊列等輸出模組(sinks)時，就可以保存為結構化的數據了。

為了簡便起見，我以 SQLite 資料庫為例來介紹一下。

添加 SQLite 依賴程式包：

dotnet add package Serilog.Sinks.SQLite

修改 appsettings.json，在 Serilog 配置中的 WriteTo 節點下添加以下配置節點，以向 SQLite 輸出日誌：

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

解釋一下 Args 各個選項的作用：

sqliteDbPath： SQLite 資料庫的路徑。
tableName： 用於存儲日誌的 SQLite 表的名稱。
maxDatabaseSize： 資料庫的最大文件大小，可以以 MB 為單位增加。默認為 10MB，最大為 20GB。為了方便測試，我在這裡將其設置為 1MB。
rollOver： 如果文件大小超過最大資料庫文件大小，則創建滾動備份，默認為 true。

此時，再次運行應用程式：

dotnet build
dotnet run

您將會在應用程式目錄下的 Logs 文件夾中看到一個 SQLite 資料庫文件 log.db。使用 DBeaver 打開檢查一下：

可以看到，SQLite 輸出模組自動為我們創建了資料庫和表，日誌記錄成功了。

我們配置了資料庫文件大於 1MB 時自動滾動備份，可以多輸出一些日誌測試一下，看它是否有自動滾動備份。我的測試結果如下圖：

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

Serilog 使用消息模板、以及命名和位置參數擴展 .NET 的格式化字元串，不過 Serilog 捕獲與每個命名參數相關聯的值，而不是直接將事件格式化為文本。我們添加幾行程式碼，測試一下 Serilog 捕獲日誌事件的情況：

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

上面的示例在日誌事件中記錄了兩個屬性：Position 和 Elapsed，Position 前面的 @ 操作符告訴 Serilog 要序列化傳入的對象。最終我們在資料庫中存儲的結構化的 Properties 如下所示：

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

Serilog 對結構化事件數據深入且豐富的支援，開創了原本使用傳統日誌記錄器所沒有的巨大的診斷可能性。

總結

在本文中，我介紹了 .NET 中常用的結構化事件日誌框架 Serilog，以及使用它的原因和好處；並通過一個 .NET Worker Service 實例，說明如何將日誌保存到滾動文件和資料庫中。

Serilog 是一個穩定的、配置簡潔的、功能強大的、可擴展的、支援結構化日誌事件的 .NET 日誌記錄提供程式，值得我們在應用中廣泛使用。

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

作者：技術譯民
出品：技術譯站

Tags: csharp dotnet