PCPP1 Block 5 (Teil 2a): logging

Track Python · PCPP1 Block 5, Ziel 5.4 · ca. 50 Min.

Worum es geht

Block 5 “Dateiverarbeitung und Umgebung” (file processing and communicating with the program environment) hat laut Quelle 15 % der PCPP1-Prüfung, das sind 7 Fragen (Stand der Quelle: 1. Oktober 2026, bitte vor der Buchung prüfen). Lektion 17 hat sqlite3, csv und xml.etree.ElementTree behandelt. Der Rest von Block 5 ist auf zwei Lektionen verteilt. Diese hier (Teil 2a) behandelt logging (Protokollierung, Ziel 5.4). Teil 2b folgt mit configparser, os, datetime, time und io.

Praxisbezug für dich als Freelancer: Jeder Dienst im Betrieb braucht Logs, sonst bist du bei einem Fehler beim Kunden blind. Wer logging sauber aufsetzt, spart sich später stundenlanges Raten.

Nicht in dieser Lektion: Dateihandler wie RotatingFileHandler im Detail (nur der Name kommt vor). Alles hier läuft im Browser: Logs gehen in einen io.StringIO-Puffer oder eine Liste statt in eine Datei.

Von JS/TS her gedacht

Thema JS/TS Python
Logging console.log, oder Bibliotheken wie pino und winston logging aus der Standardbibliothek, Level, Handler und Formatter
Level debug, info, warn, error DEBUG (10), INFO (20), WARNING (30), ERROR (40), CRITICAL (50)
Logger pro Modul pino().child({ module: "db" }) logging.getLogger("app.db"), Hierarchie über Punkte

Konzept in kleinen Schritten

Schritt 1: Level und die Standardeinstellung (Ziel 5.4)

Die Level steigen auf: DEBUG (10), INFO (20), WARNING (30), ERROR (40), CRITICAL (50). NOTSET (0) bedeutet: “erbt vom Elternlogger” (parent logger). Der Standard-Level des Root-Loggers ist WARNING. Ohne Konfiguration erscheinen debug und info also nicht.

logging.basicConfig(...) richtet den Root-Logger mit Level, Format und Ziel ein. Es wirkt nur beim ersten Aufruf, ein zweiter bleibt wirkungslos, außer mit force=True. Hier mit stream= auf einen Puffer statt filename= (im Browser gibt es keine Datei):

Ausgabe (mit Python 3.13 ausgeführt): 'INFO:i\n'. Das zweite basicConfig mit DEBUG und anderem Format hat nichts verändert. Mit force=True hätte es die erste Konfiguration ersetzt.

Das Aufräumen am Ende ist kein Schmuck: Der Root-Logger ist globaler Zustand (global state) für das ganze Programm. In diesen Übungen räumen wir immer auf, damit sich Läufe nicht gegenseitig beeinflussen. Dasselbe Problem hast du in Tests, die Logger konfigurieren.

Schritt 2: Logger, Handler, Formatter und die zwei Level-Prüfungen

Für größere Programme nimmst du benannte Logger mit eigenen Handlern. Die Bausteine:

Baustein Aufgabe
Logger nimmt Meldungen entgegen und prüft den Level. Name über logging.getLogger(name)
Handler schickt Meldungen an ein Ziel: StreamHandler, FileHandler, RotatingFileHandler, NullHandler, SMTPHandler, HTTPHandler
Formatter legt das Aussehen fest
Filter entscheidet, welche Meldungen durchkommen
LogRecord das Objekt für eine einzelne Meldung mit allen Attributen

Ausgabe:

WARNING demo18.db Logger und Handler
ERROR demo18.db Fehler
Traceback (most recent call last):
ZeroDivisionError: division by zero
10 30 0 10

Merke dir:

  • Zwei Level-Prüfungen: Eine Meldung muss erst den Level des Loggers bestehen und dann den des Handlers. debug("nur Logger") kommt durch den Logger (DEBUG), scheitert aber am Handler (WARNING).
  • Der Name ist eine Hierarchie über Punkte: demo18.db.x ist Kind von demo18.db. Das Kind hat NOTSET (0) und erbt daher den wirksamen Level (getEffectiveLevel()) des Elternloggers: 10.
  • logger.exception(...) schreibt eine ERROR-Meldung mit Traceback und gehört nur in einen except-Block.
  • Das Format aus %(...)s-Platzhaltern kennt unter anderem asctime, name, levelname, levelno, message, filename, module, funcName, lineno, pathname, process, thread und created.

Schritt 3: Weitergabe (propagation), Lazy-Formatierung, eigene Handler

Ein Logger gibt seine Meldungen auch an die Handler seiner Elternlogger weiter. Dabei wird der Level des Elternloggers nicht mehr geprüft, nur noch die Level der Handler dort. Hängt ein Handler am Kind und einer am Elternteil, kommt die Meldung doppelt an:

