浅谈Node框架接入ELK实践总结

我们都有过上机器查日志的经历，当集群数量增多的时候，这种原始的操作带来的低效率不仅给我们定位现网问题带来极大的挑战，同时，我们也无法对我们服务框架的各项指标进行有效的量化诊断，更无从谈有针对性的优化和改进。这个时候，构建具备信息查找，服务诊断，数据分析等功能的实时日志监控系统尤为重要。

ELK （ELK Stack: ElasticSearch, LogStash, Kibana, Beats） 是一套成熟的日志解决方案，其开源及高性能在各大公司广泛使用。而我们业务所使用的服务框架，如何接入 ELK 系统呢？

业务背景

我们的业务框架背景：

• 业务框架是基于 NodeJs 的 WebServer
• 服务使用 winston 日志模块将日志本地化
• 服务产生的日志存储在各自机器的磁盘上
• 服务部署在不同地域多台机器

我们将整个框架接入 ELK 简单归纳为下面几个步骤：

• 日志结构设计：由传统的纯文本日志改成结构化对象并输出为 JSON.
• 日志采集：在框架请求生命周期的一些关键节点输出日志
• ES 索引模版定义：建立 JSON 到 ES 实际存储的映射

一、日志结构设计

传统的，我们在做日志输出的时候，是直接输出日志的等级（level）和日志的内容字符串（message）。然而我们不仅关注什么时间，发生了什么，可能还需要关注类似的日志发生了多少次，日志的细节与上下文，以及关联的日志。 因此我们不只是简单地将我们的日志结构化一下为对象，还要提取出日志关键的字段。

1. 将日志抽象为事件

我们将每一条日志的发生都抽像为一个事件。事件包含：

事件元字段

• 事件发生时间：datetime, timestamp
• 事件等级：level， 例如: ERROR, INFO, WARNING, DEBUG
• 事件名称: event, 例如：client-request
• 事件发生的相对时间（单位：纳秒）：reqLife, 此字段为事件相对请求开始发生的时间（间隔）
• 事件发生的位置: line，代码位置; server, 服务器的位置

请求元字段

• 请求唯一ID: reqId, 此字段贯穿整个请求链路上发生的所有事件
• 请求用户ID: reqUid, 此字段为用户标识，可以跟踪用户的访问或请求链路

数据字段

不同类型的事件，需要输出的细节不尽相同，我们将这些细节（非元字段）统一放到d -- data，之中。使我们的事件结构更加清晰，同时，也能避免数据字段对元字段造成污染。

e.g. 如 client-init事件，该事件会在每次服务器接收到用户请求时打印，我们将用户的 ip, url等事件独有的统一归为数据字段放到 d 对象中

举个完整的例子

{
  "datetime":"2018-11-07 21:38:09.271",
  "timestamp":1541597889271,
  "level":"INFO",
  "event":"client-init",
  "reqId":"rJtT5we6Q",
  "reqLife":5874,
  "reqUid": "999793fc03eda86",
  "d":{
    "url":"/",
    "ip":"9.9.9.9",
    "httpVersion":"1.1",
    "method":"GET",
    "userAgent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/70.0.3538.77 Safari/537.36",
    "headers":"*"
  },
  "browser":"{"name":"Chrome","version":"70.0.3538.77","major":"70"}",
  "engine":"{"version":"537.36","name":"WebKit"}",
  "os":"{"name":"Mac OS","version":"10.14.0"}",
  "content":"(Empty)",
  "line":"middlewares/foo.js:14",
  "server":"127.0.0.1"
}

一些字段，如：browser, os, engine为什么在外层 有时候我们希望日志尽量扁平（最大深度为2），以避免 ES 不必要的索引带来的性能损耗。在实际输出的时候，我们会将深度大于1的值输出为字符串。而有时候一些对象字段是我们关注的，所以我们将这些特殊字段放在外层，以保证输出深度不大于2的原则。

一般的，我们在打印输出日志的时候，只须关注事件名称及数据字段即可。其他，我们可以在打印日志的方法中，通过访问上下文统一获取，计算，输出。

2. 日志改造输出

前面我们提到了如何定义一个日志事件， 那么，我们如何基于已有日志方案做升级，同时，兼容旧代码的日志调用方式。

升级关键节点的日志

// 改造前
logger.info('client-init => ' + JSON.stringfiy({
  url,
  ip,
  browser,
  //...
}));

// 改造后
logger.info({
  event: 'client-init',
  url,
  ip,
  browser,
  //...
});

兼容旧的日志调用方式

logger.debug('checkLogin');

因为 winston 的 日志方法本身就支持 string 或者 object 的传入方式, 所以对于旧的字符串传入写法，formatter 接收到的实际上是{ level: 'debug', message: 'checkLogin' }。formatter 是 winston 的日志输出前调整日志格式的一道工序， 这一点使我们在日志输出前有机会将这类调用方式输出的日志，转为一个纯输出事件 -- 我们称它们为raw-log事件，而不需要修改调用方式。

改造日志输出格式

前面提到 winston 输出日志前，会经过我们预定义的formatter，因此除了兼容逻辑的处理外，我们可以将一些公共逻辑统一放在这里处理。而调用上，我们只关注字段本身即可。

• 元字段提取及处理
• 字段长度控制
• 兼容逻辑处理

