print is fine when you're poking at a script in front of you. The moment code runs unattended, in a container, on a server, or as a scheduled job, you need something with levels, destinations, structured output, and a way to turn the noise up or down without redeploying. That's the job of the logging module in the standard library. This lesson covers why print falls apart, the five log levels and when to use each, the logger hierarchy, the four-piece pipeline that every log message flows through, how to configure logging cleanly with dictConfig, structured and JSON output, how to log exceptions properly, and the small performance trap of f-strings inside log calls.
print Falls Apart in ProductionA print call writes a string to standard output. That's it. There's no severity, no timestamp, no source attribution, no destination control. For a 20-line script you ran by hand, that's enough. For anything that lives longer than the terminal session, you start hitting limits.
Consider a small order-processing job that uses print for everything:
Four problems show up immediately:
stdout. You can't send errors to a file and debug chatter to nowhere.print calls. To get it back during an incident, you redeploy.The logging module solves all four:
Same logic, now with timestamps, levels, and a switch (level=logging.WARNING and the INFO lines disappear). Nothing else in the function changed.
Logging defines five standard severities. Each one is a method on a logger and has an integer value behind it. A log call goes through only if its level is at least the level the logger is configured for.
| Level | Value | When to use it |
|---|---|---|
| DEBUG | 10 | Fine-grained internal state. Variable dumps, loop counters, intermediate values. |
| INFO | 20 | Routine operational events. "Order placed," "User logged in," "Cache warmed." |
| WARNING | 30 | Something unexpected but not yet broken. Retries, deprecated paths, near-limits. |
| ERROR | 40 | An operation failed. The program continues, but the request didn't succeed. |
| CRITICAL | 50 | The program itself is in trouble. Out of memory, database unreachable, exiting. |
The default level in basicConfig is WARNING, which means DEBUG and INFO are silently dropped unless you explicitly opt in. That default catches new users every time, so it's worth knowing.
Picking the right level matters because operators filter on it. A noisy ERROR log that's actually a transient retry is the kind of thing that wakes someone at 3 AM for nothing. A DEBUG log that's actually a failed payment goes unnoticed for weeks.
A practical rule of thumb:
WARNING or worse.INFO or worse.DEBUG.Loggers are arranged in a tree. The names are dotted strings (algomart.carts, algomart.orders.shipping), and the dots define parent-child relationships. At the top of the tree is the root logger, which has the empty string as its name.
Two rules make the hierarchy useful:
logging.getLogger("algomart.carts") always returns the same logger object, no matter where it's called from. There's one instance per name.algomart.orders.shipping emits a record, it walks up the tree (algomart.orders, then algomart, then root), and every logger along the way gets a chance to handle it. The level check and the handler attachment can happen anywhere on that path.The convention is to put logger = logging.getLogger(__name__) at the top of every module. __name__ is the module's dotted path, so the logger name lines up with the import path automatically. A log line from algomart/carts.py looks like it came from algomart.carts, which makes filtering and routing painless.
If you only want chatty debug output from the carts module while everything else stays at INFO, you set the level on that one logger:
Every other logger keeps its existing level. That's the payoff of the hierarchy: fine-grained control without touching the code.
basicConfigbasicConfig configures the root logger. It's a one-time setup function intended for the application that owns the process. If a library calls it, the library is making choices for the whole program, often before the program has even started its own setup.
The convention for library code is:
logger = logging.getLogger(__name__).basicConfig, do not add handlers, do not set levels on the root logger.If a library does want to silence its own logs by default (so importing it doesn't print "No handlers could be found for logger X" on older Pythons), it can attach a NullHandler to its top-level logger:
The NullHandler swallows records that reach it without producing any output. If the application sets up its own handlers, those still receive the records via propagation. If it doesn't, the library stays quiet.
A log record passes through four kinds of objects on its way out: Logger, Filter, Handler, and Formatter. Knowing what each does is the difference between guessing at config and being able to debug it.
logger.info(...), it creates a LogRecord, checks its own level, and dispatches to handlers (its own and its ancestors').filter(record) method that returns True to keep the record or False to drop it. Attached to loggers or handlers. Useful for narrow rules like "only records that mention user priya@example.com."StreamHandler writes to stdout/stderr, FileHandler to a file, RotatingFileHandler to a rotating file set, and so on. Each handler has its own level threshold.LogRecord into a string. Attached to handlers. Different handlers can use different formatters (terse stderr, verbose file).Here's the path a single logger.info(...) call takes:
The record is checked twice for level (once at the logger, once at each handler) and filtered twice (once at the logger, once at each handler). Either check can drop it. Once a handler accepts it, the formatter renders it and the destination receives the string.
The level filtering decision, in plain terms:
A common mistake is to set the logger to DEBUG but leave the handler at the default WARNING and wonder why debug records vanish. The handler is the second gate, and both have to be open.
The standard library ships handlers for the common destinations. A short tour of the ones that come up often.
StreamHandler writes to a stream, defaulting to sys.stderr. This is what basicConfig adds for you.
FileHandler opens a file and appends records to it. Good for short-lived processes; the file grows forever.
RotatingFileHandler is the version you actually want for long-running services. It rotates based on file size.
When algomart.log hits 5 MB, it becomes algomart.log.1 and a fresh algomart.log is opened. Older files shift up, and anything beyond backupCount is deleted.
TimedRotatingFileHandler rotates on a clock instead of size. Pick this when you want one file per day or per hour for log retention rules.
SysLogHandler sends records to a syslog daemon, locally over a Unix socket or remotely over UDP. Useful when ops wants logs in their existing syslog pipeline:
QueueHandler is for high-throughput or multi-process scenarios. The handler puts records on a queue.Queue, and a separate thread (a QueueListener) drains the queue and dispatches to real handlers. This keeps log calls in the hot path cheap, since they only enqueue, and moves the expensive I/O off to the listener thread. It's also the recommended way to log from multiple processes safely, since the queue can be shared.
You rarely need QueueHandler for a small app, but it's worth knowing exists the moment logging shows up in a profiler.
Cost: Synchronous handlers like FileHandler block the calling thread on every record. At a few thousand records per second on a slow disk, that's measurable. QueueHandler moves the I/O off the hot path and is the usual fix.
A formatter turns a LogRecord into the string that the handler writes. The default formatter is "just the message," which throws away timestamps, levels, and source. You almost always want to set your own.
The format string uses the old %-style placeholders by default, with named keys from the LogRecord attributes:
The most useful LogRecord attributes:
| Attribute | What it gives you |
|---|---|
%(asctime)s | Human-readable timestamp (controlled by datefmt) |
%(levelname)s | The level name: DEBUG, INFO, WARNING, ERROR, CRITICAL |
%(name)s | The logger's dotted name |
%(message)s | The fully-formatted log message |
%(module)s | Module name (filename without .py) |
%(funcName)s | Function name that emitted the record |
%(lineno)d | Source line number |
%(process)d | Process ID |
%(thread)d | Thread ID |
You can use a different placeholder style by passing style="{" for str.format style or style="$" for string.Template. %-style is the default and the most common in real codebases.
basicConfig, dictConfig, fileConfigThere are three built-in ways to configure logging.
`basicConfig` is the one-liner. It sets up the root logger with a single StreamHandler and a basic formatter. Good for scripts and the first cut of any program. It silently does nothing if the root logger already has handlers, so calling it twice from different modules doesn't do what you think.
`dictConfig` is the preferred way for anything larger than a script. You hand it a dictionary that describes the entire logging tree: formatters, handlers, loggers, and how they're wired. The configuration is data, which means it can live in a YAML or JSON file alongside the rest of your app config.
The console handler is at INFO, so the debug record is dropped there. The file handler is at DEBUG, so both records land in algomart.log. propagate: False on the algomart logger means records aren't bubbled up to the root, so the root's console handler doesn't double up.
A common pattern is to load the dict from a YAML file:
The YAML version is identical in structure, just easier on the eyes:
`fileConfig` is the legacy INI-format predecessor. It still works, but it's strictly less expressive than dictConfig (no filter objects, no programmatic computation, harder to read). New projects pick dictConfig.
Plain text logs are fine until you need to search them. The moment ops asks "show me every record for order_id=102," you want logs as structured data, not strings.
The built-in lever for this is the extra kwarg, which lets you attach arbitrary fields to a record:
The fields in extra show up as attributes on the LogRecord, so the formatter can reference them with %(order_id)s. The catch is that every record going through this formatter has to provide order_id, or the format call fails with KeyError. That's brittle.
The better approach is a JSON formatter. The handler emits one JSON object per line, and every extra field is just another key on the object. Ops feeds those lines into a search index and queries by field.
There's no JSON formatter in the standard library, but the third-party python-json-logger package fills the gap:
For richer structured logging with context that follows a request through call chains (a pattern called "context binding"), the structlog package is the popular choice. It wraps the standard library and adds a fluent API for binding key-value pairs:
structlog can render JSON, key-value pairs, or pretty colored output. It also plays well with dictConfig, so you can keep using the standard library's handler ecosystem.
There are two right ways to log an exception, and a popular wrong way.
The right ways:
logger.exception(msg) is shorthand for logger.error(msg, exc_info=True). Both attach the current exception's traceback to the record, and the formatter renders it after the message. The traceback is preserved in the log file or whatever destination the handler points at, which is the entire point: when something fails in production, you want the stack trace, not just a one-line summary.
exception must be called from inside an except block, because it pulls the active exception from sys.exc_info(). Outside an except block, there's no exception to attach, and the record will just say "NoneType: None" where the traceback would be.
The popular wrong way:
This logs the exception's __str__ but throws away the traceback. When you're debugging at 2 AM, you'll wish you had the stack frame where the error originated. Use logger.exception or pass exc_info=True so the traceback ends up in the logs.
If you want to log an exception at a level other than ERROR, use the explicit form:
The exc_info=True kwarg works on every log method, so you can attach a traceback at any level.
Log calls accept the format string and its arguments separately:
The string "Processed cart for %s, total $%.2f" and the two arguments are passed to the logger. The logger does the level check first. If the level is disabled, it returns immediately without ever formatting the string. The %-substitution only happens when the record is actually going to be emitted.
Compare that to the f-string version:
The f-string is built before the call, by the interpreter. By the time logger.debug sees the argument, it's already a fully formatted string. The level check happens after the work is done, so if DEBUG is disabled, the formatting was wasted.
For a single log call, the cost is microseconds. For a debug log inside a tight loop that runs ten thousand times per request, it adds up. The rule of thumb in production code:
%-style with separate args (logger.debug("got %s", x)) for log calls inside hot paths or at DEBUG level.INFO and above, where you almost always emit anyway.The logger also accepts str.format style if you pass extra={} carefully, but %-style is the convention and the one that works without extra config.
Cost: An f-string inside a disabled logger.debug runs the full formatting (string building, __format__ calls, attribute lookups) and throws the result away. Lazy %-style skips all of that. Both styles cost the same when the level is enabled.
A few traps that catch nearly everyone.
Calling `basicConfig` twice. basicConfig does nothing if the root logger already has handlers. If two modules call it with different settings, only the first one wins, silently. Either call it once at startup or use dictConfig and skip basicConfig entirely.
Library code adding handlers. A library that calls logger.addHandler(...) is configuring the host application's logging. If two libraries both add handlers, the user gets duplicate output and no way to turn it off without touching the libraries. Library code should only emit records via logging.getLogger(__name__) and let the application decide where the records go.
Setting the logger level but forgetting the handler. You set logger.setLevel(DEBUG) and debug records still don't appear. The handler is still at WARNING. Both gates have to be open.
Swallowing exceptions in `except` blocks. This logs nothing and re-raises nothing:
The error vanishes. At minimum, log it:
If you intentionally don't want to re-raise (say you've fallen back to a different code path), still log it. Silent failure is the worst kind of bug.
Mutating handlers from inside library code. If a library iterates logger.handlers and removes or modifies them, it's messing with the host application's setup. The host owns handlers. Libraries own log records.
Using `print` for "important" output and `logging` for the rest. Pick one. Either everything goes through logging (which is the right answer for any program that runs longer than a few seconds) or you're back to grep-driven debugging.
10 quizzes