Debuggen en logging

Het probleem dat we oplossen

Wat iedereen doet als er iets misgaat:

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

Het werkt. Het probleem is wat er daarna gebeurt.

Haal de regels weg, dan moeten ze de volgende keer opnieuw geschreven worden. Laat je ze staan, dan blijven ze in de code, en op een dag print je op de terminal van iemand anders. En een programma dat op een server draait heeft helemaal geen terminal — waar print dan naartoe gaat, weet niemand.

Dit hoofdstuk gaat over twee dingen: hoe een programma een logboek van zijn eigen werk bijhoudt, en hoe je er tijdens een storing in kunt kijken.

Aan het einde van dit hoofdstuk kun je

• Een traceback in de juiste volgorde lezen, en de echte plek vinden
• Berichten schrijven met logging, en kiezen tussen de niveaus
• Uitleggen waarom logging.getLogger(__name__) zo geschreven wordt
• De volledige traceback van een opgevangen fout bewaren met log.exception
• Uitleggen waarom berichten met %s geschreven worden en niet met een f-string
• Een lopend programma stilzetten met breakpoint()

Wat je eerst nodig hebt: Testen met pytest.

Een traceback lees je van onderen

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'

Heel veel mensen zien dit, schrikken, en beginnen bovenaan te lezen. De volgorde is juist andersom.

De laatste regel is het belangrijkst — wat er misging, en met welke waarde. 'x' is geen getal.

Het blok direct erboven is het tweede — waar het gebeurde: binnen parse, regel 2.

Het bovenste deel is de route die daarheen leidde, van boven naar beneden gelezen: <module> riep total aan, total riep de generator aan, en die riep parse aan. Dit deel heb je nodig als de vraag is "welke aanroep heeft de foute waarde doorgegeven".

En de ^^^^-markeringen laten zien welk deel van de regel brak — vooral handig bij een lange regel.

Zoek het laagste frame dat van jouw eigen code is. Ook als de helft van de traceback uit bibliotheekbestanden bestaat, zit het probleem bijna altijd in je eigen laatste regel.

logging in plaats van 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

Het debug-bericht ontbreekt, omdat het niveau op INFO staat. Dit is het essentiële verschil met print: de berichten blijven in de code staan, en jij bepaalt welke ervan gezien worden.

Er zijn vijf niveaus, en hun volgorde is hun definitie:

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

Welk niveau wanneer, elk in één regel:

• debug — interne details, alleen nodig tijdens het zoeken
• info — normale gebeurtenissen: gestart, zoveel rijen gelezen, klaar
• warning — iets is ongewoon, en het werk gaat door
• error — één taak is mislukt, niet het hele programma
• critical — het programma kan niet verder

logging schrijft naar stderr en print schrijft naar stdout. In een terminal zie je beide, dus het verschil valt niet op — maar python main.py > out.txt stuurt alleen de print-uitvoer naar het bestand en laat het logboek op het scherm staan. Daarom tonen de voorbeelden hieronder de twee stromen apart — eerst de geprinte regels, dan het logboek; in je terminal lopen ze door elkaar.

__name__ — de naam van de module is de naam van de logger

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)

En 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)

De __name__ uit hoofdstuk 22 is terug, volgens precies dezelfde regel: het bestand dat gestart wordt is __main__, en een geïmporteerde module heeft zijn eigen naam.

Het voordeel zie je in het logboek — elk bericht zegt waar het vandaan komt. In een programma met twintig modules maakt dat het verschil.

Er is ook een minder zichtbaar voordeel: de namen vormen een boom via de punten, dus het niveau van shop.pricing kan apart omhoog gezet worden terwijl de rest van het programma stil blijft.

Roep basicConfig niet aan in een bibliotheek. Elke module schrijft alleen getLogger(__name__) en stuurt berichten; waar ze naartoe gaan en hoeveel er zijn, is de beslissing van main.

De reden komt uit twee regels samen. Importeren betekent het bestand uitvoeren. En basicConfig werkt alleen de eerste keer — als logging eenmaal is ingesteld, doen latere aanroepen stilletjes niets. Stel dat pricing.py per ongeluk zelf basicConfig aanroept:

import logging

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

log = logging.getLogger(__name__)


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

Draai het main.py van hierboven nog eens, zonder er iets aan te veranderen:

51.75

