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.
I’m a big fan of the logging module too, but it is easy to print a traceback:
import traceback
traceback.print_exc()
The ‘logging’ module might be better than print, but other than that it has lots of problems. Chris McDonough summarized them pretty well: http://plope.com/Members/chrism/logging_blues
Thanks Kent!
Pingback: stimulant » Blog Archive » things to look at (September 30th)
Thanks for writing this up.
But for Pete’s sake, remove your email from the example and use dummy domains.
Hi,
Thank you, this version of things has enlightened me a great deal.
Cheers
Hi!
fantastic guide, explains very simply but touches anything worth knowing!
thanks!
btw,
when you want to catch an exception, but also to rethrow it (for instance, for the correct
traceback to be printed, use can write ‘raise’.
for instance:
print "before exc"
try
raise Exception, "some exc"
except:
print "right before the exc"
raise
print "after exc"
hope this helps!
test
test
It can be overwhelming and frustrating at times. How do you choose ?the one? that works with the ?other ones? you will love and care for, and will in return inspire, bring value and joy.
…
I agree with meow mix
so true… I often find myself asking the same question when using python logger
thanks meow mix, you really helped me through a tough time of trying not to use print statements.
Hilarious!
great tutorials
grazie!
Right. Sold. I'm going to use Python Logger as well. Thanks, great article.
Good luck!
Mike Pirnat's slides have been moved to here: http://mike.pirnat.com/static/…
sometimes, I catch myself reverting to print statements also. It's sooo easy and if the previous developer used it on their coding… I tend to be consistent (if I'm doing their work for them). I have to hear all the wining when a programmer can't read their own code because I didn't modify it according to their ever changing standards. I might as well go back to developing online background checks.
Keep pushing the code, bro…
Great article, but I’m still a little confused about how I would apply this in a much larger scenario. I’ve written a program for a friend’s business, and it currently contains thousands of lines of code spanning several modules. Most bugs that throw exceptions are easily found and fixed by the traceback details, but there have been a few times where I’ve had to add print statements to help me track down problems that *didn’t* throw an exception. The program is kicked off by a main() function, so would I simply add logging calls to main(), similar to what you’ve done with f(), or should I go through the entire thing and add more logging calls in specific places? In other words, how do you determine what level of logging is appropriate for a given situation? I suppose I could log just about everything that happens with the program, but I’d rather not bloat it with so many logging calls that it becomes a huge mess.
Hey, Thanks for the comment!
In my experience, bugs that crash by throwing uncaught exceptions go away over time as a system spends time in production. After that phase, it becomes more important for a program to leave some kind of audit trail, so you can verify that it is doing what you want it to be doing.
At the same time, if you log every frackin’ variable assignment, then you create a needle in the haystack problem.
Two tricks I know of that help here:
1. I use log levels (DEBUG, INFO, etc) to break up what I log and why. I log every state-changing operation as INFO. So, when a user logs in to my web app, that’s an INFO. And when my cron script updates some database rows, that’s an INFO too.
Every instance of invalid input data gets logged as an ERROR. CRITICAL errors are just the things that I can’t recover from, like say, a lost database connection.
I use DEBUG logging for the stuff that I may ned later when debugging. Usually though, the less DEBUG logs, the better. I prefer to log the original state of the program, like maybe the whole HTTP request if I’m doing web programming, and then avoid logging all the various derived values, because I can usually recreate those given that I know the initial inputs.
2. When you make a logger, like::
import logging
log = logging.getLogger(‘…’)
You should use a name that relates to what kind of logging messages you’ll put in. In other words, all my database modelling modules have a logger like this::
log = logging.getLogger(‘project.model’)
But I make logs in cron jobs like this:
log = logging.getLogger(‘project.cron_job’)
If you use different named logs like that, you can configure your logging handlers to put stuff in different places. So, for example, you could have all your logs from one part of your program in one text file, separate from another part.
Good luck!
Matt
PS: I did a big ol’ talk at PyOhio this summer all about logging. Here’s the text from that talk: https://github.com/mw44118/really-good-logging/blob/master/finished-stuff.txt
There’s a lot of “real world” scenarios that I hash through in there. You can also find the video from the talk on youtube. Search for PyOhio really good logging.
Thank you for this article. It really helps me with switching to logging !
Thanks a lot meow mix…. great explanation.