Wie du das Python Modul logging verwendest

Das Loggingmodul gehört zum Standardrepertoire eines Pythonentwicklers.

Zur Fehleranalyse von Software willst du zur Laufzeit manchmal wissen was gerade so passiert. Gerade In größeren Projekten die aus mehreren Modulen bestehen kann das zur Laufzeit sehr unübersichtlich werden.

Eine der gängigsten Lösung ist es, dass du eine Loggingkonsole oder Logdateien bereitstellst um dem Anwender (und vor allem dir selbst!) die Fehleranalyse zu vereinfachen.

Eine Lösung bietet das logging Modul. Damit kannst du Events, die gerade stattfinden auf der Konsole ausgeben oder in eine Datei schreiben. In diesem Tutorial stelle ich dieses Modul vor und zeige dir ein paar Standardanwendungen.

Wann und warum du Logging verwenden solltest

In jedem Fall solltest du Logging Events einsetzen, um aufzuzeigen wie der aktuelle und vergangene Status des Programms ist. Loggingevents kannst du immer dann verwenden, wenn dein Programm etwas tut, bei dem es möglicherweise zu Fehlern kommen könnte.

Das betrifft zum Beispiel…

• den Zugriff auf eine Datenbank
• die Kontaktaufnahme mit einer API
• die Erstellung eines komplexen Objekts
• eine Ausführung eines zeitlichen Auslösers
• eine folgenschwere Benutzereingabe

und so weiter.

Auch wenn etwas nicht direkt zum Fehler führt hat, sondern nur zukünftig zu Fehlern führen kann, kannst du ein Loggingevent in Form einer Warnung erstellen. Beispielsweise wenn das Programm mit einer alten Runtimeversion läuft die zwar funktioniert, aber nicht den vollen Funktionsumfang bietet. Oder, wenn ein Festplattenspeicher kurz davor ist voll zu werden.

Zuletzt kannst du Logging als Alternative zu Kommentaren im Quellcode in Betracht ziehen. Die Dokumentation des Quellcodes gehört nicht in die Logs. Aber komplexe Ausführungsschritte wie “Connecting to Database …” oder “Reading file …” können für eine zukünftige Fehlersuche sinnvoll sein.

Wann du kein Logging verwenden solltest

Es gibt auch Fälle, bei denen die Loggingkonsole nicht das Mittel der Wahl ist. So ist die Loggingnachricht beim Auftreten eines kritischen Fehlers kein Ersatz für eine richtige Exception die das Programm beendet.

Der Enduser sollte für die normale Nutzung des Programms ebenfalls nicht in Berührung mit den Logs kommen. Wenn du einfach nur etwas auf der Kommandozeile ausgeben möchtest, solltest du auf Funktionen wie print() zurückgreifen.

Manche Informationen sollten auf keinen Fall in den Logs landen. Vor allem sensitive Informationen wie Passwörter oder private Schlüssel solltest du nicht in die Lognachrichten schreiben. Benutzernamen sind hingegen meistens in Ordnung da sie bei der Fehlerbehebung helfen können.

Wie funktioniert Logging

Mit dem Logging Modul kannst du auf das Loggingsystem zugreifen. Dabei werden Loggingströme erzeugt auf die du wie beim publish-subscribe Pattern zugreifen kannst. Jeder dieser Ströme hat einen eigenen Namen. Du kannst deine Loggingströme zum Beispiel nach dem Modul benennen, bei dem das zu loggende Event aufgetreten ist.

Darüber hinaus kann jedes Logevent ein Level haben, das den Detailgrad beschreibt. Die verschiedenen Level sind:

Je höher das Level, desto mehr Details beinhalten die Logevents.

Wie du Loggingströme anzeigst

Um die Nachrichten eines Loggers anzuzeigen, musst du den jeweiligen Logger importieren. Beim root Logger werden in der Standardeinstellung nur die Logginglevel WARNING, ERROR und CRITICAL angezeigt.

import logging
logging.debug("Dies wird nicht angezeigt")
logging.warning("Dies wird angezeigt")</code></pre>

WARNING:root:Dies wird angezeigt

Manuelles Logginglevel

Das Verhalten, bei dem nicht alle Logginglevel angezeigt werden, kannst du, umkonfigurieren. Dazu musst du das Logginglevel, also die Hürde bis der Logs angezeigt werden, aus bzw. auf 0 stellst.

import logging
logging.root.setLevel(logging.NOTSET)
logging.debug("Dies wird jetzt angezeigt")
logging.error("Dies wird auch angezeigt")

DEBUG:root:Dies wird jetzt angezeigt
ERROR:root:Dies wird auch angezeigt

Modularer Logger

Das oben beschriebene Vorgehen wird dir auch die Logs anzeigen die von Modulen generiert wurden, die du importiert hast. Falls du allerdings nur die Logs für Teile deines Programms und nicht alle Loggingströme des Root-Loggers anzeigen willst, kannst du auch deinen eigenen Logger erstellen und dann nur diesen anzeigen.

import logging

logger = logging.getLogger("MeinModul")
# Anstelle von "MeinModul" kannst du auch "__name__" eingeben 
# um den Namen automatisch zu ermitteln.
# Alternativ kannst du die Parameter auch leer lassen. Dann zeigt dein
# Logger dieselben Logs wie der Root-Logger.
logger.addHandler(logging.StreamHandler())
# Die Logs werden Sichtbar wenn du das Logging Level wählst.
logger.setLevel(logging.DEBUG)
logger.info("Jetzt wird dein Logger angezeigt")
logging.info("Der Root Logger wird nicht mehr angezeigt")

Jetzt wird dein Logger angezeigt

Individuelles Loggingformat

import logging

# Pick logger (leave empty to print all logs)
logger = logging.getLogger()
HANDLER = logging.StreamHandler()
# Setting logging format:
formatter = logging.Formatter(
    '%(asctime)s %(name)-12s %(levelname)-8s %(message)s')
HANDLER.setFormatter(formatter)
logger.addHandler(HANDLER)

# Picking log level to make visible:
logger.setLevel(logging.DEBUG)
logger.debug("Log im eigenen Format")

2021-08-08 10:14:02,374 root         DEBUG    Log im eigenen Format

Alternativ kannst du auch eine Konfigurationsdatei verwenden:

Dazu musst du eine Datei erstellen logging.ini:

[loggers]
keys=root

[handlers]
keys=stream_handler

[formatters]
keys=formatter

[logger_root]
level=DEBUG
handlers=stream_handler

[handler_stream_handler]
class=StreamHandler
level=DEBUG
formatter=formatter
args=(sys.stderr,)

[formatter_formatter]
format=%(asctime)s %(name)-12s %(levelname)-8s %(message)s

Diese kannst du nun mit folgender Zeile verwenden:

import logging

logging.config.fileConfig("logging.ini", disable_existing_loggers = False)

Wie du in Dateien Loggst

import logging

logging.basicConfig(
        filename=test.log,
        filemode='a',
        format='%(asctime)s,%(msecs)d %(name)s %(levelname)s %(message)s', datefmt='%H:%M:%S',
        level=logging.DEBUG
        )
logging.info("Jetzt wird sowohl der Root Logger...")
logger = logging.getLogger('mylogger')
logger.info("Als auch der eigene Logger in eine Datei geloggt.")

Inhalt von test.log:

10:01:58,733 root INFO Jetzt wird sowohl der Root Logger...
10:02:26,685 mylogger INFO Als auch der eigene Logger in eine Datei geloggt.```

Konnte ich helfen? Ich freue mich über einen Drink! 💙