Handler Architecture for Python Logging

Handler architecture defines how a LogRecord is routed, filtered, and dispatched to its destinations. The decisive design choice in any high-throughput Python service is separating log emission from the I/O that writes it, because synchronous disk and network writes on a request thread translate directly into tail-latency spikes. This guide is part of the Python Logging and Structured Data reference and covers non-blocking dispatch, backpressure control, failure isolation, and trace correlation across the queue boundary. It builds on formatter configuration for serialization and on log levels and severity mapping for routing decisions, and it drills into non-blocking logging with QueueHandler and log rotation in Python for the two sinks that most often stall a request thread.

Key architectural principles:

• Decouple log emission from disk and network writes so the calling thread never blocks.
• Deploy one handler per sink with independent filters and formatters to isolate failure domains.
• Bound every queue and define an explicit overflow policy to prevent memory exhaustion.
• Inject trace context through filters on the producing side rather than mutating global state.
• Make configuration declarative so the handler graph can be rebuilt without touching call sites.

Prerequisites

Handler decoupling and trace injection use only the standard library; the OTLP sink requires the OpenTelemetry SDK. Pin versions so opentelemetry-api and opentelemetry-sdk stay aligned — the logs SDK still moves between minor releases, and a skew between the API and the exporter is the usual cause of a handler that silently exports nothing.

pip install \
  "opentelemetry-sdk>=1.30.0,<2.0.0" \
  "opentelemetry-exporter-otlp-proto-grpc>=1.30.0,<2.0.0"

Drive the sink addresses and severity floor from the environment so the same module runs unchanged in every deployment tier, rather than branching on a hardcoded DEBUG flag.

export OTEL_EXPORTER_OTLP_ENDPOINT="http://localhost:4317"
export OTEL_SERVICE_NAME="payments-api"
export LOG_LEVEL="INFO"
export LOG_QUEUE_MAXSIZE="10000"

Concept and Architecture

A handler is the object that takes a filtered LogRecord and emits it to a destination. When you call logger.info(), the logger builds a record, runs its own filters, and then walks itself and every ancestor calling callHandlers(). Each handler whose level and filters accept the record gets handle() invoked, which acquires that handler's lock, formats the record, and writes it. Two properties of that walk drive the whole design: dispatch is synchronous on the calling thread, and it visits ancestors unless a logger sets propagate = False.

Synchronous dispatch is cheap for a StreamHandler writing to a pipe, but the cost is unbounded for anything else. A FileHandler blocks during a rollover rename; a SysLogHandler blocks on a socket write; an OTLP exporter blocks while a slow collector applies backpressure. Whatever that write costs lands on the request path, and because Handler.handle() holds a per-handler lock, one slow sink also serializes every other thread trying to log through it. Under concurrency this shows up as a P99 that tracks your logging backend's health rather than your application's.

The structural fix is to make the only handler on the application logger a QueueHandler. Its emit() does nothing but put the record on a queue.Queue, which is a lock-protected, constant-time operation with no I/O. A separate QueueListener runs on a background thread, pulls records off the queue, and dispatches them to the real handlers. This inverts the cost model: the request thread pays a few microseconds for the enqueue, and one dedicated thread absorbs all serialization and I/O for the whole process. The detailed mechanics, sentinel-based shutdown ordering, and respect_handler_level semantics are covered in non-blocking logging with QueueHandler.

What actually crosses the queue matters more than most teams expect. QueueHandler.prepare() calls self.format(record), makes a shallow copy of the record, and then sets args, exc_info, exc_text, and stack_info to None so the object is guaranteed picklable. That is correct for a multiprocessing.Queue, where the record really is serialized, but it has a sharp edge for structured output: by the time your JSON formatter runs on the listener thread, record.exc_info is None and the traceback has been concatenated onto record.getMessage(). If you are producing structured logs with a dedicated exception field, override prepare() to return the record unchanged — with an in-process queue.Queue nothing is pickled, the same object crosses by reference, and lazy %-style arguments survive intact.

