上文我们演示了使用NLog向ElasticSearch写日志的基本过程(输出的是普通文本日志)，今天我们来看下如何向ES输出结构化日志、在Kibana中分析日志。
什么是结构化日志？
当前互联网、物联网、大数据突飞猛进，软件越复杂，查找任何给定问题的起因就越困难（且成本更高）。
在实践中我们开发了各种规避、诊断应用程序错误行为的利器：静态类型检查，自动化测试，事件探查器，崩溃转储和监视系统。但是记录程序执行步骤的日志仍然是事后诊断最丰富的数据源。
在日志分析时，小批量普通的文本对于人类很友好，但却很难从大量普通文本中快速定位、精准提取特定信息。
.....
[2018-04-07T13:45:56.789Z INF] https:///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:///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
.....
- 如何定位到该耗时请求处理管道中哪一段出现性能瓶颈？
普通文本对人类友好，对于机器不友好。结构化日志提出了Message template来解决日志对机器不友好的问题。
Messgae Template: 是一个与语言无关的规范，捕获、(以对人类和机器友好的格式)呈现结构化的日志。
var traceid = _.TraceIdentifier;
// 【锁定库存】 这个动作耗时较长
_logger.LogInformation('{TraceId},{endpoint},OrderId:{orderId},decrease reserve took {elasped} ms', traceid, 'https:///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:///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:///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:///api/warehouse,OrderId:9876543210,decrease reserve took 10000 ms',
'traceId': '0HM1P3TAGNJ5Q:00000001',
'endpoint': 'https:///api/warehouse',
'orderId': 9876543210,
'elasped': 10000
},
'fields': {
'@timestamp': [
'2020-08-05T09:10:00.717Z'
]
},
'sort': [
1596618600717
]
}
通过Kibana界面我们可以便捷地完成如下分析：
- 通过{elasped} >=10s 过滤出处理时长大于10s的阶段
- 通过{ordeid} 追踪该订单完整链路
......
总结
本文肝时较长(elasped>=10天)
- 从常规诊断日志谈到[对机器友好，适用于分析的结构化日志]，其中的核心是消息模板。
- 再谈到我是如何利用NLog输出结构化日志，其中注意在NLog Target中设置
includeAllProperties=true(默认是false)， 摸索了很久
干货周边也很重要
- [如何利用NLog输出结构化日志] https://github.com/nlog/nlog/wiki/How-to-use-structured-logging
- [NLog to ES] https://github.com/markmcdowell/NLog.Targets.ElasticSearch
