仓库源文，站点原文

title: 记一次 Node.js 进程挂起的 BUG 追踪 date: 2019-08-08 21:31:02 tag: [Node.js]

categories: Node.js

前言

先把干货放前面，辅助排查的 npm 模块有：wtfnode，why-is-node-running，active-handles 等，使用方法差不多如下，可以查看各自的文档。

const wtf = require('wtfnode');

// your codes

// track down
wtf.dump();

也可以更深入地排查，因为上述模块的核心都是 Node.js 文档未标注的两个接口：

process._getActiveHandles();
process._getActiveRequests();

好了，本篇到这里结束了，剩下的内容，劝你还是跳过吧：流水帐警告⚠️️ 翻车警告⚠️️

问题经过

背景是为 ts + egg 项目引入 apm 探针，由于 apm 必须在“启动文件”的第一行完成加载，即整个 egg 的生命周期开始之前，因此需要使用独立的脚本或指令进行启动。具体如何处理可以参考这篇博客。

问题就出在脱离了 egg 的声明周期，得额外管理不同运行环境下 apm-server（APM 数据采集服务器）的地址配置。可能第一时间就能想到 Node.js 的环境变量，思路没错，毕竟程序和 egg-bin 绑定，NODE_ENV 环境变量的命名符合规范，主要为 development、test、production。特定环境读取特定的即可。

但调试过程中，写错了 apm-server 路径，遇到了进程启动过程中卡住的现象。解决起来很容易，但好奇是什么原因造成的，因为正常引入 elastic-apm-node 并填写一个错误的 url 并不妨碍主流程的运行。

战前准备

省略翻代码的过程，简单的结论就是：进程卡死的问题由 egg-bin 内置的 ets（egg-ts-helper）指令诱发，其使用 child_process.execSync 方法启动子进程来预加载一部分代码用作检查，而子进程卡住不退出，才导致父进程无法继续向下执行。

ets 执行 execSync 的位置：https://github.com/whxaxes/egg-ts-helper/blob/master/src/utils.ts#L107 其中 cmd 的内容是执行 ./scripts/eggInfo 文件。eggInfo 指令了 egg 的 loader 来获取插件信息，因此 apm 作为生命周期之前的模块被顺便加载了。

经过检查和断点调试，已经找出进程无法正常退出的根源在 elasitc-apm-http-client 模块和 apm-server 的通讯之间。并且如果把 apm-server 的目标地址改成本机未使用的端口，如 http://localhost:8201，进程可迅速地正常退出。但如果填写一个错误地或不存在的地址，例如 http://10.10.10.10:8200 ，以致访问超时，进程就会挂起。

开始狩猎

我们已经缩小了问题重现的范围，就可以仔细阅读代码了。

首先看向 http client 创建的步骤，唯一值得注意的点是一个轮询操作。apm 创建时默认开启了 elastic-apm-http-client 的 centralConfig 选项，此功能是允许在 Kibana 看板上直接修改 apm agent 的配置而无须重启 Node.js 进程，实现原理便是轮询 apm-server 以查询最新的配置信息。

Client.prototype._pollConfig = function () {
  // ...
  const req = this._transport.get(opts, res => {
    // ...
  })

  req.on('error', err => {
    this._scheduleNextConfigPoll()
    this.emit('request-error', err)
  })
}

Client.prototype._scheduleNextConfigPoll = function (seconds) {
  if (this._configTimer !== null) return

  seconds = seconds || 300

  this._configTimer = setTimeout(() => {
    this._configTimer = null
    this._pollConfig()
  }, seconds * 1000)

  this._configTimer.unref()
}

虽然轮询可怕，但上面已经为 Timeout 调用了 unref 方法。正常来说，只要没有其他 event loop 在运行，Timer.unref() 能够让 Node.js 进程在 Timeout 回调调用前退出，可以防止程序空转。

因此问题不在这段代码，为了验证推断，关闭此选项之后，果然依旧不能正常退出。

既然进程还在运转，就一定有其他的 event loop。在 elastic-apm-http-client 中继续寻找到了另一个 Timeout，该函数每次触发数据上报时都会被调用。

