In this article by Dan Nixon of the book Getting Started with Python and Raspberry Pi, we will learn more about how to debug Python code using the Python Debugger (PDB) tool and how we can use the Python logging framework to make complex applications written in Python easier to debug when they fail.

(For more resources related to this topic, see here.)

We will also look at the technique of unit testing and how the unittest Python module can be used to test small sections of a Python application to ensure that it is functioning as expected.

These techniques are commonly used in applications written in other languages and are good skills to learn if you are often going to be developing applications.

The Python debugger

PDB is a tool that allows real time debugging of running Python code. It can help to track down issues with the logic of a program to help find the cause of a crash or unexpected behavior.

PDB can be launched with the following command:

pdb2.7 do_calculaton.py

This will open a new PDB shell, as shown in the following screenshot:

We can use the continue command (which can be shortened to c) to execute the next section of the code until a breakpoint is hit. As we are yet to declare any breakpoints, this will run the script until it exits normally, as shown in the following screenshot:

We can set breakpoints in the application, where the program will be stopped, and you will be taken back to the PDB shell in order to debug the control flow of the program. The easiest way to set a breakpoint is by giving a specific line in a file, for example:

break Operation.py:7

This command will add a breakpoint on line 7 of Operation.py. When this is added, PDB will confirm the file and the line number, as shown in the following screenshot:

Now, when we run the application, we will see the program stop each time the breakpoint is reached. When a breakpoint is reached, we can resume the program using the c command:

When paused at a breakpoint, we can view the details of the local variables in the current scope. For example, in the breakpoint we have added, there is a variable named name, which we can see the value of by using the following command:

p name

This outputs the value of the variable, as shown in the following screenshot:

When at a breakpoint, we can also get a stack trace of the functions that have been called so far. This is done using the bt command and gives output like that shown in the following screenshot:

We can also modify the values of the variables when paused at a breakpoint. To do this, simply assign a value to the variable name as you would in a regular Python script:

name = 'subtract'

In the following screenshot, this was used to change the first operation in the do_calculation.py script from add to subtract; the effect on the calculation is seen in the different result value:

When at a breakpoint, we can also use the l command to see the current line the program is paused at. An example of this is shown in the following screenshot:

We can also setup a series of commands to be executed when we hit a breakpoint. This can allow debugging to be automated to an extent by automatically recording or modifying the values of the variables at certain points in the program's execution.

This can be demonstrated using the following commands on a new instance of PDB with no breakpoints set (first, quit PDB using the q command, and then re-launch it):

break Operation.py:7
commands
p name
c

This gives the following output. Note that the commands are entered on a terminal prefixed (com) rather than the PDB terminal prefixed (pdb).

This set of commands tells PDB to print the value of the name variable and continue execution when the last added breakpoint was hit. This gives the output shown in the following screenshot:

Within PDB, you can also use the ? command to get a full list of the available commands and help on using them, as shown in the following screenshot:

Further information and full documentation on PDB is available at https://docs.python.org/2/library/pdb.html.

Writing log files

The next technique we will look at is having our application output a log file. This allows us to get a better understanding of what was happening at the time an application failed, which can provide key information into finding the cause of the failure, especially when the failure is being reported by a user of your application.

