如何利用NLog輸出結構化日誌，並在Kibana優雅分析日誌？

2020 年 8 月 6 日
筆記
.NET

上文我們演示了使用NLog向ElasticSearch寫日誌的基本過程(輸出的是普通文本日誌)，今天我們來看下如何向ES輸出結構化日誌、並利用Kibana中分析日誌。

什麼是結構化日誌？

當前互聯網、物聯網、大數據突飛猛進，軟件越複雜，查找任何給定問題的起因就越困難（且成本更高）。

在實踐中我們開發了各種規避、診斷應用程序錯誤行為的利器：
靜態類型檢查，自動化測試，事件探查器，崩潰轉儲和監視系統。但是記錄程序執行步驟的日誌仍然是事後診斷最豐富的數據源。

在日誌分析時，小批量普通的文本對於人類很友好，但卻很難從大量普通文本中快速定位、精準提取特定信息。

.....
[2018-04-07T13:45:56.789Z INF] //example.com/api/warehouse,query reserve,took 100 ms
[2018-04-07T13:45:56.789Z INF] api/commitOrder,OrderId:9876543210,commit order took 50 ms
......
[2018-04-07T13:45:56.789Z INF] /login,user:Kenny,from ip_address:127.0.0.1,took 100 ms
......
[2018-04-07T13:45:56.789Z INF] //example.com/api/warehouse,OrderId:9876543210,decrease reserve took 10000 ms
[2018-04-07T13:45:56.789Z INF] /api/creatNewOrder,OrderId:9876543210, create order took 100 ms
.....

如果找到特定OrderId？
如何找到哪些請求耗時較長(比如大於2S)？
如何定位到該耗時請求處理管道中哪一段出現性能瓶頸？
出現性能瓶頸的請求佔比？

普通文本對人類友好，對於機器不友好。
結構化日誌提出了Message template來解決日誌對機器不友好的問題。

Messgae Template: 是一個與語言無關的規範，以對人類和機器友好的格式捕獲、呈現結構化的日誌事件。

var traceid = _.TraceIdentifier;
 // 【鎖定庫存】 這個動作耗時較長
_logger.LogInformation("{TraceId},{endpoint},OrderId:{orderId},decrease reserve took {elasped} ms", traceid, "//example.com/api/warehouse", 9876543210, 10000);

注意命名佔位符，它們能如格式化字符串佔位符{0}{1}一樣佔位，而且能將屬性名稱與每個匹配位置的消息數據相關聯，如下圖以json格式提取了關鍵消息。

消息模板的優勢在於：既能保持普通文本的格式，又具備捕獲結構化數據的能力(對機器友好)。

下面來完整輸出、分析提交訂單請求的日誌：

利用NLog向ES輸出結構化日誌

NLog4.5引入結構化日誌，支持Message Template，在ASP.NET Core腳手架Startup文件—>Configure方法添加如下代碼：

 app.MapWhen(_ => _.Request.Path.Value == "/" ,
                      appBuilder => appBuilder.Run(_ =>
                     {
                         var traceid = _.TraceIdentifier;
                         // 查詢庫存
                         _logger.LogInformation("{traceId},{endpoint},query reserve,took{elasped} ms", traceid, "//example.com/api/warehouse", 100);

                         // 創建訂單
                         _logger.LogInformation("{traceId},{endpoint},OrderId:{orderId}, create order took {elasped} ms", traceid, "/api/creatNewOrder", 9876543210, 100);

                         // 鎖定庫存
                         _logger.LogInformation("{traceId},{endpoint},OrderId:{orderId},decrease reserve took {elasped} ms", traceid, "//example.com/api/warehouse", 9876543210, 10000);

                         // 提交訂單
                         _logger.LogInformation("{traceId},{endpoint},OrderId:{orderId},commit order took {elasped} ms", traceid, "api/commitOrder", 9876543210, 50);

                        _.Response.StatusCode = StatusCodes.Status200OK;
                        _.Response.WriteAsync("Generate Order OK!");  
                       return Task.CompletedTask;
                    }));

這裡我們關注如何向ElasticSearch輸出結構化日誌，請務必將includeAllProperties="true",這樣輸出到ES的才會包含所有事件屬性。

<target name="elastic" xsi:type="BufferingWrapper" flushTimeout="5000">
      <target xsi:type="ElasticSearch" includeAllProperties="true" index="logstash-20200805"  uri="${configsetting:item=ConnectionStrings.ElasticUrl}" />
 </target>

Kibana中分析日誌

這個訂單請求，會產生6條日誌(這裡你也會看到日誌的顯示順序可能不能如你所願):

下面給出[鎖定庫存]日誌ES文檔，文檔上已經出現了關鍵的消息屬性[traceId] [endpoint] [orderId] [elasped]

{
  "_index": "logstash-20200805",
  "_type": "logevent",
  "_id": "emTivXMBwcdwe4RliB9f",
  "_version": 1,
  "_score": null,
  "_source": {
    "@timestamp": "2020-08-05T17:10:00.7170456+08:00",
    "level": "Info",
    "message": "2020-08-05 17:10:00.7170|INFO|EqidManager.Startup|0HM1P3TAGNJ5Q:00000001,//example.com/api/warehouse,OrderId:9876543210,decrease reserve took 10000 ms",
    "TraceId": "0HM1P3TAGNJ5Q:00000001",
    "endpoint": "//example.com/api/warehouse",
    "orderId": 9876543210,
    "elasped": 10000
  },
  "fields": {
    "@timestamp": [
      "2020-08-05T09:10:00.717Z"
    ]
  },
  "sort": [
    1596618600717
  ]
}

通過Kibana界面我們可以便捷地完成如下分析：

通過{TraceId}找到某次請求所有日誌
通過{elasped} >=10s 過濾出處理時長大於10s的階段
通過{ordeid} 追蹤該訂單完整鏈路
……

總結

本文肝時較長(elasped>=10天)

從常規診斷日誌談到[對機器友好，適用於分析的結構化日誌]，其中的核心是消息模板。
再談到我是如何利用NLog輸出結構化日誌，其中注意在NLog Target中設置includeAllProperties=true(默認是false)，摸索了很久
最後在Kibana中演示便捷的分析結構化日誌

乾貨周邊

[消息模板] //messagetemplates.org/
[如何利用NLog輸出結構化日誌] //github.com/nlog/nlog/wiki/How-to-use-structured-logging
[NLog to ES] //github.com/markmcdowell/NLog.Targets.ElasticSearch
[TraceId]
Logging with ElasticSearch, Kibana, ASP.NET Core and Docker

Tags: .NET