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
def g():
1 / 0
def f():
print "inside f!"
try:
g()
except Exception, ex:
print "Something awful happened!"
print "Finishing f!"
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.
import logging
# Log everything, and send it to stderr.
logging.basicConfig(level=logging.DEBUG)
def g():
1/0
def f():
logging.debug("Inside f!")
try:
g()
except Exception, ex:
logging.exception("Something awful happened!")
logging.debug("Finishing f!")
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
# Make a global logging object.
x = logging.getLogger("logfun")
x.setLevel(logging.DEBUG)
h = logging.StreamHandler()
f = logging.Formatter("%(levelname)s %(asctime)s %(funcName)s %(lineno)d %(message)s")
h.setFormatter(f)
x.addHandler(h)
def g():
1/0
def f():
logfun = logging.getLogger("logfun")
logfun.debug("Inside f!")
try:
g()
except Exception, ex:
logfun.exception("Something awful happened!")
logfun.debug("Finishing f!")
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
# Make a global logging object.
x = logging.getLogger("logfun")
x.setLevel(logging.DEBUG)
# This handler writes everything to a file.
h1 = logging.FileHandler("/var/log/myapp.log")
f = logging.Formatter("%(levelname)s %(asctime)s %(funcName)s %(lineno)d %(message)s")
h1.setFormatter(f)
h1.setLevel(logging.DEBUG)
x.addHandler(h1)
# This handler emails me anything that is an error or worse.
h2 = logging.handlers.SMTPHandler('localhost', '[email protected]', ['[email protected]'], 'ERROR log')
h2.setLevel(logging.ERROR)
h2.setFormatter(f)
x.addHandler(h2)
def g():
1/0
def f():
logfun = logging.getLogger("logfun")
logfun.debug("Inside f!")
try:
g()
except Exception, ex:
logfun.exception("Something awful happened!")
logfun.debug("Finishing f!")
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.