Mailing List Archive: some logged lines end with #000

some logged lines end with #000

Sep 13, 2007, 3:31 AM

Post #1 of 9 (2411 views)

hello,

today i merged michael biebls debian package source rsyslog_1.19.3-1
with the current upstream rsyslog-1.19.6.tar.gz.

the compilation went smooth and i installed the package on a host where
there used to by klogd/sysklogd under debian etch.

however, i noticed that now a lot of logged lines end with #000.

it used to be:
> Sep 13 09:27:02 xxx heartbeat: [2454]: info: Configuration validated. Starting heartbeat 2.1.2
> Sep 13 09:27:02 xxx heartbeat: [2455]: info: heartbeat: version 2.1.2
> Sep 13 09:27:02 xxx heartbeat: [2455]: info: Heartbeat generation: 193
> ...
> Sep 13 11:08:52 xxx apache[24790]: INFO: 11:08:52 URL:http://localhost:80/server-status [1735/1735] -> "-" [1]
> Sep 13 11:09:02 xxx apache[24872]: INFO: 11:09:02 URL:http://localhost:80/server-status [1735/1735] -> "-" [1]

it now is:
> Sep 13 12:12:30 xxx heartbeat: [5096]: info: Configuration validated. Starting heartbeat 2.1.2#000
> Sep 13 12:12:30 xxx heartbeat: [5097]: info: heartbeat: version 2.1.2#000
> Sep 13 12:12:30 xxx heartbeat: [5097]: info: Heartbeat generation: 194#000
> ...
> Sep 13 12:28:35 xxx apache[18033]: INFO: 12:28:35 URL:http://localhost:80/server-status [1728/1728] -> "-" [1]
> Sep 13 12:28:46 xxx apache[18243]: INFO: 12:28:46 URL:http://localhost:80/server-status [1727/1727] -> "-" [1]

you will find my configuration file attached.
do you have any ideas what might cause this behaviour?

cheers,
raoul bhatia
--
____________________________________________________________________
DI (FH) Raoul Bhatia M.Sc. email. r.bhatia at ipax.at
Technischer Leiter

IPAX - Aloy Bhatia Hava OEG web. http://www.ipax.at
Barawitzkagasse 10/2/2/11 email. office at ipax.at
1190 Wien tel. +43 1 3670030
FN 277995t HG Wien fax. +43 1 3670030 15
____________________________________________________________________
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: etc_default_rsyslog
Url: http://lists.adiscon.net/pipermail/rsyslog/attachments/20070913/41c0d4fb/etc_default_rsyslog.pot
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: rsyslog.conf
Url: http://lists.adiscon.net/pipermail/rsyslog/attachments/20070913/41c0d4fb/rsyslog.asc

some logged lines end with #000 [ In reply to ]

theinric at redhat

Sep 13, 2007, 6:01 AM

Post #2 of 9 (2389 views)

Permalink

