Are you losing system logging information (and don't know it)?

Published: 2013-02-06
Last Updated: 2013-02-06 20:30:17 UTC
by Johannes Ullrich (Version: 1)
1 comment(s)

(This is a guest diary submitted by Bill Parker)

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)

 

1 comment(s)
Diary Archives