Logging statt print

print(...) ist großartig, wenn Du schnell etwas im Terminal sehen möchtest.

print("Bin hier")
print(spieler.hp)
print("Speichern fertig")

Beim Lernen, in der REPL oder für einen schnellen Blick auf einen Wert ist das völlig in Ordnung.

Schwieriger wird es, wenn das Programm länger läuft, von anderen benutzt wird oder Du einen Fehler erst Stunden später untersuchen musst. Ein Cronjob, Bot, Webdienst oder größeres Kommandozeilentool sollte nachvollziehbar hinterlassen, was passiert ist und wie wichtig eine Meldung war.

Dafür gibt es in Python das Standardmodul logging.

In Teil 8 der Python-Serie ging es um Exceptions und Fehlerbehandlung. Logging hilft bei der nächsten Frage:

Was ist eigentlich passiert, bevor der Fehler auftrat?

Warum print(...) irgendwann nicht mehr reicht

Eine Ausgabe wie:

print(f"Spieler: {spieler.name}")

ist direkt und unkompliziert.

Bei einem dauerhaft laufenden Programm fehlen allerdings ein paar Dinge.

Diese vier Meldungen sehen für print(...) gleich aus:

print("Spiel gestartet")
print("Spielstand gespeichert")
print("Spielstand konnte nicht geladen werden")
print("Datenbank nicht erreichbar")

Für uns ist aus dem Text ungefähr erkennbar, wie ernst die Situation ist. Ein Log-Viewer oder Monitoring-System bekommt diese Information aber nicht automatisch.

Logging kennt dafür Levels.

Außerdem kannst Du zentral festlegen:

• welche Meldungen überhaupt ausgegeben werden,
• wie eine Logzeile aussieht,
• ob sie auf der Konsole oder in einer Datei landet,
• welche Module besonders ausführlich loggen,
• ob zu einem Fehler ein Traceback gespeichert wird.

Der eigentliche Programmcode muss dafür nicht überall angepasst werden.

Das erste Log

Für einen schnellen Test reicht:

import logging

logging.warning("Etwas ist seltsam.")
logging.error("Eine Operation ist fehlgeschlagen.")

Ohne eigene Konfiguration sieht die Ausgabe ungefähr so aus:

WARNING:root:Etwas ist seltsam.
ERROR:root:Eine Operation ist fehlgeschlagen.

Die Funktionen:

logging.debug(...)
logging.info(...)
logging.warning(...)
logging.error(...)
logging.critical(...)

verwenden direkt den Root-Logger.

Beim ersten Aufruf einer solchen Modul-Funktion richtet logging automatisch eine einfache Standardkonfiguration ein, falls der Root-Logger noch keine Handler besitzt.

Der Root-Logger steht standardmäßig auf WARNING. Deshalb siehst Du:

logging.warning("Warnung")

aber normalerweise nicht:

logging.info("Spiel gestartet")

Für ein echtes Programm konfigurieren wir Logging deshalb bewusst selbst.

Logging mit basicConfig(...) einrichten

Für ein normales Skript ist logging.basicConfig(...) ein guter Anfang:

import logging

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

logger = logging.getLogger(__name__)

logger.info("Spiel gestartet")

Eine mögliche Ausgabe:

2026-07-29 14:30:00,123 INFO __main__: Spiel gestartet

Im Format stecken mehrere Attribute eines Log-Records:

level=logging.INFO legt für den Root-Logger fest, dass Meldungen ab INFO verarbeitet werden.

Die Konfiguration gehört möglichst an eine zentrale Stelle beim Programmstart.

Die Logging-Levels

Python bringt fünf Levels mit, die Du im Alltag ständig siehst:

Ein Dungeon könnte beispielsweise so loggen:

logger.debug("Raumdaten geladen: %s", raum_id)
logger.info("Spiel gestartet")
logger.warning("Spielstand fehlt, neues Spiel wird begonnen")
logger.error("Spielstand konnte nicht gespeichert werden")
logger.critical("Konfiguration fehlt, Programm kann nicht sinnvoll starten")

Bei:

logging.basicConfig(level=logging.INFO)

werden INFO, WARNING, ERROR und CRITICAL verarbeitet. DEBUG bleibt ausgefiltert.

Mit:

logging.basicConfig(level=logging.WARNING)

verschwinden zusätzlich die INFO-Meldungen.

Ein Level beendet das Programm nicht

logger.critical(...) klingt drastisch, tut aber zunächst nur eines:

einen Log-Record mit dem Level CRITICAL erzeugen

