[NETCore] 結構化日誌 Serilog - Events Types 和 Enrichment ~ m@rcus 學習筆記

前言
前兩篇分別介紹了關於 Serilog 的基礎應用與設定，這篇就來針對事件類型 Event Type 與介紹幾個常用的 Enricher，若有問題或是錯誤的地方歡迎提出來一起討論。

Event Type
結構化日誌的好處是可以清楚的分辨"每一次"紀錄的事件，舉例來說下列簡單的代碼是透過 Serilog 寫入log 到 Console 與 File 檔案，紀錄內容是 3 筆資料

Log.Logger = new LoggerConfiguration()
    .WriteTo.Console()
    .WriteTo.File("logs\\log-.txt", rollingInterval: RollingInterval.Day)
    .CreateLogger();
 
Log.Information("Logging Start");
var total = 1;
for (var i = 0; i < 3; ++i)
{
    total *= i;
    Log.Information("Computed iteration {Counter}, total is {Total}", i, total);
}

上述的代碼輸出後如下

[00:35:28 INF] Logging Start
[00:35:28 INF] Computed iteration 0, total is 0
[00:35:28 INF] Computed iteration 1, total is 0
[00:35:28 INF] Computed iteration 2, total is 0

上述的 Log 雖然可以記錄事情但是假設資料量大或是 Log 數量很龐大的時候，找到同一事件(群)新增的 Log 紀錄是件很困難的事情，要解決這問題可以在 Log 加上一串識別字串 hashCode 方便查詢同樣事件使用。在 Serilog 解決方案是可以透過 Erinch 解決，首先新增一個類別 EventTypeEnricher 實作 ILogEventEnricher 介面的 Enrich 方法，內容為自訂 hash 的算法

class EventTypeEnricher : ILogEventEnricher
{
   public void Enrich(LogEvent logEvent, ILogEventPropertyFactory propertyFactory)
   {
      var murmur = MurmurHash.Create32();
      var bytes = Encoding.UTF8.GetBytes(logEvent.MessageTemplate.Text);
      var hash = murmur.ComputeHash(bytes);
      var numericHash = BitConverter.ToUInt32(hash, 0);
      var eventId = propertyFactory.CreateProperty("EventType", numericHash);
      logEvent.AddPropertyIfAbsent(eventId);
   }
}

接著在建立 ILogger 時候透過 Enrich.With 將產生 hash 字串內容，並自定義 outputTemplate 模板樣式

Log.Logger = new LoggerConfiguration()
   .Enrich.With<EventTypeEnricher>()
   .WriteTo.Console(outputTemplate:
       "{Timestamp:HH:mm:ss} [{EventType:x8} {Level:u3}] {Message:lj}{NewLine}{Exception}")
   .CreateLogger();

接著重新執行一次，可以看到 log 多了自行定義的 hash Code

01:28:08 [4dd86bd1 INF] Logging Start
01:28:08 [f20ba6e0 INF] Computed iteration 0, total is 0
01:28:08 [f20ba6e0 INF] Computed iteration 1, total is 0
01:28:08 [f20ba6e0 INF] Computed iteration 2, total is 0

成功透過自訂 Enrich 新增 hashCode 解決此問題

More Enrichers
在前一篇結構化日誌 Serilog - 配置設定中介紹了基本的應用，在 Serilog 中提供很多實用的 Enrichers 方便開發者使用，像是積木的概念如果有遇到需要的就透過 nuget 套用即可十分方便，這裡在舉例自己在專案上有用到推薦的 Enrich 項目，舉例來說如果想要在每筆 Log 都記錄 MachineName、Env、Application與 RequestID 等資訊時，目的是在 log 中紀錄下圖的資訊

在 Log 加入這些屬性的目的是為了在 ELK 搜尋時更容易分辨，如果當 Production 與 UAT 的 Log 都存放在同一台 ELK 時候，在查詢資料就可以透過 Environment 來分辨環境找到 Log 以及 Application，並自動在建立 Logger 時定義 MachineName 資訊，不用在 parser 時另外指定。

加入 Application 與 Environment
首先先從簡單的開始，分別在建立 Logger 定義 Enrich.WithProperty 屬性 Applicaion 與 Environment 並賦予相關值，在用 Json 格式輸出

Log.Logger = new LoggerConfiguration()
    .Enrich.WithProperty("Application", "MyApplication")
    .Enrich.WithProperty("Environment", ConfigurationManager.AppSettings["Environment"])
    .WriteTo.File(new CompactJsonFormatter(), "log.txt")
    .CreateLogger();

以上代碼輸出如下，很簡單的定義了輸出包含 ApplicationName 與 Environment 的 Log 資訊

{"@t":"2019-05-07T04:44:40.3369156Z","@mt":"Computed iteration {Counter}, total is {Total}","Counter":0,"Total":0,"Application":"e-Commerce","Environment":"Production"}

加入 MachineName
接著，再加上 MachineName，需要透過 nuget 安裝 Serilog.Enrichers.Environment

Install-Package Serilog.Enrichers.Environment -Version 2.1.3

並在建立 Logger 時加入 Enricher 指定 Machine

.Enrich.WithMachineName()

