Debugging and logging

The problem we are solving

What everybody does when something goes wrong:

def discount(price, rate):
    print("price:", price)
    print("rate:", rate)
    result = price * (1 - rate)
    print("result:", result)
    return result


print(discount(100.0, 0.1))

price: 100.0
rate: 0.1
result: 90.0
90.0

It works. The trouble is what happens next.

Delete the lines and they have to be written again next time. Leave them and they stay in the code, and one day print on somebody else's terminal. And a program running on a server has no terminal at all — where print goes there, nobody knows.

This chapter is two things: how a program keeps an account of its own work, and how to get inside one while it is broken.

By the end of this chapter you can

• Read a traceback in the right order, and find the real place
• Write messages with logging, and choose between the levels
• Say why logging.getLogger(__name__) is written that way
• Keep a caught error's whole traceback with log.exception
• Say why messages are written with %s rather than an f-string
• Stop inside a running program with breakpoint()

Prerequisites: Testing with pytest.

A traceback is read from the bottom

def parse(text):
    return int(text)


def total(rows):
    return sum(parse(row) for row in rows)


print(total(["1", "2", "x"]))

Traceback (most recent call last):
  File "main.py", line 9, in <module>
    print(total(["1", "2", "x"]))
          ^^^^^^^^^^^^^^^^^^^^^^
  File "main.py", line 6, in total
    return sum(parse(row) for row in rows)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "main.py", line 6, in <genexpr>
    return sum(parse(row) for row in rows)
               ^^^^^^^^^^
  File "main.py", line 2, in parse
    return int(text)
           ^^^^^^^^^
ValueError: invalid literal for int() with base 10: 'x'

A great many people see this, take fright, and start reading at the top. The order is the other way round.

The last line matters most — what happened, and to which value. 'x' is not a number.

The block just above it is second — where it happened: inside parse, line 2.

The upper part is the route that got there, read downwards: <module> called total, total called the generator, that called parse. This part is needed when the question is "which call sent the bad value".

And the ^^^^ marks show which part of the line broke — most useful of all on a long line.

Find the lowest frame that is your own code. Even when half the traceback is library files, the problem is almost always in your last line.

logging instead of print

import logging

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

log = logging.getLogger("shop")

log.debug("this is not shown")
log.info("starting")
log.warning("price is unusually high: %s", 9999)
log.error("could not read the file")

INFO shop - starting
WARNING shop - price is unusually high: 9999
ERROR shop - could not read the file

The debug message is absent, because the level is set at INFO. This is the essential difference from print: the messages stay in the code, and you decide which of them are seen.

There are five levels, and their order is their definition:

import logging

logging.basicConfig(level=logging.WARNING, format="%(levelname)s - %(message)s")

log = logging.getLogger("shop")

log.debug("debug")
log.info("info")
log.warning("warning")
log.error("error")
log.critical("critical")

WARNING - warning
ERROR - error
CRITICAL - critical

Which, when, in a line each:

• debug — internal detail, wanted only while hunting
• info — normal events: started, so many rows read, finished
• warning — something is unusual, and work continues
• error — one job failed, not the program
• critical — the program cannot continue

logging writes to stderr and print writes to stdout. In a terminal both appear, so the difference goes unnoticed — but python main.py > out.txt sends only the print output to the file and leaves the log on screen. That is why the outputs below show the two streams separately — the printed lines, then the log; on your terminal they interleave.

__name__ — the module's name is the logger's name

import logging

log = logging.getLogger(__name__)


def line_total(price, quantity):
    log.debug("line_total(%s, %s)", price, quantity)
    return round(price * quantity * 1.15, 2)

And in main.py:

import logging

import pricing

logging.basicConfig(level=logging.DEBUG, format="%(levelname)s %(name)s - %(message)s")

log = logging.getLogger(__name__)

log.info("starting")
print(pricing.line_total(15.0, 3))

51.75

INFO __main__ - starting
DEBUG pricing - line_total(15.0, 3)

Chapter twenty-two's __name__ is back, under exactly the same rule: the file being run is __main__, and an imported module has its own name.

The benefit shows in the log — every message says where it came from. In a program of twenty modules, that is what makes the difference.

There is a less visible benefit too: the names form a tree through the dots, so shop.pricing's level can be turned up on its own while the rest of the program stays quiet.

Do not call basicConfig in a library. Each module writes only getLogger(__name__) and sends messages; where they go and how many of them is main's decision. Importing means running the file, so a library calling basicConfig takes over the logging of whoever imports it.

The whole traceback of a caught error

