Logging (and Why `print` Won't Cut It)

TL;DR

print is for debugging at your laptop. logging is for everything else. The standard library’s logging module gives you levels (DEBUG, INFO, WARNING, ERROR, CRITICAL), handlers (where logs go: stdout, a file, a network sink), formatters (how each line looks), and a hierarchy of loggers (one per module).

The minimum you should always do:

1. Use logging, not print. Library code MUST use logging (callers want to control output).
2. Get a logger per module: logger = logging.getLogger(__name__).
3. Configure once at the entry point, never inside library code.
4. Use structured logging (structlog, or stdlib + JSON formatter) for production services — text logs lose value at scale.

A 30-second template for a script:

import logging

logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)s %(name)s %(levelname)s %(message)s",
    datefmt="%Y-%m-%dT%H:%M:%S",
)
logger = logging.getLogger(__name__)

logger.info("starting training run")

The picture in your head

                 logger (e.g. logging.getLogger("my_project.train"))
                    |
                    | log record (level, msg, args, exception, ...)
                    v
              level filter   -- drops if below logger's threshold
                    |
                    v
              propagate?  -- yes -> walk up to parent logger; no -> stop
                    |
                    v
                  handlers (stdout, file, JSON to ELK, ...)
                    |
                    v
                formatters (text format, JSON format)
                    |
                    v
                  output

Each logger is identified by a dotted name. Loggers form a tree: my_project.train.optimizer is a child of my_project.train, which is a child of my_project, which is a child of the root logger. Log records propagate upwards by default; handlers at any level catch them.

This sounds elaborate; in practice you rarely touch the machinery. You configure once, then sprinkle logger.info(...) everywhere.

The five levels

The rule of thumb: could a human looking at this log ten minutes from now make a decision based on it? If yes, INFO. If it’s “just context for when something else fails,” DEBUG.

Set the level on the logger or via basicConfig(level=...). Production typically runs at INFO or WARNING.

A logger per module

# src/my_project/train.py
import logging
logger = logging.getLogger(__name__)   # __name__ == "my_project.train"

def train_epoch(loader, model):
    logger.info("starting epoch with %d batches", len(loader))
    for i, batch in enumerate(loader):
        ...
        if i % 100 == 0:
            logger.debug("batch %d loss=%.4f", i, loss)
    logger.info("epoch done")

Two important practices in that snippet:

1. Use %s placeholders, not f-strings. logger.info("loss=%.4f", loss) defers the formatting until the record is actually emitted (i.e. if DEBUG is off, the format never runs). f-strings format eagerly, wasting work on dropped records.
2. No global state. This module just gets its logger; the entry point configures handlers and levels. Library code that calls logging.basicConfig() itself is hostile — it overrides the application’s choices.

Configure at the entry point

# src/my_project/__main__.py
import logging
import sys

def configure_logging(level=logging.INFO, json_format=False):
    handler = logging.StreamHandler(sys.stdout)
    if json_format:
        # use a JSON formatter (e.g., python-json-logger)
        from pythonjsonlogger import jsonlogger
        handler.setFormatter(jsonlogger.JsonFormatter(
            "%(asctime)s %(name)s %(levelname)s %(message)s"
        ))
    else:
        handler.setFormatter(logging.Formatter(
            "%(asctime)s %(name)s %(levelname)s %(message)s",
            datefmt="%Y-%m-%dT%H:%M:%S",
        ))
    root = logging.getLogger()
    root.setLevel(level)
    root.addHandler(handler)
    # Optionally tame noisy libs
    logging.getLogger("urllib3").setLevel(logging.WARNING)
    logging.getLogger("openai._base_client").setLevel(logging.WARNING)

if __name__ == "__main__":
    configure_logging(level=logging.INFO,
                       json_format=os.getenv("ENV") == "production")
    main()

Typical pattern: text format locally for human reading, JSON in production for machine parsing (Datadog, ELK, Loki, etc.).

Structured logging — structlog

When you have a service emitting thousands of logs per second, plain text becomes useless. You can’t grep loss=0.34 and loss=0.342 and loss="0.3411 (val: 0.41)" consistently. Structured logging emits a record with named fields:

import structlog

log = structlog.get_logger()

log.info("epoch_done", epoch=3, loss=0.34, val_loss=0.41, lr=3e-4)

In production, this serialises to JSON:

{"event": "epoch_done", "epoch": 3, "loss": 0.34, "val_loss": 0.41,
 "lr": 0.0003, "timestamp": "...", "level": "info", "logger": "..."}

