Logging

What you'll learn

• Replace print with the logging module and understand why production code does
• Use the five levels and choose the right one for each message
• Configure logging once, at the program's entry point, with format, level, and destination
• Get a per-module logger with getLogger(__name__) and log exceptions with their tracebacks

Concept

print is for the person at the keyboard. Logging is for the program to report what it is doing in a way that can be turned up, turned down, filtered, timestamped, and sent somewhere other than the screen, without editing the code. A production service logs to files or a collector, at a level chosen at deploy time; the same code logs everything during development and only warnings in production. That flexibility is why every library and service in Python uses logging, and why a print in a library is considered a bug.

Every message has a level, and the configured threshold decides which get through. DEBUG is detail for diagnosing, INFO is normal operation, WARNING is something unexpected that the program handled, ERROR is a failure of one operation, CRITICAL is the program cannot continue. Setting the level to INFO hides DEBUG; setting it to WARNING hides both. Choosing the level honestly is what makes logs useful later: if everything is ERROR, nothing is.

Configure once, at the entry point, and never inside libraries or modules. logging.basicConfig(level=..., format=..., handlers=...) at the top of main sets the root logger; every module then calls logging.getLogger(__name__) and uses the result. The __name__ gives each module its own logger named after its import path, app.payments, so output shows where each line came from and levels can be set per module. Libraries never configure logging; they only emit, and the application decides what to do with it.

The format string decides what each line shows: time, level, logger name, message. Messages use %s placeholders with arguments passed separately, logger.info("served %s in %dms", path, ms), not an f-string, so the formatting work happens only if the message will actually be emitted. logger.exception(...) inside an except block logs at ERROR and appends the full traceback, which is how you record a failure without losing its cause. Handlers direct output: StreamHandler to the console, FileHandler to a file, RotatingFileHandler to files that roll over by size.

Code

From print to logging: the same program with levels, a format, and the threshold hiding DEBUG. The time is replaced with a fixed marker so the output is stable.

# levels.py
import logging

logging.basicConfig(level=logging.INFO, format="%(levelname)-8s %(name)s: %(message)s")
log = logging.getLogger("shop")

log.debug("loading %d products", 120)
log.info("server started on port %d", 8000)
log.warning("config file missing, using defaults")
log.error("payment %s failed: %s", 42, "card declined")
log.critical("database unreachable")
print("debug was hidden; four lines shown at INFO")

INFO     shop: server started on port 8000
WARNING  shop: config file missing, using defaults
ERROR    shop: payment 42 failed: card declined
CRITICAL shop: database unreachable
debug was hidden; four lines shown at INFO

Per-module loggers with __name__, and levels set for one module only. The db module is turned down to WARNING while the rest stays at DEBUG.

# app/__init__.py

# app/web.py
import logging

log = logging.getLogger(__name__)


def serve(path):
    log.debug("routing %s", path)
    log.info("served %s", path)

# app/db.py
import logging

log = logging.getLogger(__name__)


def query(sql):
    log.debug("running %s", sql)
    log.warning("slow query: %s", sql)

# main.py
import logging

from app import db, web

logging.basicConfig(level=logging.DEBUG, format="%(levelname)-8s %(name)s: %(message)s")
logging.getLogger("app.db").setLevel(logging.WARNING)

web.serve("/users")
db.query("SELECT * FROM users")
print(web.log.name, db.log.name)

DEBUG    app.web: routing /users
INFO     app.web: served /users
WARNING  app.db: slow query: SELECT * FROM users
app.web app.db

Logging an exception with its traceback, and writing to a file as well as the console. exception() records the failure and its cause in one call.

# exceptions_files.py
import logging
from pathlib import Path

log_path = Path("app.log")
log_path.unlink(missing_ok=True)

console = logging.StreamHandler()
console.setLevel(logging.WARNING)
file = logging.FileHandler(log_path, encoding="utf-8")
file.setLevel(logging.DEBUG)
logging.basicConfig(level=logging.DEBUG, format="%(levelname)s %(name)s: %(message)s", handlers=[console, file])
log = logging.getLogger("payments")

log.info("starting batch of %d", 2)
try:
    total = 100 / 0
except ZeroDivisionError:
    log.exception("batch failed on item %d", 1)

lines = log_path.read_text(encoding="utf-8").splitlines()
print("file has", len(lines), "lines; first:", lines[0])
print("traceback in file:", any("ZeroDivisionError" in ln for ln in lines))

ERROR payments: batch failed on item 1
Traceback (most recent call last):
  File "exceptions_files.py", line 16, in <module>
    total = 100 / 0
            ~~~~^~~
ZeroDivisionError: division by zero
file has 7 lines; first: INFO payments: starting batch of 2
traceback in file: True

Lazy formatting and a rotating file handler. The expensive repr is never computed for a hidden DEBUG line, and the rotating handler caps the log at a size and keeps backups.

# lazy_rotate.py
import logging
from logging.handlers import RotatingFileHandler
from pathlib import Path


class Expensive:
    calls = 0

    def __repr__(self):
        Expensive.calls += 1
        return "Expensive()"


handler = RotatingFileHandler("rotating.log", maxBytes=200, backupCount=2, encoding="utf-8")
logging.basicConfig(level=logging.INFO, format="%(message)s", handlers=[handler])
log = logging.getLogger("demo")

log.debug("hidden: %r", Expensive())
log.info("shown: %r", Expensive())
print("repr computed", Expensive.calls, "time(s)")

for i in range(30):
    log.info("line %02d of the rotating log ....", i)
print(sorted(p.name for p in Path(".").glob("rotating.log*")))

repr computed 1 time(s)
['rotating.log', 'rotating.log.1', 'rotating.log.2']

Try it yourself

Take organize.py from the file-organizer project and replace its hand-written log file with logging: a module-level log = logging.getLogger(__name__), INFO for each move, WARNING for each skipped file, and basicConfig in main with a --verbose flag that switches the level to DEBUG. Add a FileHandler so the moves still land in organize.log, and use log.exception where an OSError is caught.

Common mistakes

• print in a module or library. Callers cannot silence, redirect, or timestamp it; use a logger and let the application configure it.
• Configuring logging in a library. basicConfig belongs in the entry point only; a library that configures logging fights the application that imports it.
• f-strings in log calls. log.debug(f"{expensive()}") runs the formatting even when DEBUG is off; pass arguments and let logging format lazily.

What's next

• logging separates emitting messages from deciding what to show; configure once in main with basicConfig.
• Use the five levels honestly, getLogger(__name__) per module, %s arguments instead of f-strings, and log.exception for failures.
• Handlers send output to the console, a file, or rotating files, at their own levels.

Your programs can report what they do. Next you will handle the failures they report more deeply: exception chaining, tracebacks, warnings, and retries that give up on purpose.