Saturday, October 20, 2012

Ratelimit callbacks suppressed


Recently I hardened some RHEL6 based machines.
During this hardening process - among the others - I did the following:
- disdabled ipv6 by "options ipv6 disable=1" in /etc/modprobe.d/hardening.conf
- added some more audit rules according to NSA guide
- stopped auditd therefore audit log events are redirected to kernel log
- filtered audit logs by following filter to separate audilt.log:
filter f_audit { match(' audit\(' value("MESSAGE")); };

After this hardening there were staerted appearing "__ratelimit: XX callbacks suppressed" messages regularly in kernel log, like following:

Oct 18 01:00:01 test1 kernel: __ratelimit: 4 callbacks suppressed
Oct 18 01:01:01 test1 kernel: __ratelimit: 192 callbacks suppressed
Oct 18 01:05:07 test1 kernel: __ratelimit: 188 callbacks suppressed

It didn't cause any problem but after a while I've started investigating (thx Cipo) what can cause this strange behaviour.

The root cause of this problem is a bit complex. Let's see them:
- disabling ipv6 module caused that some programs would like to insert it
- I've set an audit rule which logs any module instertion attempts: "-w /sbin/modprobe -p x -k modules"
- there are kernel.printk_ratelimit* kernel parameters
# cat /proc/sys/kernel/printk_ratelimit
5
# cat /proc/sys/kernel/printk_ratelimit_burst
10
This means that there is a 10 msgs/5 seconds limit in kernel logging. Exceeding this limit messages will be dropped AND "__ratelimit NumberOfDroppedMessages: callbacks suppressed" messages will be written to the kernel log.

To put the pieces of the picture together:
- my script runs curl 20 times
- curl tried to insert ipv6 module by modprobe
- modprobe tries were logged by audit (5 lines/ modprobe)
- too much audit log in short time exceeded the ratelimit


My solution:
- re-enable ipv6 by commenting  "options ipv6 disable=1" line in /etc/modprobe.d/hardening.conf
- prevent use of ipv6 calls by appending following line to /etc/sysctl.conf:
net.ipv6.conf.all.disable_ipv6 = 1 
(Thanks to Daniel Walsh)

These resulted that:
- ipv6 module is already inserted, so programs do not want to insert it
- ipv6 remained pseudo-disabled

After finishing this I've continued getting ratelimit messaged but not regularly.
I've  find out that Midnight Commander deletes a few temporary files and changes permissions of its config files after exiting. This process resulted more than 150 lines within one second in audit log...
My solution is that I've appended following line to the /etc/sysctl.conf file:
kernel.printk_ratelimit = 30
kernel.printk_ratelimit_burst = 200
This means that kernel accepts 200 messages/30 sec

Comments are welcome.