Node.js 应用日志切割原理与踩坑实践

时间 2020-05-10

标签 node.js node 应用日志切割原理实践栏目 Node.js 繁體版

原文原文链接

图片来源：medium.com/encored-tec…javascript

本文做者：夏银竹前端

引子

2019 年初的时候，咱们业务组上线了一个新的 Node.js 应用，主要提供C端的 API 服务。随着应用流量的逐渐增长，线上监控平台会偶发性报警，提示磁盘 disk_io 平均等待时间超出 1000ms，随后观察发现磁盘 IO 每秒写字节量忽然飙高，但很快又降低。java

具体的监控图表如上所示，线上 Node.js 应用向磁盘写入数据的惟一场景就是打印日志，经过iotop、ps 等命令也验证了该异常正是因为 Node.js 的日志切割进程致使的。node

但是为何日志切割会引发这么诡异的 IO 问题呢？在揭开谜底以前，咱们先聊一聊 Node.js 应用日志切割的原理。git

日志切割原理

为何须要日志切割

日志打印是 Node.js 工程服务化过程当中一个必不可少的环节。日志文件中包含了系统运行过程当中的关键信息，经常使用于故障诊断和系统的性能分析。github

在日志打印的过程当中一般会遇到两个问题：架构

随着时间的积累，日志文件大小会逐渐增加，系统磁盘的空间会被消耗得愈来愈多，将面临着日志写入失败、服务异常的问题。
服务的日志默认存储在单个文件中，自定义查看历史某个时间段的日志将会变得比较困难，指望日志文件可以按照必定的规则切割，以便于排序和筛选。

因此，在生产环境中一般会采用日志切割来解决上述的问题。日志切割能够限制日志文件个数，删除旧的日志文件，并建立新的日志文件，起到“转储做用”。app

实现机制

不一样的日志切割组件会采用不一样的实现机制，常见的有如下两种：框架

copytruncate 模式：async
1. copy 当前日志文件，重命名为新的日志文件，这样进程仍是往老的日志文件写入。
2. 对老的日志文件进行 truncate 清空，这样就完成了一第二天志切割。
sign 通知模式：
1. 首先重命名当前进程正在输出的日志文件名称。由于日志文件是用 inode 来在磁盘上标识，更改日志文件名称并不会影响 inode 号，进程依旧会往修改了名称的日志文件内输出日志。
2. 建立新的日志文件，文件名称和老的日志文件名称保持一致。由于是新建的文件，inode 号不同。此时进程日志仍是依旧输出到老的被重命名了的日志文件里面。
3. 对进程发起信号通知，让其重载日志的配置文件，实现平滑重启，后续的日志就会写入到新建的日志文件里。

日志切割组件通常都支持可配置日志切割频率，也有两种方式：

定时切割：进程启动一个定时任务，到设定时间后切割日志文件。
按大小切割：进程定时监控日志文件的大小，若文件超出设定的最大值时进行切割。

Node.js 应用日志切割

对于前端 Node.js 应用来讲，根据项目的框架和部署架构，可选择不一样的日志切割方案，例如：

基于 pm2 部署的 Node.js 应用，可采用 pm2-logrotate 实现日志切割。
基于 Egg.js 框架的 Node.js 应用，可采用 egg-logrotator 实现日志切割。

下面咱们详细介绍一下这两种日志切割方案的实现原理。

pm2-logrotate

实现机制

pm2-logrotate 是 pm2 扩展的日志管理插件，适用于 pm2 部署的 Node.js 应用，同时支持定时切割和按大小切割。

可经过以下的命令来设置一些配置参数：

pm2 set pm2-logrotate:<param> <value>
复制代码

其中的关键配置项以下：

max_size

日志文件的最大致积，默认值为 10 * 1024 * 1024
retain

切割出的日志文件最大份数，默认值为 30
dateFormat

日期格式，基于该日期名生成切割出的日志文件名称，默认值为 YYYY-MM-DD_HH-mm-ss
workerInterval

按大小切割时，文件扫描的间隔时间（s），默认值为 30
rotateInterval