Filters refine the graph further. A logging.Filter attached to a handler decides, per record, whether that handler emits it, and it runs before the formatter — so an expensive JSON serialization is skipped entirely for records a sink rejects. There is an important distinction between a handler's level and a filter: the level is a single floor compared against record.levelno, while a filter is arbitrary per-record logic that may also enrich the record by mutating it. That mutation ability is what makes filters the right place to attach trace identifiers.

The queue boundary decides where each filter must live. Filters attached to a logger or to the QueueHandler run during record creation, on the calling thread, where request-scoped state still exists. Filters attached to handlers owned by the QueueListener run on the listener thread, which never had that state. Read contextvars in a handler-side filter and you will get the defaults every time, because the listener thread has its own empty context. Attach context-reading filters to the producing side, and reserve handler-side filters for routing decisions that depend only on data already on the record. The full rules for propagating that state safely are in context variables and thread safety.

One last structural rule: exactly one component should own handlers. Application code configures the root logger (or a single top-level application logger) and lets everything propagate up; library code attaches logging.NullHandler() and nothing else. Handlers attached in several places are the single most common cause of duplicated log lines, and duplication corrupts every count you later derive from the log stream.

Choosing a Handler for Each Sink

Because the listener owns the concrete handlers, you can pick the right class per destination without any of them touching the request path. The choice still matters, though: the listener thread is shared, so a handler that blocks for thirty seconds stalls every other sink behind it until the timeout expires.

MemoryHandler deserves a specific mention because it solves a problem no other handler does. Wrapping a target handler in a MemoryHandler with capacity=100 and flushLevel=logging.ERROR gives you a rolling buffer of DEBUG context that is written only when something actually fails. You get full-fidelity debugging around incidents without paying to ingest debug records during normal operation — a far better trade than globally raising the level to DEBUG and hoping the bill is acceptable.

Step-by-Step Implementation

Step 1 — Inject trace context with a filter. Read the active trace_id and span_id from contextvars and attach them as record attributes. This keeps trace correlation out of every call site and out of global mutable state, and it runs on the producing thread where the context still exists.

import contextvars
import logging

trace_id_ctx: contextvars.ContextVar[str | None] = contextvars.ContextVar("trace_id", default=None)
span_id_ctx: contextvars.ContextVar[str | None] = contextvars.ContextVar("span_id", default=None)


class OTelTraceFilter(logging.Filter):
    """Inject W3C Trace Context identifiers into every record."""
    def filter(self, record: logging.LogRecord) -> bool:
        # All-zero IDs are the W3C-invalid sentinel: parseable, obviously absent.
        record.trace_id = trace_id_ctx.get() or "0" * 32
        record.span_id = span_id_ctx.get() or "0" * 16
        return True

Step 2 — Route by severity with a second filter. A range filter lets one sink take everything from INFO up while another takes only ERROR and above. Unlike setLevel(), a range can also exclude high severities, which is how you keep a noisy debug sink from mirroring your error file.

class SeverityRouter(logging.Filter):
    """Pass records whose level is within [min_level, max_level]."""
    def __init__(self, min_level: int, max_level: int):
        super().__init__()
        self.min_level = min_level
        self.max_level = max_level

    def filter(self, record: logging.LogRecord) -> bool:
        # Runs on the listener thread: inspect the record only, never ambient state.
        return self.min_level <= record.levelno <= self.max_level

Step 3 — Build per-sink handlers. Each handler gets its own formatter and the filters it needs. A failure inside one handler's emit() cannot corrupt another, and each sink's serialization format is independent: compact JSON for the machine-read stream, a human-readable line for the on-call file.

import sys

stdout_handler = logging.StreamHandler(sys.stdout)
stdout_handler.setFormatter(logging.Formatter(
    '{"time":"%(asctime)s","level":"%(levelname)s","msg":"%(message)s",'
    '"trace_id":"%(trace_id)s","span_id":"%(span_id)s"}'
))
stdout_handler.addFilter(SeverityRouter(logging.INFO, logging.CRITICAL))

