[syslog-ng] logging pauses and log entry truncation

Caylan Van Larson caylan@cs.und.edu
Wed, 14 Aug 2002 10:57:22 -0500 (CDT)


> 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
>