使用 Async-hooks 串联 HTTP 请求上下文

开门见山，以前在写业务要求的时候，有一个记录慢查询和慢请求的耗时并上报至 ES 的需求，一样也会有其余类型的日志须要记录上报，起初并无统一字段，各类类型的日志的字段比较松散，如今须要统一日志字段。这个需求提及来也算是简单，提取一些公用的字段，好比 type、timeTaken、data 等字段，另外还有一些共有的字段，好比 username、method、url 等，这些共有字段并不须要外部传进来，只需从请求上下文中获取便可。

若是上述方法能完美的解决需求，这篇专栏文章就能够立刻发布了，可现实老是要比想象的复杂。

因为上报日志的方法 (下文称为 sendLog) 已经被多处使用，且起初并无传递 req 对象，也就是说若是要使用上述方案，那么必须给 sendLog 添加参数，这个 req 对象就必须在请求处理的 handler 里面层层传递至 sendLog，对于一个已经上线了十个月的项目来讲，这样改造起来比较比较繁琐，也不够优(zhuang)雅(bi)～

那么有没有一种不用传递 req 对象且能方(you)便(ya)的获取请求上下文的方法呢？

转战 Google 和 Stack Overflow 许久以后找到了一个 NPM 包express-http-context，此包每周有 30k+ 的下载量，看介绍里面描述以为足够优雅好用，瞬间以为这下应该稳了。

一顿常规操做以后，居然跑起来了，不用传递 req 对象也能获取到共有的参数，本地各类测试 case 各来一发，结果就是一个字——完美！这就叫专业，这就叫 Perfect！

本着负(neng)责(run)尽(jiu)职(xing)的态度，抓紧测试上线。先上一波测试环境，观察一段时间以后没问题，而后就发到生产环境了，观察一段时间以后，发现日志正常，CPU 和 RAM 也正常，关机下班。

背景

上述那么一大堆就是背景。

新问题

发布上线许久以后，某天从日志里发现，MySQL 慢查询的日志里面的共有字段全是空的，问题是使用的姿式不对？又或者是上下文丢失了？一顿搜索以后，发现这不是一个新鲜的问题，再一顿搜索以后发现，大多数项目的数据库链接都先于 HTTP 服务启动，致使回调里面的 ScopeId 无法和 HTTP 请求关联，也就是说在 MySQL 的查询回调里面，没法获取请求上下文。继续搜索的时候在Context lost after mysql query、mysql2 requests aren't being attached to root scope #946和Async Hooks do not recognize execution contexts created when processing thenables #22360里发现能够用 util.promisify 规避这个问题。

拆包

express-http-context内部并无多少代码，逻辑简单到就是给cls-hooked套了一个壳子，将它封装成 Express 的中间件，下面简单看下cls-hooked，核心逻辑在cls-hooked/blob/master/context.js里面，大体是利用了 NodeJS v8 内置的async_hooks模块的异步钩子特性，基于此封装了一个命名空间来管理请求上下文，并无发现什么明显的漏洞，百思不得解，一顿搜索以后在专栏上搜索到了一篇相关的文章——《使用 Async-hooks 集成 Envoy 和咱们的 RPC 库（二）》，这篇专栏里提到的问题一和问题三应该就是上述问题的解释：

在 async_hooks 的生命周期内，before、after是可能没有的，祖先的destory可能会比后代早。

关于 async_hooks 的介绍能够参考本文末尾连接的文章。

了解到上述缘由以后，单纯的利用 async_hooks 的生命周期钩子并不能确保上下文不会丢失，因此一个简单的思路就是只使用 init 钩子函数来记录调用栈，而后在必定时间后清除这些调用栈。

造轮子

大致思路上面已经提到，这里简单总结一下：

1. 使用 async_hooks 的 init 方法来记录调用栈。
2. 找到某个特征将一个请求的调用栈串起来。
3. 定时清除调用栈。

第1步须要在 init 方法中记录调用方和被调用方的映射关系便可，这些映射关系就组成了调用栈的依赖树，一层一层的自上而下的调用下去。细节就是创建异步调用的 asyncId 和 executionAsyncId 之间的映射关系，type 参数是为了标识异步资源的类型，主要是为了区分 TCPWRAP 实例，__tm 是记录调用栈的创建时间，以便后续清除。

asyncHooks.createHook({
  init (asyncId, type) {
    const executionAsyncId = asyncHooks.executionAsyncId()

    callstackMap[asyncId] = {
      id: executionAsyncId,
      isTCP: type === TCPWRAP_NAME,
      __tm: Date.now()
    }
  }
}).enable()

第3步用定时器去清除过时的调用栈便可。

