您现在的位置是:首页 > 文章详情

记nodejs在pm2下使用log4js cluster模式的日志打印丢失问题

日期:2018-11-23点击:681

我使用pm2的cluster集群模式管理node服务,使用log4js打印日志。最近公司业务量上升,与此同时问题订单也随之增多。但多次在排查异常订单时找不到订单的正常日志,在基本排除程序本身问题后我将目光投在了日志打印插件log4js身上。

1:这是我目前的log4js的配置

log4js.configure({ appenders: { out: { type: 'stdout' }, info: { type: 'dateFile', filename: 'info', pattern: '-yyyy-MM-dd.log', layout: { type: 'pattern', pattern: '%d{yyyy-MM-ddThh:mm:ss.SSSO} %p %c - [%m]' } }, }, categories: { default: { appenders: ['out','info'], level: 'all' }, }, pm2: true, disableClustering: true });

我在网上也找到了很多博客,看到很多人都是这么写的。这么写可以解决cluster集群模式下只有一个进程输出的问题。但是在翻了log4js的源码之后我发现,如果设置了disableClustering为true之后,每个cluster进程都会单独向文件输出日志。

log4js.configure()配置的源码如下:

当你设置了disableClustering为true时log4js会做如上处理。然后当你getLogger时:

 

执行getLogger()函数时,会执行isMaster()方法,判断当前进程是不是主进程。isMaster函数执行时,如果disableClustering为true的话则认为当前进程是主进程。则会将sendLogEventToAppender作为打印日志时的执行函数。真正将日志打印到文件中。这个函数的具体执行大家可以自己去看下源码。里面逻辑很简单,就不再赘述。

这样就会发生多个进程同时向一个文件写入的情况,在某种情况下就会出现日志丢失情况。 我司遇到的问题就是在这种情况下发生的。而且官方文档也有提到这种模式会发生一些莫名其妙的问题(说的应该就是日志丢失吧)。log4js官方文档

好。到了这里,我们的node程序在pm2的cluster模式在使用log4js丢日志的原因基本是确定了。就是disableClustering的锅。那我们就要去解决它,怎么解决?

1:将disableClustering去掉。在配置中将disableClustering去掉之后,运行4个进程后发现,只有一个进程能正常打印日志,其它三个进程日志全部丢失。继续看官方文档发现下面一段话。

在log4js的配置中设置pm2为true时需要下载pm2-intercom参加才能保持日志的正常打印。ok,下载pm2-intercom。使用ab发起10个并发请求,打印结果如下。

ok。看起来一起完美。你以为结束了?当然不可能。

按照当前设置将服务发到测试环境,一跑,同样的代码,同样的设置,同样发起10个请求,只有3个打印出来了。试了好几次都是这样。so,还是在丢日志。

为什么呢?不可能啊!是不是电脑有问题?是不是pm2版本问题?是不是Node版本问题?是不是Log4js版本问题?在各种尝试了n次,将所有环境全部统一之后我发现,还是这样。so,老老实实看源码吧。

前面的一堆就不再说了,直接到关键代码。log4js下打印日志会有可能有两条路径。如下:

pm2下使用cluster模式时,其实所有的进程都是cluster,只有pm2主进程是master进程。但是pm2内部对进程做了标志。例如,启动4个cluster进程,则会有一个标志字段(默认是NODE_APP_INSTANCE)记录它的内部标志, 0、1、2、3。当标志位为0时,log4js就认为它是主进程(通过isPM2Master函数)。则此时master进程负责执行sendLogEventToAppender函数打印日志,cluster进程负责执行workerDispatch将日志发送给主进程(其实这时发送给的是pm2主进程)。

到了这里我们可以看到的结果就是,如果是cluster进程,则日志会发送给master进程,现在让我们来看pm2-intercom插件。我先是在github上找了一下它的源码发现没找到,后来问了log4js的官方人员后得到的结果是源码丢了!源码丢了!丢了! 原因不知道,结果就是找不到了。。issues地址

后来找到了一份貌似是第三方的pm2-intercom源码。pm2-intercom源码 找到源码看了一下。发现pm2-intercom会通过pm2的api连接到pm2,并接收到所有的消息:

上面是pm2官方的文档pm2文档 。pm2-intercom接收消息代码如下:

通过打印日志发现,所有cluster进程发送的消息都会被pm2-intercom接收。然后通过pm2-intercom转发出去。如下:

然后我发现在执行async.forEachLimit函数往别的进程广播时因为设置了4,所有最后执行下来。只会想pm2 list列表中的前4个进程推送消息,所有往后的进程都接收不到。 此时! 终于找到了为什么我在本地调试时为什么能接收到消息,而到了测试环境就不行。因为测试环境跑了很多服务。我的程序远在4之外。

此时,问题的原因已经找到了。通过在async.forEachLimit函数里面加上next()函数执行,发现果然所有的进程都能接收到消息。测试环境也已经可以接收到消息。

但是,这种方式有几个弊端:

1:所有的进程都能接收到消息,所有的主进程都会打印日志,所有可能你的日志会在不同的程序之间串。

2:往所有的进程发送日志,很没有效率。

所以最好可以根据自己的需求往特定的进程发送消息。

如你有一个进程专门记录日志,则可以都往那一个上面发。或者每个程序的master进程记录日志,则可以使用packet中的name来进行区分做分发。具体的实现可以自行定义。

至此,多进程打印日志的问题算是找到了。我也将修改代码发布到线上观察后续的结果。希望能解决问题。哈哈。

谨以此篇记录我踩的这些坑,如有错漏欢迎指教。

原文链接:https://my.oschina.net/xuyang950520/blog/2934086
关注公众号

低调大师中文资讯倾力打造互联网数据资讯、行业资源、电子商务、移动互联网、网络营销平台。

持续更新报道IT业界、互联网、市场资讯、驱动更新,是最及时权威的产业资讯及硬件资讯报道平台。

转载内容版权归作者及来源网站所有,本站原创内容转载请注明来源。

文章评论

共有0条评论来说两句吧...

文章二维码

扫描即可查看该文章

点击排行

推荐阅读

最新文章