child_process.exec接口引起的服务异常排查记录

山下有风
1,195 阅读6分钟

问题描述

最近在用Beidou同构框架搭建一个SSR同构服务，本地开发时毫无问题，但部署到测试环境和线上环境后，服务会不定期进程会收到exit事件而异常退出，严重影响到服务的稳定性。

背景介绍

Beidou是由阿里开发的基于EggJS的同构框架，框架本身自带CLI工具拥有进程管理能力，启动方式为beidou start。但是公司内的发布平台对NodeJS的进程管理进行了规范：

  1. 目前只支持使用PM2进行进程管理
  2. 项目工程中必须拥有./src/index.js作为启动脚本

为了遵循规范，增加了./src/index.js并且通过child_process.exec接口执行beidou start来启动服务。核心代码如下:

const { exec } = require('child_process')
let command = 'npx beidou start --port=8080 --title=*** --env=test'
exec(command, (error, stdout, stderr) => {
    xxxx
});

排查过程

确认进程状况

推荐使用通过ps axjf指令进行查看，该指令可以将父子进程以树状的形式展示，非常直观，同构服务的状态

PM2 v5.1.0: God Daemon (/home/webedit/.pm2)
  \_ node /*/src/index.js
      \_ node /usr/local/bin/npx beidou start --port=8080 --title=* --env=test
          \_ node --no-deprecation /*/node_modules/egg-scripts/lib/start-cluster
              \_ /home/node/bin/node --no-deprecation /*/node_modules/egg-cluster/lib/agent_worker.js 
              \_ /home/node/bin/node --no-deprecation /*/node_modules/egg-cluster/lib/app_worker.js 
              \_ /home/node/bin/node --no-deprecation /*/node_modules/egg-cluster/lib/app_worker.js 
              \_ /home/node/bin/node --no-deprecation /*/node_modules/egg-cluster/lib/app_worker.js 
              \_ /home/node/bin/node --no-deprecation /*/node_modules/egg-cluster/lib/app_worker.js

这里隐藏了一些项目的信息，但足矣说明进程情况：

  1. pm2启动了子进程来执行./src/index.js
  2. ./src/index.js脚本中用子进程来执行beidou start
  3. Beidou start cli指令中用子进程来执行egg-scripts/lib/start-cluster脚本
  4. 而最后的5个进程分别是EggJS中的agent_worker进程和app_worker进程，app_worker进程数量由CPU数量决定，对这块陌生的同学可查看官方文档

排查app_worker进程退出的原因

真正提供服务的是app_worker进程。如果服务异常，那么可以断定app_worker进程都退出了。要搞清楚app_worker退出的原因，首先要先了解EggJS启动方式，egg-scripts/lib/start-cluster 的源码很简单：

const options = JSON.parse(process.argv[2]);
require(options.framework).startCluster(options);

其实就是以EggJS cluster模式启动服务，的核心代码都在egg-cluster package中。app_worker进程启动的关键代码在egg-cluster/lib/master.js中：

forkAppWorkers() {
    this.appStartTime = Date.now();
    this.isAllAppWorkerStarted = false;
    this.startSuccessCount = 0;
    const args = [ JSON.stringify(this.options) ];
    this.log('[master] start appWorker with args %j', args);
    cfork({
      exec: this.getAppWorkerFile(),
      args,
      silent: false,
      count: this.options.workers,
      // don't refork in local env
      refork: this.isProduction,
      windowsHide: process.platform === 'win32',
    });
    
    ...
  }

cfork的作用就是启动指定数量的子进程用来执行app_worker的代码。了解了启动方式后就很简单了，只要监听process的exit事件和终止信号就能知道进程何时因为何种原因退出了。 通过日志分析发现，是由于mater进程收到 SIGTERM 信号后杀掉了所有的app_worker进程。

5/18/2021, 7:08:11 PM [start-cmd] Kill child 21539 with undefined
5/18/2021, 7:08:11 PM[master] receive signal SIGTERM, closing
5/18/2021, 7:08:11 PM [master] app_worker#1:undefined exit
5/18/2021, 7:08:11 PM [master] app_worker#4:undefined exit
5/18/2021, 7:08:16 PM [master] app_worker#3:undefined exit
5/18/2021, 7:08:16 PM [master] app_worker#2:undefined exit

谁发了SIGTERM信号

但谁发了SIGTERM信号？什么原因发送了SIGTERM信号？系统？还是PM2？难道要看PM2的源码？这些问题困扰了我很久。还真去了解了PM2的原理并研读了部分代码，但不是本文的重点，不展开。 根据进程的树状信息，顺腾摸瓜，当服务异常时，PM2进程却正常，初步推断是PM2内部发送的终端信号，比如内存不足等。 但是通过运维平台，并没有发现机器有内存不足的情况。所以我在./src/index.js中监听了exit事件和终止信号，当服务退出时，确实没有收到终止信号，思路好像又断了。 无奈只能求助谷歌，文章中提到可以用Audit工具排查哪个进程杀了指定进程。

audit工具是Linux系统中负责审计的进程，可以用来记录Linux系统的一些操作，比如系统调用，文件修改，执行的程序，系统登入登出和记录所有系统中所有的事件，我们可以通过配置aidutd规则来对Linux服务器中发生的一些用户行为和用户操作进行监控。

9031cc7d-b3ba-4f16-9702-f642e7a499ef.png

在SA同学的协助下，最终查到是由于一个node进程杀掉了beidou进程。

2f1e02e4-2604-4efd-9744-b5cba02c88d9.png

对audit工具不熟悉的同学看到这些日志可能一脸懵逼，大概的意思就是：一个node程序的pid为29904，kill进程的信号由pid为11779的node进程中发出，而这里29904就是app_worker，而11779就是 ./src/index.js所在的进程，好像罪魁祸首是./src/index.js？index.js脚本中通篇没有发送信号相关的代码，最有可能就是child_process.exec接口。

发出SIGTERM信号的原因

通过分析NodeJS的child_process的源码可以发现，exec接口在启动子进程后会通过'data'事件监听子进程的输出，并且设置了输出的上限，一旦超过上限就kill调子进程，而默认的信号就是SIGTERM。上证据：

function exec(command, options, callback) {
  const opts = normalizeExecArgs(command, options, callback);
  return module.exports.execFile(opts.file,
                                 opts.options,
                                 opts.callback);
}

const MAX_BUFFER = 1024 * 1024;

function execFile(file /* , args, options, callback */) {
  ...
  options = {
    encoding: 'utf8',
    timeout: 0,
    maxBuffer: MAX_BUFFER,
    killSignal: 'SIGTERM',
    cwd: null,
    env: null,
    shell: false,
    ...options
  };
  ...

  const child = spawn(file, args, {
    cwd: options.cwd,
    env: options.env,
    gid: options.gid,
    shell: options.shell,
    signal: options.signal,
    uid: options.uid,
    windowsHide: !!options.windowsHide,
    windowsVerbatimArguments: !!options.windowsVerbatimArguments
  });
  
  ...

  function kill() {
    if (child.stdout)
      child.stdout.destroy();

    if (child.stderr)
      child.stderr.destroy();

    killed = true;
    try {
      child.kill(options.killSignal);
    } catch (e) {
      ex = e;
      exithandler();
    }
  }
  ...
  if (child.stdout) {
    if (encoding)
      child.stdout.setEncoding(encoding);

    child.stdout.on('data', function onChildStdout(chunk) {
      const encoding = child.stdout.readableEncoding;
      const length = encoding ?
        Buffer.byteLength(chunk, encoding) :
        chunk.length;
      const slice = encoding ? StringPrototypeSlice :
        (buf, ...args) => buf.slice(...args);
      stdoutLen += length;

      if (stdoutLen > options.maxBuffer) {
        const truncatedLen = options.maxBuffer - (stdoutLen - length);
        ArrayPrototypePush(_stdout, slice(chunk, 0, truncatedLen));

        ex = new ERR_CHILD_PROCESS_STDIO_MAXBUFFER('stdout');
        kill();
      } else {
        ArrayPrototypePush(_stdout, chunk);
      }
    });
  }

  return child;
}