Logging beendet weder das Programm noch löst es automatisch eine Exception aus.

Wenn ein Fehler tatsächlich zum Programmende führen soll, musst Du das selbst entscheiden:

logger.critical("Konfiguration fehlt")
raise SystemExit(1)

Logging dokumentiert den Zustand. Die Programmlogik entscheidet, was danach passiert.

Ein Logger pro Modul

Für kurze Beispiele sind die direkten Funktionen:

logging.info("Spiel gestartet")

praktisch.

In einem richtigen Projekt solltest Du Dir stattdessen angewöhnen:

import logging

logger = logging.getLogger(__name__)

und danach:

logger.info("Spiel gestartet")
logger.warning("Kein Spielstand gefunden")

__name__ enthält den Namen des aktuellen Moduls.

In:

speichern.py

kann der Logger beispielsweise:

speichern

heißen.

Innerhalb eines Packages:

dungeon.speichern

Damit steht später direkt in der Logzeile, aus welchem Bereich des Programms sie stammt.

Noch wichtiger: Logger-Namen bilden eine Hierarchie.

Logger-Hierarchie und Propagation

Ein Logger:

dungeon.speichern

ist ein Kind von:

dungeon

und dieser wiederum ein Nachfahre des Root-Loggers.

Standardmäßig propagiert ein Logger seine Log-Records nach oben. Ein Record aus:

logger = logging.getLogger("dungeon.speichern")
logger.info("Spielstand geschrieben")

kann deshalb von einem Handler des Root-Loggers ausgegeben werden.

Genau darum reicht in vielen Anwendungen eine zentrale Konfiguration des Root-Loggers.

Du musst nicht in jedem Modul einen eigenen Handler einrichten.

Effective Level

Neue Logger besitzen zunächst das Level NOTSET.

Damit sagen sie sinngemäß:

Ermittle mein effektives Level aus meiner Logger-Hierarchie.

Wenn nur der Root-Logger konfiguriert ist:

logging.basicConfig(level=logging.INFO)

erben Modul-Logger effektiv dieses INFO-Level.

Für einen bestimmten Bereich kannst Du aber mehr Details erlauben:

logging.getLogger("dungeon.speichern").setLevel(logging.DEBUG)

Jetzt können DEBUG-Records dieses Loggers erzeugt werden, obwohl andere Module weiter effektiv auf INFO stehen.

Logger-Level und Handler-Level sind zwei verschiedene Filter

Hier steckt eine häufige Überraschung.

Ein Logger entscheidet zunächst, ob ein Record überhaupt erzeugt und weitergereicht wird.

Ein Handler kann danach noch einmal anhand seines eigenen Levels entscheiden, ob er diesen Record tatsächlich ausgibt.

Zum Beispiel:

handler = logging.StreamHandler()
handler.setLevel(logging.WARNING)

Dieser Handler ignoriert DEBUG und INFO, selbst wenn der Logger diese Records akzeptiert.

Andersherum wichtig: Wird ein Record von einem Child-Logger akzeptiert und nach oben propagiert, werden die Levels der übergeordneten Logger nicht noch einmal wie ein zweiter Filter angewendet. Die Handler der übergeordneten Logger entscheiden dann anhand ihrer eigenen Einstellungen.

Für einfache Programme musst Du diese Feinheit kaum anfassen. Sobald eine Logging-Konfiguration aber mehrere Logger und Handler besitzt, erklärt sie viele scheinbar merkwürdige Ergebnisse.

Handler bestimmen das Ziel

Ein Logger erzeugt Log-Records. Ein Handler entscheidet, wohin sie gehen.

Die Standardbibliothek enthält unter anderem:

basicConfig() ohne filename erzeugt normalerweise einen StreamHandler.

Eine kleine, aber manchmal wichtige Besonderheit:

Logging schreibt standardmäßig auf stderr, nicht auf stdout.

Das ist bei Shell-Skripten praktisch, weil normale Programmausgabe und Diagnoseausgabe getrennt umgeleitet werden können.

Nachrichten richtig formatieren

Bei print(...) verwenden wir gerne einen f-String:

print(f"Spielstand für {spieler.name} gespeichert")

Beim Logging ist diese Form üblich:

logger.info(
    "Spielstand für %s gespeichert",
    spieler.name,
)

Logging bekommt dabei zwei Dinge:

Formatstring
Argumente

und setzt die eigentliche Nachricht erst dann zusammen, wenn sie wirklich benötigt wird.

