Python Logging

The standard library logging module, configured the way production services actually need it.

Overview

logging is deceptively deep. The mental model that fixes most confusion: a Logger is what you call; it dispatches a LogRecord to one or more Handlers; each handler decides where the record goes and uses a Formatter to turn it into text (or JSON); Filters can drop or mutate records at either stage. Loggers form a dotted-name hierarchy, and a record propagates up that tree to ancestor handlers unless you stop it.

Most "my logs aren't appearing" or "everything is logged twice" problems come from misunderstanding the hierarchy and propagation, not from the handlers themselves. Get the topology right and the rest is configuration.

⤢ zoom

The Logging Model and Hierarchy

Key Concepts

• Always name your logger after the module: logger = logging.getLogger(__name__). With the package laid out as myapp/db/pool.py, that yields the logger name myapp.db.pool, which slots into the hierarchy automatically.
• getLogger(name) returns the same singleton for a given name, anywhere in the process. There is exactly one logger per name.
• Propagation: a record handled by myapp.db.pool also flows to myapp.db, then myapp, then the root logger (""), running each ancestor's handlers in turn. Levels are not re-checked on the way up — only the originating logger's effective level gates the record.
• Configure handlers high, log everywhere low. Attach handlers once, on the root or your top package logger; child modules just call getLogger(__name__) and log. Don't add handlers per module.

import logging

logger = logging.getLogger(__name__)   # the only line most modules need

def connect():
    logger.debug("opening connection")
    logger.info("connected to %s", "db-primary")

Libraries: never configure the root logger

If you ship a library, configuring logging is the application's job, not yours. Adding handlers, calling basicConfig, or setting levels in library import code hijacks the consuming app. The one safe thing a library does is attach a NullHandler to its top-level logger, so that if the app has configured nothing, your records don't trip the "No handlers could be found" last-resort warning.

# mylib/__init__.py
import logging

# Suppresses the "last resort" handler; the app decides where library logs go.
logging.getLogger("mylib").addHandler(logging.NullHandler())

⤢ zoom

Levels

Key Concepts

Five standard levels, numeric values in brackets:

Level	Value	Use for
DEBUG	10	Diagnostic detail, only of interest when chasing a problem
INFO	20	Normal operational milestones (started, served, finished)
WARNING	30	Something unexpected, but the app carried on
ERROR	40	An operation failed; a user/request was affected
CRITICAL	50	The app itself may be unable to continue

• Root defaults to WARNING. With no configuration, INFO/DEBUG are silently dropped — this surprises everyone once.
• A logger with no explicit level has level NOTSET (0) and inherits its effective level from the nearest ancestor that does set one (ultimately root's WARNING).
• Set the level on the logger that owns the records you want to gate; set handler levels to further restrict what a given destination emits.

import logging

logging.getLogger().setLevel(logging.INFO)            # root threshold
logging.getLogger("myapp.noisy").setLevel(logging.WARNING)  # quieten one subtree

log = logging.getLogger("myapp.noisy")
log.getEffectiveLevel()      # 30 (WARNING) — resolved up the tree
log.isEnabledFor(logging.INFO)   # False

A handler can be more restrictive than its logger, never less: a record must clear the logger's effective level and the handler's level to be emitted.

Configuration

There are three ways to configure logging, in ascending order of how production-ready they are.

basicConfig — scripts and quick spikes

One-shot setup of the root logger. It is a no-op if the root already has handlers, so calling it twice (or after a library did) silently does nothing.

import logging

logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)s %(levelname)-8s %(name)s %(message)s",
    datefmt="%Y-%m-%dT%H:%M:%S%z",
)
logging.getLogger(__name__).info("up")

force=True (3.8+) tears down existing root handlers first — handy in notebooks where re-running a cell would otherwise stack handlers.

dictConfig — the production pattern

logging.config.dictConfig is the canonical way to configure a real service: declarative, loadable from YAML/TOML/env, and it wires formatters, handlers, and loggers in one pass.

import logging.config

