Node.js 诊断指南第一弹

发表于 3年以前 | 总阅读数：434 次

TL;DR

本文介绍的诊断小技巧有：调试环境变量、进程退出码、废弃 API 警告、识别同步 I/O 和处理 Unhandled Promise Rejection。

调试环境变量

以笔者最初使用的 Node.js 版本 v0.10.x 来说，当时内置的 util 还没有提供 util.debuglog 方法，只有一个的 util.debug 效果等同于 console.error，而在当时已经开始要流行的是使用 TJ 的 debug 包，例如：

var debug = require('debug')('http')
  , http = require('http')
  , name = 'My App';

// fake app

debug('booting %o', name);

http.createServer(function(req, res){
  debug(req.method + ' ' + req.url);
  res.end('hello\n');
}).listen(3000, function(){
  debug('listening');
});

通过 DEBUG 环境变量指定了 http 这个 label，就可以把代码中 label 为 http 的调试日志输出：

在 TJ 的设想里，只要开发者所写的所有模块及其依赖的模块都使用这种方式，那么调试的时候大家都可以使用 DEBUG 这个 env 来过滤和开启所有人的 debug 日志。

由于 TJ 的这个模块出来实在是太早了（10年前），所以基本上已经成为了社区的一个默认约定，大部分流行的 npm 包内部都会使用这个模块来输出调试日志（而不是 util.debuglog）。

以国内的 eggjs 框架为例，我们直接启动的日志如下：

通过 DEBUG 环境变量可以开启指定模块的内部调试日志：

PS: 通过 DEBUG=* 就可以开启所有的日志。

实际上 Node.js 也内置了类似的机制，不过目前普遍认为 Node.js 内置的环境变量主要是用来排查 Node.js 内置的代码和模块用的。这里主要有两个环境变量分别对应了 Node.js 内置的 JavaScript 层以及 C++ 层的调试日志，分别是：

NODE_DEBUG 用于开启 JavaScript 调试日志开关（也包括用户使用 util.debuglog 的部分）
NODE_DEBUG_NATIVE 用户开启 C++ 调试日志开关

常见的 NODE_DEBUG 开关:

timer
http
net
fs
cluster
tls
stream
child_process
module

以上文中的 http 代码为例，同时开启 DEBUG 和 NODE_DEBUG 效果：

上图中，我们开启了 Node.js 内置的 net 模块的日志初始，之后每次 http 请求进来，net 模块的 debug 日志都会详细输出（由于日志内容比较多所以没有放出来请求的例子图，大家可以自行测试）。

进程退出码

有的时候我们的 Node.js 进程直接退出了，如果没有收集到足够错误日志，可以根据进程的退出码辅助判断错误情况。下面引用 Node.js 文档中的内容：

在没有更多异步操作的时候，Node.js 会直接 0 状态代码退出。在其他情况下使用以下状态代码：

1 未捕获的致命异常：存在未捕获的异常，并且其没有被 domain 模块或 'uncaughtException' 事件处理器处理。
// 省略...
6 空函数的内部异常处理器：存在未捕获的异常，然后内部致命异常处理器由于不明原因设置为了 nullptr（空函数），即没有办法执行默认的致命异常处理。
7 内部异常处理器运行时失败：存在未捕获的异常，并且内部致命异常处理函数本身在尝试处理时抛出错误。例如，如果 'uncaughtException' 或 domain.on('error') 处理器抛出错误，就会发生这种情况。
// 省略..
>128 信号退出：如果 Node.js 收到致命的信号，例如 SIGKILL 或 SIGHUP，则其退出码将是 128 加上信号代码的值。这是标准的 POSIX 实践，因为退出码被定义为 7 位整数，并且信号退出设置高位，然后包含信号代码的值。例如，信号 SIGABRT 的值是 6，因此预期的退出码将是 128 + 6 或 134。

完整参见 https://nodejs.org/api/process.html#process_exit_codes。

我们来举个例子：


// arr-crash.js
process.on('uncaughtException', () => {
  console.error('Ya!');
});

const arr = [];
while(true) arr.push(1);

然后测试：

在 Node.js 进程 crash 之后我们通过 echo $? 可以输出之前进程崩溃之后的退出码，上例中为 134。根据上文中的文档，我们可以知道 134 = 128 + 6 即导致进程退出的异常类型为 6，参考文档：

6 空函数的内部异常处理器：存在未捕获的异常，然后内部致命异常处理器由于不明原因设置为了 nullptr（空函数），即没有办法执行默认的致命异常处理。

虽然无法根据错误码知道本例中的进程 crash 的异常是什么，但是可以知道 crash 的时候进程是被强行 SIGKILL 或 SIGHUP 退出的，并且此时 V8 连默认的异常处理器都用不了了（内存爆了啥都做不了了）。

再来一个测试列子：


