Logging#
Logging is the act of keeping track of events that occur in a program and storing a message for each such event in a log file.
Print debugging#
A widespread approach to debug a program is the so-called print-debugging, where various print() statements are inserted ad-hoc to identify and understand the code responsible for the misbehavior. In most cases the print calls are removed once the bug has been fixed, as they often interfere with the normal running of the code. Given that the next debugging session is just around the corner, it would be better to leave judiciously placed print statements and enable them when needed.
Debug flag#
The simplest implementation of such a toggle is a debug flag and an optional print wrapper.
DEBUG = True # constant to toggle printing of debug messages
def print_debug(msg):
if DEBUG:
print(f"DEBUG: {msg}")
for i in range(0, 10):
print_debug(f"Loop index {i}")
Debug level#
One can also introduce different debug levels to control the verbosity of the log messages.
DEBUG_LVL = 1 # 0: no log, 1: some log, 2: verbose log
if DEBUG_LVL >= 1:
print("Starting Loop")
for i in range(0, 10):
if DEBUG_LVL >= 2:
print(f"Loop index {i}")
Logging#
The logging module is the Python built-in facility to handle log messages. Many third-party libraries use it under the hood, so it’s helpful to understand how it works and can be configured.
Log levels#
Multiple log levels allow to filter messages by severity: debug (10) < info (20) < warning (30) < error (40) < critical (50). By default debug and info messages are not shown, unless the log level is increased. When calling the logging methods directly (rather than creating a named logger as shown below), the behavior can be customized via logging.basicConfig. In particular we want to adapt the log format to include a timestamp and the name of the log level. Optionally all log messages can be redirected to a log file instead of being streamed to stderr.
import logging
logging.basicConfig(
level=logging.DEBUG, # set log level (default: logging.WARNING)
format="{asctime} {levelname} {message}", # log message format
datefmt="%Y-%m-%dT%H:%M:%S%z", # format timestamps as ISO 8601
style="{", # format string given in f-string style
# filename="app.log", # write to log file instead of stderr
# filemode="w", # write new log file instead of appending to old
)
logging.debug("detailed output for diagnostic purposes")
logging.info("typical events that occur during normal operation")
logging.warning("warn that something unusual happened")
logging.error("a serious problem occured but the program can continue")
logging.critical("a critical condition that must be investigated")
The above generates the following log output.
2025-02-24T15:50:24+0100 DEBUG detailed output for diagnostic purposes
2025-02-24T15:50:24+0100 INFO typical events that occur during normal operation
2025-02-24T15:50:24+0100 WARNING warn that something unusual happened
2025-02-24T15:50:24+0100 ERROR a serious problem occured but the program can continue
2025-02-24T15:50:24+0100 CRITICAL a critical condition that must be investigated
When logging errors related to exceptions, the full traceback can be included in the log entry.
import logging
try:
1 / 0
except Exception:
logging.exception("an exception occured with the following traceback")
Verbosity command-line argument#
Instead of having to edit the code to modify the log level, one can use command-line arguments -v, -vv, -vvv to increase the verbosity of the log messages.
import argparse
import logging
parser = argparse.ArgumentParser(description=__doc__)
parser.add_argument("-v", help="verbosity (-v, -vv, -vvv)", action="count", default=0)
args = parser.parse_args()
LOGLVL = (4 - args.v) * 10 # default (error), -v (warning), -vv (info), -vvv (debug)
logging.basicConfig(level=LOGLVL)
logging.debug("detailed output for diagnostic purposes")
logging.info("typical events that occur during normal operation")
logging.warning("warn that something unusual happened")
logging.error("a serious problem occured but the program can continue")
logging.critical("a critical condition that must be investigated")
Named logger#
Logging is performed by calling methods on instances of the Logger class. The instances have names and are arranged in a hierarchy, with the root logger being on top. Named loggers allow to handle multiple file handles or streams.
The following example sends severity error and above to stderr, but all messages to a debug log file.
import logging
# Get or create logger instance with given name.
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
# Set log format.
log_formatter = logging.Formatter(
datefmt="%Y-%m-%dT%H:%M:%S%z",
fmt="{asctime} {levelname}: {message}",
style="{",
)
# Set log to stderr.
handler_console = logging.StreamHandler()
handler_console.setFormatter(log_formatter)
handler_console.setLevel(logging.ERROR)
logger.addHandler(handler_console)
# Set log to file.
handler_file = logging.FileHandler("debug.log")
handler_file.setFormatter(log_formatter)
logger.addHandler(handler_file)
logger.debug("detailed output for diagnostic purposes")
logger.info("typical events that occur during normal operation")
logger.warning("warn that something unusual happened")
logger.error("a serious problem occured but the program can continue")
logger.critical("a critical condition that must be investigated")
Tracing#
Tracing is the act of watching the flow of execution of a program. In contrast to print debugging, where only a few print statements provide selective insight into the program’s flow, tracing follows all calls. The trace module allows to trace Python statement execution without much effort and can provide valuable debugging info.
$ python3 -m trace -t myscript.py # trace executed lines
$ python3 -m trace -l myscript.py # list executed functions
If the output is too overwhelming it can help to filter out calls to the standard library by ignoring those directories.
$ python3 -m trace --ignore-dir=$(python3 -c 'import sys; print(":".join(sys.path)[1:])') -t myscript.py