How to use rate limiting in rsyslog?
This article is tested with rsyslog 5.7.1 on Fedora 13. It will not work with version of rsyslog prior to 5.7.1.
In rsyslog 5.7.1 we introduced rate limiting. This is a option for the Unix Socket Input module called imuxsock. In short, this option limits the amount of messages written into logfiles by a process, if the process tries to write huge amounts of messages in a short period of time.
If you look a bit more into the details, this new feature makes a lot of sense. Because when regular logging happens, this makes no difference. But if a process goes wild (and I bet everyone has experienced this at least once) and starts to create large bulks of log messages, this affects the whole system in general. This blocks not only your I/O, but creates a large amount of logs that usually is simply not necessary and doesn’t really hold useful information. Therefore such messages are now discarded automatically. We will describe later how you can customize these settings for this.
This article is aimed for those who want to learn a bit more about how the rate limit works or who are new to this topic. Therefore we will not only describe how to set this up or change settings, but we want to show you some ways of testing, how imuxsock works and where some caveats are lying.
Please go on to the following pages.
Changing the settings
Go back to What is imuxsock?
Before we can begin testing on how rate limiting works, we should change the default settings. By default, rate limiting will only work, if a process sends more than 200 messages in 5 seconds.To have some influence on the rate limiting we have basically two options:
$SystemLogRateLimitInterval [number] $SystemLogRateLimitBurst [number]
The SystemLogRateLimitInterval determines the amount of time that is being measured for rate limiting. By default this is set to 5 seconds. The SystemLogRateLimitBurst defines the amount of messages, that have to occur in the time limit of SystemLogRateLimitInterval, to trigger rate limiting. Here, the default is 200 messages. For creating a more effective test, we will alter the default values.
To change these settings we open the rsyslog configuration. Open the configuration with vi (please note, that we use the default configuration path):
vi /etc/rsyslog.conf
Now we need to search the right spot for the entries. Find the following:
$ModLoad imuxsock.so
This entry will load the imuxsock module.
Now insert two new lines under the ModLoad command and fill them as follows:
$SystemLogRateLimitInterval 2 $SystemLogRateLimitBurst 50
These are the option for the module with some values. This means in plain words, that rate limiting will take effect if more than 50 messages occur in 2 seconds.
To make sure, that we will see all messages that are logged, we insert another entry into the configuration. Go to the section in the rsyslog.conf that holds the “Rules”. Insert a new rule that looks like this:
*.* /var/log/everything.log
You can name the file as you want. Every log message will be written into this file for our review.
Save the configuration file and exit vi. Now we need to restart rsyslog. This is necessary because it will only load the configuration once on startup.
First try to test rate limiting
Go back to Changing the settings
For a first test of the rate limiting feature we made up our mind on how to test it. We soon came up with the idea of a small shell script that will run logger with a test message. The script looks as follows
n=1000 i=0 while [ $i -lt $n ] do logger "This is Testmessage #$i" echo "Messages: $i" i=`expr $i + 1` done
In this example, we have a pretty simple while loop. The loop will terminate, once the variable i has the size of n. In every run, i will be incremented by 1. After that a message is logged via logger and the message will be written to the terminal. You can download the script file here. Please note, that after downloading, you need to set chmod to 755 for this file.
Now run the file.
/foldername/ratelimittest
You will see a lot of lines being written to the terminal. In the current configuration, the while loop has 1000 iterations. When finished, the terminal will show the input prompt again. We can now review the log file to see if rate limiting worked.
vi /var/log/everything.log
Oct 5 17:01:57 client test: This is Testmessage #43 Oct 5 17:01:57 client test: This is Testmessage #44 Oct 5 17:01:57 client test: This is Testmessage #45 Oct 5 17:01:57 client test: This is Testmessage #46 Oct 5 17:01:57 client test: This is Testmessage #47 Oct 5 17:01:57 client test: This is Testmessage #48 Oct 5 17:01:57 client test: This is Testmessage #49 Oct 5 17:01:57 client test: This is Testmessage #50 Oct 5 17:01:57 client test: This is Testmessage #51 Oct 5 17:01:57 client test: This is Testmessage #52 Oct 5 17:01:57 client test: This is Testmessage #53 Oct 5 17:01:57 client test: This is Testmessage #54 Oct 5 17:01:57 client test: This is Testmessage #55 Oct 5 17:01:57 client test: This is Testmessage #56 Oct 5 17:01:57 client test: This is Testmessage #57 Oct 5 17:01:57 client test: This is Testmessage #58 Oct 5 17:01:57 client test: This is Testmessage #59 Oct 5 17:01:57 client test: This is Testmessage #60 Oct 5 17:01:57 client test: This is Testmessage #61
Let’s take a look at the messages around message 50. Usually, there should be a message after message 50, that some messages are not logged due to rate limiting. So either our test is not suitable because of the runtime or it isn’t recognized correctly. To check on this, we make another change to the rsyslog configuration file as we did before. Again, go to the section for imuxsock at the beginning. Now we add a third option for imuxsock.
$SystemLogUsePIDFromSystem on
With this option, the PID of the process that is sending a message to imuxsock will be added to the log. Therefore we can check if the process has run correctly. Save the config and restart rsyslog again. Now once more, let the script run and take a look at the log afterwards.
Oct 5 17:27:01 client test[6941]: This is Testmessage #41 Oct 5 17:27:01 client test[6943]: This is Testmessage #42 Oct 5 17:27:02 client test[6945]: This is Testmessage #43 Oct 5 17:27:02 client test[6947]: This is Testmessage #44 Oct 5 17:27:02 client test[6949]: This is Testmessage #45 Oct 5 17:27:02 client test[6951]: This is Testmessage #46 Oct 5 17:27:02 client test[6953]: This is Testmessage #47 Oct 5 17:27:02 client test[6955]: This is Testmessage #48 Oct 5 17:27:02 client test[6957]: This is Testmessage #49 Oct 5 17:27:02 client test[6959]: This is Testmessage #50 Oct 5 17:27:02 client test[6961]: This is Testmessage #51 Oct 5 17:27:02 client test[6963]: This is Testmessage #52 Oct 5 17:27:02 client test[6965]: This is Testmessage #53 Oct 5 17:27:02 client test[6967]: This is Testmessage #54 Oct 5 17:27:02 client test[6969]: This is Testmessage #55 Oct 5 17:27:02 client test[6971]: This is Testmessage #56 Oct 5 17:27:02 client test[6973]: This is Testmessage #57 Oct 5 17:27:02 client test[6975]: This is Testmessage #58 Oct 5 17:27:02 client test[6977]: This is Testmessage #59 Oct 5 17:27:02 client test[6979]: This is Testmessage #60
What we see now behind the username is the PID (Process ID). As we can see now, the PID is different for every log entry. That means, that a new process has been started for every message, thus rendering our test useless, because rate limiting only works if the same PID is given.
Therefore we need a specialized test tool. How to build the appropriate tool is shown on the next page.
Go on to How to build test-tools?
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.
What is imuxsock?
Go back to How to use rate limiting
What is imuxsock some might ask. It is the name of the module that handles Unix Socket Input. For some who might not know, this module manages the delivery of syslog calls from a logging process to rsyslog. The module listens to the log sockets of a Unix system and gives rsyslog the log messages when they occur.
As a module, imuxsock has to be called in the configuration file of rsyslog. The entry looks like this:
$ModLoad imuxsock.so
Because this is the most commonly used module, this entry is in every rsyslog config by default. And because without it, no local logging could work.
The module itself has some options. The default values don’t have to be changed necessarily, because they are pretty balanced. But in some cases this has to be done, like, if a service does separate log socket or when you want to make rate limiting stricter. I won’t give a description to all the options here, because they are documented relatively good in the documentation.
Go on to Changing the settings