好久没写 Node.js 故障案例了，今天是一枚全新的进程假死无响应案例。

特点时完全不同于之前常规遇到的类死循环引发的阻塞假死，值得记录分析的过程，希望对遇到其它的类似案例的开发者有所启发。

I. 故障现象

Easy-Monitor 开源官方讨论群里有一位同学 Midqiu 遇到了进程跑几个小时后就处于假死无响应的问题，而且神奇的是进程假死的同时，监控服务端的 系统数据 也同时断开：
image.png
此时 进程数据 界面则回退到实例刚刚接入还未上报数据的状态：
image.png
可以看到业务进程依旧在，检查此进程状态则显示 xprofiler 插件未启用：
image.png
可以确认这个进程在几个小时之前是正确接入了 Easy-Monitor 的监控服务端的，经过和 Midqiu 的沟通，发现从进程假死的那一刻开始， xprofiler 插件的日志就没有再生成了。

但是 xprofiler 插件在设计之初为了规避和 JS 工作主线程之间的互相干扰，所以是采用了 uv trhread 起了工作线程处理内核数据的，理论上 JS 线程卡死也不会影响它的内核日志输出。

这样现象就很奇怪了，Node.js 的 JS 主线程卡死竟然会让插件的日志也无法正常输出。

II. 初步排查问题

既然是进程假死无响应，首先猜测的就是是不是 JS 工作主线程卡死导致的，所以线下沟通 SSH 到服务器上查看假死时的 Node.js 负载：
image.png
使用 top -H -p <pid> 查看发现 CPU 占用不到 1%，内存整体在 300MB 附近也非常正常。这时候其实我还不死心，手动在服务器应用下执行了 xprofiler 插件的命令：

  1. ./node_modules/.bin/xprofctl check_version -p <pid>

然而事实证明确实不仅仅是 JS 主线程假死，连插件创建的 IPC 通信线程也假死了：
image.png
此时第一次感到这个问题可能没有想象的那么简单了，初步总结了下故障现象：

  • 运行几小时后 Node.js 服务无响应，进程还在（未重启）
  • 进程的 CPU 和 RSS 均正常
  • xprofiler 插件创建的内核日志子线程和 IPC 通信子线程也无响应

此时没什么好办法，只能祭出大招手动生成分析 Core 文件。

III. 分析 Coredump

