I Wanted to be a Lumberjack (logging)
October 22, 2012 8 Comments
I Wanted to be a Lumberjack (logging)
Barber: All right … I confess I haven’t cut your hair … I didn’t want to be a barber anyway. I wanted to be a lumberjack. Leaping from tree to tree as they float down the mighty rivers of British Columbia . . . (he is gradually straightening up with a visionary gleam in his eyes). The giant redwood, the larch, the fir, the mighty Scots pine. (he tears off his barber’s jacket, to reveal tartan shirt and lumberjack trousers underneath; as he speaks the lights dim behind him and a choir of Mounties is heard, faintly in the distance)
When something goes wrong with a program, it is natural to try to diagnose the problem by using the print statement to check the value of variables. As your program grows in size however, this begins to get unwieldy, if only because the output of print ends up in the console and you lose it to the autoscrolling. Python offers another way to record these messages – the logging module. In its most most basic form:
import logging fn ="test.log" # Warning! Will delete any file called test.log! logging.basicConfig(filename= fn, filemode='w', level = logging.DEBUG) if __name__=="__main__": logging.debug("This is a test entry")
If you save this to a file (p4kLogging.py) and run it, it should:
- create a file called “test.log” (we could have called it something else if we wished (this is filename =fn)
- if such a file already exists, that file is deleted and a new, empty one created on top of it (this is the filemode = “w” part)
Let’s read the file now from the Python console:
>>> fn ="test.log" >>> f = open(fn,'r') >>> print f.read() DEBUG:root:This is a test entry >>> f.close()
This gives us the message (“This is a test entry”), as well as what logging status it has been given (DEBUG) and what function made the log (root – or the main part of the program)
Let’s try the same program again, but this time we’ll set the logging level to WARNING:
import logging fn ="test.log" # Warning! Will delete any file called test.log! logging.basicConfig(filename= fn, filemode='w', level = logging.WARNING) if __name__=="__main__": logging.debug("This is a test entry")
This time, when we print the contents of the file:
>>> f = open(fn,'r') >>> print f.read() >>> f.close()
It’s empty! This is because we configured the logging to only show messages which were of WARNING or higher priority. Since DEBUG is of lower priority it was filtered out. Most excellent! Imagine if these were print statements instead. Once the program was finished/or the problem debugged, you need to go back and either remove or comment out all of the print statements (leaving important ones alone – so you can’t necessarily just use search and replace). Now, instead, we simply turn all of them off by a simple change of the logger configuration. However, it gets better.
The output we initially saw was a little pedestrian. We can configure the logger to provide heaps more information. Here’s a slightly longer program with a more involved logging parameter:
import logging fn ="test.log" # Warning! Will delete any file called test.log! logging.basicConfig(filename= fn, filemode='w', level = logging.DEBUG, format= "%(levelname)s %(asctime)s %(funcName)s @%(lineno)d %(message)s") def functionA(): logging.debug("We're in function A") def functionB(): logging.debug("We're in function B") if __name__=="__main__": logging.debug("This is a test entry") functionA() functionB()
Look at what we get now when we run the program:
>>> f = open(fn,'r') >>> print f.read() DEBUG 2012-10-22 16:26:15,789 <module> @13 This is a test entry DEBUG 2012-10-22 16:26:15,789 functionA @7 We're in function A DEBUG 2012-10-22 16:26:15,789 functionB @10 We're in function B >>> f.close()
Now, we get a bunch more info, including the time and date of the logging message (down to milliseconds). Not only that, we get the name of the function from which the function call was made and the line number in the program where the function call was made.
Knowing the line number in particular is pretty useful. For example, you can filter the log file for references to that specific line number eg (this only works on systems with grep installed of course):
>grep \@7 test.log DEBUG 2012-10-22 16:26:15,789 functionA @7 We're in function A
You can even use it to open up your file at the exact line number:
>vi p4kLogging121022C.py +7
This, of course, is only if you’re using the vi editor, but other editors should have “go to line” functions which can also be used. This is much easier than hunting through your text file trying to find where the logging call was made.
Different levels you will typically use are logging.debug, logging.warning and logging.error. The logging function you use will log whatever string is passed as an argument:
logging.debug("It's this bit which will print")
You can use string formatting here as well to log variable values:
logging.warning("The value of x is %s"%(x))
It is good practice to use a logger for your debugging messages. If you have a short program it may be easier to just use print statements. However, as your programs grow, you will definitely need to do logging instead.