error_handler = logging.FileHandler("errors.log", delay=True)
error_handler.setFormatter(logging.Formatter(
    "%(asctime)s [%(levelname)s] %(name)s - %(message)s (trace=%(trace_id)s)"
))
error_handler.addFilter(SeverityRouter(logging.ERROR, logging.CRITICAL))

Step 4 — Bound the queue and define the drop policy. QueueHandler.enqueue() calls put_nowait() already, but a plain queue.Queue() is unbounded, so saturation manifests as unbounded memory growth instead of an exception. Give the queue a maxsize and replace enqueue with a policy that decides explicitly what to sacrifice.

import queue
from logging.handlers import QueueHandler, QueueListener


class SheddingQueueHandler(QueueHandler):
    """Never block the caller; shed low-severity records under saturation."""

    def __init__(self, log_queue: queue.Queue):
        super().__init__(log_queue)
        self.dropped = 0

    def prepare(self, record: logging.LogRecord) -> logging.LogRecord:
        # In-process queue: nothing is pickled, so keep exc_info and args intact
        # for the downstream formatters instead of flattening them here.
        return record

    def enqueue(self, record: logging.LogRecord) -> None:
        try:
            self.queue.put_nowait(record)
        except queue.Full:
            if record.levelno >= logging.ERROR:
                try:
                    self.queue.get_nowait()          # evict the oldest record
                    self.queue.put_nowait(record)    # keep the error
                except (queue.Empty, queue.Full):
                    self.dropped += 1
            else:
                self.dropped += 1                    # shed DEBUG/INFO/WARNING

Step 5 — Wire the listener. Attach only the queue handler to the logger and let the QueueListener own the concrete handlers. Set respect_handler_level=True so each handler's own level is honoured on the drain side; it defaults to False, which quietly bypasses every setLevel() you configured on the sinks.

import os


def setup_handlers() -> tuple[SheddingQueueHandler, QueueListener]:
    maxsize = int(os.getenv("LOG_QUEUE_MAXSIZE", "10000"))
    log_queue: queue.Queue = queue.Queue(maxsize=maxsize)

    listener = QueueListener(
        log_queue, stdout_handler, error_handler, respect_handler_level=True
    )
    listener.start()                       # spawns the single draining thread

    queue_handler = SheddingQueueHandler(log_queue)
    queue_handler.addFilter(OTelTraceFilter())   # producer side: context is live
    return queue_handler, listener

Step 6 — Attach, run, and flush on shutdown. Set propagate = False on any logger that owns handlers, and register listener.stop() so the sentinel drains the queue before the process exits.

import atexit
import time

if __name__ == "__main__":
    handler, listener = setup_handlers()
    atexit.register(listener.stop)         # flush buffered records on exit

    logger = logging.getLogger("payment.service")
    logger.setLevel(os.getenv("LOG_LEVEL", "INFO"))
    logger.addHandler(handler)
    logger.propagate = False               # the root logger must not double-emit

    trace_id_ctx.set("4bf92f3577b34da6a3ce929d0e0e4736")
    span_id_ctx.set("00f067aa0ba902b7")

    logger.info("Transaction initiated")
    logger.warning("Retry attempt 1")
    logger.error("Payment gateway timeout")

    time.sleep(0.1)                        # let the background thread drain

Expected Output: (newline-delimited JSON on stdout, Python 3.12)

{"time":"2026-07-25 14:32:11,123","level":"INFO","msg":"Transaction initiated","trace_id":"4bf92f3577b34da6a3ce929d0e0e4736","span_id":"00f067aa0ba902b7"}
{"time":"2026-07-25 14:32:11,124","level":"WARNING","msg":"Retry attempt 1","trace_id":"4bf92f3577b34da6a3ce929d0e0e4736","span_id":"00f067aa0ba902b7"}
{"time":"2026-07-25 14:32:11,125","level":"ERROR","msg":"Payment gateway timeout","trace_id":"4bf92f3577b34da6a3ce929d0e0e4736","span_id":"00f067aa0ba902b7"}

errors.log receives only the ERROR record, because its SeverityRouter rejects everything below ERROR. Note that delay=True means the file is not even created until that first error arrives, which keeps idle workers from littering empty log files across the filesystem.