定时切割的时间间隔（支持cron表达式），默认值为 0 0 * * *

对于pm2-logrotate 自己的实现机制，咱们探究源码总结出了一些关键的步骤，具体如图所示：

其中切割机制的核心源码以下，从这里咱们能够看出 pm2-logrotate 采用了上文介绍的 copytruncate 模式。

// 日志切割的具体过程
function proceed(file) {
  // 设置时间做为新的日志文件名
  var final_time = moment().format(DATE_FORMAT);
  var final_name = file.substr(0, file.length - 4) + '__' + final_time + '.log';

  // 建立 read/write streams，将日志写入到新的日志文件中
  var readStream = fs.createReadStream(file);
  var writeStream = fs.createWriteStream(final_name, {'flags': 'w+'}); 
    
  readStream.pipe(writeStream);
  
  // 日志写入完毕后， 清空应用的日志文件
  writeStream.on('finish', function() {
    readStream.close();
    writeStream.close();
    fs.truncate(file, function (err) {
      console.log('"' + final_name + '" has been created');
      if (typeof(RETAIN) === 'number') 
        delete_old(file);
    });
  });
}
复制代码

IO 异常问题分析

从新回到本文开头的线上问题，因为咱们的 Node.js 应用是基于 pm2 实现进程管理，一样也是基于 pm2-logrotate 来实现日志切割。

在排查异常的时候，咱们发现了 pm2-logrotate 在实现上的两个问题。

cluster 模式下重复切割日志的问题

经过追溯源码，咱们能够肯定 pm2-logrotate 会对全部由 pm2 启动的应用进行日志切割。

pm2.list(function(err, apps) {
  apps.forEach(function(app) {
    proceed_app(app, false);
  });
});
复制代码

可是，在 cluster 模式下，pm2 会启动多个相同的 woker 实例，而日志只会打印到同一份文件中。所以，当触发日志切割的条件时，多个 woker 实例会同时对日志文件进行切割，形成 IO 读写繁忙。

同时， copytruncate 模式在日志切割的时候会拷贝原来的日志文件，也会形成系统磁盘使用空间突增。

这个问题在日志文件体积大的时候尤其明显，也是咱们 Node.js 应用线上 IO 异常的主因。

为了解决 cluster 模式下重复切割日志的问题，须要对多个 worker 实例进行去重判断，只容许一个实例进行日志切割的操做。具体的判断逻辑可分红两步：

判断该实例是否为 cluster 模式下的实例。pm2 给每一个应用实例提供了环境变量 pm2_env 来查看运行的状态。 app.pm2_env.instances > 1 则代表有多个相同的实例，可断定为 cluster 模式。
判断是否有实例已经作了日志切割。多个 worker 实例的共同点是 app.name 应用名相同。所以，每第二天志切割的时候新建一个 map 映射表，key 为 app.name ，只有当映射表中没有查询到 app.name 的时候，才会进行日志切割。

代码部分大体以下所示：