Raoul Bhatia [IPAX] wrote:
> hello,
>
> today i merged michael biebls debian package source rsyslog_1.19.3-1
> with the current upstream rsyslog-1.19.6.tar.gz.
>
> the compilation went smooth and i installed the package on a host where
> there used to by klogd/sysklogd under debian etch.
>
> however, i noticed that now a lot of logged lines end with #000.
>
> it used to be:
>> Sep 13 09:27:02 xxx heartbeat: [2454]: info: Configuration validated.
>> Starting heartbeat 2.1.2
>> Sep 13 09:27:02 xxx heartbeat: [2455]: info: heartbeat: version 2.1.2
>> Sep 13 09:27:02 xxx heartbeat: [2455]: info: Heartbeat generation: 193
>> ...
>> Sep 13 11:08:52 xxx apache[24790]: INFO: 11:08:52
>> URL:http://localhost:80/server-status [1735/1735] -> "-" [1]
>> Sep 13 11:09:02 xxx apache[24872]: INFO: 11:09:02
>> URL:http://localhost:80/server-status [1735/1735] -> "-" [1]
>
> it now is:
>> Sep 13 12:12:30 xxx heartbeat: [5096]: info: Configuration validated.
>> Starting heartbeat 2.1.2#000
>> Sep 13 12:12:30 xxx heartbeat: [5097]: info: heartbeat: version 2.1.2#000
>> Sep 13 12:12:30 xxx heartbeat: [5097]: info: Heartbeat generation:
>> 194#000
>> ...
>> Sep 13 12:28:35 xxx apache[18033]: INFO: 12:28:35
>> URL:http://localhost:80/server-status [1728/1728] -> "-" [1]
>> Sep 13 12:28:46 xxx apache[18243]: INFO: 12:28:46
>> URL:http://localhost:80/server-status [1727/1727] -> "-" [1]
>
> you will find my configuration file attached.
> do you have any ideas what might cause this behaviour?
>
> cheers,
> raoul bhatia
>
>
> ------------------------------------------------------------------------
>
> # Options to rsyslogd
> # -m 0 disables 'MARK' messages.
> # -r enables logging from remote machines
> # -x disables DNS lookups on messages recieved with -r
> # See rsyslogd(8) for more details
> RSYSLOGD_OPTIONS="-m 0"
>
> # Options to rklogd
> # -2 prints all kernel oops messages twice; once for klogd to decode, and
> # once for processing with 'ksymoops'
> # -x disables all klogd processing of oops messages entirely
> # See rklogd(8) for more details
> RKLOGD_OPTIONS="-x"
>
>
>
> ------------------------------------------------------------------------
>
> # /etc/rsyslog.conf Configuration file for rsyslogd.
> #
> # For more information see
> # /usr/share/doc/rsyslog/html/rsyslog_conf.html
>
> #
> # First some standard logfiles. Log by facility.
> #
>
> auth,authpriv.* /var/log/auth.log
> *.*;auth,authpriv.none -/var/log/syslog
> #cron.* /var/log/cron.log
> daemon.* -/var/log/daemon.log
> kern.* -/var/log/kern.log
> lpr.* -/var/log/lpr.log
> mail.* -/var/log/mail.log
> user.* -/var/log/user.log
>
> #
> # Logging for the mail system. Split it up so that
> # it is easy to write scripts to parse these files.
> #
> mail.info -/var/log/mail.info
> mail.warn -/var/log/mail.warn
> mail.err /var/log/mail.err
>
> #
> # Logging for INN news system
> #
> news.crit /var/log/news/news.crit
> news.err /var/log/news/news.err
> news.notice -/var/log/news/news.notice
>
> #
> # Some `catch-all' logfiles.
> #
> *.=debug;\
> auth,authpriv.none;\
> news.none;mail.none -/var/log/debug
> *.=info;*.=notice;*.=warn;\
> auth,authpriv.none;\
> cron,daemon.none;\
> mail,news.none -/var/log/messages
>
> #
> # Emergencies are sent to everybody logged in.
> #
> *.emerg *
>
> #
> # I like to have messages displayed on the console, but only on a virtual
> # console I usually leave idle.
> #
> #daemon,mail.*;\
> # news.=crit;news.=err;news.=notice;\
> # *.=debug;*.=info;\
> # *.=notice;*.=warn /dev/tty8
>
> # The named pipe /dev/xconsole is for the `xconsole' utility. To use it,
> # you must invoke `xconsole' with the `-file' option:
> #
> # $ xconsole -file /dev/xconsole [...]
> #
> # NOTE: adjust the list below, or you'll go crazy if you have a reasonably
> # busy site..
> #
> daemon.*;mail.*;\
> news.err;\
> *.=debug;*.=info;\
> *.=notice;*.=warn |/dev/xconsole
> #
> # Include all config files in /etc/rsyslog.d/
> #
> $IncludeConfig /etc/rsyslog.d/
>
>
> ------------------------------------------------------------------------
>
> _______________________________________________
> rsyslog mailing list
> http://lists.adiscon.net/mailman/listinfo/rsyslog

Hi,

I've tinkered with this part of code recently, so it could be my fault.

But I wasn't able to reproduce it so far and a quick look through the
source didn't show anything suspicious.
Just a blind guess:
$EscapeControlCharactersOnReceive off
It will prevent control chars from being escaped but maybe the problem
will go away for now.

You have a
$IncludeConfig /etc/rsyslog.d/
in you conf file; is there any other part of configuration?

I will look deeper into this later today.

some logged lines end with #000 [ In reply to ]

rgerhards at hq

Sep 13, 2007, 6:48 AM

Post #3 of 9 (2381 views)

Permalink

I remember the #000. I think in the case that I remember, there was
actually a NUL character written by the remote system. It may also be
that a too-long message (off by one) is written in the output code.
Maybe this is even a clue to the bug we are hunting.

You can remove them by turning off control character escaping - but that
just a cosmetic fix, it doesn't fix the root issue, which we will need
to look at.

