Debugging syslog-ng problems

While debugging the syslog-ng issue I mentioned previously, I needed to be able to observe the syslog-ng pattern matches as they occurred. The syslog-ng daemon has a couple of useful options to assist with this. The first is the “-e” option, which causes the daemon to log to stdout. The second is the “-F” option, which stops the daemon from forking. When you combine these option with the “-d” (debug) and “-v” (verbose) options, syslog-ng will print each log message it receives along with the rule processing logic that is applied to that rule:

$ /opt/syslog-ng/sbin/syslog-ng -e -F -d -v > /tmp/syslog-ng.out 2>&1

Incoming log entry; line='<85>sshd2[382]: Public key /root/.ssh/id_rsa_1024.pub used.\x0a'
Filter rule evaluation begins; filter_rule='f_web_hosts'
Filter node evaluation result; filter_result='match', filter_type='level'
Filter node evaluation result; filter_result='not-match'
Filter node evaluation result; filter_result='not-match'
Filter node evaluation result; filter_result='not-match', filter_type='OR'
Filter node evaluation result; filter_result='not-match', filter_type='AND'
Filter rule evaluation result; filter_result='not-match', filter_rule='f_web_hosts'
Filter rule evaluation begins; filter_rule='f_app_hosts'
 ...

When a syslog message matches a given rule, you will see the filter_result string change from not-match to match:

Filter rule evaluation result; filter_result=’match’, filter_rule=’f_db_hosts’

Syslog-ng is pretty sweet, and you can check out my centralized logging presentation if you are interested in learning more about how this awesome piece of software works!

Getting syslog-ng to filter messages by source IP address

I received a call this week from one of our network guys because messages from several network devices weren’t being logged by our centralized log server. When I started debugging the issue, I noticed that traffic from the hosts (host1 in this example) was making it to our syslog-ng server:

$ tcpdump -i eth0 host host1

tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on eth0, link-type EN10MB (Ethernet), capture size 96 bytes
09:22:01.672377 host1.65093 > syslog.syslog: SYSLOG local4.error, length: 108
09:22:06.904446 host1.65093 > syslog.syslog: SYSLOG local4.notice, length: 128

While the traffic was making it to the server, the syslog messages were not being matched against a rule we had defined. Being the curious guy I am, I decided to read the syslog RFC to get a better understanding of the syslog message format. If you aren’t familiar with syslog messages, they take the following form:

<PRI> <HEADER> <MSG>

The PRI section contains the facility and priority, the HEADER section contains a timestamp and the hostname or IP address of the device, and the MSG section contains the message the host is trying to send to the server.

When I dumped one of the syslog message as a raw string of bytes, I noticed that the hostname field didn’t match the expression we were trying to match against. For reference, here is the expression we were using (FYI: the host() directive matches against the hostname in the syslog message, not the source IP address in the IP datagram):

filter f_web_hosts { (host(192.168.0.25)) };

Since the hostname and source IP address were different, the rule didn’t match. To get this to work correctly, I needed to use a netmask() statement to filter based on the source IP address in the IP datagram:

filter f_web_hosts { (netmask(192.168.0.25/32)) };

Once this rule was in place, everything worked as expected! Rock on!