A while back, I swore off using adding print statements to my code while debugging. I forced myself to use the python debugger to see values inside my code. I’m really glad I did it. Now I’m comfortable with all those cute single-letter commands that remind me of gdb. The pdb module and the command-line pdb.py script are both good friends now.

However, every once in a while, I find myself lapsing back into cramming a bunch of print statements into my code because they’re just so easy. Sometimes I don’t want to walk through my code using breakpoints. I just need to know a simple value when the script runs.

The bad thing is when I write in a bunch of print statements, then debug the problem, then comment out or remove all those print statements, then run into a slightly different bug later., and find myself adding in all those print statements again.

So I’m forcing myself to use logging in every script I do, no matter how trivial it is, so I can get comfortable with the python standard library logging module. So far, I’m really happy with it.

I’ll start with a script that uses print statements and revise it a few times and show off how logging is a better solution. Here is the original script, where I use print statements to watch what happens:

# This is a.py

if __name__ == "__main__": f()

Running the script yields this output:

$ python a.py
inside f!
Something awful happened!
Finishing f!

It turns out that rewriting that script to use logging instead just ain’t that hard:

# This is b.py.

if __name__ == "__main__":
f()

And here is the output:

$ python b.py
DEBUG 2007-09-18 23:30:19,912 debug 1327 Inside f!
ERROR 2007-09-18 23:30:19,913 error 1294 Something awful happened!
Traceback (most recent call last):
File "b.py", line 22, in f
g()
File "b.py", line 14, in g
1/0
ZeroDivisionError: integer division or modulo by zero
DEBUG 2007-09-18 23:30:19,915 debug 1327 Finishing f!

Note how we got that pretty view of the traceback when we used the exception method. Doing that with prints wouldn’t be very much fun.

So, at the cost of a few extra lines, we got something pretty close to print statements, which also gives us better views of tracebacks.

But that’s really just the tip of the iceberg. This is the same script written again, but I’m defining a custom logger object, and I’m using a more detailed format:

# This is c.py
import logging

if __name__ == "__main__":
f()


And the output:
$ python c.py
DEBUG 2007-09-18 23:32:27,157 f 23 Inside f!
ERROR 2007-09-18 23:32:27,158 exception 1021 Something awful happened!
Traceback (most recent call last):
File "c.py", line 27, in f
g()
File "c.py", line 17, in g
1/0
ZeroDivisionError: integer division or modulo by zero
DEBUG 2007-09-18 23:32:27,159 f 33 Finishing f!


Now I will change how the script handles the different types of log messages. Debug messages will go to a text file, and error messages will be emailed to me so that I am forced to pay attention to them.

# This is d.py
import logging, logging.handlers

if __name__ == "__main__":
f()


Lots of really great handlers exist in the logging.handlers module. You can log by sending HTTP gets or posts, you can send UDP packets, you can write to a local file, etc.

Finally, I’d like to point out that Mike Pirnat has some excellent slides (in PDF format) on logging using the standard python library here.

I am dogmatic about never using global variables. But when people way smarter than me use them, like Brian Kernighan does when he builds a command-line interpreter in that chapter of The Unix Programming Environment, I wonder if maybe I’m being too reluctant.

I was looking at a python module vaguely like this:

def foo():
do_foo_stuff()

def quux():
do_quux_stuff()

I had a bunch of independent functions. I wanted to add logging. I saw two easy ways to do it:

def foo():
logger = get_logging_singleton()
logger.log_stuff()
do_foo_stuff()

def quux():
logger = get_logging_singleton()
logger.log_stuff()
do_quux_stuff()

In the above code, I would get a reference to my logger object in each function call. No globals. Maybe I am violating some tenet of dependency injection, but I’ll talk about that later. Anyhow, the point I want to make is that the above approach is the way I would do it in the past.

Here’s how I decided to write it this time:

logger = get_logging_singleton()

def quux():
logger.log_stuff()
do_quux_stuff()

All the functions access the logger created in the main namespace of the module. It feels a tiny bit wrong, but I think it is the right thing to do. The other way violates DRY in a big fat way.

So, a third option would be to require the caller to pass in the logging object in every function call, like this:

def quux(logger):
logger.log_stuff()
do_quux_stuff()

This seems like the best possible outcome — it satisfies my hangup about avoiding global variables and the caller can make decisions about log levels by passing any particular logger it wants to.

There’s two reasons why I didn’t take this approach:

1. I was working on existing code, and I didn’t have the option of cramming in extra parameters in the calling library. So, I could do something like def quux(logger=globally_defined_logger) but I’m trying to make this prettier, not uglier. The whole reason that I wanted to add logging was that I wanted some visibility into what what the heck was going wrong in my app. I didn’t have time to monkey with overhauling the whole system.
2. I plan to control my logger behavior from an external configuration system. I don’t want to change code inside the caller every time I want to bump the log level up or down. It is the conventional wisdom in my work environment that I face less risk just tweaking a configuration file setting and restarting my app rather than editing my code*.

[*]I suspect that in the final analysis, this belief will be exposed as garbage. But for right now, it seems pretty true that bugs occur more frequently after editing code than after editing config files.

UPDATE: Apparently, I’m not just talking to myself here! Gary Bernhardt linked to this post and added some really interesting points. Also, his link to the post on the origin of the phrase now you have two problems was something I hadn’t heard of before.

I’m building a robot to make breakfast.

def make_breakfast():
    fridge = get_reference_to_fridge()
    eggs = fridge.get_eggs(number_of_eggs=2)
    fried_eggs = fry(eggs, over_easy)
    cabinet = get_reference_to_cabinet()
    plate = cabinet.get_plate()
    add(fried_eggs, plate)

    return plate

This is OK, but I realize my robot needs lots and lots of practice, and I don’t like wasting all my nice eggs and getting all my plates dirty. So, while my robot is still learning how to cook, I want to specify that it uses paper plates and some crappy expired eggs I fished out of the grocery store dumpster.

Continue reading →