I Wanted to be a Lumberjack (logging)


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.

Advanced stuff

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.

Final comments

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.

More info: Logging how to, logging docs

About these ads

8 Responses to I Wanted to be a Lumberjack (logging)

  1. Pingback: I Wanted to be a Lumberjack (logging) | Python-es | Scoop.it

  2. bgirardot says:

    Why does the line number seem to be off by one in the log?

    • brendanscott says:

      @bgirardot –
      short answer: WordPress’s line numbers are wrong.
      My original has an extra line of white space which WordPress’s tag has automatically collapsed.
      I have changed them manually to reflect the code as displayed by WordPress.
      +1 for being attentive
      Cheers

      Brendan

  3. Pingback: Links 24/10/2012: First GNOME 3.6 Update | Techrights

  4. Pingback: Python4Kids New Tutorial: I Wanted to be a Lumberjack (logging) | Tutorial WPAP

  5. Jay says:

    Hello, I frequently read this blog and really enjoy it. I do have a question about this post. When I try and print line numbers, as in your second example, it is reporting the line number from the logging module, not my code. So, they aren’t very useful to me. Is there some way to stop that? My code is exactly the same as yours and I’m using python 2.7.3.

    Thanks,
    Jay

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

Join 67 other followers

%d bloggers like this: