[syslog-ng]logging pauses and log entry truncation

[Dustin Trammell]

Has anyone else experienced syslog-ng occasionally pausing for a few
minutes, immediately after logging one or more truncated entries?  It
usually pauses for anywhere from 1-10 minutes or so, and the process seems
to be fine during this time (still bound to the port, doesn't appear to be
zombied or using up all the CPU or memory, etc), then it continues after the
pause as if nothing happened.  The entry immediately after the pause is
sometimes truncated also.  The lines that are getting truncated appear to
always be kernel log entries, more specifically from iptables, so I tried
both using klogd as well as a file() source using /proc/kmsg, both with the
same results.  I saw a thread a few days ago about garbled/truncated
entries, and what I got from that thread was to set the log_msg_size()
option to something larger than the largest line your expecting.  I set mine
to 2048, and that still has not solved the problem, so I'm not sure if it's
the same issue that has been discussed in the previous thread or something
different.  Below I've listed a few log entries (gathered from tail -f
logfile), and my syslog-ng.conf file is appended below my sig.

---8<-----(snip)-----8<---
Aug 12 08:10:01 172.30.10.3 arpwatch: eth7 bogon 192.168.168.14
0:4:c0:3:a8:0
Aug 12 08:10:01 172.30.10.60 traqer: doing 10 minute stuff
Aug 12 08:10:01 172.30.10.60 kernel: fwlog output accept db IN= OUT=ipsec0
SRC=172.30.10.60 DST=172.30.10.61 LEN=60 TOS=0x00 PREC=0x00 TTL=232 ID=1196
PROTO=TCP SPT=51118 DPT=5432 WINDOW=32440 RES=0x00 CWR ECE SYN URGP=0
Aug 12 08:10:01 loghost01 fwlog input drop cleanup IN=ipsec0 OUT=
MAC=00:06:5b:84:60:7e:00:08:02:10:
(pause)
Aug 12 08:20:01 loghost01 fwlog input drop cleanup IN=ipsec0 OUT= MAC=00:06:
Aug 12 08:11:05 loghost01 stunnel[23914]: httpd connected from
172.30.8.40:47705
Aug 12 08:11:05 loghost01 stunnel[23914]: SSL_accept: Peer suddenly
disconnected
---8<-----(snip)-----8<---
Aug 12 11:01:29 172.30.10.60 pluto[3590]: "itdb" #814: ignoring Delete SA
payload
Aug 12 11:01:29 172.30.10.60 pluto[3590]: "itdb" #814: received and ignored
informational message
Aug 12 11:01:29 loghost01 fwlog input drop cleanup IN=ipsec0 OUT=
MAC=00:06:5b:84:60:7e:00:08:
Aug 12 11:01:29 loghost01 fwlog input drop cleanup IN=ipsec0 OUT= MAC=
Aug 12 11:01:29 loghost01 fwlog input drop cleanup IN=ipsec0 OUT= MAC=
(pause)
Aug 12 11:06:49 loghost01 fwlog input drop cleanup IN=ipsec0 OUT= MAC=00:06:
Aug 12 11:02:07 loghost01 snmptrapd[31633]: 209.48.214.5: Enterprise
Specific Trap (500) Uptime: 6 days, 16:43:47.00,
SNMPv2-SMI::enterprises.3224.2.1 = 40, SNMPv2-SMI::enterprises.3224.2.3 =
"ALARM: vpn \"LC*Lon-VPN\" is up. (08/12/2002 11:01:27)"
Aug 12 11:02:06 loghost01 stunnel[11455]: httpd connected from
172.30.8.40:40969
Aug 12 11:02:06 loghost01 stunnel[11455]: SSL_accept: Peer suddenly
disconnected
---8<-----(snip)-----8<---
Aug 12 11:06:49 10.10.2.200 kernel: fwlog inet accept ssl IN=eth0 OUT=eth3
SRC=195.126.219.35 DST=192.168.200.20 LEN=60 TOS=0x00 PREC=0x00 TTL=50
ID=59691 DF PROTO=TCP SPT=19846 DPT=443 WINDOW=32120 RES=0x00 SYN URGP=0
Aug 12 11:06:49 172.31.1.5 LasColinas-NS10: ALARM: vpn "LC*Lon-VPN" is up.
(08/12/2002 11:01:27)
Aug 12 11:06:49 172.30.10.3 arpwatch: eth1 bogon 172.19.1.6 0:3:fe:60:8:40
Aug 12 11:06:49 172.31.1.5 LasColinas-NS10: Can't connect to E-mail server
172.30.2.51 (08/12/2002 11:01:49)
Aug 12 11:06:49 loghost01 fwlog input drop cleanup IN=ipsec0 OUT=
MAC=00:06:5b:84:60:7e:00:08:02:10:
(pause)
Aug 12 11:08:36 loghost01 fwlog input drop cleanup IN=ipsec0 OUT= MAC=00:06:
Aug 12 11:08:07 loghost01 stunnel[24185]: httpd connected from
172.30.8.40:60549
Aug 12 11:08:07 loghost01 stunnel[24185]: SSL_accept: Peer suddenly
disconnected
---8<-----(snip)-----8<---
Aug 12 11:16:13 172.31.1.5 LasColinas-NS10: NetScreen Traffic Log:
device_id=LasColinas-NS10 start_time="08/12/2002 11:09:21" src=172.30.8.76
dst=172.31.1.5 service=icmp proto=1 policy_id=18 direction=incoming
duration=1 sent=96 rcvd=96 action=Tunnel (LC*Dal-VPN) icmp type=8
Aug 12 11:20:01 loghost01 fwlog input drop cleanup IN=ipsec0 OUT=
Aug 12 11:11:04 loghost01 tac_plus[9564]: Read -1 bytes from 172.30.8.40 ,
expecting 12
(pause)
Aug 12 11:20:01 loghost01 MAC=00:06:5b:84:60:7e:00:08:02:10:cb:a4:08:00
SRC=172.30.10.61 DST=172.30.8.40 LEN=275 TOS=0x00 PREC=0x00 TTL=134 ID=4745
DF PROTO=UDP SPT=514 DPT=514 LEN=255
Aug 12 11:20:01 172.31.1.5 LasColinas-NS10: NetScreen Traffic Log:
device_id=LasColinas-NS10 start_time="08/12/2002 11:09:20" src=172.30.8.5
dst=172.31.1.5 service=icmp proto=1 policy_id=18 direction=incoming
duration=1 sent=112 rcvd=112 action=Tunnel (LC*Dal-VPN) icmp type=8
---8<-----(snip)-----8<---

