Python logging module¶

For a customer project I had a real need for adding some logging in order to prove/check that things worked.

I first did some simple logging myself. I started out with log = open("product.log", "w") and then print >> log, "My log message" and so. That got boring pretty quickly, so it became a utility method: log("My log message"). To get everything in one logfile, I had to pass log methods around when calling methods.

That turned into a bother pretty quickly. Wasn't there a standard python logging library? Yes, there is . Python comes with batteries included :-)

It works like a charm. Import the logging module and you can get your hands on a logger everywhere with a quick log = logging.getLogger("my module"). I've experimented a bit with doing this on a by-class basis (so doing a self.log = ... in the class's __init__()) or puttting a log = ... as a global variable at the top of every file. I think I like that last method best.

There are several "levels" defined in the logging module. You can choose a level of output verbosity. Most of the logging will be log.debug("Value of the variable is %s", var). User-oriented messages log.info(...). Likewise log.warn() and log.error() and so.

At the point where you start your program you need to do some setup stuff. Get the logger, tell it which file to use and what level of output verbosity you want. Handy thing is that you can have multiple output levels. For abovementioned customer project I'm logging everything to a file and mailing all error-level messages to myself and some other maintainers. For archgenxml I'm logging everything to a file (again) and printing out all info-level (and higher) to console.

Another word about that getLogger(.....). What you put in there is a string. Which may be empty, in which case you get the "root" logger. Normally you grab that root logger when initialising, as the root catches all log messages. I normally use the string you can pass to getLogger() as an identifier in the logfile. "Ah, this happened in the sql utility library" and so. But you can also redirect log messages of a certain category to a different file or so. Just grab the logger and set its output method to a different file. I'm using this to write some high-level things to a dedicated report file ("Incoming order 1234", "Order 1234 entered into the database") for subsequent report generation. Handy to use the same mechanism.

It works great. And it's good programming practice. Make your program talk to you through the logfile. This forces you to think through your code better. "What am I doing here, exactly?", "What does this input variable do anyway?". My experience is that you'll need less comments in your code, as you'll just log what you'd otherwise put in the comments.

Great way to find your way in somebody else's code: add logging. It forces you to make explicit what you think is happening.

It's not difficult to start: all those commented-oud print semi-debug statements in your code? Turn them into log.debug() and log to a file without bothering your users. When an error occurs you can always ask them to mail you the logfile for easier debugging.

Logging is especially valuable when you're working on an open source project and you've got some technically savvy users. I added logging to archgenxml and already one day later I was getting emails or IRC messages with "the logfile says it got this command line parameter, but ...". And when you get a bug report, you can look up the relevant section, add logging to it and ask the person to try again using the new version. Ah!

I'm unittesting most of my code and there's normally a tests/runalltests.py file. Which is a good place to also put that logfile initalisation stuff. This allows you to suppress all console logging (a unittest should be silent) and to redirect the logging to a separate test.log instead of your production log.