如何提取元字段，这里涉及上下文的创建与使用，这里简单介绍一下 domain 的创建与使用。

//--- middlewares/http-context.js
const domain = require('domain');
const shortid = require('shortid');

module.exports = (req, res, next) => {
  const d = domain.create();
  d.id = shortid.generate(); // reqId;
  d.req = req;
  
  //...

  res.on('finish', () => process.nextTick(() => {
    d.id = null;
    d.req = null;
    d.exit();
  });

  d.run(() => next());
}

//--- app.js
app.use(require('./middlewares/http-context.js'));

//--- formatter.js
if (process.domain) {
  reqId = process.domain.id;
}

这样，我们就可以将 reqId 输出到一次请求中所有的事件, 从而达到关联事件的目的。

二、日志采集

现在，我们知道怎么输出一个事件了，那么下一步，我们该考虑两个问题：

1. 我们要在哪里输出事件？
2. 事件要输出什么细节？

换句话说，整个请求链路中，哪些节点是我们关注的，出现问题，可以通过哪个节点的信息快速定位到问题？除此之外，我们还可以通过哪些节点的数据做统计分析？

结合一般常见的请求链路（用户请求，服务侧接收请求，服务请求下游服务器/数据库（*多次），数据聚合渲染，服务响应），如下方的流程图

流程图

那么，我们可以这样定义我们的事件：

用户请求

• client-init: 打印于框架接收到请求（未解析）， 包括：请求地址，请求头，Http 版本和方法，用户 IP 和 浏览器
• client-request: 打印于框架接收到请求（已解析），包括：请求地址，请求头，Cookie, 请求包体
• client-response: 打印于框架返回请求，包括：请求地址，响应码，响应头，响应包体

下游依赖

• http-start: 打印于请求下游起始：请求地址，请求包体，模块别名（方便基于名字聚合而且域名）
• http-success: 打印于请求返回 200：请求地址，请求包体，响应包体(code & msg & data)，耗时
• http-error: 打印于请求返回非 200，亦即连接服务器失败：请求地址，请求包体，响应包体(code & message & stack)，耗时。
• http-timeout: 打印于请求连接超时：请求地址，请求包体，响应包体(code & msg & stack)，耗时。

字段这么多，该怎么选择？ 一言以蔽之，事件输出的字段原则就是：输出你关注的，方便检索的，方便后期聚合的字段。

一些建议

请求下游的请求体和返回体有固定格式， e.g. 输入：{ action: 'getUserInfo', payload: {} } 输出: { code: 0, msg: '', data: {}} 我们可以在事件输出 action，code 等，以便后期通过 action 检索某模块具体某个接口的各项指标和聚合。

一些原则

保证输出字段类型一致 由于所有事件都存储在同一个 ES 索引， 因此，相同字段不管是相同事件还是不同事件，都应该保持一致，例如：code不应该既是数字，又是字符串，这样可能会产生字段冲突，导致某些记录（document）无法被冲突字段检索到。ES 存储类型为 keyword, 不应该超过ES mapping 设定的 ignore_above 中指定的字节数（默认4096个字节）。否则同样可能会产生无法被检索的情况三、ES 索引模版定义

这里引入 ES 的两个概念，映射(Mapping)与模版(Template)。

首先，ES 基本的存储类型大概枚举下，有以下几种

• String: keyword & text
• Numeric: long, integer, double
• Date: date
• Boolean: boolean

一般的，我们不需要显示指定每个事件字段的在ES对应的存储类型，ES 会自动根据字段第一次出现的document中的值来决定这个字段在这个索引中的存储类型。但有时候，我们需要显示指定某些字段的存储类型，这个时候我们需要定义这个索引的 Mapping, 来告诉 ES 这此字段如何存储以及如何索引。

e.g.

还记得事件元字段中有一个字段为 timestamp ？实际上，我们输出的时候，timestamp 的值是一个数字，它表示跟距离 1970/01/01 00:00:00 的毫秒数，而我们期望它在ES的存储类型为 date 类型方便后期的检索和可视化, 那么我们创建索引的时候，指定我们的Mapping。

PUT my_logs
{
 "mappings": {
  "_doc": { 
   "properties": { 
    "title":  {
      "type": "date",
      "format": "epoch_millis"
     }, 
   }
  }
 }
}

但一般的，我们可能会按日期自动生成我们的日志索引，假定我们的索引名称格式为 my_logs_yyyyMMdd （e.g. my_logs_20181030）。那么我们需要定义一个模板（Template），这个模板会在（匹配的）索引创建时自动应用预设好的 Mapping。

PUT _template/my_logs_template
{
 "index_patterns": "my_logs*",
 "mappings": {
  "_doc": { 
   "properties": { 
    "title":  {
      "type": "date",
      "format": "epoch_millis"
     }, 
   }
  }
 }
}

提示：将所有日期产生的日志都存在一张索引中，不仅带来不必要的性能开销，也不利于定期删除比较久远的日志。

小结

至此，日志改造及接入的准备工作都已经完成了，我们只须在机器上安装 FileBeat -- 一个轻量级的文件日志Agent, 它负责将日志文件中的日志传输到 ELK。接下来，我们便可使用 Kibana 快速的检索我们的日志。