Debugging and Logging

Ava's program says a customer owes eleven dollars, but the correct amount is nine. Somewhere in the code, a number goes wrong. Panicking does not help. A good debugger works like a detective, forming a theory, checking the evidence, and narrowing down the place. And a program that logs what it does leaves a trail of clues.

• The total is wrong, but where?
• Work like a detective
• Leave a trail with logging

Print debugging, done well

The simplest tool is print. Show the values of important variables at key points. Use the f string with an equals sign, which prints the name and the value together. Here, a bug hides in the loop, and printing reveals that the total starts from the wrong number, and the discount is applied twice.

def total(prices, discount):
    t = 1
    for p in prices:
        t += p
        print(f"{p=} {t=}")
    return t - discount

print(total([4, 5], 0))

p=4 t=5
p=5 t=10
10

Reading the evidence: the bug fixed

The prints show that the total started at one, instead of zero. That is the bug. A theory, evidence, and a fix. After the fix, the answer is nine, as expected. Remove the debug prints afterwards, or better, turn them into proper logging. Always rerun your tests after fixing.

def total(prices, discount):
    t = 0
    for p in prices:
        t += p
    return t - discount

print(total([4, 5], 0))

9

The debugger: pdb

Python has a built in debugger called pdb. Call the breakpoint function, and the program pauses there. You can print variables, step line by line with n, step into a call with s, continue with c, and quit with q. Editors such as VS Code and PyCharm give you the same power with a click, and a visual interface.

The logging module

For real programs, use the logging module instead of print. Messages have levels, debug, info, warning, error, and critical. You choose which level to show. You can add timestamps and names to each line, and send them to a file. In production you turn the debug noise down, without touching the code.

import logging

logging.basicConfig(level=logging.INFO, format="%(levelname)s: %(message)s")
log = logging.getLogger("leafy")

log.debug("hidden: debug level")
log.info("order received")
log.warning("stock is low")
try:
    1 / 0
except ZeroDivisionError:
    log.exception("calculation failed")

INFO: order received
WARNING: stock is low
ERROR: calculation failed
Traceback (most recent call last):
  File "/privatelogging1.py", line 10, in <module>
    1 / 0
    ~~^~~
ZeroDivisionError: division by zero

Choosing the log level

Choose levels with care. Debug is for developers, in detail. Info records normal events, like an order was placed. Warning means something unexpected, but the program continues. Error means a task failed. Critical means the whole program may stop. A good log tells the story of what happened, without drowning you in noise.

Log the shop opening

Your turn. Configure logging at the info level. Create a logger, and log an info message when the shop opens, and a warning when the stock is low. Ready? Here is one solution. Basic config, a named logger, and two calls.

import logging

logging.basicConfig(level=logging.INFO, format="%(levelname)s: %(message)s")
log = logging.getLogger("shop")
log.info("shop open")
log.warning("low stock")

INFO: shop open
WARNING: low stock

Summary