LOGGING = {
    "version": 1,
    # Critical: keep loggers created at import time (i.e. getLogger(__name__)
    # in already-imported modules) working. The default True orphans them.
    "disable_existing_loggers": False,
    "formatters": {
        "plain": {
            "format": "%(asctime)s %(levelname)-8s %(name)s %(message)s",
            "datefmt": "%Y-%m-%dT%H:%M:%S%z",
        },
        "json": {
            "()": "myapp.logging.JSONFormatter",   # custom callable
        },
    },
    "filters": {
        "request_id": {"()": "myapp.logging.RequestIdFilter"},
    },
    "handlers": {
        "console": {
            "class": "logging.StreamHandler",
            "stream": "ext://sys.stderr",
            "formatter": "json",
            "filters": ["request_id"],
            "level": "INFO",
        },
        "file": {
            "class": "logging.handlers.RotatingFileHandler",
            "filename": "/var/log/myapp/app.log",
            "maxBytes": 10_000_000,
            "backupCount": 5,
            "formatter": "json",
            "level": "DEBUG",
        },
    },
    "root": {"level": "INFO", "handlers": ["console", "file"]},
    "loggers": {
        # Tame a chatty dependency without touching its code.
        "urllib3": {"level": "WARNING", "propagate": True},
        "myapp": {"level": "DEBUG", "propagate": True},
    },
}

logging.config.dictConfig(LOGGING)

Notes that bite people:

• "version": 1 is mandatory and is the schema version, not yours.
• disable_existing_loggers defaults to True, which disables every logger that already existed when dictConfig runs — typically all your getLogger(__name__) module loggers. Set it to False unless you have a specific reason.
• () selects an arbitrary callable (your custom formatter/filter class); plain class is for the well-known handler classes. ext:// references a Python object such as sys.stderr.
• Configure once, as early as possible in startup, before worker modules log anything you care about.

fileConfig (the older .ini form) still exists but is strictly less capable — prefer dictConfig.

Handlers

Common Handlers

import logging
import logging.handlers
import sys

# Console — to stderr so stdout stays clean for real output.
logging.StreamHandler(sys.stderr)

# Single file (grows unbounded — use a rotating variant in production).
logging.FileHandler("/var/log/myapp/app.log", encoding="utf-8")

# Rotate by size: 10 MB per file, keep 5 old files.
logging.handlers.RotatingFileHandler(
    "/var/log/myapp/app.log", maxBytes=10_000_000, backupCount=5, encoding="utf-8",
)

# Rotate by time: new file at midnight, keep 14 days, UTC boundaries.
logging.handlers.TimedRotatingFileHandler(
    "/var/log/myapp/app.log", when="midnight", backupCount=14, utc=True, encoding="utf-8",
)

# Syslog (local socket or remote).
logging.handlers.SysLogHandler(address="/dev/log")
logging.handlers.SysLogHandler(address=("logs.internal", 514))

Choosing a handler

• Containers / 12-factor: log to stderr with a single StreamHandler and let the platform (systemd-journald, Docker, k8s) handle collection and rotation. Don't rotate files inside a container.
• Plain VM / bare host: RotatingFileHandler or TimedRotatingFileHandler. Note neither is safe across multiple processes writing the same file — rotation races corrupt logs. Use WatchedFileHandler (cooperates with external logrotate) or, better, the queue pattern below.
• SysLogHandler is non-blocking over UDP but lossy; over TCP it can block. For anything high-volume prefer shipping JSON to stdout and collecting downstream.

Async-safe logging: QueueHandler + QueueListener

The correct pattern when handlers do slow I/O (files, network, syslog) and you don't want logging calls blocking your worker threads, async event loop, or competing for a file lock across threads: application code only ever touches a fast in-memory QueueHandler; a single background QueueListener drains the queue and runs the real handlers.

import logging
import logging.handlers
import queue

log_queue: queue.Queue = queue.Queue(-1)      # unbounded

# The real, possibly-slow handlers live behind the queue.
file_handler = logging.handlers.RotatingFileHandler(
    "/var/log/myapp/app.log", maxBytes=10_000_000, backupCount=5,
)
listener = logging.handlers.QueueListener(
    log_queue, file_handler, respect_handler_level=True,
)
listener.start()

# Application loggers only see the cheap queue handler.
root = logging.getLogger()
root.addHandler(logging.handlers.QueueHandler(log_queue))
root.setLevel(logging.INFO)

# ... run the app ...

listener.stop()    # flush remaining records on shutdown

In dictConfig (3.12+) you can declare this directly with a QueueHandler whose handlers: key lists the downstream handlers and a listener is started for you via logging.config.dictConfig + QueueHandler's listener attribute; on 3.11 wire the listener manually as above.

