Are you losing system logging information (and don't know it)?
(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)
Join us at SANS!
Attend Intrusion Detection In-Depth with Johannes Ullrich in Las Vegas starting Jun 08 2020
