[syslog-ng] bug report

Matt Zagrabelny mzagrabe at d.umn.edu
Fri Oct 6 18:07:38 CEST 2006 

On Fri, 2006-10-06 at 11:13 +0200, Balazs Scheidler wrote:
> On Thu, 2006-09-21 at 14:29 -0500, Matt Zagrabelny wrote:
> > On Thu, 2006-09-21 at 20:53 +0200, Sandor Geller wrote:
> > > Matt Zagrabelny wrote:
> > > > does anyone on the list know the preferred way of submitting bug reports
> > > > to the developers?
> > > 
> > > Why don't you send your report to the list? 
> > 
> > just wanted to make sure the bugreport wouldnt fall on deaf ears. ;)
> > 
> > the problem has to do with using the program() destination driver
> > dropping syslog entries, or at least the program not receiving them. it
> > may very well be a problem with the program i am using, but i thought i
> > would pass it on to the experts.
> > 
> > what happens is that when the program() is executing a remote command,
> > for example via ssh, any successive input on STDIN is dropped or not
> > received or not sent or something. thus to test this phenomenon, the
> > program() must get more than one line at a time (or perhaps, at least a
> > second line before the remote program is done executing). exact timing
> > of the failure hasnt been investigated yet. the test below uses the auth
> > facilities because establishing an ssh connection sends more than one
> > message to syslog.
> 
> syslog-ng 1.6.x does not ensure that input and output flows are
> controlled, e.g. it might happen that more messages enter syslog-ng than
> it is able to send out.
> 
> If the internal log message fifo overflows (you can control its size
> using log_fifo_size) syslog-ng will start dropping messages, and it
> reports such cases in the "STATS" message it generates every once in a
> while.

i am not sure i agree...

the default setting for 'log_fifo_size' is 100, mine is set for 2048.
the log path in my problem is getting *two* lines at a time.

again, the scenario is that the *second* line is always dropped while
the destination driver's program is executing a remote command (such as
'ssh remote_ip sleep 5'). if the destination driver's program is
executing a local command (such as 'sleep 5') then the second line is
*not* dropped.

psedo-code for driver's program:
	open file handle
	while (input)
		write input to file
		ssh localhost sleep 5  << causes lines to be dropped

		sleep 5 << replace with this line causes lines not to
                           be dropped
	end

output just generated from destination driver's program:

Oct  6 08:06:31 grateful sshd[14035]: Accepted publickey for mzagrabe
from 127.0.0.1 port 56357 ssh2
Oct  6 08:06:36 grateful sshd[14049]: (pam_unix) session closed for user
mzagrabe
Oct  6 08:06:42 grateful sshd[14056]: (pam_unix) session closed for user
mzagrabe
Oct  6 08:06:47 grateful sshd[14063]: (pam_unix) session closed for user
mzagrabe
Oct  6 08:06:52 grateful sshd[14070]: (pam_unix) session closed for user
mzagrabe
Oct  6 08:06:57 grateful sshd[14077]: (pam_unix) session closed for user
mzagrabe
Oct  6 08:07:02 grateful sshd[14084]: (pam_unix) session closed for user
mzagrabe
Oct  6 08:07:07 grateful sshd[14091]: (pam_unix) session closed for user
mzagrabe
Oct  6 08:07:12 grateful sshd[14098]: (pam_unix) session closed for user
mzagrabe
Oct  6 08:07:17 grateful sshd[14105]: (pam_unix) session closed for user
mzagrabe



output from destination file:

