iptables or syslog malforming lines in /var/log/messages >:(
 

I'm finding hundreds of cases where either syslog is mutating lines, or iptables is feeding syslog malformed lines, and it's causing my analysis program to report incorrect numbers. Traffic is very heavy on these firewalls, I'm getting on the order of 45-50 GB of logs in /var/log/messages every week. (host names and ip's changed to protect the innocent):

On this firewall, rule 56 is the catch-all DENY at the very end, if one of the previous rules hasn't let you thru, you're not getting thru. About 1/2 way thru the line, "WINDOW=2048RULE 46 --" .... - The first line got cut off, and another line got inserted into the middle of the line.

Aug 5 08:26:48 FW-XXX kernel: RULE 56 -- DENY IN=eth0 OUT= MAC=00:45:8b:a9:bb:a5:00:01:d7:94:d1:bc:08:a7 SRC=12.34.56.78 DST=87.65.43.21 LEN=44 TOS=0x00 PREC=0x00 TTL=41 ID=58634 PROTO=TCP SPT=40805 DPT=453 WINDOW=2048RULE 46 -- ACCEPT IN=eth1 OUT=eth1 SRC=10.5.0.45 DST=10.6.110.86 LEN=69 TOS=0x00 PREC=0x00 TTL=32 ID=12830 PROTO=UDP SPT=2406 DPT=161 LEN=49

------------

Here's another firewall with the same problem. In this line, rule 75 is the catch-all DENY. On this first line, "RULE 75 --D" - the DENY got cut off, and some other rule is accepting a packet, and the line for that is inserted into the line.

Aug 8 22:03:28 FW-ZZZ kernel: RULE 75 -- D-- ACCEPT IN=eth4 OUT=eth2 SRC=10.0.0.58 DST=10.9.150.21 LEN=1428 TOS=0x00 PREC=0x00 TTL=127 ID=58721 PROTO=UDP SPT=1055 DPT=8038 LEN=1408

same here, this line would look like a perfectly legit line if there was 2 hyphens in the "RULE - 75". I could code my program to check for perfect form, but it'd be nicer if the logs worked like they were supposed to....

Aug 5 08:15:47 FW-ZZZ kernel: RULE 75 - ACCEPT IN=eth2 OUT=eth1 SRC=10.0.90.123 DST=10.196.5.8 LEN=48 TOS=0x00 PREC=0x00 TTL=126 ID=42629 DF PROTO=TCP SPT=1361 DPT=443 WINDOW=65535 RES=0x00 SYN URGP=0

Here's one more like that is COMPLETELY perfectly formed, but it has to be the same problem. This would be indetectable.

Aug 5 08:12:53 FW-ZZZ kernel: RULE 75 -- ACCEPT IN=eth4 OUT=eth2 SRC=10.20.0.1 DST=10.45.120.51 LEN=1150 TOS=0x00 PREC=0x00 TTL=127 ID=64260 PROTO=UDP SPT=1034 DPT=8017 LEN=1130

What gives?? Is this a syslog error or an iptables error? I haven't had much luck searching around...

If traffic reaches a high volume then the in-kernel Netfilter framework will require more CPU cycles for determination. The kernel shoves data to Syslog. Syslog needs CPU cycles itself to do (expensive!) disk I/O. Deity knows if there's any processes running on those fws that isn't vital to filtering and logging and w/o any perf details I'd guesstimate it is a backlog thing. Maybe better constructed rules can help (prolly not much), maybe better buffering (Rsyslog?) can help manage backlog or else remote logging?

Thanks, I suspected something similar..