We will add some logging statements to the Calculator.py and Operation.py files. To do this, we must first add the import for the logging module (https://docs.python.org/2/library/logging.html) to the start of each python file, which is simply:

import logging

In the Operation.py file, we will add two logging calls in the evaluate function, as shown in the following code:

def evaluate(self, a, b):
   logging.getLogger(__name__).info("Evaluating operation: %s" % (self._operation))
   logging.getLogger(__name__).debug("RHS: %f, LHS: %f" % (a, b))

This will output two logging statements: one at the debug level and one at the information level. There are in total five unique levels at which messages can be output. In increasing severity, they are:

• debug()
• info()
• warning()
• error()
• critical()

Log handlers can be filtered to only process the log messages of a certain severity if required. We will see this in action later in this section.

The logging.getLogger(__name__) call is used to retrieve the Logger class for the current module (where the name of the module is given by the __name__ variable). By default, each module uses its own Logger class identified by the name of the module.

Next, we can add some debugging statements to the Calculator.py file in the same way. Here, we will add logging to the enter_value, enter_operation, evaluate, and all_clear functions, as shown in the following code snippet:

def enter_value(self, value):
   if len(self._input_list) > 0 and not isinstance(self._input_list[-1], Operation):
       raise RuntimeError("Must enter an operation next")
   logging.getLogger(__name__).info("Adding value: %f" % (value))
   self._input_list.append(float(value))

def enter_operation(self, operation_name):
   if len(self._input_list) == 0 or isinstance(self._input_list[-1], Operation):
       raise RuntimeError("Must enter a value next")
   logging.getLogger(__name__).info("Adding operation: %s" % (operation_name))
   self._input_list.append(Operation(operation_name))

def evaluate(self):
   logging.getLogger(__name__).info("Evaluating calculation")
   if len(self._input_list) % 2 == 0:
       raise RuntimeError("Input length mismatch")
   self._result = self._input_list[0]
   for idx in range(1, len(self._input_list), 2):
       operation = self._input_list[idx]
       next_value = self._input_list[idx + 1]
       logging.getLogger(__name__).debug("Next function: %f %s %f" % (
           self._result, str(operation), next_value))
       self._result = operation.evaluate(self._result, next_value)
   logging.getLogger(__name__).info("Result is: %f" % (self._result))
   return self._result

def all_clear(self):
   logging.getLogger(__name__).info("Clearing calculator")
   self._input_list = []
   self._result = 0.0

Finally, we need to configure a handler for the log messages. This is what will handle the messages sent by each logger and output them to a suitable destination; for example, the standard output or a file.

We will configure this in the do_conversion.py file. First, we will configure a basic handler that will print all the log messages to the standard output so that they appear on the terminal. This can be achieved with the following code:

logging.basicConfig(level=logging.DEBUG)

We will also add the following line to the end of the script. This is used to close any open log handlers and should be included at the very end of an application (the logging framework should not be used after calling this function).

logging.shutdown()

Now, we can see the effects by running the script using the following command:

python do_calculation.py

This will give an output to the terminal, as shown in the following screenshot:

We can also have the log output written to a file instead of printed to the terminal by adding a filename to the logger configuration. This helps to keep the terminal free of unnecessary information.

logging.basicConfig(level=logging.DEBUG, filename='calc.log')

When executed, this will give no additional output other than the result of the calculation, but will have created an additional file, calc.log, which contains the log messages, as shown in the following screenshot:

Unit testing

Unit testing is a technique for automated testing of small sections ("units") of code to ensure that the components of a larger application are working as intended, independently of each other.

There are many frameworks for this in almost every language. In Python, we will be using the unittest module, as this is included with the language and is the most common framework used in the Python applications.

To add unit tests to our calculator module, we will create an additional module in the same directory named test. Inside that will be three files: __init__.py (used to denote that a directory is a Python package), test_Calculator.py, and test_Operation.py.

After creating this additional module, the structure of the code will be the same as shown in the following image:

Next, we will modify the test_Operation.py file to include a test case for the Operation class. As always, this will start with the required imports for the modules we will be using:

import unittest
from calculator.Operation import Operation

We will be creating a class, test_Operation, which inherits from the TestCase class provided by the unittest module. This contains the logic required to run the functions of the class as individual unit tests.

class test_Operation(unittest.TestCase):

Now, we will define four tests to test the creation of a new Operation instance for each of the operations that are supported by the class. Here, the assertEquals function is used to test for equality between two variables; this determines if the test passes or not.

   def test_create_add(self):
       op = Operation('add')
       self.assertEqual(str(op), 'add')

   def test_create_subtract(self):
       op = Operation('subtract')
       self.assertEqual(str(op), 'subtract')

   def test_create_multiply(self):
       op = Operation('multiply')
       self.assertEqual(str(op), 'multiply')

   def test_create_divide(self):
       op = Operation('divide')
       self.assertEqual(str(op), 'divide')

In this test we are checking that a RuntimeError is raised when an unknown operation is given to the Operation constructor. We will do this using the assertRaises function.

   def test_create_fails(self):
       self.assertRaises(ValueError,
                         Operation,
                         'not_a_function')

Next, we will create four tests to ensure that each of the known operations evaluates to the correct result:

   def test_add(self):
       op = Operation('add')
       result = op.evaluate(5, 2)
       self.assertEqual(result, 7)

   def test_subtract(self):
       op = Operation('subtract')
       result = op.evaluate(5, 2)
       self.assertEqual(result, 3)

   def test_multiply(self):
       op = Operation('multiply')
       result = op.evaluate(5, 2)
       self.assertEqual(result, 10)

   def test_divide(self):
       op = Operation('divide')
       result = op.evaluate(5, 2)
       self.assertEqual(result, 2)

This will form the test case for the Operation class. Typically, the test file for a module should have the name of the module prefixed by test, and the name of each test function within a test case class should start with test.

Next, we will create a test case for the Calculator class in the test_Calculator.py file. This again starts by importing the required modules and defining the class:

import unittest
from calculator.Calculator import Calculator
class test_Operation(unittest.TestCase):

We will now add two test cases that test the correct handling of errors when operations and values are entered in the incorrect order. This time, we will use the assertRaises function to create a context to test for RuntimeError being raised. In this case, the error must be raised by any of the code within the context.

   def test_add_value_out_of_order_fails(self):
       with self.assertRaises(RuntimeError):
           calc = Calculator()
           calc.enter_value(5)
           calc.enter_value(5)
           calc.evaluate()

   def test_add_operation_out_of_order_fails(self):
       with self.assertRaises(RuntimeError):
           calc = Calculator()
           calc.enter_operation('add')
           calc.evaluate()

This test is to ensure that the all_clear function works as expected. Note that, here, we have multiple test assertions in the function, and all assertions have to pass for the test to pass.

   def test_all_clear(self):
       calc = Calculator()
       calc.enter_value(5)
       calc.evaluate()
       self.assertEqual(calc.get_result(), 5)
       calc.all_clear()
       self.assertEqual(calc.get_result(), 0)

This test ensured that the evaluate() function works as expected and checks the output of a known calculation. Note, here, that we are using the assertAlmostEqual function, which ensures that two numerical variables are equal within a given tolerance, in this case 13 decimal places.

  def test_evaluate(self):
       calc = Calculator()
       calc.enter_value(5.0)
       calc.enter_operation('multiply')
       calc.enter_value(2.0)
       calc.enter_operation('divide')
       calc.enter_value(5.0)
       calc.enter_operation('add')
       calc.enter_value(18.0)
       calc.enter_operation('subtract')
       calc.enter_value(5.0)
       self.assertAlmostEqual(calc.evaluate(), 15.0, 13)
       self.assertAlmostEqual(calc.get_result(), 15.0, 13)

These two tests will test that the errors are handled correctly when the evaluate() function is called, when there are values missing from the input or the input is empty:

  def test_evaluate_failure_empty(self):
       with self.assertRaises(RuntimeError):
           calc = Calculator()
           calc.enter_operation('add')
           calc.evaluate()

   def test_evaluate_failure_missing_value(self):
       with self.assertRaises(RuntimeError):
           calc = Calculator()
           calc.enter_value(5)
           calc.enter_operation('add')
           calc.evaluate()

That completes the test case for the Calculator class.

Note that we have only used a small subset of the available test assertions over our two test classes. A full list of all the test assertions is available in the unittest module documentation at https://docs.python.org/2/library/unittest.html#test-cases.

Once all the tests are written, they can be executed using the following command in the directory containing both the calculator and tests directories:

python -m unittest discover -v

Here, we have the unit test framework discover all the tests automatically (which is why following the expected naming convention of prefixing names with "test" is important). We also request verbose output with the -v parameter, which shows all the tests executed and their results, as shown in the following screenshot:

Summary

In this article, we looked at how the PDB tool can be used to find faults in Python code and applications. We also looked at using the logging module to have Python code output a log file during execution and how this can make debugging the failures easier, as well as automated unit testing for portions of the application.

Resources for Article:

Further resources on this subject:

• Basic Image Processing[article]
• IRemote Desktop to Your Pi from Everywhere[article]
• Scraping the Data [article]