[eggjs/egg]egg-logger写日志文件失败导致服务器CPU打满100%

故障表现：服务器CPU占用100%，导致无法处理任何请求，进程假死。

错误日志文件：大量的写日志失败和reloaded错误日志：

查看每分钟重启次数，在3万次左右（基本确定是这个原因导致CPU打满）：

写一个测试js文件写入相同日志文件，写入成功，排除文件占用和权限问题：

const fs = require('fs');

const filename = '/root/logs/page-builder-client/page-builder-client-kafka.log';
const stream = fs.createWriteStream(filename, { flags: 'a' });
stream._onError = (err) => {
  console.error('%s ERROR %s [egg-logger] [%s] %s',
    Date(), process.pid, this.options.file, err.stack);
  this.reload();
  console.warn('%s WARN %s [egg-logger] [%s] reloaded', Date(), process.pid, this.options.file);
};
stream.write('this is a test input.', 'utf-8');

问题：这个是什么原因导致的写入失败，reload的重试没有次数限制吗，导致耗尽CPU资源，怎么处理这种问题。相关issue问题：https://github.com/eggjs/egg/issues/4533

附上定位问题查到的相关源代码：

/**
   * reload file stream
   */
  reload() {
    this._closeStream();
    this._stream = this._createStream();
  }

/**
   * create stream
   * @return {Stream} return writeStream
   * @private
   */
  _createStream() {
    mkdirp.sync(path.dirname(this.options.file));
    const stream = fs.createWriteStream(this.options.file, { flags: 'a' });

    const onError = err => {
      console.error('%s ERROR %s [egg-logger] [%s] %s',
        utility.logDate(','), process.pid, this.options.file, err.stack);
      this.reload();
      console.warn('%s WARN %s [egg-logger] [%s] reloaded', utility.logDate(','), process.pid, this.options.file);
    };
    // only listen error once because stream will reload after error
    stream.once('error', onError);
    stream._onError = onError;
    return stream;
  }

  /**
   * close stream
   * @private
   */
  _closeStream() {
    if (this._stream) {
      this._stream.end();
      this._stream.removeListener('error', this._stream._onError);
      this._stream = null;
    }
  }

LeonSage

我猜测是你的应用本身有问题，打开了大量 fd，导致 egg logger 的 reload suck 住了，解决应用自身打开大量 fd 的问题就可以规避掉这个错误了。

hyj1991

对问题进程调用下 lsof -p <pid> | wc -l 可以看到究竟是哪些重复的 fd 被你的应用打开了

hyj1991

确实是触发到了文件打开数的上限：上限是1048576：一个刚启动10分钟的实例打开的文件数是683个，20小时的实例打开了65000个，运行了26个小时的实例数是1048592。超过了上限，所以该进程无法写入文件了。

打开的文件都是该日志文件，所以为什么node进程会打开该文件104万次，是不是_closeStream()没有执行成功？

LeonSage

这显然是你的 nodejs kafka client 出了问题，你就算修改了 egg 这边的日志 reload 逻辑，你的应用还是假死，fd 打满后进程就无响应了，所以你要解决这个 kafka client fd 重复打开的问题

hyj1991

这个client-kafka只是一个命名而已，其实就是普通的egg的info日志文件。这里查到的是node打开了之后没有释放fd，275进程是egg的服务进程，所以是不是还是node的写日志后没有释放。

LeonSage

这样的看的话确实，你有办法能在本地复现这个问题么，能复现就有思路排查下，我猜测是底层的某个系统异常触发了 egg logger 的什么 bug，看起来可能比较隐蔽

hyj1991

该bug是能够稳定复现的，重启新容器实例后，查看node进程的文件打开文件数，随着时间在稳定增长，直到达到连接数上线，然后每秒3万次重试relaod写入日志导致CPU打满后服务假死。

LeonSage

我的意思是提取一份最小逻辑能在本地复现，只在你的容器里复现那只能你自己对比源代码里面的内容定位了，如果能有最小逻辑可以共享本地复现的话，其他人也可以帮你一起定位

hyj1991

因为单单就你这边给出来的信息太少了

hyj1991

从代码层面分析写日志的代码逻辑，定位为该段代码重复执行导致问题，每个请求服务时都会创建一个Logger子线程，并持有文件：

// lib/plugin/egg-oversea-logger/lib/customLogger.js

module.exports = function (ctx) {
  const logger = new Logger();
  const { file } = ctx.app.config.ologger;

  utils.meta = getMetaFromCtx(ctx);

  logger.set('file', new FileTransport({
    level: 'INFO',
    file,
  }), ctx);

  logger.set('console', new ConsoleTransport({
    level: 'INFO',
  }), ctx);
  return logger;
};

将相关逻辑从exports中挪入到初始化逻辑中即可修复该问题：

const logger = new Logger();
logger.set('file', new FileTransport({
  level: 'INFO',
  file,
}));
logger.set('console', new ConsoleTransport({
  level: 'INFO',
}));

module.exports = function (ctx) {
  utils.meta = getMetaFromCtx(ctx);
  return logger;
};

LeonSage

感谢大佬提供解决问题的思路 @hyj1991

LeonSage

解决了就行，其实这是个 logger 重复使用的常见 case，之前我也帮别人定位过一个类似的：文件句柄泄露导致进程假死，一般来说句柄打满都是异常的业务逻辑上造成的 :)

顺便打个广告，Node.js 应用监控工具可以试试看 Easy-Monitor 3.0，帮助快速定位解决各种疑难杂症 :)

hyj1991

[eggjs/egg]egg-logger写日志文件失败导致服务器CPU打满100%

回答