Formatters

Format strings and attributes

The default formatter style is %-style (%(name)s). Common LogRecord attributes:

Attribute	Meaning
%(asctime)s	Human-readable timestamp (see datefmt)
%(created)f	Unix timestamp (float)
%(levelname)s / %(levelno)d	INFO / 20
%(name)s	Logger name (myapp.db.pool)
%(message)s	The formatted log message
%(module)s %(funcName)s %(lineno)d	Call site
%(process)d %(processName)s	Process id / name
%(thread)d %(threadName)s	Thread id / name
%(taskName)s	asyncio task name (3.12+)

import logging

fmt = logging.Formatter(
    "%(asctime)s %(levelname)-8s [%(process)d] %(name)s:%(lineno)d %(message)s",
    datefmt="%Y-%m-%dT%H:%M:%S%z",
)

ISO timestamps and UTC

asctime defaults to local time with a comma-millisecond suffix. For ISO-8601 UTC, the robust route is a formatter that emits an offset-aware timestamp rather than relying on datefmt alone:

import datetime
import logging

class UTCISOFormatter(logging.Formatter):
    def formatTime(self, record, datefmt=None):
        dt = datetime.datetime.fromtimestamp(record.created, datetime.timezone.utc)
        return dt.isoformat(timespec="milliseconds")

Process-wide, you can force UTC for all default formatters with logging.Formatter.converter = time.gmtime, but a dedicated formatter is clearer and doesn't leak into third-party config.

Exception Logging

Logging tracebacks correctly

Inside an except block, logger.exception(...) logs at ERROR and attaches the active traceback. It's the idiomatic call and should only ever be used where there is a current exception.

import logging

logger = logging.getLogger(__name__)

try:
    charge_card(order)
except PaymentError:
    # ERROR level + full traceback, automatically.
    logger.exception("payment failed for order %s", order.id)

Equivalents and extras:

# Same traceback attachment at a chosen level:
logger.error("payment failed for order %s", order.id, exc_info=True)
logger.critical("unrecoverable", exc_info=True)

# Capture the *calling* stack even without an exception (where was this logged from?):
logger.warning("slow path hit", stack_info=True)

• Don't pass the exception object into the message (logger.exception("failed: %s", e) loses the traceback structure) — let exc_info carry it.
• logging.raiseExceptions (default True) makes errors inside logging (e.g. a broken formatter) surface as tracebacks during development. Set it to False in production so a logging bug can never crash request handling.

Structured / JSON Logging

Line-oriented JSON is what log aggregators (Loki, Elasticsearch, CloudWatch) actually want — one object per line, queryable fields instead of regex over a format string.

Hand-rolled JSON formatter

No dependency, full control. Anything passed via extra= lands as a record attribute and can be promoted into the payload.

import datetime
import json
import logging

# Built-in LogRecord attributes we don't want to re-emit blindly.
_RESERVED = set(logging.makeLogRecord({}).__dict__) | {"message", "asctime"}

class JSONFormatter(logging.Formatter):
    def format(self, record: logging.LogRecord) -> str:
        payload = {
            "ts": datetime.datetime.fromtimestamp(
                record.created, datetime.timezone.utc
            ).isoformat(timespec="milliseconds"),
            "level": record.levelname,
            "logger": record.name,
            "msg": record.getMessage(),
        }
        # Promote anything supplied via extra={...}.
        for key, value in record.__dict__.items():
            if key not in _RESERVED and not key.startswith("_"):
                payload[key] = value
        if record.exc_info:
            payload["exc"] = self.formatException(record.exc_info)
        return json.dumps(payload, default=str)

logger.info("order placed", extra={"order_id": "ORD-123", "total": 99.99})
# {"ts": "...", "level": "INFO", "logger": "...", "msg": "order placed",
#  "order_id": "ORD-123", "total": 99.99}

Libraries

For new services, reach for a library rather than maintaining the formatter above:

• structlog — the modern choice. It wraps stdlib logging (or replaces it), gives you a clean log.info("event", key=value) API, immutable bound context, and pluggable JSON/console renderers. It's flagged for its own sheet in this repo's backlog; lean towards it for greenfield work. Typical setup pipes structlog through a stdlib ProcessorFormatter so library logs and your own share one JSON output.
• python-json-logger — a drop-in jsonlogger.JsonFormatter you slot straight into dictConfig. Minimal change to an existing stdlib setup; good when you can't justify adopting structlog wholesale.