Bei DEBUG-Meldungen, die im normalen Betrieb oft deaktiviert sind, spart das unnötige Formatierungsarbeit.

Weniger günstig:

logger.debug(f"Raumdaten: {raeume}")

Besser:

logger.debug("Raumdaten: %s", raeume)

Lazy Formatting spart nicht jede Arbeit

Die verzögerte Formatierung betrifft nur das Zusammenbauen der Nachricht.

Dieser Funktionsaufruf passiert trotzdem sofort:

logger.debug(
    "Analyse: %s",
    berechne_teure_analyse(),
)

Auch wenn DEBUG ausgeschaltet ist, muss Python zunächst berechne_teure_analyse() ausführen, um das Argument an logger.debug() zu übergeben.

Wenn die Berechnung tatsächlich teuer ist, kannst Du vorher prüfen:

if logger.isEnabledFor(logging.DEBUG):
    logger.debug(
        "Analyse: %s",
        berechne_teure_analyse(),
    )

Für normale Variablen ist das unnötig. Relevant wird es erst bei wirklich aufwendigen Argumenten.

Mehrere Werte im Log

Bei Diagnosemeldungen sind konkrete Werte meistens hilfreicher als allgemeine Texte:

logger.info(
    "Spielstand gespeichert: spieler=%s ort=%s",
    spieler.name,
    ort,
)

Ausgabe:

2026-07-29 14:30:00,123 INFO __main__: Spielstand gespeichert: spieler=Karl ort=halle

Für Debugging kann dieselbe Schreibweise noch detaillierter sein:

logger.debug(
    "Befehl verarbeitet: verb=%s argument=%s ort=%s",
    verb,
    argument,
    ort,
)

Das ist noch kein strukturiertes Logging im engeren Sinn. Die Nachricht bleibt ein String.

Die Form:

spieler=Karl ort=halle

ist aber konsistent, gut durchsuchbar und später leichter maschinell weiterzuverarbeiten als ständig wechselnde Prosa.

Zusätzlichen Kontext mit extra anhängen

Ein LogRecord besitzt viele Attribute wie:

name
levelname
filename
lineno
message

Eigene Attribute kannst Du über extra ergänzen:

logger.info(
    "Spielstand gespeichert",
    extra={
        "spieler": spieler.name,
        "ort": ort,
    },
)

Ein Formatter kann darauf zugreifen:

format_string = (
    "%(asctime)s %(levelname)s %(name)s "
    "spieler=%(spieler)s ort=%(ort)s: %(message)s"
)

Das ist nützlich, wenn Kontext nicht nur Teil eines freien Textes sein soll.

Dabei gibt es allerdings einen Haken: Erwartet Dein Formatter:

%(spieler)s

muss dieses Attribut für jeden Record vorhanden sein, der durch diesen Formatter läuft. Sonst entsteht beim Formatieren selbst ein Fehler.

Für größere Anwendungen gibt es deshalb weitere Möglichkeiten wie LoggerAdapter, Filter oder eigene Formatter. Für den Einstieg ist die klassische Nachricht mit %s meist unkomplizierter.

Exceptions mit Traceback loggen

Im except-Block willst Du bei einem technischen Fehler häufig nicht nur die Meldung, sondern den vollständigen Traceback behalten.

Dafür gibt es:

logger.exception(...)

Beispiel:

try:
    lade_spielstand()
except SpielstandError:
    logger.exception(
        "Spielstand konnte nicht geladen werden"
    )
    print("Der Spielstand konnte nicht geladen werden.")

logger.exception() verwendet standardmäßig das Level ERROR und hängt die aktuelle Exception samt Traceback an.

Es entspricht im Wesentlichen:

logger.error(
    "Spielstand konnte nicht geladen werden",
    exc_info=True,
)

logger.exception() ist für einen aktiven Exception-Kontext gedacht und gehört deshalb normalerweise in einen except-Block.

Wenn Du einen Traceback mit einem anderen Level benötigst, kannst Du exc_info=True auch dort verwenden:

try:
    lade_optionale_datei()
except OSError:
    logger.warning(
        "Optionale Datei konnte nicht gelesen werden",
        exc_info=True,
    )

Nicht jeder Fehler braucht einen Traceback

Ein Benutzer gibt ein:

nimm drachenei

aber im Raum liegt kein Drachenei.

Das ist kein technischer Programmfehler.

Dafür genügt vielleicht:

logger.info(
    "Gegenstand nicht gefunden: %s",
    argument,
)
print(f"Hier liegt kein Gegenstand namens {argument}.")

Ein voller Traceback wäre nur Lärm.