Dat is alles — geen logregels, en ook geen foutmelding. main.py deed eerst import pricing, dus de basicConfig van de bibliotheek liep als eerste en zette het niveau op WARNING. Daarna werd de eigen basicConfig(level=logging.DEBUG, ...) van main.py stilletjes genegeerd. De bibliotheek nam de logging over van het programma dat haar importeerde.

De volledige traceback van een opgevangen fout

Hoofdstuk 24 leerde fouten opvangen. Maar opvangen hoeft niet te betekenen dat je de informatie kwijtraakt.

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 bewaart de volledige traceback in het logboek — en het programma gaat gewoon door.

Dit lost het dilemma uit hoofdstuk 24 op. except ... : pass verliest de informatie; zonder except stopt het programma. log.exception geeft beide: het werk gaat door, en een volledig verslag van wat er misging blijft bewaard.

Als alleen het bericht nodig is, gebruik je 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'

De regel is eenvoudig: log.exception binnen een except-blok, log.error daarbuiten. exception betekent alleen iets zolang er een fout wordt afgehandeld.

%s in het bericht, geen f-string

De gebruikelijke manier waarop logging berichten opbouwt, ziet er eerst vreemd uit:

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

De reden is luiheid: als het niveau het bericht weggooit, wordt de tekst nooit samengesteld. Geschreven als f-string zou het samenstellen eerst gebeuren, en dan zou het resultaat weggegooid worden.

Ook de grens is het waard om te kennen:

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

Het bericht werd niet afgedrukt, maar expensive() werd toch uitgevoerd. Wat lui is, is de opmaak, niet het berekenen van de argumenten — die worden voordat log.debug wordt aangeroepen al berekend, want zo werkt elke aanroep in Python.

Dus als iets kostbaars alleen nodig is voor het debuggen, controleer dan eerst: if log.isEnabledFor(logging.DEBUG):.

Naar een bestand schrijven

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

Met filename gaan de berichten naar een bestand in plaats van naar het scherm — en er verandert geen enkele regel code. Hier liggen print en logging het verst uit elkaar: de modules bepalen wat er geschreven wordt, en main bepaalt waarheen.

In de praktijk zet je de tijd ook in de format:

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

Daarmee komt er een datum en tijd aan het begin van elke regel. De voorbeelden in dit hoofdstuk laten dat weg, omdat de uitvoer dan bij elke run anders zou zijn — en wat een cursus laat zien, moet hetzelfde zijn als wat jouw computer laat zien.

Erin kijken — breakpoint()

Een logboek zegt wat er gebeurd is. Soms wil je de toestand op dit moment zien.

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


print(discount(100.0, 0.1))

Als breakpoint() wordt bereikt, stopt het programma en verschijnt er een prompt. Een sessie ziet er zo uit — de eerste regel bevat het volledige pad van je eigen bestand:

> .../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

Een handvol commando's dekt het meeste werk:

• p <naam> — print een waarde (pp print hem mooi opgemaakt)
• n — de volgende regel, zonder in een functie te gaan
• s — stap de functie in
• c — doorgaan tot de volgende stop
• l — de omringende code tonen
• q — stoppen

Het voordeel ten opzichte van print is dat je niet van tevoren hoeft te bepalen wat je wilt zien. Eenmaal gestopt kun je elke naam printen en elke expressie uitvoeren.

Een compleet voorbeeld

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()

Gewoon uitgevoerd als python main.py — de geprinte rijen:

pen        51.75
ink       276.00

En in het logboek:

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

Nu met SHOP_DEBUG=1, dezelfde 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

Vijf dingen om op te letten.

Eén programma, twee hoeveelheden uitvoer, zonder dat de code is veranderd. Dat is dit hoofdstuk in het klein. Met print zou de cyclus van regels toevoegen en weer verwijderen nooit eindigen.

bag,eight,1 en clip,5.0,0 zijn om twee verschillende redenen overgeslagen, en één except ValueError ving beide op. float("eight") gooit een ValueError, en line_total gooit er zelf een voor quantity=0. Het ontwerp uit hoofdstuk 24 in actie: de lagere functie gooit een fout, de bovenste functie vangt hem op en beslist wat er gebeurt.

