Python-Protokollierung: Ein ausführliches Tutorial

Da Anwendungen immer komplexer werden, kann es sehr nützlich sein, gute Protokolle zu haben, nicht nur beim Debuggen, sondern auch, um Einblicke in Anwendungsprobleme/Leistung zu erhalten.

Die Python-Standardbibliothek enthält ein Protokollierungsmodul , das die meisten grundlegenden Protokollierungsfunktionen bereitstellt. Durch die korrekte Einrichtung kann eine Protokollnachricht viele nützliche Informationen darüber liefern, wann und wo das Protokoll ausgelöst wird, sowie über den Protokollkontext, z. B. den laufenden Prozess/Thread.

Trotz der Vorteile wird das Protokollierungsmodul oft übersehen, da es einige Zeit in Anspruch nimmt, es richtig einzurichten, und obwohl es meiner Meinung nach vollständig ist, das offizielle Protokollierungsdokument unter https://docs.python.org/3/library/logging.html gibt nicht wirklich Best Practices für die Protokollierung oder hebt einige Protokollierungsüberraschungen hervor.

Dieses Python-Logging-Tutorial ist nicht als vollständiges Dokument zum Logging-Modul gedacht, sondern eher als „Erste Schritte“-Anleitung, die einige Logging-Konzepte sowie einige „Fallstricke“ vorstellt, auf die Sie achten sollten. Der Beitrag endet mit Best Practices und enthält einige Hinweise auf fortgeschrittenere Protokollierungsthemen.

Bitte beachten Sie, dass alle Codeschnipsel im Beitrag davon ausgehen, dass Sie das Protokollierungsmodul bereits importiert haben:

 import logging

Konzepte für die Python-Protokollierung

Dieser Abschnitt gibt einen Überblick über einige Konzepte, die häufig im Protokollierungsmodul vorkommen.

Python-Protokollierungsebenen

Die Protokollebene entspricht der „Wichtigkeit“, die einem Protokoll beigemessen wird: Ein „Fehler“-Protokoll sollte dann dringender sein als das „Warn“-Protokoll, während ein „Debug“-Protokoll nur beim Debuggen der Anwendung nützlich sein sollte.

Es gibt sechs Protokollebenen in Python; Jede Ebene ist mit einer Ganzzahl verknüpft, die den Schweregrad des Protokolls angibt: NOTSET=0, DEBUG=10, INFO=20, WARN=30, ERROR=40 und CRITICAL=50.

Alle Ebenen sind ziemlich unkompliziert (DEBUG < INFO < WARN ), mit Ausnahme von NOTSET, dessen Besonderheit als nächstes angesprochen wird.

Formatierung der Python-Protokollierung

Der Protokollformatierer reichert eine Protokollnachricht grundsätzlich an, indem er ihr Kontextinformationen hinzufügt. Es kann nützlich sein zu wissen, wann das Protokoll gesendet wird, wohin (Python-Datei, Zeilennummer, Methode usw.) und zusätzlichen Kontext wie Thread und Prozess (kann beim Debuggen einer Multithread-Anwendung äußerst nützlich sein).

Wenn beispielsweise ein Protokoll „Hallo Welt“ über einen Protokollformatierer gesendet wird:

 "%(asctime)s — %(name)s — %(levelname)s — %(funcName)s:%(lineno)d — %(message)s"

es wird werden

 2018-02-07 19:47:41,864 - abc - WARNING - <module>:1 - hello world 

Python-Logging-Handler

Der Protokollhandler ist die Komponente, die effektiv ein Protokoll schreibt/darstellt: Zeigen Sie es in der Konsole (über StreamHandler), in einer Datei (über FileHandler) oder sogar per E-Mail über SMTPHandler usw. an.

Jeder Log-Handler hat zwei wichtige Felder:

• Ein Formatierer, der einem Protokoll Kontextinformationen hinzufügt.
• Eine Protokollebene, die Protokolle herausfiltert, deren Ebenen minderwertig sind. Ein Protokollhandler mit dem INFO-Level verarbeitet also keine DEBUG-Protokolle.

Die Standardbibliothek bietet eine Handvoll Handler, die für gängige Anwendungsfälle ausreichen sollten: https://docs.python.org/3/library/logging.handlers.html#module-logging.handlers. Die gebräuchlichsten sind StreamHandler und FileHandler:

 console_handler = logging.StreamHandler() file_handler = logging.FileHandler("filename")

