Capturing errors and problems

An automated task's main characteristic is its fire-and-forget quality. We are not actively looking at the result, but making it run in the background.

Most of the recipes in this book deal with external information, such as web pages or other reports, so the likelihood of finding an unexpected problem when running it is high. This recipe will present an automated task that will safely store unexpected behaviors in a log file that can be checked afterward.

Getting ready

As a starting point, we'll use a task that will divide two numbers, as described in the command line.

This task is very similar to the one presented in step 5 of How it works for the Preparing a task recipe, earlier this chapter. However, instead of multiplying two numbers, we'll divide them.

How to do it...

1. Create the task_with_error_handling_step1.py file, as follows:

   import argparse
   import sys
   def main(number, other_number, output):
       result = number / other_number
       print(f'The result is {result}', file=output)
   if __name__ == '__main__':
       parser = argparse.ArgumentParser()
       parser.add_argument('-n1', type=int, help='A number', default=1)
       parser.add_argument('-n2', type=int, help='Another number', default=1)      
       parser.add_argument('-o', dest='output', type=argparse.FileType('w'),
                           help='output file', default=sys.stdout)
       args = parser.parse_args()
       main(args.n1, args.n2, args.output)
   

2. Execute it a couple of times to see that it divides two numbers:

   $ python3 task_with_error_handling_step1.py -n1 3 -n2 2
   The result is 1.5
   $ python3 task_with_error_handling_step1.py -n1 25 -n2 5
   The result is 5.0
   

3. Check that dividing by 0 produces an error, and that the error is not logged on the result file:

   $ python task_with_error_handling_step1.py -n1 5 -n2 1 -o result.txt
   $ cat result.txt
   The result is 5.0
   $ python task_with_error_handling_step1.py -n1 5 -n2 0 -o result.txt
   Traceback (most recent call last):
    File "task_with_error_handling_step1.py", line 20, in <module>
    main(args.n1, args.n2, args.output)
    File "task_with_error_handling_step1.py", line 6, in main  result = number / other_number
   ZeroDivisionError: division by zero
   $ cat result.txt
   

4. Create the task_with_error_handling_step4.py file:

   import argparse
   import sys
   import logging
   LOG_FORMAT = '%(asctime)s %(name)s %(levelname)s %(message)s'
   LOG_LEVEL = logging.DEBUG
   def main(number, other_number, output):
       logging.info(f'Dividing {number} between {other_number}')
       result = number / other_number
       print(f'The result is {result}', file=output)
   if __name__ == '__main__':
       parser = argparse.ArgumentParser()
       parser.add_argument('-n1', type=int, help='A number', default=1)
       parser.add_argument('-n2', type=int, help='Another number', default=1)
       parser.add_argument('-o', dest='output', type=argparse.FileType('w'),
                           help='output file', default=sys.stdout)
       parser.add_argument('-l', dest='log', type=str, help='log file',
                           default=None)
       args = parser.parse_args()
       if args.log:
           logging.basicConfig(format=LOG_FORMAT, filename=args.log,
                               level=LOG_LEVEL)
       else:
           logging.basicConfig(format=LOG_FORMAT, level=LOG_LEVEL)
       try:
           main(args.n1, args.n2, args.output)
       except Exception as exc:
           logging.exception("Error running task")
           exit(1)
   

5. Run it to check that it displays the proper INFO and ERROR logs, and that it stores it on the log file:

   $ python3 task_with_error_handling_step4.py -n1 5 -n2 0
   2020-01-19 14:25:28,849 root INFO Dividing 5 between 0
   2020-01-19 14:25:28,849 root ERROR division by zero
   Traceback (most recent call last):
     File "task_with_error_handling_step4.py", line 31, in <module>
       main(args.n1, args.n2, args.output)
     File "task_with_error_handling_step4.py", line 10, in main
       result = number / other_number
   ZeroDivisionError: division by zero
   $ python3 task_with_error_handling_step4.py -n1 5 -n2 0 -l error.log
   $ python3 task_with_error_handling_step4.py -n1 5 -n2 0 -l error.log
   $ cat error.log
   2020-01-19 14:26:15,376 root INFO Dividing 5 between 0
   2020-01-19 14:26:15,376 root ERROR division by zero
   Traceback (most recent call last):
     File "task_with_error_handling_step4.py", line 33, in <module>
       main(args.n1, args.n2, args.output)
     File "task_with_error_handling_step4.py", line 11, in main
       result = number / other_number
   ZeroDivisionError: division by zero
   2020-01-19 14:26:19,960 root INFO Dividing 5 between 0
   2020-01-19 14:26:19,961 root ERROR division by zero
   Traceback (most recent call last):
     File "task_with_error_handling_step4.py", line 33, in <module>
       main(args.n1, args.n2, args.output)
     File "task_with_error_handling_step4.py", line 11, in main
       result = number / other_number
   ZeroDivisionError: division by zero
   

