上文我們演示了使用NLog向ElasticSearch寫日志的基本過程(輸出的是普通文本日志)，今天我們來看下如何向ES輸出結構化日志、並利用Kibana中分析日志。
什么是結構化日志？
當前互聯網、物聯網、大數據突飛猛進，軟件越復雜，查找任何給定問題的起因就越困難（且成本更高）。
在實踐中我們開發了各種規避、診斷應用程序錯誤行為的利器：
靜態類型檢查，自動化測試，事件探查器，崩潰轉儲和監視系統。但是記錄程序執行步驟的日志仍然是事后診斷最豐富的數據源。
在日志分析時，小批量普通的文本對於人類很友好，但卻很難從大量普通文本中快速定位、精准提取特定信息。
.....
[2018-04-07T13:45:56.789Z INF] https://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] https://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, "https://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, "https://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, "https://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,https://example.com/api/warehouse,OrderId:9876543210,decrease reserve took 10000 ms",
"TraceId": "0HM1P3TAGNJ5Q:00000001",
"endpoint": "https://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中演示便捷的分析結構化日志
干貨周邊
- [消息模板] https://messagetemplates.org/
- [如何利用NLog輸出結構化日志] https://github.com/nlog/nlog/wiki/How-to-use-structured-logging
- [NLog to ES] https://github.com/markmcdowell/NLog.Targets.ElasticSearch
- [被忽略的TraceId,可以用起來了] https://www.cnblogs.com/JulianHuang/p/11952959.html
- Logging with ElasticSearch, Kibana, ASP.NET Core and Docker