[syslog-ng] Unpredictable log output when message has many newlines

[Balazs Scheidler]

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