Configuration Reference

Backpressure and Overflow Policy

High request rates expose the queue to saturation whenever a downstream sink slows. Queue depth is your backpressure signal: a steadily growing queue means the listener cannot drain as fast as producers enqueue, almost always because one sink — typically the network exporter — has stalled. Because the listener is a single thread, the drain rate is bounded by the sum of every handler's per-record cost, so adding a slow fourth sink reduces the headroom of the other three.

Size maxsize from measurement, not intuition. Multiply your peak emission rate by the longest sink stall you want to absorb without loss: a service emitting 2,000 records per second that should ride out a three-second collector hiccup needs roughly 6,000 slots. Then sanity-check the memory: a LogRecord with a modest message costs on the order of a kilobyte once formatted, so 10,000 slots is single-digit megabytes — cheap enough to be generous, but not so large that a sustained outage buffers gigabytes before the drop policy ever engages.

The overflow policy is a deliberate trade-off, not an error path to ignore. Dropping DEBUG and INFO under saturation preserves the ERROR and CRITICAL records that incident response actually needs, and it stops the logging subsystem from being the cause of an out-of-memory kill during an unrelated outage. Emit a counter each time a record is shed so the loss is visible rather than silent; the dropped attribute in Step 4 exists precisely so it can be scraped. A pipeline that quietly discards records during exactly the incidents you are trying to debug is worse than one that is merely slow.

Choosing which severities to shed is a policy decision that belongs alongside your severity conventions — if WARNING is used for genuinely actionable conditions in your codebase, shedding it is wrong, and the fix is upstream in log levels and severity mapping. The cheapest backpressure control of all is not emitting the record: a logger-level setLevel(logging.INFO) discards debug records before a LogRecord object is even constructed, which costs less than any queue policy can.

Failure Isolation and Handler Errors

Keeping one handler per sink confines failure. If the file handler raises during rollover or the OTLP exporter times out, the exception is contained to that handler's emit(), and stdout keeps receiving records. A single multiplexing handler couples these fates together, so an outage in the slowest sink stalls every destination behind it.

The standard library backs this up at the class level. Handler.handle() wraps emit() so that an exception raised inside a handler is caught and routed to handleError(), which prints a traceback to sys.stderr when logging.raiseExceptions is true and otherwise does nothing. That is why a broken sink degrades rather than crashing your request. It also means handler bugs are easy to miss: leave raiseExceptions = True in staging so mistakes are loud, and be aware that in production the failure is visible only on stderr.