Chapter twenty-four taught catching errors. But catching is not supposed to mean losing the information.

import logging

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

log = logging.getLogger("shop")


def parse(text):
    return int(text)


for value in ["1", "x"]:
    try:
        print(parse(value))
    except ValueError:
        log.exception("could not parse %r", value)

print("still running")

1
still running

ERROR - could not parse 'x'
Traceback (most recent call last):
  File "main.py", line 14, in <module>
    print(parse(value))
          ^^^^^^^^^^^^
  File "main.py", line 9, in parse
    return int(text)
           ^^^^^^^^^
ValueError: invalid literal for int() with base 10: 'x'

log.exception keeps the whole traceback in the log — and the program still carries on.

This resolves chapter twenty-four's tension. except ... : pass loses the information; no except at all stops the program. log.exception gives both: work continues, and a full account of what broke survives.

When only the message is wanted, log.error:

import logging

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

log = logging.getLogger("shop")

try:
    int("x")
except ValueError as err:
    log.error("could not parse: %s", err)

print("done")

done

ERROR - could not parse: invalid literal for int() with base 10: 'x'

The rule is simple: log.exception inside an except block, log.error outside one. exception only means anything while an error is being handled.

%s in the message, not an f-string

Logging's conventional way of writing a message looks odd at first:

log.debug("line_total(%s, %s)", price, quantity)

The reason is laziness: if the level discards the message, the text is never assembled. Written as an f-string the assembling would happen first, and the result then be thrown away.

The limit is worth knowing too:

import logging

logging.basicConfig(level=logging.WARNING, format="%(levelname)s - %(message)s")

log = logging.getLogger("shop")


def expensive():
    print("expensive() was called")
    return 42


log.debug("value is %s", expensive())
log.debug("value is %s", "cheap")
print("done")

expensive() was called
done

The message was not printed, and expensive() ran anyway. What is lazy is the formatting, not the evaluation of the arguments — those are worked out before log.debug is called at all, because that is how every call in Python works.

So when something costly is wanted only for debugging, ask first: if log.isEnabledFor(logging.DEBUG):.

Writing to a file

import logging
from pathlib import Path

logging.basicConfig(
    level=logging.INFO,
    format="%(levelname)s %(name)s - %(message)s",
    filename="run.log",
)

log = logging.getLogger("shop")
log.info("starting")
log.warning("something odd")

print("nothing was printed to the screen by logging")
print(Path("run.log").read_text(encoding="utf-8"), end="")

nothing was printed to the screen by logging
INFO shop - starting
WARNING shop - something odd

With filename, the messages go to a file instead of the screen — and not one line of the code changes. This is where print and logging are furthest apart: the modules decide what is written, and main decides where it goes.

In practice the time goes in the format as well:

format="%(asctime)s %(levelname)-8s %(name)s - %(message)s"

which puts a date and time at the start of every line. The examples in this chapter leave it out, because the output would then differ on every run — and what a course prints should be what your machine prints.

Getting inside — breakpoint()

A log says what happened. Sometimes what is wanted is the state right now.

def discount(price, rate):
    result = price * (1 - rate)
    breakpoint()
    return result


print(discount(100.0, 0.1))

Reaching breakpoint() stops the program and gives a prompt. A session looks like this — the first line carries the full path of your own file:

> .../main.py(4)discount()
-> return result
(Pdb) p price
100.0
(Pdb) p rate
0.1
(Pdb) p result
90.0
(Pdb) c
90.0

A handful of commands covers most of the work:

• p <name> — print a value (pp prints it prettily)
• n — the next line, without going into a function
• s — step into the function
• c — carry on until the next stop
• l — show the surrounding code
• q — quit

The advantage over print is that you do not have to decide in advance what you want to see. Once stopped, any name can be printed and any expression run.

A complete example

pricing.py:

"""Prices and tax, with logging instead of prints."""

import logging

log = logging.getLogger(__name__)

TAX_RATE = 0.15


def line_total(price, quantity):
    log.debug("line_total(price=%s, quantity=%s)", price, quantity)
    if quantity < 1:
        raise ValueError(f"quantity must be at least 1: {quantity}")
    return round(price * quantity * (1 + TAX_RATE), 2)


def read_order(rows):
    """Returns the usable lines, logging and skipping the rest."""
    lines = []
    for number, row in enumerate(rows, start=1):
        try:
            name, price, quantity = row.split(",")
            lines.append((name, line_total(float(price), int(quantity))))
        except ValueError:
            log.warning("line %d skipped: %r", number, row)
    log.info("%d of %d lines usable", len(lines), len(rows))
    return lines