Ausgabe: erst 'doppelt\ndoppelt\n', dann 'doppelt\ndoppelt\neinfach\n'. Nach propagate = False landet die Meldung nur noch beim Handler des Kindes.

Lazy-Formatierung: logger.info("x=%s", x) statt logger.info(f"x={x}"). Beim f-String wird der Text immer gebaut, auch wenn die Meldung wegen des Levels verworfen wird. Bei %s mit Argumenten baut Python den Text nur, wenn die Meldung wirklich ausgegeben wird:

Ausgabe: Unter lazy: steht nichts, unter f-String: steht __str__ wurde aufgerufen.

Eigene Handler und Formatter erbst du. Ein Handler überschreibt emit(record), ein Formatter format(record):

Ausgabe: ['WARNING ACHTUNG KUNDE'].

Falle: die Prüfungs- und Praxisklassiker

  1. logging.debug und logging.info erscheinen ohne Konfiguration nicht. Der Root-Logger steht auf WARNING.
  2. Zwei Level-Prüfungen. Logger-Level und Handler-Level müssen beide passen. Ein DEBUG-Handler hilft nichts, wenn der Logger auf WARNING steht.
  3. Propagation erzeugt doppelte Ausgaben, wenn Kind und Elternteil beide einen Handler haben. Der Level des Elternloggers wird bei der Weitergabe nicht geprüft, nur die Handler dort.
  4. basicConfig wirkt nur beim ersten Aufruf, außer mit force=True.
  5. Handler bei jedem Aufruf hinzufügen. Wer addHandler in einer Funktion aufruft, die mehrfach läuft, bekommt jede Meldung mehrfach.
  6. f-String im Logging baut den Text auch dann, wenn er verworfen wird. Nimm logger.info("x=%s", x).

Übungen

Übung 1: Logger, Handler und Weitergabe vorhersagen (ca. 8 Min.)

Zwei Logger, ein Handler pro Logger, jeder sammelt die Texte der Meldungen, die bei ihm ankommen (die Klasse ListHandler ist vorgegeben). Welche Meldungen landen in welcher Liste? Trage das Tupel (h_kind.messages, h_eltern.messages) ein, ohne den Code auszuführen.

Gehe Meldung für Meldung durch: Besteht sie den Level des Kind-Loggers? Dann den Level des Handlers am Kind. Wird sie weitergegeben, und wird dort noch der Level des Elternloggers geprüft oder nur der des Handlers? Was ändert propagate = False für die letzte Meldung?

antwort = (["c", "d", "e"], ["b", "c", "d"])
antwort

Der Kind-Logger steht auf DEBUG, alle Meldungen kommen durch. Sein Handler (WARNING) nimmt c, d und e. Weitergegeben wird an den Handler des Elternteils (INFO): Der Level des Elternloggers (ERROR) wird dabei nicht geprüft, nur der Handler-Level. Dort kommen b, c, d an. a ist DEBUG und scheitert an beiden Handlern. e kommt nach propagate = False nur beim Kind an.

Übung 2: Logger einrichten, ohne Handler zu verdoppeln (ca. 10 Min.)

Schreibe richte_logger(name, stream). Sie gibt den Logger mit dem Namen name zurück und stellt ihn so ein:

  • Logger-Level DEBUG, Weitergabe an Elternlogger aus.
  • Genau ein StreamHandler auf stream mit Handler-Level INFO und dem Format %(levelname)s|%(name)s|%(message)s.
  • Die Funktion darf mehrfach für denselben Namen aufgerufen werden. Danach hat der Logger genau einen Handler, nämlich den mit dem zuletzt übergebenen Stream. Es gibt keine doppelten Ausgaben.

Die Prüfung hängt an den Elternlogger einen eigenen Handler, um Weitergabe zu erkennen, und räumt danach alles auf.

Du brauchst vier Einstellungen am Logger und drei am Handler. Was muss vor dem Hinzufügen eines neuen Handlers mit den schon vorhandenen passieren, damit ein zweiter Aufruf nicht doppelt ausgibt? Ein bloßes “nur hinzufügen, wenn keiner da ist” reicht für einen neuen Stream nicht aus. Welche Liste am Logger zeigt die Handler?

import logging

def richte_logger(name, stream):
    logger = logging.getLogger(name)
    logger.setLevel(logging.DEBUG)
    logger.propagate = False
    for h in logger.handlers[:]:
        logger.removeHandler(h)
    handler = logging.StreamHandler(stream)
    handler.setLevel(logging.INFO)
    handler.setFormatter(logging.Formatter("%(levelname)s|%(name)s|%(message)s"))
    logger.addHandler(handler)
    return logger

richte_logger

getLogger(name) gibt für denselben Namen immer dasselbe Objekt zurück. Darum bleiben Handler eines früheren Aufrufs hängen und müssen vor dem Hinzufügen entfernt werden. Über logger.handlers[:] iterierst du über eine Kopie, damit das Entfernen die Schleife nicht stört.

