Logging instead of print

A print shows a message and nothing else: no severity, no source, no way to turn it off without editing the code. The logging module gives each message a level, sends it where you choose, and lets you change how much is shown without touching the code that produced it. The beginner debugging lesson used print to see values. Logging is the permanent version of that habit.

Levels and basicConfig

There are five standard levels, from least to most severe: DEBUG (10), INFO (20), WARNING (30), ERROR (40) and CRITICAL (50). Use them like this:

• DEBUG: details for whoever is diagnosing a problem.
• INFO: normal events worth recording, such as “server started”.
• WARNING: something unexpected, but the program carried on.
• ERROR: an operation failed.
• CRITICAL: the program cannot continue.

logging.basicConfig sets up the output in one call. Here it sends everything from DEBUG upward to standard output, with a custom line format:

import logging
import sys

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

logging.debug("reading settings")
logging.info("server started on port %d", 8080)
logging.warning("disk is %d%% full", 91)
logging.error("could not open %s", "report.csv")
logging.critical("out of memory")

DEBUG:root:reading settings
INFO:root:server started on port 8080
WARNING:root:disk is 91% full
ERROR:root:could not open report.csv
CRITICAL:root:out of memory

root is the name of the default logger, used by the module-level functions. The format string uses %(...)s fields, and %(asctime)s for a timestamp is one you will add in real programs. The values after the message (8080, 91) fill the %d placeholders. We will see below why they are not an f-string.

Without any configuration, the root logger shows only WARNING and above, on standard error, as a bare message. That is why a forgotten logging.info(...) seems to do nothing.

The level decides what gets through

Each logger has a level, and messages below it are dropped. Changing the level changes the volume without editing a single log call. This script emits the same four messages three times and raises the verbosity in between:

import logging
import sys

logging.basicConfig(stream=sys.stdout, format="%(levelname)-8s %(message)s")
log = logging.getLogger("demo")


def emit_all():
    log.debug("a detail for developers")
    log.info("a normal event")
    log.warning("something unexpected, but handled")
    log.error("an operation failed")


print("-- default level (WARNING)")
emit_all()

print("-- after log.setLevel(logging.INFO)")
log.setLevel(logging.INFO)
emit_all()

print("-- after log.setLevel(logging.DEBUG)")
log.setLevel(logging.DEBUG)
emit_all()

-- default level (WARNING)
WARNING  something unexpected, but handled
ERROR    an operation failed
-- after log.setLevel(logging.INFO)
INFO     a normal event
WARNING  something unexpected, but handled
ERROR    an operation failed
-- after log.setLevel(logging.DEBUG)
DEBUG    a detail for developers
INFO     a normal event
WARNING  something unexpected, but handled
ERROR    an operation failed

logging.getLogger("demo") returned a named logger. It has no level of its own until setLevel is called, so it first inherits the root logger’s WARNING. (logging.getLevelName converts between a number and a name in both directions, if you need it.)

One logger per module

Name a logger after the module that uses it. The convention is one line near the top of each file:

"""A module that logs but leaves logging setup to the application."""

import logging

logger = logging.getLogger(__name__)


def total(prices):
    logger.debug("adding %d prices", len(prices))
    result = sum(prices)
    if result > 100:
        logger.warning("large order: %s", result)
    return result

__name__ is the module’s import name, so records say where they came from. Loggers form a tree by dotted name: app.db is a child of app, and a child passes its records up to its parent’s handlers. The module above only emits. It does not call basicConfig, add handlers or set levels. That decision belongs to the application, which knows where output should go. A library that configured logging itself would override the choices of every program that imports it.

The application configures logging once, usually at start-up:

import logging
import sys

import c38_orders

print("before configuring:", c38_orders.total([60, 70]))

logging.basicConfig(
    stream=sys.stdout,
    level=logging.DEBUG,
    format="%(name)s %(levelname)s %(message)s",
)

print("after configuring:", c38_orders.total([60, 70]))

before configuring: 130
c38_orders DEBUG adding 2 prices
c38_orders WARNING large order: 130
after configuring: 130

The block above shows standard output only. Before the configuration, the warning went to standard error as the bare text large order: 130, and the debug message was dropped. After it, both records appear on standard output with the module’s name. Same module, no change to its code.

Handlers and formatters: where records go

basicConfig is enough for scripts. For more control, learn the three parts it creates. A logger receives your calls and checks the level. A handler sends a record somewhere: StreamHandler to a stream such as the console, FileHandler to a file. A formatter turns the record into text. Each handler can have its own level and formatter, so one logger can show only INFO and above on screen while writing everything to a file:

import logging
import sys
import tempfile
from pathlib import Path