Rainer

> -----Original Message-----
> From: rsyslog-bounces at lists.adiscon.com [mailto:rsyslog-
> bounces at lists.adiscon.com] On Behalf Of Raoul Bhatia [IPAX]
> Sent: Thursday, September 13, 2007 12:32 PM
> To: rsyslog-users
> Subject: [rsyslog] some logged lines end with #000
>
> hello,
>
> today i merged michael biebls debian package source rsyslog_1.19.3-1
> with the current upstream rsyslog-1.19.6.tar.gz.
>
> the compilation went smooth and i installed the package on a host
where
> there used to by klogd/sysklogd under debian etch.
>
> however, i noticed that now a lot of logged lines end with #000.
>
> it used to be:
> > Sep 13 09:27:02 xxx heartbeat: [2454]: info: Configuration
validated.
> Starting heartbeat 2.1.2
> > Sep 13 09:27:02 xxx heartbeat: [2455]: info: heartbeat: version
2.1.2
> > Sep 13 09:27:02 xxx heartbeat: [2455]: info: Heartbeat generation:
> 193
> > ...
> > Sep 13 11:08:52 xxx apache[24790]: INFO: 11:08:52
> URL:http://localhost:80/server-status [1735/1735] -> "-" [1]
> > Sep 13 11:09:02 xxx apache[24872]: INFO: 11:09:02
> URL:http://localhost:80/server-status [1735/1735] -> "-" [1]
>
> it now is:
> > Sep 13 12:12:30 xxx heartbeat: [5096]: info: Configuration
validated.
> Starting heartbeat 2.1.2#000
> > Sep 13 12:12:30 xxx heartbeat: [5097]: info: heartbeat: version
> 2.1.2#000
> > Sep 13 12:12:30 xxx heartbeat: [5097]: info: Heartbeat generation:
> 194#000
> > ...
> > Sep 13 12:28:35 xxx apache[18033]: INFO: 12:28:35
> URL:http://localhost:80/server-status [1728/1728] -> "-" [1]
> > Sep 13 12:28:46 xxx apache[18243]: INFO: 12:28:46
> URL:http://localhost:80/server-status [1727/1727] -> "-" [1]
>
> you will find my configuration file attached.
> do you have any ideas what might cause this behaviour?
>
> cheers,
> raoul bhatia
> --
> ____________________________________________________________________
> DI (FH) Raoul Bhatia M.Sc. email. r.bhatia at ipax.at
> Technischer Leiter
>
> IPAX - Aloy Bhatia Hava OEG web. http://www.ipax.at
> Barawitzkagasse 10/2/2/11 email. office at ipax.at
> 1190 Wien tel. +43 1 3670030
> FN 277995t HG Wien fax. +43 1 3670030 15
> ____________________________________________________________________

some logged lines end with #000 [ In reply to ]

r.bhatia at ipax

Sep 13, 2007, 7:16 AM

Post #4 of 9 (2380 views)

Permalink

Rainer Gerhards wrote:
> I remember the #000. I think in the case that I remember, there was
> actually a NUL character written by the remote system. It may also be
> that a too-long message (off by one) is written in the output code.
> Maybe this is even a clue to the bug we are hunting.
>
> You can remove them by turning off control character escaping - but that
> just a cosmetic fix, it doesn't fix the root issue, which we will need
> to look at.

so then please tell me how to help :)

cheers,
raoul bhatia
--
____________________________________________________________________
DI (FH) Raoul Bhatia M.Sc. email. r.bhatia at ipax.at
Technischer Leiter

IPAX - Aloy Bhatia Hava OEG web. http://www.ipax.at
Barawitzkagasse 10/2/2/11 email. office at ipax.at
1190 Wien tel. +43 1 3670030
FN 277995t HG Wien fax. +43 1 3670030 15
____________________________________________________________________

some logged lines end with #000 [ In reply to ]

r.bhatia at ipax

Sep 13, 2007, 7:33 AM

Post #5 of 9 (2374 views)

Permalink

Tomas Heinrich wrote:
> Hi,
>
> I've tinkered with this part of code recently, so it could be my fault.
>
> But I wasn't able to reproduce it so far and a quick look through the
> source didn't show anything suspicious.
> Just a blind guess:
> $EscapeControlCharactersOnReceive off
> It will prevent control chars from being escaped but maybe the problem
> will go away for now.

this does not seem to help.

