RE: [syslog-ng] logging pauses and log entry truncation
One difference I noticed between your log entries and mine is, yours appear to either get mangled and/or truncated, and then that's it, it continues on the next line with a new log entry. I've seen a bit different behavior in mine, where it will mangle and/or truncate a line, but then on the next entry, it continues with the rest of the previous entry. It's like when reading from /proc/kmsg it's erroneously detecting an end of line, sending that bit of data to the destinations, then continues reading from /proc/kmsg, starting where it cut off. For example: Aug 14 10:17:46 loghost01 fwlog input drop cleanup IN=eth0 OUT= MAC=00:06: Aug 14 10:17:46 loghost01 5b:84:60:7e:00:50:04:a5:11:1f:08:00 SRC=172.30.10.33 DST=172.30.8.40 LEN=60 TOS=0x00 PREC=0x00 TTL=219 ID=61008 DF PROTO=TCP SPT=54189 DPT=32601 WINDOW=5840 RES=0x00 SYN URGP=0 Aug 14 10:17:52 loghost01 <4>fwlog input drop cleanup IN=eth0 OUT= MAC=00: Aug 14 10:17:52 loghost01 06:5b:84:60:7e:00:50:04:a5:11:1f:08:00 SRC=172.30.10.33 DST=172.30.8.40 LEN=60 TOS=0x00 PREC=0x00 TTL=219 ID=36311 DF PROTO=TCP SPT=54189 DPT=32601 WINDOW=5840 RES=0x00 SYN URGP=0 As you can see, the first line gets truncated, then on the next line, it continues with the rest of the log entry starting where the previous one got cut off. While writing this, I just saw the most mangled entry I've seen yet: Aug 14 10:16:15 loghost01 fwlog input drop clenup Ib:84:602. PREC=0x00 TTL=79 ID=T=TCP S SYN TCP i OUT MAC=00:06:5b:84172.3072.=5840 RES=0x00 N=0 As opposed to what it /should/ look like: Aug 14 10:17:46 loghost01 fwlog input drop cleanup IN=eth0 OUT= MAC=00:06:5b:84:60:7e:00:50:04:a5:11:1f:08:00 SRC=172.30.10.33 DST=172.30.8.40 LEN=60 TOS=0x00 PREC=0x00 TTL=219 ID=45827 DF PROTO=TCP SPT=38821 DPT=32606 WINDOW=5840 RES=0x00 SYN URGP=0 Weird weird stuff. Hopefully some of this discussion and related log snippets will help Balazs pinpoint the problem. --- Dustin D. Trammell Information Security Specialist Penson Financial Services, Inc. -----Original Message----- From: Caylan Van Larson [mailto:caylan@cs.und.edu] Sent: Wednesday, August 14, 2002 10:08 To: 'syslog-ng@lists.balabit.hu' Subject: RE: [syslog-ng] logging pauses and log entry truncation Yes, similar, but also erratic. I have it happening in the MAC addy and toward the end. Sometimes it seems as they are folded in on itself. I have placed a sample on www.cs.und.edu/~caylan/kern for your viewing pleasure. It is not my sytle to make things like this publicly accessible but I want to get this issue resolved. In case you did not see the above URL or are too lazy :P Aug 14 10:02:30 smack IPTABLES UDP-IN: IN=eth1 OUT= MAC=00:03:47:4e:32:44:00:05:01:fb:e3:fc:08: Aug 14 10:02:31 smack IPTABLES TCP-IN: IN=eth1 OUT= MAC=00:03:47:4e:32:44:00:05:01:fb:e3:fc:08:00 SRC=63.151.197.164 DST=134.129.212.30 LEN=48 TOS=0x00 PREC=0x00TT14 2103DF PRTCP SW=163 Aug 14 10:02:32 smack IPTABLES UDP-IN: IN=eth1 OUT= MAC=00:03:47:4e:32:44:00:05:01:fb:e3:fc:08: Aug 14 10:02:32 smack IPTABLES UDP-IN: IN=eth1 OUT= MAC=00:03:47:4e:32:44:00:05:01:fb:e3:fc: Aug 14 10:02:32 smack IPTABLES UDP-IN: IN=eth1 OUT= MAC=00:03:47:4e:32:44:00:05:01:fb:e3:fc:08:00 SRC=134.129.215.35 DST=1PSPT7 DPT=137 L Aug 14 10:02:32 smack IPTABLES UDP-IN: IN=eth1 OUT= MAC=00:03:47:4e:32:44:00:05:01:fb:e3:fc:08: Aug 14 10:02:33 smack IPTABLES UDP-IN: IN=eth1 OUT= MAC=00:03:47:4e:32:44:00:05:01:fb:e3:fc:08:00 SRC=134.129.215.35 DST=134.129.212.30 LEN=9 138 N=20 Aug 14 10:02:33 smack IPTABLES UDP-IN: IN=eth1 OUT= MAC=00:03:47:4e:32:44:00:05:01:fb:e3:fc:08: Thats a pretty damn good sample! Good luck, Caylan Van Larson Unix Administrator - Systems Team Member University of North Dakota (Aerospace College) caylan@cs.und.edu 701-777-6151 (work)
One difference I noticed between your log entries and mine is, yours appear to either get mangled and/or truncated, and then that's it, it continues on the next line with a new log entry. I've seen a bit different behavior in mine, where it will mangle and/or truncate a line, but then on the next entry, it continues with the rest of the previous entry. It's like when reading from /proc/kmsg it's erroneously detecting an end of line, sending that bit of data to the destinations, then continues reading from /proc/kmsg, starting where it cut off. For example:
Aug 14 10:17:46 loghost01 fwlog input drop cleanup IN=eth0 OUT= MAC=00:06: Aug 14 10:17:46 loghost01 5b:84:60:7e:00:50:04:a5:11:1f:08:00 SRC=172.30.10.33 DST=172.30.8.40 LEN=60 TOS=0x00 PREC=0x00 TTL=219 ID=61008 DF PROTO=TCP SPT=54189 DPT=32601 WINDOW=5840 RES=0x00 SYN URGP=0
Aug 14 10:17:52 loghost01 <4>fwlog input drop cleanup IN=eth0 OUT= MAC=00: Aug 14 10:17:52 loghost01 06:5b:84:60:7e:00:50:04:a5:11:1f:08:00 SRC=172.30.10.33 DST=172.30.8.40 LEN=60 TOS=0x00 PREC=0x00 TTL=219 ID=36311 DF PROTO=TCP SPT=54189 DPT=32601 WINDOW=5840 RES=0x00 SYN URGP=0
True.
While writing this, I just saw the most mangled entry I've seen yet:
Aug 14 10:16:15 loghost01 fwlog input drop clenup Ib:84:602. PREC=0x00 TTL=79 ID=T=TCP S SYN TCP i OUT MAC=00:06:5b:84172.3072.=5840 RES=0x00 N=0
Yikes.
As opposed to what it /should/ look like:
Aug 14 10:17:46 loghost01 fwlog input drop cleanup IN=eth0 OUT= MAC=00:06:5b:84:60:7e:00:50:04:a5:11:1f:08:00 SRC=172.30.10.33 DST=172.30.8.40 LEN=60 TOS=0x00 PREC=0x00 TTL=219 ID=45827 DF PROTO=TCP SPT=38821 DPT=32606 WINDOW=5840 RES=0x00 SYN URGP=0
Weird weird stuff. Hopefully some of this discussion and related log snippets will help Balazs pinpoint the problem.
Also, I would like to add that syslog-ng stops appending to /var/log/kern after about 20k of data. It just stops, nothing. I restart syslog-ng and here is what happens: /var/log/bootup Aug 14 10:49:44 smack syslog-ng: klogd shutdown succeeded Aug 14 10:49:48 smack syslog-ng: syslog-ng startup succeeded Aug 14 10:49:48 smack syslog-ng: klogd startup succeeded (never says anything about syslog-ng shutdown ducceeded, is this normal?) /var/log/kern Populated for about 30k of data, truncated. I would also like to know why when I restart iptables it puts any output from the scripts to /var/log/bootup??? For instance, the iptables init script calls a firewall script that runs a bunch of iptable commands. This script also outputs some settings: --SNIP (from /var/log/bootup on iptables restart) Aug 14 10:50:53 smack fw-iptables: Serving port 22 (tcp) only to 134.129.212.0/24 134.129.217.128/26 Aug 14 10:50:53 smack fw-iptables: Serving port 113 (tcp) only to 134.129.212.0/24 Aug 14 10:50:53 smack fw-iptables: Serving port 515 (tcp) to the world. Aug 14 10:50:53 smack fw-iptables: Serving needs client as well: Client may access port 9100 (tcp) anywhere. Aug 14 10:50:53 smack fw-iptables: Enabling DNS Server Communications: Aug 14 10:50:53 smack fw-iptables: Serving port 53 (udp) to the world. Aug 14 10:50:53 smack fw-iptables: Serving needs client as well: Client may access port 53 (udp) anywhere. Aug 14 10:50:53 smack fw-iptables: Serving port 53 (tcp) Zone Transfers to 134.129.217.44 Aug 14 10:50:53 smack fw-iptables: Serving port 53 (tcp) Zone Transfers to 134.129.217.46 Aug 14 10:50:53 smack fw-iptables: Serving port 67 (udp) to the world. Aug 14 10:50:53 smack fw-iptables: Serving port 58884 (tcp) only to 134.129.212.0/24 Aug 14 10:50:53 smack fw-iptables: Client may access port 515 (tcp) only on 134.129.212.0/24 Aug 14 10:50:53 smack fw-iptables: Client may access port 389 (tcp) only on 134.129.212.0/24 Aug 14 10:50:53 smack fw-iptables: Client may access port 636 (tcp) only on 134.129.212.0/24 Aug 14 10:50:53 smack fw-iptables: Client may access port 37 (tcp) only on 134.129.212.0/24 Aug 14 10:50:53 smack fw-iptables: Client may access port 514 (tcp) only on 134.129.212.0/24 Aug 14 10:50:53 smack fw-iptables: Client may access port 514 (udp) only on 134.129.212.0/24 Aug 14 10:50:53 smack fw-iptables: Client may access port 143 (tcp) only on 134.129.212.0/24 Aug 14 10:50:53 smack fw-iptables: Client may access port 993 (tcp) only on 134.129.212.0/24 Aug 14 10:50:53 smack fw-iptables: Client may access port 110 (tcp) only on 134.129.212.0/24 Aug 14 10:50:53 smack fw-iptables: Client may access port 995 (tcp) only on 134.129.212.0/24 Aug 14 10:50:53 smack fw-iptables: Client may access port 58884 (tcp) only on 134.129.212.0/24 Aug 14 10:50:53 smack fw-iptables: Client may access port 23 (tcp) anywhere. Aug 14 10:50:53 smack fw-iptables: Client may access port 113 (tcp) anywhere. --SNAP Also, it may help to know that I am running all of my iptables LOG commands with the --log-level 6 and with custom --log-prefix "PREFIX" like this: --SNIP # Any tcp not already allowed is logged and then dropped. iptables -A INPUT -i $IFACE -p tcp -j LOG --log-level 6 --log-prefix "IPTABLES TCP-IN: " iptables -A INPUT -i $IFACE -p tcp -j DROP iptables -A OUTPUT -o $IFACE -p tcp -j LOG --log-level 6 --log-prefix "IPTABLES TCP-OUT: " iptables -A OUTPUT -o $IFACE -p tcp -j DROP --SNAP Are you adding these loglevel and logprefix switches also? Could this possibly be the problem? If iptables is adding these prefixes to late? I dont know :P Thanks, Caylan
--- Dustin D. Trammell Information Security Specialist Penson Financial Services, Inc.
-----Original Message----- From: Caylan Van Larson [mailto:caylan@cs.und.edu] Sent: Wednesday, August 14, 2002 10:08 To: 'syslog-ng@lists.balabit.hu' Subject: RE: [syslog-ng] logging pauses and log entry truncation
Yes, similar, but also erratic. I have it happening in the MAC addy and toward the end. Sometimes it seems as they are folded in on itself.
I have placed a sample on www.cs.und.edu/~caylan/kern for your viewing pleasure. It is not my sytle to make things like this publicly accessible but I want to get this issue resolved.
In case you did not see the above URL or are too lazy :P
Aug 14 10:02:30 smack IPTABLES UDP-IN: IN=eth1 OUT= MAC=00:03:47:4e:32:44:00:05:01:fb:e3:fc:08: Aug 14 10:02:31 smack IPTABLES TCP-IN: IN=eth1 OUT= MAC=00:03:47:4e:32:44:00:05:01:fb:e3:fc:08:00 SRC=63.151.197.164 DST=134.129.212.30 LEN=48 TOS=0x00 PREC=0x00TT14 2103DF PRTCP SW=163 Aug 14 10:02:32 smack IPTABLES UDP-IN: IN=eth1 OUT= MAC=00:03:47:4e:32:44:00:05:01:fb:e3:fc:08: Aug 14 10:02:32 smack IPTABLES UDP-IN: IN=eth1 OUT= MAC=00:03:47:4e:32:44:00:05:01:fb:e3:fc: Aug 14 10:02:32 smack IPTABLES UDP-IN: IN=eth1 OUT= MAC=00:03:47:4e:32:44:00:05:01:fb:e3:fc:08:00 SRC=134.129.215.35 DST=1PSPT7 DPT=137 L Aug 14 10:02:32 smack IPTABLES UDP-IN: IN=eth1 OUT= MAC=00:03:47:4e:32:44:00:05:01:fb:e3:fc:08: Aug 14 10:02:33 smack IPTABLES UDP-IN: IN=eth1 OUT= MAC=00:03:47:4e:32:44:00:05:01:fb:e3:fc:08:00 SRC=134.129.215.35 DST=134.129.212.30 LEN=9 138 N=20 Aug 14 10:02:33 smack IPTABLES UDP-IN: IN=eth1 OUT= MAC=00:03:47:4e:32:44:00:05:01:fb:e3:fc:08:
Thats a pretty damn good sample!
Good luck,
Caylan Van Larson Unix Administrator - Systems Team Member University of North Dakota (Aerospace College) caylan@cs.und.edu 701-777-6151 (work)
_______________________________________________ syslog-ng maillist - syslog-ng@lists.balabit.hu https://lists.balabit.hu/mailman/listinfo/syslog-ng Frequently asked questions at http://www.campin.net/syslog-ng/faq.html
participants (2)
-
Caylan Van Larson
-
Dustin Trammell