Python logging: levels, handlers, formatters and configuration

When a program misbehaves on someone else's machine, or at 3 a.m. on a server, print statements are not enough. They can't be switched off, can't be sorted by importance and don't say when or where they happened. Python's logging module solves all of that. This post shows how to use it from the one-line setup to configuring several destinations. Every output below was produced by running the code (Python 3.9).

Why not just print?

Logging gives you:

• Levels, so you can show only important messages in production and everything while developing.
• Destinations: screen, a file, the network, email, or several at once.
• Context: time, severity, module, function and line number, added automatically.
• Exception details, including the traceback, with one call.
• Control without editing code: change the level or format in one place.

Levels

There are five standard levels, each with a number. A message is shown only if its level is at or above the logger's level.

Level	Number	Use for
DEBUG	10	Detailed information for diagnosing problems
INFO	20	Confirmation that things work as expected
WARNING	30	Something unexpected, but the program continues (the default threshold)
ERROR	40	A serious problem: an operation failed
CRITICAL	50	The program may not be able to continue

import logging
print(logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL, logging.NOTSET)
# 10 20 30 40 50 0
print(logging.getLevelName(30), logging.getLevelName("ERROR"))     # WARNING 40

By default only WARNING and above are shown, so logging.info("...") prints nothing until you lower the threshold.

The quickest start: basicConfig

import sys
logging.basicConfig(stream=sys.stdout, level=logging.DEBUG,
                    format="%(levelname)s:%(name)s:%(message)s")
logging.debug("debug msg")
logging.info("info msg")
logging.warning("warn msg")
logging.error("err msg")
logging.critical("crit msg")

Output:

DEBUG:root:debug msg
INFO:root:info msg
WARNING:root:warn msg
ERROR:root:err msg
CRITICAL:root:crit msg

basicConfig sets up the root logger once. Its main arguments:

Argument	Meaning
level	Minimum level to record
format	The layout of each line
filename, filemode	Write to a file ("a" appends, "w" overwrites it each run)
datefmt	Format of %(asctime)s
stream	A stream such as sys.stdout (default is sys.stderr)
force=True	Replace existing handlers and configure again

Important: calling basicConfig a second time does nothing unless you pass force=True (the root logger already has a handler, so it returns). In a test run, a second call left exactly one root handler. Configure logging once, at the start of your program.

To write to a file, overwriting it each run: logging.basicConfig(filename="app.log", filemode="w", level=logging.INFO).

Formatting messages

The format string uses these fields (among others):

Field	Meaning
%(asctime)s	Time of the record
%(levelname)s	INFO, ERROR, ...
%(name)s	Logger name
%(message)s	The message
%(filename)s, %(module)s	Source file and module
%(funcName)s, %(lineno)d	Function name and line
%(process)d, %(thread)d, %(threadName)s	Process and thread

A typical production format: "%(asctime)s | %(levelname)-8s | %(name)s | %(message)s". Format the time with datefmt="%Y-%m-%d %H:%M:%S".

Pass values to the logger as arguments, not through an f-string:

log = logging.getLogger("shop.orders")
log.info("order %s total %.2f", 101, 250)       # INFO:shop.orders:order 101 total 250.00

With %s-style arguments, the string is built only if the message will actually be emitted, which saves work when DEBUG is off.

Logging exceptions

Inside an except block, logger.exception(...) logs at ERROR level and appends the traceback:

try:
    1 / 0
except ZeroDivisionError:
    log.exception("calc failed")

Output (path shortened):

ERROR:shop.orders:calc failed
Traceback (most recent call last):
  File ".../t9.py", line 8, in <module>
    try: 1/0
ZeroDivisionError: division by zero

When you only want the message, use log.error("failed: %s", e), which printed ERROR:shop.orders:failed: division by zero. You can also write log.error("...", exc_info=True). Logging the exception and then continuing is how a long-running program survives errors while leaving evidence.

Named loggers and the hierarchy

The root logger is fine for scripts. In real programs, each module gets its own logger, named after the module:

log = logging.getLogger(__name__)

Logger names form a hierarchy with dots: shop.orders is a child of shop, which is a child of the root. Three consequences:

• A child inherits the effective level from its parent unless it sets its own.
• Records propagate upward to the parent's handlers, so handlers on the root see every module's messages.
• You can tune one part of the application: set logging.getLogger("shop").setLevel(logging.ERROR) and everything under shop.* goes quiet except errors.