Anders sieht es aus, wenn beim Speichern unerwartet ein I/O-Fehler auftritt:

try:
    speichere_spielstand(...)
except OSError:
    logger.exception(
        "Schreiben des Spielstands fehlgeschlagen"
    )
    raise

Die Wahl des Levels sollte also von der Bedeutung der Situation abhängen, nicht davon, ob irgendwo ein except steht.

Benutzeroberfläche und Logging sind zwei Dinge

Diese Ausgabe:

print("Spielstand gespeichert.")

richtet sich an den Benutzer.

Diese Meldung:

logger.info(
    "Spielstand gespeichert: spieler=%s ort=%s",
    spieler.name,
    ort,
)

richtet sich an Entwickler, Betreiber oder die spätere Fehlersuche.

Beides darf im selben Programm vorkommen.

Eine verständliche Benutzeroberfläche sollte nicht aus internen Logmeldungen bestehen. Genauso wenig sollte ein freundlicher Text wie:

Leider ist etwas schiefgegangen.

die einzige Information sein, die nach einem technischen Fehler übrig bleibt.

In eine Datei loggen

Für ein kleines Skript kann basicConfig() direkt einen FileHandler erzeugen:

import logging

logging.basicConfig(
    filename="dungeon.log",
    encoding="utf-8",
    level=logging.INFO,
    format="%(asctime)s %(levelname)s %(name)s: %(message)s",
)

Alle entsprechenden Meldungen landen jetzt in:

dungeon.log

Standardmäßig wird die Datei im Append-Modus geöffnet. Neue Logs werden also angehängt.

Wenn Du sie bei jedem Start überschreiben möchtest:

logging.basicConfig(
    filename="dungeon.log",
    filemode="w",
    encoding="utf-8",
    level=logging.INFO,
)

Für ein dauerhaft laufendes Programm sollte eine Logdatei allerdings nicht beliebig wachsen.

Gleichzeitig Konsole und Datei

Sollen Logs an mehrere Ziele gehen, kannst Du mehrere Handler konfigurieren:

import logging

logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)s %(levelname)s %(name)s: %(message)s",
    handlers=[
        logging.StreamHandler(),
        logging.FileHandler(
            "dungeon.log",
            encoding="utf-8",
        ),
    ],
)

Ein einzelner Log-Record kann damit von beiden Handlern verarbeitet werden.

Das ist einer der großen Unterschiede zu print(...): Die Stelle im Anwendungscode weiß nicht mehr, wohin eine Meldung letztlich geschrieben wird.

Sie sagt nur:

logger.info(...)

Die Logging-Konfiguration entscheidet über das Ziel.

Rotierende Logdateien

Ein Dienst, der monatelang läuft, sollte nicht endlos dieselbe Datei vergrößern.

Dafür gibt es beispielsweise RotatingFileHandler:

import logging
from logging.handlers import RotatingFileHandler

handler = RotatingFileHandler(
    "dungeon.log",
    maxBytes=1_000_000,
    backupCount=3,
    encoding="utf-8",
)

logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)s %(levelname)s %(name)s: %(message)s",
    handlers=[handler],
)

Sobald die aktuelle Datei ungefähr die konfigurierte Größe überschreitet, rotiert der Handler sie. backupCount=3 begrenzt die Zahl der aufgehobenen Backups.

Alternativ gibt es:

TimedRotatingFileHandler

für zeitbasierte Rotation.

In Umgebungen wie systemd oder Containern ist es häufig sinnvoller, auf stdout beziehungsweise stderr zu loggen und Rotation sowie Speicherung dem umgebenden System zu überlassen.

Vorsicht mit mehreren Prozessen

Das Logging-Modul ist für mehrere Threads innerhalb eines Prozesses threadsicher.

Das bedeutet aber nicht, dass mehrere Prozesse problemlos gleichzeitig mit eigenen FileHandler-Instanzen in dieselbe Datei schreiben sollten.

Die Standard-File-Handler besitzen keine prozessübergreifende Sperre. Bei mehreren Worker-Prozessen können deshalb konkurrierende Schreibzugriffe und insbesondere Logrotation problematisch werden.

Ein übliches Muster ist dann:

Worker-Prozesse
      ↓
 QueueHandler
      ↓
    Queue
      ↓
 QueueListener
      ↓
 FileHandler

Nur eine Stelle schreibt tatsächlich in die Datei.

Für unseren Dungeon brauchen wir das nicht. Bei Webservern, Multiprocessing-Workern und ähnlichen Anwendungen ist der Unterschied dagegen wichtig.