Oct  6 08:06:31 grateful sshd[14035]: Accepted publickey for mzagrabe
from 127.0.0.1 port 56357 ssh2
Oct  6 08:06:31 grateful sshd[14040]: (pam_unix) session opened for user
mzagrabe by (uid=0)
Oct  6 08:06:31 grateful sshd[14042]: Accepted publickey for mzagrabe
from 127.0.0.1 port 56358 ssh2
Oct  6 08:06:31 grateful sshd[14049]: (pam_unix) session opened for user
mzagrabe by (uid=0)
Oct  6 08:06:36 grateful sshd[14049]: (pam_unix) session closed for user
mzagrabe
Oct  6 08:06:37 grateful sshd[14052]: Accepted publickey for mzagrabe
from 127.0.0.1 port 56359 ssh2
Oct  6 08:06:37 grateful sshd[14056]: (pam_unix) session opened for user
mzagrabe by (uid=0)
Oct  6 08:06:42 grateful sshd[14056]: (pam_unix) session closed for user
mzagrabe
Oct  6 08:06:42 grateful sshd[14059]: Accepted publickey for mzagrabe
from 127.0.0.1 port 56360 ssh2
Oct  6 08:06:42 grateful sshd[14063]: (pam_unix) session opened for user
mzagrabe by (uid=0)
Oct  6 08:06:47 grateful sshd[14063]: (pam_unix) session closed for user
mzagrabe
Oct  6 08:06:47 grateful sshd[14066]: Accepted publickey for mzagrabe
from 127.0.0.1 port 45040 ssh2
Oct  6 08:06:47 grateful sshd[14070]: (pam_unix) session opened for user
mzagrabe by (uid=0)
Oct  6 08:06:52 grateful sshd[14070]: (pam_unix) session closed for user
mzagrabe
Oct  6 08:06:52 grateful sshd[14073]: Accepted publickey for mzagrabe
from 127.0.0.1 port 45041 ssh2
Oct  6 08:06:52 grateful sshd[14077]: (pam_unix) session opened for user
mzagrabe by (uid=0)
Oct  6 08:06:57 grateful sshd[14077]: (pam_unix) session closed for user
mzagrabe
Oct  6 08:06:57 grateful sshd[14080]: Accepted publickey for mzagrabe
from 127.0.0.1 port 45042 ssh2
Oct  6 08:06:57 grateful sshd[14084]: (pam_unix) session opened for user
mzagrabe by (uid=0)
Oct  6 08:07:02 grateful sshd[14084]: (pam_unix) session closed for user
mzagrabe
Oct  6 08:07:02 grateful sshd[14087]: Accepted publickey for mzagrabe
from 127.0.0.1 port 45043 ssh2
Oct  6 08:07:02 grateful sshd[14091]: (pam_unix) session opened for user
mzagrabe by (uid=0)
Oct  6 08:07:07 grateful sshd[14091]: (pam_unix) session closed for user
mzagrabe
Oct  6 08:07:07 grateful sshd[14094]: Accepted publickey for mzagrabe
from 127.0.0.1 port 45044 ssh2
Oct  6 08:07:07 grateful sshd[14098]: (pam_unix) session opened for user
mzagrabe by (uid=0)
Oct  6 08:07:12 grateful sshd[14098]: (pam_unix) session closed for user
mzagrabe
Oct  6 08:07:12 grateful sshd[14101]: Accepted publickey for mzagrabe
from 127.0.0.1 port 45045 ssh2
Oct  6 08:07:12 grateful sshd[14105]: (pam_unix) session opened for user
mzagrabe by (uid=0)
Oct  6 08:07:14 grateful sshd[14040]: (pam_unix) session closed for user
mzagrabe
Oct  6 08:07:17 grateful sshd[14105]: (pam_unix) session closed for user
mzagrabe
Oct  6 08:07:18 grateful sshd[14109]: Accepted publickey for mzagrabe
from 127.0.0.1 port 45046 ssh2
Oct  6 08:07:18 grateful sshd[14113]: (pam_unix) session opened for user
mzagrabe by (uid=0)


> Syslog-ng 2.0.x has a solution for this problem, it can stop reading
> input messages if the output queues are full. This can be enabled on a
> per-log-statement basis, using the "flow-control" flag, like this:
> 
> log { source(src); destination(dst); flags(flow-control); };
> 
> This way, if the input channels are flow controlled (e.g. connection
> oriented sockets), syslog-ng will be able to block applications a bit
> while its output queues are flushed.
> 
> If a program destination is slow for a little while (e.g. during
> startup), the output queue will fill up quickly. In this case the only
> possibility is to stop the application. If the destination remains slow,
> the slow-down propagates back to the application, and the service
> becomes slower as a whole.
> 
> Hope this explanation helps,
> 
-- 
Matt Zagrabelny - mzagrabe at d.umn.edu - (218) 726 8844
University of Minnesota Duluth
Information Technology Systems & Services
PGP key 1024D/84E22DA2 2005-11-07
Fingerprint: 78F9 18B3 EF58 56F5 FC85  C5CA 53E7 887F 84E2 2DA2

He is not a fool who gives up what he cannot keep to gain what he cannot
lose.
-Jim Elliot
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 189 bytes
Desc: This is a digitally signed message part
Url : http://lists.balabit.hu/pipermail/syslog-ng/attachments/20061006/dbc44095/attachment.pgp

More information about the syslog-ng mailing list