[syslog-ng] missing logs when SIGHUP

[Martin Ervius]

Hi,

It seems that sometimes when syslog-ng receives a SIGHUP (like for example
after logrotating or config change) it loses track of the logs that has been
received, but are not yet written to disk. Except for this problem,
syslog-ng can receive ~35000 logs/sec on the same machine without any loss
at all.

I have been able to reproduce the situation in a test environment on both
FreeBSD 6.1 (Opteron) with syslog-ng 2.0.3 and on Ubuntu Linux 7.10 (i386)
with syslog-ng 2.0.5. On linux, it appears that the number of logs lost
equals the size of the log_fetch_limit parameter, because the number of lost
logs are in multiples of this value.

To see what happens I used strace to follow syslog-ng and dump read and
write calls while sending numbered logs at a rate of 1000/sec. Only one
machine was sending logs and they were transferred from a different machine
over tcp. During this time I sent a SIGHUP to the receiving syslog with two
seconds apart (since it doesn't occur with every SIGHUP). log_fetch_limit is
set to 100, log_fifo_size to 51200 and log_msg_size is 2048. Flow-control is
not activated since it didn't appear to make any difference in this
particular case.


This is the output of 'strace -s 65536 -e write,read' with the irrelevant
parts omitted (I captured a similar output on FreeBSD with ktrace, but is
not included in this mail)

## read from tcp socket (only beginning and end to save space)
read(5, "<135>Nov 27 18:36:34 tiger logger: hejsan 9388\n<135>Nov 27
18:36:34 tiger logger: hejsan 9389\n<135>Nov 27 18:36:34 tiger logger:
hejsan 9390\n<135>Nov 27 18:36:34 tiger logger: hejsan 9391\n<135>Nov 27
18:36:34 tiger logger: hejsan 9392\n<135>Nov 27 18:36:34 tiger logger:
hejsan 9393\n<135>Nov 27 18:36:34 tiger logger: hejsan 9394\n<135>Nov 27
18:36:34 tiger logger: hejsan 9395\n<135>Nov 27 18:36:34 tiger logger:
hejsan 9396\n<135>Nov 27 18:36:34 tiger logger: hejsan 9397\n<135>Nov 27
18:36:34 tiger logger: hejsan 9398\n<135>Nov 27 18:36:34 tiger logger:
hejsan 9399\n<135>Nov 27 18:36:34 tiger logger: hejsan 9400\n<135>Nov 27
18:36:34 tiger logger: hejsan 9401\n<135>Nov 27 18:36:34 tiger logger:
hejsan 9402\n<135>Nov 27 18:36:34 tiger logger: hejsan 9403\n<135>Nov 27
18:36:34 tiger logger: hejsan 9404\n<135>Nov 27 18:36:34 tiger logger:
hejsan 9405\n<135>Nov 27 18:36:34 tiger logger: hejsan 9406\n<135>Nov 27
18:36:34 tiger logger: hejsan 9407\n<135>Nov 27 18:36:34 tiger logger:
hejsan 9408\n<135>Nov 27 18:36:34 tiger logger: hejsan 9409\n<135>Nov 27
18:36:34 tiger logger: hejsan 9410\n
. . .
<135>Nov 27 18:36:34 tiger logger: hejsan 9504\n<135>Nov 27 18:36:34 tiger
logger: hejsan 9505\n<135>Nov 27 18:36:3
4 tiger logger: hejsan 9506\n<135>Nov 27 18:36:34 tiger logger: hejsan
9507\n<135>Nov 27 18:36:34 tiger logger: hej
", 8192) = 5678

## then follows all the writes until a SIGHUP is received
...
write(6, "Nov 27 18:36:34 tiger logger: hejsan 9401\n", 42) = 42
write(6, "Nov 27 18:36:34 tiger logger: hejsan 9402\n", 42) = 42
write(6, "Nov 27 18:36:34 tiger logger: hejsan 9403\n", 42) = 42
write(6, "Nov 27 18:36:34 tiger logger: hejsan 9404\n", 42) = 42
write(6, "Nov 27 18:36:34 tiger logger: hejsan 9405\n", 42) = 42
write(6, "Nov 27 18:36:34 tiger logger: hejsan 9406\n", 42) = 42
write(6, "Nov 27 18:36:34 tiger logger: hejsan 9407\n", 42) = 42
write(6, "Nov 27 18:36:34 tiger logger: hejsan 9408\n", 42) = 42
--- SIGHUP (Hangup) @ 0 (0) ---


## After the config file is re-read, syslog-ng continues to read new logs
from the socket, with unwritten logs from 9409 to 9507 in the buffer (9508
is partly read before the SIGHUP)
read(5, "san 9508\n<135>Nov 27 18:36:34 tiger logger: hejsan 9509\n<135>Nov
27 18:36:34 tiger logger: hejsan 9510\n<135>Nov 27 18:36:34 tiger logger:
hejsan 9511\n<135>Nov 27 18:36:34 tiger logger: hejsan 9512\n<135>Nov 27
18:36:34 tiger logger: hejsan 9513\n<135>Nov 27 18:36:34 tiger logger:
hejsan 9514\n<135>Nov 27 18:36:34 tiger logger: hejsan 9515\n....


## And finally new writes are done, but starting at 9508. The logs ranging
from 9409 to 9507 are now lost and are consequently missing in the
destination file.
write(4, "Nov 27 18:36:34 tiger logger: hejsan 9508\n", 42) = 42
write(4, "Nov 27 18:36:34 tiger logger: hejsan 9509\n", 42) = 42
write(4, "Nov 27 18:36:34 tiger logger: hejsan 9510\n", 42) = 42
write(4, "Nov 27 18:36:34 tiger logger: hejsan 9511\n", 42) = 42

-----------------------------------------------------------------------------------------


I have experimented with different parameter settings, but am still losing
logs at SIGHUP. I hope this information is enough if someone is able to
diagnose the issue. If not, I can send my particular config etc on request.
Any input on this is appreciated, has anyone else noticed this behaviour or
is it maybe a configuration issue with this setup?


// Martin
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.balabit.hu/pipermail/syslog-ng/attachments/20071130/5aae3a52/attachment.htm