How it works...

To properly capture any unexpected exceptions, the main function should be wrapped in a try-except block, as implemented in step 4 of the How to do it… section. Compare this to how step 1 does not wrap the code:

    try:
        main(...)
    except Exception as exc:
        # Something went wrong
        logging.exception("Error running task")
        exit(1)

Note that logging the exception is important for getting information on what went wrong.

This kind of exception is nicknamed Pokémon Exception because it can catch 'em all. It will capture any unexpected error at the highest level. Do not use it in other areas of the code, as capturing everything can hide unexpected errors. At the very least, any unexpected exception should be logged to allow for further analysis.

The extra step, to exit with status 1 by using the exit(1) call, informs the operating system that something went wrong with our script.

The logging module allows us to log. Note the basic configuration, which includes an optional file to store the logs, the format, and the level of the logs to display.

The available levels for logs are—from less critical to more critical—DEBUG, INFO, WARNING, ERROR, and CRITICAL. The logging level will set the minimum severity required to log the message. For example, an INFO log won't be stored if the severity is set to WARNING.

Creating logs is easy. You can do this by making a call to the logging.<logging level> method (where the logging level is debug, info, and so on). For example:

>>> import logging
>>> logging.basicConfig(level=logging.INFO)
>>> logging.warning('a warning message')
WARNING:root:a warning message
>>> logging.info('an info message')
INFO:root:an info message
>>> logging.debug('a debug message')
>>>

Note how logs with a severity lower than INFO are not displayed. Use the level definition to tweak how much information to display. This may change, for example, how DEBUG logs may be used only while developing the task, but not be displayed when running it. Notice that task_with_error_handling_step4.py defines the logging level to be DEBUG, by default.

A good definition of log levels is key to displaying relevant information while reducing noise. It is not easy to set up sometimes, but especially if more than one person is involved, try to agree on exactly what WARNING versus ERROR means to avoid misinterpretations.

logging.exception() is a special case that will create an ERROR log, but it will also include information about the exception, such as the stack trace.

Remember to check logs to discover errors. A useful reminder is to add a note to the results file, like this:

try:
    main(args.n1, args.n2, args.output)
except Exception as exc:
    logging.exception(exc)
    print('There has been an error. Check the logs', file=args.output)

There's more...

The Python logging module has many capabilities, including the following:

• It provides further tweaks to the format of the log, for example, including the file and line number of the log that was produced.
• It defines different logger objects, each one with its own configuration, such as logging level and format. This allows us to publish logs to different systems in different ways, though, normally, a single logger object is used to keep things simple.
• It sends logs to multiple places, such as the standard output and file, or even a remote logger.
• It automatically rotates logs, creating new log files after a certain time or size. This is handy for keeping logs organized by day or week. It also allows for the compression or removal of old logs. Logs take up space when they accumulate.
• It reads standard logging configurations from files.

Instead of creating complex rules on what to log, try to log extensively using the proper level for each, and then filter by level.

For comprehensive details, refer to the Python documentation of the module at https://docs.python.org/3.8/library/logging.html, or the tutorial at https://docs.python.org/3.8/howto/logging.html.

See also

• The Adding command-line options recipe in Chapter 1, Let's Begin Our Automation Journey, to describe the basic elements of the command-line options.
• The Preparing a task recipe, covered earlier in the chapter, to learn about the strategy to follow when designing an automated task.