rsyslog update on Amazon Linux suddenly treats INFO level messages as EMERG

Question

I'm having strange issue with rsyslog on some of my EC2 instances running Amazon Linux 2012.3. Upon yum upgrading rsyslog 4.6 to 5.8.10, it seems like every INFO level log message is suddenly treated as an EMERG level issue and they are getting broadcast everywhere. Commenting out *.emerg * from /etc/rsyslog.conf squelches the messages, but obviously that's not much of a solution.

The messages look like this:

Message from syslogd@hostname at Jul 13 19:35:07 ...
¿<14>processname[1696]: INFO <yadayadayada>

Most of my logging is coming from a Python 2.6 logger with a logging.handler.SysLogHandler, the configuration of which I've posted below. I've had no luck finding any other information about this specific problem online, and the only thing that seems to solve the problem for me is rolling back to rsyslog 4.6, which instantly solves the problem. It's not a tragedy if I'm stuck with 4.6, but this problem is very disconcerting and makes me wonder if I've misconfigured something that just took until I updated to rear its head.

Here's my rsyslog.conf:

#### MODULES ####
$ModLoad imuxsock # provides support for local system logging (e.g. via logger command)
$ModLoad imklog   # provides kernel logging support (previously done by rklogd)

#### GLOBAL DIRECTIVES ####
$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
$IncludeConfig /etc/rsyslog.d/*.conf # this directory is empty

#### RULES ####
kern.*                                                 /dev/console

# Log anything (except mail) of level info or higher.
# Don't log private authentication messages!
*.info;mail.none;authpriv.none;cron.none                /var/log/messages

# The authpriv file has restricted access.
authpriv.*                                              /var/log/secure
# Log all the mail messages in one place.
mail.*                                                  -/var/log/maillog
# Log cron stuff
cron.*                                                  /var/log/cron
# Everybody gets emergency messages
*.emerg                                                 *
# Save news errors of level crit and higher in a special file.
uucp,news.crit                                          /var/log/spooler
# Save boot messages also to boot.log
local7.*                                                /var/log/boot.log

And this is the configuration for the Python logger:

[handler_syslog]
formatter = syslog
class = handlers.SysLogHandler
args = ('/dev/log',handlers.SysLogHandler.LOG_USER)
level = INFO

[formatter_syslog]
format = %(name)s[%(process)d]: %(levelname)s %(message)s

I'm not sure if I've provided enough information about my question, and this is the first time I've posted on serverfault, so my apologies for any breaches of etiquette. Thanks a lot.

Answer 1

Most likely you are running into a bug/limitation of SysLogHandler that leads to a BOM inserted in the wrong place. This confuses the rsyslog parser, and leads to the message being attributed the EMERG priority.

This has been "fixed" in Python 2.7 by removing the BOM insertion altogether.

You have two options:

1. Upgrade to Python 2.7

2. Encode the message into a str during formatting to workaround the BOM insertion code. One way of doing that is to implement a small custom formatter like this:

   class BOMLessFormatter(logging.Formatter):
       def format(self, record):
         return logging.Formatter.format(self, record).encode('utf-8')