main.py:

import logging
import os

import pricing

logging.basicConfig(
    level=logging.DEBUG if os.environ.get("SHOP_DEBUG") else logging.INFO,
    format="%(levelname)-8s %(name)s - %(message)s",
)

log = logging.getLogger(__name__)

ROWS = ["pen,15.0,3", "bag,eight,1", "ink,120.0,2", "clip,5.0,0"]


def main():
    log.info("reading %d rows", len(ROWS))
    for name, amount in pricing.read_order(ROWS):
        print(f"{name:<6} {amount:>9.2f}")


if __name__ == "__main__":
    main()

Run plainly as python main.py — the printed rows:

pen        51.75
ink       276.00

And in the log:

INFO     __main__ - reading 4 rows
WARNING  pricing - line 2 skipped: 'bag,eight,1'
WARNING  pricing - line 4 skipped: 'clip,5.0,0'
INFO     pricing - 2 of 4 lines usable

Now run with SHOP_DEBUG=1, the same code:

INFO     __main__ - reading 4 rows
DEBUG    pricing - line_total(price=15.0, quantity=3)
WARNING  pricing - line 2 skipped: 'bag,eight,1'
DEBUG    pricing - line_total(price=120.0, quantity=2)
DEBUG    pricing - line_total(price=5.0, quantity=0)
WARNING  pricing - line 4 skipped: 'clip,5.0,0'
INFO     pricing - 2 of 4 lines usable

Five things worth looking at.

One program, two volumes of output, with no code changed. That is this chapter in miniature. Done with print, the cycle of adding lines and deleting them again would never end.

bag,eight,1 and clip,5.0,0 were skipped for two different reasons, and one except ValueError caught both. float("eight") raises a ValueError, and line_total raises one itself for quantity=0. Chapter twenty-four's design at work: the lower level throws, the upper level catches and decides what to do.

The debug log shows what the ordinary log cannot. For the clip row, line_total really was called — the DEBUG ... quantity=0 line proves it — and then threw. The bag row has no DEBUG line, because float("eight") broke before it. Both rows are "skipped", and they broke in different places, which only the debug level reveals.

The level comes from the environment, not the code. For a program running on a server that is the normal way — change a variable and run it again, rather than editing a file and releasing it.

pricing.py calls basicConfig nowhere. It only writes getLogger(__name__) and sends messages. Where they go and how many is entirely main's decision. Which is why testing pricing, or using it in another program, takes over nobody's logging.

When it breaks

Nothing appears in the log basicConfig was not called, or the level is too high. The default level is WARNING, so log.info is invisible by default.

I called basicConfig and nothing changed It takes effect once — if logging has already started somewhere, a later call is ignored in silence. Call it once at the very start, or pass force=True.

Every message appears twice basicConfig was called twice, or a library called it too. No basicConfig in libraries.

The log is not going to the file Logging had already started before filename was given. The "once" rule again.

I used log.exception and there is no traceback It only has a traceback inside an except block. Outside one, use log.error.

I ran python main.py > out.txt and the log is not in the file logging writes to stderr. Use 2> log.txt, or filename.

The traceback is long and all library files Read from the bottom up, and find the lowest frame that is your own code. The problem is almost always there.

breakpoint() does nothing PYTHONBREAKPOINT=0 is set. Remove it.

Your turn

Take chapter twenty-eight's library.py and replace every print with logging.

• log = logging.getLogger(__name__) at the top of the module
• A debug message in add(), with the book's title
• A warning when bad data is skipped
• A main.py that calls basicConfig and takes the level from an environment variable
• No basicConfig in library.py

Then six experiments:

• Run at level INFO, then at DEBUG. Did any code have to change?
• Add filename="run.log" to basicConfig. What is left on the screen?
• Call basicConfig in library.py as well. What happens to the messages?
• Cause a KeyError on purpose, then in the except block write log.error(err) once and log.exception("...") once. Which is more useful, and why?
• Write log.debug("%s", expensive()) where expensive() prints something, and keep the level at WARNING. Does expensive() run?
• Put a breakpoint() in and explore with p, n and c.

The fourth experiment is this chapter's last word. How a program is doing is known from what it leaves behind — and an except block that leaves nothing behind has only postponed the question.

What next

That is the end of the Python course. Twenty-nine chapters on, you can write a program, handle what breaks, test it and see what it is doing — and those last three are what keep a program alive beyond its first day.

The next step is no longer learning the language but doing something with it. The pandas course starts exactly there: chapter twenty-five's CSV files, but with thousands of rows, and questions a loop is no longer a sensible way to answer.