Übung 3: Fehler finden im Import-Logging (ca. 10 Min.)

Die Funktion importiere wandelt Zeilen in Zahlen um. Ungültige Zeilen werden übersprungen und geloggt. Die Vorgabe für das Logging:

  • Jede ungültige Zeile: eine Meldung mit Level WARNING am Logger log, die den Wert enthält.
  • Am Ende eine Zusammenfassung mit Level INFO am Logger log, Text "<ok> von <gesamt> importiert".
  • Alle Meldungen mit Lazy-Formatierung (Format-String plus Argumente), keine f-Strings.
  • Bibliothekscode konfiguriert das Logging nicht und nutzt nur seinen eigenen Logger.

Der Code unten hat drei Fehler. Finde und behebe sie. Die Prüfung hängt einen Handler an log, sammelt alle Meldungen samt Level und Argumenten und schaut, ob der Root-Logger unberührt bleibt.

Prüfe jede der beiden Logging-Zeilen einzeln gegen die Vorgabe: Passt der Level? Wird der Text beim Aufruf schon gebaut oder erst bei Bedarf? Und an welches Objekt geht der Aufruf: an log oder an das Modul logging selbst, also an den Root-Logger? Prüfe außerdem die Vorgabe “konfiguriert das Logging nicht” gegen den Code.

import logging

log = logging.getLogger("lek18.import")

def importiere(zeilen):
    ok = []
    for z in zeilen:
        try:
            ok.append(int(z))
        except ValueError:
            log.warning("ungueltig: %r", z)
    log.info("%d von %d importiert", len(ok), len(zeilen))
    return ok

importiere

Fehler 1: error statt warning, eine übersprungene Zeile ist kein Fehler des Programms. Fehler 2: f-Strings bauen den Text immer, "...%r", z nur bei Bedarf. Fehler 3: logging.info(...) geht an den Root-Logger, nicht an log. Außerdem ruft logging.info ohne Konfiguration still basicConfig auf und verändert den globalen Zustand. Bibliothekscode nutzt seinen eigenen Logger und lässt die Konfiguration der Anwendung.

Übung 4: Multiple Choice mit Begründung (ca. 5 Min.)

Ein Dienst startet mit logging.basicConfig(level=logging.INFO). Das Modul shop holt sich logger = logging.getLogger("shop"), hängt einen eigenen StreamHandler() an und schreibt logger.info("bestellt"). In der Konsole steht jede Zeile zweimal. Welche Aussage erklärt das und nennt den passenden Weg zur Lösung?

  • A Der Logger-Level ist zu niedrig. Mit logger.setLevel(logging.ERROR) erscheint jede Zeile danach nur noch einmal.
  • B basicConfig wurde zweimal aufgerufen. Mit dem Argument force=True wird die Einrichtung nur noch einmal angewendet.
  • C Der Handler ist doppelt registriert. addHandler darf deshalb pro Programm höchstens einmal vorkommen.
  • D Die Meldung geht erst an den Handler von shop und wird dann an den Root weitergereicht. Mit logger.propagate = False endet das.

Zähle die Handler: Wo hängt einer, und wo hängt noch einer? Prüfe dann bei jeder Option, ob sie die Ursache beseitigt oder nur Meldungen unterdrückt oder umkonfiguriert.

antwort = "D"
antwort

basicConfig hängt einen Handler an den Root. shop hat einen eigenen. Weil Meldungen standardmäßig an die Elternlogger weitergegeben werden, kommt jede Meldung bei beiden Handlern an. propagate = False am Logger shop schaltet die Weitergabe ab.

Merksatz

Eine Log-Meldung muss zwei Level-Prüfungen bestehen (Logger, dann Handler) und wandert danach zu den Handlern aller Elternlogger (propagation). Doppelte Zeilen kommen fast immer von zwei Handlern in der Kette oder von einem addHandler bei jedem Aufruf.

Prüfstein

Ein Kollege meldet: “Seit dem letzten Release stehen die Logs doppelt in der Datei, und die debug-Zeilen fehlen, obwohl ich den Handler auf DEBUG gestellt habe.” Nenne mindestens drei Ursachen, die du in dieser Reihenfolge prüfst, und für jede, woran du sie erkennst und wie du sie behebst.

Weiter mit Teil 2b: configparser, os, datetime, time, io.

Quelle: quellen/python-glossar-pcap-pcpp1.md, Abschnitt “PCPP1 Block 5: Dateiverarbeitung und Umgebung”, Unterabschnitt 5.4 (Logging) und “Typische Fallen in Block 5”. Die Prüfungsgewichtung (15 %, 7 Fragen) steht dort, vor der Buchung bitte prüfen. Nicht aus der Quelle, sondern allgemeines Python-Wissen (bitte prüfen): dass bei der Weitergabe der Level des Elternloggers nicht mehr geprüft wird, und getEffectiveLevel(). Alle Ausgaben im Text wurden mit Python 3.13 ausgeführt.