Debugging und Logging

Das Problem, das wir lösen

Das macht jeder, wenn etwas schiefgeht:

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

Es funktioniert. Das Problem kommt danach.

Löschst du die Zeilen, musst du sie beim nächsten Mal wieder schreiben. Lässt du sie drin, bleiben sie im Code, und eines Tages landen sie im Terminal von jemand anderem. Und ein Programm, das auf einem Server läuft, hat gar kein Terminal — wohin print dort schreibt, weiß niemand.

Dieses Kapitel hat zwei Teile: wie ein Programm selbst festhält, was es tut, und wie man in ein kaputtes Programm hineinschaut.

Am Ende dieses Kapitels kannst du

• Einen Traceback in der richtigen Reihenfolge lesen und die eigentliche Stelle finden
• Meldungen mit logging schreiben und zwischen den Leveln wählen
• Erklären, warum logging.getLogger(__name__) so geschrieben wird
• Den vollständigen Traceback eines abgefangenen Fehlers mit log.exception festhalten
• Erklären, warum Meldungen mit %s statt mit einem f-String geschrieben werden
• Ein laufendes Programm mit breakpoint() anhalten

Was du vorher brauchst: Testen mit pytest.

Ein Traceback wird von unten gelesen

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'

Sehr viele Leute sehen das, erschrecken und fangen oben an zu lesen. Die Reihenfolge ist andersherum.

Die letzte Zeile ist am wichtigsten — was passiert ist und bei welchem Wert. 'x' ist keine Zahl.

Der Block direkt darüber kommt als Zweites — wo es passiert ist: in parse, Zeile 2.

Der obere Teil ist der Weg dorthin, von oben nach unten gelesen: <module> hat total aufgerufen, total hat den Generator aufgerufen, und der hat parse aufgerufen. Dieser Teil braucht man, wenn die Frage lautet: „Welcher Aufruf hat den falschen Wert geschickt?“

Und die ^^^^-Markierungen zeigen, welcher Teil der Zeile kaputtging — am nützlichsten bei einer langen Zeile.

Such den untersten Frame, der dein eigener Code ist. Auch wenn die Hälfte des Tracebacks aus Bibliotheksdateien besteht: Das Problem steckt fast immer in deiner letzten Zeile.

logging statt 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

Die debug-Meldung fehlt, weil das Level auf INFO steht. Das ist der entscheidende Unterschied zu print: Die Meldungen bleiben im Code, und du entscheidest, welche davon sichtbar sind.

Es gibt fünf Level, und ihre Reihenfolge ist das, was sie ausmacht:

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

Wofür und wann, jeweils in einer Zeile:

• debug — interne Details, nur bei der Fehlersuche interessant
• info — normale Ereignisse: gestartet, so viele Zeilen gelesen, fertig
• warning — etwas ist ungewöhnlich, und die Arbeit geht weiter
• error — ein Auftrag ist fehlgeschlagen, nicht das ganze Programm
• critical — das Programm kann nicht weitermachen

logging schreibt nach stderr, print nach stdout. Im Terminal erscheinen beide, deshalb fällt der Unterschied nicht auf — aber python main.py > out.txt schreibt nur die print-Ausgabe in die Datei und lässt das Log auf dem Bildschirm. Deshalb zeigen die Ausgaben unten die beiden Ströme getrennt — erst die ausgegebenen Zeilen, dann das Log; in deinem Terminal mischen sie sich.

__name__ — der Modulname ist der Name des Loggers

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)

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

Das __name__ aus Kapitel 22 ist wieder da, nach genau derselben Regel: Die Datei, die gestartet wird, heißt __main__, und ein importiertes Modul hat seinen eigenen Namen.

Der Vorteil zeigt sich im Log — jede Meldung sagt, woher sie kommt. Bei einem Programm mit zwanzig Modulen macht genau das den Unterschied.

Es gibt außerdem einen weniger offensichtlichen Vorteil: Die Namen bilden über die Punkte einen Baum, sodass das Level von shop.pricing allein aufgedreht werden kann, während der Rest des Programms still bleibt.

Ruf basicConfig nicht in einer Bibliothek auf. Jedes Modul schreibt nur getLogger(__name__) und sendet Meldungen; wohin sie gehen und wie viele davon, entscheidet main.

Der Grund ergibt sich aus zwei Regeln zusammen. Importieren heißt, die Datei auszuführen. Und basicConfig wirkt nur beim ersten Mal — ist das Logging einmal eingerichtet, tun spätere Aufrufe stillschweigend nichts. Angenommen, pricing.py ruft aus Versehen selbst basicConfig auf:

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)

Starte die main.py von oben noch einmal, ohne sie überhaupt zu ändern:

51.75