If anyone has experienced this or has any other ideas that I may not have
tried yet, any info you can provide would be most appreciated.

Thanks,

---
Dustin D. Trammell
Information Security Specialist
Penson Financial Services, Inc.



### Syslog-NG Config File

# Global Options
options {
  chain_hostnames(no);
  use_dns(no);
  log_fifo_size(2000);
  log_msg_size(2048);
  sync(0);
};

# Source Objects
source s_local { internal(); };
source s_kmsg { file("/proc/kmsg"); };
source s_devlog { unix-stream("/dev/log" max-connections(150)); };
source s_udp514 { udp(); };
source s_tcp514 { tcp(ip("127.0.0.1") max-connections(150) keep-alive(yes));
};
source s_kernel { file("/proc/kmsg"); };

# Destination Objects
destination d_varlog { file("/var/log/log"); };
destination d_tty8 { pipe("/dev/tty8"); };
destination d_logresp { pipe("/usr/local/logrespond/fifo/log"
owner(logrespond) group(root) perm(0600) ); };
destination d_logtraq { pipe("/usr/local/logtraq/logpipe" owner(root)
group(logtraq) perm(0640) ); };

# Log Paths
log {
  source(s_local); source(s_kmsg); source(s_devlog); source(s_udp514);
source(s_tcp514); source(s_kernel);
  destination(d_varlog); destination(d_tty8); destination(d_logresp);
destination(d_logtraq);
};