[syslog-ng] 3.3.6 - udp sources and delayed log receipt

[Evan Rempel]

Thanks Balazs this explanation helps a lot. I now recall this discussion from an earlier thread.

Increasing flush-lines actuall causes more problems for me since my destiantion is
actually a pipe (fifo). The pipe does not buffer much data (8KB or something small like that) so a
large flush just blocks anyways.

Having increased the log_iw_size my delay is only in the order of seconds, and that might be due
to flush-lines and buffering on the sender/intermediate/destinations just resulting  in the messages
arriving out of order of the creation accross the 100's of servers. What I mean by this is that
the log lines are in order for each server, but one server may commit them to the syslog server
before/after a second server, so the time stamps from the various servers all get intermingled.

The end result now is that they time stamps are never out of order by more than a few seconds, so I don't
think it is my destination flush timings are biting me now.

We will be moving to an environment where we don't use the pipes for output any more, so this complexity will
go away in the near future.

Thanks for your explanation.

EVan.
________________________________________
From: Balazs Scheidler [bazsi77 at gmail.com]
Sent: Tuesday, October 23, 2012 11:09 AM
To: Syslog-ng users' and developers' mailing list; Evan Rempel
Subject: Re: [syslog-ng] 3.3.6 - udp sources and delayed log receipt

----- Original message -----
> Any suggestions on how I debug this?
>
> I have a tcp and a udp source (defined as separate sources) that share a
> common destination
>
> log { souce(s_udp); source(s_tcp); destination(d_file); };
>
> 90% of the log volume comes from the tcp sources.
> The udp log lines are logged 10 minutes "late". If I decrease the
> so_rcvbuf then I can get this down to 5-10 seconds "late." I can issue
> on a source udp server
>
> logger -t test "this is a test"
>
> and wait on the server. It shows up, but minutes later.
>
> OK, playing a little more, if I add the log_iw_size option on the
> udp source, the symptoms go away. Odd since I do NOT have any flow
> control in any destination.
>
> Can anyone explain why that option would make a difference?

hmmm,, with 3.3 flow control behaviour was changed a bit because of the multithreaded nature of syslog-ng. file destinations enable a mode I called soft-flow-control.

In 3.2 and earlier, syslog-ng always prioritized output over input, effectively starving all inputs as long as the outputs were busy flushing data.

The same behaviour was unfeasible with the multithreaded architecture, so I employed the flow control logic to control the input flow (that was its role after all). However people usually don't have flags(flow-control) in their configuration, removing the architectural guarantee to prioritize output over inputs would cause message loss in cases there were none before.

Therefore file destinations automatically enable soft-flow-control, which means that as long as there's an active file opened, flow control is in operation. If syslog-ng fails to open a file, or it gets suspended because of a write error (e.g. disk full) flow control is lifted again.

This way, log-iw-size() does have an effect after all, as long as you have a file destination in the log path.

The log-iw-size and log-fifo-size defaults were also increased in a number of cases, but maybe not for udp.

What may be biting you is a small window size and a busy file destination, which takes minutes to flush its buffered data (that must be busy indeed) Try increasing flush-lines for the file destination, it should increase the output bandwidth a lot.

Probably the so-rcvbuf() only decreased the amount of lost udp frames, the one delayed was probably lost before.

hope this helps.