lesson 119 Debugging & Logging · intermediate

Log exceptions with their traceback

When a program handles an error and carries on, the log must still say what failed and where. logger.exception writes the message and the full traceback; the error's type name makes a compact summary.

You'll be able to

Use log.exception(...) inside except to keep the traceback in the log
Read an error's type name with type(err).__name__ for summaries
Decide between logging and carrying on, and logging then re-raising

The idea

log.error("payment failed: %s", err) records the message ('amount') and nothing else: no type, no line. When the job carries on after an error, the log is the only place the traceback can survive.

log.exception("..."), called inside an except block, logs at ERROR level and appends the traceback of the error being handled. At other levels, pass exc_info=True to get the same traceback. For a one-line summary or a count, type(err).__name__ is the error's type as text, such as "KeyError".

Run each example to see what it prints. Running examples doesn't count toward progress.

example-1.py · One failed payment, with its traceback

import logging
import sys

logging.basicConfig(stream=sys.stdout, level=logging.INFO, format="%(levelname)s %(name)s: %(message)s", force=True)
log = logging.getLogger("payments")

def charge(payment):
    return round(payment["amount"] * 100)

for payment in [{"id": "PAY0000416", "amount": 35.84}, {"id": "PAY0000417"}]:
    try:
        cents = charge(payment)
        log.info("charged %s: %d cents", payment["id"], cents)
    except KeyError:
        log.exception("could not charge %s", payment["id"])
log.info("run finished")

A traceback per failure is right for the detail; for the end-of-run summary you want counts. Counting by type(err).__name__ (with Counter from the Collections & Itertools module) turns hundreds of failures into a few lines that point at the causes.

Not every error should be swallowed. If the failure means the whole run's result would be wrong, log it and re-raise with a bare raise inside the except block: the traceback is kept and the program stops.

example-2.py · Failures counted by type

import logging
import sys
from collections import Counter

logging.basicConfig(stream=sys.stdout, level=logging.WARNING, format="%(levelname)s %(name)s: %(message)s", force=True)
log = logging.getLogger("import")

def to_row(record):
    return {"sku": record["sku"], "price": float(record["price"]), "stock": int(record["stock"])}

records = [
    {"sku": "21329", "price": "2.55", "stock": "40"},
    {"sku": "85048", "price": "n/a", "stock": "3"},
    {"sku": "21252", "price": "1.25"},
    {"sku": "84031A", "price": "3.75", "stock": "4.5"},
]
rows = []
failures = Counter()
for record in records:
    try:
        rows.append(to_row(record))
    except (KeyError, ValueError) as err:
        failures[type(err).__name__] += 1
        log.warning("skipped %s: %s: %s", record["sku"], type(err).__name__, err)
print(len(rows), "rows imported")
print(dict(failures))

When to use it: log.exception in any except block that handles an error without re-raising it. Type names for summaries, dashboards and counts.

Mistakes to avoid: except Exception as err: log.error(err), which keeps only the message; calling log.exception outside an except block (there is no traceback to attach); and catching an error, logging it, and carrying on when the rest of the run depends on that step. Log and raise instead.

Review

log.exception("...") inside except logs at ERROR with the traceback; exc_info=True does the same at other levels.
type(err).__name__ names the error for summaries and counts.
Handle and continue only when the rest of the run is still meaningful; otherwise log and raise.
Next: choosing between a warning, a skip and a stop for each kind of bad input.

Practise this

The error that was swallowed