上文我們演示了使用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的才會包含所有事件屬性。 ```

``` #### 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天) - 從常規診斷日誌談到[對機器友好，適用於分析的結構化日誌]，其中的核心是訊息模板。 - 再談到我是如何利用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] https://www.cnblogs.com/JulianHuang/p/11952959.html 5. Logging with ElasticSearch, Kibana, ASP.NET Core an