首页
学习
活动
专区
工具
TVP
发布
社区首页 >专栏 >如何利用NLog输出结构化日志,并在Kibana优雅分析日志?

如何利用NLog输出结构化日志,并在Kibana优雅分析日志?

作者头像
有态度的马甲
发布2020-08-10 11:09:12
9960
发布2020-08-10 11:09:12
举报
文章被收录于专栏:精益码农精益码农

上文我们演示了使用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界面我们可以便捷地完成如下分析:

  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,可以用起来了]
  5. Logging with ElasticSearch, Kibana, ASP.NET Core and Docker
本文参与 腾讯云自媒体分享计划,分享自微信公众号。
原始发表:2020-08-06,如有侵权请联系 cloudcommunity@tencent.com 删除

本文分享自 精益码农 微信公众号,前往查看

如有侵权,请联系 cloudcommunity@tencent.com 删除。

本文参与 腾讯云自媒体分享计划  ,欢迎热爱写作的你一起参与!

评论
登录后参与评论
0 条评论
热度
最新
推荐阅读
目录
  • 什么是结构化日志?
    • 利用NLog向ES输出结构化日志
      • Kibana中分析日志
      • 总结
      • 干货周边也很重要
      相关产品与服务
      Elasticsearch Service
      腾讯云 Elasticsearch Service(ES)是云端全托管海量数据检索分析服务,拥有高性能自研内核,集成X-Pack。ES 支持通过自治索引、存算分离、集群巡检等特性轻松管理集群,也支持免运维、自动弹性、按需使用的 Serverless 模式。使用 ES 您可以高效构建信息检索、日志分析、运维监控等服务,它独特的向量检索还可助您构建基于语义、图像的AI深度应用。
      领券
      问题归档专栏文章快讯文章归档关键词归档开发者手册归档开发者手册 Section 归档