QueueHandler bei langsamen Zielen

Auch innerhalb eines einzelnen Prozesses kann ein Handler blockieren.

Ein File- oder Netzwerk-Handler erledigt seine I/O-Arbeit normalerweise im Thread, der gerade loggt.

In einem zeitkritischen Thread oder einem Async-Programm kann das störend sein.

Das Standardmodul bietet dafür:

QueueHandler
QueueListener

Der eigentliche Anwendungscode legt den Log-Record nur in eine Queue. Ein separater Listener verarbeitet ihn anschließend mit den langsameren Handlern.

Das ist bereits fortgeschrittenes Logging. Gut zu wissen ist vor allem: logger.info(...) ist nicht automatisch eine kostenlose, asynchrone Operation.

Datum und Uhrzeit formatieren

%(asctime)s fügt einen Zeitstempel ein.

Mit datefmt kannst Du dessen Darstellung ändern:

logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)s %(levelname)s %(name)s: %(message)s",
    datefmt="%Y-%m-%d %H:%M:%S",
)

Ausgabe:

2026-07-29 14:30:00 INFO __main__: Spiel gestartet

Ohne eigenes datefmt verwendet der Standard-Formatter normalerweise auch Millisekunden.

Der Zeitstempel basiert standardmäßig auf der lokalen Zeit des laufenden Systems. Bei verteilten Diensten wird deshalb häufig bewusst eine einheitliche Zeitzone wie UTC gewählt.

basicConfig(...) wirkt nicht beliebig oft

logging.basicConfig(...) konfiguriert den Root-Logger nur, wenn dort noch keine Handler eingerichtet sind.

Darum funktioniert diese Erwartung nicht:

logging.basicConfig(level=logging.WARNING)
logging.basicConfig(level=logging.DEBUG)

logging.debug("Diese Meldung erscheint nicht.")

Der zweite Aufruf ändert die bestehende Konfiguration normalerweise nicht.

Seit Python 3.8 kannst Du sie mit force=True bewusst ersetzen:

logging.basicConfig(
    level=logging.DEBUG,
    force=True,
)

Vorhandene Handler des Root-Loggers werden dabei entfernt und geschlossen, bevor die neue Konfiguration eingerichtet wird.

Eine Modul-Funktion kann basicConfig() unbemerkt vorwegnehmen

Noch tückischer ist:

import logging

logging.info("Programm startet")

logging.basicConfig(level=logging.DEBUG)

logging.debug("Debug-Information")

Der erste Aufruf von:

logging.info(...)

stellt fest, dass der Root-Logger noch keinen Handler besitzt und ruft automatisch basicConfig() auf.

Dadurch existiert anschließend bereits eine Logging-Konfiguration.

Der explizite spätere Aufruf:

logging.basicConfig(level=logging.DEBUG)

tut deshalb nichts mehr.

Die erste INFO-Meldung war wegen des Default-Levels WARNING trotzdem nicht sichtbar.

Genau solche Effekte sind ein guter Grund, Logging möglichst früh und zentral zu konfigurieren und im übrigen Code mit Modul-Loggern zu arbeiten.

force=True ist nützlich, wenn Du den gesamten Prozess selbst kontrollierst, etwa in einem kleinen Skript oder Test. In einer eingebetteten Anwendung oder einem Framework solltest Du damit nicht unbedacht fremde Handler entfernen.

Bibliotheken konfigurieren Logging nicht selbst

Eine wiederverwendbare Bibliothek sollte ihre Logs erzeugen, aber nicht entscheiden, wohin sie gehen.

In einem Modul genügt:

import logging

logger = logging.getLogger(__name__)


def speichern(name):
    logger.info(
        "Speichere Spielstand für %s",
        name,
    )

Die Bibliothek sollte normalerweise kein:

logging.basicConfig(...)

aufrufen und auch nicht eigenmächtig File- oder Stream-Handler installieren.

Die Anwendung weiß schließlich, ob sie Logs:

ins Terminal
in eine Datei
an journald
an einen Logserver
oder gar nicht

schicken möchte.

NullHandler für Bibliotheken

Wenn eine Bibliothek auch ohne konfigurierte Anwendung garantiert still bleiben soll, kann ihr Top-Level-Logger einen NullHandler bekommen:

import logging

logging.getLogger("meine_bibliothek").addHandler(
    logging.NullHandler()
)

Der Handler tut absichtlich nichts.

