Logging

Logging exceptions

Inside an except block, log.exception(...) logs at ERROR level and adds the full traceback, which is exactly what you need to find the cause later:

import io
import logging

buf = io.StringIO()
log = logging.getLogger("shop.import")
log.handlers.clear(); log.propagate = False
log.addHandler(logging.StreamHandler(buf))

def import_line(line):
    sku, qty = line.split(",")
    return sku, int(qty)

for line in ["TE-101,2", "PA-108,two"]:
    try:
        import_line(line)
    except ValueError:
        log.exception("couldn't import line %r", line)

text = buf.getvalue()
print(text.splitlines()[0])
print("traceback included:", "Traceback" in text, "| last line:", text.strip().splitlines()[-1])

Log an exception once, where you handle it. Logging it at every level as it travels up the call stack fills the logs with the same traceback five times. And don't log and re-raise and log again higher up: pick the place that can do something about it.

Configuring it all in one place

Configuration belongs at the program's entry point (the main function or the web app's startup), never inside library modules, which should only call getLogger(__name__). logging.config.dictConfig describes the whole setup as data, which can also come from a file:

import logging.config

logging.config.dictConfig({
    "version": 1,
    "formatters": {"short": {"format": "%(levelname)s %(name)s: %(message)s"}},
    "handlers": {
        "console": {"class": "logging.StreamHandler", "level": "INFO", "formatter": "short"},
        "file": {"class": "logging.FileHandler", "filename": "problems.log", "level": "WARNING", "formatter": "short"},
    },
    "root": {"level": "DEBUG", "handlers": ["console", "file"]},
})

Many services collect logs as JSON lines: one JSON object per line, so a search tool can filter by level, logger or any field without parsing free text. A small Formatter subclass does it, as the exercise shows.

Never log secrets or personal data. Passwords, API keys, tokens, card numbers and often email addresses must not reach logs. Logs get copied to many systems and kept for a long time, and more people can read them than can read the database. A filter on a handler can redact anything that slips through, but the first defense is not passing secrets to log calls at all.

import io
import logging
import re


class Redact(logging.Filter):
    def filter(self, record):
        return True


buf = io.StringIO()
log = logging.getLogger("drill.redact")
log.handlers.clear(); log.propagate = False
handler = logging.StreamHandler(buf)
handler.addFilter(Redact())
log.addHandler(handler)
log.warning("login failed for %s with password=%s", "ada", "hunter2")
print(buf.getvalue().strip())

What makes a good log line

A log is written for a stranger: you, months from now, at an inconvenient hour, trying to work out what happened. A few habits make that person's job much easier.

Say what happened, to what, with the numbers. "Failed" tells nobody anything. "Payment for order 50232 declined by the bank (code 51)" says which order, what went wrong and where to look next. Include the ids that let someone find the record: order numbers, product codes, request ids.

Log events, not every line. One INFO line when a job starts, one when it finishes with a summary, and a WARNING or ERROR for each problem is usually right. A log that records every loop step is too long to read, and it hides the line that matters.

Keep the format consistent. The same event should always produce the same message template, so you can search for it, count it and set an alert on it. That's another reason to pass values as arguments instead of building the text with an f-string.

Think about volume and cost. Logs are stored, shipped and searched, and all of that costs money. DEBUG is for turning on while investigating, not for leaving on in production. Rotating file handlers (logging.handlers.RotatingFileHandler) cap how much disk a log may use.

Test that you log what matters. pytest's caplog fixture captures log records in a test, so you can check that a failed payment really does produce an ERROR line.

import io
import logging

log_text = io.StringIO()
log = logging.getLogger("jobs.prices")
log.handlers.clear(); log.propagate = False
handler = logging.StreamHandler(log_text)
handler.setFormatter(logging.Formatter("%(levelname)-7s %(name)s: %(message)s"))
log.addHandler(handler)
log.setLevel(logging.INFO)

PRICES = {"TE-107": 356.25, "PA-111": 267.56, "CA-129": None}

def check_prices(targets):
    log.info("checking %d products", len(targets))
    alerts = 0
    for sku, target in targets.items():
        try:
            price = PRICES[sku]
            if price is None:
                log.warning("price for %s unavailable; skipped", sku)
                continue
            if price <= target:
                alerts += 1
                log.info("%s at $%.2f reached the target $%.2f", sku, price, target)
        except KeyError:
            log.exception("unknown product %s", sku)
    log.info("done: %d alert(s)", alerts)
    return alerts

check_prices({"TE-107": 400, "PA-111": 240, "CA-129": 25, "XX-000": 10})
for line in log_text.getvalue().splitlines():
    if not line.startswith(("Traceback", "  ")):
        print(line)