Client.prototype._maybeCork = function () {
  if (!this._writableState.corked && this._conf.bufferWindowTime !== -1) {
    this.cork()
    if (this._corkTimer && this._corkTimer.refresh) {
      // the refresh function was added in Node 10.2.0
      this._corkTimer.refresh()
    } else {
      this._corkTimer = setTimeout(() => {
        this.uncork()
      }, this._conf.bufferWindowTime)
    }
  } else if (this._writableState.length >= this._conf.bufferWindowSize) {
    this._maybeUncork()
  }
}

Timer.refresh() 可以重置已执行的定时任务，这里很有可能是真正的问题点。

暂停代码阅读，先盲目猜测一波：在第一次请求超时之前，进程一定不会退出，但超时之后，将在 30 秒后才会重新发起新的请求，进程退出的机会就在这 30 秒。而 _maybeCork 这里虽然每次数据上报都会触发不经过 unref 处理的 setTimeout，奈何我查了 bufferWindowTime 默认才 20 毫秒。所以问题出在这里的可能性又很渺茫了，试下把这段注释掉，果然…… 但凭着对 elastic-apm-node 项目的熟悉，性能指标的上报间隔恰好也是 30 秒，这里一定有个定时任务的，但之前直接在项目中搜索关键字未找到，就忽略了。

根据相关时间字段，又检索到了定时任务的创建地点 —— measured-reporting 模块，然而这里也做了 unref 处理。

_createIntervalCallback(intervalInSeconds) {
  this._log.debug(`_createIntervalCallback() called with intervalInSeconds: ${intervalInSeconds}`);

  const timer = setInterval(() => {
    this._reportMetricsWithInterval(intervalInSeconds);
  }, intervalInSeconds * 1000);

  if (this._unrefTimers) {
    timer.unref();
  }

  this._intervals.push(timer);
}

狩猎失败/超时

在 node_modules 中全局搜索了 setTimeout 以及 setInterval，排除了所有可疑迹象，剩下的连接就难排查了，迫于“生产力”，问题暂时追踪到这里。。。

亡羊补牢

思考了对应的解决方案：

将 ets 改成异步执行，但可能失去了前置检查的意义
分析并重写 elastic-apm-node 的连接机制
在 ets 执行时不启动 apm
做好连通性检测，确保 apm 的配置可靠再 apm.start()，但网络请求是异步的，会让 apm 之后整个项目的模块加载都在异步回调中处理

1、2 的成本太高，而 4 没有做过可靠的测试，不保证不会对模块加载和优化产生副作用，所以最可行的方案是 3。

找准方向就开搞，通过 process.env 入手，关注几个比较有用的环境变量：

process.env.NODE_ENV
process.env.ETS_REGISTER_PID，此变量存在时，证明有 ets 参与，不启动。但特别地，单独运行 ets 时没有此变量，也没有 NODE_ENV，应对方法是将 NODE_ENV 为 undefined 的环境也排除。
process.env.npm_lifecycle_event，是 npm 添加的当前执行的 npm script 名称标识。可以考虑为 start，restart 时才启动。

补充方案：通过 process.env 向 apm 传递自定义参数，便于控制配置项。

最后 apm 启动头部长这个样子

// 自定义 APM_ENABLE 作为开关条件
const enableAPM = process.env.APM_ENABLE || (process.env.NODE_ENV && !process.env.ETS_REGISTER_PID);
if (enableAPM) {
  // 除了 NODE_ENV，也可以使用自定义的 ENV
  const options = getOptionsByENV(process.env.NODE_ENV)
  apm.start(options);
}

总结

虽然没结论，但进程挂起的根本原因是没错的。找 BUG 最耗时的是方向歪了，试过用干净的 Node.js 代码模拟，没能复现问题。而 wtfnode 和其他跟踪模块，因为 callsite 覆盖问题，也没能提供清晰的调用栈，或许应该考虑从修复 callsite 这个方向入手？

To be continue?

但是意义不大了，从这堆充满 hack 的代码中并没有学到特别有价值的东西，而且时间成本太高。倒是警醒自己在 Timer 和 socket 的底层使用上，务必留意 unref 的处理。还是把时间留给更重要的事吧，衰！