Second try to test rate limiting
Go back to How to build test-tools?
After building the test tool syslog caller, we can give the testing another try. The syslog caller tool will be one process that creates the designated amount of messages. Since it has a very large output, we need it to produce a lot of messages to see the proper effects. We leave the rsyslog config as it is now.
Before we start, delete the logfile and restart rsyslog.
rm /var/log/everything.log /etc/rc.d/init.d/rsyslog restart
Now we start the syslog caller tool with the following command:
/path/to/rsyslog/tests/syslog_caller -m 1000000
This will run for a little while and then bring you back onto the command prompt. With “-m 1000000” we determine how many messages will be generated. In this case we try 1 million messages, just to be on the safe side.
The entries in the logfile should look like this:
Oct 5 18:22:51 client kernel: imklog 5.7.1, log source = /proc/kmsg started. Oct 5 18:22:51 client rsyslogd: [origin software="rsyslogd" swVersion="5.7.1" x-pid="7193" x-info="http://www.rsyslog.com"] startOct 5 18:23:52 client syslog_caller[7200]: test message nbr 0, severity=6 Oct 5 18:23:52 client syslog_caller[7200]: test message nbr 0, severity=6 Oct 5 18:23:52 client syslog_caller[7200]: test message nbr 1, severity=6 Oct 5 18:23:52 client syslog_caller[7200]: test message nbr 2, severity=6 Oct 5 18:23:52 client syslog_caller[7200]: test message nbr 3, severity=6 . . . Oct 5 18:23:52 client syslog_caller[7200]: test message nbr 47, severity=6 Oct 5 18:23:52 client syslog_caller[7200]: test message nbr 48, severity=6 Oct 5 18:23:52 client syslog_caller[7200]: test message nbr 49, severity=6 Oct 5 18:23:52 client rsyslogd-2177: imuxsock begins to drop messages from pid 7200 due to rate-limiting Oct 5 18:23:57 client rsyslogd-2177: imuxsock lost 111673 messages from pid 7200 due to rate-limiting Oct 5 18:23:57 client syslog_caller[7200]: test message nbr 111723, severity=6 Oct 5 18:23:57 client syslog_caller[7200]: test message nbr 111724, severity=6 Oct 5 18:23:57 client syslog_caller[7200]: test message nbr 111725, severity=6 Oct 5 18:23:57 client syslog_caller[7200]: test message nbr 111726, severity=6 Oct 5 18:23:57 client syslog_caller[7200]: test message nbr 111727, severity=6
The first two messages that we have in the logfile are the startup messages. Right after that, the messages from syslog_caller appear. In the brackets behind the process name we find again the PID. If you compare the PID to the other log messages, you will find that is always the same. Syslog_caller is definately suitable for the test. In the shown log above, i skipped some messages, but the essence is visible. Take a look at message 49 (which is message 50 obviously). Right after that, you find a message logged from rsyslog directly. It states that imuxsock starts dropping messages from PID 7200, in this case the syslog_caller. The next message is again from rsyslog and states the amount of messages that have been lost due to rate-limiting. After this, messages are logged again, at least until rate limiting intervenes again.
This is how we can test the rate limiting properly.