如何正确的为 NodeJS 打日志并快速定位问题～-Js中文网

JS中文网 - 前端进阶资源教程,www.javascriptC.com
当你在 NodeJS 中 log 时，什么是让你最头疼的事情？如果你问我，我会认为是缺乏创建 trace ID 的工业标准。本文中，我们将看一看如何创建这些 trace ID（我们将简要地试验如何在本地持续存储，即 CLS），并且深入了解如何利用 Proxy 使之在任意 logger 中生效。

为何在 NodeJS 中为每一个请求创建 trace ID 会遇到问题

在那些会为每个请求创建一条新线程的多线程平台中，有一个概念叫本地线程存储(TLS(thread-local storage))，它会将一个线程中的所有可用数据保存下来。如果原生 API 支持 TLS，则可以轻松地为每一个请求创建一个随机 ID，后续只需将其放入 TLS 中以备之后在 controller 或 service 中使用。所以在 NodeJS 中怎么做到的呢？众所周知，NodeJS 是一个单线程平台（不太准确，因为我们知道有 workers，但是不影响大图），这使得 TLS 意义不大。NodeJS 并不会操作不同的线程，而是在同一线程中执行不同的回调（如果你对 NodeJS 感兴趣的话，这里有一份全面的系列文章），而且 NodeJS 为我们提供了一种方法用来唯一地标识这些回调并且追踪他们之间的联系。

回到过去 (v0.11.11)，addAsyncListener 方法为我们提供了追踪异步事件的能力。Forrest Norvell 基于它实现了第一版持续本地存储即 CLS 。但我们无需了解这个 CLS 的实现，因为这个 API 在 v0.12 中已经被去掉了。

直到 NodeJS 8 之前，我们都没有官方的方法监听 NodeJS 的异步事件进度。NodeJS 8 终于通过 async_hooks 为我们提供了这个能力(如果你想深入理解 async_hooks 请看这篇文章)。它为我们带来了基于 async_hooks 的 CLS 实现 ——cls-hooked。

JS中文网 – 前端进阶资源教程 www.javascriptC.com
一个致力于帮助开发者用代码改变世界为使命的平台，每天都可以在这里找到技术世界的头条内容

CLS 总览

下图简要展示了 CLS 的运行流：

JS中文网 - 前端进阶资源教程,www.javascriptC.com

我们来一步步地拆解它:

假设我们有一个经典的 web 服务器。首先我们需要创建一个 CLS 命名空间，它将会作用于我们应用的整个生命周期。
然后，我们需要配置一个中间件用于为每个请求创建一个新的 CLS 上下文。简单点，我们假设这个中间件仅仅是接收到一个新请求后执行的一个回调函数。
所以，当一个新请求到来时，我们就会调用那个回调函数。
在这个函数中，我们创建一个新的 CLS 上下文（一种办法是使用 run API 调用）
此时，CLS 将这个新的上下文放入一个上下文的 map 中（通过当前的执行 ID）。
每一个 CLS 命名空间拥有一个 active 属性。在此阶段，CLS 将 active 分配到 context 中。
在上下文中，我们向某个异步资源发起请求，比如向数据库请求一些数据。我们将回调函数传入这个请求，在数据库请求完成后将会调用这个回调函数。
新异步操作会触发一个init异步钩子。它会通过异步 ID 将当前的上下文加入上下文 map（该 ID 可以标识这次新异步操作）。现在，这个 map 中会有两个 ID 指向同一个 context。
由于我们的首次回调中没有额外的逻辑了，因此它会及时退出并结束我们的首次异步操作。
首次回调会触发 after 异步钩子。它将命名空间中的活跃上下文设为 undefined（不一定会这么做，比如我们可能会有多个嵌套的上下文，但是对于大部分简单的 case 来说是这样的）。
首次操作会触发 destroy 钩子。它会通过自己的异步 ID 将上下文移出我们的 map（该 ID 与我们第一次回调的执行 ID 一致）。
数据库请求结束，我们的第二次回调将会被触发。
此时 before 异步钩子开始工作。它当前的执行 ID 与第二次操作（请求数据库）的异步 ID 一致。它将命名空间下的 active 属性赋值为它的执行 ID 对应的上下文。这个上下文就是我们之前创建的。
现在我们开始执行第二次回调，在内部执行一些业务逻辑。在该函数中，我们可以从 CLS 中通过 key 获得任何值，它会在我们之前创建的上下文中搜索并返回该 key 相应的内容。
假设我们的方法返回的请求过程结束了。
after 异步钩子为第二次回调触发。它将命名空间中的活动上下文设为 undefined。
destroy 为第二次异步操作触发。它从上下文 map 中移除了我们的上下文（通过它的异步 ID）使其彻底清空。
由于我们不再拥有任何上下文对象的引用，我们的垃圾回收释放了其对应的内存。