第2步就是如何在茫茫如海的调用栈中将一个请求全部相关的调用栈串起来，最终请求都会通过这个中间件，如何在 Express 或者 Koa 这种框架的模型下组织请求上下文？写个 Express 和 async_hooks 组合的例子，看看 init 方法的参数：

const fs = require('fs')
const asyncHooks = require('async_hooks')
const express = require('express')

asyncHooks.createHook({
  init (asyncId, type, triggerAsyncId) {
    const eid = asyncHooks.executionAsyncId()
    fs.writeSync(1, `${type}(${asyncId}): trigger: ${triggerAsyncId} execution: ${eid}\n`)
  }
}).enable()

const app = express()

app.all('*', (req, res) => {
  res.send('Hello World!')
})

app.listen(3001)

请求三次后查看打印以下：

TCPWRAP(6): trigger: 1 execution: 1
TickObject(7): trigger: 6 execution: 1
TCPWRAP(8): trigger: 6 execution: 0
TIMERWRAP(9): trigger: 6 execution: 6
Timeout(10): trigger: 6 execution: 6
HTTPPARSER(11): trigger: 6 execution: 6
HTTPPARSER(12): trigger: 6 execution: 6
TickObject(13): trigger: 6 execution: 6
TIMERWRAP(14): trigger: 12 execution: 12
Timeout(15): trigger: 12 execution: 12
TickObject(16): trigger: 8 execution: 12
WRITEWRAP(17): trigger: 8 execution: 12
TickObject(18): trigger: 12 execution: 12
TickObject(19): trigger: 12 execution: 12
TickObject(20): trigger: 16 execution: 16
TIMERWRAP(21): trigger: 16 execution: 16
TickObject(22): trigger: 19 execution: 19
TickObject(23): trigger: 20 execution: 20
TickObject(24): trigger: 20 execution: 20
TickObject(25): trigger: 20 execution: 20
TickObject(26): trigger: 8 execution: 8
TickObject(27): trigger: 8 execution: 8
TCPWRAP(28): trigger: 6 execution: 0
Timeout(29): trigger: 6 execution: 6
HTTPPARSER(30): trigger: 6 execution: 6
TickObject(31): trigger: 6 execution: 6
TIMERWRAP(32): trigger: 30 execution: 30
TickObject(33): trigger: 28 execution: 30
WRITEWRAP(34): trigger: 28 execution: 30
TickObject(35): trigger: 30 execution: 30
TickObject(36): trigger: 30 execution: 30
TickObject(37): trigger: 33 execution: 33
TickObject(38): trigger: 36 execution: 36
TickObject(39): trigger: 37 execution: 37
TickObject(40): trigger: 37 execution: 37
TickObject(41): trigger: 37 execution: 37
TickObject(42): trigger: 28 execution: 28
TickObject(43): trigger: 28 execution: 28
TCPWRAP(44): trigger: 6 execution: 0
Timeout(45): trigger: 6 execution: 6
HTTPPARSER(46): trigger: 6 execution: 6
TickObject(47): trigger: 6 execution: 6
TickObject(48): trigger: 44 execution: 46
WRITEWRAP(49): trigger: 44 execution: 46
TickObject(50): trigger: 46 execution: 46
TickObject(51): trigger: 46 execution: 46
TickObject(52): trigger: 48 execution: 48
TickObject(53): trigger: 51 execution: 51
TickObject(54): trigger: 52 execution: 52
TickObject(55): trigger: 52 execution: 52
TickObject(56): trigger: 52 execution: 52
TickObject(57): trigger: 44 execution: 44
TickObject(58): trigger: 44 execution: 44

其中第1-2行的日志在我没有请求的时候就已经有了，因此请求产生的日志是从第三行开始的，仔细观察就会发现，每一次请求都会有一个类型为TCPWRAP的调用栈记录，NodeJS 官方文档里这样解释：

The TCPWRAPis the new connection from the client. When a new connection is made, the TCPWrapinstance is immediately constructed. This happens outside of any JavaScript stack. (An executionAsyncId()of 0means that it is being executed from C++ with no JavaScript stack above it.) With only that information, it would be impossible to link resources together in terms of what caused them to be created, so triggerAsyncIdis given the task of propagating what resource is responsible for the new resource's existence.

简而言之就是每接收到一个来自客户端的请求，当这个请求链接创建的时候，这个 TCPWrap 实例就马上被建立。

经过以上发现，咱们能够利用 TCPWRAP 来标志一个请求的开始，这个标志也就能够做为这个请求调用栈的根。下面就须要将 TCPWRAP 和中间件关联起来，咱们经过中间件执行时的 executionAsyncId 和 init 里记录的调用栈来向上寻找最近的 TCPWRAP 实例对应的 executionAsyncId，这个 TCPWRAP 实例对应 executionAsyncId 就是这个请求的根。