log = logging.getLogger("backup")
log.setLevel(logging.DEBUG)  # the logger lets everything through...

# ...and each handler decides what it shows.
console = logging.StreamHandler(sys.stdout)
console.setLevel(logging.INFO)
console.setFormatter(logging.Formatter("%(levelname)s: %(message)s"))

The file handler is created inside a temporary folder, so the example cleans up after itself:

FILE_FORMAT = "%(levelname)s %(name)s %(funcName)s: %(message)s"

with tempfile.TemporaryDirectory() as folder:
    logfile = Path(folder) / "backup.log"
    to_file = logging.FileHandler(logfile, encoding="utf-8")
    to_file.setLevel(logging.DEBUG)
    to_file.setFormatter(logging.Formatter(FILE_FORMAT))

    log.addHandler(console)
    log.addHandler(to_file)

    def run():
        log.debug("scanning %s", "/data")
        log.info("copied %d files", 12)
        log.warning("skipped %s: permission denied", "/data/private")

    run()

    log.removeHandler(to_file)
    to_file.close()
    print("--- contents of the file")
    print(logfile.read_text(encoding="utf-8"), end="")

INFO: copied 12 files
WARNING: skipped /data/private: permission denied
--- contents of the file
DEBUG backup run: scanning /data
INFO backup run: copied 12 files
WARNING backup run: skipped /data/private: permission denied

The console got two lines and the file got three, because the handlers filter independently. The encoding="utf-8" follows the habit from text and binary files. The handler is closed before the folder is deleted. A real program would write to a fixed path, and logging.handlers.RotatingFileHandler starts a new file when the old one gets big.

For one-call setups with a prepared formatter object, basicConfig accepts a formatter argument 3.15+Requires version 3.15 or later (see basicConfig):

import logging
import sys

# Python 3.15 or newer: basicConfig accepts a ready-made Formatter object.
formatter = logging.Formatter("[{levelname}] {name}: {message}", style="{")
logging.basicConfig(stream=sys.stdout, level=logging.INFO, formatter=formatter)

logging.getLogger("billing").info("invoice %s sent", "A-17")
logging.getLogger("billing.retry").warning("attempt %d failed", 2)

[INFO] billing: invoice A-17 sent
[WARNING] billing.retry: attempt 2 failed

On older versions, pass format= and style= instead, or create the handler yourself and call setFormatter as above. force=True in basicConfig replaces handlers that are already installed, and it has been available since 3.8. It is useful in notebooks and tests where something configured logging first.

Log exceptions with their traceback

Inside an except block, log.exception("message") logs at ERROR level and appends the full traceback. That is the logging equivalent of letting the exception propagate, for code that must keep going.

import io
import logging

stream = io.StringIO()
logging.basicConfig(stream=stream, format="%(levelname)s %(message)s")
log = logging.getLogger("importer")


def parse_row(row):
    return int(row)


for row in ["12", "x7"]:
    try:
        print("parsed", parse_row(row))
    except ValueError:
        log.exception("bad row %r", row)

lines = stream.getvalue().splitlines()
print(lines[0])
print("traceback included:", "Traceback (most recent call last):" in lines)
print(lines[-1])

parsed 12
ERROR bad row 'x7'
traceback included: True
ValueError: invalid literal for int() with base 10: 'x7'

The log went to a StringIO here only so the example could inspect it. The message comes first, then the traceback you know from reading tracebacks, and last the exception itself. Use log.exception only inside an except block. Elsewhere, pass exc_info=True to a normal call.

Why the arguments are not an f-string

A log call like log.debug("state: %s", obj) hands the template and the values to the logging system separately. If DEBUG is turned off, the message is never built. With an f-string, the text is built before log.debug is even called, and then thrown away:

import logging
import sys

logging.basicConfig(
    stream=sys.stdout, level=logging.WARNING, format="%(message)s"
)
log = logging.getLogger("lazy")


class Expensive:
    def __str__(self):
        print("(building the message)")
        return "expensive text"


print("with an f-string:")
log.debug(f"state: {Expensive()}")

print("with %s arguments:")
log.debug("state: %s", Expensive())

print("when the level is enabled:")
log.warning("state: %s", Expensive())

with an f-string:
(building the message)
with %s arguments:
when the level is enabled:
(building the message)
state: expensive text

The f-string paid for the work even though nothing was logged. The %s form did not. The cost is usually small, but a constant template also lets log tools group similar messages. A linter can flag the f-string form; see ruff and type checking.

Keep secrets out of the log