首先在服务器上安装神器 gcore，然后执行 sudo gcore <pid> 生成 core 文件。Midqiu 将生成的 core 文件和 node 可执行文件打包发给了我，本地使用 GDB 进行分析：

  1.  gdb ./node core.24269
  2.  For help, type "help".
  3. Type "apropos word" to search for commands related to "word"...
  4. Reading symbols from ./node...done.
  5. warning: .dynamic section for "/lib64/ld-linux-x86-64.so.2" is not at the expected address (wrong library or version mismatch?)
  6. warning: Could not load shared library symbols for 7 libraries, e.g. /lib64/libdl.so.2.
  7. Use the "info sharedlibrary" command to see the complete listing.
  8. Do you need "set solib-search-path" or "set sysroot"?
  9. Core was generated by `node'.
  10. #0  0x00007f2e584a6483 in ?? ()
  11. [Current thread is 1 (LWP 24270)]
  12. (gdb) bt
  13. #0  0x00007f2e584a6483 in ?? ()
  14. #1  0x0000000000000000 in ?? ()

好家伙全是乱码，这里显然缺少运行时的动态链接库，将服务器上的动态链接库打包后手动指定根目录：

  1. (gdb) set sysroot /home/hyj1991/git/examples/0924/libs
  2. Reading symbols from /home/hyj1991/git/examples/0924/libs/lib64/libdl.so.2...(no debugging symbols found)...done.
  3. Reading symbols from /home/hyj1991/git/examples/0924/libs/lib64/libstdc++.so.6...(no debugging symbols found)...done.
  4. Reading symbols from /home/hyj1991/git/examples/0924/libs/lib64/libm.so.6...(no debugging symbols found)...done.
  5. Reading symbols from /home/hyj1991/git/examples/0924/libs/lib64/libgcc_s.so.1...(no debugging symbols found)...done.
  6. Reading symbols from /home/hyj1991/git/examples/0924/libs/lib64/libpthread.so.0...(no debugging symbols found)...done.
  7. warning: Unable to find libthread_db matching inferior's thread library, thread debugging will not be available.
  8. Reading symbols from /home/hyj1991/git/examples/0924/libs/lib64/libc.so.6...(no debugging symbols found)...done.
  9. Reading symbols from /home/hyj1991/git/examples/0924/libs/home/work/node/node_modules/xprofiler/build/binding/Release/node-v72-linux-x64/xprofiler.node...(no debugging symbols found)...done.

这样总算可以正常查看每一个线程的栈帧回溯：

  1. (gdb) thread apply all bt
  2. Thread 13 (LWP 24269):
  3. #0  0x00007f2e584a6483 in epoll_wait () from /home/hyj1991/git/examples/0924/libs/lib64/libc.so.6
  4. #1  0x00000000013480e0 in uv__io_poll (loop=loop@entry=0x2c9aac0 <default_loop_struct>, timeout=5526) at ../deps/uv/src/unix/linux-core.c:309
  5. #2  0x0000000001335ddf in uv_run (loop=0x2c9aac0 <default_loop_struct>, mode=UV_RUN_DEFAULT) at ../deps/uv/src/unix/core.c:381
  6. #3  0x0000000000a4b5f5 in node::NodeMainInstance::Run() ()
  7. #4  0x00000000009da5a8 in node::Start(int, char**) ()
  8. #5  0x00007f2e583ca3d5 in __libc_start_main () from /home/hyj1991/git/examples/0924/libs/lib64/libc.so.6
  9. #6  0x0000000000979215 in _start ()
  11. Thread 8 (LWP 24285):
  12. #0  0x00007f2e5846ce2d in nanosleep () from /home/hyj1991/git/examples/0924/libs/lib64/libc.so.6
  13. #1  0x00007f2e5846ccc4 in sleep () from /home/hyj1991/git/examples/0924/libs/lib64/libc.so.6
  14. #2  0x00007f2e559809c8 in xprofiler::CreateIpcServer(void (*)(char*)) () from /home/hyj1991/git/examples/0924/libs/home/work/node/node_modules/xprofiler/build/binding/Release/node-v72-linux-x64/xprofiler.node
  15. #3  0x00007f2e5877cdd5 in start_thread () from /home/hyj1991/git/examples/0924/libs/lib64/libpthread.so.0
  16. #4  0x00007f2e584a5ead in clone () from /home/hyj1991/git/examples/0924/libs/lib64/libc.so.6
  18. Thread 7 (LWP 24284):
  19. #0  0x00007f2e5846ce2d in nanosleep () from /home/hyj1991/git/examples/0924/libs/lib64/libc.so.6
  20. #1  0x00007f2e5846ccc4 in sleep () from /home/hyj1991/git/examples/0924/libs/lib64/libc.so.6
  21. #2  0x00007f2e559409b4 in xprofiler::CreateLogThread(void*) () from /home/hyj1991/git/examples/0924/libs/home/work/node/node_modules/xprofiler/build/binding/Release/node-v72-linux-x64/xprofiler.node
  22. #3  0x00007f2e5877cdd5 in start_thread () from /home/hyj1991/git/examples/0924/libs/lib64/libpthread.so.0
  23. #4  0x00007f2e584a5ead in clone () from /home/hyj1991/git/examples/0924/libs/lib64/libc.so.6

可以看到 xprofiler 插件创建的两个线程正常工作，JS 主线程则处于 epoll_wait 状态，没有任何可疑的会导致进程假死的阻塞！

到这里我是真的疑惑了，线程堆栈完全正常，CPU 和内存也正常，那么进程为什么会处于无响应的假死状态呢？

IV. 另一个思路

连万能的 Core 分析都找不到异常的地方，似乎这个问题已经没办法排查了。

无奈之下，我又回到一开始的问题：

  • 为什么处于子线程的 xprofiler 插件不再输出日志

回顾了一遍 xprofiler 插件中定时采集输出日志的逻辑：

  1. static void CreateLogThread(void *unused) {
  2.   uint64_t last_loop_time = uv_hrtime();
  3.   while (1) {
  4.     Sleep(1);
  6.     SetNowCpuUsage();
  8.     if (uv_hrtime() - last_loop_time >= GetLogInterval() * 10e8) {
  9.       last_loop_time = uv_hrtime();
  10.       bool log_format_alinode = GetFormatAsAlinode();
  12.       GetMemoryInfo();
  13.       GetLibuvHandles();
  15.       Sleep(1);
  17.       WriteCpuUsageInPeriod(log_format_alinode);
  18.       WriteMemoryInfoToLog(log_format_alinode);
  19.       WriteGcStatusToLog(log_format_alinode);
  20.       WriteLibuvHandleInfoToLog(log_format_alinode);
  21.       WriteHttpStatus(log_format_alinode, GetPatchHttpTimeout());
  22.     }
  23.   }
  24. }

可以确定只要日志线程依旧存活，一定会走到写日志的逻辑：

  1. #define WRITET_TO_FILE(type)                   \
  2.   uv_mutex_lock(&logger_mutex);                \
  3.   type##_stream.open(filepath, std::ios::app); \
  4.   type##_stream << log;                        \
  5.   type##_stream.close();                       \
  6.   uv_mutex_unlock(&logger_mutex);

这里用了一个宏来将日志写到文件，本质上就是一个 ofstream 的文件流，看到这里我有一个猜测是不是这个文件流打开失败了导致内核日志没有正常写入文件。

于是去翻 Linux Man 手册 open 方法 看看哪些情况下会调用失败：
image.png
其它的看起来都不太可能，唯独和文件打开数相关的限制看起来可疑：

The system limit on the total number of open files has been reached.

到这里感觉突然峰回路转，立马联系 Midqiu 查看重启后的进程的文件打开数：

  1. lsof -p <pid> | wc -l

并且将这个值与系统的 ulimit -n 限制进行对比：
image.png
果然，重启后的 Node.js 进程文件打开数随着访问量逐步上涨，逐渐逼近系统的限制，问题就是出在这个假死进程的文件打开数上！

V. 定位问题代码段

有了问题的方向接下来就方便很多，我们可以使用 lsof -p <pid> 查看具体是哪些句柄：
image.png
好家伙，8W+ 的 /home/work/node/logs/important/production.x-access.serverless_runtime.2020-09-24.log 这个文件的重复文件句柄！

经过沟通，这个文件是项目里面用来记录用户请求 access 日志对应的日志文件，那么猜测是记录 access 日志的中间件在重复的 fs.open 此文件。

拿到这个日志中间件的源代码，果然存在一个 Logger 类里有 fs.open 动作：

  1. private async ensureFile(filename: string): Promise < number > {
  2.   if(Object.keys(this.fds).length > 150) {
  3.     for (const [_, fd] of Object.entries(this.fds)) {
  4.       fs.close(fd);
  5.     }
  6.     this.fds = {};
  7.    }
  8.   if (!this.fds[filename]) {
  9.     this.fds[filename] = await new Promise<number>((resolve, reject) => {
  10.       fs.open(filename, "a", (err, fd) => {
  11.         if (err) {
  12.           reject(err);
  13.         } else {
  14.           resolve(fd);
  15.         }
  16.       });
  17.     });
  18.   }
  19.   return this.fds[filename];
  20. }

然后是记录日志的地方会调用这个方法获取日志文件的 fd：

  1. private async appendLine(filename: string, line: string): Promise < void> {
  2.   const fd = await this.ensureFile(filename);
  3.   await new Promise(((resolve, reject) => {
  4.     fs.write(fd, line + "\n", (err) => {
  5.       if (err) {
  6.         reject(err);
  7.       } else {
  8.         resolve();
  9.       }
  10.     });
  11.   }));
  12. }

这个 Logger 类到这里看起来也没问题，然而最后回到服务的入口文件时发现开发者竟然把 Logger 这个需要全局共享的实例初始化放到了 Express 中间件里：

  1. app.use(function(req, res, next) {
  2.   //...
  3.   const logger = new Logger();
  4.   res.locals.log = logger;
  5.   next();
  6. });

这就导致每来一个用户请求都会实例化一个 Logger 实例，此时记录本次请求的 access 日志就会打开一个重复的日志文件句柄，从而导致了进程文件句柄的泄露。

最后进程可使用的文件句柄数超过系统限制后进程就处于假死状态，表现为文件句柄数溢出后，后续此进程任何 I/O 相关的系统调用都会阻塞。

VI. 修复文件句柄泄露

定位到代码问题后，修复也非常简单，这里可以全局初始化 access 日志实例，请求日志共享此文件句柄即可。

另外简单点也可以直接修改 appendLine 方法为 fs.writeFile ：

  1. private async appendLine(filename: string, line: string): Promise < void> {
  2.   await new Promise(((resolve, reject) => {
  3.     fs.writeFile(filename, line + "\n", { flag: 'a' }, (err) => {
  4.       if (err) {
  5.         reject(err);
  6.       } else {
  7.         resolve();
  8.       }
  9.     });
  10.   }));
  11. }

这样牺牲了一部分性能但是不会有文件句柄泄露的问题。

VII. 小结

实际上 Node.js 提供的的 stream 、 net 以及 fs 里面的 fd 相关操作函数，这些模块或者函数相对 Node.js 其它封装的上层函数更接近底层库。

而历史经验告诉我们，这部分底层库相关的函数，如果自己没有完全理解千万不要随便想当然的用，大概率一写一个大坑等着你。

最后 Easy-Monitor 即将加入对监控进程自身的文件打开数的监控，帮助大家下次秒解决此类问题。