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:

import logging
logging.basicConfig()    # configs the logging instance

logging.debug('This is a DEBUG message')
logging.info('This is an INFO message')
logging.warning('This is a WARNING message')
logging.error('This is an ERROR message')
logging.critical('This is a CRITICAL message')

Executing that code will output the following messages:

[coe332-vm]$ 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:

import logging
logging.basicConfig(level='DEBUG')

logging.debug('This is a DEBUG message')
logging.info('This is an INFO message')
logging.warning('This is a WARNING message')
logging.error('This is an ERROR message')
logging.critical('This is a CRITICAL message')

[coe332-vm]$ 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.:

import argparse
import logging

parser = argparse.ArgumentParser()
parser.add_argument('-l', '--loglevel', type=str, required=False, default='WARNING',
                    help='set log level to DEBUG, INFO, WARNING, ERROR, or CRITICAL')
args = parser.parse_args()

logging.basicConfig(level=args.loglevel)

logging.debug('This is a DEBUG message')
logging.info('This is an INFO message')
logging.warning('This is a WARNING message')
logging.error('This is an ERROR message')
logging.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 (virtual) 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.

import argparse
import logging
import socket

parser = argparse.ArgumentParser()
parser.add_argument('-l', '--loglevel', type=str, required=False, default='WARNING',
                    help='set log level to DEBUG, INFO, WARNING, ERROR, or CRITICAL')
args = parser.parse_args()

format_str=f'[%(asctime)s {socket.gethostname()}] %(filename)s:%(funcName)s:%(lineno)s - %(levelname)s: %(message)s'
logging.basicConfig(level=args.loglevel, format=format_str)

logging.debug('This is a DEBUG message')
logging.info('This is an INFO message')
logging.warning('This is a WARNING message')
logging.error('This is an ERROR message')
logging.critical('This is a CRITICAL message')

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

[coe332-vm]$ python3 log_test.py -l CRITICAL
[2024-01-27 21:13:40,265 coe332-vm] 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 Meteorite Landings analysis script and associated functions we have been working on, add some logging, focusing on DEBUG and ERROR messages.

def compute_average_mass(landings: list[MeteoriteLanding]) -> float:
     """
     Iterates through a list of meteorite landing objects, adds their masses together
     and returns that sum divided by the total number or landings

     Args:
         landings: A list of meteorite landing objects

     Returns:
         result: Average value.
     """
     total_mass = 0.
     for ml in landings:
         total_mass += ml.mass
     return (total_mass / len(landings))

 def check_hemisphere(ml: MeteoriteLanding) -> str:
     """
     Given a meteorite landing's location (latitude and longitude in decimal notation),
     returns which hemispheres those coordinates land in.

     Args:
         ml: A MeteoriteLanding object

     Returns:
         location: Short string listing two hemispheres.
     """
     location = ''
     if (ml.location.lat > 0):
         location = 'Northern'
     else:
         location = 'Southern'
     if (ml.location.long > 0):
         location = f'{location} & Eastern'
     else:
         location = f'{location} & Western'
     return(location)

 def count_classes(landings: list[MeteoriteLanding]) -> dict[str, int]:
     """
     Iterates through a list of meteorite landing object and adds each class name
     as a key to a dictionary where the value of each key is the number of times
     this class appears in the dataset

     Args:
         landings: A list of MeteoriteLanding objects

     Returns:
         classes_observed: Dictionary of class counts.
     """
     classes_observed = {}
     for ml in landings:
         if ml.class_name not in classes_observed:
             classes_observed[ml.class_name] == 0

         classes_observed[ml.class_name] += 1
     return(classes_observed)

Additional Resources

• Python3 Logging How To Guide