这是使用钩子的具体流程的一个简化版本，它覆盖了所有主要的步骤。如果你想深入了解，可以查看这份不到 500 行的源码。

JS中文网 – 前端进阶资源教程 www.javascriptC.com
一个致力于帮助开发者用代码改变世界为使命的平台，每天都可以在这里找到技术世界的头条内容

生成 trace ID

通过上述内容我们全面了解了 CLS，所以我们思考下如何利用它为我们服务。一种方式是创建一个中间件包裹一个上下文中的每个请求，生成一个随机标识并将其放入CLS 中的 key traceID 下。之后我们可以在我们的所有 controller 和 service 中从 CLS 中获取这个标识。

在 express 中这个中间件可以这么写：

const cls = require('cls-hooked')
const uuidv4 = require('uuid/v4')

const clsNamespace = cls.createNamespace('app')

const clsMiddleware = (req, res, next) => {
  // req and res are event emitters. We want to access CLS context inside of their event callbacks
  clsNamespace.bind(req)
  clsNamespace.bind(res)

  const traceID = uuidv4()

  clsNamespace.run(() => {
    clsNamespace.set('traceID', traceID)

    next()
  })
}

然后在 controller 中，我们可以用这种方式获取 traceID：

const controller = (req, res, next) => {
  const traceID = clsNamespace.get('traceID')
}

这个 traceID 没什么用，除非我们将其加入我们的日志中。

我们将其加入 winston 中。

const { createLogger, format, transports } = require('winston')

const addTraceId = printf((info) => {
  let message = info.message
  const traceID = clsNamespace.get('taceID')
  if (traceID) {
    message = `[TraceID: ${traceID}]: ${message}`
  }
  return message
})

const logger = createLogger({
  format: addTraceId,
  transports: [new transports.Console()],
})

当然，如果所有 logger 支持以函数的形式定义 formatter（很多 logger 因特定原因不支持），那么这篇文章就没必要写了。所以如何将 traceID 加到我最爱的 pino中呢？Proxy 可以做到！

JS中文网 – 前端进阶资源教程 www.javascriptC.com
一个致力于帮助开发者用代码改变世界为使命的平台，每天都可以在这里找到技术世界的头条内容

结合 Proxy 和 CLS

Proxy 是一个可以包裹基础对象的对象，使得我们可以在特定场景下重载其表现。这些场景（被称作 trap）是有限的，你可以在这里浏览整个列表。但是我们只关心 get 这个 trap。它为我们提供了拦截属性获取过程的能力，这意味着如果我们使用 Proxy 包裹 const a = { prop: 1 } 对象，我们可以使用 get trap 为 a.prop 返回任何值。

所以，我们的办法是为每一个请求生成一个随机 traceID，创建一个包含该 traceID 的子 pino logger，并将其放入 CLS。然后我们可以使用 Proxy 包裹原生 logger，如果找到代理，它将把所有记录请求重定向到CLS 内的子 logger 中，否则继续使用原生 logger。

在这种场景下，我们的 Proxy 可以这么写：

const pino = require('pino')

const logger = pino()
const loggerCls = new Proxy(logger, {
  get(target, property, receiver) {
    // Fallback to our original logger if there is no child logger in CLS
    target = clsNamespace.get('loggerCls') || target
    return Reflect.get(target, property, receiver)
  },
})

我们的中间件将会改写成如下形式：

const cls = require('cls-hooked')
const uuidv4 = require('uuid/v4')

const clsMiddleware = (req, res, next) => {
  // req and res are event emitters. We want to access CLS context inside of their event callbacks
  clsNamespace.bind(req)
  clsNamespace.bind(res)

  const traceID = uuidv4()
  const loggerWithTraceId = logger.child({ traceID })

  clsNamespace.run(() => {
    clsNamespace.set('loggerCls', loggerWithTraceId)

    next()
  })
}

然后我们用如下方式使用 logger：

const controller = (req, res, next) => {
  loggerCls.info('Long live rocknroll!')
  // Logs something like
  // {"level":30,"time":1551385666046,"msg":"Long live rocknroll!","pid":25,"hostname":"eb6a6c70f5c4","traceID":"9ba393f0-ec8c-4396-8092-b7e4b6f375b5","v":1}
}

cls-proxify

基于上面的想法，我们创建了一个小工具 cls-proxify。它集成了 express、koa 及 fastify 并做到开箱即用。它不仅为原生对象应用了 get trap，还应用了一些其他的。因此，基于它可以做无限可能的应用，你可以代理函数调用、类构造以及几乎任何事情！唯一限制你的只是你的想象力！这个 demo 展示了将其运用于 pino 和 fastify，pino 和 express。

希望您发现了对您的项目有用的东西。随时向我传达您的反馈！我非常感谢任何批评和疑问。