print(log.name, log.parent.name, log.getEffectiveLevel(), log.isEnabledFor(logging.DEBUG))
# shop.orders root 10 True
logging.getLogger("shop").setLevel(logging.ERROR)
log.info("hidden now"); log.error("still shown")        # only the error appears
print(logging.getLogger("shop.orders") is log)           # True: same name, same object

Problems with the root logger

Using logging.info(...) directly goes through the root logger. That is fine for small scripts, but libraries and larger apps should avoid it: you can't tell which module a message came from, and you can't control one module separately. Use getLogger(__name__) and let the application configure the handlers once.

Handlers, formatters and levels per destination

A handler decides where records go; a formatter decides how they look. One logger can have several handlers with different levels, for example short messages on screen and full detail in a file:

lg = logging.getLogger("demo")
lg.setLevel(logging.DEBUG)
lg.propagate = False                      # do not also send to the root logger

ch = logging.StreamHandler(sys.stdout)
ch.setLevel(logging.INFO)
ch.setFormatter(logging.Formatter("%(levelname)-8s %(message)s"))

fh = logging.FileHandler("app.log", mode="w")
fh.setLevel(logging.DEBUG)
fh.setFormatter(logging.Formatter("%(levelname)s|%(name)s|%(funcName)s|%(message)s"))

lg.addHandler(ch); lg.addHandler(fh)

def work():
    lg.debug("details only in file")
    lg.info("starting")
    lg.warning("careful")
work()

The screen showed:

INFO     starting
WARNING  careful

and app.log contained:

DEBUG|demo|work|details only in file
INFO|demo|work|starting
WARNING|demo|work|careful

The logger's level (DEBUG) is the first filter; each handler's level is the second. Common handlers: StreamHandler (console), FileHandler, RotatingFileHandler (starts a new file when one grows too large, keeping a number of backups), TimedRotatingFileHandler (rotates daily, for example), SMTPHandler (email) and HTTPHandler. Rotating files keep logs from filling a disk.

Filters

A filter can reject records that other settings would pass:

class OnlyWarn(logging.Filter):
    def filter(self, rec):
        return rec.levelno >= logging.WARNING

lg2 = logging.getLogger("f"); lg2.propagate = False; lg2.setLevel(logging.DEBUG)
h = logging.StreamHandler(sys.stdout); h.addFilter(OnlyWarn()); lg2.addHandler(h)
lg2.info("x"); lg2.warning("only warning shows")      # prints only the warning

Configuration from a dictionary or a file

For a bigger app, describe the setup as data rather than code. logging.config.dictConfig takes a dictionary (which you can load from JSON or YAML), and fileConfig reads an INI-style file.

import logging.config
logging.config.dictConfig({
    "version": 1,
    "formatters": {"s": {"format": "%(levelname)s %(name)s %(message)s"}},
    "handlers": {"c": {"class": "logging.StreamHandler", "stream": "ext://sys.stdout",
                        "formatter": "s", "level": "INFO"}},
    "loggers": {"cfg": {"handlers": ["c"], "level": "DEBUG", "propagate": False}},
})
c = logging.getLogger("cfg")
c.debug("no"); c.info("config works")        # INFO cfg config works

Here the debug message was dropped by the handler's INFO level and the info message passed.

Custom loggers: a recommended pattern

1. In each module: log = logging.getLogger(__name__), and log with log.info(...).
2. In the application's entry point only: configure handlers and levels once (basicConfig, dictConfig).
3. In libraries: never configure handlers; add logging.getLogger("yourlib").addHandler(logging.NullHandler()) so the application stays in control.

What to log, and what not to

• Log events and decisions: start and end of jobs, retries, configuration used, counts, timings.
• Log errors with context: which order, which user id, which file.
• Use DEBUG for detail, INFO for milestones, WARNING for recoverable oddities, ERROR for failures.
• Never log secrets: passwords, tokens, full card numbers or personal data. Logs are copied around and rarely protected as well as databases.
• Keep messages specific: "payment failed for order 101: card declined" beats "error".

Common mistakes

• Calling basicConfig after something has already logged, or twice, and wondering why nothing changes.
• Expecting INFO messages with the default WARNING threshold.
• Building messages with f-strings in hot paths.
• Using print in libraries.
• Forgetting propagate = False, which produces duplicate lines when both a child and the root have handlers.
• Logging inside a loop millions of times at DEBUG in production.
• Logging sensitive data.

Watch and continue

Watch the lesson: Episode 53: Python Logging. Logging is thread-safe, so it works well with multithreading (add %(threadName)s to the format), and it is the right way to record errors from database code. The Python cheat sheet lists the exceptions you will most often log.