Logging & Debugging

# The print() approach — quick, but no metadata, no off-switch
print("Something went wrong with user", user_id)

# The logging approach — severity, timestamp, and toggleable
import logging
logging.warning("Something went wrong with user %s", user_id)

import logging

logging.debug("Variable x = %d", x)        # Level 10
logging.info("Server started on port %d", port)  # Level 20
logging.warning("Disk usage above 80%%")    # Level 30
logging.error("Failed to connect to DB: %s", err)  # Level 40
logging.critical("Out of memory — shutting down")   # Level 50

import logging

logging.basicConfig(
    level=logging.DEBUG,
    format="%(asctime)s [%(levelname)s] %(message)s",
)

logging.info("App started")
# 2024-06-15 09:01:32,451 [INFO] App started

import logging

logging.basicConfig(
    level=logging.WARNING,
    filename="app.log",
    filemode="a",
    format="%(asctime)s %(levelname)s %(name)s: %(message)s",
)

logging.error("Database timeout")
# Written to app.log, not the console

import logging
import sys

# basicConfig sets up the file handler
logging.basicConfig(
    level=logging.DEBUG,
    filename="debug.log",
    format="%(asctime)s [%(levelname)s] %(name)s: %(message)s",
)

# Add a second handler for the console
console = logging.StreamHandler(sys.stdout)
console.setLevel(logging.INFO)
console.setFormatter(logging.Formatter("[%(levelname)s] %(message)s"))
logging.getLogger().addHandler(console)

logging.debug("Only in file")
logging.info("In file AND console")

import logging

# Best practice: one logger per module
logger = logging.getLogger(__name__)  # e.g. "myapp.services.auth"

import logging

# Suppose root has a StreamHandler
logging.basicConfig(level=logging.DEBUG)

child = logging.getLogger("myapp.db")
child.setLevel(logging.WARNING)

child.info("Ignored — below child's effective level")
child.warning("Handled by child, then propagated to root's handler")

# Stop propagation when a child has its own handler:
child.propagate = False

import logging
from logging.handlers import RotatingFileHandler, TimedRotatingFileHandler

logger = logging.getLogger("myapp")
logger.setLevel(logging.DEBUG)

# 1) Console handler — INFO and above
ch = logging.StreamHandler()
ch.setLevel(logging.INFO)

# 2) Rotating file handler — DEBUG and above, 5 MB per file, keep 3 backups
rfh = RotatingFileHandler(
    "app.log", maxBytes=5_000_000, backupCount=3
)
rfh.setLevel(logging.DEBUG)

# 3) Timed rotation — rotate at midnight, keep 7 days
tfh = TimedRotatingFileHandler(
    "daily.log", when="midnight", backupCount=7
)
tfh.setLevel(logging.WARNING)

# Attach all handlers
formatter = logging.Formatter("%(asctime)s [%(levelname)s] %(name)s: %(message)s")
for h in (ch, rfh, tfh):
    h.setFormatter(formatter)
    logger.addHandler(h)

logger.debug("Goes to rotating file only")
logger.info("Goes to console + rotating file")
logger.error("Goes to all three destinations")

import logging

fmt = logging.Formatter(
    fmt="%(asctime)s | %(levelname)-8s | %(name)s:%(funcName)s:%(lineno)d — %(message)s",
    datefmt="%Y-%m-%d %H:%M:%S",
)

# 2024-06-15 09:12:45 | ERROR    | myapp.db:connect:42 — Connection refused

import logging

# Only allow records from "myapp.services" and its children
f = logging.Filter("myapp.services")
handler.addFilter(f)

import logging

class DropNoisyModule(logging.Filter):
    """Suppress all records from the 'urllib3' logger."""

    def filter(self, record: logging.LogRecord) -> bool:
        # Return True to keep the record, False to drop it
        return not record.name.startswith("urllib3")


# Attach to a handler — only this destination is affected
console_handler.addFilter(DropNoisyModule())

# Or attach to a logger — all of its handlers are affected
logger = logging.getLogger("myapp")
logger.addFilter(DropNoisyModule())

import logging.config

LOGGING_CONFIG = {
    "version": 1,
    "disable_existing_loggers": False,
    "formatters": {
        "standard": {
            "format": "%(asctime)s [%(levelname)s] %(name)s: %(message)s",
            "datefmt": "%Y-%m-%d %H:%M:%S",
        },
        "brief": {
            "format": "[%(levelname)s] %(message)s",
        },
    },
    "handlers": {
        "console": {
            "class": "logging.StreamHandler",
            "level": "INFO",
            "formatter": "brief",
            "stream": "ext://sys.stdout",
        },
        "file": {
            "class": "logging.handlers.RotatingFileHandler",
            "level": "DEBUG",
            "formatter": "standard",
            "filename": "app.log",
            "maxBytes": 10_000_000,
            "backupCount": 5,
        },
    },
    "loggers": {
        "myapp": {
            "level": "DEBUG",
            "handlers": ["console", "file"],
            "propagate": False,
        },
        "urllib3": {
            "level": "WARNING",
        },
    },
    "root": {
        "level": "WARNING",
        "handlers": ["console"],
    },
}

logging.config.dictConfig(LOGGING_CONFIG)

logger = logging.getLogger("myapp.api")
logger.info("Server ready")  # goes to console + file via "myapp" config

# pip install python-json-logger
import logging
from pythonjsonlogger import jsonlogger

logger = logging.getLogger("myapp")
logger.setLevel(logging.DEBUG)

handler = logging.StreamHandler()
formatter = jsonlogger.JsonFormatter(
    fmt="%(asctime)s %(levelname)s %(name)s %(message)s",
    rename_fields={"asctime": "timestamp", "levelname": "level"},
)
handler.setFormatter(formatter)
logger.addHandler(handler)

logger.info("User signed in", extra={"user_id": 42, "ip": "10.0.0.1"})

{
  "timestamp": "2024-06-15 09:30:12,003",
  "level": "INFO",
  "name": "myapp",
  "message": "User signed in",
  "user_id": 42,
  "ip": "10.0.0.1"
}

def calculate_discount(price, pct):
    breakpoint()          # execution pauses here; opens (Pdb) prompt
    discount = price * pct / 100
    return price - discount

calculate_discount(100, 20)

import pdb, traceback

def risky():
    data = [1, 2, 3]
    return data[10]          # IndexError

try:
    risky()
except Exception:
    traceback.print_exc()
    pdb.post_mortem()        # opens (Pdb) at the crash site

# Drop into pdb at the first line of the script
python -m pdb my_script.py

# Post-mortem: run normally; if it crashes, open pdb at the exception
python -m pdb -c continue my_script.py

# ── In a LIBRARY ── (mylib/utils.py)
import logging

# Use __name__ — gives 'mylib.utils'; let the application configure the handler
logger = logging.getLogger(__name__)
logger.addHandler(logging.NullHandler())   # library standard — silent by default


# ── In an APPLICATION ── (main.py)
import logging
import logging.config
from mylib.utils import do_work

LOGGING_CONFIG = {
    "version": 1,
    "formatters": {
        "default": {"format": "%(asctime)s [%(levelname)s] %(name)s: %(message)s"}
    },
    "handlers": {
        "console": {
            "class": "logging.StreamHandler",
            "formatter": "default",
        }
    },
    "root": {"level": "INFO", "handlers": ["console"]},
}

logging.config.dictConfig(LOGGING_CONFIG)

do_work()   # mylib.utils log records now flow through the app's handler