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

[Jean-Baptiste Quenot]

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
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
------------------------------------------------------------------------

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'
------------------------------------------------------------------------

Thanks in advance for your help,
-- 
Jean-Baptiste Quenot
http://caraldi.com/jbq/blog/