// uncaught-exception.js
process.on('uncaughtException', () => {
  throw new Error('there..')
});

throw new Error('here..')

测试情况：

根据错误码，我们可以找到文档：

7 内部异常处理器运行时失败：存在未捕获的异常，并且内部致命异常处理函数本身在尝试处理时抛出错误。例如，如果 'uncaughtException' 或 domain.on('error') 处理器抛出错误，就会发生这种情况。

可以发现跟我们测试的情况吻合 —— 在执行致命异常处理器（uncaughtException handler）的时候抛错导致异常无法处理然后进程退出。

废弃 API 警告

Node.js 提供了官方的废弃（deprecate）标记，开发者也可以通过 util.deprecate 方法，将某些接口标记为废弃状态，例如：


// uncaught-exception.js
process.on('uncaughtException', () => {
  throw new Error('there..')
});

throw new Error('here..')

我们也可以通过 --no-deprecations 来关闭平常使用过程中碰到的 deprecate 警告（不过不是很推荐）。

有时候我们想找到抛这个警告的代码位置在哪，那么可以使用 --trace-deprecation 来开启 trace 错误栈，这样在警告出来的时候就会附上具体的代码 stack。如果更严格一些不希望代码中出现使用废弃版本的情况，那么可以考虑使用 --throw-deprecations 标志，这样使用废弃 API 的地方会直接 throw error，例如：

识别同步 I/O 操作

由于 Node.js 是单线程的，在使用提供服务的时候，如果出现了耗时过长的同步 I/O 操作，那么期间就会 block 住整个线程。为了避免这种情况我们可以使用 --trace-sync-io 标志开启 Node.js 内置的同步 I/O 追踪检测功能。


const { readFileSync } = require('fs');

setImmediate(() => readFileSync(__filename));

测试效果：

Unhandled Promise Rejection

测试代码：

const p = new Promise((resolve, reject) => {
  // throw new Error(111); // 与下一行等效
  reject(new Error(111));
});

测试效果

(node:10142) UnhandledPromiseRejectionWarning: Error: 111
    at /Users/lellansinhuang/workspace/midwayjs-tutorial/tmp/reject.js:4:10
    at new Promise (<anonymous>)
    at Object.<anonymous> (/Users/lellansinhuang/workspace/midwayjs-tutorial/tmp/reject.js:2:11)
    at Module._compile (internal/modules/cjs/loader.js:1147:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:1167:10)
    at Module.load (internal/modules/cjs/loader.js:996:32)
    at Function.Module._load (internal/modules/cjs/loader.js:896:14)
    at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:71:12)
    at internal/main/run_main_module.js:17:47
    (node:10142) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 1)

JavaScript 的 Promise 有三种状态，分别是 pending、fulfilled 和 rejected。当一个 promise 的 rejected 状态没有后续处理的时候就会触发上述报错。也就是说如果上面的代码加上，如 p.catch(console.log) 这样的捕获异常逻辑就不会出现 UnhandledPromiseRejectionWarning 警告。

Unhandled Promise Rejection 是在 Node.js v12 时引入的新特性。不处理 Promies 的这种状态在浏览器中一种可以接受的行文，但是在服务端则不然，因为这种报错可能导致内存泄漏。为了避免这种问题，可以了解一下 --unhandled-rejections 的几种设置：

throw: 触发一个 unhandledRejection 事件，你可以通过 promise.on('<span style="color: var(--green4);">unhandledRejection') 来监听，如果你没有监听，那么会当成一个未捕获的 error 抛出。（默认行为）
strict: 直接抛 error。
warn: 不论是否设置了监听行为，总是产生一个警告。
warn-with-error-code: 触发 unhandledRejection 事件，如果没有监听，触发一个警告，并把进程退出码设置为 1。
none: 静默所有警告。

我们将上文中的测试改为使用 strict 模式，则可以得到如下报错：

$ node --unhandled-rejections=strict reject.js
/Users/lellansinhuang/workspace/midwayjs-tutorial/tmp/reject.js:4
  reject(new Error(111));
         ^

Error: 111
    at /Users/lellansinhuang/workspace/midwayjs-tutorial/tmp/reject.js:4:10
    at new Promise (<anonymous>)
    at Object.<anonymous> (/Users/lellansinhuang/workspace/midwayjs-tutorial/tmp/reject.js:2:11)
    at Module._compile (internal/modules/cjs/loader.js:1147:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:1167:10)
    at Module.load (internal/modules/cjs/loader.js:996:32)
    at Function.Module._load (internal/modules/cjs/loader.js:896:14)
    at Function.executeUserEntryPoint [as runMain] (internal/modules/run_main.js:71:12)
    at internal/main/run_main_module.js:17:47

通过 strict 让进程直接 crash 或者流程报错 block 住，这是一种 let it crash 的思想。

- END -