Logging

Logging#

As your Python3 applications grow in complexity, so too does your need to be able to track what is going on in the code during run time. Logging can be used to track arbitrary events as the code runs. As we will see, logging will be useful to keep track of the progression of your code, and it will also be useful to help us track what parts of our code are causing errors. This is especially useful when working with multiple applications across distributed systems. After going through this module, students should be able to:

  • Import the logging module into their Python3 scripts

  • Set log level to either DEBUG, INFO, WARNING, ERROR, or CRITICAL

  • Write appropriate log messages for each log level

  • Read output logs and track warnings / errors back to specific spots in their code

Log Levels#

Many of us have probably used arbitrary print statements in our code as a means to debug errors. Yes, there is a better way! The Python3 logging module, part of the Standard Library, provides functions for reporting different types of events that occur during run time. Save print statements for printing out the normal things that the code is supposed to display, and use exceptions to interrupt the code when it encounters errors. Use logging for everything else, including:

  • Printing detailed information about normal things that are supposed to occur, but should not be in the standard output

  • Printing warnings about particular run time events

  • Printing when an error has occurred but was suppressed by, e.g., an error handler.

Log levels are used to distinguish between the severity or importance of the different events. Using different log levels, you can always leave the log statements which print useful information in your code, but toggle them on and off depending on which level of severity you want to monitor. The standard log levels and their purposes are:

  • DEBUG: Detailed information, typically of interest only when diagnosing problems

  • INFO: Confirmation that things are working as expected.

  • WARNING: An indication that something unexpected happened, or indicative of some problem in the near future (e.g. ‘disk space low’). The software is still working as expected.

  • ERROR: Due to a more serious problem, the software has not been able to perform some function.

  • CRITICAL: A serious error, indicating that the program itself may be unable to continue running.