Das verhindert unter anderem, dass Meldungen ab WARNING mangels anderer Handler beim sogenannten lastResort-Handler auf stderr landen.

Andere echte Handler gehören trotzdem in die Anwendung, nicht in die Library.

Logging im Dungeon

Wir ergänzen unseren Dungeon nun um eine einfache zentrale Konfiguration.

Am Anfang des Programms:

import logging
from pathlib import Path

LOGDATEI = Path("dungeon.log")

logger = logging.getLogger(__name__)

Dann:

def konfiguriere_logging():
    logging.basicConfig(
        level=logging.INFO,
        format="%(asctime)s %(levelname)s %(name)s: %(message)s",
        handlers=[
            logging.StreamHandler(),
            logging.FileHandler(
                LOGDATEI,
                encoding="utf-8",
            ),
        ],
    )

Die Funktion wird einmal beim Start aufgerufen:

def main():
    konfiguriere_logging()

    logger.info("Dungeon gestartet")

    ...

Beim regulären Beenden:

if verb == "ende":
    logger.info(
        "Dungeon beendet: spieler=%s ort=%s",
        spieler.name,
        ort,
    )
    print("Du verlässt das Verlies. Bis zum nächsten Mal.")
    break

Beim Speichern:

if verb == "speichern":
    speichere_spielstand(
        spieler=spieler,
        ort=ort,
        raeume=raeume,
        besuchte_raeume=besuchte_raeume,
    )

    logger.info(
        "Spielstand gespeichert: spieler=%s ort=%s",
        spieler.name,
        ort,
    )

    print("Spielstand gespeichert.")
    continue

Beim Laden:

if verb == "laden":
    (
        spieler,
        ort,
        raeume,
        besuchte_raeume,
    ) = lade_spielstand()
    raum_anzeigen = True

    logger.info(
        "Spielstand geladen: spieler=%s ort=%s",
        spieler.name,
        ort,
    )

    print("Spielstand geladen.")
    continue

Erwartbare Fehler behandeln wir ohne Traceback:

try:
    ...
except DungeonError as fehler:
    logger.warning(
        "Aktion abgelehnt: %s",
        fehler,
    )
    print(fehler)

Echte Bugs fangen wir im Game-Loop dagegen nicht mit einem pauschalen:

except Exception:

ab.

Wenn der Code an einer unerwarteten Stelle kaputtgeht, soll der Fehler während der Entwicklung weiterhin sichtbar sein.

Logging in der Speicherfunktion

Gerade I/O-Code profitiert von zusätzlichen Debug-Meldungen:

def speichere_spielstand(
    spieler,
    ort,
    raeume,
    besuchte_raeume,
):
    logger.debug(
        "Erstelle Spielstand: spieler=%s ort=%s inventar=%s",
        spieler.name,
        ort,
        len(spieler.inventar),
    )

    daten = erstelle_spielstand(
        spieler=spieler,
        ort=ort,
        raeume=raeume,
        besuchte_raeume=besuchte_raeume,
    )

    try:
        with SPEICHERDATEI.open("w", encoding="utf-8") as datei:
            json.dump(
                daten,
                datei,
                ensure_ascii=False,
                indent=2,
            )
            datei.write("\n")
    except OSError as fehler:
        logger.exception(
            "Schreiben des Spielstands fehlgeschlagen"
        )
        raise SpielstandError(
            f"Der Spielstand konnte nicht gespeichert werden: {fehler}"
        ) from fehler

Im normalen Betrieb mit INFO sehen wir die DEBUG-Meldung nicht.

Für die Fehlersuche können wir das Logging auf DEBUG stellen, indem wir in konfiguriere_logging() level=logging.DEBUG setzen.

Sobald der Dungeon in Module aufgeteilt ist, geht das auch gezielt nur für den betreffenden Logger, etwa dungeon.speichern:

logging.getLogger("dungeon.speichern").setLevel(
    logging.DEBUG
)

So bleibt detaillierter Diagnosecode im Programm, ohne den normalen Betrieb mit tausenden Meldungen zu überfluten.

stack_info und stacklevel

Neben Exception-Tracebacks besitzt Logging zwei Optionen, die gelegentlich hilfreich sind.

stack_info=True

Damit kannst Du den aktuellen Aufrufpfad protokollieren, obwohl überhaupt keine Exception existiert:

logger.debug(
    "Aktueller Pfad durch das Programm",
    stack_info=True,
)

Das ist etwas anderes als exc_info=True.

exc_info beschreibt den Stack einer Exception.

stack_info zeigt, wie die aktuelle Logging-Stelle erreicht wurde.