Das war's — keine Log-Zeilen und auch kein Fehler. main.py hat zuerst import pricing ausgeführt, also lief das basicConfig der Bibliothek zuerst und setzte das Level auf WARNING. Danach wurde das eigene basicConfig(level=logging.DEBUG, ...) von main.py stillschweigend ignoriert. Die Bibliothek hat die Logging-Steuerung des Programms übernommen, das sie importiert hat.

Der vollständige Traceback eines abgefangenen Fehlers

Kapitel 24 hat gezeigt, wie man Fehler abfängt. Abfangen soll aber nicht heißen, dass die Information verloren geht.

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 hält den vollständigen Traceback im Log fest — und das Programm läuft trotzdem weiter.

Das löst das Dilemma aus Kapitel 24. except ... : pass verliert die Information; gar kein except bricht das Programm ab. log.exception bietet beides: Die Arbeit läuft weiter, und ein vollständiger Bericht darüber, was kaputtging, bleibt erhalten.

Wenn nur die Meldung gewünscht ist, nimm 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'

Die Regel ist einfach: log.exception innerhalb eines except-Blocks, log.error außerhalb davon. exception ergibt nur einen Sinn, während ein Fehler gerade behandelt wird.

%s in der Meldung statt eines f-Strings

Die übliche Schreibweise für eine Meldung beim Logging wirkt am Anfang seltsam:

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

Der Grund ist Faulheit: Verwirft das Level die Meldung, wird der Text gar nicht erst zusammengebaut. Als f-String geschrieben, würde das Zusammenbauen zuerst passieren, und das Ergebnis würde dann weggeworfen.

Die Grenze sollte man auch 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

Die Meldung wurde nicht ausgegeben, und expensive() lief trotzdem. Faul ist das Formatieren, nicht das Auswerten der Argumente — die werden bevor log.debug überhaupt aufgerufen wird berechnet, weil jeder Aufruf in Python so funktioniert.

Wenn etwas Aufwendiges nur fürs Debugging gebraucht wird, frag also zuerst: if log.isEnabledFor(logging.DEBUG):.

In eine Datei schreiben

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

Mit filename landen die Meldungen in einer Datei statt auf dem Bildschirm — und keine einzige Zeile des Codes ändert sich. Hier liegen print und logging am weitesten auseinander: Die Module entscheiden, was geschrieben wird, und main entscheidet, wohin es geht.

In der Praxis gehört außerdem die Uhrzeit ins format:

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

Das setzt Datum und Uhrzeit an den Anfang jeder Zeile. Die Beispiele in diesem Kapitel lassen es weg, weil die Ausgabe sich sonst bei jedem Lauf ändern würde — und was ein Kurs ausgibt, soll dem entsprechen, was dein Rechner ausgibt.

Hineinschauen — breakpoint()

Ein Log sagt was passiert ist. Manchmal braucht man aber den Zustand genau jetzt.

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


print(discount(100.0, 0.1))

Sobald breakpoint() erreicht wird, hält das Programm an und zeigt eine Eingabeaufforderung. Eine Sitzung sieht so aus — in der ersten Zeile steht der vollständige Pfad deiner eigenen Datei:

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

Eine Handvoll Befehle reicht für den größten Teil der Arbeit:

• p <name> — gibt einen Wert aus (pp gibt ihn schön formatiert aus)
• n — die nächste Zeile, ohne in eine Funktion hineinzugehen
• s — in die Funktion hineinspringen
• c — weiterlaufen, bis zum nächsten Halt
• l — den umgebenden Code anzeigen
• q — beenden

Der Vorteil gegenüber print ist, dass du nicht im Voraus festlegen musst, was du sehen willst. Einmal angehalten, lässt sich jeder Name ausgeben und jeder Ausdruck ausführen.

Ein vollständiges Beispiel

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

Einfach als python main.py ausgeführt — die ausgegebenen Zeilen:

pen        51.75
ink       276.00

Und im 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

Jetzt mit SHOP_DEBUG=1 ausgeführt, derselbe 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

Fünf Dinge, die einen Blick wert sind.

Ein Programm, zwei Detailstufen der Ausgabe, und kein Code wurde geändert. Das ist dieses Kapitel im Kleinen. Mit print gelöst, würde der Kreislauf aus Zeilen einfügen und wieder löschen nie aufhören.

bag,eight,1 und clip,5.0,0 wurden aus zwei verschiedenen Gründen übersprungen, und ein einziges except ValueError hat beide abgefangen. float("eight") löst einen ValueError aus, und line_total löst selbst einen für quantity=0 aus. Das Muster aus Kapitel 24 in Aktion: Die untere Funktion löst aus, die obere fängt ab und entscheidet, was zu tun ist.