既然有了这个能够标志根的 executionAsyncId，暂且叫它 rootId，那么请求在进入下一个中间件的时候，均可以根据自身的 executionAsyncId 来向上寻找，直到找到 rootId。每次 set、get 的时候，都会根据对应的 rootId 找到对应的上下文，这样就将一个请求的上下文串起来了。

因为 rootId 是在中间件执行的时候肯定的，因此在 TCPWRAP 实例建立以后到中间件之间，不该该有任何异步的操做，简而言之就是将该中间件放置在其他含有异步操做的中间件的最前面，该中间件以前不该有任何包含异步操做的中间件。

由于从 TCPWRAP 实例建立到进入中间件是同步的，因此在进入中间件的时候，只需按照中间件对应的 executionAsyncId 向前递归查找最近的 TCPWRAP 实例对应的 asyncId 便可，也就找到了此次请求对应的 rootId。以后给 rootId 对应的调用栈初始化一个空的上下文，

// middleware logic
const middleware = () => {
  const executionAsyncId = asyncHooks.executionAsyncId()
  const rootId = findTCPWrapAsyncId(executionAsyncId)
  callstackMap[rootId].data = {}
  callstackMap[executionAsyncId] = {
    id: rootId,
    __tm: Date.now()
  }
}

// find rootId
const findTCPWrapAsyncId = asyncId => {
  if (callstackMap[asyncId]) {
    if (callstackMap[asyncId].type === TCPWRAP_NAME) {
      return asyncId
    }
    return findTCPWrapAsyncId(asyncId - 1)
  }
}

优化

总以为第3步用定时器清除调用栈的操做不够优雅，出于能尽可能尽快的删除无用调用栈的考虑，能否在某些时刻主动删除，而不是一股脑的都在定时器里删除。

首先想到的就是利用前文所说的 destory 钩子方法，可是考虑到上文说起到的问题，须要在 TCPWRAP 实例销毁的时候清除对应调用栈。还有一种方法就是在 http.ServerResponse 的 finish 和 close 事件触发的时候清除调用栈。

最后再使用定时器去删除一些游走在 http 请求以外的调用栈便可。

还没完

上述逻辑上线以后，仍然有上下文丢失的状况发生，真是急秃了头。从日志里发现，上下文丢失绝大多数发生在服务端异步请求超时以后，本地也能够模拟复现这个问题。许久以后在想明白，在客户端请求超时或者用户终止里链接，上述优化操做在这个时候就会清除该请求的调用栈，可是这其中有一个很微妙的细节，客户端超时以后，服务端调用其余服务可能尚未结束，在这些调用结束以前，它所属的请求的调用栈早已被清除，这些调用结束以后在操做上下文的话，上下文早已销声匿迹了，无处可寻。

因此上文提到的优化并不可靠，目前只能依赖定时器去清除调用栈，且要根据业务须要合理设置有效时间。

必须优化

还有没有其余的优化办法呢？固然有！既然 destory 钩子方法不可靠，那就从其余可靠的地方下手，NodeJS 的请求里面有两个事件，分别是finish和close，两者必然会触发一个。固然在这两个事件直接触发以后清除调用栈是能够的，不过仍然有一种情形须要妥善考虑，测试过程当中发现 close 事件通常发生在客户端终止请求，这种情形通常发生在服务端超时(亦或者是服务端处理时间太久)，用户失去耐心，关闭页面或者刷新页面致使的。这种情形下，close 事件触发以后清除调用栈，内部的异步请求可能稍后才有返回，这是再去获取上下文就已经迟了。虽然这个优化点要比 destory 钩子方法可靠一点，但也不是绝对可靠的，可是在大多数业务场景下，在 finish 事件以后清除调用栈是可靠的！

既然都不是绝对可靠的，那就将这些优化操做做为可选项，默认关闭。在内部使用中，只开启了 finish 事件以后清除调用栈，效果挺好。

具体逻辑和以前相似，全部拥有 rootId 的调用栈都会被记到 rootId 下，一旦 finish/close 事件触发，若是须要清除调用栈的就将该 rootId 对应的调用栈一并清理掉便可。

End

上线观察一段时间后，没有出现过上下文丢失的状况了，内存使用也正常，服务性能也正常，目前惟一担忧的就是该中间件可否经得住大流量&复杂逻辑场景的考验。

最后的产出就是一个中间件http-request-context，总的代码加上对 Express + Koa 中间件的封装不足百行，欢迎使用、指正。

参考

• 原文首发于知乎专栏《使用 Async-hooks 串联 HTTP 请求上下文》
• NodeJS async_hooks
• 《Node.js v8.x 新特性 Async Hook 简介》
• 《使用 Async-hooks 集成 Envoy 和咱们的 RPC 库（二）》