[syslog-ng] syslog 2.0.8 lost some messages

[Balazs Scheidler]

On Tue, 2008-11-04 at 11:47 -0800, Evan Rempel wrote:
> First, were there any changes to the buffer/reopen code in
> 2.0.9 that may fix "lost" messages.
> 
> My host turtle lost connection to the syslog server, and
> upon regaining connection did not send all (any?) of the buffered messages.
> 
> This is only the syslog-ng stats messages, there were lots of other message that
> didn't "make it" to the server, but I wanted to show the problem with the smallest number,
> AND show that syslog-ng did NOT report that it dropped any messages.
> 
> -------------------------------
> Client (turtle)
> 
> 2008-11-03T15:39:49-08:00 local at turtle.comp.uvic.ca syslog.info syslog-ng[3232]: Log statistics; 
> dropped='tcp(AF_INET(142.104.5.206:514))=0', dropped='tcp(AF_INET(142.104.246.92:514))=0'
> 
> 2008-11-03T15:49:49-08:00 local at turtle.comp.uvic.ca syslog.info syslog-ng[3232]: Log statistics; 
> dropped='tcp(AF_INET(142.104.5.206:514))=0', dropped='tcp(AF_INET(142.104.246.92:514))=0'
> 
> 2008-11-03T15:55:15-08:00 local at turtle.comp.uvic.ca syslog.err syslog-ng[3232]: EOF occurred while idle; fd='7'
> 
> 2008-11-03T15:55:15-08:00 local at turtle.comp.uvic.ca syslog.err syslog-ng[3232]: Connection broken; time_reopen='5'
> 
> 2008-11-03T15:59:49-08:00 local at turtle.comp.uvic.ca syslog.info syslog-ng[3232]: Log statistics; 
> dropped='tcp(AF_INET(142.104.5.206:514))=0', dropped='tcp(AF_INET(142.104.246.92:514))=0'
> 
> 2008-11-03T16:09:49-08:00 local at turtle.comp.uvic.ca syslog.info syslog-ng[3232]: Log statistics; 
> dropped='tcp(AF_INET(142.104.5.206:514))=0', dropped='tcp(AF_INET(142.104.246.92:514))=0'
> 
> -----------------
> On the syslog server
> 
> 2008-11-03T15:39:49-08:00 local at turtle.comp.uvic.ca/turtle.comp.uvic.ca syslog.info syslog-ng[3232]: Log statistics; 
> dropped='tcp(AF_INET(142.104.5.206:514))=0', dropped='tcp(AF_INET(142.104.246.92:514))=0'
> 
> 2008-11-03T15:55:15-08:00 local at turtle.comp.uvic.ca/turtle.comp.uvic.ca syslog.err syslog-ng[3232]: EOF occurred while 
> idle; fd='7'
> 
> 2008-11-03T15:55:15-08:00 local at turtle.comp.uvic.ca/turtle.comp.uvic.ca syslog.err syslog-ng[3232]: Connection broken; 
> time_reopen='5'
> 
> 2008-11-03T15:59:49-08:00 local at turtle.comp.uvic.ca/turtle.comp.uvic.ca syslog.info syslog-ng[3232]: Log statistics; 
> dropped='tcp(AF_INET(142.104.5.206:514))=0', dropped='tcp(AF_INET(142.104.246.92:514))=0'
> 
> 2008-11-03T16:09:49-08:00 local at turtle.comp.uvic.ca/turtle.comp.uvic.ca syslog.info syslog-ng[3232]: Log statistics; 
> dropped='tcp(AF_INET(142.104.5.206:514))=0', dropped='tcp(AF_INET(142.104.246.92:514))=0'
> 
> ------------------------------
> The message with time stamp of 2008-11-03T15:49:49-08:00 did not get recorded at the server.
> 
> The EOF actually occurred due to a reload of the iptables, which then started blocking responses from the
> syslog server (142.104.246.92) until the connection was reopened by the client (142.104.5.223).
> 
> 2008-11-03T15:31:17-08:00 local at turtle.comp.uvic.ca local7.notice iptables:  succeeded
> 
> 2008-11-03T15:39:50-08:00 local at turtle.comp.uvic.ca kern.warning kernel: iptables: IN=eth0 OUT= 
> MAC=00:09:6b:89:ca:ec:00:0a:42:cb:84:00:08:00 SRC=142.104.246.92 DST=142.104.5.223 LEN=52 TOS=0x00 PREC=0x00 TTL=61 
> ID=23252 DF PROTO=TCP SPT=514 DPT=55411
>   WINDOW=350 RES=0x00 ACK URGP=0
> 
> ... 14 other packets dropped
> 
> 2008-11-03T15:53:15-08:00 local at turtle.comp.uvic.ca kern.warning kernel: iptables: IN=eth0 OUT= 
> MAC=00:09:6b:89:ca:ec:00:0a:42:cb:84:00:08:00 SRC=142.104.246.92 DST=142.104.5.223 LEN=64 TOS=0x00 PREC=0x00 TTL=61 
> ID=23282 DF PROTO=TCP SPT=514 DPT=55411
>   WINDOW=350 RES=0x00 ACK URGP=0

This problem has been known for some time: the lack of application layer
acknowledgements. The problem is that the only possible solution is to
change the syslog protocol, and no, the latest IETF drafts don't solve
this issue either.

The problem is that syslog-ng assumes that a given chunk of data is
sent, when it invokes the send() system call, but some cases the data
sent might still be sitting in the socket output buffer. But syslog-ng
did not get an error code to react on.

As I said, if I invented some kind of app layer acknowledgement and the
receiver would ACK back received data, it'd be possible to detect which
messages made it to the server. The core infrastructure to support this
is already implemented in the 3.0 branch, only the protocol part is
missing.

what this means, that with the current infrastructure, connection breaks
will probably result in message loss. if the connection is broken
actively (e.g. the receiver properly closes the channel), then syslog-ng
will notice this, but this only means that the window of opportunity is
smaller.

-- 
Bazsi