Node.js应用日志切分原理及踩坑实践.js应用主要提供C端API服务。随着应用流量的逐渐增大，在线监控平台会不定期的报警，提示disk_io平均等待时间超过1000ms，然后观察到磁盘IO每秒写入的字节数突然飙升，但很快又回落.具体监控图如上所示。线上Node.js应用向磁盘写入数据的唯一场景就是打印日志。iotop、ps等命令也验证了异常是Node.js的日志切割过程导致的。但是为什么logcutting会导致这么奇怪的IO问题呢？在揭开谜底之前，先说说Node.js应用日志切割的原理。日志切割原理为什么需要日志切割日志打印是Node.js项目服务过程中必不可少的一个环节。日志文件包含系统运行过程中的关键信息，常用于故障诊断和系统性能分析。在打印日志的过程中，通常会遇到两个问题：随着时间的积累，日志文件的大小会逐渐变大，系统盘的空间消耗越来越大，会面临日志写入失败和服务异常的问题。服务日志默认保存在单个文件中，自定义查看历史某段时间的日志会比较困难。希望日志文件可以按照一定的规则进行切割，方便排序和过滤。因此，在生产环境中，通常会使用日志切割来解决上述问题。日志切割可以限制日志文件的数量，删除旧的日志文件，创建新的日志文件，起到“转储”的作用。不同实现机制的日志切割组件会采用不同的实现机制，常见的有以下两种：copytruncate方式：复制当前日志文件并重命名为新的日志文件，使进程仍然写入旧的日志文件。执行truncate清除旧的日志文件，从而完成一次日志切割。登录通知方式：先重命名当前进程正在输出的日志文件的名称。因为日志文件在磁盘上是通过inode标识的，所以修改日志文件的名称不会影响inode编号，进程仍然会向修改后名称的日志文件输出日志。创建一个与旧日志文件同名的新日志文件。因为是新文件，所以inode号不一样。此时进程日志仍然输出到旧的重命名的日志文件中。向进程发起信号通知重新加载日志配置文件，实现平滑重启，后续日志会写入新创建的日志文件。日志切割组件一般都支持可配置的日志切割频率，有两种方式：定时切割：进程启动一个定时任务，在设定的时间后切割日志文件。按大小裁剪：进程定时监控日志文件的大小，如果超过设置的最大值则裁剪文件。Node.js应用日志切割对于前端Node.js应用，可以根据项目框架和部署架构选择不同的日志切割方案。比如基于pm2部署的Node.js应用，可以使用pm2-logrotate来实现日志切割。基于Egg.js框架的Node.js应用可以使用egg-logrotator实现日志切割。下面详细介绍一下这两种日志切割方案的实现原理。pm2-logrotate实现机制pm2-logrotate是一个pm2扩展的日志管理插件，适用于pm2部署的Node.js应用，支持定时裁剪和按大小裁剪。一些配置参数可以通过以下命令设置：pm2setpm2-logrotate:关键配置项如下：max_size日志文件的最大容量，默认值为1010241024retain最大日志filecutoutNumber，默认值为30dateFormat日期格式，根据日期名称生成日志文件名切出，默认值为YYYY-MM-DD_HH-mm-ssworkerInterval按大小切出时，文件的间隔时间scanning(s)，默认值为30rotateInterval定时切割的时间间隔（支持cron表达式），默认值为00*对于pm2-logrotate本身的实现机制，我们摸索了源码，总结了一些关键步骤，如如图：裁剪机制的核心源码如下，从中可以看出pm2-logrotate采用了上面介绍的copytruncate方式。//日志切割的具体过程functionproceed(file){//设置时间为新的日志文件名varfinal_time=moment().format(DATE_FORMAT);varfinal_name=file.substr(0,file.length-4)+'__'+final_time+'.log';//创建读/写流并将日志写入新的日志文件varreadStream=fs.createReadStream(file);varwriteStream=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+'"hasbeencreated');if(typeof(RETAIN)==='number')delete_old(file);});});}IO异常问题分析返回本文开头的在线问题，因为我们的Node.js应用是基于pm2实现进程管理的，同时也是基于pm2-logrotate实现日志切割的。在排查异常的时候，我们发现pm2-logrotate的实现有两个问题。集群模式下重复切日志的问题通过追溯源码，我们可以确认pm2-logrotate会对所有pm2启动的应用程序进行切日志。pm2.list(function(err,apps){apps.forEach(function(app){proceed_app(app,false);});});但是在集群模式下，pm2会启动多个相同的woker实例，并且日志只会打印到同一个文件中。因此，当触发日志拆分条件时，多个woker实例会同时拆分日志文件，导致IO读写繁忙。同时，copytruncate方式在切割日志的时候会复制原来的日志文件，也会造成系统盘使用空间突然增大。这个问题在日志文件比较大的时候尤为明显，也是导致我们的Node.js应用在线IO异常的主要原因。为了解决集群模式下日志重复拆分的问题，需要对多个worker实例进行去重，只允许一个实例进行日志拆分。具体判断逻辑可以分为两步：判断实例是否为集群模式实例。pm2为每个应用实例提供了一个环境变量pm2_env，用于查看运行状态。app.pm2_env.instances>1表示有多个相同的实例，可以判断为集群模式。判断一个实例是否被切日志。多个工作实例的共同点是app.name与应用程序名称相同。所以每次切日志都会新建一个map映射表，key为app.name。只有在映射表中没有查询到app.name时，才会进行日志切分。代码部分大致如下：pm2.list(function(err,apps){...varappMap={};apps.forEach(function(app){//集群模式去重判断if(app.pm2_env.instances>1&&appMap[app.name])return;appMap[app.name]=app;//开始日志切割proceed_app(app,false);});以上去重判断逻辑已经作为PR提交并合并。此问题已在pm2-logrotatev2.7.0中修复。日志丢失问题pm2-logrotate在进行日志切割时，根据dateFormat参数格式化生成新的日志文件名。源码如下：varDATE_FORMAT=conf.dateFormat||'YYYY-MM-DD_HH-mm-ss';varfinal_time=moment().format(DATE_FORMAT);varfinal_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对应的文件不存在则创建，如果存在则覆盖整体内容varwriteStream=fs.createWriteStream(final_name,{'flags':'w+'});解决这个问题，一方面可以将dateFormatAccurate设置为秒级来规避；另一方面，需要评估日志文件的大小，合理设置max_size参数，避免频繁触发日志切割。egg-logrotator实现机制egg-logrotator是Egg.js框架扩展的日志切割插件。与pm2-logrotate相比，其配置更加灵活，支持按天、按小时、按大小切分。关键配置项如下：filesRotateByHour需要按小时切分的文件列表，默认值为[]hourDelimiter按小时切分的文件，小时部分的分隔符，默认值为'-'filesRotateBySize需要按大小裁切的文件列表，默认值为[]maxFileSize日志文件的最大体积，默认值为5010241024maxFiles按大小裁切，文件裁切的最大份数，默认值为10rotateDuration当按照大小裁剪时，文件扫描的间隔时间，默认值为60000maxDays日志最大保留天数，默认值为31。具体裁剪的实现原理如图图：核心源码如下。与pm2-logrotate相比，我们可以看出egg-logrotator采用了另一种标志通知方式。//旋转日志切割源代码asyncrotate(){//获取需要切割的日志文件列表constfiles=awaitthis.getRotateFiles();常量旋转文件=[];for(constfileoffiles.values()){try{//重命名日志文件awaitrenameOrDelete(file.srcPath,file.targetPath);rotatedFile.push(`${file.srcPath}->${file.targetPath}`);}catch(err){}}if(rotatedFile.length){//重新加载重新加载日志文件this.logger.info('[egg-logrotator]broadcastlog-reload');this.app.messenger.sendToApp('log-reload');这个.app。messenger.sendToAgent('log-reload');}}}//重新加载重新加载日志文件reload(){this._closeStream();//结束当前日志文件流this._stream=this._createStream();//新建一个写入日志文件流}优点在实现上，copytruncate方式比较简单，而sign通知方式比较复杂，需要完善的通知重启机制。但是与基于copytruncate模式的pm2-logrotate相比，基于signnotification模式的egg-logrotator有两个明显的优势：copytruncate模式在日志切割过程中需要复制原始日志文件。如果日志文件太大，系统可用空间会突然爆炸。标志通知模式不需要复制原始日志文件。对于按大小切割的场景，egg-logrotator充分考虑了切割日志文件的命名。新日志文件将命名为${final_name}.1。当已经有切割文件时，原文件会加1，比如文件名后缀加1（.log.1->.log.2），直到日志文件数达到最大值maxFiles，最后一个会直接覆盖copys.log.${maxFiles}。这种实现可以最大程度保证日志的完整性。总结日志切割是提高Node.js服务可观察性的重要前提，也是实现日志可视化检索、日志监控告警、全链路日志分析的前提之一。本文阐述了日志切割的一般原理，扩展解释了Node.js应用中两种常用的日志切割方案及其背后的实现机制，并比较了两种实现方案的优缺点。希望能给大家在Node.js的生产实践中带来启发和帮助。参考资料pm2-logrotateegg-logrotatorlogrotate机制及原理本文由网易云音乐前端团队发布，文章未经授权禁止任何形式转载。我们一直在招聘，如果你恰好准备跳槽，又恰好喜欢云音乐，那就加入我们吧！