Both interoperate with everything in this sheet — they're formatters/wrappers over the same Logger/Handler machinery, not replacements for it.

Correlation IDs and Contextual Logging

Tying every log line of a request together with a shared id is the single highest-value structured-logging habit. Three mechanisms, roughly in order of preference.

contextvars + a filter (async-safe, recommended)

contextvars (3.7+) is the only option that behaves correctly under asyncio: each task sees its own value, with no bleed between concurrent requests. A Filter injects the current id onto every record, so call sites stay clean.

import contextvars
import logging
import uuid

request_id: contextvars.ContextVar[str] = contextvars.ContextVar("request_id", default="-")

class RequestIdFilter(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        record.request_id = request_id.get()
        return True   # never drops; just annotates

# At the entry point of each request (FastAPI middleware, worker, etc.):
token = request_id.set(str(uuid.uuid4()))
try:
    handle_request()          # every log line below carries request_id
finally:
    request_id.reset(token)

Add "%(request_id)s" to your format string (or read record.request_id in the JSON formatter), wire the filter onto your handlers via dictConfig, and you're done.

setLogRecordFactory — inject onto every record globally

If you want the id present on records you didn't create (third-party libraries), patch the record factory rather than every logger:

import logging

_old_factory = logging.getLogRecordFactory()

def _factory(*args, **kwargs):
    record = _old_factory(*args, **kwargs)
    record.request_id = request_id.get()
    return record

logging.setLogRecordFactory(_factory)

LoggerAdapter — scoped extra for a block of code

When the context is local rather than process-wide, wrap a logger:

import logging

base = logging.getLogger(__name__)
log = logging.LoggerAdapter(base, {"order_id": "ORD-123", "tenant": "acme"})
log.info("processing")     # both keys attached to this record

extra={...} on a single call does the same for one line; LoggerAdapter carries it across many. For request-scoped ids that cross await boundaries, prefer the contextvars approach — an adapter won't follow the task.

Async and Multiprocessing

asyncio: logging is blocking I/O

logger.info(...) runs its handlers synchronously on the calling thread. In an event loop a slow handler (file fsync, syslog over TCP) stalls every coroutine. The fix is the QueueHandler + QueueListener pattern from above: the loop only touches the in-memory queue (microseconds); the listener does the slow work on its own thread. Use %(taskName)s (3.12+) to attribute lines to tasks.

⤢ zoom

Multiprocessing and fork

• Inherited handlers + locks across fork. A child forked while a parent thread holds a handler's internal lock inherits a locked lock with no owner — the child can deadlock the first time it logs. This is the classic gunicorn/multiprocessing hang. Configure logging after the fork (in the worker's post-fork hook / initializer), or use spawn instead of fork.
• Multiple processes, one file is unsafe with RotatingFileHandler — concurrent rotation truncates each other's output.
• The cross-process pattern: each worker process attaches only a QueueHandler feeding a multiprocessing.Queue; one dedicated process runs a QueueListener with the real file/network handlers. This is the multiprocessing analogue of the asyncio fix and the recommended way to centralise logs from a process pool.

import logging
import logging.handlers
import multiprocessing

def worker_init(log_queue):
    root = logging.getLogger()
    root.handlers.clear()
    root.addHandler(logging.handlers.QueueHandler(log_queue))
    root.setLevel(logging.INFO)

def main():
    log_queue = multiprocessing.Queue(-1)
    listener = logging.handlers.QueueListener(
        log_queue, logging.handlers.RotatingFileHandler("/var/log/myapp/app.log"),
    )
    listener.start()
    with multiprocessing.Pool(initializer=worker_init, initargs=(log_queue,)) as pool:
        pool.map(do_work, range(100))
    listener.stop()

Performance

Lazy formatting — never f-strings in log calls

Pass the format string and arguments separately. The message is only rendered if the record actually clears the level, so a suppressed DEBUG line costs almost nothing.

# CORRECT — arguments evaluated lazily; no work if DEBUG is off.
logger.debug("user=%s scopes=%s", user_id, scopes)

# WRONG — the f-string is built on every call, even when DEBUG is disabled.
logger.debug(f"user={user_id} scopes={scopes}")