pm2.list(function(err, apps) {
  ...
  var appMap = {};
  apps.forEach(function(app) {
    // cluster模式下的去重判断
    if(app.pm2_env.instances > 1 && appMap[app.name]) return;
    appMap[app.name] = app;
    
		// 开始日志切割
    proceed_app(app, false);
});
复制代码

以上去重判断的逻辑已经提交 PR 并被 merged 。该问题已在 pm2-logrotate v2.7.0 的版本修复。

日志丢失问题

pm2-logrotate 进行日志切割时，新的日志文件名是根据 dateFormat 参数格式化生成的，源码以下所示：

var DATE_FORMAT = conf.dateFormat || 'YYYY-MM-DD_HH-mm-ss';
var final_time = moment().format(DATE_FORMAT);
var final_name = file.substr(0, file.length - 4) + '__' + final_time + '.log';
复制代码

该参数的默认值 YYYY-MM-DD_HH-mm-ss，能够精确到秒级别。在实际生产环境，为了便于检索和查看日志，文件的命名每每会按照按天/小时的维度进行命名。

可是若是 DATE_FORMAT 的格式为 YYYY-MM-DD ，会存在这么一个坑：当一天中应用日志体积屡次超出设置的 max_size 后，会出现屡次切割的操做，可是每次切割生成的新日志文件名倒是相同的。

在已有切割日志的状况下， pm2-logrotate 再次切割时不会判断新的日志文件是否已经存在，而是直接用新切割出来的日志覆盖了以前的日志，从而会致使日志丢失。

// 若是final_name对应的文件不存在则建立，存在则总体内容覆盖
var writeStream = fs.createWriteStream(final_name, {'flags': 'w+'});  
复制代码

针对该问题的解决方案，一方面能够经过设置 dateFormat 精确到秒级来避免；另外一方面，须要评估日志文件的大小，合理设置 max_size 参数，避免频繁触发日志切割。

egg-logrotator

实现机制

egg-logrotator 是 Egg.js 框架扩展的日志切割插件。相较于 pm2-logrotate ，其配置更加灵活，同时支持按天切割、按小时切割和按大小切割。关键配置项以下：

filesRotateByHour

须要按小时切割的文件列表，默认值为 [ ]
hourDelimiter

按小时切割的文件，小时部分的分隔符号，默认值为 '-'
filesRotateBySize

须要按大小切割的文件列表，默认值为 [ ]
maxFileSize

日志文件的最大致积，默认值为 50 * 1024 * 1024
maxFiles

按大小切割时，文件最大切割的份数，默认值为 10
rotateDuration

按大小切割时，文件扫描的间隔时间，默认值为 60000
maxDays

日志保留的最久天数，默认值为 31

具体切割的实现原理如图所示：

其中的核心源码以下，相较于 pm2-logrotate ，从这里咱们能够看出 egg-logrotator 则采用了另一种 sign 通知模式。

// rotate 日志切割源码
async rotate() {
  	// 获取须要切割的日志文件列表
    const files = await this.getRotateFiles();
    const rotatedFile = [];
    for (const file of files.values()) {
      try {
        // 重命名日志文件
        await renameOrDelete(file.srcPath, file.targetPath);
        rotatedFile.push(`${file.srcPath} -> ${file.targetPath}`);
      } catch (err) {
      }
    }

    if (rotatedFile.length) {
      // reload 从新加载日志文件
      this.logger.info('[egg-logrotator] broadcast log-reload');
      this.app.messenger.sendToApp('log-reload');
      this.app.messenger.sendToAgent('log-reload');
    }
  }
}

// reload从新加载日志文件
reload() {
  this._closeStream();   // 结束当前日志文件流
  this._stream = this._createStream(); // 建立一个新的写日志文件流
}
复制代码

优点

就实现方式而言，copytruncate 模式较简单，sign 通知模式则较为复杂，须要有一套完整的通知重启机制。

可是相较于基于 copytruncate 模式实现的pm2-logrotate，基于 sign 通知模式实现的 egg-logrotator 具备两点明显的优点：

copytruncate 模式在日志切割的过程当中须要拷贝原来的日志文件，若是日志文件过大，系统可用空间会忽然爆增。sign 通知模式则无需拷贝原来的日志文件。
对于按大小切割的场景， egg-logrotator 充分考虑了切割出的日志文件命名问题。新的日志文件会被命名为 ${final_name}.1。当已有切割文件时，会将原文件自增1，如文件名后缀加1（ .log.1 -> .log.2 ），直到日志文件数量达到 maxFiles 最大值后，才会直接覆盖最后一份 .log.${maxFiles}。这种实现方式可以最大程度上保证日志的完整性。

小结

日志切割是完善 Node.js 服务可观测性的重要前提，是实现日志可视化检索、日志监控告警和全链路日志分析的前置条件之一。

本文对通用的日志切割原理进行了阐述，展开说明了 Node.js 应用中两种经常使用的日志切割方案及其背后的实现机制，并对两种实现方案进行了优劣对比。但愿给你们在 Node.js 的生产实践中带来启示和帮助。

参考资料

本文发布自网易云音乐前端团队，文章未经受权禁止任何形式的转载。咱们一直在招人，若是你刚好准备换工做，又刚好喜欢云音乐，那就加入咱们！