Automate the Boring Stuff with Python
Page 22
But if while writing switchLights() you had added an assertion to check that at least one of the lights is always red, you might have included the following at the bottom of the function:
assert 'red' in stoplight.values(), 'Neither light is red! ' + str(stoplight)
With this assertion in place, your program would crash with this error message:
Traceback (most recent call last): File "carSim.py", line 14, in
The important line here is the AssertionError ➊. While your program crashing is not ideal, it immediately points out that a sanity check failed: Neither direction of traffic has a red light, meaning that traffic could be going both ways. By failing fast early in the program’s execution, you can save yourself a lot of future debugging effort.
Disabling Assertions
Assertions can be disabled by passing the -O option when running Python. This is good for when you have finished writing and testing your program and don’t want it to be slowed down by performing sanity checks (although most of the time assert statements do not cause a noticeable speed difference). Assertions are for development, not the final product. By the time you hand off your program to someone else to run, it should be free of bugs and not require the sanity checks. See Appendix B for details about how to launch your probably-not-insane programs with the -O option.
Logging
If you’ve ever put a print() statement in your code to output some variable’s value while your program is running, you’ve used a form of logging to debug your code. Logging is a great way to understand what’s happening in your program and in what order its happening. Python’s logging module makes it easy to create a record of custom messages that you write. These log messages will describe when the program execution has reached the logging function call and list any variables you have specified at that point in time. On the other hand, a missing log message indicates a part of the code was skipped and never executed.
Using the logging Module
To enable the logging module to display log messages on your screen as your program runs, copy the following to the top of your program (but under the #! python shebang line):
import logging logging.basicConfig(level=logging.DEBUG, format=' %(asctime)s - %(levelname)s - %(message)s')
You don’t need to worry too much about how this works, but basically, when Python logs an event, it creates a LogRecord object that holds information about that event. The logging module’s basicConfig() function lets you specify what details about the LogRecord object you want to see and how you want those details displayed.
Say you wrote a function to calculate the factorial of a number. In mathematics, factorial 4 is 1 × 2 × 3 × 4, or 24. Factorial 7 is 1 × 2 × 3 × 4 × 5 × 6 × 7, or 5,040. Open a new file editor window and enter the following code. It has a bug in it, but you will also enter several log messages to help yourself figure out what is going wrong. Save the program as factorialLog.py.
import logging logging.basicConfig(level=logging.DEBUG, format=' %(asctime)s - %(levelname)s - %(message)s') logging.debug('Start of program') def factorial(n): logging.debug('Start of factorial(%s%%)' % (n)) total = 1 for i in range(n + 1): total *= i logging.debug('i is ' + str(i) + ', total is ' + str(total)) logging.debug('End of factorial(%s%%)' % (n)) return total print(factorial(5)) logging.debug('End of program')
Here, we use the logging.debug() function when we want to print log information. This debug() function will call basicConfig(), and a line of information will be printed. This information will be in the format we specified in basicConfig() and will include the messages we passed to debug(). The print(factorial(5)) call is part of the original program, so the result is displayed even if logging messages are disabled.
The output of this program looks like this:
2015-05-23 16:20:12,664 - DEBUG - Start of program 2015-05-23 16:20:12,664 - DEBUG - Start of factorial(5) 2015-05-23 16:20:12,665 - DEBUG - i is 0, total is 0 2015-05-23 16:20:12,668 - DEBUG - i is 1, total is 0 2015-05-23 16:20:12,670 - DEBUG - i is 2, total is 0 2015-05-23 16:20:12,673 - DEBUG - i is 3, total is 0 2015-05-23 16:20:12,675 - DEBUG - i is 4, total is 0 2015-05-23 16:20:12,678 - DEBUG - i is 5, total is 0 2015-05-23 16:20:12,680 - DEBUG - End of factorial(5) 0 2015-05-23 16:20:12,684 - DEBUG - End of program
The factorial() function is returning 0 as the factorial of 5, which isn’t right. The for loop should be multiplying the value in total by the numbers from 1 to 5. But the log messages displayed by logging.debug() show that the i variable is starting at 0 instead of 1. Since zero times anything is zero, the rest of the iterations also have the wrong value for total. Logging messages provide a trail of breadcrumbs that can help you figure out when things started to go wrong.
Change the for i in range(n + 1): line to for i in range(1, n + 1):, and run the program again. The output will look like this:
2015-05-23 17:13:40,650 - DEBUG - Start of program 2015-05-23 17:13:40,651 - DEBUG - Start of factorial(5) 2015-05-23 17:13:40,651 - DEBUG - i is 1, total is 1 2015-05-23 17:13:40,654 - DEBUG - i is 2, total is 2 2015-05-23 17:13:40,656 - DEBUG - i is 3, total is 6 2015-05-23 17:13:40,659 - DEBUG - i is 4, total is 24 2015-05-23 17:13:40,661 - DEBUG - i is 5, total is 120 2015-05-23 17:13:40,661 - DEBUG - End of factorial(5) 120 2015-05-23 17:13:40,666 - DEBUG - End of program
The factorial(5) call correctly returns 120. The log messages showed what was going on inside the loop, which led straight to the bug.
You can see that the logging.debug() calls printed out not just the strings passed to them but also a timestamp and the word DEBUG.
Don’t Debug with print()
Typing import logging and logging.basicConfig(level=logging.DEBUG, format= '%(asctime)s - %(levelname)s - %(message)s') is somewhat unwieldy. You may want to use print() calls instead, but don’t give in to this temptation! Once you’re done debugging, you’ll end up spending a lot of time removing print() calls from your code for each log message. You might even accidentally remove some print() calls that were being used for nonlog messages. The nice thing about log messages is that you’re free to fill your program with as many as you like, and you can always disable them later by adding a single logging.disable(logging.CRITICAL) call. Unlike print(), the logging module makes it easy to switch between showing and hiding log messages.
Log messages are intended for the programmer, not the user. The user won’t care about the contents of some dictionary value you need to see to help with debugging; use a log message for something like that. For messages that the user will want to see, like File not found or Invalid input, please enter a number, you should use a print() call. You don’t want to deprive the user of useful information after you’ve disabled log messages.
Logging Levels
Logging levels provide a way to categorize your log messages by importance. There are five logging levels, described in Table 10-1 from least to most important. Messages can be logged at each level using a different logging function.
Table 10-1. Logging Levels in Python
Level
Logging Function
Description
DEBUG
logging.debug()
The lowest level. Used for small details. Usually you care about these messages only when diagnosing problems.
INFO
logging.info()
Used to record information on general events in your program or confirm that things are working at their point in the program.
WARNING
logging.warning()
Used to indicate a potential problem that doesn’t prevent the program from working but might do so in the future.
ERROR
logging.error()
Used to record an error that caused the program to fail to do something.
CRITICAL
logging.critical(
)
The highest level. Used to indicate a fatal error that has caused or is about to cause the program to stop running entirely.
Your logging message is passed as a string to these functions. The logging levels are suggestions. Ultimately, it is up to you to decide which category your log message falls into. Enter the following into the interactive shell:
>>> import logging >>> logging.basicConfig(level=logging.DEBUG, format=' %(asctime)s - %(levelname)s - %(message)s') >>> logging.debug('Some debugging details.') 2015-05-18 19:04:26,901 - DEBUG - Some debugging details. >>> logging.info('The logging module is working.') 2015-05-18 19:04:35,569 - INFO - The logging module is working. >>> logging.warning('An error message is about to be logged.') 2015-05-18 19:04:56,843 - WARNING - An error message is about to be logged. >>> logging.error('An error has occurred.') 2015-05-18 19:05:07,737 - ERROR - An error has occurred. >>> logging.critical('The program is unable to recover!') 2015-05-18 19:05:45,794 - CRITICAL - The program is unable to recover!
The benefit of logging levels is that you can change what priority of logging message you want to see. Passing logging.DEBUG to the basicConfig() function’s level keyword argument will show messages from all the logging levels (DEBUG being the lowest level). But after developing your program some more, you may be interested only in errors. In that case, you can set basicConfig()’s level argument to logging.ERROR. This will show only ERROR and CRITICAL messages and skip the DEBUG, INFO, and WARNING messages.
Disabling Logging
After you’ve debugged your program, you probably don’t want all these log messages cluttering the screen. The logging.disable() function disables these so that you don’t have to go into your program and remove all the logging calls by hand. You simply pass logging.disable() a logging level, and it will suppress all log messages at that level or lower. So if you want to disable logging entirely, just add logging.disable(logging.CRITICAL) to your program. For example, enter the following into the interactive shell:
>>> import logging >>> logging.basicConfig(level=logging.INFO, format=' %(asctime)s - %(levelname)s - %(message)s') >>> logging.critical('Critical error! Critical error!') 2015-05-22 11:10:48,054 - CRITICAL - Critical error! Critical error! >>> logging.disable(logging.CRITICAL) >>> logging.critical('Critical error! Critical error!') >>> logging.error('Error! Error!')
Since logging.disable() will disable all messages after it, you will probably want to add it near the import logging line of code in your program. This way, you can easily find it to comment out or uncomment that call to enable or disable logging messages as needed.
Logging to a File
Instead of displaying the log messages to the screen, you can write them to a text file. The logging.basicConfig() function takes a filename keyword argument, like so:
import logging logging.basicConfig(filename='myProgramLog.txt', level=logging.DEBUG, format=' %(asctime)s - %(levelname)s - %(message)s')
The log messages will be saved to myProgramLog.txt. While logging messages are helpful, they can clutter your screen and make it hard to read the program’s output. Writing the logging messages to a file will keep your screen clear and store the messages so you can read them after running the program. You can open this text file in any text editor, such as Notepad or TextEdit.
IDLE’s Debugger
The debugger is a feature of IDLE that allows you to execute your program one line at a time. The debugger will run a single line of code and then wait for you to tell it to continue. By running your program “under the debugger” like this, you can take as much time as you want to examine the values in the variables at any given point during the program’s lifetime. This is a valuable tool for tracking down bugs.
To enable IDLE’s debugger, click Debug▸Debugger in the interactive shell window. This will bring up the Debug Control window, which looks like Figure 10-1.
When the Debug Control window appears, select all four of the Stack, Locals, Source, and Globals checkboxes so that the window shows the full set of debug information. While the Debug Control window is displayed, any time you run a program from the file editor, the debugger will pause execution before the first instruction and display the following:
The line of code that is about to be executed
A list of all local variables and their values
A list of all global variables and their values
Figure 10-1. The Debug Control window
You’ll notice that in the list of global variables there are several variables you haven’t defined, such as __builtins__, __doc__, __file__, and so on. These are variables that Python automatically sets whenever it runs a program. The meaning of these variables is beyond the scope of this book, and you can comfortably ignore them.
The program will stay paused until you press one of the five buttons in the Debug Control window: Go, Step, Over, Out, or Quit.
Go
Clicking the Go button will cause the program to execute normally until it terminates or reaches a breakpoint. (Breakpoints are described later in this chapter.) If you are done debugging and want the program to continue normally, click the Go button.
Step
Clicking the Step button will cause the debugger to execute the next line of code and then pause again. The Debug Control window’s list of global and local variables will be updated if their values change. If the next line of code is a function call, the debugger will “step into” that function and jump to the first line of code of that function.
Over
Clicking the Over button will execute the next line of code, similar to the Step button. However, if the next line of code is a function call, the Over button will “step over” the code in the function. The function’s code will be executed at full speed, and the debugger will pause as soon as the function call returns. For example, if the next line of code is a print() call, you don’t really care about code inside the built-in print() function; you just want the string you pass it printed to the screen. For this reason, using the Over button is more common than the Step button.
Out
Clicking the Out button will cause the debugger to execute lines of code at full speed until it returns from the current function. If you have stepped into a function call with the Step button and now simply want to keep executing instructions until you get back out, click the Out button to “step out” of the current function call.
Quit
If you want to stop debugging entirely and not bother to continue executing the rest of the program, click the Quit button. The Quit button will immediately terminate the program. If you want to run your program normally again, select Debug▸Debugger again to disable the debugger.
Debugging a Number Adding Program
Open a new file editor window and enter the following code:
print('Enter the first number to add:') first = input() print('Enter the second number to add:') second = input() print('Enter the third number to add:') third = input() print('The sum is ' + first + second + third)
Save it as buggyAddingProgram.py and run it first without the debugger enabled. The program will output something like this:
Enter the first number to add: 5 Enter the second number to add: 3 Enter the third number to add: 42 The sum is 5342
The program hasn’t crashed, but the sum is obviously wrong. Let’s enable the Debug Control window and run it again, this time under the debugger.
When you press F5 or select Run▸Run Module (with Debug▸Debugger enabled and all four checkboxes on the Debug Control window checked), the program starts in a paused state on line 1. The debugger will always pause on the line of code it is about to execute. The Debug Control window will look like Figure 10-2.
Figure 10-2. The Debug Control window when the program first starts under the debugger
Click the Over button once to execute the first print() call. You should use Over instead of Step here, since you don’t want to step into the code for the print() function. The Debug Control window will update to line 2
, and line 2 in the file editor window will be highlighted, as shown in Figure 10-3. This shows you where the program execution currently is.
Figure 10-3. The Debug Control window after clicking Over
Click Over again to execute the input() function call, and the buttons in the Debug Control window will disable themselves while IDLE waits for you to type something for the input() call into the interactive shell window. Enter 5 and press Return. The Debug Control window buttons will be reenabled.
Keep clicking Over, entering 3 and 42 as the next two numbers, until the debugger is on line 7, the final print() call in the program. The Debug Control window should look like Figure 10-4. You can see in the Globals section that the first, second, and third variables are set to string values '5', '3', and '42' instead of integer values 5, 3, and 42. When the last line is executed, these strings are concatenated instead of added together, causing the bug.
Figure 10-4. The Debug Control window on the last line. The variables are set to strings, causing the bug.