Im normalen Anwendungscode brauchst Du das selten.

stacklevel

Wenn Du eine eigene Logging-Hilfsfunktion schreibst:

def logge_warnung(nachricht):
    logger.warning(
        nachricht,
        stacklevel=2,
    )

soll die Logzeile häufig nicht auf:

logge_warnung()

als Quelle zeigen, sondern auf deren Aufrufer.

stacklevel=2 überspringt dafür einen zusätzlichen Stack Frame.

Das ist besonders praktisch für kleine Wrapper um die Logging-API.

Größere Konfigurationen mit dictConfig

Sobald eine Anwendung mehrere Logger, Handler und Formatter besitzt, wird ein riesiger basicConfig()-Aufruf unübersichtlich.

Das Standardmodul enthält dafür:

import logging.config

logging.config.dictConfig(...)

Die komplette Konfiguration kann damit als Dictionary beschrieben werden.

Ein stark vereinfachtes Beispiel:

import logging.config

LOGGING = {
    "version": 1,
    "formatters": {
        "standard": {
            "format": (
                "%(asctime)s %(levelname)s "
                "%(name)s: %(message)s"
            ),
        },
    },
    "handlers": {
        "console": {
            "class": "logging.StreamHandler",
            "formatter": "standard",
        },
    },
    "root": {
        "level": "INFO",
        "handlers": ["console"],
    },
}

logging.config.dictConfig(LOGGING)

Für den Lern-Dungeon ist das unnötig viel Konfiguration.

Bei größeren Anwendungen lässt sich damit aber sauber trennen:

Anwendungscode
Logging-Konfiguration

und dieselbe Konfiguration kann mehrere Logger und Ziele koordinieren.

Welches Level nehme ich?

Es gibt keine mathematisch exakte Regel dafür, wann etwas INFO oder WARNING sein muss.

Ein brauchbarer Maßstab ist die Frage, wofür eine Meldung später nützlich sein soll.

DEBUG

Details für Entwickler:

logger.debug(
    "Befehl zerlegt: verb=%s argument=%s",
    verb,
    argument,
)

Oder:

logger.debug("Geladene Rohdaten: %r", daten)

Davon darf es viele geben, weil sie im normalen Betrieb üblicherweise deaktiviert sind.

INFO

Normale relevante Ereignisse:

logger.info("Dungeon gestartet")
logger.info("Spielstand gespeichert")
logger.info("Spielstand geladen")

Damit lässt sich später grob nachvollziehen, was das Programm regulär getan hat.

WARNING

Etwas ist ungewöhnlich, aber die Anwendung kann sinnvoll weiterarbeiten:

logger.warning(
    "Kein Spielstand gefunden, neues Spiel wird begonnen"
)

Ein unbekannter Spielerbefehl muss dagegen nicht automatisch eine Warnung sein. Wenn solche Eingaben normal zu erwarten sind, reicht eventuell INFO oder gar kein Log.

ERROR

Eine konkrete Operation ist fehlgeschlagen:

logger.error(
    "Spielstand konnte nicht gespeichert werden"
)

Mit Traceback im Exception-Handler:

logger.exception(
    "Spielstand konnte nicht gespeichert werden"
)

CRITICAL

Der Prozess befindet sich in einem Zustand, in dem er wahrscheinlich nicht sinnvoll weiterarbeiten kann:

logger.critical(
    "Zwingende Konfiguration fehlt"
)

Das Level selbst stoppt das Programm trotzdem nicht.

Keine Geheimnisse ins Log schreiben

Logs leben oft deutlich länger als erwartet.

Sie landen möglicherweise:

in Backups
auf zentralen Logservern
in Tickets
in Fehlerberichten
in CI-Artefakten

Darum gehören Passwörter, API-Tokens, Session-Cookies und andere Credentials nicht hinein.

Problematisch können auch komplette Request-Daten, personenbezogene Informationen oder private Inhalte sein.

Dieses Debug-Log ist beispielsweise keine gute Idee:

logger.debug(
    "Login: benutzer=%s passwort=%s",
    benutzername,
    passwort,
)

Dass ein Log nur auf DEBUG steht, macht sensible Daten nicht sicher.

Häufige Stolperfallen

• Logging nur als kompliziertes print(...) verwenden: Der eigentliche Nutzen steckt in Levels, Loggern, Handlern, zentraler Konfiguration und zusätzlichem Kontext.

• In jedem Modul basicConfig() aufrufen: Die Anwendung sollte Logging zentral konfigurieren.