Guard genuinely expensive arguments

Lazy %-formatting doesn't help if computing an argument is costly — that happens before the call. Guard those:

if logger.isEnabledFor(logging.DEBUG):
    logger.debug("state dump: %s", expensive_serialise(obj))

Other levers

import logging

# Hard floor: drop everything at or below WARNING, process-wide, cheaply.
# Useful to silence noise in a hot path or a benchmark.
logging.disable(logging.WARNING)
logging.disable(logging.NOTSET)   # lift the floor again

# Cut per-record overhead you don't use (3.x toggles, all default True):
logging.logProcesses = False      # skip os.getpid()
logging.logThreads = False        # skip thread id/name
logging.logMultiprocessing = False

• Disabling unused handlers (or raising their level) is the cheapest win — the formatter and I/O are the real cost, not the dispatch.
• For high-throughput services, the QueueHandler pattern also is a performance fix: it moves formatting and I/O off the request path.

Quick Reference

import logging

logger = logging.getLogger(__name__)          # always __name__

logger.debug("x=%s", x)                        # lazy args, not f-strings
logger.info("started")
logger.warning("retrying %d/%d", n, total)
logger.error("failed", exc_info=True)
logger.exception("failed")                     # ERROR + traceback, in except only
logger.info("event", extra={"key": "value"})  # structured fields

logging.basicConfig(level=logging.INFO)        # scripts only
logging.config.dictConfig(LOGGING)             # services

logger.setLevel(logging.DEBUG)
logger.isEnabledFor(logging.DEBUG)             # guard expensive args

Need	Reach for
Module logger	logging.getLogger(__name__)
Configure a service	logging.config.dictConfig
Library, don't hijack the app	getLogger("lib").addHandler(NullHandler())
JSON output	custom formatter, or python-json-logger / structlog
Request correlation id	contextvars + Filter
Slow handlers / asyncio	QueueHandler + QueueListener
Log an exception	logger.exception() inside except
Rotate by size / time	RotatingFileHandler / TimedRotatingFileHandler

Common Issues and Solutions

Nothing is logged below WARNING

Problem: logger.info(...) produces no output.

Cause: Root defaults to WARNING and you never lowered the threshold. Set a level (and a handler) — logging.basicConfig(level=logging.INFO) for scripts, or dictConfig with root.level: INFO for services.

Every line is logged twice (or more)

Problem: Duplicate output.

Cause: A handler on a child logger and on root, with propagation on; or basicConfig called more than once; or a handler added on every request. Attach handlers once, high in the tree. To stop a record reaching ancestors deliberately, set logger.propagate = False on that logger — but then it needs its own handler.

dictConfig silenced my module loggers

Problem: Loggers worked before dictConfig, then went quiet.

Cause: disable_existing_loggers defaults to True, disabling every logger created at import time. Set "disable_existing_loggers": False.

logger.exception() logged no traceback

Problem: Called it but got only the message.

Cause: It was called outside an active except block, so there was no current exception to attach. Use it only where an exception is being handled; elsewhere use stack_info=True for the call stack.

Worker hangs the first time it logs after fork

Problem: A forked child or pool worker deadlocks on its first log call.

Cause: A handler lock was held at fork time and inherited locked. Configure logging after the fork (post-fork hook / Pool(initializer=...)), switch to the spawn start method, or route everything through a QueueHandler to a single listener process.

Logs are garbled across processes

Problem: Interleaved or truncated lines in a shared log file under multiprocessing.

Cause: Multiple processes writing/rotating the same RotatingFileHandler. Use the multiprocessing.Queue + single-QueueListener pattern, or have every process log JSON to stdout and collect centrally.

A typo in a log call crashed a request

Problem: A bad format string or broken formatter raised inside logging.

Cause: logging.raiseExceptions is True by default, so logging errors propagate. Set logging.raiseExceptions = False in production so logging can never take down the work it's observing.

Related Topics

• Python - Sentry SDK — error tracking that consumes these logs and tracebacks
• Python - asyncio — event-loop model behind the blocking-I/O and contextvars guidance here
• Python - Debugging Tools — logging, pdb, and tracebacks as a debugging toolkit
• OpenTelemetry — correlate logs with traces and spans via shared context
• Loki — aggregating and querying the JSON lines this sheet emits
• Observability Patterns — where structured logs sit alongside metrics and traces