Das Debug-Log zeigt, was das normale Log nicht zeigen kann. Bei der clip-Zeile wurde line_total tatsächlich aufgerufen — die DEBUG ... quantity=0-Zeile beweist es — und danach warf es einen Fehler. Die bag-Zeile hat keine DEBUG-Zeile, weil float("eight") vorher kaputtging. Beide Zeilen sind „übersprungen“, aber sie sind an verschiedenen Stellen kaputtgegangen, was nur das Level debug sichtbar macht.

Das Level kommt aus der Umgebung, nicht aus dem Code. Bei einem Programm, das auf einem Server läuft, ist das der übliche Weg — eine Variable ändern und neu starten, statt eine Datei zu bearbeiten und neu auszuliefern.

pricing.py ruft basicConfig nirgends auf. Es schreibt nur getLogger(__name__) und sendet Meldungen. Wohin sie gehen und wie viele, entscheidet allein main. Deshalb übernimmt es beim Testen von pricing oder bei der Nutzung in einem anderen Programm niemandes Logging.

Wenn es schiefgeht

Im Log erscheint nichts basicConfig wurde nicht aufgerufen, oder das Level ist zu hoch. Das Standard-Level ist WARNING, also ist log.info standardmäßig unsichtbar.

Ich habe basicConfig aufgerufen, und nichts hat sich geändert Es wirkt nur einmal — wenn das Logging irgendwo schon gestartet wurde, wird ein späterer Aufruf stillschweigend ignoriert. Ruf es einmal ganz am Anfang auf, oder übergib force=True.

Das Level oder Format von main hat keine Wirkung, und es gibt keinen Fehler Eine importierte Bibliothek hat selbst basicConfig aufgerufen, und das lief vor dem Aufruf in main. Deshalb wird das basicConfig von main stillschweigend ignoriert. Entferne basicConfig aus der Bibliothek — eine Bibliothek verwendet nur getLogger(__name__).

Das Log landet nicht in der Datei Das Logging war schon gestartet, bevor filename angegeben wurde. Wieder die Regel mit dem „einmal“.

Ich habe log.exception benutzt, und es gibt keinen Traceback Einen Traceback gibt es nur innerhalb eines except-Blocks. Außerhalb davon nimm log.error.

Ich habe python main.py > out.txt ausgeführt, und das Log steht nicht in der Datei logging schreibt nach stderr. Benutze 2> log.txt oder filename.

Der Traceback ist lang und besteht nur aus Bibliotheksdateien Von unten nach oben lesen und den untersten Frame finden, der dein eigener Code ist. Das Problem steckt fast immer dort.

breakpoint() tut nichts PYTHONBREAKPOINT=0 ist gesetzt. Entferne es.

Jetzt bist du dran

Nimm die library.py, die du in Kapitel 28 getestet hast, und ersetze jedes print durch logging.

• log = logging.getLogger(__name__) oben im Modul
• Eine debug-Meldung in add() mit dem Titel des Buchs
• Eine warning-Meldung, wenn fehlerhafte Daten übersprungen werden
• Eine main.py, die basicConfig aufruft und das Level aus einer Umgebungsvariablen liest
• Kein basicConfig in library.py

Dann sechs Experimente:

• Führ es zuerst mit dem Level INFO, dann mit DEBUG aus. Musste irgendein Code geändert werden?
• Füg filename="run.log" zu basicConfig hinzu. Was bleibt auf dem Bildschirm?
• Ruf auch in library.py basicConfig auf, mit einem anderen Level als in main.py. Wessen Level wird jetzt benutzt — und warum?
• Provozier absichtlich einen KeyError, und schreib dann im except-Block einmal log.error(err) und einmal log.exception("..."). Welches ist nützlicher, und warum?
• Schreib log.debug("%s", expensive()), wobei expensive() etwas ausgibt, und lass das Level auf WARNING. Läuft expensive()?
• Setz ein breakpoint() ein und erkunde mit p, n und c.

Das vierte Experiment ist das letzte Wort dieses Kapitels. Wie es einem Programm geht, erkennt man an dem, was es zurücklässt — und ein except-Block, der nichts zurücklässt, hat die Frage nur aufgeschoben.

Wie es weitergeht

Damit endet der Python-Kurs. Nach 29 Kapiteln kannst du ein Programm schreiben, mit Fehlern umgehen, es testen und sehen, was es tut — und die letzten drei sind das, was ein Programm über seinen ersten Tag hinaus am Leben hält.

Der nächste Schritt ist nicht mehr, die Sprache zu lernen, sondern etwas mit ihr zu machen. Genau dort beginnt der pandas-Kurs: mit den CSV-Dateien aus Kapitel 25, aber mit Tausenden von Zeilen und Fragen, auf die eine Schleife nicht mehr sinnvoll antworten kann.