Python Logging

3Python Logging: explained step by step

Every beginner debugs with print(). It works until the program grows: you cannot switch the messages off without deleting them, you cannot tell a harmless note from a disaster, and nothing says which part of the program spoke. The standard logging module fixes all three. You write log calls once, give each a severity level, and decide later, in one place, what to show and where to send it. If you already know modules and exceptions, you are ready.

Logging levels from DEBUG to CRITICAL

Every message has a level, and every level is a number. A logger shows a message only when its level is at least the configured threshold.

import logging

for name in ["DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"]:
    print(f"{name:<9}{getattr(logging, name)}")

Use DEBUG for details only a developer needs, INFO for normal milestones ("loaded 120 rows"), WARNING for something odd that the program survived, ERROR when an operation failed, and CRITICAL when the whole program may not continue. Set the threshold to WARNING in production and to DEBUG while hunting a bug, without touching a single log call.

Why logging.info shows nothing: the default WARNING level

The root logger starts with the threshold WARNING, so debug() and info() are silently dropped. logging.basicConfig() sets the threshold, the message layout and the destination. Here stream=sys.stdout sends output to the normal output (the default is stderr), and force=True replaces any earlier configuration so the example behaves the same every time you run it.

import logging
import sys

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

logging.debug("cache contents: {}")
logging.info("server started")
logging.warning("disk is 91 percent full")
logging.error("could not save report")

The debug line is missing because DEBUG (10) is below the INFO (20) threshold. The format string uses fields such as %(levelname)s, %(name)s and %(message)s; in real programs you would usually add %(asctime)s for a timestamp, which these lessons leave out so the output stays identical on every run.

Named loggers and the logger hierarchy

Instead of the root logger, each module should create its own with logging.getLogger(__name__). Names are separated by dots, and that forms a tree: "shop.cart" is a child of "shop". A child passes its records up to its parents, so one handler on the root can serve the whole program, and the %(name)s field tells you which part spoke.

import logging
import sys

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

cart = logging.getLogger("shop.cart")
payment = logging.getLogger("shop.payment")
logging.getLogger("shop.payment").setLevel(logging.ERROR)

cart.info("added 2 items")
payment.info("card checked")
payment.error("card declined")
print(cart.parent.name, payment.getEffectiveLevel(), cart.getEffectiveLevel())

Setting a level on shop.payment quiets only that branch. A logger with no level of its own uses the level of the nearest parent, which is why cart still logs at INFO.

Handlers and formatters send logs anywhere

A handler decides where records go and a formatter decides how they look. One logger can feed several handlers, each with its own level: show warnings on the screen but keep everything in a file. The in-browser file system is temporary, but the code is identical to what you would write on your own computer.

import logging
import sys

log = logging.getLogger("app")
log.handlers.clear()
log.setLevel(logging.DEBUG)
log.propagate = False

screen = logging.StreamHandler(sys.stdout)
screen.setLevel(logging.WARNING)
screen.setFormatter(logging.Formatter("%(levelname)s: %(message)s"))

journal = logging.FileHandler("app.log", mode="w")
journal.setFormatter(logging.Formatter("%(levelname)s:%(name)s:%(message)s"))

log.addHandler(screen)
log.addHandler(journal)

log.debug("opening config")
log.warning("config key missing, using default")
journal.close()

print("--- file ---")
with open("app.log") as f:
    print(f.read().strip())

The logger threshold (DEBUG) is checked first and the handler threshold second, so the screen shows one line while the file keeps both. Reading the file back uses a plain with statement and the ideas from file handling.

Log a traceback with logger.exception

Inside an except block, logger.exception("message") logs at ERROR level and appends the full traceback. That is far more useful than print(err), because it shows where the failure happened. The traceback contains file paths, so this demo captures the output in a StringIO and prints only the first and last lines.

import io
import logging

buffer = io.StringIO()
log = logging.getLogger("importer")
log.handlers.clear()
log.propagate = False
log.addHandler(logging.StreamHandler(buffer))

try:
    price = float("12,50")
except ValueError:
    log.exception("bad price in row 7")

lines = buffer.getvalue().splitlines()
print(lines[0])
print(lines[-1])
print(len(lines) > 2)

Pass values as arguments, not f-strings

logger.info("loaded %d rows from %s", count, name) hands the template and the values to the logger separately, and formatting only happens if the message is actually emitted. With an f-string Python builds the text every time, even for a DEBUG message that is switched off. Use %s, %d and %r in log calls; it is the one place where this older style is still the recommended choice.

Capture logs with StringIO in tests

Because handlers accept any stream, a test can attach one that writes to io.StringIO, run the code, and compare the text. The testing lesson builds on this idea.

import io
import logging

def make_logger(stream):
    log = logging.getLogger("checkout")
    log.handlers.clear()
    log.setLevel(logging.INFO)
    log.propagate = False
    handler = logging.StreamHandler(stream)
    handler.setFormatter(logging.Formatter("%(levelname)s:%(message)s"))
    log.addHandler(handler)
    return log

def apply_discount(total, code, log):
    if code == "SAVE10":
        log.info("discount %s applied to %.2f", code, total)
        return round(total * 0.9, 2)
    log.warning("unknown discount code %r", code)
    return total

stream = io.StringIO()
log = make_logger(stream)
print(apply_discount(50, "SAVE10", log), apply_discount(50, "FREE", log))
print(stream.getvalue().splitlines())

Two common logging traps

basicConfig() does nothing if the root logger already has handlers, and calling logging.warning() before it configures logging implicitly, so a later basicConfig(level=DEBUG) is ignored unless you pass force=True. The second trap is adding a handler inside a function that runs repeatedly: every call stacks another handler and each message is printed again and again. Configure logging once, at startup.