How many administrators review log files in /var/log/*, but don't realize they may be losing possibly important (or even critical) information?

 

In working with a commonly used IDS (Snort 2.9.x) on one of my test platforms (CentOS 6.3 64-bit inside of VirtualBox 4.2.6), I happened to notice a unusual line in /var/log/messages when snort initialized via startup script in /etc/init.d:

 

Feb  5 13:07:52 plugh snort[12105]:       Non-RFC Compliant Characters: 0x00 0x01 0x02 0x03 0x04 0x05 0x06 0x07 

Feb  5 13:07:52 plugh snort[12105]:       Whitespace Characters: 0x09 0x0b 0x0c 0x0d 

Feb  5 13:07:52 plugh snort[12105]: rpc_decode arguments:

Feb  5 13:07:52 plugh snort[12105]:     Ports to decode RPC on: 111 32770 32771 32772 32773 32774 32775 32776 32777 32778 32779 

Feb  5 13:07:52 plugh snort[12105]:     alert_fragments: INACTIVE

Feb  5 13:07:52 plugh snort[12105]:     alert_large_fragments: INACTIVE

Feb  5 13:07:52 plugh snort[12105]:     alert_incomplete: INACTIVE

Feb  5 13:07:52 plugh snort[12105]:     alert_multiple_requests: INACTIVE

Feb  5 13:07:52 plugh snort[12105]: FTPTelnet Config:

Feb  5 13:07:52 plugh snort[12105]:     GLOBAL CONFIG

Feb  5 13:07:52 plugh rsyslogd-2177: imuxsock begins to drop messages from pid 12105 due to rate-limiting <- LOOK HERE

Feb  5 13:07:57 plugh snort[12106]: Daemon initialized, signaled parent pid: 12105

Feb  5 13:07:57 plugh snort[12106]: Reload thread starting...

Feb  5 13:07:57 plugh snort[12106]: Reload thread started, thread 0x7f4039a37700 (12106)

Feb  5 13:07:57 plugh kernel: device eth0 entered promiscuous mode

Feb  5 13:07:57 plugh snort[12106]: Decoding Ethernet

Feb  5 13:07:57 plugh snort[12106]: Checking PID path...

Feb  5 13:07:57 plugh snort[12106]: PID path stat checked out ok, PID path set to /var/run/

Feb  5 13:07:57 plugh snort[12106]: Writing PID "12106" to file "/var/run//snort_eth0.pid"

Feb  5 13:07:57 plugh snort[12106]: Set gid to 40000

Feb  5 13:07:57 plugh snort[12106]: Set uid to 40000

Feb  5 13:07:57 plugh snort[12106]: 

Feb  5 13:07:57 plugh snort[12106]:         --== Initialization Complete ==--

Feb  5 13:07:57 plugh snort[12106]: Commencing packet processing (pid=12106)

 

It turns out that many modern Linux distributions come with 'rsyslog', which is a replacement for 'syslogd' or 'sysklogd', but starting with version 5.7.1 of rsyslog, a feature known as rate-limiting was added to the utility, and if a given process ID (PID) were to send more than 200 messages to /var/log/messages in a 5 second interval (the default setting in rsyslog), it will start to drop messages and place the following warning inside of /var/log/messages:

 

Feb  5 13:07:52 plugh rsyslogd-2177: imuxsock begins to drop messages

from pid 12105 due to rate-limiting

 

In the case of daemons or processes logging to /var/log/messages (or any other directory/file which rsyslog happens to be handling  logging for), a great deal of important and/or critical logging  data could be lost to security or system administrators.

 

While rate-limiting on routers/firewalls/web servers is a useful method of containing certain types of network based attacks, in the case of system and/or application logging, this may create a logistical nightmare for SIEM's or applications which collect and analyze large amounts of system and/or application logs for event information/messages/warnings.

 

In doing some research on rsyslog, I found two solutions which can be used to solve this condition on systems where rsyslog is the default system logging method.

 

Note - Back up any file(s) listed below before proceeding!

 

The first solution is to simply increase the messages allowed and the time interval before rate-limiting occurs in rsyslog.  To do this, locate the rsyslog.conf and/or rsyslog.early.conf (usually in /etc) and add the following lines:

 

$SystemLogRateLimitInterval 10

$SystemLogRateLimitBurst 500

 

after any ModLoad commands in rsyslog.conf and/or rsyslog.early.conf

 

This will tell rsyslog to start rate-limiting (discarding messages) when more than 500 messages from a single PID are received within a 10 second interval (these numbers are not absolutes, they can be tailored to any given system, btw).

 

The second solution is to simply turn off rate-limiting for rsyslog, and to do this, add the following line to rsyslog.early.conf and/or rsyslog.conf using your favorite editor (Iím a vi/vim/gvim hound):

 

$SystemLogRateLimitInterval 0

 

after any ModLoad commands in rsyslog.conf and/or rsyslog.early.conf

 

This will disable any rate-limiting in effect for the rsyslog process running on this system.  Note that by doing this, an out of control process ID on your system can fill up /var/log/messages with a lot of useless messages (which is why rate-limiting is enabled by default in rsyslog).

 

Remember to stop/start or restart the rsyslog daemon in order to make the changes to rsyslog.conf and/or rsyslog.early.conf take effect.

 

The following Linux systems use 'rsyslog' as the default system logger (these are distributions which I am actively using, btw):

 

CentOS 6.x

Debian 5.0 or greater

Fedora 13 or greater

OpenSuSE 11.x/12.x

Ubuntu 10.0 or greater

 

BSD based systems (FreeBSD 8.x/9.0, OpenBSD 5.x, and NetBSD 5.x/6.0) use traditional syslogd as the default system logging utility.

 

If you need more information about rsyslog, you can visit the following URL:

 

http://www.rsyslog.com/doc

 

Questions/Comments/Suggestions?

 

Bill Parker (wp02855 at gmail dot com)