新技能：NLog輸出結構化日志，并在Kibana優(yōu)雅分析日志？

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

什么是結構化日志？

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

在實踐中我們開發(fā)了各種規(guī)避、診斷應用程序錯誤行為的利器：靜態(tài)類型檢查，自動化測試，事件探查器，崩潰轉儲和監(jiān)視系統(tǒng)。但是記錄程序執(zhí)行步驟的日志仍然是事后診斷最豐富的數據源。

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

.....
[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: 是一個與語言無關的規(guī)范，捕獲、(以對人類和機器友好的格式)呈現結構化的日志。

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

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

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

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

利用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);

?????????????????????????//?創(chuàng)建訂單
?????????????????????????_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的才會包含所有事件屬性。

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

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界面我們可以便捷地完成如下分析：

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

總結

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

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

干貨周邊也很重要

1. [消息模板] ? ?https://messagetemplates.org/
2. [如何利用NLog輸出結構化日志] ? https://github.com/nlog/nlog/wiki/How-to-use-structured-logging
3. [NLog to ES] ? https://github.com/markmcdowell/NLog.Targets.ElasticSearch
4. [被忽略的TraceId，可以用起來了]
5. Logging with ElasticSearch, Kibana, ASP.NET Core and Docker