(Source: Python Docs https://docs.python.org/3/howto/logging.html)

Initialize Logging#

Let’s work through an example. Add the following lines to a script called, e.g. log_test.py:

1import logging
2logging.basicConfig()    # configs the logging instance
3
4logging.debug('This is a DEBUG message')
5logging.info('This is an INFO message')
6logging.warning('This is a WARNING message')
7logging.error('This is an ERROR message')
8logging.critical('This is a CRITICAL message')

Executing that code will output the following messages:

[terminal]$ python3 log_test.py
WARNING:root:This is a WARNING message
ERROR:root:This is an ERROR message
CRITICAL:root:This is a CRITICAL message

By default, the log level is set to WARNING, and only messages that are WARNING or higher in level of severity will be printed to screen.

If you set a lower log level, e.g. to DEBUG, all levels of log messages will be printed:

1import logging
2logging.basicConfig(level='DEBUG')
3
4logging.debug('This is a DEBUG message')
5logging.info('This is an INFO message')
6logging.warning('This is a WARNING message')
7logging.error('This is an ERROR message')
8logging.critical('This is a CRITICAL message')

[terminal]$ python3 log_test.py
DEBUG:root:This is a DEBUG message
INFO:root:This is an INFO message
WARNING:root:This is a WARNING message
ERROR:root:This is an ERROR message
CRITICAL:root:This is a CRITICAL message

An even better set up would be to enable the option to pass the desired log level on the command line when you execute the code. E.g.:

 1import argparse
 2import logging
 3
 4parser = argparse.ArgumentParser()
 5parser.add_argument('-l', '--loglevel', type=str, required=False, default='WARNING',
 6                    help='set log level to DEBUG, INFO, WARNING, ERROR, or CRITICAL')
 7args = parser.parse_args()
 8
 9logging.basicConfig(level=args.loglevel)
10
11logging.debug('This is a DEBUG message')
12logging.info('This is an INFO message')
13logging.warning('This is a WARNING message')
14logging.error('This is an ERROR message')
15logging.critical('This is a CRITICAL message')

Tip

Try running the above code with and without the -l flag on the command line.

What to Include in a Log#

As we work toward systems in which we are running multiple applications distributed over remote systems, it is important to be mindful of what sort of log information will be useful. In particular, it would be a good idea to be able to gather information about:

  • Timestamp: when the error occurred, also acts as a good reference point when referring to a specific log message

  • Hostname: what machine the error occurred on, as you may have multiple instances of an application running on different machines

  • Locale: what script and/or what function did the message originate from, helps to pinpoint where the message is coming from

To include some of this information in a log message, we need to specify a little more information in the basic config. We also need to import the socket module from the Standard Library so we can grab information about the hostname from the environment. We also will be calling a few other of the logging formatter’s pre-defined macros.

 1import argparse
 2import logging
 3import socket
 4
 5parser = argparse.ArgumentParser()
 6parser.add_argument('-l', '--loglevel', type=str, required=False, default='WARNING',
 7                    help='set log level to DEBUG, INFO, WARNING, ERROR, or CRITICAL')
 8args = parser.parse_args()
 9
10format_str=f'[%(asctime)s {socket.gethostname()}] %(filename)s:%(funcName)s:%(lineno)s - %(levelname)s: %(message)s'
11logging.basicConfig(level=args.loglevel, format=format_str)
12
13logging.debug('This is a DEBUG message')
14logging.info('This is an INFO message')
15logging.warning('This is a WARNING message')
16logging.error('This is an ERROR message')
17logging.critical('This is a CRITICAL message')

[terminal]$ python3 log_test.py
[2024-01-27 21:13:36,258 terminal] log_test.py:<module>:15 - WARNING: This is a WARNING message
[2024-01-27 21:13:36,258 terminal] log_test.py:<module>:16 - ERROR: This is an ERROR message
[2024-01-27 21:13:36,258 terminal] log_test.py:<module>:17 - CRITICAL: This is a CRITICAL message

[terminal]$ python3 log_test.py -l CRITICAL
[2024-01-27 21:13:40,265 terminal] log_test.py:<module>:17 - CRITICAL: This is a CRITICAL message

Later in the semester, most of the work we will do will be containerized. It is a little difficult to retrieve log files from inside containers, especially if they crash with an error. An easy work around is to use logging to print to standard out (as above), and those messages will end up in the container logs from which they are easily extracted.

EXERCISE#

Given the groceries script we have been working on, add some logging throughout the script, focusing on DEBUG and ERROR messages.

 1#!/usr/bin/env python3
 2 import json
 3
 4 def compute_average_quantity(a_list_of_dicts, a_key_string)-> float:
 5     """
 6     Iterate through a list of dictionaries, pulling out values associated with
 7     a given key. Returns the average of those values.
 8
 9     Args:
10         a_list_of_dicts (list): A list of dictionaries, each dict should have the
11                                 same set of keys.
12         a_key_string (string): A key that appears in each dictionary associated
13                             with the desired value( will enforce float type).
14
15     Returns:
16         result (float): Average value.
17     """
18
19     total_quantity = 0
20     for item in a_list_of_dicts:
21         total_quantity += item[ a_key_string ]
22
23     return int( total_quantity / len( a_list_of_dicts ) )
24
25 def calc_total_price( price, quantity )-> float:
26     """
27     Given a price and quantity, calculate to total price of items in stock and return
28     the calculated amount.
29
30     Args:
31         price (float): price of an item
32         quantity (float): amount of an item the grocery store has in stock
33
34     Returns:
35         total_price (float): total calculated price of item.
36     """
37
38     total_price = price * quantity
39     return total_price
40
41 def count_categories(a_list_of_dicts, a_key_string)-> dict:
42     """
43     Iterate through a list of dictionaries, counting the number of times
44     a particular category is found in the list. Returns a count of all
45     categories found and their amount.
46
47     Args:
48         a_list_of_dicts (list): A list of dictionaries, each dict should have the
49                                 same set of keys.
50         a_key_string (string): A key that appears in each dictionary associated
51                             string to check for counting.
52
53     Returns:
54         categories_observed(dict): categories and their count.
55     """
56
57     categories_observed = {}
58     for item in a_list_of_dicts:
59         if item[a_key_string] in categories_observed:
60             categories_observed[item[a_key_string]] += 1
61         else:
62             categories_observed[item[a_key_string]] = 1
63     return(categories_observed)
64
65 def main():
66     with open('groceries.json', 'r') as f:
67         grocery_data = json.load( f )
68
69     print( compute_average_quantity( grocery_data['items'], 'quantity' ) )
70
71     for row in grocery_data['items']:
72         total_price = calc_total_price( float( row['price']), float( row['quantity'] ) )
73         print(f'Total Price: {total_price:.2f}')
74
75     print( count_categories( grocery_data['items'], 'category' ) )
76
77 if __name__ == '__main__':
78     main()

Additional Resources#

Contents