Python logging TypeError messages

I've been writing small Python programs for about two years now. There are a few things that slipped my notice until really recently though, and having good application logging instead of using "print" is on that list. Lost some time today figuring out that "global" goes inside functions where that global is used, rather than as a modifier when creating the variable; Understanding 'global' in Python cleared that up for me. While trying to sort that out, I started converting my program's mess of print statements into something that used the logging facility instead. There's an unexpected and quite messy surprise waiting there, a simple to make mistake that the logging facility completely botches handling in a friendly way.

Let's say we start with a simple program that logs the value of a variable at a point:

#!/usr/bin/env python
x=1
print "x =",x

We decide to switch that over to use logging instead, so that we can adjust whether that bit of detail is logged or not better. You might do that (wrongly!) like this:

#!/usr/bin/env python
import logging
x=1
logging.warning("x =",x)

I'd guess this is a pretty common amateur mistake. If you pass more than one argument into a logging statement, the module presumes the first one is a format string and the rest fill in parameters in that string. This gives you the following cryptic error when it uses the "%" facility to format that string with the variable given:

Traceback (most recent call last):
File "/usr/lib/python2.6/logging/__init__.py", line 760, in emit
msg = self.format(record)
File "/usr/lib/python2.6/logging/__init__.py", line 644, in format
return fmt.format(record)
File "/usr/lib/python2.6/logging/__init__.py", line 432, in format
record.message = record.getMessage()
File "/usr/lib/python2.6/logging/__init__.py", line 302, in getMessage
msg = msg % self.args
TypeError: not all arguments converted during string formatting

OK, so that's my bad. But notice what's missing from there? There's not a hint of an idea where in my code the error is at! All of the error messages refer to things within the logging __init__.py module. What to do?

This topic came up recently on the Python list, with a couple of messages about how to hack up the logging module to present more information. That works, but isn't particularly elegant. Buried in there was a clever way around this problem though: override the error handler. Here's what that looks like patched into our bad code example:

#!/usr/bin/env python
import logging

def handleError(self, record):
  raise
logging.Handler.handleError = handleError

x=1
logging.warning("x =",x)

Now when this is run, the error traceback you get starts by showing you the bad line in your code:

Traceback (most recent call last):
File "./logtest.py", line 9, in 
logging.warning("x =",x)
File "/usr/lib/python2.6/logging/__init__.py", line 1441, in warning
root.warning(*((msg,)+args), **kwargs)
...

Note that just inserting an error handler like this isn't what you want to deploy, because an error in logging should introduce an application error. It's really more for making sure you get all your log messages correct in the first place. Make sure you read and following through understanding the comments about how handleError works later in the message thread before leaving this error dumping code in your app permanently.

I broke this down into a trivial case for demonstration, in my actual problem I had 600 lines of code filled with logging calls and only one of them was bad. Patching the error handler took me right to the bad one, and it was obvious how to fix it once I was staring at it.

Here's a correct snippet of code below, including some initialization bits I borrowed from the excellent Manage concurrent threads tutorial that makes the log messages more appropriate for threads. The reason I needed logging and global variables here were to cope with some program-wide thread locking issues with a single shared resource, and something like this is what's actually going into my app now that the log messages are all formatted properly and I could punt the error handler hack out of the program. But you can bet I'll remember that for the next time I run into the cryptic logging TypeError.

#!/usr/bin/env python
import logging
logging.basicConfig(
  level=logging.DEBUG,
  format='(%(threadName)-10s) %(message)s')          
x=1
logging.warning("x = %s",x)

Note that there are all sorts of additional format strings like "%(threadname)" available, including timestamps and line numbers, and making changes to the base format lets you adjust that for the whole program. If you find yourself starting to put function names into your log messages or similarly repetitive work, you should consider using those substitution formatters instead.