云音乐大前端专栏

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

2020-05-09

header.png

图片来源:https://medium.com/encored-technologies-engineering-data-science

本文作者:夏银竹

引子

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

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

可是为什么日志切割会引起这么诡异的 IO 问题呢?在揭开谜底之前,我们先聊一聊 Node.js 应用日志切割的原理。

日志切割原理

为什么需要日志切割

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

在日志打印的过程中通常会遇到两个问题:

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

所以,在生产环境中通常会采用日志切割来解决上述的问题。日志切割可以限制日志文件个数, 删除旧的日志文件,并创建新的日志文件,起到“转储作用”。

实现机制

不同的日志切割组件会采用不同的实现机制,常见的有以下两种:

  • copytruncate 模式

    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

其中切割机制的核心源码如下,从这里我们可以看出 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 给每个应用实例提供了环境变量 pm2env 来查看运行的状态。 `app.pm2env.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 的生产实践中带来启示和帮助。

参考资料

本文发布自 网易云音乐前端团队,文章未经授权禁止任何形式的转载。我们一直在招人,如果你恰好准备换工作,又恰好喜欢云音乐,那就 加入我们