Now you can filter / aggregate / alert on loss > 1.0 in your log pipeline trivially.

For local dev, structlog formats the same record as readable text:

2026-05-03T14:23:01 [info] epoch_done epoch=3 loss=0.34 val_loss=0.41 lr=0.0003

Same call site, two output formats based on configuration. The right default for new ML services in 2026.

Logging exceptions — exc_info and logger.exception

try:
    risky_op()
except Exception:
    logger.exception("risky_op failed")    # logs at ERROR level WITH stack trace

logger.exception(msg) is shorthand for logger.error(msg, exc_info=True). The stack trace gets included in the log record.

For a known exception you want to log at WARNING:

try:
    flaky_call()
except APIError as e:
    logger.warning("transient API error: %s; retrying", e, exc_info=True)

exc_info=True includes the traceback at any level.

Per-record context — extra and adapters

logger.info("batch processed", extra={"batch_id": "abc123", "size": 64})

The extra dict gets attached to the record. Custom formatters can include it. With structlog, you’d use bind:

log = structlog.get_logger().bind(run_id="r-001", model="gpt-4o-mini")
log.info("starting")           # includes run_id and model
log.info("step done", step=5)  # also includes them

This is how you get “every log from this request includes the request ID” in a web service.

A worked ML example — training loop with structured logging

import structlog

log = structlog.get_logger()

def train(cfg, model, loader):
    log.info("training_start",
             model=model.__class__.__name__,
             batch_size=cfg.batch_size,
             lr=cfg.learning_rate)

    for epoch in range(cfg.epochs):
        epoch_log = log.bind(epoch=epoch)
        losses = []
        for i, batch in enumerate(loader):
            try:
                loss = train_step(model, batch)
                losses.append(loss)
            except OutOfMemoryError:
                epoch_log.warning("oom", batch_id=i, batch_size=len(batch))
                continue
            if i % 100 == 0:
                epoch_log.debug("batch_done", step=i, loss=loss)
        epoch_log.info("epoch_done",
                        avg_loss=sum(losses) / len(losses),
                        n_batches=len(losses))

    log.info("training_complete")

Each event is a named record with structured fields. In production this lights up in Datadog as filterable, alertable metrics. Locally it’s still readable text.

Common gotchas

• print in library code. Anyone using your library can’t easily silence or redirect it. Use logging. Always.
• logging.basicConfig() at module import time. Overrides whatever the app set. Library code never configures handlers.
• f-string in log calls. logger.info(f"loss={loss}") formats every time, even when the log is filtered out. Use logger.info("loss=%s", loss).
• Logging huge tensors. logger.info("weights: %s", model.state_dict()) serialises gigabytes of float32. Don’t. Log shapes, summaries, norms.
• Logging secrets. API keys, user data, prompt content. Strip before logging. Use a redaction processor with structlog.
• Many loggers, no parent setup. Logs disappear because the root logger has no handlers. Configure the root, or configure the parent of all your modules.
• Logging in tight inner loops. Even at filtered DEBUG, the call has overhead (a few µs). 100k calls/sec → noticeable. Sample.

When to use print after all

• One-off scripts you’ll run once and throw away.
• The very first 10 lines of a notebook cell where you just want to see a value.
• Output that’s the purpose of the script (a CLI tool’s main output).

For everything else: logging.

Where this shows up in real ML codebases

• Production inference services — every request gets a structured log line with request ID, latency, token counts, model.
• Training jobs — per-epoch metrics logged as structured records, shipped to a log aggregator alongside MLflow / W&B.
• Data pipelines — Airflow / Prefect tasks log progress; structured logs feed dashboards.
• Library code — every PyPI package uses logging, not print. Your import torch; torch.save(...) doesn’t print anything because PyTorch logs via logging.

The defensive habit: at the top of every .py file in a real project, logger = logging.getLogger(__name__). At the top of __main__.py, configure once. Never use print for anything you’d want to filter, search, or attach metadata to.

Resources

• Python docs — logging HOWTO — docs.python.org — start here.
• Python docs — logging cookbook — docs.python.org — recipes for common setups.
• structlog — structlog.org — the modern structured-logging library. Recommended default.
• loguru — github.com/Delgan/loguru — opinionated, simple, popular for scripts; integrates poorly with the stdlib so use carefully in libraries.
• python-json-logger — github.com/madzak/python-json-logger — minimal JSON formatter for stdlib logging.