Logging Best Practices

1. LEVELS — print() can't distinguish "this is routine info" from
   "this is a critical failure." Every print looks identical.

2. TIMESTAMPS — print("Order processed") tells you nothing about
   WHEN it happened, unless you manually format one into every call.

3. ROUTING — print() always goes to stdout. You can't send warnings
   to one file, errors to another, and info messages nowhere at all,
   without rewriting every call site.

4. VERBOSITY CONTROL — you can't turn print() calls "off" selectively.
   Either the print() line runs, or you delete/comment it out by hand.

import logging

logger = logging.getLogger(__name__)

logger.debug("Cache lookup for key=user:4821 — miss")       # DEBUG    — fine-grained, dev-only detail
logger.info("Order #8842 processed successfully")            # INFO     — routine, expected events
logger.warning("Retrying API call — attempt 2 of 3")          # WARNING  — unexpected, but recovered
logger.error("Failed to charge card for order #8842")          # ERROR    — a real failure, needs attention
logger.critical("Database connection pool exhausted")            # CRITICAL — the system is in serious trouble

DEBUG    — "here's exactly what the code is doing, step by step"
INFO     — "this expected thing happened"
WARNING  — "something odd happened, but I recovered"
ERROR    — "this specific operation failed"
CRITICAL — "the whole system may be about to go down"

LOGGER     — decides IF a message is important enough to process at all
HANDLER    — decides WHERE a message goes (console, a file, both, a remote server...)
FORMATTER  — decides WHAT a message looks like (timestamp, level, message text...)

import logging

logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

# A handler that writes to the console
console_handler = logging.StreamHandler()
console_handler.setLevel(logging.INFO)   # only INFO and above reach the console

# A formatter controlling the text layout of every message
formatter = logging.Formatter(
    "%(asctime)s | %(levelname)-8s | %(name)s | %(message)s"
)
console_handler.setFormatter(formatter)

logger.addHandler(console_handler)

logger.debug("This won't appear on console — below the handler's INFO level")
logger.info("Order #8842 processed successfully")
# Output: 2026-08-14 09:12:03,881 | INFO     | myapp.orders | Order #8842 processed successfully

import logging

logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)s | %(levelname)-8s | %(message)s",
)

logging.info("Service started")
# basicConfig() sets up the root logger in one call — fine for a small script,
# but real applications configure named loggers explicitly, as shown above.

import logging

logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

file_handler = logging.FileHandler("app.log")
file_handler.setLevel(logging.DEBUG)
file_handler.setFormatter(logging.Formatter(
    "%(asctime)s | %(levelname)-8s | %(name)s | %(message)s"
))

console_handler = logging.StreamHandler()
console_handler.setLevel(logging.WARNING)   # console stays quiet — only warnings and above
console_handler.setFormatter(logging.Formatter("%(levelname)s: %(message)s"))

logger.addHandler(file_handler)
logger.addHandler(console_handler)

logger.info("Order #8842 processed")      # goes to app.log only
logger.warning("Retry attempt 2 of 3")     # goes to both app.log AND the console

from logging.handlers import RotatingFileHandler

handler = RotatingFileHandler(
    "app.log", maxBytes=10 * 1024 * 1024, backupCount=5
)
# app.log fills up -> renamed to app.log.1, a fresh app.log starts.
# Once app.log.5 would be created, the oldest file is deleted instead.

2026-08-14 09:12:03 | INFO | Order #8842 processed for user 4821, total $129.50

# To find "every failed order for user 4821 over $100", a search tool has to
# parse this sentence with a fragile regex, hoping the wording never changes.

{"timestamp": "2026-08-14T09:12:03Z", "level": "INFO", "event": "order_processed",
 "order_id": 8842, "user_id": 4821, "total": 129.50}

# Now "every order over $100 for user 4821" is a direct field query —
# total > 100 AND user_id = 4821 — not a text-parsing guess.

logger.info(f"Login attempt: {request.json}")
# If request.json includes {"username": "...", "password": "hunter2"},
# that plaintext password is now permanently sitting in a log file.

logger.debug(f"Processing payment: {payment_details}")
# If payment_details includes a full card number, this is very likely
# a compliance violation (PCI-DSS) on top of being a security risk.

logger.info(f"Login attempt for username={request.json.get('username')!r}")
# No password in the log at all — just enough to investigate the attempt.

logger.debug(f"Processing payment for order_id={order_id}, "
             f"card_last4={card_number[-4:]}")
# Only the last 4 digits — enough to identify the transaction to a support
# agent, useless to an attacker who reads the log file.

import logging
from logging.handlers import RotatingFileHandler

def configure_logging():
    root = logging.getLogger()
    root.setLevel(logging.DEBUG)

    file_handler = RotatingFileHandler(
        "orders.log", maxBytes=5 * 1024 * 1024, backupCount=3
    )
    file_handler.setLevel(logging.DEBUG)
    file_handler.setFormatter(logging.Formatter(
        "%(asctime)s | %(levelname)-8s | %(name)s | %(message)s"
    ))

    console_handler = logging.StreamHandler()
    console_handler.setLevel(logging.INFO)
    console_handler.setFormatter(logging.Formatter(
        "%(levelname)-8s | %(message)s"
    ))

    root.addHandler(file_handler)
    root.addHandler(console_handler)

import logging

logger = logging.getLogger(__name__)

def process_order(order):
    logger.info(f"Processing order_id={order.id}")
    try:
        charge_card(order)
        logger.info(f"Payment succeeded for order_id={order.id}")
    except PaymentError as e:
        logger.error(f"Payment failed for order_id={order.id}: {e}")
        raise
    logger.debug(f"Order {order.id} full payload: {order.items}")

from logging_config import configure_logging
from orders import process_order

if __name__ == "__main__":
    configure_logging()
    process_order(load_next_order())

A subscription-box company runs a nightly script that charges every customer due for renewal that day. It has always used print() statements, redirected to a text file by the server's cron job (python billing.py >> billing_output.txt), and nobody has ever needed to look closely at that file — until a Monday when finance notices Friday night's revenue is roughly 15% below every other Friday that month.

What the investigation runs into immediately

The on-call engineer opens billing_output.txt expecting to find the answer quickly. Instead they find exactly what Part 01 of this module warned about: thousands of identical-looking lines of plain text, no timestamps (so there is no way to isolate "just Friday night's run" — the file is one continuous append across every night the script has ever run), and no severity level distinguishing a customer whose card was declined normally from a customer the script actually failed to process due to a bug. Every line looks the same.

What proper logging would have shown immediately

With the file re-run under a real logger — using getLogger(__name__), level-aware output, and a timestamp on every line, exactly as shown in Part 07 — the engineer would have been able to grep directly for ERROR lines within Friday's timestamp range and found the actual cause in seconds: a third-party payment API had briefly returned malformed responses for about twenty minutes, and the billing script's exception handling silently skipped those customers instead of raising or clearly recording the failure. Roughly 200 renewals were quietly never charged, and nothing distinguished those failures from the thousands of normal successful lines around them.

The team spent the rest of that week replacing every print() in the billing system with structured, leveled logging (Parts 02–05), specifically so that a future incident like this one would be a two-minute log search instead of a two-day manual investigation through an undifferentiated text file. This is precisely the gap between print() and real logging that this module opened with — and it is a genuinely common story across companies that treat logging as an afterthought until a missed-revenue incident forces the issue.