Introduction

At the end of the last lesson, we encountered a run time error in our program. In this lesson we will learn some techniques to understand and track what our program is doing and help us to identify and fix errors. This is a two parter. Part 1 is on logging. Part 2 is on debugging.

Again we will revisit an analogy and think of a program like a recipe. Logging statements are the notes written in the margins of the cookbook. A chef may keep record of steps that were successful or not and also track tweaks to cook times or the amount of ingredients. This way, if the recipe turns out especially tasty or foul, there is a record of how the recipe was followed.

Logging is a tool that lets a program track steps and display messages to the console or save them to a file so that after the fact there is a history of what occurred.

Learning Goals

By the end of this lesson, you should be able to implement basic logging statements in your programs. You will be able to log messages both to the console and to a file. You should also be able to set the log level, so that only appropriately important messages are captured.

Logging to the Console

First lets take a look at logging. We’ll use a simple example for this. Lets calculate some averages! Create a file called logging-part1.py:

Now, run this program and try entering some numbers. For example, 5 and 6. You should get a long error message, with some snippets of code and a hint as to what is wrong.


> python debugging-part1.py
Enter two numbers to average:
x = 5
y = 6
Traceback (most recent call last):
File ".\debugging-part1.py", line 7, in
print('The average is: ' + get_average(x_in, y_in));
File ".\debugging-part1.py", line 2, in get_average
return (x + y) / 2
TypeError: unsupported operand type(s) for /: 'str' and 'int'



This doesn’t mean a lot to someone new to Python, but there are a few hints.

1. We learned about different variable types, like strings and integers. The message “unsupported operand type(s) for /: 'str' and 'int'” seems to indicate that our variable types might be part of the problem.
2. The line line that is generating the error is the last one in the list, ie return (x + y) / 2

So, lets add some logging statements right before that line to try and deduce the problem.

Modify your get_average function like this:

Lets notice a few things here.

First, we’ve imported a new module, called logging. This module adds the capability to log whatever messages we want, for various levels of severity. When you log messages, by default they go to the console, but we can configure them to go to a file as well, and we’ll do that soon.

The next thing to notice is line two, logging.basicConfig(level=logging.DEBUG). This line is important, because it sets the severity level of our logging. This is so that you can include logging statements, but depending on how you run the code you might not want them all captured. For example, you would not want debug level logging when running your code in a production setting. It would probably capture an unnecessarily fine level of detail, and would slow your program down and fill up your drive with useless messages. Right now we’ve hard-coded our program to log at the DEBUG level. Later we will look at how to change this dynamically from the command line.

Last is the line added to actually log a message: logging.debug('Variable x is type: ' + str(type(x))). This line logs which type of variable is variable X. It logs it at the debug level, which corresponds to the level set above on line 2.

When you run the program again, the output changes:


> python .\logging-part1.py
Enter two numbers to average:
x = 5
y = 6
DEBUG:root:Variable x is type: <class 'str'>
Traceback (most recent call last):
File ".\logging-part1.py", line 11, in
print('The average is: ' + get_average(x_in, y_in));
File ".\logging-part1.py", line 6, in get_average
return (x + y) / 2
TypeError: unsupported operand type(s) for /: 'str' and 'int'



The important thing to note here is that we now have an extra message printed to the console. This line tells us the debug level, the logger name, and the message we set. Notice that our X variable is of type STR, even though we’ve entered an integer at the prompt. We’ll solve that problem soon.

First, lets look at…

Logging to a File

Modifying our program to log to a file is very simple. We just need to alter our configuration slightly to specify the file name.

Create a new file called logging-part2.py and copy the contents of our previous file. Next alter line 2 so that it looks like this:

Now, instead of logging to the console, your messages will be logged to the file logging-part2.log in the same location as your current working directory. This keeps your console from becoming cluttered with messages, and collects all your logging in one location. Every new message will be apended to the end of this file.

Changing the Log Level

Right now we’ve forced our program to always log at the debug level. What if we wanted to deploy our program right now, with logging turned off? It wouldn’t be possible! We’ve have to change our code. Lets make our program able to log at different levels based on a command line argument.

First, lets understand the different log levels. There are five standard levels, with Warning being the default level. When you set the log level, anything with that severity or higher will be logged.

Severity	Level	Function
10	DEBUG	logging.debug(msg)
20	INFO	logging.info(msg)
30	WARNING	logging.warning(msg)
40	ERROR	logging.error(msg)
50	CRITICAL	logging.critical(msg)

Now, create a new file, logging-part3.py. We will use a module called argparse in order to read the log level from the command line and set it in code. Add the following code to your new file:

What is this doing? Well, first we instantiate a new ArgumentParser. Then we configure the settings for our command line switch. In this case, our switch will be the --log option, and our valid choices are the Logging Levels, with a default set to ‘ERROR’ in case the user omits the switch.

Then, on the next line, we parse the arguments from the command line using args.parse_args() and store them in the args object. This object will have a log variable on it, that contains the text from the command line. We use that variable on the following line to get the appropriate logging attribute and set the level.

Now we can run our program as follows, and dynamically change the logging level:


> python logging-part3.py --log WARNING
...
> python logging-part3.py --log CRITICAL
...
etc



And, if no log level is specified, the program runs with a default of ERROR.

Try running the program with an invalid log level, and see how the program reacts.

Fixing our Error

We previously determined that the problem was our X and Y variables were string types. Calculating an average for a string does not make much sense, so lets convert them to numbers using float()
logging-part4.py:

Run the program with DEBUG logging:


> python logging-part4.py --log DEBUG
Enter two numbers to average:
x = 5
y = 6
The average is: 5.5



If you check the log file, you’ll see the following:

DEBUG:root:Variable x is type: <class 'float'>.

Conclusion

We’ve learned a few neat tricks in this lesson. We learned how to use the logging module to log messages to the console and how to redirect them to a file. We also learned how to set the log level both in code and from the command line using the argparse module. And, we solved our bug by using some knowledge we already had to convert string variables to numeric ones.

Before moving on to the next lesson, try these additional exercises to help solidify these concepts.

Exercises:

1. Add additional logging statements at the info, warning, error, or critical level. Run the program with various logging levels from the comand line. How does the program handle each log statement at each different log level?
2. Add another command line argument to let the user change the log file name.
3. Consider what might happen if the user enters non-numeric data at the prompt. How might you handle this scenario?