lesson 118 Debugging & Logging · intermediate

Log with the logging module

Prints are for the person running a script; logs are for whoever has to find out later what it did. The logging module adds levels, names and a consistent format, and lets you turn detail up or down without editing code.

You'll be able to

Get a logger per module with logging.getLogger(__name__)
Pick DEBUG, INFO, WARNING or ERROR for a message, and filter by level
Configure the output once, in the program's entry point, with basicConfig

The idea

A nightly import runs with nobody watching. When finance asks why yesterday's numbers are low, the program's output is all you have. Logging writes messages that carry a level (how serious), the name of the part of the program that wrote them, and a consistent format, often with a time stamp.

The five levels, from least to most serious: DEBUG (detail for diagnosing), INFO (normal progress), WARNING (something odd, but the program carries on), ERROR (an operation failed), CRITICAL (the program can't go on). The configured level is a threshold: at INFO, DEBUG messages are dropped and everything else is shown.

logging.basicConfig sets this up once. Real programs leave logs on the error stream (the default); the examples pass stream=sys.stdout only so the lines appear in the output shown here, and force=True replaces any setup from an earlier run of the page.

Run each example to see what it prints. Running examples doesn't count toward progress.

example-1.py · Levels, names and a format

import logging
import sys

logging.basicConfig(stream=sys.stdout, level=logging.INFO, format="%(levelname)s %(name)s: %(message)s", force=True)
log = logging.getLogger("invoices")

log.debug("raw line: %s", "489434,12,2.55")
log.info("loaded %d lines from %s", 3, "march.csv")
log.warning("line %d has no customer id", 2)
log.error("could not parse quantity %r", "six")

Each module gets its own logger with logging.getLogger(__name__). __name__ is the module's import name (see Modules & Packages), so log lines say which file they came from, and you can turn detail up for one module only. Modules only *get* loggers; the program you run configures logging, once.

example-2.py · A logger per module

import logging
import sys
from pathlib import Path

Path("pricing.py").write_text('''import logging

log = logging.getLogger(__name__)

def line_total(quantity, unit_price):
    log.debug("pricing %s x %s", quantity, unit_price)
    if quantity < 0:
        log.warning("negative quantity %s treated as a return", quantity)
    return quantity * unit_price
''')

import pricing

logging.basicConfig(stream=sys.stdout, level=logging.INFO, format="%(levelname)s %(name)s: %(message)s", force=True)
log = logging.getLogger(__name__)

log.info("pricing two lines")
print(pricing.line_total(12, 2.5), pricing.line_total(-1, 4.95))
logging.getLogger("pricing").setLevel(logging.DEBUG)
log.info("detail switched on for pricing only")
print(pricing.line_total(2, 3.0))

When to use it: anything that runs unattended, or long enough that you'd want a record. Keep print for output that *is* the program's result (a report on screen).

Mistakes to avoid: calling basicConfig inside a module that others import (only the entry point configures); calling it a second time and expecting a change (without force=True the second call does nothing); logging everything at INFO so warnings drown; and building the message with an f-string when the arguments form is available, which formats text even for lines that are filtered out.

Review

log = logging.getLogger(__name__) in every module; configure once in the entry point with basicConfig.
Levels: DEBUG, INFO, WARNING, ERROR, CRITICAL; the configured level is a threshold, per logger if needed.
Pass values as arguments (log.info("loaded %d", n)); keep print for the program's actual output.
Next: logging an exception together with its traceback.

Practise this