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
How to build the testing tools?
This article has been tested with rsyslog 5.7.1 on Fedora 13. It is part of the article “How to use rate limiting?”
Go back to First try to test rate limiting (fail)
When building a configuration for rsyslog, you will sometimes stumble upon the question, if your setup really works. To prove this in your environment is very complicated in most cases. For this we have made some test tools, which help you test your configuration. The main reason for us to create these tools was for testing new features and try out scenarios. But in the end we deliver them with every release. We will describe the way how to create and use the testing tools with the example of the tool syslog_caller. This tool creates a bunch of messages for the local loghost.
First you need to navigate to your rsyslog folder. From there you need to go to the subfolder tests. The path could look like this:
/home/username/rsyslog/tests/
We need to “make” the tests first before we can use it.
# make syslog_caller
The make process gives you some output. It looks like this:
CC syslog_caller.or CCLD syslog_caller
After that, we are ready to use the test-tool. Use the following command:
./syslog_caller
This will generate 500 messages by default. You can change the default values with some switches. The switches are usually documented in the .c file of the tool. In this case, when using the following:
./syslog_caller -m 10000
will generate 10000 messages. With the test tools, you can do some stress-testing for your rsyslog installation. A good way to proof, if your configuration is working correctly.