On Sun, 2008-03-16 at 16:38 +0100, Jean-Baptiste Quenot wrote:
Hi there,
Thanks for the great syslog-ng program, it rocks.
I have a step-by-step recipe below that yields unpredictable results in the syslog output, and this worries me a bit as in my company we have similar messages sent to syslog by PHP's print_r() function. The example is simplified to a message that consists of 40 occurences of an incrementing number, with a newline separating each number. Let's call it syslog_overflow.txt:
------------------------------------------------------------------------ 0 1 2 3 ... ------------------------------------------------------------------------
Now let's send this message repeatedly using a simple Perl script. Let's call it syslog_overflow.pl:
------------------------------------------------------------------------ #!/usr/bin/perl
use Sys::Syslog qw( :DEFAULT setlogsock );
setlogsock('unix'); # First argument is program name, used for passing vhost openlog(@ARGV[0], 'cons,pid', 'user');
$log = `cat syslog_overflow.txt`;
while (1) { syslog('notice', $log); } closelog ------------------------------------------------------------------------
Run this script, and watch the syslog output, while filtering out the expected message, where newlines are converted to spaces:
tail -f /var/log/syslog | grep -v ': 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39'
You will notice unpredictable results like this:
------------------------------------------------------------------------ Mar 16 16:17:42 dockee jbq[12563]: 0 Mar 16 16:17:42 dockee 1 Mar 16 16:17:42 dockee 2 Mar 16 16:17:42 dockee 3 Mar 16 16:17:42 dockee 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 Mar 16 16:17:42 dockee jbq[12563]: 0 Mar 16 16:17:42 dockee 1 Mar 16 16:17:42 dockee 2 Mar 16 16:17:42 dockee 3 Mar 16 16:17:42 dockee 4 Mar 16 16:17:42 dockee 5 Mar 16 16:17:42 dockee 6 Mar 16 16:17:42 dockee 7 Mar 16 16:17:42 dockee 8 Mar 16 16:17:42 dockee 9 Mar 16 16:17:42 dockee 10 Mar 16 16:17:42 dockee 11 Mar 16 16:17:42 dockee 12 Mar 16 16:17:42 dockee 13 Mar 16 16:17:42 dockee 14 Mar 16 16:17:42 dockee 15 Mar 16 16:17:42 dockee 16 Mar 16 16:17:42 dockee 17 Mar 16 16:17:42 dockee 18 ------------------------------------------------------------------------
I could reproduce this behaviour easily on various hosts, with syslog-ng 2.0.0 up to 2.0.8 from a fresh git checkout. However, this problem does not appear with the legacy syslog daemon.
I'd be glad to provide more details if necessary. I tried to fiddle with the various options: log_fetch_limit, log_msg_size, with no luck. I also activated the various debugging features and had a look at logreader.c, but couldn't find anything obvious.
The only noteworthy debugging output I could get is the one below, which means the bogus lines are already present on the logreader side:
------------------------------------------------------------------------ Incoming log entry; line='<13>Mar 16 16:33:36 jbq[12638]: 0' Incoming log entry; line='1' Incoming log entry; line='2' Incoming log entry; line='3' Incoming log entry; line='4\x0a5\x0a6\x0a7\x0a8\x0a9\x0a10\x0a11\x0a12\x0a13\x0a14\x0a15\x0a16\x0a17\x0a18\x0a19\x0a20\x0a21\x0a22\x0a23\x0a24\x0a25\x0a26\x0a27\x0a28\x0a29\x0a30\x0a31\x0a32\x0a33\x0a34\x0a35\x0a36\x0a37\x0a38\x0a39\x0a' ------------------------------------------------------------------------
What driver are you using for /dev/log? unix-stream or unix-dgram? Can you check how your perl program actually _sends_ data to syslog-ng? e.g. can you strace it to check in what way does it call the send() system call? If you use unix-stream, syslog-ng will interpret NL and NUL characters as the end of message indicator, for unix-dgram NL characters can be embedded in messages and will be replaced by space in syslog-ng. Judging the debug output that you posted, I assume you are using unix-dgram (otherwise NL characters would not be included in the debugging output), in which case I guess it is perl which does it wrong. Again the strace output would help here. -- Bazsi