Taking Some Pain out of Python Logging

Even the best of us hate logging in Python sometimes. And while a lot of its problems are actually just bad docs and terrible defaults in the past, there is some pain that can be avoided.

One of the big problems with logging in general is that every class and function reek of NIH in the name of cross-platform. And to make it even more fun, there are several ways to do it: standard library, Twisted, Logbook…

For example to get useful log rotation by day (whoever came up with rotating by size may be a good idea‽), you’d go for TimedRotatingFileHandler in stdlib, but in Twisted everything works slightly differently.

All of this isn’t just annoying, it’s also unnecessary. Your UNIX-like operating system – which you presumably use to deploy your applications – offers formidable solutions to both logging and rotating. It’s out there for you to use. Since the 1980s.

Nowadays when I deploy web applications I use StreamHandler as logger which sends all logs to stderr. For paster (Pylons/Pyramid) it looks like this:

[handler_stderr]
class = StreamHandler
args = (sys.stderr,)
level = INFO
formatter = your_formatter

For Django, you go with:

'handlers': {
    'stderr': {
        'level': 'INFO',
        'class': 'logging.StreamHandler',
        'formatter': 'your_formatter',
    },
},

Then tell uwsgi to forward all of the app output (i.e. including prints and possible tracebacks!) to syslog with the app name attached:

$ uwsgi --log-syslog=yourapp …

And if I deploy Twisted applications, it looks similarly:

$ twistd --syslog --prefix yourapp …

Suddenly you’ll get all the syslog goodness the ops folks swear by:

Stop worrying about writing from several processes into one log file. That’s basically the raison d’être for syslog.

Consistent time stamps all over the server. Inconsistent time stamps suck. And having to make sure they are consistent even more so. You remove time stamps from your log entries altogether and let the OS handle that.

Filtering into files by application. You’ll want to have your logs split by application. Doing that using rsyslog simply involves these two lines in a file under /etc/rsyslog.d/:

if $programname == 'yourapp' then /var/log/yourapp/yourapp.log
& ~

rsyslog even makes sure the path exists.

Log rotation. Your OS has powerful log rotation built in with extra features like removal after a certain period or compressing your logs. And logs are awesomely compressible! Since you log to syslog, you don’t have to worry about re-opening your log files on rotation.

Remote logging. Yes, rsyslog even supports logging remotely to another server. Did you know about that?

You’ll still have to do some configuration to your logging. Mostly log levels and e-mail notifications. And that’s fine, because these are your application’s concerns. Handling log files and rotating them isn’t.

P.S. stdlib’s logging does have a SysLog handler. Unfortunately it doesn’t support setting the app name out of the box (Python 3 does). Additionally if your app explodes and sends a traceback to stderr, it lands in your logs too with the approach above. And frankly, I try to configure logging as little as possible – I’m just not smart enough to do it properly.

FREE Bonus Tip: Pyramid, uwsgi, and Python 3

I’ve been developing a new Python app and we chose to go Python 3.3 for the first time. There is the little catch that you have to use --ini-paste-logged to make uwsgi initialize your logging from your configuration file – otherwise you just get an empty log and wonder why.

However, that feature requires PasteScript which is Python 2-only. The solution to this problem has been discussed on the Pylons mailing list but I’m putting it out here for better Googleability:

You have to initialize your logging manually by adding a pointer to your config file that points at itself in the [app:main] section:

logging.config = %(here)s/development.ini

and then simply load it in your main() that sets up your Pyramid application (usually inside of <appname>.__init__.py):

logging.config.fileConfig(settings['logging.config'],
                          disable_existing_loggers=False)

You will have to import logging.config first.