Logging von Python-Applikationen
Nochmal zum Mitschreiben
Veröffentlicht in Ausgabe 06/2023 - SCHWERPUNKT
Für die Integration von Logging in Programme ist es ein guter Start, wenn die eingesetzte Sprache ein Interface für die Verarbeitung von Logdaten vorsieht. Der Nutzer muss sich dann lediglich auf das Aufrufen der vorgesehenen Funktionen beschränken, während Drittanbietermodule eine API zur Verarbeitung vorfinden. Im Fall von Python gibt es die unter [1] im Detail beschriebene API.
Einstieg in das Python-Logging
Für ein erstes Beispiel im Rahmen unseres Workshops bietet es sich an, die Ausgabe von drei Statusmeldungen in Python zu befehlen. Interessant ist, dass das Logging-Objekt eine Gruppe von Methoden darstellt – jede von ihnen übernimmt eine Nachricht, die Wichtigkeit erschließt sich aus der benutzten Methode:
import logging
logging.error('Dies ist ein Fehler')
logging.warning('Dies ist eine Warnung')
logging.info('Dies ist eine Information')
Das kleine Programm erzeugt ein Ergebnis, in dem jedoch eine der von uns angelegten Ausgaben fehlt. Die Menge der im Prompt angezeigten Informationen lässt sich durch Umgebungsvariablen steuern. Die reduzierte Darstellung in den im Artikel verwendeten Screenshots erfolgte durch die Eingabe von
export PS1='\u@\h: '.Für die Integration von Logging in Programme ist es ein guter Start, wenn die eingesetzte Sprache ein Interface für die Verarbeitung von Logdaten vorsieht. Der Nutzer muss sich dann lediglich auf das Aufrufen der vorgesehenen Funktionen beschränken, während Drittanbietermodule eine API zur Verarbeitung vorfinden. Im Fall von Python gibt es die unter [1] im Detail beschriebene API.
Einstieg in das Python-Logging
Für ein erstes Beispiel im Rahmen unseres Workshops bietet es sich an, die Ausgabe von drei Statusmeldungen in Python zu befehlen. Interessant ist, dass das Logging-Objekt eine Gruppe von Methoden darstellt – jede von ihnen übernimmt eine Nachricht, die Wichtigkeit erschließt sich aus der benutzten Methode:
import logging
logging.error('Dies ist ein Fehler')
logging.warning('Dies ist eine Warnung')
logging.info('Dies ist eine Information')
Das kleine Programm erzeugt ein Ergebnis, in dem jedoch eine der von uns angelegten Ausgaben fehlt. Die Menge der im Prompt angezeigten Informationen lässt sich durch Umgebungsvariablen steuern. Die reduzierte Darstellung in den im Artikel verwendeten Screenshots erfolgte durch die Eingabe von
export PS1='\u@\h: '.Das Logging-Framework in Python bietet die Möglichkeit, Logging-Meldungen Wichtigkeiten zuzuweisen. Von Haus aus gibt es die unten dargestellten Optionen, bestehend aus Log-Level und zugehörigem Ausgabewert. Angemerkt sei, dass Log-Levels in Form von Konstanten vorliegen – es ist Ihnen erlaubt, eigene Werte zwischen den vorgegebenen Leveln zu schreiben:
- logging.NOTSET: 0
- logging.DEBUG: 10
- logging.INFO: 20
- logging.WARNING: 30
- logging.ERROR: 40
- logging.CRITICAL: 50
Zur Anzeige der Meldung ist eine Anpassung der Filtereinstellungen erforderlich. Dies erledigen Sie durch die basicConfig-Methode:
import logging
logging.basicConfig(level=logging.INFO)
logging.error('Dies ist ein Fehler')
logging.warning('Dies ist eine Warnung')
logging.info('Dies ist eine Information')
Das basicConfig-Kommando lädt Standardeinstellungen in das Logging-Objekt, das als Basis des Aufrufs dient. Durch Übergeben des level-Parameters legt der Code fest, welche Mindestwichtigkeit notwendig ist. Lohn der Ausführung ist das Aufscheinen der Meldung "INFO: root:Dies ist eine Information" in der Kommandozeile.
Verwalten von Logging-Konfigurationen
Logging lohnt sich insbesondere in komplexen Applikationen. Das Nutzen eines statischen Objekts in mehreren Modulen wirkt sich negativ auf die Wartbarkeit des Codes aus. Im Fall des Logging-Systems von Python gilt, dass die Runtime eine Liste aller existierenden Logging-Objekte verwaltet. Dabei hat es sich als Best Practice etabliert, "__name__" zur Ermittlung eines "Lokalkontexts" heranzuziehen:
import logging
tamslogger = logging.getLogger(__name__)
tamslogger.setLevel(logging.INFO)
tamslogger.error('Dies ist ein Fehler')
tamslogger.warning('Dies ist eine Warnung')
tamslogger.info('Dies ist eine Information')
Die Konstante "__name__" erlaubt die Verortung von Code per Reflektion. Reflektion bedeutet in der Programmierung, dass ein Programm seine eigene Struktur kennt beziehungsweise diese modifizieren kann. Zum Überprüfen bietet es sich an, den Wert via
print(__name__) auszugeben. Lohn der Mühen ist das Erscheinen des folgenden Strings:tamhan@tamhan-gf65: python3 worker.py
__main__
Bringen wir unser Programm nun abermals zur Ausführung, zeigt sich ein Ergebnis wie in Bild 1, wobei jedoch der setLevel-Befehl nicht funktioniert. Damit dieser korrekt arbeitet, ist folgende Anpassung erforderlich:
tamslogger = logging.getLogger(__name__)
tamslogger.setLevel(logging.INFO)
console = logging.StreamHandler()
tamslogger.addHandler(console)
Im Hintergrund jedes Logging-Objekts arbeiten Handler. Das sind Hilfsobjekte [2], die eingehende Logging-Daten in Richtung einer "Datensenke" weiterreichen. Unser neu erzeugtes Logging-Objekt hat keinen Handler, weshalb der unter [3] beschriebene und nicht zur Gewichtung von Logs befähigte "Handler of Last Resort" zum Einsatz kommt. Sodann erzeugen Sie durch die Eingabe von
code modula.py ein neues Modul mit folgendem Code:import logging
def modulaHallo():
print(__name__)
Im Hauptprogramm folgt eine Aktivierung der Testfunktion, dabei informiert Sie "__name__" in der Rückmeldung über den Ausführungskontext:
import logging
import modula
modula.modulaHallo()
Im nächsten Schritt rufen wir die Modul-Methode im Hauptteil des Programms wie folgt auf:
tamslogger = logging.getLogger(__name__)
tamslogger.setLevel(logging.INFO)
console = logging.StreamHandler()
tamslogger.addHandler(console)
modula.modulaHallo()
Nun erhält "modulaHallo()" zusätzliche Befehle. Amtshandlung eins ist das abermalige Aufrufen von "logging.getLogger (__name__)", danach erfolgt die Ausgabe von Logging-Nachrichten:
import logging
def modulaHallo():
tamslogger = logging.getLogger(__name__)
tamslogger.error('Dies ist ein Fehler')
tamslogger.warning('Dies ist eine Warnung')
tamslogger.info('Dies ist eine Information')
print ("- - - - - - -")
Bei der Ausführung zeigt sich, dass im Modul ödie per "info()" ausgegebene Nachricht nicht auf dem Bildschirm erscheint. Zur Behebung des Problems versorgen wir "modulaHallo" mit einem Parameter, der "getLogger" entsprechend beeinflusst:
import logging
def modulaHallo(whichName):
tamslogger = logging.getLogger(whichName)
Ein neuer Aufruf erlaubt das Übergeben von "Name":
modula.modulaHallo(__name__)
Da der an "getLogger" übergebene String in beiden Fällen konstant ist, liefert der Logging-Manager dasselbe Logging-Objekt zurück.
Zusätzliche Informationen anzeigen
Ein Vergleich der beiden Ausgaben zeigt, dass der "allgemeine" Logger mehr Informationen über den Systemzustand liefert. Sie finden unter [4] eine Liste mit rund zwei Dutzend Strings, die Informationen über den Systemzustand bereitstellen. Um diese zu nutzen, ist es erforderlich, dass Sie dem Logging-Prozess einen "Formatter" verpassen:
console = logging.StreamHandler()
formatter = logging.Formatter ('%(asctime)s:%(levelname)s:%(message)s')
console.setFormatter(formatter)
tamslogger.addHandler(console)
Neben der Auswahl der auszugebenden Informationen ist der Befehl zum Anpassen der Anzeige zu mehr in der Lage: Durch Übergeben des Strings "-12" lässt sich eine Mindestlänge zuweisen, um die Ausgabe übersichtlicher zu gestalten (das Ergebnis sehen Sie in Bild 2):
formatter = logging.Formatter('%(asctime)s:%(levelname)-12s:%(message)s')
Handler und Dateiinformationen
Die Handler-Infrastruktur steigert die Flexibilität bei der Verarbeitung der Logdaten. Die durch die Meldemethoden angelieferten Informationen lassen sich mit Bordmitteln in rotierende Logdateien oder E-Mails verpacken. Das manuelle Implementieren des Interfaces erlaubt die Realisierung exotischerer Vorgehensweisen wie etwa der Umwandlung in einen per RS232 übertragbaren Datenstrom.
Als Demonstration sollen Informationen in eine lokale Logdatei wandern. Beim Einsatz des basicConfig-Befehls reicht das Übergeben von "filename" aus:
logging.basicConfig(filename='example.log', encoding='utf-8', level=logging.DEBUG)
Verwenden Sie zur Reduktion der Koppelung alleinstehende Logging-Objekte, müssen Sie ein FileHandler-Objekt ergänzen:
tamslogger.addHandler(console)
filehdlr = logging.FileHandler('filehandler.txt')
filehdlr.setFormatter(formatter)
tamslogger.addHandler(filehdlr)
Logging-Objekte sind zur gleichzeitigen Verarbeitung mehrerer Handler befähigt – platzieren Sie den zweiten Aufruf von "addHandler" unter den ersten, kommen beide beim Eingehen einer Message zum Zug. Die Logdatei wächst dann stark an.
Durch Übergeben des Modus-Parameters "w" (für "write") lässt sich der FileHandler anweisen, bei jedem Durchlauf des Programms eine neue Logdatei anzulegen:
filehdlr = logging.FileHandler('filehandler.txt', mode='w')
filehdlr.setFormatter(formatter)
Nur kurze Zeit laufende Programme sind hierbei unproblematisch, weil sie in der Praxis bei Unix-Systemen nur selten vorkommen. Werkzeuge wie newsyslog oder logrotate betreffen derartige Beispiele nicht – so die Utilities im produktiven Einsatz eine geöffnete Logdatei löschen, kommt es beim normalen FileHandler zu undefiniertem Verhalten, wenn dieser versucht, den nicht mehr gültigen Datei-Deskriptor zum Schreiben zu verwenden. Der "WatchedFileHandler" [5] schafft Abhilfe.
Zu beachten ist jedoch, dass Windows keine Dateisystem-Überwachungs-API bietet, sodass der WatchedFileHandler nur unter unixoiden Systemen nutzbar ist. Dessen Nutzung setzt ein zusätzliches Paket voraus:
import logging.handlers
Zur Inbetriebnahme des WatchedFileHandler kommt derselbe Konstruktor zum Einsatz. Das Einschreiben des Formatters und die Zuweisung des Handlers in den Logger sind jedoch auch hier erforderlich:
filehdlr = logging.handlers.WatchedFileHandler('filehandler.txt', mode='w')
filehdlr.setFormatter(formatter)
tamslogger.addHandler(filehdlr)
Um das korrekte Verhalten zu überprüfen, ist ein lang anhaltender Logging-Prozess notwendig. Dieser lässt sich für einen Test durch eine Endlosschleife abbilden, die alle drei Sekunden neue Logdaten erzeugt:
while 1==1:
tamslogger.error('Dies ist ein Fehler')
time.sleep(3)
Der Test erfolgt in zwei Terminalfenstern. In Fenster eins läuft der Python-Code, während die Logdatei in Fenster zwei per rm gelöscht wird. Diese Manipulation erfolgt ohne Beeinflussung des Programmverhaltens, womit wir die gewünschte Funktionalität verifiziert haben.
FileHandler und seine Verwandten löschen Logdateien auf Wunsch bei jedem Durchlauf des Programms. Dies beschränkt den verbrauchten Speicherplatz, es besteht allerdings das Risiko, keine Daten zu einem kritischen Vorfall mehr vorzufinden. In der Praxis ist es besser, Logdateien zu rotieren. Darunter ist der zeitgesteuerte Austausch von Daten unter Vorhalten einer Reserve mit aktuellen Informationen zu verstehen. Alle für dieses Verhalten vorgesehenen Handler sind Varianten des "BaseRotatingHandler", der folgende Basisparameter erfodert:
class logging.handlers.BaseRotatingHandler(filename, mode, encoding= None, delay=False, errors=None)¶
In der Praxis lässt sich die abstrakte Klasse jedoch nicht einsetzen – die häufigste verwendete Implementierung ist der RotatingFileHandler:
rh = logging.handlers.RotatingFileHandler('rotated.log', maxBytes=128, backupCount=5)
Mit "maxBytes" legen Sie die maximale Größe einer Logdatei fest, während Sie mit "backupCount" die Anzahl der vorzuhaltenden Backups bestimmen. Zu dessen Überprüfung bietet sich folgender Code an:
rh = logging.handlers.RotatingFileHandler('rotated.log', maxBytes=128,backupCount=5)
rh.setFormatter(formatter)
tamslogger.addHandler(rh)
while 1==1:
tamslogger.error
('Dies ist ein Fehler')
Am daraufhin erzeugten Ergebnis ist erkennbar, dass RotatingFileHandler die per backupCount und maxBytes festgelegten Constraints einhält.
Das in der Klasse angelegte Verhalten lässt sich durch Hilfsmethoden anpassen:
def namer(name):
return name + ".gz"
def rotator(source, dest):
with open(source, 'rb') as f_in:
with gzip.open(dest, 'wb') as f_out:
shutil.copyfileobj(f_in, f_out)
os.remove(source)
rh.rotator = rotator
rh.namer = namer
Hierbei hat "Namer" die Aufgabe, in das Erzeugen der Dateinamen einzugreifen. Die Methode bekommt den von der im FileHandler enthaltenen Logik generierten Namen und kann diesen – hier durch das Anfügen einer Dateiendung – adaptieren. In "Rotator" findet sich Logik für die Dateiumbenennung und Dateiverschiebung.
Sofern Logdateien nach einer gewissen Zeit verfallen, bietet sich der "TimedRotatingFileHandler" an. Er nutzt die unter [6] gezeigten und an CRON erinnernden Strings zum Festlegen des Vorhaltezeitraums:
class logging.handlers.TimedRotatingFileHandler(filename, when='h', interval=1, backupCount=0, encoding=None, delay=False, utc=False, atTime=None, errors=None)
Handler liefern Nachrichten ins SysLog
Die Überwachung der SysLog-Inhalte ist häufig bereits implementiert. Das Einrichten eines unabhängigen zweiten Logging-Prozesses lässt sich vermeiden, wenn Python seine Daten in das SysLog schreibt. Dies ist Aufgabe von "SysLogHandler". Wir illustrieren seinen Einsatz unter Ubuntu 22.04LTS – da verschiedene Betriebssysteme unterschiedliche Logging-Infrastrukturen mitbringen, ist eventuell eine Anpassung erforderlich.
Bevor wir damit starten noch der Hinweis, dass SysLogHandler nur unter Unix-Betriebssystemen zur Verfügung steht. Windows-Plattformen verwenden die Klasse "NTEventLogHandler" – sie verhält sich analog, loggt aber in das Windows-SysLog.
Von Haus aus verbindet sich der SysLogHandler unter Nutzung des UDP-Protokolls mit der Endstelle "localhost:514". Ubuntu weist an dieser Stelle keinen Logging-Dienst auf, die korrekte Parametrierung sieht daher folgendermaßen aus:
loghdler = logging.handlers.SysLogHandler(address = '/dev/log')
loghdler.setFormatter(formatter)
tamslogger.addHandler(loghdler)
Der Befehl
cat /var/log/syslog | tail -f
liefert Ihnen nun die vom Python-Programm angelieferten Informationen auf den Bildschirm.
Handler exportieren Logdaten ins Netz
Das lokale Vorhalten von Logdateien ist in kritischen Umgebungen nicht empfehlenswert, denn Angreifer finden in den Logging-Speichern angegriffener Systeme wertvolle Informationen. Python begegnet diesem Problem durch Handler, die Logdaten ins Netzwerk übertragen. So kümmern sich "SocketHandler" und "DatagramHandler" um das Absenden von Nachrichten über TCP beziehungsweise UDP. Als Gegenstelle erwarten die Klassen eine beliebige Netzwerkapplikation, die per Berkeley-Socket-API realisierbar ist. Dies ist eine Netzwerk-API, die auf so gut wie allen Betriebssystemen gleichermaßen umgesetzt ist [7].
Dieser Artikel soll nicht in einem Tutorial der Netzwerkprogrammierung ausarten, daher greifen wir auf ein fertiges Beispielprogramm [8] zurück. Dieses liegt für so gut wie alle Socket-Implementierungen als sogenannter Echoserver vor. Sie nehmen die eingehenden Informationen entgegen und schicken diese an den Client zurück. Für die folgenden Schritte adaptieren wir das Programm wie in Listing 1, sodass es die angelieferten Informationen nicht mehr in den Socket zurückschreibt, sondern sie in Richtung der Kommandozeile ausgibt.
Listing 1: Anpassungen am Echoserver
import socket
HOST = '127.0.0.1'
PORT = 5000
with socket.socket(socket.AF_INET, socket.SOCK_STREAM) as s:
s.bind((HOST, PORT))
s.listen()
conn, addr = s.accept()
with conn:
print ("Neuer Client")
while True:
data = conn.recv(1024)
print (data)
Relevant ist die Nutzung des Ports 5000, denn Verbindungen zu Ports kleiner als 1024 setzen auf unixoiden Betriebssystemen das Vorhandensein von Root-Rechten voraus, was wir vermeiden wollen. Da Server und das Logging-Programm auf dem gleichen System arbeiten, können Sie außerdem den String "localhost" anstatt einer IP-Adresse verwenden.
Dank der Modularität des Logging-Systems sind nur minimale Eingriffe erforderlich. Das soeben verwendete Programm zur Ausgabe in den Systemlog lässt sich durch die Klasse "logging.handlers.SocketHandler" in einen Socket-Logger umwandeln:
loghdler = logging.handlers.SocketHandler('localhost', 5000)
loghdler.setFormatter(formatter)
tamslogger.addHandler(loghdler)
Laufen Logger und Server parallel, präsentieren sich die Nachrichten seltsam formatiert. Ursache ist eine als "Pickler" bezeichnete Komponente. Er wandelt eingehende Nachrichten in ein über das Netzwerk übertragbares Binärformat um.
Da wir in unserem Beispiel Zeichenketten verarbeiten wollen, müssen wir den Pickler adaptieren. Hierbei bieten sich die objektorientierten Funktionen von Python an. Durch Vererbung lässt sich eine vorhandene Klasse als Blaupause für eine neue heranziehen, deren Eigenschaften veränderbar werden. Für "PlainTcpHandler" ist ein neuer Pickler erforderlich:
class PlainTcpHandler(logging.handlers.SocketHandler):
def makePickle(self, record):
message = self.formatter. format(record) + "\r\n" return message.encode()
Der mit "class" beginnende Programmteil folgt den Import-Deklarationen. Danach ist noch eine Anpassung notwendig:
loghdler = PlainTcpHandler('localhost', 5000)
Die Ausführung dieses Programms bringt die Nachrichten in die Kommandozeile. Angemerkt sei, dass das Python-Loggingsystem auch E-Mails senden kann. Hierzu ist ein SMTP-Server erforderlich, der wie folgt Teil des Konstruktors der SMTPHandler-Klasse wird:
class logging.handlers.SMTP-Handler(mailhost, fromaddr, toaddrs, subject, credentials=None, secure=None, timeout=1.0)¶
Allerdings ist SMTPHandler kaum mit kommerziellen Mailservern kompatibel, denn die Klasse bietet keine Unterstützung für TLS-Übertragungen, was die Verwendung von Systemen wie Gmail und Co. erschwert.
Wichtig ist außerdem, dass der Handler normalerweise pro Message eine E-Mail sendet. Dies führt in der Praxis zum Überlaufen der Mailbox und Logging-Nachrichten werden nach kurzer Zeit ungelesen gelöscht. Zur Lösung bietet sich die MemoryHandler-Klasse [9] an. Dabei handelt es sich um einen Handler, der eingehende Informationen im ersten Schritt in einem Puffer sammelt und die Logdaten in einem zweiten Schritt blockweise schreibt.
Logging in durchsatzkritischen Szenarien
Die in Python implementierte Logging-Infrastruktur ist prinzipiell Thread-sicher ausgeführt. Das bedeutet, dass das gleichzeitige Aufrufen von Methoden in einem Logger aus verschiedenen Threads keine Probleme verursacht. Kritisch ist lediglich die Nutzung einer Logdatei aus mehreren Prozessen.
Ein Grund für die hohe Thread-Sicherheit der Logger ist, dass Handler per se blockierend angelegt sind. Nutzt Code beispielsweise einen SMTP-Handler, läuft das Programm erst nach dem erfolgreichen Versand der E-Mail weiter (Stichwort Netzwerklatenz). Zur Lösung des Problems hat sich in der Python-Community der in Listing 2 gezeigte Code etabliert. Die Klasse "QueueListener" lebt hier in einem eigenen Thread, der sich um die Abarbeitung der Re-
moteLogHandler-Instanzen beziehungsweise der bei ihnen eingehenden Informationen kümmert.
Listing 2: SMTP-Handler nutzen
import queue
from logging.handlers import QueueHandler, QueueListener
log_queue = queue.Queue(-1)
queue_handler = QueueHandler(log_queue)
remote_handler = RemoteLogHandler()
remote_listener = QueueListener(log_queue, remote_handler)
logging.getLogger().addHandler(queue_handler)
remote_listener.start()
Fazit
Die Anreicherung von Python-Code mit Logfunktionen sorgt dafür, dass der Administrator im Ernstfall auf umfangreiche Informationen zu aufgetretenen Fehlern zurückgreifen kann. Bei geschickter Kombination der verschiedenen Handler ist zum Einrichten eines flexiblen und redundanten Loggings in Python-Applikationen nur wenig Handarbeit erforderlich.
(jp)
Link-Codes
[1] Logging-Modul für Python: https://docs.python.org/3/library/logging.html/
[2] Logging-Handler: https://docs.python.org/3/library/logging.handlers.html/
[3] Last-Resort-Handler: https://docs.python.org/3/library/logging.html#logging.lastResort/
[4] Attribute von LogRecord: https://docs.python.org/3/library/logging.html#logrecord-attributes/
[5] WatchedFileHandler: https://docs.python.org/3/howto/logging.html#logging-advanced-tutorial
[6] TimedRotatingFileHandler: https://docs.python.org/3/library/logging.handlers.html#timedrotatingfilehandler/
[7] Socket-Programmierung: https://docs.python.org/3/howto/sockets.html/
[8] Beispielprogramm zu Echoserver: https://realpython.com/python-sockets/#echo-server/
[9] Überlaufen der Logging-Nachrichten verhindern: https://stackoverflow.com/questions/1610845/collate-output-in-python-logging-memoryhandler-with-smtphandler/