
Logging in Python: Moving Beyond print()
Every Python program starts out debugging with print(). It's immediate and it works. Then the program grows: it runs on a server where nobody watches the terminal, you need to know when something happened, you want the noisy debug output gone in production but back on when a bug shows up, and you want errors written to a file with full tracebacks. Now you're commenting print calls in and out, and they're mixed into the program's real output.
The logging module solves all of that, and it's in the standard library. Each message gets a severity level, a timestamp, and the name of the module that produced it. Where messages go, how they look, and which ones are shown is configured in one place, separate from the code that emits them.
This guide covers levels, named loggers, handlers and formatters, configuring logging for a real application with dictConfig, logging exceptions, structured JSON logs, and the mistakes that cause missing or duplicated messages.
Why Not Just print()?
print() has a few problems that get worse as a program grows:
- No severity. A debug detail and a fatal error look the same.
- No on/off switch. You can't silence debug output without editing code.
- One destination. Everything goes to standard output, mixed in with the program's actual output.
- No context. No timestamp, no module name, no line number, unless you add them by hand every time.
With logging, the code says what happened and how serious it is. Configuration decides everything else.
The Quickest Possible Start
You can call the module-level functions directly:
import logging
logging.warning("Disk space is low")
logging.info("This will not appear")
WARNING:root:Disk space is low
Two things to notice. The info message vanished, because the default threshold is WARNING. And the format is bare: level, logger name (root), message. Both are fixed with basicConfig.
Log Levels
Every message has a level. A logger only passes on messages at or above its configured level.
| Level | Value | Use it for |
|---|---|---|
DEBUG | 10 | Detailed internals you only need while diagnosing a problem |
INFO | 20 | Normal, noteworthy events: startup, requests, jobs completed |
WARNING | 30 | Something unexpected that the program handled |
ERROR | 40 | An operation failed |
CRITICAL | 50 | The program itself may not be able to continue |
Setting the level to INFO shows INFO, WARNING, ERROR, and CRITICAL, and hides DEBUG. That's the whole filtering model, and it's what lets you leave debug statements in your code permanently.
basicConfig: Good Enough for Scripts
basicConfig sets up the root logger with a level and a format in one call:
import logging
logging.basicConfig(
level=logging.DEBUG,
format="%(asctime)s %(levelname)-8s %(name)s: %(message)s",
datefmt="%H:%M:%S",
)
logger = logging.getLogger("shop.orders")
logger.debug("Loaded %d orders from cache", 42)
logger.info("Order %s placed by %s", "A-1001", "ada")
logger.warning("Payment retry %d/%d", 2, 3)
logger.error("Could not reach inventory service")
logger.critical("Database unavailable, shutting down")
07:05:12 DEBUG shop.orders: Loaded 42 orders from cache
07:05:12 INFO shop.orders: Order A-1001 placed by ada
07:05:12 WARNING shop.orders: Payment retry 2/3
07:05:12 ERROR shop.orders: Could not reach inventory service
07:05:12 CRITICAL shop.orders: Database unavailable, shutting down
The format string uses LogRecord attributes. The ones you'll use most:
| Placeholder | Meaning |
|---|---|
%(asctime)s | Time the record was created |
%(levelname)s | DEBUG, INFO, ... |
%(name)s | Logger name |
%(message)s | The formatted message |
%(module)s, %(funcName)s, %(lineno)d | Where the call happened |
%(process)d, %(threadName)s | Process ID and thread name |
basicConfig only does something the first time it's called, and only if the root logger has no handlers yet. If a call seems to be ignored, something else configured logging first. Pass force=True to replace the existing setup.
Pass Arguments, Don't Pre-Format
Notice the calls above use logger.info("Order %s placed by %s", order_id, user) rather than an f-string. That's intentional. The arguments are only merged into the message if the record is actually going to be emitted. With an f-string, the string is built every time, even for a debug message that gets thrown away (assume state and expensive_repr are defined elsewhere):
logger.debug(f"State: {expensive_repr(state)}") # always calls expensive_repr
logger.debug("State: %s", expensive_repr(state)) # still evaluates the argument...
To be precise, the second form still evaluates expensive_repr(state) because it's a normal function argument. What it skips is the string formatting. If the argument itself is expensive, guard it:
if logger.isEnabledFor(logging.DEBUG):
logger.debug("State: %s", expensive_repr(state))
The %s style also keeps the message template constant, which lets log aggregation tools group "Order %s placed" events together regardless of the order ID.
Named Loggers: One per Module
Instead of calling logging.info() on the root logger, create a logger per module:
# myapp/orders.py
import logging
logger = logging.getLogger(__name__)
def place_order(order_id: str, total: float) -> None:
logger.debug("Validating order %s", order_id)
logger.info("Order %s placed, total %.2f", order_id, total)
__name__ is the module's dotted import path, such as myapp.orders, so every message records exactly where it came from. getLogger returns the same object for the same name, so there's no need to pass loggers around.
The dots matter. Loggers form a hierarchy: myapp.orders is a child of myapp, which is a child of the root logger. Two rules follow from that:
- Levels are inherited. If
myapp.ordershas no level set, it uses the nearest ancestor's level. SettingmyapptoDEBUGturns on debug output for your whole package. - Records propagate upward. A message logged on
myapp.ordersis passed to the handlers ofmyappand then the root logger. So you typically attach handlers once, at the root, and every module's messages flow there.
That's why library code and application modules should only ever call getLogger(__name__) and log. They shouldn't add handlers or call basicConfig. Configuration is the application's job, done once at startup.
Handlers and Formatters
A logger decides whether a message is emitted. A handler decides where it goes, and a formatter decides what it looks like. One logger can have several handlers, each with its own level and format.
A common setup sends INFO and above to the console in a short format, and everything including DEBUG to a file in a detailed format:
import logging
import sys
logger = logging.getLogger("shop")
logger.setLevel(logging.DEBUG)
console = logging.StreamHandler(sys.stderr)
console.setLevel(logging.INFO)
console.setFormatter(logging.Formatter("%(levelname)s: %(message)s"))
logfile = logging.FileHandler("app.log", encoding="utf-8")
logfile.setLevel(logging.DEBUG)
logfile.setFormatter(
logging.Formatter("%(asctime)s %(levelname)s %(name)s [%(funcName)s:%(lineno)d] %(message)s")
)
logger.addHandler(console)
logger.addHandler(logfile)
logger.debug("Cache warmed with %d keys", 120)
logger.info("Server started on port %d", 8000)
logging.getLogger("shop.payments").warning("Card declined for order %s", "A-1002")
The console shows:
INFO: Server started on port 8000
WARNING: Card declined for order A-1002
And app.log gets everything:
2026-09-20 07:05:00,123 DEBUG shop [<module>:20] Cache warmed with 120 keys
2026-09-20 07:05:00,123 INFO shop [<module>:21] Server started on port 8000
2026-09-20 07:05:00,123 WARNING shop.payments [<module>:22] Card declined for order A-1002
Filtering happens twice: first at the logger's level, then at each handler's level. The logger is set to DEBUG so nothing is dropped early, and each handler picks what it wants. The shop.payments message reached both handlers through propagation, even though the handlers are attached to shop.
Some handlers worth knowing, all in logging or logging.handlers:
| Handler | Writes to |
|---|---|
StreamHandler | sys.stderr by default, or any stream |
FileHandler | A file |
RotatingFileHandler | A file, rolled over at a size limit |
TimedRotatingFileHandler | A file, rolled over by time (e.g. midnight) |
SysLogHandler | The system log |
QueueHandler / QueueListener | A queue, so slow I/O happens off the main thread |
NullHandler | Nowhere (used by libraries) |
Note that logging writes to standard error by default, not standard output. That's what you want: a command-line tool's real output stays clean on stdout, and diagnostics go to stderr.
Configuring a Real Application with dictConfig
Wiring handlers by hand gets verbose. For applications, logging.config.dictConfig describes the whole setup as a dictionary, which is easier to read and easy to load from a file if you want:
# myapp/logging_config.py
import logging.config
from pathlib import Path
LOG_DIR = Path("logs")
def setup_logging(level: str = "INFO") -> None:
LOG_DIR.mkdir(exist_ok=True)
logging.config.dictConfig(
{
"version": 1,
"disable_existing_loggers": False,
"formatters": {
"simple": {"format": "%(levelname)s %(name)s: %(message)s"},
"detailed": {
"format": "%(asctime)s %(levelname)s %(name)s %(process)d %(message)s",
},
},
"handlers": {
"console": {
"class": "logging.StreamHandler",
"formatter": "simple",
"level": level,
"stream": "ext://sys.stderr",
},
"file": {
"class": "logging.handlers.RotatingFileHandler",
"formatter": "detailed",
"level": "DEBUG",
"filename": str(LOG_DIR / "app.log"),
"maxBytes": 1_000_000,
"backupCount": 5,
"encoding": "utf-8",
},
},
"loggers": {
"myapp": {"level": "DEBUG"},
"urllib3": {"level": "WARNING"},
},
"root": {"level": "INFO", "handlers": ["console", "file"]},
}
)
Call it once, as early as possible in your entry point:
# main.py
import logging
from myapp.logging_config import setup_logging
from myapp.orders import place_order
setup_logging()
logger = logging.getLogger("myapp")
logger.info("Starting up")
place_order("A-1001", 59.9)
logging.getLogger("urllib3").info("Starting new HTTPS connection")
Console output:
INFO myapp: Starting up
INFO myapp.orders: Order A-1001 placed, total 59.90
And logs/app.log:
2026-09-20 07:05:00,990 INFO myapp 70190 Starting up
2026-09-20 07:05:00,991 DEBUG myapp.orders 70190 Validating order A-1001
2026-09-20 07:05:00,991 INFO myapp.orders 70190 Order A-1001 placed, total 59.90
A few details in this config are worth calling out:
"version": 1is required. It's the schema version, and 1 is the only one."disable_existing_loggers": Falseis important. The default isTrue, which silences every logger that already exists whendictConfigruns. Heremyapp.orderswas created at import time, beforesetup_logging()was called, so with the default its messages would silently disappear. Always set this toFalse.- Handlers live on the root logger. Everything propagates there, including third-party libraries.
- The
myapplogger is set toDEBUG, so your own debug messages reach the file handler, while the root stays atINFOfor everything else. - Noisy libraries are turned down with their own entry.
urllib3(used byrequests) is chatty atINFO, so its info message was dropped. RotatingFileHandlercaps the file at about 1 MB and keeps 5 old copies (app.log.1toapp.log.5), so logs never fill the disk.
Since it's just a dictionary, you can keep it in a JSON or TOML file and load it at startup, or tweak the level from a command-line flag. If you're building a CLI, mapping -v and -vv to INFO and DEBUG is a common pattern; see building command-line tools with argparse.
Logging Exceptions
When you catch an exception you want to record, use logger.exception() inside the except block. It logs at ERROR level and appends the full traceback:
import logging
logging.basicConfig(level=logging.INFO, format="%(levelname)s %(name)s: %(message)s")
logger = logging.getLogger(__name__)
def parse_price(raw: str) -> float:
try:
return float(raw)
except ValueError:
logger.exception("Could not parse price %r", raw)
return 0.0
parse_price("12,50")
ERROR __main__: Could not parse price '12,50'
Traceback (most recent call last):
File "/home/maria/shop/prices.py", line 9, in parse_price
return float(raw)
ValueError: could not convert string to float: '12,50'
If you want the traceback at a different level, pass exc_info=True to any logging call, for example logger.warning("Retrying", exc_info=True).
A common anti-pattern is logger.error(str(e)) or logger.error(f"Error: {e}"). You lose the traceback, which is usually the most useful part. And avoid logging an exception and then re-raising it at every layer; you'll get the same traceback five times. Log it once, where it's actually handled. The exception handling guide covers where that should be.
Adding Context to Messages
The extra Argument
extra attaches additional attributes to a log record. They can be referenced in a format string or picked up by a custom formatter:
logger.info("Request handled", extra={"path": "/orders", "status": 201})
If your format string references %(path)s, every message through that handler must supply path, or formatting fails. That makes extra most useful with formatters that handle missing keys, such as the JSON formatter below.
LoggerAdapter for Per-Request Context
When every message in a block of code should carry the same context, like a request ID, wrap the logger in a LoggerAdapter:
import logging
logging.basicConfig(level=logging.INFO, format="%(levelname)s [%(request_id)s] %(message)s")
base = logging.getLogger("api")
log = logging.LoggerAdapter(base, {"request_id": "req-7f3a"})
log.info("Fetching user %d", 42)
INFO [req-7f3a] Fetching user 42
Structured JSON Logs
When logs go to a system like Elasticsearch, Loki, Datadog, or CloudWatch, one JSON object per line is much easier to search than free text. You don't need a library for this; a small Formatter subclass does it:
# json_logging.py
import json
import logging
from datetime import UTC, datetime
STANDARD_ATTRS = set(vars(logging.makeLogRecord({}))) | {"message", "asctime"}
class JsonFormatter(logging.Formatter):
def format(self, record: logging.LogRecord) -> str:
payload = {
"time": datetime.fromtimestamp(record.created, tz=UTC).isoformat(),
"level": record.levelname,
"logger": record.name,
"message": record.getMessage(),
}
# Anything passed via extra= shows up as a non-standard attribute.
payload.update(
{key: value for key, value in vars(record).items() if key not in STANDARD_ATTRS}
)
if record.exc_info:
payload["exception"] = self.formatException(record.exc_info)
return json.dumps(payload, default=str)
handler = logging.StreamHandler()
handler.setFormatter(JsonFormatter())
logging.basicConfig(level=logging.INFO, handlers=[handler])
logger = logging.getLogger("api")
logger.info("Request handled", extra={"path": "/orders", "status": 201, "duration_ms": 18.4})
{"time": "2026-09-20T07:05:00.806690+00:00", "level": "INFO", "logger": "api", "message": "Request handled", "path": "/orders", "status": 201, "duration_ms": 18.4}
STANDARD_ATTRS is built from an empty LogRecord, so anything not in that set must have come from extra. record.getMessage() merges the %s arguments into the message, and default=str keeps json.dumps from failing on values like datetime or Decimal. For more on custom serialization, see working with JSON in Python.
Logging in Libraries
If you're writing a package that other people import, the rules are stricter:
- Use
logging.getLogger(__name__)and log. Nothing else. - Never call
basicConfigor add a handler to the root logger. That's the application's decision. - Optionally add a
NullHandlerto your package's top-level logger, which is the pattern the logging docs recommend:
# mylib/__init__.py
import logging
logging.getLogger(__name__).addHandler(logging.NullHandler())
Common Pitfalls
Messages appear twice. This almost always means a handler is attached to both a logger and one of its ancestors. The record is handled by the child's handler, then propagates up and is handled again by the root's:
import logging
logging.basicConfig(level=logging.INFO, format="%(levelname)s %(name)s: %(message)s")
logger = logging.getLogger("worker")
logger.addHandler(logging.StreamHandler())
logger.info("Job finished")
Job finished
INFO worker: Job finished
Fix it by attaching handlers in one place (usually the root), or set logger.propagate = False on the child if it really needs its own handler. Re-running setup code that calls addHandler (common in notebooks and tests) causes the same thing.
Debug messages don't show up. Check both levels: the logger's and the handler's. A DEBUG handler on an INFO logger still receives nothing below INFO.
Messages from your modules vanish after configuration. That's disable_existing_loggers defaulting to True in dictConfig or fileConfig. Set it to False.
Configuring at import time. Putting basicConfig at the top of a module means importing that module changes global logging. Keep configuration in your entry point, inside if __name__ == "__main__": or a main() function.
Logging sensitive data. Logs are often shipped to third-party services and kept for a long time. Keep passwords, tokens, and personal data out of messages and extra fields.
Logging vs print: A Quick Rule
Use print() for output that is the program's result: the report a CLI generates, the answer a script computes. Use logging for everything about the program: progress, decisions, warnings, and errors. When you're hunting a bug interactively, a debugger is often faster than either; how to debug a Python program covers that side.
Conclusion
The logging module looks intimidating because of its moving parts, but the model is simple: modules call getLogger(__name__) and log at an appropriate level, and the application configures handlers and formatters once at startup. Pass arguments instead of f-strings, use logger.exception() in except blocks, set disable_existing_loggers to False, and attach handlers in one place to avoid duplicates. Once that's in place, you can turn debug output on with a config change instead of a code change, and your print() calls can go back to printing results.