輸出的 Log 部分會加上 ServerName

{"@t":"2019-05-07T10:24:50.2274022Z","@mt":"Computed iteration {Counter}, total is {Total}","Counter":0,"Total":0,"Application":"MyApplication","Environment":"Production","MachineName":"ServerName"}

加入 RequestID
在 Serilog 中可以使用 SerilogWeb.Classic 紀錄 RequestId，使用方式很簡單透過 nuget 下載後使用 WithHttpRequestId 方法，就可以很輕鬆的達到紀錄 RequestId 的需求。在 Serilog 中有另外提供一個好用的物件 LogContext 可以讓所有的紀錄事件加入特定的屬性，使用方式是new LoggerConfiguration 加上 Enrich.FromLogContext() 擴充方法，再透過 LogContext.PushProperty 將特定的屬性以 key/value 方式加入紀錄事件中，代碼如下 Enrich.WithMachineName() 指定 Machine

var logger = new LoggerConfiguration()
    .Enrich.FromLogContext()
    .Enrich.WithProperty("Application", "MyApplication")
    .Enrich.WithProperty("Environment", "Production")
    .WriteTo.File(new CompactJsonFormatter(), "log.txt")
    .WriteTo.Console(outputTemplate:
        "{Timestamp:HH:mm:ss} [{EventType:x8} {Level:u3}] {Message:lj}{NewLine}{Exception}")
    .CreateLogger(); 
 
var requestId = Guid.NewGuid();
using (LogContext.PushProperty("RequestId", requestId, true))
{
    // Middleware Invoke
    logger.Information("This is a book, not a pencil");
}

在代碼中透過 pushProperty 方式將 requestId 注入到 LogContent 中，值為隨機產生GUID其結果輸出如下

{"@t":"2019-05-07T14:56:47.2892546Z","@mt":"This is a book, not a pencil","RequestId":"0e9eaf11-544f-414d-8091-76bb7797edea","Application":"MyApplication","Environment":"Production"}

可以看到 Log 順利紀錄了指定的 RequestId 資訊，如果在 ASP.NET Core 中止需要將產生 RequestID 的方式加到 MiddleWare 中的 Invoke 方法，即可順利地產生出 RequestID 資訊，這裡就不在細說
另外在 LogContext 中也提供指定 source Type 方法

var valueLog = Log.ForContext<valueController>();

想要了解更細節的部份可以看作者所撰寫的 Context and correlation – structured logging concepts in .NET，相信可以對細節與應用情境有更深入的了解。以上介紹了幾種簡單的應用，官網也有列出 enricher package 項目，如果有興趣的也可以到 github 查看使用方式及使用。

希望這篇的介紹對各位有幫助，Happy Coding :)

參考

Structured logging concepts in .NET Series

Serilog

[CheatSheets] LINQ API 廢話 LINQ的好用大家都知道，今天不小心發現LINQ API簡單易上手的圖片介紹檔(大喜也簡單做個筆記方便日後查詢使用 :D 同場加映 : LINQ Tutorial … Read More
[typescript] 如何在 Visual Studio 2017 安裝 TypeScript 1.8 Compiler ? 前言最近公司在進行升級 Visual Studio 2017 IDE，有些專案在過去開發時是使用舊的 TypeScript 版本，這篇文章是在記錄如何在 Visual Studio 2017安裝 TypeScript 1.8版 Compiler (預設不會裝) 的過程釐清案情專案從版控下載後發現Build不過，發現錯誤訊息如下圖錯誤訊息疑似是版本不支援關係，這時需要查看此專案檔用 TypeScript用到的版本號為 1… Read More
[VS2017] 如何在Visual Studio中設定C#建置版本發生情境前陣子同事從版控取完最新的source Build在Build時跳出錯誤，錯誤訊息如下 Feature 'nameof operator' is not available in C# 5. Please use language version 6 or greater.錯誤訊息中很明確的說明在 code 所使用的 nameof function 僅支援 C# 6以上的版本，但修改的同事並未發生此問題，因此立即解決發生提出… Read More
[IIS] HTTP 錯誤 500.21 - Internal Server Error前言換新筆電後在安裝公司專案過程遇到很多問題，昨天是SQL Server服務異常關閉，今天是專案出現問題是"HTTP 錯誤500.21 - Internal Server Error"，但這樣也不錯，可以學到更多新知識與問題，這裡簡單紀錄一下處理過程錯誤訊息 HTTP 錯誤 500.21 HTTP Status Code 狀態碼是Server端 Response 的狀態，在 Status Code Definitions&nbs… Read More
[Nuget] Nuget operation failed前言為了取得/建置專案的方便，最近常遇到同事透過 powershell 指令使用svn取得最新的代碼並呼叫MSBuild自動建置專案，今天在執行完前同事所撰寫的 powershell script 後開啟專案跳出 Nuget operation failed 提示訊提，這種情況還是第一次遇到，新筆電與桌基平常都正常來記錄處理臭蟲的過程症狀開啟Visual Studio 2017跳出錯誤訊息：Nuget o… Read More

m@rcus 學習筆記

只有累積，沒有奇蹟

2019年5月6日星期一