On Thu, 2005-02-03 at 11:53 +0100, Roberto Nibali wrote:

...

are you sure you want to add the condition as displayed above? that would mean that only dgram sockets will have this check, however it is more common to exceed line lengths with stream oriented sockets.

I think you wanted something like

if (!eol && closure->pos == closure->max_log_line) { werror("Message length overflow (ignored the rest)\n"); }

Please confirm, then I could add the patch.

Absolutely. I was mislead by the enclosing if (closure->dgram ...) into thinking do_read_line() only handles dgrams. If you would be so kind as to include your version of this patch, I'd be much delighted.

Added. Though the snapshot I've uploaded 5 minutes ago still does not contain it. Look for it tomorrow (clarified the message somewhat, and moved the check above the trailing NL and NUL character check) -- Bazsi

On Wed, 2005-02-02 at 17:38 +0100, Roberto Nibali wrote:

Hello,

...

As there are some changes since syslog-ng 1.6.5, I'd like to release a new version. Before doing so I'd like to ask you to test the latest snapshot a little bit.

Ok, while browsing through our internal bugzilla DB I've found another bug which is still reproduceable with the latest drop of your sources. The problem is that with a TCP reset from the receiving end of syslog-ng messages we lose one message line while syslog-ng tries to reconnect. Here is a brief instruction on how to reproduce this use case: [detailed error description removed]

I know about this problem but I'm afraid it is very difficult to solve in the 1.6.x branch, and should be solved by the new development branch. The problem is that syslog-ng polls the destination TCP sockets for writing only, and whenever the remote endpoint closes the TCP connection, it is not indicated in any way (as closing a socket triggers readability and not writability). Whenever a message is to be written to this socket, the first write() syscall succeeds, and only the next write() will return EPIPE, so syslog-ng is able to detect the broken connection. Here's the strace that shows this behaviour: The message aa4 is sent still on the old connection: read(5, "<5>Feb 3 09:42:01 bazsi: aa4\0", 2048) = 30 time(NULL) = 1107420121 time(NULL) = 1107420121 time(NULL) = 1107420121 poll([{fd=5, events=POLLIN, revents=POLLIN|POLLHUP}, {fd=4, events=POLLOUT, revents=POLLOUT}, {fd=3, events=POLLIN}], 3, 100) = 2 read(5, "", 2048) = 0 write(2, "Read EOF on fd 5.\n", 18) = 18 write(2, "Marking fd 5 for closing.\n", 26) = 26 write(4, "<5>Feb 3 09:42:01 src@bzorp bazsi: aa4\n", 40) = 40 time(NULL) = 1107420121 poll([{fd=5, events=POLLIN, revents=POLLIN|POLLHUP}, {fd=4, events=0}, {fd=3, events=POLLIN}], 3, 100) = 1 time(NULL) = 1107420121 Then I terminated netcat, and sent another message: read(5, "<5>Feb 3 09:42:05 bazsi: aa5\0", 2048) = 30 time(NULL) = 1107420125 time(NULL) = 1107420125 time(NULL) = 1107420125 poll([{fd=5, events=POLLIN, revents=POLLIN|POLLHUP}, {fd=4, events=POLLOUT, revents=POLLOUT}, {fd=3, events=POLLIN}], 3, 100) = 2 read(5, "", 2048) = 0 write(2, "Read EOF on fd 5.\n", 18) = 18 write(2, "Marking fd 5 for closing.\n", 26) = 26 write(4, "<5>Feb 3 09:42:05 src@bzorp bazsi: aa5\n", 40) = 40 time(NULL) = 1107420125 poll([{fd=5, events=POLLIN, revents=POLLIN|POLLHUP}, {fd=4, events=0, revents=POLLERR|POLLHUP}, {fd=3, events=POLLIN}], 3, 100) = 2 Even though the connection was broken the write() syscall returned success, and only the next poll() call indicates some problems. time(NULL) = 1107420125 poll([{fd=5, events=POLLIN, revents=POLLIN|POLLHUP}, {fd=4, events=0, revents=POLLERR|POLLHUP}, {fd=3, events=POLLIN}], 3, 100) = 2 write(2, "io_iter(): POLLHUP on inactive fd!\n", 35) = 35 write(2, "Marking fd 4 for closing.\n", 26) = 26 time(NULL) = 1107420125 write(2, "Closing fd 5.\n", 14) = 14 close(5) = 0 write(2, "Connection broken to AF_INET(127.0.0.1:2000), reopening in 1 seconds\n", 69) = 69 time(NULL) = 1107420125 write(2, "Closing fd 4.\n", 14) = 14 close(4) = 0 The current solution in version 1.9 is to poll the fd for reading as well as writing, so we get immediate notification when the connection is broken. The same problem could still occur, though only within a very small timeframe. -- Bazsi

