Bug 249277

I have tried to reproduce it, but to no avail. Seems not to be related to the
message size. My best guess currently is that it is actually one message in
which LF is used as a message delimiter. Is that possible? Could you run
rsyslogd interactively in debug mode (add -d -n to options) and post/mail me the
outcome. I am interested in the debug output when such a message comes in.

> I see messages like this in my /var/log/maillog:(In reply to comment #0)
> I have rsyslog-1.17.0-1.fc8.
> 
> I see messages like this in my /var/log/maillog:
> 
> Jul 22 15:38:01 jik2 bogofilter-milter.pl[2689]: DEBUG: my_eom_callback: 
> entering with $hash = {'msg' => 'Received: (from root@localhost)#012#011by 
> jik2.kamens.brookline.ma.us (8.14.1/8.14.1/Submit) id 
> l6MJc1xj010149;#012#011Sun, 22 Jul 2007 15:38:01 -0400#012Date: Sun, 22 Jul 
> 2007 15:38:01 -0400#012Message-Id: 
> <200707221938.l6MJc1xj010149.brookline.ma.us>#012From: 
> root.brookline.ma.us (Cron Daemon)#012To: 
> root.brookline.ma.us#012Subject: Cron 
> <root@jik2> /home/jik/scripts/logwatch.pl --stamp-file /var/log/logwatch.time --
> rotate-logs --link-full /var/log/logwatch.log#012Content-Type: text/plain; 
> charset=UTF-8#012Auto-Submitted: auto-generated#012X-Cron-Env: 
> <BACKUP_LEVEL=3>#012X-Cron-Env: <SHELL=/bin/sh>#012X-Cron-Env: 
> <HOME=/root>#012X-Cron-Env: <PATH=/usr/bin:/bin>#012X-Cron-Env: 
> <LOGNAME=root>#012X-Cron-Env: <USER=root>#012#012Count#011Message#015#012-----
> #011-------#015#0121#011sendmail: l6MJbvYO010132: 122-116-17-
> 133.dynamic.hinet.net [122.116.17.133]: probable open proxy: command=GET 
> http://www.scanproxy.com:80/px_judge#015#012#015#012file:///tmp/P89ifRp7iy.txt#0
> 15#012','rcpt' => 'root'};#012#000
> 
> This is actually two different log messages inappropriately concatenated 
> together.  The text near the end starting with "sendmail: 16M..." should have 
> been its own message.
> 
> It seems likely to me that this has something to do with very long messages, 
> given the length of the first message shown above.  If a message is too long, 
> it should be truncated, rather than the next message being glommed onto it.

Could you please attach your original /var/log/maillog here? (If it isn't a
privacy/security issue)

It's way too big to attach.  I will try to reproduce the issue with -d -n and 
let you know what I find out.

-1208813888: 
Successful select, descriptor count = 1, Activity on: 3 
-1208813888: Message from UNIX socket: #3
-1208813888: Message length: 978, File descriptor: 3.
-1208813888: logmsg: mail.debug<23>, flags 2, from 'jik2', msg Jul 24 16:40:02
bogofilter-milter.pl[31951]: DEBUG: my_eom_callback: entering with $hash =
{'msg' => 'Received: (from root@localhost)#012#011by jik2.kamens.brookline.ma.us
(8.14.1/8.14.1/Submit) id l6OKe2eP031250;#012#011Tue, 24 Jul 2007 16:40:02
-0400#012Date: Tue, 24 Jul 2007 16:40:02 -0400#012Message-Id:
<200707242040.l6OKe2eP031250.brookline.ma.us>#012From:
root.brookline.ma.us (Cron Daemon)#012To:
root.brookline.ma.us#012Subject: Cron <root@jik2>
/home/jik/scripts/logwatch.pl --stamp-file /var/log/logwatch.time --rotate-logs
--link-full /var/log/logwatch.log#012Content-Type: text/plain;
charset=UTF-8#012Auto-Submitted: auto-generated#012X-Cron-Env:
<BACKUP_LEVEL=3>#012X-Cron-Env: <SHELL=/bin/sh>#012X-Cron-Env:
<HOME=/root>#012X-Cron-Env: <PATH=/usr/bin:/bin>#012X-Cron-Env:
<LOGNAME=root>#012X-Cron-Env:
<USER=root>#012#012Count#011Message#015#012-----#011-------#015#0121#011sendmail:
l6OKdOtB031100: <teamngp-board.org>... User
unknown#015#012#015#012file:///tmp/a1Vq3BrpS8.txt#015#012','rcpt' =>
'root'};#012#000
-1208813888: Message has legacy syslog format.
-1208813888: EnqueueMsg signaled condition (0)
-1208816752: Lone worker is running...
-1208816752: Called fprintlog, logging to FILE-1208813888: -1208816752: 
(/var/log/maillog)

If that "sendmail: 16..." is the second message, then we have a problem. The
whole thing is emitted as a single message from the log source. I can check if
sysklogd has some special handling, but I would like a confirmation first that
these are two messages.

Yes, those are two messages, and I didn't start having this problem until I 
replaced sysklogd with rsyslog.

I'm seeing a similar issue, but occurring within a given message.  The '#nnn'
strings are displayed by syslogd as whitespace in these messages. Some examples:

dbus: Can't send to audit system: USER_AVC avc:  received setenforce notice
(enforcing=1)#012: exe="/bin/dbus-daemon" (sauid=503, hostname=?, addr=?,
terminal=?)

Updated: rsyslog.x86_64 1.19.6-3.fc8#000

DHCP Discover   #015
DHCP Request   68.192.12.60#015
DHCP Request success   68.192.12.60#015

To prevent control characters being converted to the "#xyz" form, add
$EscapeControlCharactersOnReceive off
to your configuration file, but then you'll have them in your log. syslog doesn't do 
anything extra except for replacing '\n' with ' '. You can replace or drop them using 
a template like this:
$template TraditionalFormat,"%timegenerated% %HOSTNAME% %syslogtag%%msg:::space-cc%\n"

Created attachment 219911 [details]
rsyslog.conf with template

The template would have been an ideal solution, but it appears that the
space-cc function does nothing.  I used the attached rsyslog.conf and generated
a test message using:

$ msg="a^Hb"
$ echo $msg
b
$ logger "$msg"

The log contains:

Oct  8 13:20:32 mmouse logger: a#010b

Should this be opened as a separate bug or did I make an error in the
specification?

Nevermind; my bad.  I forgot to add the "$EscapeControlCharactersOnReceive off"
in addition to the template, so there was nothing to convert to spaces.  Doh.

I'm closing this bug report, because we can't reproduce the problem.