Python-Logger

Logger ist wahrscheinlich derjenige, der direkt am häufigsten im Code verwendet wird und der auch am kompliziertesten ist. Einen neuen Logger erhalten Sie wie folgt:

 toto_logger = logging.getLogger("toto")

Ein Logger hat drei Hauptfelder:

• Propagate: Legt fest, ob ein Log an den übergeordneten Logger weitergegeben werden soll. Standardmäßig ist sein Wert True.
• A-Level: Wie der Log-Handler-Level dient der Logger-Level dazu, „weniger wichtige“ Logs herauszufiltern. Anders als beim Log-Handler wird die Ebene nur beim „untergeordneten“ Logger überprüft; Sobald das Protokoll an seine Eltern weitergegeben wird, wird die Ebene nicht überprüft. Dies ist eher ein nicht intuitives Verhalten.
• Handler: Die Liste der Handler, an die ein Protokoll gesendet wird, wenn es bei einem Logger ankommt. Dies ermöglicht eine flexible Protokollverwaltung – Sie können beispielsweise einen Dateiprotokollhandler haben, der alle DEBUG-Protokolle protokolliert, und einen E-Mail-Protokollhandler, der nur für CRITICAL-Protokolle verwendet wird. In dieser Hinsicht ähnelt die Logger-Handler-Beziehung einer Publisher-Consumer-Beziehung: Ein Log wird an alle Handler gesendet, sobald es die Logger-Level-Prüfung bestanden hat.

Ein Logger ist namentlich eindeutig , was bedeutet, dass, wenn ein Logger mit dem Namen „toto“ erstellt wurde, die nachfolgenden Aufrufe von logging.getLogger("toto") dasselbe Objekt zurückgeben:

 assert id(logging.getLogger("toto")) == id(logging.getLogger("toto"))

Wie Sie vielleicht erraten haben, haben Logger eine Hierarchie. Ganz oben in der Hierarchie befindet sich der Root-Logger, auf den über Logging.root zugegriffen werden kann. Dieser Logger wird aufgerufen, wenn Methoden wie logging.debug() verwendet werden. Standardmäßig ist die Root-Protokollebene WARN, sodass alle Protokolle mit niedrigerer Ebene (z. B. über logging.info("info") ) ignoriert werden. Eine weitere Besonderheit des Root-Loggers besteht darin, dass sein Standard-Handler erstellt wird, wenn zum ersten Mal ein Log mit einer höheren Ebene als WARN protokolliert wird. Die direkte oder indirekte Verwendung des Root-Loggers über Methoden wie logging.debug() wird im Allgemeinen nicht empfohlen.

Wenn ein neuer Logger erstellt wird, wird sein übergeordneter Logger standardmäßig auf den Root-Logger gesetzt:

 lab = logging.getLogger("ab") assert lab.parent == logging.root # lab's parent is indeed the root logger

Der Logger verwendet jedoch die „Punktnotation“, was bedeutet, dass ein Logger mit dem Namen „ab“ das Kind des Loggers „a“ ist. Dies gilt jedoch nur, wenn der Logger „a“ erstellt wurde, ansonsten ist „ab“ parent immer noch die Wurzel.

 la = logging.getLogger("a") assert lab.parent == la # lab's parent is now la instead of root

Wenn ein Logger entscheidet, ob ein Log gemäß der Level-Prüfung bestehen soll (z. B. wenn der Log-Level niedriger als der Logger-Level ist, wird das Log ignoriert), verwendet er seinen „effektiven Level“ anstelle des tatsächlichen Levels. Der effektive Pegel ist derselbe wie der Logger-Pegel, wenn der Pegel nicht NOTSET ist, dh alle Werte von DEBUG bis CRITICAL; Wenn die Protokollierungsebene jedoch NOTSET ist, dann ist die effektive Ebene die erste Vorgängerebene, die eine Nicht-NOTSET-Ebene hat.

