🎓 A1Learner
🔍

Python Logging in Depth

Logger names with dots form a tree of loggers. A record climbs from a child logger to its parents.

Names build a tree

A dot in a name makes a child logger. The child knows its parent.

import logging

parent = logging.getLogger("shop")
child = logging.getLogger("shop.orders")
print(child.parent is parent)
print(parent.name, child.name)

Why messages print twice

Here the root logger has a handler from basicConfig. The child adds one more handler, and the record reaches both.

import logging, sys

logging.basicConfig(level=logging.WARNING, stream=sys.stdout, format="%(levelname)s: %(message)s")
child = logging.getLogger("demo.child")
handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(logging.Formatter("%(levelname)s: %(message)s"))
child.addHandler(handler)
child.warning("Careful")

Drop records with a filter

A filter returns True to keep a record. This one keeps only WARNING records and above.

import logging, sys

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


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


logger = logging.getLogger("demo")
logger.addFilter(WarningsOnly())
logger.info("Hidden by the filter")
logger.warning("Shown by the filter")

Warnings join the log

captureWarnings sends warnings to a logger named py.warnings. The full warning line also carries a file path, so this check prints only two facts about the captured text.

import logging, io, warnings

stream = io.StringIO()
logging.basicConfig(level=logging.WARNING, stream=stream, format="%(levelname)s %(name)s: %(message)s")
logging.captureWarnings(True)
warnings.simplefilter("always")
warnings.warn("Check this value")
text = stream.getvalue()
print(text.startswith("WARNING py.warnings:"))
print("Check this value" in text)

A rotating file in dictConfig

This is one piece of a config dictionary. RotatingFileHandler starts a fresh file when the size limit is reached.

"handlers": {
    "file": {
        "class": "logging.handlers.RotatingFileHandler",
        "filename": "app.log",
        "maxBytes": 1000000,
        "backupCount": 3,
    },
},

Example

# worker.py
import logging

logger = logging.getLogger("app.worker")


def do_work():
    logger.info("Work started")
    logger.warning("Work is slow")

# main.py
import logging
import logging.config

CONFIG = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "simple": {"format": "%(levelname)s %(name)s: %(message)s"}
    },
    "handlers": {
        "console": {
            "class": "logging.StreamHandler",
            "stream": "ext://sys.stdout",
            "formatter": "simple",
        }
    },
    "loggers": {
        "app": {"level": "INFO", "handlers": ["console"], "propagate": False}
    },
}

logging.config.dictConfig(CONFIG)

import worker

logger = logging.getLogger("app")
logger.info("App started")
worker.do_work()
logger.info("App finished")

Key points

  • Hierarchy: loggers form a tree by name, so shop.orders is a child of shop
  • Propagation: a record passing from a child logger up to the handlers of its parents
  • Filter: an object that can accept or drop each record before it prints
  • A record prints once for each handler it reaches.
  • Two handlers on the path mean two prints.
  • Use logging.config.dictConfig(...) to set loggers, handlers, formatters, and filters in one place
  • Use RotatingFileHandler to start a fresh file when a log file grows past a size you set
  • Handlers you can pick from include StreamHandler, FileHandler, RotatingFileHandler, and NullHandler
  • Use logging.captureWarnings(True) to send warnings from the warnings module into logging

In this example, the app has two files, and you run python3 main.py from their folder. The worker.py file makes a logger named app.worker and logs two lines inside do_work(). The main.py file holds the whole setup in a dictionary named CONFIG. dictConfig builds one console handler from that dictionary. Only the app logger owns the handler, and its propagate value is False. Records from app.worker climb to app and print there. They never reach the root logger, which has no handler at all. Each event prints exactly once, and the four lines appear in call order.

Note

Set propagate to False on a logger with its own handlers.

Then each record prints once only.

Try it Yourself

Edit the code, then press Run.

Running is simulated · Python Playground

Exercise

A message prints twice. Its logger has a handler, and its parent logger has one too. What is the most likely cause?