Logs are copied, shipped to other systems and read by more people than the program’s input. Never log passwords, tokens, keys, full card numbers or personal data. The safest policy is not to put them in a log message at all. As a second line of defence, a logging.Filter can rewrite records on their way out. This one finds secrets with a regular expression, from the re module covered in the standard library tour:

import logging
import re
import sys


class RedactSecrets(logging.Filter):
    """Mask the value after password= or token= in every message."""

    pattern = re.compile(r"(password|token)=\S+")

    def filter(self, record):
        record.msg = self.pattern.sub(r"\1=***", record.getMessage())
        record.args = None
        return True

Install the filter on a handler, then log some secrets:

handler = logging.StreamHandler(sys.stdout)
handler.addFilter(RedactSecrets())
logging.basicConfig(
    handlers=[handler],
    level=logging.INFO,
    format="%(levelname)s %(message)s",
)

logging.info("connecting as ana with password=hunter2")
logging.info("calling the API with token=abc123 for user %s", "ana")
logging.info("done")

INFO connecting as ana with password=***
INFO calling the API with token=*** for user ana
INFO done

The filter builds the final message with record.getMessage(), masks the secrets in it, and returns True to let the record through. This catches key=value text only, which is why it is a backup, not a plan. Tracebacks from log.exception can include argument values too.

Common pitfalls

• Calling basicConfig after something else configured logging. It does nothing the second time unless you pass force=True.
• Putting user input into the format string. log.info(user_text) fails or misformats if the text contains %. Use log.info("%s", user_text).
• Missing output. A logger at DEBUG with a handler at INFO shows only INFO. Check both levels.

import logging
import sys

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

app = logging.getLogger("app")
db = logging.getLogger("app.db")
net = logging.getLogger("net")

db.setLevel(logging.ERROR)
net.setLevel(logging.DEBUG)

app.info("starting")
app.debug("config loaded")
db.warning("slow query")
db.error("connection lost")
net.debug("sending %d bytes", 512)

app INFO starting
app.db ERROR connection lost
net DEBUG sending 512 bytes

def cleanup(names):
    for name in names:
        print("checking", name)
        if name.endswith(".tmp"):
            print("removing", name)
        elif name.startswith("."):
            print("leaving hidden file", name)
    print("done")

"""A script with a -v / -q switch that controls how much it logs."""

import argparse
import logging
import sys

log = logging.getLogger("cleanup")
LEVELS = {-1: logging.ERROR, 0: logging.WARNING, 1: logging.INFO}


def configure(verbosity):
    level = LEVELS.get(verbosity, logging.DEBUG)
    logging.basicConfig(
        stream=sys.stdout,
        level=level,
        format="%(levelname)s %(message)s",
        force=True,
    )

def cleanup(names):
    for name in names:
        log.debug("checking %s", name)
        if name.endswith(".tmp"):
            log.info("removing %s", name)
        elif name.startswith("."):
            log.warning("leaving hidden file %s", name)
    log.info("done")

parser = argparse.ArgumentParser()
parser.add_argument("-v", "--verbose", action="count", default=0)
parser.add_argument("-q", "--quiet", action="store_true")

for argv in ([], ["-v"], ["-vv"], ["-q"]):
    args = parser.parse_args(argv)
    configure(-1 if args.quiet else args.verbose)
    print("== arguments:", argv)
    cleanup(["a.tmp", ".env", "notes.txt"])

== arguments: []
WARNING leaving hidden file .env
== arguments: ['-v']
INFO removing a.tmp
WARNING leaving hidden file .env
INFO done
== arguments: ['-vv']
DEBUG checking a.tmp
INFO removing a.tmp
DEBUG checking .env
WARNING leaving hidden file .env
DEBUG checking notes.txt
INFO done
== arguments: ['-q']

import logging
import sys

logging.basicConfig(stream=sys.stdout, format="%(levelname)s %(message)s")
log = logging.getLogger("jobs")
log.setLevel(logging.INFO)

log.debug("queue length: %d", 3)
log.info("starting")

import logging
import sys

logging.basicConfig(stream=sys.stdout, format="%(levelname)s %(message)s")
log = logging.getLogger("jobs")
log.setLevel(logging.DEBUG)

log.debug("queue length: %d", 3)
log.info("starting")

DEBUG queue length: 3
INFO starting

Summary

• Log with DEBUG to CRITICAL, configure once with basicConfig, and change the level instead of the code. The default level is WARNING.
• Create logger = logging.getLogger(__name__) in each module. Only the application configures handlers and levels.
• Handlers send records to places and have their own levels and formatters. log.exception(...) inside except adds the traceback.
• Pass values as arguments ("%s", value) instead of building an f-string, and never log secrets.
• The next lesson goes beyond print and logging, to stopping a running program and looking around.