On Thu, 2005-02-03 at 11:31 +0100, Roberto Nibali wrote:

...

The problem is that syslog-ng polls the destination TCP sockets for writing only,

That's the issue with poll(). Dumb question: Why not using select()?

the same, in the kernel internally both poll and select use the same interfaces, e.g. the same rules apply how they will indicate readability.

...

and whenever the remote endpoint closes the TCP connection, it is not indicated in any way (as closing a socket triggers readability and not writability). Whenever a message is to be written to this socket, the first write() syscall succeeds, and only the next write() will return EPIPE, so syslog-ng is able to detect the broken connection.

Also a signal SIGPIPE is invoked. Again, stupid question: Couldn't you use SIGPIPE to inject the write request off the remaining buffer?

I think SIGPIPE is issued at the same time write() returns EPIPE, so I think it also happens at the second write, and the kernel already acknowledged the previous message. I was curious whether this was true, but even when I disabled SIG_IGNing SIGPIPE, it did not occur for some reason. tcp(7) states that SIGPIPEs are only triggered for SO_KEEPALIVE-d sockets, I enabled SO_KEEPALIVE still no SIGPIPEs. Anyway I don't think SIGPIPE would help us here. The real problem is that the kernel returns success for the write() system call, while the connection was already broken. I hackish solution would be to buffer the last line written, and in case of failure push it back to the FIFO queue. This is ugly but could work.

The way I see syslog-ng functionally working (extremely simplified, please correct), is:

o syslog-ng polls on read_fds for incoming syslog messages o syslog-ng maintains a queue or linked list of messages where the newly arrived messages get queued up for delivery. This queue is also used in case a destination is down and needs to be reprobed (reopened) for a connection. o syslog-ng polls on write_fds for outgoing possibilities and if success, sends out in FIFO the queued messages.

yes, it is more or less correct, though the same loop is used for read/write polling.

o TCP close -> eof reaches the socket and gets passed up to syslog-ng which has already sent (write()) one line _but_ not yet lost the buffer it has written. o A new write will return EPIPE and a SIGPIPE signal.

The idea is to either pass the EPIPE back to the caller function sending the syslog message chunk or to invoke a signal handler that signals the caller to resend that message again. Or use select() to poll for readability? Or create a thread within the calling stack (same process with access to the write buffer) of the poll function and have it wait on a condition variable which is set upon EPIPE. The thread waits in pthread_cond_wait() and will write the last successfully written buffer again.

Again the solution I outlined above might be ok, though the fact that syslog-ng might coalesce outgoing TCP writes it is not very simple. [snip]

Could you point me to the code in question in 1.6.x so I could check it out for myself, please?

it is implemented in libol/src/pkt_buffer.c, packet buffers can operate in two modes packet and stream mode. packet mode makes the output routines write a single message at a time, stream mode enables write coalescing. These two modes have two independent flush functions: static int do_flush_stream(struct abstract_buffer *c, struct abstract_write *w) static int do_flush_pkt(struct abstract_buffer *c, struct abstract_write *w) Solving the first would mean to save the last coalesced buffer and push it back to the buffer in case of EPIPE, but in fact this can also introduce platform dependence, I'm not sure all IP stacks behave identically. The other option is to add reading the socket to the poll loop like it is done in 1.9.x (can be done using io_read_write instead of io_write, and drop the connection from the read callback when the socket is readable and read() returns 0 bytes.) -- Bazsi