> You have a
> $IncludeConfig /etc/rsyslog.d/
> in you conf file; is there any other part of configuration?

no, there aren't any configuration files in there. see:
> root at xxx /var/log # find /etc/rsyslog.d -type f
> root at xxx /var/log #

raoul
--
____________________________________________________________________
DI (FH) Raoul Bhatia M.Sc. email. r.bhatia at ipax.at
Technischer Leiter

IPAX - Aloy Bhatia Hava OEG web. http://www.ipax.at
Barawitzkagasse 10/2/2/11 email. office at ipax.at
1190 Wien tel. +43 1 3670030
FN 277995t HG Wien fax. +43 1 3670030 15
____________________________________________________________________

some logged lines end with #000 [ In reply to ]

rgerhards at hq

Sep 13, 2007, 8:31 AM

Post #6 of 9 (2381 views)

Permalink

> -----Original Message-----
> From: rsyslog-bounces at lists.adiscon.com [mailto:rsyslog-
> bounces at lists.adiscon.com] On Behalf Of Raoul Bhatia [IPAX]
> Sent: Thursday, September 13, 2007 4:33 PM
> To: rsyslog-users
> Subject: Re: [rsyslog] some logged lines end with #000
>
> Tomas Heinrich wrote:
> > Hi,
> >
> > I've tinkered with this part of code recently, so it could be my
> fault.
> >
> > But I wasn't able to reproduce it so far and a quick look through
the
> > source didn't show anything suspicious.
> > Just a blind guess:
> > $EscapeControlCharactersOnReceive off
> > It will prevent control chars from being escaped but maybe the
> problem
> > will go away for now.
>
> this does not seem to help.

Ummm... should have thought about this. NULs are treated special. This
is routed in the sysklogd code. Rsyslog uses standard C strings for the
most part. Standard C strings are terminated as soon as the first NUL is
detected. So we can not allow NULs to be part of the message. Thus, NUL
is always escaped, no matter what the control character escape sequences
is.

Can you provide us with a debug log (rsyslogd -d -n) showing a message
with #000 being processed?

Rainer
>
> > You have a
> > $IncludeConfig /etc/rsyslog.d/
> > in you conf file; is there any other part of configuration?
>
> no, there aren't any configuration files in there. see:
> > root at xxx /var/log # find /etc/rsyslog.d -type f
> > root at xxx /var/log #
>
> raoul
> --
> ____________________________________________________________________
> DI (FH) Raoul Bhatia M.Sc. email. r.bhatia at ipax.at
> Technischer Leiter
>
> IPAX - Aloy Bhatia Hava OEG web. http://www.ipax.at
> Barawitzkagasse 10/2/2/11 email. office at ipax.at
> 1190 Wien tel. +43 1 3670030
> FN 277995t HG Wien fax. +43 1 3670030 15
> ____________________________________________________________________
> _______________________________________________
> rsyslog mailing list
> http://lists.adiscon.net/mailman/listinfo/rsyslog

some logged lines end with #000 [ In reply to ]

r.bhatia at ipax

Sep 14, 2007, 1:06 AM

Post #7 of 9 (2385 views)

Permalink

Rainer Gerhards wrote:
> Ummm... should have thought about this. NULs are treated special. This
> is routed in the sysklogd code. Rsyslog uses standard C strings for the
> most part. Standard C strings are terminated as soon as the first NUL is
> detected. So we can not allow NULs to be part of the message. Thus, NUL
> is always escaped, no matter what the control character escape sequences
> is.
>
> Can you provide us with a debug log (rsyslogd -d -n) showing a message
> with #000 being processed?

attached, you will find the output.

cheers,
raoul bhatia
--
____________________________________________________________________
DI (FH) Raoul Bhatia M.Sc. email. r.bhatia at ipax.at
Technischer Leiter

IPAX - Aloy Bhatia Hava OEG web. http://www.ipax.at
Barawitzkagasse 10/2/2/11 email. office at ipax.at
1190 Wien tel. +43 1 3670030
FN 277995t HG Wien fax. +43 1 3670030 15
____________________________________________________________________

some logged lines end with #000 [ In reply to ]

rgerhards at hq

Sep 14, 2007, 1:17 AM

Post #8 of 9 (2378 views)

Permalink

