如何利用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的才会包含所有事件属性。

dotnet  add  package  NLog.Targets.ElasticSearch 


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

nlog 异步写日志

常见的日志target是file、db， 这时就需要异步写日志，能显著提高写日志的性能。

上面我们给出的是 BufferingWrapper， 这与nlog AsyncWrapper 还是有一点差别，：
BufferingWrapper： Once there are enough messages (specified by bufferSize parameter) in the buffer, BufferingWrapper will block and write the messages to its target. The caller will need to wait until the writing is finished.

AsyncWrapper： AsyncWrapper uses a separate thread to handle the writes. The calls return immediately and the caller can continue its work and the log gets written later.

异步写日志的实现原理，是写日志进队列，对消息进行排队并在单独的线程中处理它们
https://nlog-project.org/documentation/v5.0.0/html/T_NLog_Targets_Wrappers_AsyncTargetWrapper.htm

快捷方式

 <targets async="true">
   ... your targets go here ...
</targets>

实质是 ：

<?xml version="1.0" ?>
 <nlog xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
     xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance">
    <targets>
       <!-- Log in a separate thread, possibly queueing up to
         5000 messages. When the queue overflows, discard any
        extra messages-->
 
         <target name="file" xsi:type="AsyncWrapper" queueLimit="5000" overflowAction="Discard">
            <target xsi:type="File" fileName="${basedir}/logs/${level}.txt" />
        </target>
    </targets>

   <rules>
        <logger name="*" minlevel="Debug" writeTo="file" />
    </rules>
</nlog>

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 and Docker
posted @ 2020-08-06 07:54  博客猿马甲哥  阅读(1789)  评论(3)  编辑  收藏  举报