SysLogHandler message formatting

[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