如何利用NLog输出结构化日志,并在Kibana优雅分析日志?
上文我们演示了使用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,可以用起来了]
- Logging with ElasticSearch, Kibana, ASP.NET Core and Docker
- JavaScript 教程
- JavaScript 编辑工具
- JavaScript 与HTML
- JavaScript 与Java
- JavaScript 数据结构
- JavaScript 基本数据类型
- JavaScript 特殊数据类型
- JavaScript 运算符
- JavaScript typeof 运算符
- JavaScript 表达式
- JavaScript 类型转换
- JavaScript 基本语法
- JavaScript 注释
- Javascript 基本处理流程
- Javascript 选择结构
- Javascript if 语句
- Javascript if 语句的嵌套
- Javascript switch 语句
- Javascript 循环结构
- Javascript 循环结构实例
- Javascript 跳转语句
- Javascript 控制语句总结
- Javascript 函数介绍
- Javascript 函数的定义
- Javascript 函数调用
- Javascript 几种特殊的函数
- JavaScript 内置函数简介
- Javascript eval() 函数
- Javascript isFinite() 函数
- Javascript isNaN() 函数
- parseInt() 与 parseFloat()
- escape() 与 unescape()
- Javascript 字符串介绍
- Javascript length属性
- javascript 字符串函数
- Javascript 日期对象简介
- Javascript 日期对象用途
- Date 对象属性和方法
- Javascript 数组是什么
- Javascript 创建数组
- Javascript 数组赋值与取值
- Javascript 数组属性和方法
- Android7.0开发实现Launcher3去掉应用抽屉的方法详解
- Android利用Paint自定义View实现进度条控件方法示例
- 前端科普系列(5):ESLint - 守住优雅的护城河
- 图的储存方式,链式前向星最简单实现方式 (边集数组)
- 技术前刊:PostgreSQL12 COPY和bulkloading提升
- 疯子的算法总结(八) 最短路算法+模板
- POJ - 2387 Til the Cows Come Home (最短路入门)
- POJ - 3074 Sudoku (搜索)剪枝+位运算优化
- C语言rand随机函数问题
- HDU - 1253 胜利大逃亡(搜索)
- Android7.0版本影响开发的改进分析
- POJ - 2251 Dungeon Master(搜索)
- An Overview of PostgreSQL & MySQL Cross Replication
- POJ - 1321 棋盘问题
- CREATE TABLE ... WITH storage_parameter [= value] [, ... ]