Standardmäßig hat ein neuer Logger die Ebene NOTSET, und da die Root-Protokollierung eine WARN-Ebene hat, ist die effektive Ebene der Protokollierung WARN. Selbst wenn ein neuer Logger einige Handler angehängt hat, werden diese Handler nicht aufgerufen, es sei denn, die Protokollebene überschreitet WARN:

 toto_logger = logging.getLogger("toto") assert toto_logger.level == logging.NOTSET # new logger has NOTSET level assert toto_logger.getEffectiveLevel() == logging.WARN # and its effective level is the root logger level, ie WARN # attach a console handler to toto_logger console_handler = logging.StreamHandler() toto_logger.addHandler(console_handler) toto_logger.debug("debug") # nothing is displayed as the log level DEBUG is smaller than toto effective level toto_logger.setLevel(logging.DEBUG) toto_logger.debug("debug message") # now you should see "debug message" on screen

Standardmäßig wird das Logging-Level verwendet, um zu entscheiden, ob ein Log durchlaufen wird: Wenn das Logging-Level niedriger als das Logging-Level ist, wird das Log ignoriert.

Best Practices für die Python-Protokollierung

Das Logging-Modul ist zwar sehr praktisch, enthält aber einige Macken, die selbst den besten Python-Entwicklern stundenlange Kopfschmerzen bereiten können. Hier sind meiner Meinung nach die besten Praktiken für die Verwendung dieses Moduls:

• Konfigurieren Sie den Root-Logger, aber verwenden Sie ihn niemals in Ihrem Code – rufen Sie beispielsweise niemals eine Funktion wie logging.info() auf, die den Root-Logger tatsächlich hinter den Kulissen aufruft. Wenn Sie Fehlermeldungen von den von Ihnen verwendeten Bibliotheken abfangen möchten, stellen Sie sicher, dass der Root-Logger so konfiguriert ist, dass er beispielsweise in eine Datei schreibt, um das Debugging zu vereinfachen. Standardmäßig gibt der Root-Logger nur an stderr aus, sodass das Protokoll leicht verloren gehen kann.
• Um die Protokollierung zu verwenden, stellen Sie sicher, dass Sie einen neuen Logger erstellen, indem logging.getLogger(logger name) . Normalerweise verwende ich __name__ als Protokollnamen, aber alles kann verwendet werden, solange es konsistent ist. Um weitere Handler hinzuzufügen, habe ich normalerweise eine Methode, die einen Logger zurückgibt (das Wesentliche finden Sie unter https://gist.github.com/nguyenkims/e92df0f8bd49973f0c94bddf36ed7fd0).

 import logging import sys from logging.handlers import TimedRotatingFileHandler FORMATTER = logging.Formatter("%(asctime)s — %(name)s — %(levelname)s — %(message)s") LOG_FILE = "my_app.log" def get_console_handler(): console_handler = logging.StreamHandler(sys.stdout) console_handler.setFormatter(FORMATTER) return console_handler def get_file_handler(): file_handler = TimedRotatingFileHandler(LOG_FILE, when='midnight') file_handler.setFormatter(FORMATTER) return file_handler def get_logger(logger_name): logger = logging.getLogger(logger_name) logger.setLevel(logging.DEBUG) # better to have too much log than not enough logger.addHandler(get_console_handler()) logger.addHandler(get_file_handler()) # with this pattern, it's rarely necessary to propagate the error up to parent logger.propagate = False return logger

Danach können Sie einen neuen Logger erstellen und verwenden:

 my_logger = get_logger("my module name") my_logger.debug("a debug message")

• Verwenden Sie RotatingFileHandler-Klassen wie den im Beispiel verwendeten TimedRotatingFileHandler anstelle von FileHandler, da er die Datei automatisch für Sie dreht, wenn die Datei eine Größenbeschränkung erreicht, oder dies jeden Tag tut.
• Verwenden Sie Tools wie Sentry, Airbrake, Raygun usw., um Fehlerprotokolle automatisch für Sie abzufangen. Dies ist besonders nützlich im Zusammenhang mit einer Web-App, wo das Protokoll sehr ausführlich sein kann und Fehlerprotokolle leicht verloren gehen können. Ein weiterer Vorteil der Verwendung dieser Tools besteht darin, dass Sie Details zu Variablenwerten im Fehler erhalten, sodass Sie wissen, welche URL den Fehler auslöst, welcher Benutzer betroffen ist usw.

Wenn Sie an weiteren Best Practices interessiert sind, lesen Sie The 10 Most Common Mistakes That Python Developers Make von Toptaler Martin Chikilian.