Grokking OpenStack

OpenStack - little pieces

Logging & Debugging

I addressed my first foray into debugging, setting it up using the python console, in this post.

For some reason, when I turned to debugging one day I couldn’t get it to work and I couldn’t figure out why (I will explain the solution at the conclusion of this post). Fortunately I had a great guide in the form of russellb who likes to use logging and just happened to be willing to make a bit of time for me. What follows is what I learned about logging.

Logging

Logging is useful to see the status of something either as it is running or after it has run. If you are using Devstack (as I am) you already have access to continual logging of processes via the screen tool. When Devstack installs it sets up a window for each process, so executing a variation of screen -r stack gets you in to view the process logs as each process runs and updates the log. (Remember to exit screen with Ctrl+a d to detach the shell from screen while leaving screen running.) Now I am learning to parse these logs slowly but the point is they exist, which I needed pointed out to me so I am glad I know now.

Next is setting up logging to provide output for a local process I am working on understanding and addressing. The simplest example involves adding import logging to the top of the file, creating an instance of logging with LOG = logging.getLogger(__name__) outside of any of the classes and then an individual log statement inside the class and function you wish to explore LOG.debug('class.function was called").

Examples are gold to me, so lets work with this as a series of incremental examples.

First the bare minimum to get some logging working:

If this were the contents of a file entitled logging_example_01.py, you could expect the following output:

Let’s see what other kind of logging statements are available.

Here is the expected output:

As you can see, critical, warning and error logging messages were output and debug and info messages were skipped.

How do we get the debug and info messages output? We have to change the logging level.

By passing level=logging.INFO as an argument to basicConfig() we set the logging level to INFO.

Alas, our debug message still is not output. We change the logging level once again, this time to DEBUG.

Now we see all of our logging messages:

We are ready to put this knowledge to use in an OpenStack project file.

I was working with glanceclient Image.delete so let’s look at putting logging in that file. With the imported files add a line with import logging. Below the constants SORT_DIR_VALUES and SORT_KEY_VALUES add LOG = logging.getLogger(__name__). We don’t need the logging.basicConfig() line of code since this is taken care of for us elsewhere. This is the set up, finally the execution with the logging statement. Within the Image class inside the delete() function add LOG.debug('ImageManager.delete was called').

After I make these edits and save the file I have to reinstall the client with sudo python setup.py install otherwise my edits will not take effect. Then I can run glance --debug image-delete <image_id> and my log message will be output, amongst the rest of the debugging information.

This is what I understand about logging so far, and it is very helpful to have this as a tool.

Debugging

The only code I need for debugging is import pdb set at the top of the file with the other imports (alphabetically) and pdb.set_trace() wherever I want the trace to start. But here is the key, which I didn’t know until I was learning logging with russellb, after I edit the file to include the import and set_trace() I have to reinstall the client with sudo python setup.py install otherwise no debugging happens. Also after I remove the debugging code I must again reinstall the client to have my working code reflect the code in the files.

If you reached the end, I thank you. Here is a cat picture for you to enjoy.

Thanks for supporting this GNOME OPW intern,
Anita Kuno.

Comments