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? Evan. Balazs Scheidler wrote:

that shouldn't be the case, I've never seen anything like this.

----- Original message -----

...

When I have a udp log source defined with a large so_rcvbuf the upd messages are being delayed.

It seems that the so_rcvbuf needs to fill before the data is read.

Can anyone confirm that the so_rcvbuf needs to fill prior to data being read from the port?

Evan.

______________________________________________________________________________

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