The list server is quite picky on attachment types (aka "does not accept
most of them" ;)). And I have to admit I introduced that policy and
still think it is not a bad one.

Can you send me the attachment via private mail please.

Thanks,
Rainer

> -----Original Message-----
> From: rsyslog-bounces at lists.adiscon.com [mailto:rsyslog-
> bounces at lists.adiscon.com] On Behalf Of Raoul Bhatia [IPAX]
> Sent: Friday, September 14, 2007 10:07 AM
> To: rsyslog-users
> Subject: Re: [rsyslog] some logged lines end with #000
>
> Rainer Gerhards wrote:
> > Ummm... should have thought about this. NULs are treated special.
> This
> > is routed in the sysklogd code. Rsyslog uses standard C strings for
> the
> > most part. Standard C strings are terminated as soon as the first
NUL
> is
> > detected. So we can not allow NULs to be part of the message. Thus,
> NUL
> > is always escaped, no matter what the control character escape
> sequences
> > is.
> >
> > Can you provide us with a debug log (rsyslogd -d -n) showing a
> message
> > with #000 being processed?
>
> attached, you will find the output.
>
> cheers,
> raoul bhatia
> --
> ____________________________________________________________________
> DI (FH) Raoul Bhatia M.Sc. email. r.bhatia at ipax.at
> Technischer Leiter
>
> IPAX - Aloy Bhatia Hava OEG web. http://www.ipax.at
> Barawitzkagasse 10/2/2/11 email. office at ipax.at
> 1190 Wien tel. +43 1 3670030
> FN 277995t HG Wien fax. +43 1 3670030 15
> ____________________________________________________________________

some logged lines end with #000 [ In reply to ]

rgerhards at hq

Sep 14, 2007, 2:15 AM

Post #9 of 9 (2374 views)

Permalink

I have created a new version which is currently available under the
interim name of

http://download.rsyslog.com/rsyslog/rsyslog-1.19.7.tar.gz

[***This is NOT 1.19.7 but will become it over time!***]

In that version, I have handled NULs that are emitted by faulty senders
(and there seem to be lots of them). A quick test both by me and Raoul
Bhatia indicates that those NULs disappear. And so do LF NUL (#012#000)
as the LF shown is an artifact from the NUL being then the last char of
the message).

I would now be interested to know if somebody still sees unexpected #000
at the very end of the message. If there are, they now almost for sure
identify a rsyslog problem.

Thanks,
Rainer

> -----Original Message-----
> From: rsyslog-bounces at lists.adiscon.com [mailto:rsyslog-
> bounces at lists.adiscon.com] On Behalf Of Rainer Gerhards
> Sent: Friday, September 14, 2007 10:17 AM
> To: rsyslog-users
> Subject: Re: [rsyslog] some logged lines end with #000
>
> The list server is quite picky on attachment types (aka "does not
> accept
> most of them" ;)). And I have to admit I introduced that policy and
> still think it is not a bad one.
>
> Can you send me the attachment via private mail please.
>
> Thanks,
> Rainer
>
> > -----Original Message-----
> > From: rsyslog-bounces at lists.adiscon.com [mailto:rsyslog-
> > bounces at lists.adiscon.com] On Behalf Of Raoul Bhatia [IPAX]
> > Sent: Friday, September 14, 2007 10:07 AM
> > To: rsyslog-users
> > Subject: Re: [rsyslog] some logged lines end with #000
> >
> > Rainer Gerhards wrote:
> > > Ummm... should have thought about this. NULs are treated special.
> > This
> > > is routed in the sysklogd code. Rsyslog uses standard C strings
for
> > the
> > > most part. Standard C strings are terminated as soon as the first
> NUL
> > is
> > > detected. So we can not allow NULs to be part of the message.
Thus,
> > NUL
> > > is always escaped, no matter what the control character escape
> > sequences
> > > is.
> > >
> > > Can you provide us with a debug log (rsyslogd -d -n) showing a
> > message
> > > with #000 being processed?
> >
> > attached, you will find the output.
> >
> > cheers,
> > raoul bhatia
> > --
> > ____________________________________________________________________
> > DI (FH) Raoul Bhatia M.Sc. email. r.bhatia at ipax.at
> > Technischer Leiter
> >
> > IPAX - Aloy Bhatia Hava OEG web. http://www.ipax.at
> > Barawitzkagasse 10/2/2/11 email. office at ipax.at
> > 1190 Wien tel. +43 1 3670030
> > FN 277995t HG Wien fax. +43 1 3670030 15
> > ____________________________________________________________________
>
> _______________________________________________
> rsyslog mailing list
> http://lists.adiscon.net/mailman/listinfo/rsyslog