SysLogHandler message formatting

  • Thread starter Dustin C. Hatch
  • Start date
D

Dustin C. Hatch

I have a daemon that uses the built-in SysLogHandler logging handler
class to log messages to the host's syslog. Unfortunately, I am having
trouble getting it to work with Metalog[1]. At first, I thought the
problem was Metalog's fault because everything works as expected with
syslog-ng. Upon further investigation, I have come to the conclusion
that the SysLogHandler may be sending invalid syslog messages. When I
disabled all filtering in Metalog, my messages started appearing in
Metalog's output logs, but they were displayed inappropriately.
Namely, the entire message was appearing where the program name should
appear. Entries in the output file generally look like this:

%b %d %H:%M:%S [%(ident)s] %(message)s

For example, here is an entry from sshd:

Oct 06 12:19:45 [sshd] Connection from 127.0.0.1 port 34142

In contrast, here is the entry generated by my program:

Oct 06 11:41:05 [INFO Started an Idler for sysattend on
mail.gosupertechs.com] 993 using SSL

Here is the snippet of code I am using to set up the logger:

root_logger = logging.getLogger()
root_logger.setLevel(config.get_value("log_level"))
syslog_hdlr = SysLogHandler(address='/dev/log',
facility=SysLogHandler.LOG_DAEMON)
syslog_hdlr.setLevel(logging.DEBUG)
formatter = logging.Formatter('%(name)s: %(levelname)s %
(message)s')
syslog_hdlr.setFormatter(formatter)
root_logger.addHandler(syslog_hdlr)

logger = logging.getLogger("imapcd.daemon")
logger.debug('test')

I believe that the issue is LogRecords formatted using the Formatter
class, but are not modified into a valid syslog message. I set up a
fake syslog daemon that just listened on /dev/log and echoed
everything it received to the console. When my program logs a message,
it comes through like thist:

<31>imapcd.daemon: DEBUG test

which is exactly how the Formatter formatted the message. Other
programs that log to syslog, on the other hand, send messages that
look like this:

<149>Oct 6 11:17:19 sudo: dhatch : TTY=pts/7 ; PWD=/home/dhatch ;
USER=root ; COMMAND=/usr/bin/whoami

If I adjust the Formatter definition to mimic that, like so:

formatter = logging.Formatter('%(asctime)s %(name)s: %(levelname)s
%(message)s', '%b %e %H:%M:%S')

then all works well.

My question, therefore, is where does this problem lie? Is it a bug in
Metalog that it doesn't properly parse the message, or is it a bug in
SysLogHandler that it doesn't properly format it? I guess it could
also be that if one wants to use the SysLogHandler, then that
particular format string must be used to ensure compatibility with all
syslog daemons. I found a couple of examples[2][3] of people
describing the usage of SysLogHandler, but none of them mention a
problem with formatting.

Any thoughts or suggestions would be appreciated. I will patch my
program to use the latter format string for now, but I would still
like to find the root cause for this problem.

Regards,
Dustin C. Hatch

[1] http://metalog.sourceforge.net/
[2] http://scottbarnham.com/blog/2008/01/01/sysloghandler-not-writing-to-syslog-with-python-logging/
[3] http://www.mechanicalcat.net/richard/log/Python/Simple_usage_of_Python_s_logging_module
 
V

Vinay Sajip

My question, therefore, is where does this problem lie? Is it a bug in
Metalog that it doesn't properly parse the message, or is it a bug in
SysLogHandler that it doesn't properly format it? I guess it could
also be that if one wants to use the SysLogHandler, then that
particular format string must be used to ensure compatibility with all
syslog daemons. I found a couple of examples[2][3] of people

Hi Dustin,

Thanks for the detailed report. I tried posting a response a couple of times,
but Google appears to have swallowed it ... trying again. Sorry if it results in
multiple responses.

The SysLogHandler aims to work within RFC 5424, though that does provide for
some flexibility in message formats. The SysLogHandler sends <priority>formatted
message, as you've observed, with the "formatted message" part encoded in UTF-8
with a prepended BOM if it's Unicode.

The existing SysLogHandler code seems to work OK with syslog, syslog-ng and
rsyslog - perhaps these are more forgiving than Metalog in the way they parse
messages, or perhaps it's a Metalog configuration issue. I'd try posting this
issue to the Metalog forum / mailing list to see what feedback they can give. If
you do think it's a bug in SysLogHandler then please create an issue on
bugs.python.org and assign it to me, so I can take a look at it; however, I
think using an appropriate Formatter will ensure interoperability in any
particular scenario. I don't especially want to hard-code any format into
SysLogHandler, since a Formatter can be used to set the format flexibly.

Regards,

Vinay Sajip
 
D

Dustin C. Hatch

Thanks for the detailed report. I tried posting a response a couple of times,
but Google appears to have swallowed it ... trying again. Sorry if it results in
multiple responses.
Hmm, I too seem to be experiencing this problem...
The SysLogHandler aims to work within RFC 5424, though that does provide for
some flexibility in message formats. The SysLogHandler sends <priority>formatted
message, as you've observed, with the "formatted message" part encoded in UTF-8
with a prepended BOM if it's Unicode.
I started to read RFC 5424 yesterday before posting this, but it
seemed to describe a much more complex message format than
SysLogHandler was producing, so I wasn't sure if that was the
reference or not. I may go back and read it completely, now that I
know, though.
The existing SysLogHandler code seems to work OK with syslog, syslog-ng and
rsyslog
I agree with this, so I would normally assume that Metalog is the
problem and simply stop using it. Unfortunately, I have several
systems that use Metalog, and I don't want to introduce any
inconsistencies by having one use something else. Switching them all
would also be a hassle.
- perhaps these are more forgiving than Metalog in the way they parse
messages, or perhaps it's a Metalog configuration issue. I'd try posting this
issue to the Metalog forum / mailing list to see what feedback they can give.
I will do that; I just wanted to see what the Python stance was first.
I will keep you apprised of anything determined through that route.
If you do think it's a bug in SysLogHandler then please create an issue on
bugs.python.org and assign it to me, so I can take a look at it
After I communicate with the Metalog community, I will definitely file
an issue if necessary. I didn't want to jump the gun, though.
I think using an appropriate Formatter will ensure interoperability in any
particular scenario. I don't especially want to hard-code any format into
SysLogHandler, since a Formatter can be used to set the format flexibly.
I think the only problem with doing it that way is that I wasn't
initially aware that using a Formatter affected how the message is
sent to Syslog, but assumed it only modified the visible portion. I
will admit that, until yesterday, I knew nothing of the syslog
protocol. Perhaps the best solution would be to simply document the
fact that adjusting the message format can affect how the message is
parsed by the syslog daemon receiving it.

Thank you for your feedback.
 
D

Dustin C. Hatch

Thanks for the detailed report. I tried posting a response a couple of times,
but Google appears to have swallowed it ... trying again. Sorry if it results in
multiple responses.
Hmm, I too seem to be experiencing this problem...
The SysLogHandler aims to work within RFC 5424, though that does provide for
some flexibility in message formats. The SysLogHandler sends <priority>formatted
message, as you've observed, with the "formatted message" part encoded in UTF-8
with a prepended BOM if it's Unicode.
I started to read RFC 5424 yesterday before posting this, but it
seemed to describe a much more complex message format than
SysLogHandler was producing, so I wasn't sure if that was the
reference or not. I may go back and read it completely, now that I
know, though.
The existing SysLogHandler code seems to work OK with syslog, syslog-ng and
rsyslog
I agree with this, so I would normally assume that Metalog is the
problem and simply stop using it. Unfortunately, I have several
systems that use Metalog, and I don't want to introduce any
inconsistencies by having one use something else. Switching them all
would also be a hassle.
- perhaps these are more forgiving than Metalog in the way they parse
messages, or perhaps it's a Metalog configuration issue. I'd try posting this
issue to the Metalog forum / mailing list to see what feedback they can give.
I will do that; I just wanted to see what the Python stance was first.
I will keep you apprised of anything determined through that route.
If you do think it's a bug in SysLogHandler then please create an issue on
bugs.python.org and assign it to me, so I can take a look at it
After I communicate with the Metalog community, I will definitely file
an issue if necessary. I didn't want to jump the gun, though.
I think using an appropriate Formatter will ensure interoperability in any
particular scenario. I don't especially want to hard-code any format into
SysLogHandler, since a Formatter can be used to set the format flexibly.
I think the only problem with doing it that way is that I wasn't
initially aware that using a Formatter affected how the message is
sent to Syslog, but assumed it only modified the visible portion. I
will admit that, until yesterday, I knew nothing of the syslog
protocol. Perhaps the best solution would be to simply document the
fact that adjusting the message format can affect how the message is
parsed by the syslog daemon receiving it.

Thank you for your feedback.
 
D

Dustin C. Hatch

Thanks for the detailed report. I tried posting a response a couple of times,
but Google appears to have swallowed it ... trying again. Sorry if it results in
multiple responses.
I tried to respond yesterday, but I also noticed this probelm.
The SysLogHandler aims to work within RFC 5424, though that does provide for
some flexibility in message formats. The SysLogHandler sends <priority>formatted
message, as you've observed, with the "formatted message" part encoded in UTF-8
with a prepended BOM if it's Unicode.
I started to read RFC 5424 yesterday before posting this, but it
seemed to describe a much more complex message format than
SysLogHandler was producing, so I wasn't sure if that was the
reference or not. I may go back and read it completely, now that I
know, though.
The existing SysLogHandler code seems to work OK with syslog, syslog-ng and
rsyslog
I agree with this, so I would normally assume that Metalog is the
problem and simply stop using it. Unfortunately, I have several
systems that use Metalog, and I don't want to introduce any
inconsistencies by having one use something else. Switching them all
would also be a hassle.
- perhaps these are more forgiving than Metalog in the way they parse
messages, or perhaps it's a Metalog configuration issue. I'd try posting this
issue to the Metalog forum / mailing list to see what feedback they can give.
I will do that; I just wanted to see what the Python stance was first.
I will keep you apprised of anything determined through that route.
If you do think it's a bug in SysLogHandler then please create an issue on
bugs.python.org and assign it to me, so I can take a look at it
After I communicate with the Metalog community, I will definitely file
an issue if necessary. I didn't want to jump the gun, though.
I think using an appropriate Formatter will ensure interoperability in any
particular scenario. I don't especially want to hard-code any format into
SysLogHandler, since a Formatter can be used to set the format flexibly.
I think the only problem with doing it that way is that I wasn't
initially aware that using a Formatter affected how the message is
sent to Syslog, but assumed it only modified the visible portion. I
will admit that, until yesterday, I knew nothing of the syslog
protocol. Perhaps the best solution would be to simply document the
fact that adjusting the message format can affect how the message is
parsed by the syslog daemon receiving it.

Thank you for your feedback.
 

Ask a Question

Want to reply to this thread or ask your own question?

You'll need to choose a username for the site, which only take a couple of moments. After that, you can post your question and our members will help you out.

Ask a Question

Members online

Forum statistics

Threads
473,744
Messages
2,569,484
Members
44,904
Latest member
HealthyVisionsCBDPrice

Latest Threads

Top