The one place this safety net does not reach is code that runs outside emit(). A custom handler that does work in __init__ on first use, or a filter that raises, can kill the QueueListener thread — and because that thread is not the main thread, the process keeps serving traffic while logging silently stops. Guard custom filter and handler logic with its own try/except, and expose a liveness signal (the listener thread's is_alive(), or a heartbeat counter of records drained) so a dead listener is detectable rather than merely mysterious.

Finally, keep sinks independent in their configuration, not just their code. Two handlers writing to the same file, or a rotating handler shared between processes, reintroduces a coupling the architecture was meant to remove; the multi-process case has its own rules in thread-safe and multiprocessing-safe logging.

Async and Concurrency Considerations

Standard logging emission is thread-safe — every handler holds a lock during emit() — but thread safety is not the same as non-blocking. The QueueHandler pattern is what makes logging safe for an asyncio event loop: because enqueue is constant-time and does no I/O, a coroutine that logs never yields control to disk or network latency, and the loop's other tasks are unaffected. The single QueueListener thread becomes the only place blocking I/O happens, which as a bonus serializes writes to a shared file without any additional locking.

Context variables are the correct carrier for request-scoped trace data in async code: they propagate across await points within a task and are snapshotted when a child task is created with create_task(). A worker thread, however, does not inherit the event loop's context. When you offload work to a ThreadPoolExecutor via run_in_executor, capture the context with contextvars.copy_context() and invoke the callable through ctx.run(...), or use asyncio.to_thread(), which performs that copy for you. Skip it and the trace filter reads its defaults, so the offloaded work logs all-zero identifiers.

The same reasoning explains why the trace filter belongs on the QueueHandler and not on the sinks. The listener thread is created once at startup, long before any request exists, and it never enters a request's context — so a contextvars read there is guaranteed to miss. Attach the enrichment where the record is born; by the time the record reaches the listener, trace_id is a plain attribute that any formatter can interpolate. The full propagation model, including task groups and thread boundaries, is covered in context variables and thread safety, and the resulting fields are described in adding trace IDs to log records.

Process boundaries need a different answer entirely. Under fork(), a QueueListener thread does not survive into the child — only the forking thread continues — so a worker that inherits a configured logger enqueues records that nobody drains. Build the queue and start the listener after the fork, in a post_fork or worker_process_init hook, or switch to a multiprocessing.Queue with a single listener in the parent. Third-party libraries solve the same problem their own way; Loguru's enqueue=True is the direct analogue, described in async and non-blocking logging with Loguru.

Production Code Examples

Declarative queue topology with dictConfig

Building handlers imperatively is fine for illustration, but production configuration should be data. Python 3.12 taught dictConfig to construct the queue path directly: a handler with class: logging.handlers.QueueHandler accepts a handlers list naming the sinks the listener should own, and dictConfig creates the listener for you and exposes it as handler.listener. The declarative form is covered end to end in logging configuration and dictConfig.

import atexit
import logging
import logging.config
import os

LOGGING = {
    "version": 1,
    "disable_existing_loggers": False,
    "filters": {
        "trace": {"()": "myapp.logging_setup.OTelTraceFilter"},
    },
    "formatters": {
        "json": {
            "format": '{"time":"%(asctime)s","level":"%(levelname)s",'
                      '"logger":"%(name)s","msg":"%(message)s",'
                      '"trace_id":"%(trace_id)s"}',
        },
        "plain": {"format": "%(asctime)s [%(levelname)s] %(name)s - %(message)s"},
    },
    "handlers": {
        "stdout": {                       # owned by the listener, not the logger
            "class": "logging.StreamHandler",
            "stream": "ext://sys.stdout",
            "formatter": "json",
            "level": "INFO",
        },
        "errors": {
            "class": "logging.handlers.RotatingFileHandler",
            "filename": "errors.log",
            "maxBytes": 10_485_760,       # 10 MiB
            "backupCount": 5,
            "delay": True,
            "formatter": "plain",
            "level": "ERROR",
        },
        "queue": {                        # the only handler the app logger sees
            "class": "logging.handlers.QueueHandler",
            "filters": ["trace"],         # producer side: context still live
            "handlers": ["stdout", "errors"],
            "respect_handler_level": True,
        },
    },
    "root": {"level": os.getenv("LOG_LEVEL", "INFO"), "handlers": ["queue"]},
}

logging.config.dictConfig(LOGGING)
listener = logging.getHandlerByName("queue").listener   # 3.12+
listener.start()
atexit.register(listener.stop)

logging.getLogger("payment.service").info("checkout completed", extra={"order": "o-91"})

Expected Output: (one compact JSON line on stdout; errors.log stays uncreated because delay=True and no error was emitted)

{"time":"2026-07-25 14:40:02,881","level":"INFO","logger":"payment.service","msg":"checkout completed","trace_id":"00000000000000000000000000000000"}

Atomic listener swap for zero-loss reconfiguration

Because the logger only ever holds a QueueHandler, you can rebuild the entire sink topology — add an OTLP exporter, drop a file sink, change formats — by draining the old listener and starting a new one against the same queue. The handler the application logs through is never detached, so no record emitted during the swap is lost: worst case it waits in the queue until the new listener starts draining.

import logging
import queue
from logging.handlers import QueueHandler, QueueListener


def reconfigure(log_queue: queue.Queue, old: QueueListener,
                *new_handlers: logging.Handler) -> QueueListener:
    """Swap the sink topology without touching the logger's QueueHandler."""
    old.stop()                              # sentinel: drains, then joins the thread
    for handler in old.handlers:
        handler.close()                     # release file descriptors and sockets
    new = QueueListener(log_queue, *new_handlers, respect_handler_level=True)
    new.start()
    logging.getLogger(__name__).debug(
        "listener reconfigured with %d sinks", len(new_handlers)
    )
    return new

Expected Output: (records emitted mid-swap are buffered, then drained by the new sinks)

2026-07-25 14:41:19,004 [DEBUG] myapp.logging_setup - listener reconfigured with 3 sinks

Two details make this safe. QueueListener.stop() enqueues a sentinel and joins the thread, so every record already in the queue is dispatched to the old handlers before they close — you never lose the tail. And closing the old handlers explicitly matters when they hold file descriptors or sockets; stop() alone leaves them open, and a service that reloads configuration on SIGHUP will leak one descriptor set per reload otherwise.

Common Mistakes

• Error signature: P99 latency tracks the health of your log backend, and flame graphs show request threads parked in socket.send or os.write inside emit. Root cause: a FileHandler, SysLogHandler, or HTTP-based handler is attached directly to the application logger, so every write happens synchronously on the request thread while holding the handler lock. Remediation: make a QueueHandler the only handler on that logger and move the concrete sinks behind a QueueListener, as in Step 5.

• Error signature: every log line appears exactly twice (or N+1 times) in the aggregator, and derived event counts are inflated. Root cause: handlers are attached to both a child logger and the root, and the child left propagate at its default True, so callHandlers() walks the ancestor chain and emits again. Remediation: attach handlers in exactly one place — normally the root — and set propagate = False on any logger that owns handlers; libraries should attach only logging.NullHandler().

• Error signature: structured logs show "exception": null while the traceback text is glued onto the message field, but only after a queue was introduced. Root cause: QueueHandler.prepare() formatted the record and cleared exc_info, exc_text, args, and stack_info to make it picklable, so the listener-side formatter has no exception object left to project. Remediation: with an in-process queue.Queue, override prepare() to return the record unchanged; with a multiprocessing.Queue, serialize the exception into a plain string field before enqueueing.

• Error signature: trace_id is all zeros in production but correct in unit tests, or the formatter raises ValueError: Formatting field not found in record: 'trace_id'. Root cause: the context-reading filter was attached to a handler owned by the QueueListener, so it executes on the listener thread, which never entered the request's contextvars context. Remediation: attach context filters to the logger or to the QueueHandler — the producing side — and keep handler-side filters restricted to data already on the record.

• Error signature: RSS climbs steadily during a collector outage and the process is OOM-killed, with no dropped-record warnings anywhere. Root cause: the queue was created without maxsize, so a stalled sink lets it grow without bound; the drop policy never ran because the queue was never full. Remediation: always pass an explicit maxsize, shed low-severity records on queue.Full, and export a counter of shed records so degradation is observable.

• Error signature: the last few seconds of logs are missing after every deploy, and crash diagnostics are truncated exactly where they matter. Root cause: the process exited without calling listener.stop(), so records still in the queue were discarded along with the daemon listener thread — or the listener was never started at all after dictConfig. Remediation: register listener.stop() with atexit or the framework's shutdown hook, and assert listener._thread is not None in a startup self-check; see how to configure Python logging for production for the full startup checklist.

Related

• Python Logging and Structured Data — the parent reference covering the record schema, handler graph, and context propagation this architecture sits inside.
• Non-blocking logging with QueueHandler — the focused walkthrough of queue mechanics, sentinel shutdown, and respect_handler_level.
• Best practices for log rotation in Python — sizing, retention, and the multi-process hazards of the rotating file sinks used above.
• Formatter configuration for Python logging — what each handler does with a record once the listener hands it over.
• Logging configuration and dictConfig in Python — the declarative wiring that builds this entire graph from one dictionary.
• Context variables and thread safety in Python logging — why context-reading filters must run on the producing side of the queue.
• Writing a custom logging handler in Python — subclassing Handler safely: emit, handleError, the lock, and a shutdown that terminates.
• Buffering log records with MemoryHandler — hold DEBUG context in memory and ship it only when a request fails.

Frequently Asked Questions