Bug 249277 - messages that should be separate are glommed together
messages that should be separate are glommed together
Status: CLOSED WORKSFORME
Product: Fedora
Classification: Fedora
Component: rsyslog (Show other bugs)
rawhide
All Linux
low Severity low
: ---
: ---
Assigned To: Peter Vrabec
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2007-07-23 10:30 EDT by Jonathan Kamens
Modified: 2007-11-30 17:12 EST (History)
4 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2007-10-09 06:55:24 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
rsyslog.conf with template (2.26 KB, application/octet-stream)
2007-10-08 13:21 EDT, Mace Moneta
no flags Details

  None (edit)
Description Jonathan Kamens 2007-07-23 10:30:37 EDT
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@jik2.kamens.brookline.ma.us>#012From: 
root@jik2.kamens.brookline.ma.us (Cron Daemon)#012To: 
root@jik2.kamens.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.
Comment 1 Rainer Gerhards 2007-07-23 11:15:17 EDT
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.
Comment 2 Daniel Kopeček 2007-07-24 08:38:38 EDT
> 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@jik2.kamens.brookline.ma.us>#012From: 
> root@jik2.kamens.brookline.ma.us (Cron Daemon)#012To: 
> root@jik2.kamens.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)
Comment 3 Jonathan Kamens 2007-07-24 09:28:49 EDT
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.
Comment 4 Jonathan Kamens 2007-07-24 20:00:45 EDT
-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@jik2.kamens.brookline.ma.us>#012From:
root@jik2.kamens.brookline.ma.us (Cron Daemon)#012To:
root@jik2.kamens.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@ngp.big-8.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)
Comment 5 Rainer Gerhards 2007-07-25 02:47:48 EDT
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.
Comment 6 Jonathan Kamens 2007-07-25 12:11:12 EDT
Yes, those are two messages, and I didn't start having this problem until I 
replaced sysklogd with rsyslog.
Comment 7 Mace Moneta 2007-10-07 06:54:47 EDT
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

Comment 8 Tomas Heinrich 2007-10-08 07:15:00 EDT
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"
Comment 9 Mace Moneta 2007-10-08 13:21:45 EDT
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?
Comment 10 Mace Moneta 2007-10-08 13:46:45 EDT
Nevermind; my bad.  I forgot to add the "$EscapeControlCharactersOnReceive off"
in addition to the template, so there was nothing to convert to spaces.  Doh.
Comment 11 Peter Vrabec 2007-10-09 06:55:24 EDT
I'm closing this bug report, because we can't reproduce the problem.

Note You need to log in before you can comment on or make changes to this bug.