Python Logging and Structured Data: Architecture Guide for SREs
Python's standard logging module is the substrate every production service builds its diagnostics on, and structured JSON output is what turns those diagnostics into queryable observability data. This guide is written for backend engineers and SREs who own services in production, and it covers the logger hierarchy, structured record design, handler and sink topology, concurrency safety, and OpenTelemetry alignment. It anchors five implementation areas you will configure repeatedly: handler architecture for routing and non-blocking dispatch, formatter configuration for machine-parsable output, log levels and severity mapping for alert fidelity, context variables and thread safety for request correlation across async boundaries, and logging configuration with dictConfig for declarative, environment-driven setup.
Logging is the foundation of the broader observability stack alongside distributed tracing and OpenTelemetry in Python and Python metrics and instrumentation. Logs answer "what happened and why" with high-cardinality detail, while traces answer "where" and metrics answer "how much." Designing the logging layer correctly from the start avoids the most expensive observability mistake: emitting unstructured strings that no backend can query. Everything on this page uses the standard library only; the trade-offs against third-party alternatives are weighed in the modern Python logging libraries deep dive.
Key architectural principles:
- Decouple log generation from I/O so request threads and the event loop never block on disk or network writes.
- Keep library code free of handler configuration; configure only at the application entry point, exactly once.
- Emit machine-parsable structured records with mandatory correlation fields from day one, named to match OpenTelemetry semantic conventions.
- Propagate request-scoped context explicitly across thread, task, and process boundaries rather than hoping it is inherited.
- Centralize configuration declaratively so verbosity and routing can change without code edits or redeploys.
- Decide the drop policy before you need it: bound every queue, sample at the emission boundary, and shed low-severity records first.
Foundational Architecture and the Logger Hierarchy
Python's logging module operates on a hierarchical tree of logger instances keyed by dotted names. A logger named payment.gateway.stripe is a descendant of payment.gateway, which descends from payment, which descends from the root. Each logger inherits its effective level and handler set from its ancestors unless explicitly overridden. Calling logging.getLogger(__name__) in every module yields a namespace that mirrors your package layout, giving you per-subsystem control without configuration collisions.
Loggers are process-global singletons: two calls to getLogger("payment") from anywhere in the process return the same object. This is what makes the tree a shared, mutable configuration surface, and it is why configuration must be applied exactly once at startup rather than re-derived per request. The tree is also lazily materialized — intermediate loggers like payment.gateway are created as placeholder nodes the first time a descendant is requested, so the hierarchy always resolves even when no module ever names the middle node directly.
Records propagate upward through the tree to ancestor handlers by default. This is why a single handler on the root logger captures output from every module. It is also the most common source of duplicate lines: attach a handler to a child logger and leave propagate = True, and the record is emitted once by the child and again by the root. Set propagate = False on any logger that owns its own handlers.
propagate = False blocks it.Effective level resolution is worth internalizing because it governs whether a record is created at all. When you log at a given level, the logger walks up the tree until it finds an ancestor with an explicitly set level, and compares against that. A logger left at the default NOTSET defers entirely to its parent. This means a misconfigured root level silently suppresses every record in the process, and conversely a child set to DEBUG with a root at WARNING still emits debug records through its own handlers. The level check happens before any handler or filter runs, so it is the cheapest place to control volume. The precise resolution rules and the OpenTelemetry severity translation are detailed in log levels and severity mapping, and the level layout for a running service is worked end to end in how to configure Python logging for production.
Library code should never configure the root logger or attach handlers. A library that calls logging.basicConfig() hijacks the host application's output. The correct contract is that libraries obtain a named logger and emit records; applications decide where those records go. A well-behaved library that fears emitting warnings before the host configures logging can attach a logging.NullHandler to its top-level logger, which absorbs records silently until the application installs real handlers. Detailed routing patterns, fan-out to multiple sinks, and queue-based dispatch are covered in handler architecture.
# module: payment/gateway.py — Python 3.12 standard library only, no dependencies.
import logging
# Library code: get a named logger, never configure handlers here.
logger = logging.getLogger(__name__) # "payment.gateway"
def charge(amount_cents: int, currency: str) -> None:
# Structured fields travel in extra={}, never concatenated into the message.
logger.info("charge initiated", extra={"amount_cents": amount_cents, "currency": currency})
Expected Output: (when the application configures a JSON handler on the root logger)
{"level": "INFO", "logger": "payment.gateway", "message": "charge initiated", "amount_cents": 4200, "currency": "USD"}
The LogRecord as a Data Model
Everything downstream — filters, formatters, handlers, the OpenTelemetry bridge — operates on a single object: the LogRecord. Treating it as your event data model rather than as an implementation detail is what makes the pipeline predictable. The record is constructed once per emitted call, carries the call site, the timestamp, the severity, the un-interpolated format string with its arguments, and any attributes you attach through extra={}. Because msg and args stay separate until something calls record.getMessage(), the interpolation cost of logger.debug("state %s", expensive) is never paid when the level is disabled — which is precisely why f-strings in log calls are a performance regression rather than a style preference.
The following record attributes are the ones worth mapping deliberately onto your structured output. Aligning them with OpenTelemetry semantic conventions at the formatter means the same records survive a move from a log-file backend to an OTLP pipeline without a remapping layer.
| Record attribute | What it holds | Structured field to emit |
|---|---|---|
created, msecs |
Unix timestamp of the call | timestamp as RFC 3339 UTC |
levelname, levelno |
Severity text and numeric value | level, severity_number |
name |
Dotted logger name | logger |
msg, args |
Format string plus lazy arguments | message (after getMessage()) |
exc_info |
Exception type, value, traceback | exception.type, exception.stacktrace |
pathname, lineno, funcName |
Call site | code.filepath, code.lineno, code.function |
process, thread |
OS process and thread identity | process.pid, thread.id |
taskName (Python 3.12+) |
Name of the running asyncio task | asyncio.task |
Anything you add through extra={} becomes a plain attribute alongside these, which is why the reserved-name collision described below is a real hazard rather than a theoretical one.
Handler, Formatter, and Filter Responsibilities
These three abstractions are frequently conflated, and keeping their responsibilities distinct is the difference between a maintainable pipeline and an unreadable one. A handler owns a destination and the I/O to reach it: StreamHandler writes to a stream, RotatingFileHandler writes to a rolling file, SocketHandler writes to a TCP socket. A handler also has its own level, which is a second gate applied after the logger's level, so a single logger can fan one record out to a console handler at INFO and a file handler at DEBUG. A formatter is pure transformation: it takes a LogRecord and returns a string, with no I/O and no routing decisions. A filter is a predicate that returns truthy to admit a record and falsy to drop it, and — critically — it runs early enough that it is also the correct place to enrich a record with derived fields such as a trace identifier before any handler formats it.
The order matters. A record is created only if it clears the logger's effective level. It then passes through the logger's filters, propagates to each handler, clears each handler's own level, passes through that handler's filters, and finally is rendered by that handler's formatter. Because filters can mutate the record in place, attaching an enrichment filter to the logger applies it once for every downstream sink, whereas attaching it to a single handler scopes the enrichment to that one destination. Choosing the attachment point deliberately is what keeps redaction uniform and correlation fields consistent.
Output Formatting and Structured Data
The single most impactful change you can make is to move from human-readable text to machine-parsable JSON. Structured emission turns log lines into queryable events: level:ERROR AND service.name:checkout AND amount_cents:>10000 is impossible against free text but trivial against structured records. A custom logging.Formatter that serializes a dictionary to JSON is the minimum viable implementation; the field schema is what matters, and the full implementation is walked through in structured logging with the Python standard library.
A deliberate structured-data strategy treats the record as a typed event with three layers. The first is the fixed envelope every record carries: timestamp, level, logger name, and message. The second is the correlation layer of identifiers that join records across services: service.name, deployment.environment, deployment.version, and a request or trace id. The third is the event-specific payload passed through extra={}, which varies per call site. Keeping these layers explicit lets you validate the envelope and correlation layers in CI while leaving the payload open, and it prevents the common drift where one team's userId is another's user_id. Align the field names with OpenTelemetry semantic conventions from the start so the same records flow through the OTLP bridge without remapping; the mechanics of writing formatters and choosing serializers are detailed in formatter configuration, and the correlation layer specifically in adding trace ids to log records.
Timestamps deserve one explicit decision. The default %(asctime)s renders local time with a comma-separated millisecond field, which no ingestion pipeline parses natively and which becomes ambiguous the moment a container runs in a different zone. Emit UTC in RFC 3339 form (2026-07-25T14:32:01.123Z) from a formatter that calls datetime.fromtimestamp(record.created, tz=timezone.utc). That is the one field every backend indexes and every query orders by, so getting it wrong degrades every subsequent investigation.
Strip sensitive payloads and PII before serialization. Implement deterministic hashing for user identifiers so events remain joinable without storing raw values. Never log raw authentication tokens, full payment card numbers, or unmasked financial data. Redaction belongs in a logging.Filter that runs before the formatter, so the rule is enforced uniformly across every sink.
There is a subtle correctness trap in stdlib logging that structured emission depends on getting right: the extra={} dictionary keys become attributes on the LogRecord, but they collide fatally with reserved record fields such as message, args, levelname, and name. Passing extra={"message": ...} raises KeyError at emission time. Namespace your custom fields or nest them under a single key like extra={"context": {...}} to avoid the reserved-name surface entirely. A robust JSON formatter also handles non-serializable values defensively with json.dumps(..., default=str), because an arbitrary object attached through extra would otherwise raise inside the formatter and, depending on logging.raiseExceptions, either crash the call or silently swallow the record.
Serialization cost is the one place where the standard library shows its age. json.dumps is pure-Python for anything but the simplest types, and at tens of thousands of records per second it becomes measurable. Two mitigations compose well: keep the serializer off the request path entirely (the queue pattern below), and swap in a faster encoder behind the same formatter interface. If your team would rather adopt a library that ships this design pre-assembled, the comparison in structlog vs Loguru vs stdlib logging covers what you gain and what you give up.
Instrumentation Strategy and Configuration
Static, hard-coded logging configuration hinders incident triage. Centralize configuration declaratively with logging.config.dictConfig(), which describes the entire logger, handler, formatter, and filter graph in a single dictionary. This is the canonical approach for production services and is covered end to end in logging configuration and dictConfig, with an annotated reference configuration in configuring logging with dictConfig. A dictionary configuration is loadable from YAML or environment-driven settings, version-controlled, and applied atomically at startup.
dictConfig is more than a convenience wrapper. It resolves the entire graph in dependency order — formatters first, then filters, then handlers that reference them by name, then loggers that reference the handlers — so a single typo in a handler's formatter key fails loudly at startup rather than producing silently unformatted output later. The disable_existing_loggers flag is the field that most often surprises teams: left at its default of True, it disables every logger created before dictConfig ran, which silently mutes any module-level logger imported earlier. Setting it to False is almost always what a production service wants. The ext:// prefix lets the dictionary reference live objects such as ext://sys.stdout without importing them, keeping the configuration declarative and serializable.
formatter key crashes at startup instead of producing unformatted output hours later.The bootstrap sequence that survives contact with production is short and worth following in order. First, fix the record schema — envelope, correlation, and payload layers — because every later decision references those field names. Second, express the whole graph as a dictConfig dictionary with disable_existing_loggers set to False, and call it exactly once from the entry point before any request is served. Third, attach the enrichment and redaction filters at the logger rather than at individual handlers so every sink inherits identical fields. Fourth, make a QueueHandler the only handler on the application logger and let a QueueListener own the concrete sinks. Fifth, register the shutdown path — listener.stop() plus any exporter flush — with the framework's shutdown hook, because records buffered in a queue at exit are records you will wish you had during the postmortem.
# Python 3.12 standard library only — dictConfig ships with the interpreter.
import logging.config
LOGGING = {
"version": 1,
"disable_existing_loggers": False, # keep module loggers imported before this call
"formatters": {
"json": {"format": '{"level":"%(levelname)s","logger":"%(name)s","msg":"%(message)s"}'},
},
"handlers": {
# ext:// resolves the live object without importing it here.
"stdout": {"class": "logging.StreamHandler", "formatter": "json", "stream": "ext://sys.stdout"},
},
"loggers": {
# propagate=False because this logger owns its handler.
"payment": {"level": "INFO", "handlers": ["stdout"], "propagate": False},
},
"root": {"level": "WARNING", "handlers": ["stdout"]},
}
logging.config.dictConfig(LOGGING)
logging.getLogger("payment.gateway").info("configured")
Expected Output:
{"level":"INFO","logger":"payment.gateway","msg":"configured"}
During an incident you often need to raise verbosity on one subsystem without a restart. Call logging.getLogger("payment").setLevel(logging.DEBUG) from a guarded administrative endpoint, scope it to a specific tenant or trace identifier, and automate rollback with a timer to prevent uncontrolled storage growth. Expose any such endpoint behind strict authentication and record every configuration mutation for audit compliance.
Guard expensive serialization behind logger.isEnabledFor(level) checks on hot paths. The level mapping you choose directly determines alert fidelity, so align Python's defaults (DEBUG=10, INFO=20, WARNING=30, ERROR=40, CRITICAL=50) with your alerting contracts as described in log levels and severity mapping. Resist the urge to invent custom numeric levels such as TRACE=5 or NOTICE=25 unless you also own the mapping into every downstream system — a custom level that no exporter recognizes collapses into the nearest standard band and quietly distorts both alert routing and dashboards.
Async and Concurrency Patterns
Standard logging calls are thread-safe: a module-level lock serializes handler emission. They are not, however, async-aware, and they carry no request-scoped context on their own. The correct pattern is to store per-request metadata in contextvars.ContextVar objects and read them in a filter at emission time. Context variables propagate correctly across await boundaries within a task and are copied when a new task is spawned, which makes them the right primitive for asyncio services. The full treatment of safe context propagation lives in context variables and thread safety, with the request-scoped pattern applied concretely in using contextvars for request tracing.
The serialization and I/O performed by handlers must never run on the event loop or a request worker thread. Wrap concrete handlers with QueueHandler, which only enqueues the record, and drain the queue from a dedicated QueueListener consumer thread. This keeps the calling path free of formatting and write latency. The dedicated walkthrough is non-blocking logging with QueueHandler. Always copy context variables explicitly before crossing a thread boundary, because a worker thread does not inherit the spawning task's context.
await boundary is free: a thread hop needs an explicit copy_context(), and a process hop starts with an empty context and its own logger tree.There is a deeper reason the queue matters under asyncio specifically: a single synchronous write to a slow file or socket inside a handler blocks the entire event loop, not just the coroutine that logged, because the loop runs cooperatively on one thread. A 5 ms disk hiccup therefore stalls every concurrent request the loop was juggling. Moving the I/O to a QueueListener thread bounds the producer's cost to a non-blocking enqueue and isolates the loop from sink latency entirely.
Process boundaries break more assumptions than thread boundaries do. Under gunicorn, uvicorn --workers, or a multiprocessing.Pool, each worker is a distinct interpreter with its own logger tree, its own handlers, and its own file descriptors. Two processes appending to the same file with a RotatingFileHandler will eventually corrupt a rollover, because the rename is not coordinated. The safe topologies are either one sink per process (distinct filenames, or simply stdout with the platform collecting per-container streams) or a multiprocessing.Queue feeding a single listener process that owns the sink exclusively. Context variables are not inherited across a fork in any useful way either, so worker initialization must re-establish resource attributes such as service.instance.id explicitly. The patterns are worked through in thread-safe logging in multiprocessing.
# Python 3.12 standard library only — asyncio, contextvars, logging.handlers.
import asyncio
import json
import logging
import queue
from contextvars import ContextVar
from logging.handlers import QueueHandler, QueueListener
request_id_ctx: ContextVar[str | None] = ContextVar("request_id", default=None)
class RequestContextFilter(logging.Filter):
"""Attach request-scoped context read from contextvars to each record."""
def filter(self, record: logging.LogRecord) -> bool:
record.request_id = request_id_ctx.get()
return True
class JSONFormatter(logging.Formatter):
def format(self, record: logging.LogRecord) -> str:
payload = {
"timestamp": self.formatTime(record, self.datefmt),
"level": record.levelname,
"message": record.getMessage(),
"request_id": getattr(record, "request_id", None),
"logger": record.name,
}
if record.exc_info and record.exc_info[0] is not None:
payload["exception"] = self.formatException(record.exc_info)
return json.dumps(payload, default=str)
def setup_async_logger() -> tuple[logging.Logger, QueueListener]:
log_queue: queue.Queue = queue.Queue(maxsize=10000) # bounded to cap memory
console = logging.StreamHandler()
console.setFormatter(JSONFormatter())
console.addFilter(RequestContextFilter())
listener = QueueListener(log_queue, console, respect_handler_level=True)
listener.start() # background drain thread
logger = logging.getLogger("app")
logger.setLevel(logging.INFO)
logger.addHandler(QueueHandler(log_queue)) # non-blocking enqueue only
logger.propagate = False
return logger, listener
async def process_request(logger: logging.Logger) -> None:
token = request_id_ctx.set("req-8f3a-9c2b")
try:
logger.info("Processing payment workflow")
await asyncio.sleep(0.01)
finally:
request_id_ctx.reset(token)
if __name__ == "__main__":
app_logger, listener = setup_async_logger()
asyncio.run(process_request(app_logger))
listener.stop() # flush and join the drain thread on shutdown
Expected Output: (Python 3.12, stdlib logging)
{"timestamp": "2026-06-19 14:32:01,123", "level": "INFO", "message": "Processing payment workflow", "request_id": "req-8f3a-9c2b", "logger": "app"}
Network and Protocol Integration
Logs become observability data only when they reach a backend. In containerized deployments the cloud-native convention is to write JSON to sys.stdout and let the platform's collector tail the container log. Disable direct file handlers in ephemeral containers; a RotatingFileHandler inside a pod competes with the orchestrator's own log capture and complicates rotation. Where a file sink is genuinely required — a host agent, a VM deployment, an audit trail with its own retention rules — the durability and locking concerns are covered in best practices for log rotation in Python.
To bridge Python logging into the OpenTelemetry pipeline, use the OTel Logs Bridge API. It maps each LogRecord to OTel semantic conventions, attaches active trace_id and span_id from the current span context, and exports over OTLP gRPC or HTTP to a collector. Records should be batched by a BatchLogRecordProcessor to minimize network round-trips, and the W3C Trace Context fields must align with the trace identifiers your tracing layer emits — the same identifiers described in context propagation and baggage.
localhost: routing, sampling, and vendor credentials live at the collector, which is what keeps backend migrations out of application config.Treat the collector as the integration boundary rather than wiring each service directly to a vendor backend. A service exports OTLP to a local collector agent, the collector enriches and batches, and only the collector holds vendor credentials and routing rules. This keeps the application's logging configuration stable across backend migrations and lets you change sampling or destination centrally.
Severity mapping matters at this boundary because three numbering schemes meet here. Python uses 10 to 50, OpenTelemetry uses a 1 to 24 severity_number scale, and syslog uses 0 to 7 in the opposite direction — lower is more severe. The bridge handles the standard translation, but any custom level you define needs an explicit mapping or it collapses into the nearest standard band and distorts alerting. The syslog direction specifically is worked through in mapping Python log levels to syslog.
| Python level | levelno |
OTel severity_number |
syslog severity | Typical production routing |
|---|---|---|---|---|
DEBUG |
10 | 5 | 7 (debug) | Off by default; enabled per-subsystem during triage |
INFO |
20 | 9 | 6 (informational) | Sampled; the bulk of ingested volume |
WARNING |
30 | 13 | 4 (warning) | Retained in full; dashboards only |
ERROR |
40 | 17 | 3 (error) | Retained in full; paged if rate exceeds budget |
CRITICAL |
50 | 21 | 2 (critical) | Retained in full; always paged |
# pip install "opentelemetry-sdk>=1.30.0,<2.0.0" \
# "opentelemetry-instrumentation-logging>=0.51b0,<1.0.0"
import logging
from opentelemetry import trace
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk._logs import LoggerProvider
from opentelemetry.sdk._logs.export import BatchLogRecordProcessor, ConsoleLogExporter
from opentelemetry.instrumentation.logging import LoggingInstrumentor
# Initialize the OTel providers once at startup, after any worker fork.
trace.set_tracer_provider(TracerProvider())
logger_provider = LoggerProvider()
# Batching amortizes the network round-trip across many records.
logger_provider.add_log_record_processor(BatchLogRecordProcessor(ConsoleLogExporter()))
# Bridge stdlib logging into the OTel Logs pipeline and inject trace ids.
LoggingInstrumentor().instrument(set_logging_format=True)
logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)
with trace.get_tracer("app").start_as_current_span("checkout_flow"):
logger.info("Cart validation complete", extra={"cart_id": "c_9921"})
Expected Output: (representative OTLP log record, opentelemetry-sdk>=1.30.0,<2.0.0)
{
"body": "Cart validation complete",
"severity_number": 9,
"severity_text": "INFO",
"attributes": {
"cart_id": "c_9921",
"code.function": "<module>",
"trace_id": "0x8a3f3c12d4bf92f3577b34da6a3ce929",
"span_id": "0x9b2ea41f00f067aa"
}
}
Data Volume and Cost Control
Log volume is the dominant driver of observability cost, and most of that volume is DEBUG and INFO noise that no one queries. Set the production level to INFO or WARNING by default and elevate selectively. Sample high-frequency events at the emission boundary rather than discarding them downstream, where you have already paid the ingestion cost.
When a bounded queue saturates during a sink outage, drop DEBUG records first to preserve ERROR and CRITICAL visibility. This trade-off prioritizes incident response over diagnostic completeness and prevents the logging subsystem from triggering an out-of-memory kill. On disk-backed sinks, cap retention with rotation. Finally, prune redundant fields from your record schema. Every field is multiplied by your event rate, so a 200-byte field on a 50,000-events-per-second service is roughly 800 GB per day before compression.
Cost control is also a sampling-design problem, not only a level-threshold problem. A flat 1% sample of INFO discards the one slow request you needed; an outcome-biased sample that always keeps records carrying an error flag or a high latency attribute keeps the signal while shedding the bulk. Implement that decision in a filter at the emission boundary so the dropped records never cost serialization, never enter the queue, and never reach the collector. The non-blocking queue and its drop policy are the second safety net for the volume that survives sampling, detailed in non-blocking logging with QueueHandler.
Retention tiering is the last lever and the one most teams leave unpulled. Not every record needs the same lifetime: seven days of hot, fully indexed storage covers almost all incident investigation, while compliance and audit records belong in cheap object storage with a much longer horizon and no index at all. Route by a field in the record — an audit: true attribute or a dedicated logger name — at the collector rather than in the application, so retention policy stays a platform decision. Where a signal is genuinely a counter rather than an event, move it out of logs entirely: a per-request "cache hit" line at 50,000 requests per second is a metric, not a log, and costs orders of magnitude less as one.
Production Code Examples
The three examples below are not independent recipes: each one plugs into a different stage of the same record pipeline, which is why they compose without touching one another.
Redacting PII with a reusable filter
The cleanest place to enforce data-protection rules is a logging.Filter shared across every handler. It runs before any formatter, so the redaction applies uniformly regardless of sink.
# Python 3.12 standard library only — hashlib, logging, re.
import hashlib
import logging
import re
EMAIL = re.compile(r"[\w.+-]+@[\w-]+\.[\w.-]+")
class RedactionFilter(logging.Filter):
"""Hash user ids and mask emails before any handler formats the record."""
def filter(self, record: logging.LogRecord) -> bool:
user_id = getattr(record, "user_id", None)
if user_id is not None:
# Deterministic hash keeps events joinable without storing the raw id.
record.user_id = hashlib.sha256(str(user_id).encode()).hexdigest()[:16]
record.msg = EMAIL.sub("[redacted-email]", str(record.msg))
return True
logging.basicConfig(level=logging.INFO, format="%(levelname)s user=%(user_id)s %(message)s")
log = logging.getLogger("auth")
log.addFilter(RedactionFilter()) # attached at the logger, so every sink inherits it
log.info("login from alice@example.com", extra={"user_id": 100237})
Expected Output: (Python 3.12)
INFO user=8c6f9a1b2e3d4f50 login from [redacted-email]
Correlating logs with an active trace
When logging runs inside a span, injecting the active trace and span identifiers lets your backend join a log line to the exact request that produced it.
# pip install "opentelemetry-api>=1.30.0,<2.0.0" "opentelemetry-sdk>=1.30.0,<2.0.0"
import logging
from opentelemetry import trace
class TraceContextFilter(logging.Filter):
def filter(self, record: logging.LogRecord) -> bool:
# Zero-filled ids keep the field present when no span is active.
ctx = trace.get_current_span().get_span_context()
record.trace_id = format(ctx.trace_id, "032x") if ctx.is_valid else "0" * 32
record.span_id = format(ctx.span_id, "016x") if ctx.is_valid else "0" * 16
return True
logging.basicConfig(
level=logging.INFO,
format='{"msg":"%(message)s","trace_id":"%(trace_id)s","span_id":"%(span_id)s"}',
)
log = logging.getLogger("checkout")
log.addFilter(TraceContextFilter())
with trace.get_tracer("app").start_as_current_span("place_order"):
log.info("order accepted")
Expected Output: (with a configured TracerProvider)
{"msg":"order accepted","trace_id":"4bf92f3577b34da6a3ce929d0e0e4736","span_id":"00f067aa0ba902b7"}
Capturing exceptions with structured tracebacks
Production incident debugging depends on exceptions arriving as structured records rather than bare stderr dumps. logger.exception inside an except block attaches exc_info, and a JSON formatter renders the traceback into a single queryable field so the stack is searchable alongside its correlation identifiers.
# Python 3.12 standard library only — json, logging, sys.
import json
import logging
import sys
class ExcJSONFormatter(logging.Formatter):
def format(self, record: logging.LogRecord) -> str:
payload = {
"level": record.levelname,
"logger": record.name,
"message": record.getMessage(),
}
if record.exc_info:
# Render the traceback into one field instead of multiple stderr lines.
payload["exception"] = self.formatException(record.exc_info)
return json.dumps(payload)
handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(ExcJSONFormatter())
log = logging.getLogger("orders")
log.setLevel(logging.INFO)
log.addHandler(handler)
log.propagate = False # this logger owns its handler, so do not re-emit at the root
def settle(order_id: str) -> None:
try:
raise ValueError("gateway declined")
except ValueError:
# exc_info=True is implied by logger.exception.
log.exception("settlement failed", extra={"order_id": order_id})
if __name__ == "__main__":
settle("o_5521")
Expected Output: (single JSON record; traceback abbreviated)
{"level": "ERROR", "logger": "orders", "message": "settlement failed", "exception": "Traceback (most recent call last):\n File \"app.py\", line 27, in settle\n raise ValueError(\"gateway declined\")\nValueError: gateway declined"}
Common Mistakes
- Using
print()for production diagnostics. It bypasses the logging pipeline entirely, so there is no level filtering, no structured formatting, and no path to centralized aggregation. Every diagnostic statement should go through a named logger. - Blocking I/O in synchronous handlers. File or network writes on the request thread cause P99 latency spikes under sustained load, and on the event loop they stall every concurrent request. Wrap concrete handlers with
QueueHandlerand drain from aQueueListenerbackground thread. - String concatenation or f-strings instead of structured fields. Building messages like
f"user {uid} failed"defeats downstream parsers and pays the interpolation cost even when the level is disabled. Pass structured data throughextra={}and serialize with a JSON formatter so fields stay queryable. - Missing correlation identifiers. Without a request or trace id on every record, logs cannot be joined across service boundaries, and distributed debugging becomes guesswork.
- Configuring logging inside library code. Calling
basicConfig()or attaching handlers in an imported package hijacks the host application's output and produces duplicate or misrouted lines. Libraries emit; applications configure. - Leaving
propagate = Trueon a logger that owns handlers. Records are then emitted once by the child and again by the root, doubling volume and corrupting any per-record metrics. - Leaving
disable_existing_loggersat its default. AdictConfigcall with the flag leftTruesilently mutes every logger created before configuration ran, which usually means every module-level logger imported at startup. Set it toFalsefor application services. - Never flushing on shutdown. A process that exits without calling
listener.stop()and flushing the OTLP log record processor discards exactly the records emitted during the failure that killed it. Wire both into the framework's shutdown hook.
Related Reading
- Handler Architecture — routing, multi-sink fan-out, queue-based dispatch, and rotation.
- Formatter Configuration — writing JSON formatters, field schemas, and trace-id injection.
- Log Levels and Severity Mapping — effective level resolution and the OTel and syslog translations.
- Context Variables and Thread Safety — request context across tasks, threads, and processes.
- Logging Configuration and dictConfig — declarative, environment-driven configuration applied at startup.
- Exception and Traceback Logging —
exc_info, chained exceptions, the hooks that catch what escapes, and redaction. - Python Logging Performance and Overhead — what a log call actually costs, and how to shed volume without going dark.
- Modern Python Logging Libraries Deep Dive — where structlog and Loguru change these trade-offs.
- Distributed Tracing and OpenTelemetry in Python — the trace identifiers your log records correlate against.
- Python Metrics and Instrumentation — the signal to reach for when an event is really a counter.
Frequently Asked Questions
Why should production Python services use structured logging instead of plain text?
Structured JSON enables automated parsing, efficient querying, and reliable correlation across distributed systems. This reduces mean time to resolution during incidents by eliminating manual log scanning and brittle regex parsers.
How does Python logging integrate with OpenTelemetry without vendor lock-in?
OpenTelemetry provides a standardized Logs Bridge API that maps Python log records to OTel semantic conventions. Records export to any compliant backend through the OTLP protocol, so you can switch vendors without rewriting instrumentation.
What is the performance overhead of JSON formatting in high-throughput services?
Overhead is minimal when serialization is deferred to a background thread. Wrap concrete handlers with QueueHandler and QueueListener so the calling thread never blocks on formatting or I/O, and guard expensive log calls with isEnabledFor on hot paths.
How can I safely log sensitive data without exposing PII?
Implement a logging.Filter that redacts or deterministically hashes sensitive fields before serialization, and validate schema compliance at the formatter layer. Never log raw authentication tokens, full payment card numbers, or unmasked personal identifiers.
Should libraries configure the root logger?
No. Library code should only obtain a named logger and emit records, leaving handler and level configuration to the application. Configuring the root logger from a library produces duplicate output and surprises downstream consumers.
What is the difference between a handler, a formatter, and a filter?
A handler decides where a record goes and owns the I/O; a formatter decides how the record is serialized into text or JSON; a filter decides whether a record passes and can enrich it with extra fields. A record flows logger to filter to handler to formatter to sink.
Does the GIL make logging a throughput bottleneck under high concurrency?
The module-level lock serializes handler emission, so every thread that logs contends on the same lock while a handler performs its write. The contention only matters when the work inside the lock is slow, which is why moving formatting and I/O behind a QueueHandler — leaving only a non-blocking enqueue on the caller — removes logging as a throughput ceiling.