前段时间使用 Node 写了一些小工具脚本,其中包含了一些命令执行,结果发现,在运行较长的任务时,经常会发生自杀而找不到原因。
由于整个脚本运行在一个 async IIFE 下,一开始的报错是 UnhandledPromiseRejection: null。
于是按照一般思路在 process 上监听一下未处理的 promise rejection。发现得到的错误是个 null,这就,很迷。
回滚了几个版本,发现问题依旧,找不到问题引入的时间。
而且这个错误是随机触发的,有时候会在 Step 1 触发,有时候到了 Step 3 才会触发。
审视了一下代码里所有的 reject,最终将目光锁定在了
const exec = require('child_process').exec;
const execCommand = (command) => {
return new Promise((resolve, reject) => {
const child = exec(command);
child.stdout.on('data', (data) => {
console.log(data);
});
child.stderr.on('data', (data) => {
console.log(data);
});
child.on('close', (code, signal) => {
if (code === 0) {
resolve();
} else {
reject(code)
}
});
})
}
当子进程结束的时候,观察 return code,不为 0 则说明发生了错误。
打印了一下发现这个 code 居然是 null。于是查了下文档,发现,code 和 signal 互斥,只能有一个不为空。
于是再打印一下 signal,发现是 SIGTERM。
于是我们的问题转换为,为什么我们叉出去的子进程会被 SIGTERM 杀掉,还是随机发生的。
于是我升级了一下 Node 然后发现没有用
脚本中的一个模块使用了大量异步操作来进行并发下载,我一度以为是这个模块的问题,调试了半天也改了许多代码,结果测试发现这个模块自己运行的时候并不会出现随机自杀的问题。
那问题到底是什么呢——
其实是因为 child process 有一个默认的 maxBuffer,当 child process 打印出的日志超过 maxBuffer 的时候,会收到 SIGTERM 。
为什么随机出现呢:因为每次打印出的日志量不一样,有网络错误的时候打印出的日志会更多,也就出现的越早。而且因为几个模块都是作为同一个子进程运行的,各自打印的日志会互相累积,导致了这个错误不一定会在哪个模块运行的时候被触发。
作为临时解决方案,提高了 maxBuffer 的值,问题解决。
References:
https://stackoverflow.com/questions/43401872/node-js-child-process-exits-with-sigterm
https://stackoverflow.com/questions/39159312/child-process-exits-with-code-null