Het debug-logboek laat zien wat het gewone logboek niet kan. Bij de clip-rij is line_total echt aangeroepen — de regel DEBUG ... quantity=0 bewijst het — en daarna gooide hij een fout. Bij de bag-rij staat geen DEBUG-regel, omdat float("eight") brak voordat het zover kwam. Beide rijen zijn "overgeslagen", en ze braken op verschillende plekken, en dat laat alleen het debug-niveau zien.

Het niveau komt uit de omgeving, niet uit de code. Voor een programma op een server is dat de normale manier — een variabele veranderen en het opnieuw draaien, in plaats van een bestand bewerken en opnieuw uitrollen.

pricing.py roept nergens basicConfig aan. Het schrijft alleen getLogger(__name__) en stuurt berichten. Waar ze naartoe gaan en hoeveel er zijn, is volledig de beslissing van main. Daarom neemt het testen van pricing, of het gebruiken ervan in een ander programma, niemands logging over.

Wanneer het breekt

Er verschijnt niets in het logboek basicConfig is niet aangeroepen, of het niveau staat te hoog. Het standaardniveau is WARNING, dus log.info is standaard onzichtbaar.

Ik heb basicConfig aangeroepen en er veranderde niets Het werkt één keer — als logging ergens al is gestart, wordt een latere aanroep stilletjes genegeerd. Roep het één keer aan, helemaal aan het begin, of geef force=True mee.

Het niveau of de format van main heeft geen effect, en er is geen foutmelding Een geïmporteerde bibliotheek heeft zelf basicConfig aangeroepen, en dat gebeurde eerder dan de aanroep van main. Dus de basicConfig van main wordt stilletjes genegeerd. Haal basicConfig uit de bibliotheek — een bibliotheek gebruikt alleen getLogger(__name__).

Het logboek belandt niet in het bestand Logging was al gestart voordat filename werd opgegeven. Weer de "één keer"-regel.

Ik gebruik log.exception en er is geen traceback Die heeft alleen een traceback binnen een except-blok. Daarbuiten gebruik je log.error.

Ik heb python main.py > out.txt gedraaid en het logboek staat niet in het bestand logging schrijft naar stderr. Gebruik 2> log.txt, of filename.

De traceback is lang en bestaat uit bibliotheekbestanden Lees van onder naar boven en zoek het laagste frame dat van jouw eigen code is. Het probleem zit bijna altijd daar.

breakpoint() doet niets PYTHONBREAKPOINT=0 is ingesteld. Verwijder het.

Jouw beurt

Neem het library.py dat je in hoofdstuk 28 hebt getest en vervang elke print door logging.

• log = logging.getLogger(__name__) bovenaan de module
• Een debug-bericht in add(), met de titel van het boek
• Een warning wanneer slechte data wordt overgeslagen
• Een main.py dat basicConfig aanroept en het niveau uit een omgevingsvariabele haalt
• Geen basicConfig in library.py

Dan zes experimenten:

• Draai op niveau INFO, en daarna op DEBUG. Moest er code veranderen?
• Voeg filename="run.log" toe aan basicConfig. Wat blijft er op het scherm staan?
• Roep ook in library.py basicConfig aan, met een ander niveau dan main.py. Wiens niveau wordt nu gebruikt — en waarom?
• Veroorzaak opzettelijk een KeyError, en schrijf dan in het except-blok één keer log.error(err) en één keer log.exception("..."). Welke is nuttiger, en waarom?
• Schrijf log.debug("%s", expensive()), waarbij expensive() iets print, en houd het niveau op WARNING. Wordt expensive() uitgevoerd?
• Zet een breakpoint() erin en onderzoek met p, n en c.

Het vierde experiment is het laatste woord van dit hoofdstuk. Hoe het met een programma gaat, blijkt uit wat het achterlaat — en een except-blok dat niets achterlaat, heeft de vraag alleen maar uitgesteld.

Wat volgt

Dat is het einde van de Python-cursus. Na 29 hoofdstukken kun je een programma schrijven, opvangen wat er misgaat, het testen en zien wat het doet — en die laatste drie zorgen ervoor dat een programma ook na de eerste dag blijft werken.

De volgende stap is niet meer de taal leren, maar er iets mee doen. De pandas-cursus begint precies daar: de CSV-bestanden uit hoofdstuk 25, maar met duizenden rijen, en vragen die een lus niet meer redelijkerwijs kan beantwoorden.