Node.js+ELK日志规范的实现
一般前端开发同学，对日志其实不太敏感，毕竟前端大多数情况下，不太关心日志。即使有，也可能调用一些第三方的统计，比如百度统计或者别的等。在Node.js(下文中简称node)推进过程中，也发现我们平常打日志太随意，该打的日志没有打，打的一些关键日志缺少必要上下文信息，导致在线上定位问题的时候很困难。
本文主要梳理了目前我们团队在nodejs开发中日志方面存在的问题，以及通过统一日志规范，希望达到什么样的效果。
问题
- node日志不规范，打日志太随意
- 没有良好的日志格式、约定的字段，在ELK里不能很好的解析&检索(PS:ELK文章在路上)
- 由于node对接的后端服务化，调用链不清晰，定位问题困难
- 数据部门对node日志的使用，没有明确的记录。node修改了日志，导致统计数据异常
目标
- 规范日志打印字段&格式，便于ELK检索
- 增强node上下游(nginx/后端)日志格式，加入惟一requestId，方便微服务下定位问题
- 统计应用运行情况，性能数据
- 维护数据部门对node日志的使用情况
实现方案
日志类型
参考一些日志的最佳实践，目前将node日志分为如下几种类型(scope)：
- desc:系统启动、运行过程中，打的日志，表明系统的一些启动日志、启动参数等，也包含在不能捕获到http上下文的时候，打的日志
- stat:系统性能统计日志，应用会定时收集一些性能信息，便于查询应用当前状态
- visit:每个http请求相关的日志，会包含惟一的requestId，定位该请求相关的所有日志
- biz:业务数据相关日志，主要提供给数据统计使用
日志级别
只使用FATAL、ERROR、WARN、INFO和DEBUG等级。
- FATAL-导致程序退出的严重系统级错误，不可恢复，当错误发生时，系统管理员需要立即介入，一般应用代码不使用。
- ERROR-运行时异常以及预期之外的错误，也需要立即处理，但紧急程度低于FATAL,当错误发生时，影响了程序的正确执行。需要注意的是这两种级别属于服务自己的错误，需要管理员介入，用户输入出错不属于此分类，请求后端、读文件、数据库等超时、返回错误结构，属于ERROR
- WARN-预期之外的运行时状况，表示系统可能出现问题。对于那些目前还不是错误，然而不及时处理也会变成错误的情况，也可以记为WARN，如磁盘过低。
- INFO-有意义的事件信息，记录程序正常的运行状态，比如收到请求，成功执行。通过查看INFO,可以快速定位WARN，ERROR,FATAL。INFO不宜过多，通常情况下不超过DEBUG的10%。
- DEBUG-与程序运行时的流程相关的详细信息以及当前变量状态。
日志格式/字段
- 日志格式统一采用JSON，便于ELK解析处理。
- 日志中的各个字段的值，都应该尽量使用英文，不使用中文。
- 日志具体字段，分为基础数据+扩展数据。基础数据，是底层日志框架自带的，所有日志都会包含。扩展数据，不同类型的日志，包含不同的字段。
日志基础数据
目前使用的node-bunyan日志库，官方文档，基础字段包含如下：
- v:integer。bunyan的日志版本号
- level:integer。日志级别对应的数字
- name:string。服务名
- hostname:string。主机名
- pid:integer。进程号
- time:string。UTC格式的日期
- msg:string。日志主体信息
日志扩展数据
下面定义的各个数据类型的扩展数据，不是全部的字段，仅包含该日志类型下，必需的字段。这些必需的扩展字段，需要在ELK中建立索引，方便定位各种问题。
- desc类型日志，扩展字段：TODO
- stat类型日志，扩展字段：{perf:{rss:xxxx,cpu:xxx}}
- visit类型日志，扩展字段：
- biz
{
/////////////基础数据////////
v:1,
level:20,
/////////////扩展字段////////
//标志日志类型
scope:"visit",
//事件类型：在visit的日志类型下，还会细分不同的事件，比如client-req、client-res、普通trace、请求后端service-start,service-end,service-err等。
event:"trace",
//客户端ID，追踪用户、设备会话。在web端，可以是长期的cookie；在APP端，可以是device-id等
rrdid:"",
//本次请求的惟一ID，串联本次请求的所有相关日志
req_id:"some-uuid-for-request",
//本次请求的用户ID
uid:"",
//本次请求的客户端相关数据，通过ctx.logger打日志时，自动加上
d:{
url:"/some/path?include-query",
//客户端ip
ip:"10.138.10.1",
//客户端的userAgent
ua:""
},
//本次node请求的处理时间，毫秒
tm:500,
//该日志相关的上下文数据，尽量拼成一个字符串，放在extra里
extra:"",
//ERROR级别日志，最好包含error相关信息，比如请求后端相关参数等
err:{
msg:"",
stack:""
},
//调用后端服务相关参数和响应
service_req:{
host:"",
path:"",
payload:""
},
service_res:{
//http状态码
http_code:200,
//响应时间
tm:100,
//响应的body
body:"",
//异常信息
err:""
}
}
什么时候打日志
开发者目前只关心visit类型的日志，即和某一次http请求相关联的日志。desc和stat类型的日志，统一由开发框架封装后实现，业务开发不用关心。下面讲的，都是针对visit类型的日志。
一次http请求，会打出一系列相关联的日志。在node层，通常一次请求，会进一步转发给N个后端服务，然后对后端数据进行一些处理、合并等操作，最后渲染页面或是输出JSON。因此，一次请求相关的日志，大体分为以下几种event：
- client-req:client请求到达node层，统一由框架打日志，开发不关心
- service-start:node对某个后端服务发起请求，由通用请求库负责打日志，开发不关心
- service-end:node请求某个后端服务结束，由通用请求库负责打日志，开发不关心
- service-err:node请求后端服务异常，由通用请求库负责打日志，开发不关心。调用后端服务异常，日志级别为WARN，不是ERROR
- trace:node中业务层打的日志，如果异常，能帮助定位本次请求相关问题
- client-res:结束client的请求，打印本次请求的httpcode，本次请求处理时间等，由框架统一打，开发不关心
开发同学在打日志时，应该谨慎的选择级别，INFO(含)级别以上，都应该能对定位问题、具体业务统计需求有要求，才能使用。大部分情况下，可以使用DEBUG级别，线上不会开启DEBUG级别。
具体方法调用
针对打印visit类型的日志，调用ctx.logger(基于Koa的框架)属性打日志，推荐参数都传递JSON，具体方法如下：
ctx.logger.debug({msg:"","extra":"a=1b=2c=value"});
ctx.logger.info({msg:"xxx","extra":"其他的额外字段"});
ctx.logger.warn({msg:"xxx","extra":"额外上下文数据"});
//ERROR级别日志，应该提供Error对象
ctx.logger.error({msg:'xxx',err:error,extra:""});
注意1，额外的参数，推荐存放在extra字段中，统一拼成string；如果确实有必要单独出每个字段，禁止额外的参数占用上述通用字段名！！
注意2，基础数据中的msg字段，禁止包含具体的上下文数据，和该日志相关的上下文数据，应该拼成字符串，放在单独的extra字段中。比如，某个用户登录接口，希望统计调用次数，可以这样打印:
ctx.logger.info({msg:"userlogin","extra":'mobile=18712387101code=xxxxk3=value3'});
以上就是本文的全部内容，希望对大家的学习有所帮助，也希望大家多多支持毛票票。
声明：本文内容来源于网络，版权归原作者所有，内容由互联网用户自发贡献自行上传，本网站不拥有所有权，未作人工编辑处理，也不承担相关法律责任。如果您发现有涉嫌版权的内容，欢迎发送邮件至：czq8825#qq.com（发邮件时，请将#更换为@）进行举报，并提供相关证据，一经查实，本站将立刻删除涉嫌侵权内容。