而我们的服务一直在跑，日志一直在输出，所以服务退出是早晚的事儿。官方文档其实已经写得很清楚，只怪自己没仔细看文档。

Largest amount of data in bytes allowed on stdout or stderr. If exceeded, the child process is terminated and any output is truncated. See caveat at maxBuffer and Unicode. Default: 1024 * 1024.

20842fc3-1a08-49ca-a0a1-24b967192ca8.png

最后提一嘴，SIGTERM信号一般不会由系统发出，如果您遇到SIGTERM的情况，请先从自己应用着手排查。

解决方案

原因找到了，解决也就很简单了，使用不关心子进程stdout和stderr的接口即可，比如：child_process.spawn。

let childProcess = spawn(`npx beidou start --port=${PORT} --title=* --env=${EGG_SERVER_ENV}`, [], {
  shell: true,
  stdio: 'inherit'
})

复盘总结

整个排查过程虽然一波三折，但也有很多收获：

  1. 首先是对ps指令有了更多实践，特别是通过ps axjf可以以树状的形式查看进程关系
  2. 对Egg CLI工具的设计原理和内部流程有了初步认识
  3. 对EggJS和pm2的cluster模式有了完整的认识，至少可以自己写一个cluster模式了
  4. 通读child_process模块源码，对每个接口(exec/execFile/fork/spawn)内部逻辑有了清晰的认知
  5. 运维知识也得到了扩充，学会使用Audit工具对Linux服务器中发生的一些用户行为和用户操作进行监控

感谢您的观看！

avatar
文章
阅读
粉丝