• Vor der Konfiguration Modul-Funktionen wie logging.info() aufrufen: Sie können automatisch basicConfig() auslösen und damit eine spätere Konfiguration scheinbar wirkungslos machen.

• In einer Library Handler installieren: Wiederverwendbarer Code erzeugt Logs, die Anwendung entscheidet über ihre Ausgabe. NullHandler ist die übliche Ausnahme.

• Nur den Root-Logger verwenden: Für mehr als kleine Skripte ist logging.getLogger(__name__) die bessere Gewohnheit.

• Logger-Level und Handler-Level verwechseln: Beide können Records filtern, tun das aber an unterschiedlichen Stellen.

• Propagation ignorieren: Ein Child-Logger reicht Records normalerweise an die Handler seiner Vorfahren weiter. Zusätzliche Handler auf mehreren Ebenen können dadurch doppelte Ausgaben verursachen.

• f-Strings für deaktivierte Debug-Meldungen bauen: logger.debug(f"{wert}") formatiert sofort. Übergib Formatstring und Argumente getrennt.

• Von Lazy Formatting erwarten, dass Funktionsargumente nicht ausgewertet werden: Ein teurer Funktionsaufruf findet trotzdem statt. Nutze bei Bedarf logger.isEnabledFor(...).

• logger.exception() außerhalb eines Exception-Handlers verwenden: Die Methode ist für den aktuellen Exception-Kontext gedacht.

• Jede abgefangene Exception mit vollständigem Traceback loggen: Erwartbare Benutzerfehler brauchen meistens keinen.

• CRITICAL mit Programmabbruch verwechseln: Logging entscheidet nicht über den Kontrollfluss.

• StreamHandler automatisch für stdout halten: Ohne angegebenen Stream schreibt er standardmäßig nach stderr.

• logging.warn(...) verwenden: Die alte Methode ist deprecated. Verwende warning(...).

• Mehrere Prozesse in dieselbe Logdatei schreiben lassen: Die eingebauten File-Handler synchronisieren nicht prozessübergreifend.

• Unbegrenzte Logdateien erzeugen: Nutze Rotation oder überlasse die Verwaltung einem externen Logging-System.

• Geheimnisse loggen: Zugangsdaten und sensible Inhalte gehören nicht unbedacht in Logs.

• Logs mit Benutzerkommunikation verwechseln: Diagnosemeldungen ersetzen keine verständliche UI-Ausgabe.

Übungen

1. Logging einrichten

Richte Logging so ein, dass INFO und höhere Levels mit Zeitstempel, Level und Logger-Name ausgegeben werden.

import logging

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

logger = logging.getLogger(__name__)

logger.info("Programm gestartet")

2. Einen Modul-Logger verwenden

Schreibe eine Funktion speichern(name), die eine Logmeldung ausgibt. Die Funktion selbst darf Logging nicht konfigurieren.

import logging

logger = logging.getLogger(__name__)


def speichern(name):
    logger.info(
        "Speichere Spielstand für %s",
        name,
    )

3. Eine Exception mit Traceback loggen

Fange einen ValueError ab und logge den vollständigen Traceback.

import logging

logging.basicConfig(level=logging.INFO)

logger = logging.getLogger(__name__)

try:
    zahl = int("viel")
except ValueError:
    logger.exception(
        "Umwandlung in int fehlgeschlagen"
    )

4. In eine Datei loggen

Konfiguriere Logging so, dass Meldungen ab INFO in app.log geschrieben werden.

import logging

logging.basicConfig(
    filename="app.log",
    encoding="utf-8",
    level=logging.INFO,
    format="%(asctime)s %(levelname)s %(name)s: %(message)s",
)

logger = logging.getLogger(__name__)

logger.info("Datei-Logging aktiv")

5. Eine teure Debug-Ausgabe vermeiden

Die Funktion berechne_status() benötigt viel Rechenzeit. Sorge dafür, dass sie nur ausgeführt wird, wenn DEBUG für den Logger tatsächlich aktiv ist.

import logging

logger = logging.getLogger(__name__)

if logger.isEnabledFor(logging.DEBUG):
    logger.debug(
        "Status: %s",
        berechne_status(),
    )

Weiterlesen

• Python lernen, Teil 8: Wenn's schiefgeht
• Python lernen, Teil 9: Dateien und Speichern
• Debuggen mit pdb
• Python-Dokumentation: Logging HOWTO
• Python-Dokumentation: Logging Cookbook
• Python-Dokumentation: logging
• Python-Dokumentation: logging.handlers