[syslog-ng] Fail safe test for syslog-ng

[Balazs Scheidler]

On Thu, 2008-01-17 at 17:27 +0200, dstuxo wrote:
> Since I made some changes to the config since then, just to be sure, I 
> attached another 3 strace logs with
> corresponding config file.
> 
> I can see some delay for each test...
> 
> * The script used for testing:
> #!/bin/sh
> 
> for i in `seq 1 10000`;
>  do
>    echo "THIS IS A TEST MESSAGE $i"
>    logger -t tester -p cron.info "THIS IS A TEST MESSAGE $i"
>  done
> #eof
> 

I've checked the strace dumps that you posted, and I see nothing out of
the ordinary here. For example:

first three test messages in test_1.txt:

14:41:09.227599 read(6, "<78>Jan 17 14:41:09 tester: THIS IS A TEST MESSAGE 1\0", 8192) = 53 <0.000012>
14:41:09.228875 write(10, "Jan 17 14:41:09 localhost tester: THIS IS A TEST MESSAGE 1\n", 59) = 59 <0.000017>
14:41:09.229576 read(9, "<78>Jan 17 14:41:09 tester: THIS IS A TEST MESSAGE 2\0", 8192) = 53 <0.000010>
14:41:09.230433 write(10, "Jan 17 14:41:09 localhost tester: THIS IS A TEST MESSAGE 2\n", 59) = 59 <0.000011>
14:41:09.231096 read(6, "<78>Jan 17 14:41:09 tester: THIS IS A TEST MESSAGE 3\0", 8192) = 53 <0.000010>
14:41:09.231924 write(10, "Jan 17 14:41:09 localhost tester: THIS IS A TEST MESSAGE 3\n", 59) = 59 <0.000011>

test_2.txt:

14:48:06.211659 read(6, "<78>Jan 17 14:48:06 tester: THIS IS A TEST MESSAGE 1\0", 8192) = 53 <0.000011>
14:48:06.212941 write(8, "Jan 17 14:48:06 localhost tester: THIS IS A TEST MESSAGE 1\n", 59) = 59 <0.001210>
14:48:06.214877 read(7, "<78>Jan 17 14:48:06 tester: THIS IS A TEST MESSAGE 2\0", 8192) = 53 <0.000011>
14:48:06.215676 write(8, "Jan 17 14:48:06 localhost tester: THIS IS A TEST MESSAGE 2\n", 59) = 59 <0.000013>
14:48:06.216339 read(6, "<78>Jan 17 14:48:06 tester: THIS IS A TEST MESSAGE 3\0", 8192) = 53 <0.000010>
14:48:06.217114 write(8, "Jan 17 14:48:06 localhost tester: THIS IS A TEST MESSAGE 3\n", 59) = 59 <0.000011>
14:48:06.217798 read(7, "<78>Jan 17 14:48:06 tester: THIS IS A TEST MESSAGE 4\0", 8192) = 53 <0.000010>
14:48:06.218596 write(8, "Jan 17 14:48:06 localhost tester: THIS IS A TEST MESSAGE 4\n", 59) = 59 <0.000011>

test_3.txt:

14:54:19.460453 read(8, "<78>Jan 17 14:54:19 tester: THIS IS A TEST MESSAGE 1\0", 8192) = 53 <0.000011>
14:54:19.460891 read(8, 0x8079138, 8192) = -1 EAGAIN (Resource temporarily unavailable) <0.000008>
14:54:19.461267 write(9, "Jan 17 14:54:19 localhost tester: THIS IS A TEST MESSAGE 1\n", 59) = 59 <0.000016>
14:54:19.463589 read(8, "<78>Jan 17 14:54:19 tester: THIS IS A TEST MESSAGE 2\0", 8192) = 53 <0.000009>
14:54:19.464037 read(8, 0x8079138, 8192) = -1 EAGAIN (Resource temporarily unavailable) <0.000009>
14:54:19.464409 write(9, "Jan 17 14:54:19 localhost tester: THIS IS A TEST MESSAGE 2\n", 59) = 59 <0.000013>
14:54:19.466650 read(8, "<78>Jan 17 14:54:19 tester: THIS IS A TEST MESSAGE 3\0", 8192) = 53 <0.000010>
14:54:19.467075 read(8, 0x8079138, 8192) = -1 EAGAIN (Resource temporarily unavailable) <0.000008>
14:54:19.467447 write(9, "Jan 17 14:54:19 localhost tester: THIS IS A TEST MESSAGE 3\n", 59) = 59 <0.000014>


The latency between the read and the accompanying write system call is 
about 0.001sec. If syslog-ng issues the write system call, then it is 
up to the kernel and the disks to get it written.

You can ask syslog-ng to issue an fsync on the file(), but as you mention, 
that seriously degrades performance.

Or was I missing something? syslog-ng received the message and wrote it 
to a destination file within a couple of msecs. If you turn off power 
after 2-3 seconds, and the message is lost, it is probably not syslog-ng's 
fault.

-- 
Bazsi