我们採用Linux的syslog来记录产品的debug log。
调用当中的一个可运行文件。运行完命令之后,查看debug log的信息,竟然从某一条log之后的log都丢失了。多次尝试后,发现每次都在某条固定的log之后的log都丢失了。
这篇博文就让我们一起来探个到底。
一. 问题发现
在发现真正问题之前我做了下面尝试:
(1) 进程是否在固定log之后某种逻辑退出?或者在固定log打印之后的语句中会产生信号导致进程终止? 在程序末尾打印一个消息到屏幕,能够看到程序正常执行,并退出。
(2) 是否debug log对象发生了改变。或者debug level在执行中发生了改变? 相同在程序中打印这些信息,发现并无异常。
(3) gdb调试查看程序走的分支逻辑
如上方法均未发现问题,事实上另一种想法:syslog会不会丢弃一些log信息?但一開始是被我排除的,当时原因有二:第一在Redhat4/5上均不会出现这个问题;第二Redhat 6平台上的产品已经公布了至少一年了,要是debug log总是缺少应该不会等到我来发现吧。然而。正是因为一些惯有的思维。或者是一些看似有理却不严谨的判断。导致真相姗姗来迟。
接着。我优先查看了/var/log/messages文件, 看到了例如以下的错误信息。而6292正是我之前运行的进程ID。
imuxsock begins to drop messages from pid 6292 due to rate-limiting
那么非常显然。于是非常快利用google神器,找到了原因。这个是和Redhat 6中的rsyslog的机制有关系。而且这些机制可配置。
二. Redhat 6.3中rsyslog的Rate Limit配置
所谓Rate limit就是指,在某个固定的时间段内,syslog最多同意打印的log信息数量(多出的log信息将被丢弃)。在Redhat 6中。由配置文件/etc/rsyslog.conf中下面两个配置项决定:
$SystemLogRateLimitInterval [Number1]: Number1 为设定的限制的时间间隔大小
$SystemLogRateLimitBurst [Number2]: Number2 为在设定的限制的时间间隔内,最多输出的log信息数量。
在设定完后,则表示在每个Number1时间间隔内,假设超过Number2个数的log信息将会被去除。
默认Number1为5秒钟,Number2为200.但假设我们不希望。在打印的log时有丢失,则能够在/etc/rsyslog.conf中加入或者设置:
$SystemLogRateLimitInterval 0
当然设置完毕后,一定要记得又一次启动rsyslog服务(用命令:service rsyslog restart)哦~~~
Note:rsyslog 5.7.1之后的版本号才加入了此功能,而Redhat 6.3採用的是rsyslog 5.8.10 。
參考:
1. https://bugzilla.redhat.com/show_bug.cgi?format=multiple&id=753363
2. http://lists.adiscon.net/pipermail/rsyslog/2011-April/028307.html
3. http://www.rsyslog.com/tag/rate-limiting/
4. http://www.rsyslog.com/changelog-for-5-7-1-v5-devel/