Linux rsyslog imuxsock lost xxx messages from pid xx due to rate-limitin

由于 rsyslog 的速率限制,/var/log/messages 显示大量已删除的消息条目:

...
Nov 7 14:23:14 thx1138 rsyslogd-2177: imuxsock lost 516 messages from pid 159386 due to rate-limiting
Nov 7 14:23:15 thx1138 rsyslogd-2177: imuxsock begins to drop messages from pid 159386 due to rate-limiting
Nov 7 14:23:20 thx1138 rsyslogd-2177: imuxsock lost 512 messages from pid 159386 due to rate-limiting
Nov 7 14:23:21 thx1138 rsyslogd-2177: imuxsock begins to drop messages from pid 159386 due to rate-limiting
Nov 7 14:29:50 thx1138 rsyslogd-2177: imuxsock begins to drop messages from pid 238300 due to rate-limiting
...

这是预期的行为。
rsyslogd 工作正常。
有关丢弃消息的条目是正常条目。
默认情况下,rsyslogd 在 5 秒内接受来自单个进程的 200 条消息。
如果超过该阈值,消息将被丢弃。
因此,在下面的示例条目中,进程 77845 在 5 秒内发送了大约 436 条消息。
由于速率限制,rsyslogd 删除了其中的 236 个。

...
Nov 6 15:46:48 thx1138 rsyslogd-2177: imuxsock begins to drop messages from pid 77845 due to rate-limiting
Nov 6 15:46:52 thx1138 rsyslogd-2177: imuxsock lost 236 messages from pid 77845 due to rate-limiting PID 77845
...

使用下面显示的值设置以下参数将禁用速率限制并且不会丢弃任何消息。

# vi /etc/rsyslog.conf
$SystemLogRateLimitInterval 0
$SystemLogRateLimitBurst 0
$IMUXSockRateLimitBurst 0
$IMUXSockRateLimitInterval 0
$IMUXSockRateLimitSeverity 7
...

人们可能期望 rsyslog 处理的每个条目都将输入到消息文件中。
不是这种情况。
rsyslog.conf 文件有一个名为 RULES 的部分,用于管理 rsyslog 写入消息的位置。
默认情况下,只有内核消息、信息性消息和紧急消息被写入消息文件。
其他消息写入其他文件。
例如,处理用户身份验证的消息转到 /var/log/secure ,处理邮件的消息转到 /var/log/maillog 。

由于 rsyslog 根据消息类型将消息写入不同的文件,因此关闭速率限制将导致所有消息写入其指定的日志文件,而不仅仅是消息文件。
我们可以通过执行以下操作来查看此操作:

  1. 备份 /etc/rsyslogd.conf 文件。
# cp -p /etc/rsyslog.conf /etc/rsyslog.conf_orig
  1. 根据操作系统版本,禁用速率限制,如下面的帖子所示。

  2. 记下 /var/log 中日志文件的大小:

# ls -la /var/log
  1. 重启 rsyslog。
# service rsyslog restart       ### CentOS/RHEL 6
# systemctl restart rsyslog       ### CentOS/RHEL 7
  1. 等待约 1 小时。

  2. 恢复在步骤 2 中所做的更改。

  3. 重新启动 rsyslog。

# service rsyslog restart       ### CentOS/RHEL 6
# systemctl restart rsyslog       ### CentOS/RHEL 7
  1. 注意 /var/log 中日志文件的大小。

这样做的结果将是:

  • 除了 /var/log 中的消息文件之外,一个或者多个日志文件的大小大大增加。
  • 在禁用速率限制期间,一个或者多个日志文件中的条目频率增加。
  • 在消息文件中几乎没有看到任何条目。如本例所示,消息一直被丢弃,直到速率限制被禁用并且 rsyslog 在 14:30 重新启动。在 14:30 和 15:33 之间,只有 14:44 的 rngd 条目。启用速率限制后,丢弃的消息再次开始。
Nov 7 14:23:21 thx1138 rsyslogd-2177: imuxsock begins to drop messages from pid 159386 due to rate-limiting
Nov 7 14:29:50 thx1138 rsyslogd-2177: imuxsock begins to drop messages from pid 238300 due to rate-limiting
Nov 7 14:30:02 thx1138 kernel: Kernel logging (proc) stopped.
Nov 7 14:30:02 thx1138 rsyslogd: [oroirn software="rsyslogd" swVersion="5.8.10" x-pid="13439" x-info="http://www.rsyslog.com"] exiting on signal 15.
Nov 7 14:30:02 thx1138 kernel: imklog 5.8.10, log source = /proc/kmsg started.
Nov 7 14:30:02 thx1138 rsyslogd: [oroirn software="rsyslogd" swVersion="5.8.10" x-pid="242406" x-info="http://www.rsyslog.com"] start
Nov 7 14:44:15 thx1138 rngd[13453]: read error
Nov 7 15:32:58 thx1138 kernel: Kernel logging (proc) stopped.
Nov 7 15:32:58 thx1138 rsyslogd: [oroirn software="rsyslogd" swVersion="5.8.10" x-pid="242406" x-info="http://www.rsyslog.com"] exiting on signal 15.
Nov 7 15:32:59 thx1138 kernel: imklog 5.8.10, log source = /proc/kmsg started.
Nov 7 15:32:59 thx1138 rsyslogd: [oroirn software="rsyslogd" swVersion="5.8.10" x-pid="175797" x-info="http://www.rsyslog.com"] start
Nov 7 15:34:25 thx1138 rsyslogd-2177: imuxsock begins to drop messages from pid 179680 due to rate-limiting
Nov 7 15:35:56 thx1138 rsyslogd-2177: imuxsock lost 193 messages from pid 179680 due to rate-limiting

所以从上面,我们可以看到禁用速率限制实际上是有效的,只是不像人们预期的那样有效。
关于速率限制,必须考虑以下几点:

  1. 随机且不频繁的消息突发并不一定表明存在问题。
    然而,可以调查丢弃消息的持续持续重复。
    如果丢弃的消息频繁发生并且丢弃了大量消息,则需要调查这些消息是什么(错误的信息性或者实际警告)。
    我们可以使用上面的测试来查看消息的去向,然后查看 /var/log 中的日志以确定问题是否确实存在或者记录。

  2. 在更改 rsyslogd.conf 中的速率限制设置或者完全禁用速率限制时要小心。
    丢弃的消息越少意味着记录它们所需的处理越多。
    过多的消息会导致性能问题,在极端情况下甚至会导致驱逐。

日期:2020-09-17 00:14:10 来源:oir作者:oir