Kochbuch zur Protokollierung¶
Diese Seite enthält eine Reihe von Rezepten rund um die Protokollierung, die sich in der Vergangenheit als nützlich erwiesen haben. Verweise auf Tutorial- und Referenzinformationen findest du unter Weitere Quellen.
Protokollierung in mehreren Modulen verwenden¶
Mehrere Aufrufe von logging.getLogger('someLogger') geben einen Verweis auf dasselbe Logger-Objekt zurück. Das gilt nicht nur innerhalb desselben Moduls, sondern auch über Module hinweg, solange es derselbe Prozess des Python-Interpreters ist. Es gilt für Verweise auf dasselbe Objekt. Darüber hinaus kann Anwendungscode in einem Modul einen Eltern-Logger festlegen und konfigurieren und in einem anderen Modul einen Kind-Logger erzeugen (aber nicht konfigurieren), und alle Logger-Aufrufe am Kind werden an den Eltern-Logger weitergegeben. Hier ein Hauptmodul:
import logging
import auxiliary_module
# create logger with 'spam_application'
logger = logging.getLogger('spam_application')
logger.setLevel(logging.DEBUG)
# create file handler which logs even debug messages
fh = logging.FileHandler('spam.log')
fh.setLevel(logging.DEBUG)
# create console handler with a higher log level
ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)
# create formatter and add it to the handlers
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
fh.setFormatter(formatter)
ch.setFormatter(formatter)
# add the handlers to the logger
logger.addHandler(fh)
logger.addHandler(ch)
logger.info('creating an instance of auxiliary_module.Auxiliary')
a = auxiliary_module.Auxiliary()
logger.info('created an instance of auxiliary_module.Auxiliary')
logger.info('calling auxiliary_module.Auxiliary.do_something')
a.do_something()
logger.info('finished auxiliary_module.Auxiliary.do_something')
logger.info('calling auxiliary_module.some_function()')
auxiliary_module.some_function()
logger.info('done with auxiliary_module.some_function()')
Hier das Hilfsmodul:
import logging
# create logger
module_logger = logging.getLogger('spam_application.auxiliary')
class Auxiliary:
def __init__(self):
self.logger = logging.getLogger('spam_application.auxiliary.Auxiliary')
self.logger.info('creating an instance of Auxiliary')
def do_something(self):
self.logger.info('doing something')
a = 1 + 1
self.logger.info('done doing something')
def some_function():
module_logger.info('received a call to "some_function"')
Die Ausgabe sieht so aus:
2005-03-23 23:47:11,663 - spam_application - INFO -
creating an instance of auxiliary_module.Auxiliary
2005-03-23 23:47:11,665 - spam_application.auxiliary.Auxiliary - INFO -
creating an instance of Auxiliary
2005-03-23 23:47:11,665 - spam_application - INFO -
created an instance of auxiliary_module.Auxiliary
2005-03-23 23:47:11,668 - spam_application - INFO -
calling auxiliary_module.Auxiliary.do_something
2005-03-23 23:47:11,668 - spam_application.auxiliary.Auxiliary - INFO -
doing something
2005-03-23 23:47:11,669 - spam_application.auxiliary.Auxiliary - INFO -
done doing something
2005-03-23 23:47:11,670 - spam_application - INFO -
finished auxiliary_module.Auxiliary.do_something
2005-03-23 23:47:11,671 - spam_application - INFO -
calling auxiliary_module.some_function()
2005-03-23 23:47:11,672 - spam_application.auxiliary - INFO -
received a call to 'some_function'
2005-03-23 23:47:11,673 - spam_application - INFO -
done with auxiliary_module.some_function()
Aus mehreren Threads protokollieren¶
Aus mehreren Threads zu protokollieren erfordert keinen besonderen Aufwand. Das folgende Beispiel zeigt die Protokollierung aus dem Haupt-Thread (dem ersten) und einem weiteren Thread:
import logging
import threading
import time
def worker(arg):
while not arg['stop']:
logging.debug('Hi from myfunc')
time.sleep(0.5)
def main():
logging.basicConfig(level=logging.DEBUG, format='%(relativeCreated)6d %(threadName)s %(message)s')
info = {'stop': False}
thread = threading.Thread(target=worker, args=(info,))
thread.start()
while True:
try:
logging.debug('Hello from main')
time.sleep(0.75)
except KeyboardInterrupt:
info['stop'] = True
break
thread.join()
if __name__ == '__main__':
main()
Beim Ausführen sollte das Skript etwa Folgendes ausgeben:
0 Thread-1 Hi from myfunc
3 MainThread Hello from main
505 Thread-1 Hi from myfunc
755 MainThread Hello from main
1007 Thread-1 Hi from myfunc
1507 MainThread Hello from main
1508 Thread-1 Hi from myfunc
2010 Thread-1 Hi from myfunc
2258 MainThread Hello from main
2512 Thread-1 Hi from myfunc
3009 MainThread Hello from main
3013 Thread-1 Hi from myfunc
3515 Thread-1 Hi from myfunc
3761 MainThread Hello from main
4017 Thread-1 Hi from myfunc
4513 MainThread Hello from main
4518 Thread-1 Hi from myfunc
Das zeigt die Protokollausgabe ineinander verschränkt, wie man es erwarten würde. Dieser Ansatz funktioniert natürlich auch mit mehr Threads als hier gezeigt.
Mehrere Handler und Formatter¶
Logger sind gewöhnliche Python-Objekte. Die Methode addHandler() hat keine Mindest- oder Höchstzahl für die Handler, die du hinzufügen darfst. Manchmal ist es für eine Anwendung sinnvoll, alle Meldungen aller Schweregrade in eine Textdatei zu protokollieren und gleichzeitig Fehler und Schlimmeres auf der Konsole zu protokollieren. Dazu konfigurierst du einfach die passenden Handler. Die Protokollierungsaufrufe im Anwendungscode bleiben unverändert. Hier eine kleine Abwandlung des vorherigen einfachen, modulbasierten Konfigurationsbeispiels:
import logging
logger = logging.getLogger('simple_example')
logger.setLevel(logging.DEBUG)
# create file handler which logs even debug messages
fh = logging.FileHandler('spam.log')
fh.setLevel(logging.DEBUG)
# create console handler with a higher log level
ch = logging.StreamHandler()
ch.setLevel(logging.ERROR)
# create formatter and add it to the handlers
formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
ch.setFormatter(formatter)
fh.setFormatter(formatter)
# add the handlers to logger
logger.addHandler(ch)
logger.addHandler(fh)
# 'application' code
logger.debug('debug message')
logger.info('info message')
logger.warning('warn message')
logger.error('error message')
logger.critical('critical message')
Beachte, dass den „Anwendungs“-Code die mehreren Handler nicht interessieren. Geändert hat sich nur, dass ein neuer Handler namens fh hinzugekommen und konfiguriert worden ist.
Neue Handler mit Filtern für höhere oder niedrigere Schweregrade anlegen zu können, kann beim Schreiben und Testen einer Anwendung sehr hilfreich sein. Verwende zur Fehlersuche statt vieler print-Anweisungen logger.debug: Anders als die print-Anweisungen, die du später löschen oder auskommentieren musst, können die logger.debug-Anweisungen im Quellcode stehen bleiben und ruhen dort, bis du sie wieder brauchst. Dann musst du nur noch den Schweregrad des Loggers und/oder des Handlers auf debug ändern.
An mehrere Ziele protokollieren¶
Nehmen wir an, du willst mit unterschiedlichen Meldungsformaten und unter unterschiedlichen Umständen auf die Konsole und in eine Datei protokollieren. Nehmen wir an, du willst Meldungen mit den Schweregraden DEBUG und höher in eine Datei und die Meldungen mit Schweregrad INFO und höher auf die Konsole protokollieren. Nehmen wir weiter an, die Datei soll Zeitstempel enthalten, die Meldungen auf der Konsole aber nicht. So erreichst du das:
import logging
# set up logging to file - see previous section for more details
logging.basicConfig(level=logging.DEBUG,
format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s',
datefmt='%m-%d %H:%M',
filename='/tmp/myapp.log',
filemode='w')
# define a Handler which writes INFO messages or higher to the sys.stderr
console = logging.StreamHandler()
console.setLevel(logging.INFO)
# set a format which is simpler for console use
formatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(message)s')
# tell the handler to use this format
console.setFormatter(formatter)
# add the handler to the root logger
logging.getLogger().addHandler(console)
# Now, we can log to the root logger, or any other logger. First the root...
logging.info('Jackdaws love my big sphinx of quartz.')
# Now, define a couple of other loggers which might represent areas in your
# application:
logger1 = logging.getLogger('myapp.area1')
logger2 = logging.getLogger('myapp.area2')
logger1.debug('Quick zephyrs blow, vexing daft Jim.')
logger1.info('How quickly daft jumping zebras vex.')
logger2.warning('Jail zesty vixen who grabbed pay from quack.')
logger2.error('The five boxing wizards jump quickly.')
Wenn du das ausführst, siehst du auf der Konsole
root : INFO Jackdaws love my big sphinx of quartz.
myapp.area1 : INFO How quickly daft jumping zebras vex.
myapp.area2 : WARNING Jail zesty vixen who grabbed pay from quack.
myapp.area2 : ERROR The five boxing wizards jump quickly.
und in der Datei siehst du etwa
10-22 22:19 root INFO Jackdaws love my big sphinx of quartz.
10-22 22:19 myapp.area1 DEBUG Quick zephyrs blow, vexing daft Jim.
10-22 22:19 myapp.area1 INFO How quickly daft jumping zebras vex.
10-22 22:19 myapp.area2 WARNING Jail zesty vixen who grabbed pay from quack.
10-22 22:19 myapp.area2 ERROR The five boxing wizards jump quickly.
Wie du siehst, erscheint die DEBUG-Meldung nur in der Datei. Die anderen Meldungen gehen an beide Ziele.
Dieses Beispiel verwendet einen Konsolen- und einen Datei-Handler, du kannst aber beliebig viele Handler in beliebiger Kombination verwenden.
Beachte, dass die obige Wahl des Protokolldateinamens /tmp/myapp.log einen Standardort für temporäre Dateien auf POSIX-Systemen voraussetzt. Unter Windows musst du für das Protokoll möglicherweise einen anderen Verzeichnisnamen wählen – achte nur darauf, dass das Verzeichnis existiert und du darin Dateien anlegen und ändern darfst.
Eigene Behandlung von Schweregraden¶
Manchmal willst du etwas anderes als die übliche Behandlung von Schweregraden in Handlern, bei der ein Handler alle Grade oberhalb einer Schwelle verarbeitet. Dazu musst du Filter verwenden. Sehen wir uns einen Fall an, in dem du es folgendermaßen einrichten willst:
Meldungen mit Schweregrad
INFOundWARNINGansys.stdoutsendenMeldungen mit Schweregrad
ERRORund höher ansys.stderrsendenMeldungen mit Schweregrad
DEBUGund höher in die Dateiapp.logsenden
Nehmen wir an, du konfigurierst die Protokollierung mit folgendem JSON:
{
"version": 1,
"disable_existing_loggers": false,
"formatters": {
"simple": {
"format": "%(levelname)-8s - %(message)s"
}
},
"handlers": {
"stdout": {
"class": "logging.StreamHandler",
"level": "INFO",
"formatter": "simple",
"stream": "ext://sys.stdout"
},
"stderr": {
"class": "logging.StreamHandler",
"level": "ERROR",
"formatter": "simple",
"stream": "ext://sys.stderr"
},
"file": {
"class": "logging.FileHandler",
"formatter": "simple",
"filename": "app.log",
"mode": "w"
}
},
"root": {
"level": "DEBUG",
"handlers": [
"stderr",
"stdout",
"file"
]
}
}
Diese Konfiguration tut fast das, was wir wollen, nur würde sys.stdout auch Meldungen mit Schweregrad ERROR anzeigen, und es würden neben den INFO- und WARNING-Meldungen auch Ereignisse dieses und höheren Schweregrades verfolgt. Um das zu verhindern, können wir einen Filter einrichten, der diese Meldungen ausschließt, und ihn dem betreffenden Handler hinzufügen. Das lässt sich konfigurieren, indem wir einen Abschnitt filters parallel zu formatters und handlers ergänzen:
{
"filters": {
"warnings_and_below": {
"()" : "__main__.filter_maker",
"level": "WARNING"
}
}
}
und den Abschnitt zum Handler stdout so ändern, dass er ihn aufnimmt:
{
"stdout": {
"class": "logging.StreamHandler",
"level": "INFO",
"formatter": "simple",
"stream": "ext://sys.stdout",
"filters": ["warnings_and_below"]
}
}
Ein Filter ist einfach eine Funktion, wir können filter_maker (eine Factory-Funktion) also so festlegen:
def filter_maker(level):
level = getattr(logging, level)
def filter(record):
return record.levelno <= level
return filter
Das wandelt das übergebene Zeichenkettenargument in einen numerischen Schweregrad um und gibt eine Funktion zurück, die nur dann True zurückgibt, wenn der Schweregrad des übergebenen Datensatzes auf oder unter dem angegebenen Grad liegt. Beachte, dass ich filter_maker in diesem Beispiel in einem Testskript main.py festgelegt habe, das ich von der Befehlszeile aus starte. Sein Modul ist damit __main__ – daher das __main__.filter_maker in der Filterkonfiguration. Das musst du ändern, wenn du es in einem anderen Modul festlegst.
Mit dem ergänzten Filter können wir main.py ausführen, das vollständig so aussieht:
import json
import logging
import logging.config
CONFIG = '''
{
"version": 1,
"disable_existing_loggers": false,
"formatters": {
"simple": {
"format": "%(levelname)-8s - %(message)s"
}
},
"filters": {
"warnings_and_below": {
"()" : "__main__.filter_maker",
"level": "WARNING"
}
},
"handlers": {
"stdout": {
"class": "logging.StreamHandler",
"level": "INFO",
"formatter": "simple",
"stream": "ext://sys.stdout",
"filters": ["warnings_and_below"]
},
"stderr": {
"class": "logging.StreamHandler",
"level": "ERROR",
"formatter": "simple",
"stream": "ext://sys.stderr"
},
"file": {
"class": "logging.FileHandler",
"formatter": "simple",
"filename": "app.log",
"mode": "w"
}
},
"root": {
"level": "DEBUG",
"handlers": [
"stderr",
"stdout",
"file"
]
}
}
'''
def filter_maker(level):
level = getattr(logging, level)
def filter(record):
return record.levelno <= level
return filter
logging.config.dictConfig(json.loads(CONFIG))
logging.debug('A DEBUG message')
logging.info('An INFO message')
logging.warning('A WARNING message')
logging.error('An ERROR message')
logging.critical('A CRITICAL message')
Und nach einem Aufruf wie diesem:
python main.py 2>stderr.log >stdout.log
sehen wir, dass die Ergebnisse den Erwartungen entsprechen:
$ more *.log
::::::::::::::
app.log
::::::::::::::
DEBUG - A DEBUG message
INFO - An INFO message
WARNING - A WARNING message
ERROR - An ERROR message
CRITICAL - A CRITICAL message
::::::::::::::
stderr.log
::::::::::::::
ERROR - An ERROR message
CRITICAL - A CRITICAL message
::::::::::::::
stdout.log
::::::::::::::
INFO - An INFO message
WARNING - A WARNING message
Beispiel für einen Konfigurationsserver¶
Hier ein Beispiel für ein Modul, das den Konfigurationsserver der Protokollierung verwendet:
import logging
import logging.config
import time
import os
# read initial config file
logging.config.fileConfig('logging.conf')
# create and start listener on port 9999
t = logging.config.listen(9999)
t.start()
logger = logging.getLogger('simpleExample')
try:
# loop through logging calls to see the difference
# new configurations make, until Ctrl+C is pressed
while True:
logger.debug('debug message')
logger.info('info message')
logger.warning('warn message')
logger.error('error message')
logger.critical('critical message')
time.sleep(5)
except KeyboardInterrupt:
# cleanup
logging.config.stopListening()
t.join()
Und hier ein Skript, das einen Dateinamen nimmt und diese Datei – korrekt um die binär kodierte Länge vorangestellt – als neue Protokollierungskonfiguration an den Server sendet:
#!/usr/bin/env python
import socket, sys, struct
with open(sys.argv[1], 'rb') as f:
data_to_send = f.read()
HOST = 'localhost'
PORT = 9999
s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
print('connecting...')
s.connect((HOST, PORT))
print('sending config...')
s.send(struct.pack('>L', len(data_to_send)))
s.send(data_to_send)
s.close()
print('complete')
Mit Handlern umgehen, die blockieren¶
Manchmal musst du dafür sorgen, dass deine Protokollierungs-Handler ihre Arbeit tun, ohne den Thread zu blockieren, aus dem du protokollierst. Das kommt in Webanwendungen häufig vor, tritt natürlich aber auch in anderen Fällen auf.
Ein häufiger Übeltäter mit träger Arbeitsweise ist SMTPHandler: Das Versenden von E-Mails kann aus einer Reihe von Gründen außerhalb der Kontrolle des Entwicklers lange dauern (etwa eine schlecht arbeitende Mail- oder Netzinfrastruktur). Aber fast jeder netzbasierte Handler kann blockieren: Selbst eine Operation von SocketHandler nimmt unter der Haube möglicherweise eine DNS-Abfrage vor, die zu langsam ist (und diese Abfrage kann tief im Code der Socket-Bibliothek liegen, unterhalb der Python-Schicht und außerhalb deiner Kontrolle).
Eine Lösung besteht in einem zweiteiligen Ansatz. Für den ersten Teil hängst du an die Logger, auf die aus geschwindigkeitskritischen Threads zugegriffen wird, nur einen QueueHandler. Die schreiben einfach in ihre Warteschlange, die groß genug bemessen oder ganz ohne Obergrenze angelegt werden kann. Das Schreiben in die Warteschlange wird üblicherweise schnell angenommen, auch wenn du in deinem Code vorsichtshalber wahrscheinlich die Ausnahme queue.Full abfangen musst. Bist du Bibliotheksentwickler und hast geschwindigkeitskritische Threads in deinem Code, dann dokumentiere das unbedingt (zusammen mit der Empfehlung, an deine Logger nur QueueHandlers zu hängen), damit andere Entwickler, die deinen Code verwenden, davon profitieren.
Der zweite Teil der Lösung ist QueueListener, der als Gegenstück zu QueueHandler entworfen wurde. Ein QueueListener ist sehr einfach: Ihm werden eine Warteschlange und einige Handler übergeben, und er startet einen internen Thread, der an seiner Warteschlange auf LogRecords lauscht, die von QueueHandlers gesendet werden (oder, was das betrifft, von jeder anderen Quelle von LogRecords). Die LogRecords werden aus der Warteschlange genommen und zur Verarbeitung an die Handler übergeben.
Der Vorteil einer eigenen Klasse QueueListener ist, dass du dieselbe Instanz für mehrere QueueHandlers nutzen kannst. Das ist ressourcenschonender als etwa Thread-Varianten der bestehenden Handler-Klassen, die ohne besonderen Nutzen einen Thread je Handler verbrauchen würden.
Ein Beispiel für die Verwendung dieser beiden Klassen folgt (Importe weggelassen):
que = queue.Queue(-1) # no limit on size
queue_handler = QueueHandler(que)
handler = logging.StreamHandler()
listener = QueueListener(que, handler)
root = logging.getLogger()
root.addHandler(queue_handler)
formatter = logging.Formatter('%(threadName)s: %(message)s')
handler.setFormatter(formatter)
listener.start()
# The log output will display the thread which generated
# the event (the main thread) rather than the internal
# thread which monitors the internal queue. This is what
# you want to happen.
root.warning('Look out!')
listener.stop()
was beim Ausführen Folgendes ergibt:
MainThread: Look out!
Bemerkung
Die obige Erörterung sprach nicht ausdrücklich von asynchronem Code, sondern von langsamen Protokollierungs-Handlern. Dennoch sei angemerkt, dass beim Protokollieren aus asynchronem Code Netz- und sogar Datei-Handler zu Problemen führen können (sie blockieren die Ereignisschleife), weil ein Teil der Protokollierung aus den Interna von asyncio erfolgt. Wird in einer Anwendung asynchroner Code verwendet, ist es vermutlich am besten, für die Protokollierung den oben beschriebenen Ansatz zu nehmen, damit blockierender Code nur im Thread des QueueListener läuft.
Geändert in Version 3.5: Vor Python 3.5 gab QueueListener jede aus der Warteschlange empfangene Meldung immer an jeden Handler weiter, mit dem er angelegt worden war. (Das lag daran, dass man annahm, die Filterung nach Schweregrad finde vollständig auf der anderen Seite statt, wo die Warteschlange gefüllt wird.) Ab 3.5 lässt sich dieses Verhalten ändern, indem dem Konstruktor des Listeners das Schlüsselwortargument respect_handler_level=True übergeben wird. Dann vergleicht der Listener den Schweregrad jeder Meldung mit dem des Handlers und gibt eine Meldung nur dann an einen Handler weiter, wenn es angemessen ist.
Geändert in Version 3.14: QueueListener lässt sich über die with-Anweisung starten (und stoppen). Zum Beispiel:
with QueueListener(que, handler) as listener:
# The queue listener automatically starts
# when the 'with' block is entered.
pass
# The queue listener automatically stops once
# the 'with' block is exited.
Protokollierungsereignisse über ein Netz senden und empfangen¶
Nehmen wir an, du willst Protokollierungsereignisse über ein Netz senden und am Empfangsende verarbeiten. Ein einfacher Weg dazu ist, am Sendeende eine Instanz von SocketHandler an den Wurzel-Logger zu hängen:
import logging, logging.handlers
rootLogger = logging.getLogger()
rootLogger.setLevel(logging.DEBUG)
socketHandler = logging.handlers.SocketHandler('localhost',
logging.handlers.DEFAULT_TCP_LOGGING_PORT)
# don't bother with a formatter, since a socket handler sends the event as
# an unformatted pickle
rootLogger.addHandler(socketHandler)
# Now, we can log to the root logger, or any other logger. First the root...
logging.info('Jackdaws love my big sphinx of quartz.')
# Now, define a couple of other loggers which might represent areas in your
# application:
logger1 = logging.getLogger('myapp.area1')
logger2 = logging.getLogger('myapp.area2')
logger1.debug('Quick zephyrs blow, vexing daft Jim.')
logger1.info('How quickly daft jumping zebras vex.')
logger2.warning('Jail zesty vixen who grabbed pay from quack.')
logger2.error('The five boxing wizards jump quickly.')
Am Empfangsende kannst du mit dem Modul socketserver einen Empfänger einrichten. Hier ein einfaches, funktionierendes Beispiel:
import pickle
import logging
import logging.handlers
import socketserver
import struct
class LogRecordStreamHandler(socketserver.StreamRequestHandler):
"""Handler for a streaming logging request.
This basically logs the record using whatever logging policy is
configured locally.
"""
def handle(self):
"""
Handle multiple requests - each expected to be a 4-byte length,
followed by the LogRecord in pickle format. Logs the record
according to whatever policy is configured locally.
"""
while True:
chunk = self.connection.recv(4)
if len(chunk) < 4:
break
slen = struct.unpack('>L', chunk)[0]
chunk = self.connection.recv(slen)
while len(chunk) < slen:
chunk = chunk + self.connection.recv(slen - len(chunk))
obj = self.unPickle(chunk)
record = logging.makeLogRecord(obj)
self.handleLogRecord(record)
def unPickle(self, data):
return pickle.loads(data)
def handleLogRecord(self, record):
# if a name is specified, we use the named logger rather than the one
# implied by the record.
if self.server.logname is not None:
name = self.server.logname
else:
name = record.name
logger = logging.getLogger(name)
# N.B. EVERY record gets logged. This is because Logger.handle
# is normally called AFTER logger-level filtering. If you want
# to do filtering, do it at the client end to save wasting
# cycles and network bandwidth!
logger.handle(record)
class LogRecordSocketReceiver(socketserver.ThreadingTCPServer):
"""
Simple TCP socket-based logging receiver suitable for testing.
"""
allow_reuse_address = True
def __init__(self, host='localhost',
port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,
handler=LogRecordStreamHandler):
socketserver.ThreadingTCPServer.__init__(self, (host, port), handler)
self.abort = 0
self.timeout = 1
self.logname = None
def serve_until_stopped(self):
import select
abort = 0
while not abort:
rd, wr, ex = select.select([self.socket.fileno()],
[], [],
self.timeout)
if rd:
self.handle_request()
abort = self.abort
def main():
logging.basicConfig(
format='%(relativeCreated)5d %(name)-15s %(levelname)-8s %(message)s')
tcpserver = LogRecordSocketReceiver()
print('About to start TCP server...')
tcpserver.serve_until_stopped()
if __name__ == '__main__':
main()
Starte zuerst den Server, dann den Client. Auf der Client-Seite wird nichts auf der Konsole ausgegeben. Auf der Server-Seite solltest du etwa Folgendes sehen:
About to start TCP server...
59 root INFO Jackdaws love my big sphinx of quartz.
59 myapp.area1 DEBUG Quick zephyrs blow, vexing daft Jim.
69 myapp.area1 INFO How quickly daft jumping zebras vex.
69 myapp.area2 WARNING Jail zesty vixen who grabbed pay from quack.
69 myapp.area2 ERROR The five boxing wizards jump quickly.
Beachte, dass es in manchen Fällen Sicherheitsprobleme mit pickle gibt. Betreffen die dich, kannst du ein anderes Serialisierungsverfahren verwenden. Überschreibe dazu die Methode makePickle(), setze dein Verfahren dort um und passe das obige Skript entsprechend an.
Einen Socket-Listener für die Protokollierung im Produktivbetrieb laufen lassen¶
Um einen Listener für die Protokollierung im Produktivbetrieb laufen zu lassen, brauchst du möglicherweise ein Werkzeug zur Prozessverwaltung wie Supervisor. Hier ist ein Gist mit den nötigsten Dateien, um die obige Funktionalität mit Supervisor zu betreiben. Es besteht aus den folgenden Dateien:
Datei |
Zweck |
|---|---|
|
Ein Bash-Skript, das die Umgebung für Tests vorbereitet |
|
Die Konfigurationsdatei von Supervisor mit Einträgen für den Listener und eine Webanwendung mit mehreren Prozessen |
|
Ein Bash-Skript, das sicherstellt, dass Supervisor mit der obigen Konfiguration läuft |
|
Das Socket-Listener-Programm, das Protokollierungsereignisse empfängt und in eine Datei schreibt |
|
Eine einfache Webanwendung, die über ein mit dem Listener verbundenes Socket protokolliert |
|
Eine JSON-Konfigurationsdatei für die Webanwendung |
|
Ein Python-Skript, das die Webanwendung auf Trab bringt |
Die Webanwendung verwendet Gunicorn, einen verbreiteten Anwendungsserver für Webanwendungen, der mehrere Arbeiterprozesse startet, um Anfragen zu bearbeiten. Dieser Beispielaufbau zeigt, wie die Arbeiter in dieselbe Protokolldatei schreiben können, ohne sich gegenseitig in die Quere zu kommen — sie gehen alle über den Socket-Listener.
Um diese Dateien zu testen, gehe in einer POSIX-Umgebung so vor:
Lade das Gist über die Schaltfläche Download ZIP als ZIP-Archiv herunter.
Entpacke die obigen Dateien aus dem Archiv in ein Arbeitsverzeichnis.
Führe im Arbeitsverzeichnis
bash prepare.shaus, um alles vorzubereiten. Das erzeugt ein Unterverzeichnisrunfür die Supervisor- und Protokolldateien sowie ein Unterverzeichnisvenvfür eine virtuelle Umgebung, in diebottle,gunicornundsupervisorinstalliert werden.Führe
bash ensure_app.shaus, um sicherzustellen, dass Supervisor mit der obigen Konfiguration läuft.Führe
venv/bin/python client.pyaus, um die Webanwendung auf Trab zu bringen. Dadurch werden Datensätze ins Protokoll geschrieben.Sieh dir die Protokolldateien im Unterverzeichnis
runan. Die neuesten Protokollzeilen solltest du in Dateien finden, die auf das Musterapp.log*passen. Sie stehen in keiner bestimmten Reihenfolge, weil sie von verschiedenen Arbeiterprozessen nebenläufig und nicht deterministisch verarbeitet wurden.Den Listener und die Webanwendung fährst du mit
venv/bin/supervisorctl -c supervisor.conf shutdownherunter.
In dem unwahrscheinlichen Fall, dass die konfigurierten Ports mit etwas anderem in deiner Testumgebung kollidieren, musst du die Konfigurationsdateien anpassen.
Die Standardkonfiguration verwendet ein TCP-Socket auf Port 9020. Statt eines TCP-Sockets kannst du folgendermaßen ein Unix-Domain-Socket verwenden:
Ergänze in
listener.jsoneinen Schlüsselsocketmit dem Pfad zum gewünschten Domain-Socket. Ist dieser Schlüssel vorhanden, lauscht der Listener am entsprechenden Domain-Socket und nicht an einem TCP-Socket (der Schlüsselportwird ignoriert).Ändere in
webapp.jsondas Konfigurations-Dictionary des Socket-Handlers so, dass der Wert vonhostder Pfad zum Domain-Socket ist, und setze den Wert vonportaufnull.
Kontextinformationen zu deiner Protokollausgabe hinzufügen¶
Manchmal soll die Protokollausgabe neben den Parametern, die dem Protokollierungsaufruf übergeben werden, auch Kontextinformationen enthalten. In einer vernetzten Anwendung kann es zum Beispiel wünschenswert sein, client-spezifische Informationen ins Protokoll zu schreiben (etwa den Benutzernamen oder die IP-Adresse des entfernten Clients). Du könntest das zwar über den Parameter extra erreichen, aber es ist nicht immer bequem, die Informationen auf diesem Weg zu übergeben. Es mag verlockend sein, Logger-Instanzen je Verbindung zu erzeugen, aber das ist keine gute Idee, denn diese Instanzen werden nicht von der Speicherbereinigung erfasst. In der Praxis ist das kein Problem, solange die Anzahl der Logger-Instanzen von der gewünschten Feinheit der Protokollierung einer Anwendung abhängt. Wird die Anzahl der Logger-Instanzen aber praktisch unbegrenzt, kann es schwer zu handhaben werden.
Mit LoggerAdapter Kontextinformationen mitgeben¶
Ein einfacher Weg, Kontextinformationen zu übergeben, die zusammen mit den Informationen zum Protokollierungsereignis ausgegeben werden, ist die Klasse LoggerAdapter. Diese Klasse ist so entworfen, dass sie wie ein Logger aussieht, du kannst also debug(), info(), warning(), error(), exception(), critical() und log() aufrufen. Diese Methoden haben dieselben Signaturen wie ihre Gegenstücke in Logger, du kannst die beiden Arten von Instanzen also austauschbar verwenden.
Wenn du eine Instanz von LoggerAdapter erzeugst, übergibst du ihr eine Logger-Instanz und ein dict-artiges Objekt mit deinen Kontextinformationen. Rufst du eine der Protokollierungsmethoden an einer Instanz von LoggerAdapter auf, gibt sie den Aufruf an die zugrunde liegende Logger-Instanz weiter, die ihrem Konstruktor übergeben wurde, und sorgt dafür, dass die Kontextinformationen im weitergegebenen Aufruf mitkommen. Hier ein Ausschnitt aus dem Code von LoggerAdapter:
def debug(self, msg, /, *args, **kwargs):
"""
Delegate a debug call to the underlying logger, after adding
contextual information from this adapter instance.
"""
msg, kwargs = self.process(msg, kwargs)
self.logger.debug(msg, *args, **kwargs)
In der Methode process() von LoggerAdapter werden die Kontextinformationen zur Protokollausgabe hinzugefügt. Ihr werden die Meldung und die Schlüsselwortargumente des Protokollierungsaufrufs übergeben, und sie gibt (möglicherweise) veränderte Fassungen davon zurück, die im Aufruf des zugrunde liegenden Loggers verwendet werden. Die Standardumsetzung dieser Methode lässt die Meldung unangetastet, fügt aber in den Schlüsselwortargumenten einen Schlüssel „extra“ ein, dessen Wert das dem Konstruktor übergebene dict-artige Objekt ist. Hattest du im Aufruf des Adapters natürlich selbst ein Schlüsselwortargument „extra“ übergeben, wird es stillschweigend überschrieben.
Der Vorteil von „extra“ ist, dass die Werte im dict-artigen Objekt in das __dict__ der LogRecord-Instanz übernommen werden. Damit kannst du in deinen Formatter-Instanzen eigene Zeichenketten verwenden, die die Schlüssel des dict-artigen Objekts kennen. Brauchst du ein anderes Vorgehen, willst du etwa die Kontextinformationen der Meldungszeichenkette voranstellen oder anhängen, dann musst du nur eine Unterklasse von LoggerAdapter bilden und process() so überschreiben, dass sie tut, was du brauchst. Hier ein einfaches Beispiel:
class CustomAdapter(logging.LoggerAdapter):
"""
This example adapter expects the passed in dict-like object to have a
'connid' key, whose value in brackets is prepended to the log message.
"""
def process(self, msg, kwargs):
return '[%s] %s' % (self.extra['connid'], msg), kwargs
das du so verwenden kannst:
logger = logging.getLogger(__name__)
adapter = CustomAdapter(logger, {'connid': some_conn_id})
Alle Ereignisse, die du dann über den Adapter protokollierst, haben den Wert von some_conn_id vor der Protokollmeldung stehen.
Andere Objekte als Dictionarys verwenden, um Kontextinformationen zu übergeben¶
Du musst einem LoggerAdapter kein echtes Dictionary übergeben – du könntest eine Instanz einer Klasse übergeben, die __getitem__ und __iter__ umsetzt, sodass sie für die Protokollierung wie ein Dictionary aussieht. Das ist nützlich, wenn du Werte dynamisch erzeugen willst (während die Werte in einem Dictionary feststehen würden).
Mit Filtern Kontextinformationen mitgeben¶
Du kannst Kontextinformationen auch mit einem selbst festgelegten Filter zur Protokollausgabe hinzufügen. Filter-Instanzen dürfen die ihnen übergebenen LogRecords verändern, also auch zusätzliche Attribute ergänzen, die sich dann über eine passende Formatzeichenkette oder, falls nötig, über einen eigenen Formatter ausgeben lassen.
In einer Webanwendung lässt sich zum Beispiel die gerade bearbeitete Anfrage (oder mindestens deren interessante Teile) in einer thread-lokalen Variablen (threading.local) ablegen und dann aus einem Filter heraus darauf zugreifen, um etwa Informationen aus der Anfrage – sagen wir die entfernte IP-Adresse und den Benutzernamen des entfernten Benutzers – mit den Attributnamen „ip“ und „user“ zum LogRecord hinzuzufügen, wie im obigen LoggerAdapter-Beispiel. In diesem Fall lässt sich dieselbe Formatzeichenkette verwenden, um eine ähnliche Ausgabe wie oben zu erhalten. Hier ein Beispielskript:
import logging
from random import choice
class ContextFilter(logging.Filter):
"""
This is a filter which injects contextual information into the log.
Rather than use actual contextual information, we just use random
data in this demo.
"""
USERS = ['jim', 'fred', 'sheila']
IPS = ['123.231.231.123', '127.0.0.1', '192.168.0.1']
def filter(self, record):
record.ip = choice(ContextFilter.IPS)
record.user = choice(ContextFilter.USERS)
return True
if __name__ == '__main__':
levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)
logging.basicConfig(level=logging.DEBUG,
format='%(asctime)-15s %(name)-5s %(levelname)-8s IP: %(ip)-15s User: %(user)-8s %(message)s')
a1 = logging.getLogger('a.b.c')
a2 = logging.getLogger('d.e.f')
f = ContextFilter()
a1.addFilter(f)
a2.addFilter(f)
a1.debug('A debug message')
a1.info('An info message with %s', 'some parameters')
for x in range(10):
lvl = choice(levels)
lvlname = logging.getLevelName(lvl)
a2.log(lvl, 'A message at %s level with %d %s', lvlname, 2, 'parameters')
was beim Ausführen etwa Folgendes ergibt:
2010-09-06 22:38:15,292 a.b.c DEBUG IP: 123.231.231.123 User: fred A debug message
2010-09-06 22:38:15,300 a.b.c INFO IP: 192.168.0.1 User: sheila An info message with some parameters
2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1 User: sheila A message at CRITICAL level with 2 parameters
2010-09-06 22:38:15,300 d.e.f ERROR IP: 127.0.0.1 User: jim A message at ERROR level with 2 parameters
2010-09-06 22:38:15,300 d.e.f DEBUG IP: 127.0.0.1 User: sheila A message at DEBUG level with 2 parameters
2010-09-06 22:38:15,300 d.e.f ERROR IP: 123.231.231.123 User: fred A message at ERROR level with 2 parameters
2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 192.168.0.1 User: jim A message at CRITICAL level with 2 parameters
2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1 User: sheila A message at CRITICAL level with 2 parameters
2010-09-06 22:38:15,300 d.e.f DEBUG IP: 192.168.0.1 User: jim A message at DEBUG level with 2 parameters
2010-09-06 22:38:15,301 d.e.f ERROR IP: 127.0.0.1 User: sheila A message at ERROR level with 2 parameters
2010-09-06 22:38:15,301 d.e.f DEBUG IP: 123.231.231.123 User: fred A message at DEBUG level with 2 parameters
2010-09-06 22:38:15,301 d.e.f INFO IP: 123.231.231.123 User: fred A message at INFO level with 2 parameters
Verwendung von contextvars¶
Seit Python 3.7 bietet das Modul contextvars einen kontextlokalen Speicher, der sowohl für Verarbeitung mit threading als auch mit asyncio funktioniert. Diese Art Speicher ist thread-lokalen Variablen daher allgemein vorzuziehen. Das folgende Beispiel zeigt, wie sich Protokolle in einer Umgebung mit mehreren Threads mit Kontextinformationen füllen lassen, etwa mit Attributen von Anfragen, die Webanwendungen bearbeiten.
Nehmen wir zur Veranschaulichung an, du hast verschiedene Webanwendungen, jede unabhängig von der anderen, die aber im selben Python-Prozess laufen und eine gemeinsame Bibliothek verwenden. Wie kann jede dieser Anwendungen ihr eigenes Protokoll haben, in dem alle Protokollmeldungen aus der Bibliothek (und aus dem übrigen Code zur Anfragebearbeitung) in die Protokolldatei der jeweiligen Anwendung gelenkt werden und zugleich zusätzliche Kontextinformationen wie Client-IP, HTTP-Anfragemethode und Client-Benutzername im Protokoll stehen?
Nehmen wir an, die Bibliothek lässt sich durch folgenden Code nachbilden:
# webapplib.py
import logging
import time
logger = logging.getLogger(__name__)
def useful():
# Just a representative event logged from the library
logger.debug('Hello from webapplib!')
# Just sleep for a bit so other threads get to run
time.sleep(0.01)
Die mehreren Webanwendungen können wir mit zwei einfachen Klassen nachbilden, Request und WebApp. Die bilden nach, wie echte Webanwendungen mit Threads arbeiten – jede Anfrage wird von einem Thread bearbeitet:
# main.py
import argparse
from contextvars import ContextVar
import logging
import os
from random import choice
import threading
import webapplib
logger = logging.getLogger(__name__)
root = logging.getLogger()
root.setLevel(logging.DEBUG)
class Request:
"""
A simple dummy request class which just holds dummy HTTP request method,
client IP address and client username
"""
def __init__(self, method, ip, user):
self.method = method
self.ip = ip
self.user = user
# A dummy set of requests which will be used in the simulation - we'll just pick
# from this list randomly. Note that all GET requests are from 192.168.2.XXX
# addresses, whereas POST requests are from 192.16.3.XXX addresses. Three users
# are represented in the sample requests.
REQUESTS = [
Request('GET', '192.168.2.20', 'jim'),
Request('POST', '192.168.3.20', 'fred'),
Request('GET', '192.168.2.21', 'sheila'),
Request('POST', '192.168.3.21', 'jim'),
Request('GET', '192.168.2.22', 'fred'),
Request('POST', '192.168.3.22', 'sheila'),
]
# Note that the format string includes references to request context information
# such as HTTP method, client IP and username
formatter = logging.Formatter('%(threadName)-11s %(appName)s %(name)-9s %(user)-6s %(ip)s %(method)-4s %(message)s')
# Create our context variables. These will be filled at the start of request
# processing, and used in the logging that happens during that processing
ctx_request = ContextVar('request')
ctx_appname = ContextVar('appname')
class InjectingFilter(logging.Filter):
"""
A filter which injects context-specific information into logs and ensures
that only information for a specific webapp is included in its log
"""
def __init__(self, app):
self.app = app
def filter(self, record):
request = ctx_request.get()
record.method = request.method
record.ip = request.ip
record.user = request.user
record.appName = appName = ctx_appname.get()
return appName == self.app.name
class WebApp:
"""
A dummy web application class which has its own handler and filter for a
webapp-specific log.
"""
def __init__(self, name):
self.name = name
handler = logging.FileHandler(name + '.log', 'w')
f = InjectingFilter(self)
handler.setFormatter(formatter)
handler.addFilter(f)
root.addHandler(handler)
self.num_requests = 0
def process_request(self, request):
"""
This is the dummy method for processing a request. It's called on a
different thread for every request. We store the context information into
the context vars before doing anything else.
"""
ctx_request.set(request)
ctx_appname.set(self.name)
self.num_requests += 1
logger.debug('Request processing started')
webapplib.useful()
logger.debug('Request processing finished')
def main():
fn = os.path.splitext(os.path.basename(__file__))[0]
adhf = argparse.ArgumentDefaultsHelpFormatter
ap = argparse.ArgumentParser(formatter_class=adhf, prog=fn,
description='Simulate a couple of web '
'applications handling some '
'requests, showing how request '
'context can be used to '
'populate logs')
aa = ap.add_argument
aa('--count', '-c', type=int, default=100, help='How many requests to simulate')
options = ap.parse_args()
# Create the dummy webapps and put them in a list which we can use to select
# from randomly
app1 = WebApp('app1')
app2 = WebApp('app2')
apps = [app1, app2]
threads = []
# Add a common handler which will capture all events
handler = logging.FileHandler('app.log', 'w')
handler.setFormatter(formatter)
root.addHandler(handler)
# Generate calls to process requests
for i in range(options.count):
try:
# Pick an app at random and a request for it to process
app = choice(apps)
request = choice(REQUESTS)
# Process the request in its own thread
t = threading.Thread(target=app.process_request, args=(request,))
threads.append(t)
t.start()
except KeyboardInterrupt:
break
# Wait for the threads to terminate
for t in threads:
t.join()
for app in apps:
print('%s processed %s requests' % (app.name, app.num_requests))
if __name__ == '__main__':
main()
Führst du das Obige aus, solltest du feststellen, dass etwa die Hälfte der Anfragen in app1.log landet und der Rest in app2.log, und dass alle Anfragen in app.log protokolliert werden. Jedes anwendungsspezifische Protokoll enthält nur Einträge dieser einen Webanwendung, und die Informationen zur Anfrage werden im Protokoll einheitlich angezeigt (die Informationen jeder Pseudo-Anfrage erscheinen also immer gemeinsam in einer Protokollzeile). Das zeigt die folgende Shell-Ausgabe:
~/logging-contextual-webapp$ python main.py
app1 processed 51 requests
app2 processed 49 requests
~/logging-contextual-webapp$ wc -l *.log
153 app1.log
147 app2.log
300 app.log
600 total
~/logging-contextual-webapp$ head -3 app1.log
Thread-3 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started
Thread-3 (process_request) app1 webapplib jim 192.168.3.21 POST Hello from webapplib!
Thread-5 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started
~/logging-contextual-webapp$ head -3 app2.log
Thread-1 (process_request) app2 __main__ sheila 192.168.2.21 GET Request processing started
Thread-1 (process_request) app2 webapplib sheila 192.168.2.21 GET Hello from webapplib!
Thread-2 (process_request) app2 __main__ jim 192.168.2.20 GET Request processing started
~/logging-contextual-webapp$ head app.log
Thread-1 (process_request) app2 __main__ sheila 192.168.2.21 GET Request processing started
Thread-1 (process_request) app2 webapplib sheila 192.168.2.21 GET Hello from webapplib!
Thread-2 (process_request) app2 __main__ jim 192.168.2.20 GET Request processing started
Thread-3 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started
Thread-2 (process_request) app2 webapplib jim 192.168.2.20 GET Hello from webapplib!
Thread-3 (process_request) app1 webapplib jim 192.168.3.21 POST Hello from webapplib!
Thread-4 (process_request) app2 __main__ fred 192.168.2.22 GET Request processing started
Thread-5 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started
Thread-4 (process_request) app2 webapplib fred 192.168.2.22 GET Hello from webapplib!
Thread-6 (process_request) app1 __main__ jim 192.168.3.21 POST Request processing started
~/logging-contextual-webapp$ grep app1 app1.log | wc -l
153
~/logging-contextual-webapp$ grep app2 app2.log | wc -l
147
~/logging-contextual-webapp$ grep app1 app.log | wc -l
153
~/logging-contextual-webapp$ grep app2 app.log | wc -l
147
Kontextinformationen in Handlern mitgeben¶
Jeder Handler hat seine eigene Kette von Filtern. Willst du Kontextinformationen zu einem LogRecord hinzufügen, ohne dass sie zu anderen Handlern durchsickern, kannst du einen Filter verwenden, der einen neuen LogRecord zurückgibt statt ihn an seinem Platz zu verändern, wie das folgende Skript zeigt:
import copy
import logging
def filter(record: logging.LogRecord):
record = copy.copy(record)
record.user = 'jim'
return record
if __name__ == '__main__':
logger = logging.getLogger()
logger.setLevel(logging.INFO)
handler = logging.StreamHandler()
formatter = logging.Formatter('%(message)s from %(user)-8s')
handler.setFormatter(formatter)
handler.addFilter(filter)
logger.addHandler(handler)
logger.info('A log message')
Aus mehreren Prozessen in eine einzige Datei protokollieren¶
Die Protokollierung ist zwar threadsicher, und das Protokollieren aus mehreren Threads eines Prozesses in eine einzige Datei wird unterstützt, das Protokollieren aus mehreren Prozessen in eine einzige Datei aber nicht, weil es in Python keinen Standardweg gibt, den Zugriff auf eine einzige Datei über mehrere Prozesse hinweg zu serialisieren. Musst du aus mehreren Prozessen in eine einzige Datei protokollieren, dann lässt sich das zum Beispiel so lösen, dass alle Prozesse in einen SocketHandler protokollieren und ein eigener Prozess einen Socket-Server umsetzt, der vom Socket liest und in die Datei protokolliert. (Wenn du magst, kannst du für diese Aufgabe auch einen Thread in einem der bestehenden Prozesse abstellen.) Dieser Abschnitt beschreibt diesen Ansatz ausführlicher und enthält einen funktionierenden Socket-Empfänger, den du als Ausgangspunkt für eigene Anwendungen anpassen kannst.
Du könntest auch einen eigenen Handler schreiben, der mit der Klasse Lock aus dem Modul multiprocessing den Zugriff deiner Prozesse auf die Datei serialisiert. FileHandler und seine Unterklassen aus der Standardbibliothek verwenden multiprocessing nicht.
Alternativ kannst du eine Queue und einen QueueHandler verwenden, um alle Protokollierungsereignisse an einen der Prozesse deiner Anwendung mit mehreren Prozessen zu senden. Das folgende Beispielskript zeigt, wie das geht. Im Beispiel lauscht ein eigener Listener-Prozess auf Ereignisse, die andere Prozesse senden, und protokolliert sie nach seiner eigenen Protokollierungskonfiguration. Das Beispiel zeigt zwar nur einen Weg (du willst vielleicht einen Listener-Thread statt eines eigenen Listener-Prozesses verwenden – die Umsetzung wäre entsprechend), es erlaubt aber völlig unterschiedliche Protokollierungskonfigurationen für den Listener und die übrigen Prozesse deiner Anwendung und lässt sich als Grundlage für Code nehmen, der deine eigenen Anforderungen erfüllt:
# You'll need these imports in your own code
import logging
import logging.handlers
import multiprocessing
# Next two import lines for this demo only
from random import choice, random
import time
#
# Because you'll want to define the logging configurations for listener and workers, the
# listener and worker process functions take a configurer parameter which is a callable
# for configuring logging for that process. These functions are also passed the queue,
# which they use for communication.
#
# In practice, you can configure the listener however you want, but note that in this
# simple example, the listener does not apply level or filter logic to received records.
# In practice, you would probably want to do this logic in the worker processes, to avoid
# sending events which would be filtered out between processes.
#
# The size of the rotated files is made small so you can see the results easily.
def listener_configurer():
root = logging.getLogger()
h = logging.handlers.RotatingFileHandler('mptest.log', 'a', 300, 10)
f = logging.Formatter('%(asctime)s %(processName)-10s %(name)s %(levelname)-8s %(message)s')
h.setFormatter(f)
root.addHandler(h)
# This is the listener process top-level loop: wait for logging events
# (LogRecords)on the queue and handle them, quit when you get a None for a
# LogRecord.
def listener_process(queue, configurer):
configurer()
while True:
try:
record = queue.get()
if record is None: # We send this as a sentinel to tell the listener to quit.
break
logger = logging.getLogger(record.name)
logger.handle(record) # No level or filter logic applied - just do it!
except Exception:
import sys, traceback
print('Whoops! Problem:', file=sys.stderr)
traceback.print_exc(file=sys.stderr)
# Arrays used for random selections in this demo
LEVELS = [logging.DEBUG, logging.INFO, logging.WARNING,
logging.ERROR, logging.CRITICAL]
LOGGERS = ['a.b.c', 'd.e.f']
MESSAGES = [
'Random message #1',
'Random message #2',
'Random message #3',
]
# The worker configuration is done at the start of the worker process run.
# Note that on Windows you can't rely on fork semantics, so each process
# will run the logging configuration code when it starts.
def worker_configurer(queue):
h = logging.handlers.QueueHandler(queue) # Just the one handler needed
root = logging.getLogger()
root.addHandler(h)
# send all messages, for demo; no other level or filter logic applied.
root.setLevel(logging.DEBUG)
# This is the worker process top-level loop, which just logs ten events with
# random intervening delays before terminating.
# The print messages are just so you know it's doing something!
def worker_process(queue, configurer):
configurer(queue)
name = multiprocessing.current_process().name
print('Worker started: %s' % name)
for i in range(10):
time.sleep(random())
logger = logging.getLogger(choice(LOGGERS))
level = choice(LEVELS)
message = choice(MESSAGES)
logger.log(level, message)
print('Worker finished: %s' % name)
# Here's where the demo gets orchestrated. Create the queue, create and start
# the listener, create ten workers and start them, wait for them to finish,
# then send a None to the queue to tell the listener to finish.
def main():
queue = multiprocessing.Queue(-1)
listener = multiprocessing.Process(target=listener_process,
args=(queue, listener_configurer))
listener.start()
workers = []
for i in range(10):
worker = multiprocessing.Process(target=worker_process,
args=(queue, worker_configurer))
workers.append(worker)
worker.start()
for w in workers:
w.join()
queue.put_nowait(None)
listener.join()
if __name__ == '__main__':
main()
Eine Abwandlung des obigen Skripts behält die Protokollierung im Hauptprozess, in einem eigenen Thread:
import logging
import logging.config
import logging.handlers
from multiprocessing import Process, Queue
import random
import threading
import time
def logger_thread(q):
while True:
record = q.get()
if record is None:
break
logger = logging.getLogger(record.name)
logger.handle(record)
def worker_process(q):
qh = logging.handlers.QueueHandler(q)
root = logging.getLogger()
root.setLevel(logging.DEBUG)
root.addHandler(qh)
levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,
logging.CRITICAL]
loggers = ['foo', 'foo.bar', 'foo.bar.baz',
'spam', 'spam.ham', 'spam.ham.eggs']
for i in range(100):
lvl = random.choice(levels)
logger = logging.getLogger(random.choice(loggers))
logger.log(lvl, 'Message no. %d', i)
if __name__ == '__main__':
q = Queue()
d = {
'version': 1,
'formatters': {
'detailed': {
'class': 'logging.Formatter',
'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'
}
},
'handlers': {
'console': {
'class': 'logging.StreamHandler',
'level': 'INFO',
},
'file': {
'class': 'logging.FileHandler',
'filename': 'mplog.log',
'mode': 'w',
'formatter': 'detailed',
},
'foofile': {
'class': 'logging.FileHandler',
'filename': 'mplog-foo.log',
'mode': 'w',
'formatter': 'detailed',
},
'errors': {
'class': 'logging.FileHandler',
'filename': 'mplog-errors.log',
'mode': 'w',
'level': 'ERROR',
'formatter': 'detailed',
},
},
'loggers': {
'foo': {
'handlers': ['foofile']
}
},
'root': {
'level': 'DEBUG',
'handlers': ['console', 'file', 'errors']
},
}
workers = []
for i in range(5):
wp = Process(target=worker_process, name='worker %d' % (i + 1), args=(q,))
workers.append(wp)
wp.start()
logging.config.dictConfig(d)
lp = threading.Thread(target=logger_thread, args=(q,))
lp.start()
# At this point, the main process could do some useful work of its own
# Once it's done that, it can wait for the workers to terminate...
for wp in workers:
wp.join()
# And now tell the logging thread to finish up, too
q.put(None)
lp.join()
Diese Abwandlung zeigt, wie du zum Beispiel eine Konfiguration für bestimmte Logger anwenden kannst – etwa hat der Logger foo einen besonderen Handler, der alle Ereignisse des Teilsystems foo in einer Datei mplog-foo.log ablegt. Die Protokollierungsmaschinerie im Hauptprozess nutzt das (auch wenn die Protokollierungsereignisse in den Arbeiterprozessen entstehen), um die Meldungen an die passenden Ziele zu lenken.
concurrent.futures.ProcessPoolExecutor verwenden¶
Willst du deine Arbeiterprozesse mit concurrent.futures.ProcessPoolExecutor starten, musst du die Warteschlange etwas anders anlegen. Statt
queue = multiprocessing.Queue(-1)
solltest du
queue = multiprocessing.Manager().Queue(-1) # also works with the examples above
verwenden, und die Erzeugung der Arbeiter ersetzt du dann von dieser Fassung:
workers = []
for i in range(10):
worker = multiprocessing.Process(target=worker_process,
args=(queue, worker_configurer))
workers.append(worker)
worker.start()
for w in workers:
w.join()
durch diese (und denkst daran, zuerst concurrent.futures zu importieren):
with concurrent.futures.ProcessPoolExecutor(max_workers=10) as executor:
for i in range(10):
executor.submit(worker_process, queue, worker_configurer)
Webanwendungen mit Gunicorn und uWSGI ausliefern¶
Lieferst du Webanwendungen mit Gunicorn oder uWSGI (oder Ähnlichem) aus, werden mehrere Arbeiterprozesse erzeugt, um Client-Anfragen zu bearbeiten. Vermeide es in solchen Umgebungen, dateibasierte Handler direkt in deiner Webanwendung zu erzeugen. Verwende stattdessen einen SocketHandler, um aus der Webanwendung an einen Listener in einem eigenen Prozess zu protokollieren. Das lässt sich mit einem Werkzeug zur Prozessverwaltung wie Supervisor einrichten – näheres unter Einen Socket-Listener für die Protokollierung im Produktivbetrieb laufen lassen.
Dateirotation verwenden¶
Manchmal willst du eine Protokolldatei bis zu einer bestimmten Größe wachsen lassen, dann eine neue Datei anlegen und in diese protokollieren. Vielleicht willst du eine bestimmte Anzahl dieser Dateien behalten und sie, sobald so viele angelegt wurden, rotieren, damit Anzahl und Größe der Dateien beide beschränkt bleiben. Für dieses Nutzungsmuster bietet das Paket logging einen RotatingFileHandler:
import glob
import logging
import logging.handlers
LOG_FILENAME = 'logging_rotatingfile_example.out'
# Set up a specific logger with our desired output level
my_logger = logging.getLogger('MyLogger')
my_logger.setLevel(logging.DEBUG)
# Add the log message handler to the logger
handler = logging.handlers.RotatingFileHandler(
LOG_FILENAME, maxBytes=20, backupCount=5)
my_logger.addHandler(handler)
# Log some messages
for i in range(20):
my_logger.debug('i = %d' % i)
# See what files are created
logfiles = glob.glob('%s*' % LOG_FILENAME)
for filename in logfiles:
print(filename)
Das Ergebnis sollten 6 einzelne Dateien sein, jede mit einem Teil der Protokollgeschichte der Anwendung:
logging_rotatingfile_example.out
logging_rotatingfile_example.out.1
logging_rotatingfile_example.out.2
logging_rotatingfile_example.out.3
logging_rotatingfile_example.out.4
logging_rotatingfile_example.out.5
Die jeweils aktuellste Datei ist immer logging_rotatingfile_example.out, und jedes Mal, wenn sie die Größengrenze erreicht, wird sie mit der Endung .1 umbenannt. Jede der vorhandenen Sicherungsdateien wird mit um eins erhöhter Endung umbenannt (.1 wird zu .2 und so weiter), und die Datei .6 wird gelöscht.
Dieses Beispiel setzt die Protokolllänge natürlich viel zu klein, um ein Extrem zu zeigen. Du würdest maxBytes auf einen angemessenen Wert setzen.
Andere Formatierungsstile verwenden¶
Als die Protokollierung in die Python-Standardbibliothek aufgenommen wurde, war die %-Formatierung die einzige Möglichkeit, Meldungen mit veränderlichem Inhalt zu formatieren. Seitdem hat Python zwei neue Formatierungsansätze erhalten: string.Template (hinzugekommen in Python 2.4) und str.format() (hinzugekommen in Python 2.6).
Die Protokollierung bietet (seit 3.2) bessere Unterstützung für diese beiden zusätzlichen Formatierungsstile. Die Klasse Formatter wurde um einen zusätzlichen, optionalen Schlüsselwortparameter namens style erweitert. Dessen Vorgabe ist '%', möglich sind aber auch die Werte '{' und '$', die den beiden anderen Formatierungsstilen entsprechen. Die Verträglichkeit mit früheren Versionen bleibt standardmäßig erhalten (wie zu erwarten), aber indem du einen style-Parameter ausdrücklich angibst, kannst du Formatzeichenketten verwenden, die mit str.format() oder string.Template arbeiten. Hier eine Beispielsitzung in der Konsole, die die Möglichkeiten zeigt:
>>> import logging
>>> root = logging.getLogger()
>>> root.setLevel(logging.DEBUG)
>>> handler = logging.StreamHandler()
>>> bf = logging.Formatter('{asctime} {name} {levelname:8s} {message}',
... style='{')
>>> handler.setFormatter(bf)
>>> root.addHandler(handler)
>>> logger = logging.getLogger('foo.bar')
>>> logger.debug('This is a DEBUG message')
2010-10-28 15:11:55,341 foo.bar DEBUG This is a DEBUG message
>>> logger.critical('This is a CRITICAL message')
2010-10-28 15:12:11,526 foo.bar CRITICAL This is a CRITICAL message
>>> df = logging.Formatter('$asctime $name ${levelname} $message',
... style='$')
>>> handler.setFormatter(df)
>>> logger.debug('This is a DEBUG message')
2010-10-28 15:13:06,924 foo.bar DEBUG This is a DEBUG message
>>> logger.critical('This is a CRITICAL message')
2010-10-28 15:13:11,494 foo.bar CRITICAL This is a CRITICAL message
>>>
Beachte, dass die Formatierung von Protokollmeldungen für die endgültige Ausgabe in die Protokolle völlig unabhängig davon ist, wie eine einzelne Protokollmeldung aufgebaut wird. Die kann weiterhin %-Formatierung verwenden, wie hier gezeigt:
>>> logger.error('This is an%s %s %s', 'other,', 'ERROR,', 'message')
2010-10-28 15:19:29,833 foo.bar ERROR This is another, ERROR, message
>>>
Protokollierungsaufrufe (logger.debug(), logger.info() und so weiter) nehmen für die eigentliche Protokollmeldung nur positionsbezogene Parameter; Schlüsselwortparameter dienen nur dazu, Optionen für die Behandlung des Protokollierungsaufrufs festzulegen (etwa der Schlüsselwortparameter exc_info, der anzeigt, dass Traceback-Informationen protokolliert werden sollen, oder der Schlüsselwortparameter extra, der zusätzliche Kontextinformationen für das Protokoll anzeigt). Du kannst Protokollierungsaufrufe also nicht unmittelbar in der Syntax von str.format() oder string.Template machen, weil das Paket logging intern %-Formatierung verwendet, um Formatzeichenkette und veränderliche Argumente zusammenzuführen. Daran ließe sich nichts ändern, ohne die Verträglichkeit mit früheren Versionen aufzugeben, denn alle Protokollierungsaufrufe im vorhandenen Code verwenden %-Formatzeichenketten.
Es gibt allerdings einen Weg, {}- und $-Formatierung zu nutzen, um deine einzelnen Protokollmeldungen aufzubauen. Denk daran, dass du als Formatzeichenkette einer Meldung ein beliebiges Objekt verwenden kannst und dass das Paket logging str() auf dieses Objekt anwendet, um die eigentliche Formatzeichenkette zu erhalten. Betrachte die folgenden zwei Klassen:
class BraceMessage:
def __init__(self, fmt, /, *args, **kwargs):
self.fmt = fmt
self.args = args
self.kwargs = kwargs
def __str__(self):
return self.fmt.format(*self.args, **self.kwargs)
class DollarMessage:
def __init__(self, fmt, /, **kwargs):
self.fmt = fmt
self.kwargs = kwargs
def __str__(self):
from string import Template
return Template(self.fmt).substitute(**self.kwargs)
Beide lassen sich anstelle einer Formatzeichenkette verwenden, sodass sich der eigentliche „Meldungs“-Teil, der in der formatierten Protokollausgabe anstelle von „%(message)s“, „{message}“ oder „$message“ erscheint, mit {}- oder $-Formatierung aufbauen lässt. Die Klassennamen jedes Mal zu schreiben, wenn du etwas protokollieren willst, ist etwas sperrig, aber durchaus erträglich, wenn du einen Alias wie __ verwendest (doppelter Unterstrich — nicht zu verwechseln mit _, dem einfachen Unterstrich, der als Synonym bzw. Alias für gettext.gettext() und Verwandte dient).
Die obigen Klassen sind nicht Teil von Python, lassen sich aber leicht in deinen eigenen Code kopieren. Sie lassen sich so verwenden (unter der Annahme, dass sie in einem Modul namens wherever deklariert sind):
>>> from wherever import BraceMessage as __
>>> print(__('Message with {0} {name}', 2, name='placeholders'))
Message with 2 placeholders
>>> class Point: pass
...
>>> p = Point()
>>> p.x = 0.5
>>> p.y = 0.5
>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})',
... point=p))
Message with coordinates: (0.50, 0.50)
>>> from wherever import DollarMessage as __
>>> print(__('Message with $num $what', num=2, what='placeholders'))
Message with 2 placeholders
>>>
Die obigen Beispiele verwenden print(), um die Arbeitsweise der Formatierung zu zeigen. Zum eigentlichen Protokollieren mit diesem Ansatz würdest du natürlich logger.debug() oder Ähnliches verwenden.
Festzuhalten ist, dass du mit diesem Ansatz keinen bedeutsamen Geschwindigkeitsnachteil hast: Die eigentliche Formatierung findet nicht beim Protokollierungsaufruf statt, sondern dann (und nur dann), wenn die protokollierte Meldung von einem Handler tatsächlich in ein Protokoll geschrieben werden soll. Das einzige leicht Ungewöhnliche, über das du stolpern könntest, ist, dass die Klammern um die Formatzeichenkette und die Argumente stehen, nicht nur um die Formatzeichenkette. Das liegt daran, dass die __-Schreibweise nur Zuckerguss für einen Konstruktoraufruf einer der Klassen XXXMessage ist.
Wenn du magst, kannst du mit einem LoggerAdapter eine ähnliche Wirkung wie oben erreichen, wie im folgenden Beispiel:
import logging
class Message:
def __init__(self, fmt, args):
self.fmt = fmt
self.args = args
def __str__(self):
return self.fmt.format(*self.args)
class StyleAdapter(logging.LoggerAdapter):
def log(self, level, msg, /, *args, stacklevel=1, **kwargs):
if self.isEnabledFor(level):
msg, kwargs = self.process(msg, kwargs)
self.logger.log(level, Message(msg, args), **kwargs,
stacklevel=stacklevel+1)
logger = StyleAdapter(logging.getLogger(__name__))
def main():
logger.debug('Hello, {}', 'world!')
if __name__ == '__main__':
logging.basicConfig(level=logging.DEBUG)
main()
Das obige Skript sollte die Meldung Hello, world! protokollieren, wenn es mit Python 3.8 oder neuer ausgeführt wird.
LogRecord anpassen¶
Jedes Protokollierungsereignis wird durch eine LogRecord-Instanz dargestellt. Wird ein Ereignis protokolliert und nicht durch den Schweregrad eines Loggers herausgefiltert, so wird ein LogRecord erzeugt, mit Informationen über das Ereignis gefüllt und dann an die Handler dieses Loggers übergeben (und an die seiner Vorfahren, bis einschließlich zu dem Logger, bei dem die weitere Weitergabe in der Hierarchie abgeschaltet ist). Vor Python 3.2 gab es nur zwei Stellen, an denen diese Erzeugung geschah:
Logger.makeRecord(), die im normalen Ablauf der Protokollierung eines Ereignisses aufgerufen wird. Sie riefLogRecordunmittelbar auf, um eine Instanz zu erzeugen.makeLogRecord(), die mit einem Dictionary aufgerufen wird, das Attribute enthält, die dem LogRecord hinzugefügt werden sollen. Das wird üblicherweise aufgerufen, wenn ein passendes Dictionary über das Netz empfangen wurde (etwa in pickle-Form über einenSocketHandleroder in JSON-Form über einenHTTPHandler).
Das bedeutete meist, dass du eines der Folgenden tun musstest, wenn du mit einem LogRecord etwas Besonderes vorhattest.
Eine eigene Unterklasse von
Loggeranlegen, dieLogger.makeRecord()überschreibt, und sie mitsetLoggerClass()setzen, bevor irgendeiner der Logger, um die es dir geht, angelegt wird.Einem Logger oder Handler einen
Filterhinzufügen, der beim Aufruf seiner Methodefilter()die nötige besondere Bearbeitung vornimmt.
Der erste Ansatz wäre etwas sperrig in dem Fall, dass (sagen wir) mehrere verschiedene Bibliotheken Unterschiedliches vorhaben. Jede würde versuchen, ihre eigene Unterklasse von Logger zu setzen, und die, die das zuletzt täte, würde gewinnen.
Der zweite Ansatz funktioniert in vielen Fällen recht gut, erlaubt dir aber zum Beispiel nicht, eine besondere Unterklasse von LogRecord zu verwenden. Bibliotheksentwickler können einen passenden Filter an ihren Loggern setzen, müssten aber daran denken, das jedes Mal zu tun, wenn sie einen neuen Logger einführen (was sie schon dadurch tun, dass sie neue Pakete oder Module hinzufügen und
logger = logging.getLogger(__name__)
auf Modulebene schreiben). Das ist vermutlich eine Sache zu viel, an die man denken muss. Entwickler könnten den Filter auch einem NullHandler hinzufügen, der an ihrem obersten Logger hängt, aber der würde nicht aufgerufen, wenn ein Anwendungsentwickler einen Handler an einen tieferliegenden Bibliotheks-Logger hängt — die Ausgabe dieses Handlers würde dann also nicht die Absichten des Bibliotheksentwicklers widerspiegeln.
In Python 3.2 und neuer geschieht die Erzeugung von LogRecord über eine Factory, die du angeben kannst. Die Factory ist einfach ein aufrufbares Objekt, das du mit setLogRecordFactory() setzen und mit getLogRecordFactory() abfragen kannst. Die Factory wird mit derselben Signatur wie der Konstruktor von LogRecord aufgerufen, denn LogRecord ist die Standardeinstellung für die Factory.
Dieser Ansatz erlaubt einer eigenen Factory, alle Aspekte der Erzeugung eines LogRecord zu steuern. Du könntest zum Beispiel eine Unterklasse zurückgeben oder dem erzeugten Datensatz einfach einige zusätzliche Attribute hinzufügen, nach einem Muster wie diesem:
old_factory = logging.getLogRecordFactory()
def record_factory(*args, **kwargs):
record = old_factory(*args, **kwargs)
record.custom_attribute = 0xdecafbad
return record
logging.setLogRecordFactory(record_factory)
Dieses Muster erlaubt verschiedenen Bibliotheken, Factorys aneinanderzuketten, und solange sie nicht die Attribute der jeweils anderen oder versehentlich die standardmäßig vorhandenen Attribute überschreiben, sollte es keine Überraschungen geben. Allerdings ist zu bedenken, dass jedes Glied der Kette allen Protokollierungsoperationen Laufzeitaufwand hinzufügt. Die Technik sollte nur dann eingesetzt werden, wenn ein Filter nicht das gewünschte Ergebnis liefert.
Unterklassen von QueueHandler und QueueListener bilden – ein ZeroMQ-Beispiel¶
Unterklasse von QueueHandler¶
Mit einer Unterklasse von QueueHandler kannst du Meldungen an andere Arten von Warteschlangen senden, etwa an ein „publish“-Socket von ZeroMQ. Im Beispiel unten wird das Socket getrennt erzeugt und dem Handler (als seine „queue“) übergeben:
import zmq # using pyzmq, the Python binding for ZeroMQ
import json # for serializing records portably
ctx = zmq.Context()
sock = zmq.Socket(ctx, zmq.PUB) # or zmq.PUSH, or other suitable value
sock.bind('tcp://*:5556') # or wherever
class ZeroMQSocketHandler(QueueHandler):
def enqueue(self, record):
self.queue.send_json(record.__dict__)
handler = ZeroMQSocketHandler(sock)
Natürlich gibt es andere Wege, das zu gestalten, etwa indem die Daten übergeben werden, die der Handler zum Erzeugen des Sockets braucht:
class ZeroMQSocketHandler(QueueHandler):
def __init__(self, uri, socktype=zmq.PUB, ctx=None):
self.ctx = ctx or zmq.Context()
socket = zmq.Socket(self.ctx, socktype)
socket.bind(uri)
super().__init__(socket)
def enqueue(self, record):
self.queue.send_json(record.__dict__)
def close(self):
self.queue.close()
Unterklasse von QueueListener¶
Du kannst auch eine Unterklasse von QueueListener bilden, um Meldungen aus anderen Arten von Warteschlangen zu holen, etwa aus einem „subscribe“-Socket von ZeroMQ. Hier ein Beispiel:
class ZeroMQSocketListener(QueueListener):
def __init__(self, uri, /, *handlers, **kwargs):
self.ctx = kwargs.get('ctx') or zmq.Context()
socket = zmq.Socket(self.ctx, zmq.SUB)
socket.setsockopt_string(zmq.SUBSCRIBE, '') # subscribe to everything
socket.connect(uri)
super().__init__(socket, *handlers, **kwargs)
def dequeue(self):
msg = self.queue.recv_json()
return logging.makeLogRecord(msg)
Unterklassen von QueueHandler und QueueListener bilden – ein pynng-Beispiel¶
Ähnlich wie im obigen Abschnitt können wir einen Listener und einen Handler mit pynng umsetzen, einer Python-Anbindung an NNG, das als geistiger Nachfolger von ZeroMQ angekündigt wird. Die folgenden Ausschnitte zeigen das – du kannst sie in einer Umgebung testen, in der pynng installiert ist. Der Abwechslung halber stellen wir den Listener zuerst vor.
Unterklasse von QueueListener¶
# listener.py
import json
import logging
import logging.handlers
import pynng
DEFAULT_ADDR = "tcp://localhost:13232"
interrupted = False
class NNGSocketListener(logging.handlers.QueueListener):
def __init__(self, uri, /, *handlers, **kwargs):
# Have a timeout for interruptibility, and open a
# subscriber socket
socket = pynng.Sub0(listen=uri, recv_timeout=500)
# The b'' subscription matches all topics
topics = kwargs.pop('topics', None) or b''
socket.subscribe(topics)
# We treat the socket as a queue
super().__init__(socket, *handlers, **kwargs)
def dequeue(self, block):
data = None
# Keep looping while not interrupted and no data received over the
# socket
while not interrupted:
try:
data = self.queue.recv(block=block)
break
except pynng.Timeout:
pass
except pynng.Closed: # sometimes happens when you hit Ctrl-C
break
if data is None:
return None
# Get the logging event sent from a publisher
event = json.loads(data.decode('utf-8'))
return logging.makeLogRecord(event)
def enqueue_sentinel(self):
# Not used in this implementation, as the socket isn't really a
# queue
pass
logging.getLogger('pynng').propagate = False
listener = NNGSocketListener(DEFAULT_ADDR, logging.StreamHandler(), topics=b'')
listener.start()
print('Press Ctrl-C to stop.')
try:
while True:
pass
except KeyboardInterrupt:
interrupted = True
finally:
listener.stop()
Unterklasse von QueueHandler¶
# sender.py
import json
import logging
import logging.handlers
import time
import random
import pynng
DEFAULT_ADDR = "tcp://localhost:13232"
class NNGSocketHandler(logging.handlers.QueueHandler):
def __init__(self, uri):
socket = pynng.Pub0(dial=uri, send_timeout=500)
super().__init__(socket)
def enqueue(self, record):
# Send the record as UTF-8 encoded JSON
d = dict(record.__dict__)
data = json.dumps(d)
self.queue.send(data.encode('utf-8'))
def close(self):
self.queue.close()
logging.getLogger('pynng').propagate = False
handler = NNGSocketHandler(DEFAULT_ADDR)
# Make sure the process ID is in the output
logging.basicConfig(level=logging.DEBUG,
handlers=[logging.StreamHandler(), handler],
format='%(levelname)-8s %(name)10s %(process)6s %(message)s')
levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,
logging.CRITICAL)
logger_names = ('myapp', 'myapp.lib1', 'myapp.lib2')
msgno = 1
while True:
# Just randomly select some loggers and levels and log away
level = random.choice(levels)
logger = logging.getLogger(random.choice(logger_names))
logger.log(level, 'Message no. %5d' % msgno)
msgno += 1
delay = random.random() * 2 + 0.5
time.sleep(delay)
Du kannst die obigen zwei Ausschnitte in getrennten Befehlsfenstern ausführen. Lassen wir den Listener in einem Fenster laufen und den Sender in zwei weiteren Fenstern, sollten wir etwa Folgendes sehen. Im ersten Senderfenster:
$ python sender.py
DEBUG myapp 613 Message no. 1
WARNING myapp.lib2 613 Message no. 2
CRITICAL myapp.lib2 613 Message no. 3
WARNING myapp.lib2 613 Message no. 4
CRITICAL myapp.lib1 613 Message no. 5
DEBUG myapp 613 Message no. 6
CRITICAL myapp.lib1 613 Message no. 7
INFO myapp.lib1 613 Message no. 8
(and so on)
Im zweiten Senderfenster:
$ python sender.py
INFO myapp.lib2 657 Message no. 1
CRITICAL myapp.lib2 657 Message no. 2
CRITICAL myapp 657 Message no. 3
CRITICAL myapp.lib1 657 Message no. 4
INFO myapp.lib1 657 Message no. 5
WARNING myapp.lib2 657 Message no. 6
CRITICAL myapp 657 Message no. 7
DEBUG myapp.lib1 657 Message no. 8
(and so on)
Im Listener-Fenster:
$ python listener.py
Press Ctrl-C to stop.
DEBUG myapp 613 Message no. 1
WARNING myapp.lib2 613 Message no. 2
INFO myapp.lib2 657 Message no. 1
CRITICAL myapp.lib2 613 Message no. 3
CRITICAL myapp.lib2 657 Message no. 2
CRITICAL myapp 657 Message no. 3
WARNING myapp.lib2 613 Message no. 4
CRITICAL myapp.lib1 613 Message no. 5
CRITICAL myapp.lib1 657 Message no. 4
INFO myapp.lib1 657 Message no. 5
DEBUG myapp 613 Message no. 6
WARNING myapp.lib2 657 Message no. 6
CRITICAL myapp 657 Message no. 7
CRITICAL myapp.lib1 613 Message no. 7
INFO myapp.lib1 613 Message no. 8
DEBUG myapp.lib1 657 Message no. 8
(and so on)
Wie du siehst, ist die Protokollierung der beiden Senderprozesse in der Ausgabe des Listeners miteinander verschränkt.
Ein Beispiel für eine Dictionary-basierte Konfiguration¶
Unten ein Beispiel für ein Dictionary zur Protokollierungskonfiguration – es ist der Dokumentation des Django-Projekts entnommen. Dieses Dictionary wird dictConfig() übergeben, um die Konfiguration wirksam zu machen:
LOGGING = {
'version': 1,
'disable_existing_loggers': False,
'formatters': {
'verbose': {
'format': '{levelname} {asctime} {module} {process:d} {thread:d} {message}',
'style': '{',
},
'simple': {
'format': '{levelname} {message}',
'style': '{',
},
},
'filters': {
'special': {
'()': 'project.logging.SpecialFilter',
'foo': 'bar',
},
},
'handlers': {
'console': {
'level': 'INFO',
'class': 'logging.StreamHandler',
'formatter': 'simple',
},
'mail_admins': {
'level': 'ERROR',
'class': 'django.utils.log.AdminEmailHandler',
'filters': ['special']
}
},
'loggers': {
'django': {
'handlers': ['console'],
'propagate': True,
},
'django.request': {
'handlers': ['mail_admins'],
'level': 'ERROR',
'propagate': False,
},
'myproject.custom': {
'handlers': ['console', 'mail_admins'],
'level': 'INFO',
'filters': ['special']
}
}
}
Mehr Informationen zu dieser Konfiguration findest du im entsprechenden Abschnitt der Django-Dokumentation.
Mit einem Rotator und einem Namer die Protokollrotation anpassen¶
Ein Beispiel dafür, wie du einen Namer und einen Rotator festlegen kannst, gibt das folgende lauffähige Skript, das die Protokolldatei mit gzip komprimiert:
import gzip
import logging
import logging.handlers
import os
import shutil
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 = logging.handlers.RotatingFileHandler('rotated.log', maxBytes=128, backupCount=5)
rh.rotator = rotator
rh.namer = namer
root = logging.getLogger()
root.setLevel(logging.INFO)
root.addHandler(rh)
f = logging.Formatter('%(asctime)s %(message)s')
rh.setFormatter(f)
for i in range(1000):
root.info(f'Message no. {i + 1}')
Nach dem Ausführen siehst du sechs neue Dateien, von denen fünf komprimiert sind:
$ ls rotated.log*
rotated.log rotated.log.2.gz rotated.log.4.gz
rotated.log.1.gz rotated.log.3.gz rotated.log.5.gz
$ zcat rotated.log.1.gz
2023-01-20 02:28:17,767 Message no. 996
2023-01-20 02:28:17,767 Message no. 997
2023-01-20 02:28:17,767 Message no. 998
Ein ausgefeilteres Beispiel mit multiprocessing¶
Das folgende funktionierende Beispiel zeigt, wie sich die Protokollierung zusammen mit multiprocessing über Konfigurationsdateien nutzen lässt. Die Konfigurationen sind recht einfach, verdeutlichen aber, wie sich komplexere in einem echten Szenario mit mehreren Prozessen umsetzen ließen.
Im Beispiel erzeugt der Hauptprozess einen Listener-Prozess und einige Arbeiterprozesse. Hauptprozess, Listener und Arbeiter haben jeweils drei getrennte Konfigurationen (die Arbeiter teilen sich alle dieselbe Konfiguration). Wir sehen die Protokollierung im Hauptprozess, wie die Arbeiter in einen QueueHandler protokollieren und wie der Listener einen QueueListener und eine komplexere Protokollierungskonfiguration umsetzt und dafür sorgt, dass über die Warteschlange empfangene Ereignisse an die in der Konfiguration angegebenen Handler verteilt werden. Beachte, dass diese Konfigurationen rein zur Veranschaulichung dienen, du solltest dieses Beispiel aber auf dein eigenes Szenario anpassen können.
Hier das Skript – die Docstrings und die Kommentare erklären hoffentlich, wie es arbeitet:
import logging
import logging.config
import logging.handlers
from multiprocessing import Process, Queue, Event, current_process
import os
import random
import time
class MyHandler:
"""
A simple handler for logging events. It runs in the listener process and
dispatches events to loggers based on the name in the received record,
which then get dispatched, by the logging system, to the handlers
configured for those loggers.
"""
def handle(self, record):
if record.name == "root":
logger = logging.getLogger()
else:
logger = logging.getLogger(record.name)
if logger.isEnabledFor(record.levelno):
# The process name is transformed just to show that it's the listener
# doing the logging to files and console
record.processName = '%s (for %s)' % (current_process().name, record.processName)
logger.handle(record)
def listener_process(q, stop_event, config):
"""
This could be done in the main process, but is just done in a separate
process for illustrative purposes.
This initialises logging according to the specified configuration,
starts the listener and waits for the main process to signal completion
via the event. The listener is then stopped, and the process exits.
"""
logging.config.dictConfig(config)
listener = logging.handlers.QueueListener(q, MyHandler())
listener.start()
if os.name == 'posix':
# On POSIX, the setup logger will have been configured in the
# parent process, but should have been disabled following the
# dictConfig call.
# On Windows, since fork isn't used, the setup logger won't
# exist in the child, so it would be created and the message
# would appear - hence the "if posix" clause.
logger = logging.getLogger('setup')
logger.critical('Should not appear, because of disabled logger ...')
stop_event.wait()
listener.stop()
def worker_process(config):
"""
A number of these are spawned for the purpose of illustration. In
practice, they could be a heterogeneous bunch of processes rather than
ones which are identical to each other.
This initialises logging according to the specified configuration,
and logs a hundred messages with random levels to randomly selected
loggers.
A small sleep is added to allow other processes a chance to run. This
is not strictly needed, but it mixes the output from the different
processes a bit more than if it's left out.
"""
logging.config.dictConfig(config)
levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,
logging.CRITICAL]
loggers = ['foo', 'foo.bar', 'foo.bar.baz',
'spam', 'spam.ham', 'spam.ham.eggs']
if os.name == 'posix':
# On POSIX, the setup logger will have been configured in the
# parent process, but should have been disabled following the
# dictConfig call.
# On Windows, since fork isn't used, the setup logger won't
# exist in the child, so it would be created and the message
# would appear - hence the "if posix" clause.
logger = logging.getLogger('setup')
logger.critical('Should not appear, because of disabled logger ...')
for i in range(100):
lvl = random.choice(levels)
logger = logging.getLogger(random.choice(loggers))
logger.log(lvl, 'Message no. %d', i)
time.sleep(0.01)
def main():
q = Queue()
# The main process gets a simple configuration which prints to the console.
config_initial = {
'version': 1,
'handlers': {
'console': {
'class': 'logging.StreamHandler',
'level': 'INFO'
}
},
'root': {
'handlers': ['console'],
'level': 'DEBUG'
}
}
# The worker process configuration is just a QueueHandler attached to the
# root logger, which allows all messages to be sent to the queue.
# We disable existing loggers to disable the "setup" logger used in the
# parent process. This is needed on POSIX because the logger will
# be there in the child following a fork().
config_worker = {
'version': 1,
'disable_existing_loggers': True,
'handlers': {
'queue': {
'class': 'logging.handlers.QueueHandler',
'queue': q
}
},
'root': {
'handlers': ['queue'],
'level': 'DEBUG'
}
}
# The listener process configuration shows that the full flexibility of
# logging configuration is available to dispatch events to handlers however
# you want.
# We disable existing loggers to disable the "setup" logger used in the
# parent process. This is needed on POSIX because the logger will
# be there in the child following a fork().
config_listener = {
'version': 1,
'disable_existing_loggers': True,
'formatters': {
'detailed': {
'class': 'logging.Formatter',
'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'
},
'simple': {
'class': 'logging.Formatter',
'format': '%(name)-15s %(levelname)-8s %(processName)-10s %(message)s'
}
},
'handlers': {
'console': {
'class': 'logging.StreamHandler',
'formatter': 'simple',
'level': 'INFO'
},
'file': {
'class': 'logging.FileHandler',
'filename': 'mplog.log',
'mode': 'w',
'formatter': 'detailed'
},
'foofile': {
'class': 'logging.FileHandler',
'filename': 'mplog-foo.log',
'mode': 'w',
'formatter': 'detailed'
},
'errors': {
'class': 'logging.FileHandler',
'filename': 'mplog-errors.log',
'mode': 'w',
'formatter': 'detailed',
'level': 'ERROR'
}
},
'loggers': {
'foo': {
'handlers': ['foofile']
}
},
'root': {
'handlers': ['console', 'file', 'errors'],
'level': 'DEBUG'
}
}
# Log some initial events, just to show that logging in the parent works
# normally.
logging.config.dictConfig(config_initial)
logger = logging.getLogger('setup')
logger.info('About to create workers ...')
workers = []
for i in range(5):
wp = Process(target=worker_process, name='worker %d' % (i + 1),
args=(config_worker,))
workers.append(wp)
wp.start()
logger.info('Started worker: %s', wp.name)
logger.info('About to create listener ...')
stop_event = Event()
lp = Process(target=listener_process, name='listener',
args=(q, stop_event, config_listener))
lp.start()
logger.info('Started listener')
# We now hang around for the workers to finish their work.
for wp in workers:
wp.join()
# Workers all done, listening can now stop.
# Logging in the parent still works normally.
logger.info('Telling listener to stop ...')
stop_event.set()
lp.join()
logger.info('All done.')
if __name__ == '__main__':
main()
Ein BOM in Meldungen einfügen, die an einen SysLogHandler gehen¶
RFC 5424 verlangt, dass eine Unicode-Meldung als Folge von Bytes mit folgendem Aufbau an einen syslog-Daemon gesendet wird: ein optionaler reiner ASCII-Teil, gefolgt von einer UTF-8-Bytereihenfolgemarke (BOM), gefolgt von Unicode, kodiert in UTF-8. (Siehe den entsprechenden Abschnitt der Spezifikation.)
In Python 3.1 wurde SysLogHandler um Code ergänzt, der ein BOM in die Meldung einfügt, der aber leider falsch umgesetzt war: Das BOM erschien am Anfang der Meldung, sodass davor kein reiner ASCII-Teil stehen konnte.
Weil dieses Verhalten fehlerhaft ist, wird der falsche Code zum Einfügen des BOM in Python 3.2.4 und neuer entfernt. Er wird allerdings nicht ersetzt, und willst du Meldungen gemäß RFC 5424 erzeugen, die ein BOM, davor eine optionale reine ASCII-Folge und danach beliebiges, in UTF-8 kodiertes Unicode enthalten, dann musst du Folgendes tun:
Hänge eine
Formatter-Instanz an deineSysLogHandler-Instanz, mit einer Formatzeichenkette wie:'ASCII section\ufeffUnicode section'
Der Unicode-Codepunkt U+FEFF wird, in UTF-8 kodiert, zu einem UTF-8-BOM – der Bytefolge
b'\xef\xbb\xbf'.Ersetze den ASCII-Teil durch beliebige Platzhalter, achte aber darauf, dass die Daten, die nach dem Einsetzen dort erscheinen, immer ASCII sind (so bleiben sie nach der UTF-8-Kodierung unverändert).
Ersetze den Unicode-Teil durch beliebige Platzhalter. Enthalten die Daten, die dort nach dem Einsetzen erscheinen, Zeichen außerhalb des ASCII-Bereichs, ist das in Ordnung – sie werden in UTF-8 kodiert.
Die formatierte Meldung wird von SysLogHandler in UTF-8 kodiert. Hältst du dich an die obigen Regeln, solltest du Meldungen gemäß RFC 5424 erzeugen können. Tust du es nicht, beschwert sich die Protokollierung möglicherweise nicht, aber deine Meldungen entsprechen nicht RFC 5424, und dein syslog-Daemon beschwert sich möglicherweise doch.
Strukturierte Protokollierung umsetzen¶
Die meisten Protokollmeldungen sind zwar zum Lesen durch Menschen gedacht und damit nicht ohne Weiteres maschinell zerlegbar, aber es kann Umstände geben, in denen du Meldungen in einem strukturierten Format ausgeben willst, das sich von einem Programm zerlegen lässt (ohne komplexe reguläre Ausdrücke zum Zerlegen der Protokollmeldung). Mit dem Paket logging ist das unkompliziert zu erreichen. Es gibt dafür mehrere Wege, der folgende ist aber ein einfacher Ansatz, der das Ereignis mit JSON maschinenlesbar serialisiert:
import json
import logging
class StructuredMessage:
def __init__(self, message, /, **kwargs):
self.message = message
self.kwargs = kwargs
def __str__(self):
return '%s >>> %s' % (self.message, json.dumps(self.kwargs))
_ = StructuredMessage # optional, to improve readability
logging.basicConfig(level=logging.INFO, format='%(message)s')
logging.info(_('message 1', foo='bar', bar='baz', num=123, fnum=123.456))
Wird das obige Skript ausgeführt, gibt es aus:
message 1 >>> {"fnum": 123.456, "num": 123, "bar": "baz", "foo": "bar"}
Beachte, dass die Reihenfolge der Einträge je nach verwendeter Python-Version unterschiedlich sein kann.
Brauchst du eine spezialisiertere Verarbeitung, kannst du einen eigenen JSON-Kodierer verwenden, wie im folgenden vollständigen Beispiel:
import json
import logging
class Encoder(json.JSONEncoder):
def default(self, o):
if isinstance(o, set):
return tuple(o)
elif isinstance(o, str):
return o.encode('unicode_escape').decode('ascii')
return super().default(o)
class StructuredMessage:
def __init__(self, message, /, **kwargs):
self.message = message
self.kwargs = kwargs
def __str__(self):
s = Encoder().encode(self.kwargs)
return '%s >>> %s' % (self.message, s)
_ = StructuredMessage # optional, to improve readability
def main():
logging.basicConfig(level=logging.INFO, format='%(message)s')
logging.info(_('message 1', set_value={1, 2, 3}, snowman='\u2603'))
if __name__ == '__main__':
main()
Wird das obige Skript ausgeführt, gibt es aus:
message 1 >>> {"snowman": "\u2603", "set_value": [1, 2, 3]}
Beachte, dass die Reihenfolge der Einträge je nach verwendeter Python-Version unterschiedlich sein kann.
Handler mit dictConfig() anpassen¶
Manchmal willst du Protokollierungs-Handler auf bestimmte Weise anpassen, und mit dictConfig() gelingt dir das möglicherweise ohne Unterklassen. Nimm als Beispiel, dass du den Eigentümer einer Protokolldatei setzen willst. Unter POSIX geht das leicht mit shutil.chown(), aber die Datei-Handler der Standardbibliothek unterstützen das nicht von sich aus. Du kannst die Erzeugung des Handlers mit einer gewöhnlichen Funktion anpassen, etwa so:
def owned_file_handler(filename, mode='a', encoding=None, owner=None):
if owner:
if not os.path.exists(filename):
open(filename, 'a').close()
shutil.chown(filename, *owner)
return logging.FileHandler(filename, mode, encoding)
In einer Protokollierungskonfiguration, die du dictConfig() übergibst, kannst du dann angeben, dass ein Protokollierungs-Handler durch den Aufruf dieser Funktion erzeugt wird:
LOGGING = {
'version': 1,
'disable_existing_loggers': False,
'formatters': {
'default': {
'format': '%(asctime)s %(levelname)s %(name)s %(message)s'
},
},
'handlers': {
'file':{
# The values below are popped from this dictionary and
# used to create the handler, set the handler's level and
# its formatter.
'()': owned_file_handler,
'level':'DEBUG',
'formatter': 'default',
# The values below are passed to the handler creator callable
# as keyword arguments.
'owner': ['pulse', 'pulse'],
'filename': 'chowntest.log',
'mode': 'w',
'encoding': 'utf-8',
},
},
'root': {
'handlers': ['file'],
'level': 'DEBUG',
},
}
In diesem Beispiel setze ich den Eigentümer, nur zur Veranschaulichung, auf den Benutzer und die Gruppe pulse. Zu einem funktionierenden Skript zusammengesetzt, chowntest.py:
import logging, logging.config, os, shutil
def owned_file_handler(filename, mode='a', encoding=None, owner=None):
if owner:
if not os.path.exists(filename):
open(filename, 'a').close()
shutil.chown(filename, *owner)
return logging.FileHandler(filename, mode, encoding)
LOGGING = {
'version': 1,
'disable_existing_loggers': False,
'formatters': {
'default': {
'format': '%(asctime)s %(levelname)s %(name)s %(message)s'
},
},
'handlers': {
'file':{
# The values below are popped from this dictionary and
# used to create the handler, set the handler's level and
# its formatter.
'()': owned_file_handler,
'level':'DEBUG',
'formatter': 'default',
# The values below are passed to the handler creator callable
# as keyword arguments.
'owner': ['pulse', 'pulse'],
'filename': 'chowntest.log',
'mode': 'w',
'encoding': 'utf-8',
},
},
'root': {
'handlers': ['file'],
'level': 'DEBUG',
},
}
logging.config.dictConfig(LOGGING)
logger = logging.getLogger('mylogger')
logger.debug('A debug message')
Um das auszuführen, musst du vermutlich als root arbeiten:
$ sudo python3.3 chowntest.py
$ cat chowntest.log
2013-11-05 09:34:51,128 DEBUG mylogger A debug message
$ ls -l chowntest.log
-rw-r--r-- 1 pulse pulse 55 2013-11-05 09:34 chowntest.log
Beachte, dass dieses Beispiel Python 3.3 verwendet, weil dort shutil.chown() auftritt. Dieser Ansatz sollte mit jeder Python-Version funktionieren, die dictConfig() unterstützt – also mit Python 2.7, 3.2 oder neuer. Mit Versionen vor 3.3 müsstest du den eigentlichen Eigentümerwechsel zum Beispiel mit os.chown() umsetzen.
In der Praxis liegt die Funktion, die den Handler erzeugt, möglicherweise in einem Hilfsmodul irgendwo in deinem Projekt. Statt der Zeile in der Konfiguration:
'()': owned_file_handler,
könntest du zum Beispiel schreiben:
'()': 'ext://project.util.owned_file_handler',
wobei project.util durch den tatsächlichen Namen des Pakets zu ersetzen ist, in dem die Funktion liegt. Im obigen funktionierenden Skript sollte 'ext://__main__.owned_file_handler' arbeiten. Hier löst dictConfig() das eigentliche aufrufbare Objekt aus der ext://-Angabe auf.
Dieses Beispiel weist hoffentlich auch den Weg, wie du auf dieselbe Weise andere Arten von Dateiänderungen umsetzen könntest – etwa das Setzen bestimmter POSIX-Rechtebits mit os.chmod().
Natürlich ließe sich der Ansatz auch auf andere Handler-Arten als FileHandler ausdehnen – zum Beispiel auf einen der rotierenden Datei-Handler oder auf eine völlig andere Art von Handler.
In der ganzen Anwendung bestimmte Formatierungsstile verwenden¶
In Python 3.2 erhielt Formatter einen Schlüsselwortparameter style, dessen Vorgabe aus Verträglichkeitsgründen % ist, der aber auch { oder $ erlaubt, um die Formatierungsansätze von str.format() und string.Template zu unterstützen. Beachte, dass das die Formatierung von Protokollmeldungen für die endgültige Ausgabe in die Protokolle steuert und völlig unabhängig davon ist, wie eine einzelne Protokollmeldung aufgebaut wird.
Protokollierungsaufrufe (debug(), info() und so weiter) nehmen für die eigentliche Protokollmeldung nur positionsbezogene Parameter; Schlüsselwortparameter dienen nur dazu, Optionen für die Behandlung des Protokollierungsaufrufs festzulegen (etwa der Schlüsselwortparameter exc_info, der anzeigt, dass Traceback-Informationen protokolliert werden sollen, oder der Schlüsselwortparameter extra, der zusätzliche Kontextinformationen für das Protokoll anzeigt). Du kannst Protokollierungsaufrufe also nicht unmittelbar in der Syntax von str.format() oder string.Template machen, weil das Paket logging intern %-Formatierung verwendet, um Formatzeichenkette und veränderliche Argumente zusammenzuführen. Daran ließe sich nichts ändern, ohne die Verträglichkeit mit früheren Versionen aufzugeben, denn alle Protokollierungsaufrufe im vorhandenen Code verwenden %-Formatzeichenketten.
Es gab Vorschläge, Formatstile mit bestimmten Loggern zu verknüpfen, aber auch dieser Ansatz läuft in Verträglichkeitsprobleme, weil vorhandener Code einen gegebenen Loggernamen zusammen mit %-Formatierung verwenden könnte.
Damit die Protokollierung zwischen Bibliotheken Dritter und deinem Code zusammenspielt, müssen Entscheidungen über die Formatierung auf der Ebene des einzelnen Protokollierungsaufrufs fallen. Das eröffnet ein paar Wege, auf denen sich andere Formatierungsstile unterbringen lassen.
LogRecord-Factorys verwenden¶
In Python 3.2 erhielt das Paket logging neben den oben erwähnten Änderungen an Formatter auch die Möglichkeit, dass Benutzer über die Funktion setLogRecordFactory() eigene Unterklassen von LogRecord setzen. Damit kannst du deine eigene Unterklasse von LogRecord setzen, die das Richtige tut, indem sie die Methode getMessage() überschreibt. In der Umsetzung dieser Methode in der Basisklasse findet die Formatierung msg % args statt, und dort kannst du deine abweichende Formatierung einsetzen. Du solltest allerdings darauf achten, alle Formatierungsstile zu unterstützen und %-Formatierung als Vorgabe zuzulassen, damit das Zusammenspiel mit anderem Code gewährleistet bleibt. Achte außerdem darauf, str(self.msg) aufzurufen, so wie es die Umsetzung in der Basisklasse tut.
Mehr Informationen findest du in der Referenzdokumentation zu setLogRecordFactory() und LogRecord.
Eigene Meldungsobjekte verwenden¶
Es gibt einen weiteren, vielleicht einfacheren Weg, {}- und $-Formatierung zu nutzen, um deine einzelnen Protokollmeldungen aufzubauen. Du erinnerst dich vielleicht (aus Beliebige Objekte als Meldungen verwenden), dass du beim Protokollieren ein beliebiges Objekt als Formatzeichenkette einer Meldung verwenden kannst und dass das Paket logging str() auf dieses Objekt anwendet, um die eigentliche Formatzeichenkette zu erhalten. Betrachte die folgenden zwei Klassen:
class BraceMessage:
def __init__(self, fmt, /, *args, **kwargs):
self.fmt = fmt
self.args = args
self.kwargs = kwargs
def __str__(self):
return self.fmt.format(*self.args, **self.kwargs)
class DollarMessage:
def __init__(self, fmt, /, **kwargs):
self.fmt = fmt
self.kwargs = kwargs
def __str__(self):
from string import Template
return Template(self.fmt).substitute(**self.kwargs)
Beide lassen sich anstelle einer Formatzeichenkette verwenden, sodass sich der eigentliche „Meldungs“-Teil, der in der formatierten Protokollausgabe anstelle von „%(message)s“, „{message}“ oder „$message“ erscheint, mit {}- oder $-Formatierung aufbauen lässt. Findest du es etwas sperrig, die Klassennamen jedes Mal zu schreiben, wenn du etwas protokollieren willst, kannst du es erträglicher machen, indem du für die Meldung einen Alias wie M oder _ verwendest (oder vielleicht __, wenn du _ für die Lokalisierung nutzt).
Beispiele für diesen Ansatz folgen unten. Zunächst die Formatierung mit str.format():
>>> __ = BraceMessage
>>> print(__('Message with {0} {1}', 2, 'placeholders'))
Message with 2 placeholders
>>> class Point: pass
...
>>> p = Point()
>>> p.x = 0.5
>>> p.y = 0.5
>>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})', point=p))
Message with coordinates: (0.50, 0.50)
Und zweitens die Formatierung mit string.Template:
>>> __ = DollarMessage
>>> print(__('Message with $num $what', num=2, what='placeholders'))
Message with 2 placeholders
>>>
Festzuhalten ist, dass du mit diesem Ansatz keinen bedeutsamen Geschwindigkeitsnachteil hast: Die eigentliche Formatierung findet nicht beim Protokollierungsaufruf statt, sondern dann (und nur dann), wenn die protokollierte Meldung von einem Handler tatsächlich in ein Protokoll geschrieben werden soll. Das einzige leicht Ungewöhnliche, über das du stolpern könntest, ist, dass die Klammern um die Formatzeichenkette und die Argumente stehen, nicht nur um die Formatzeichenkette. Das liegt daran, dass die __-Schreibweise nur Zuckerguss für einen Konstruktoraufruf einer der oben gezeigten Klassen XXXMessage ist.
Filter mit dictConfig() konfigurieren¶
Du kannst Filter mit dictConfig() konfigurieren, auch wenn auf den ersten Blick nicht offensichtlich ist, wie (daher dieses Rezept). Da Filter die einzige Filterklasse in der Standardbibliothek ist und kaum viele Anforderungen abdeckt (sie ist nur als Basisklasse gedacht), musst du üblicherweise deine eigene Unterklasse von Filter mit einer überschriebenen Methode filter() festlegen. Gib dazu im Konfigurations-Dictionary für den Filter den Schlüssel () an und nenne darin ein aufrufbares Objekt, mit dem der Filter erzeugt wird (eine Klasse ist das Naheliegendste, du kannst aber jedes aufrufbare Objekt angeben, das eine Filter-Instanz zurückgibt). Hier ein vollständiges Beispiel:
import logging
import logging.config
import sys
class MyFilter(logging.Filter):
def __init__(self, param=None):
self.param = param
def filter(self, record):
if self.param is None:
allow = True
else:
allow = self.param not in record.msg
if allow:
record.msg = 'changed: ' + record.msg
return allow
LOGGING = {
'version': 1,
'filters': {
'myfilter': {
'()': MyFilter,
'param': 'noshow',
}
},
'handlers': {
'console': {
'class': 'logging.StreamHandler',
'filters': ['myfilter']
}
},
'root': {
'level': 'DEBUG',
'handlers': ['console']
},
}
if __name__ == '__main__':
logging.config.dictConfig(LOGGING)
logging.debug('hello')
logging.debug('hello - noshow')
Dieses Beispiel zeigt, wie du dem aufrufbaren Objekt, das die Instanz erzeugt, Konfigurationsdaten in Form von Schlüsselwortparametern übergeben kannst. Beim Ausführen gibt das obige Skript aus:
changed: hello
was zeigt, dass der Filter wie konfiguriert arbeitet.
Noch ein paar zusätzliche Hinweise:
Kannst du das aufrufbare Objekt in der Konfiguration nicht unmittelbar ansprechen (etwa weil es in einem anderen Modul liegt und du es dort, wo das Konfigurations-Dictionary steht, nicht unmittelbar importieren kannst), dann kannst du die Form
ext://...verwenden, wie unter Access to external objects beschrieben. Du hättest im obigen Beispiel zum Beispiel den Text'ext://__main__.MyFilter'stattMyFilterverwenden können.Diese Technik lässt sich nicht nur für Filter, sondern auch zum Konfigurieren eigener Handler und Formatter verwenden. Unter User-defined objects findest du mehr dazu, wie die Protokollierung selbst festgelegte Objekte in ihrer Konfiguration unterstützt, und siehe auch das andere Rezept Handler mit dictConfig() anpassen weiter oben in diesem Kochbuch.
Eigene Formatierung von Ausnahmen¶
Manchmal willst du Ausnahmen selbst formatieren – nehmen wir der Argumentation halber an, du willst genau eine Zeile je protokolliertem Ereignis, auch wenn Informationen zu einer Ausnahme dabei sind. Das kannst du mit einer eigenen Formatter-Klasse erreichen, wie das folgende Beispiel zeigt:
import logging
class OneLineExceptionFormatter(logging.Formatter):
def formatException(self, exc_info):
"""
Format an exception so that it prints on a single line.
"""
result = super().formatException(exc_info)
return repr(result) # or format into one line however you want to
def format(self, record):
s = super().format(record)
if record.exc_text:
s = s.replace('\n', '') + '|'
return s
def configure_logging():
fh = logging.FileHandler('output.txt', 'w')
f = OneLineExceptionFormatter('%(asctime)s|%(levelname)s|%(message)s|',
'%d/%m/%Y %H:%M:%S')
fh.setFormatter(f)
root = logging.getLogger()
root.setLevel(logging.DEBUG)
root.addHandler(fh)
def main():
configure_logging()
logging.info('Sample message')
try:
x = 1 / 0
except ZeroDivisionError as e:
logging.exception('ZeroDivisionError: %s', e)
if __name__ == '__main__':
main()
Beim Ausführen entsteht eine Datei mit genau zwei Zeilen:
28/01/2015 07:21:23|INFO|Sample message|
28/01/2015 07:21:23|ERROR|ZeroDivisionError: division by zero|'Traceback (most recent call last):\n File "logtest7.py", line 30, in main\n x = 1 / 0\nZeroDivisionError: division by zero'|
Die obige Behandlung ist zwar vereinfacht, weist aber den Weg, wie sich Informationen zu Ausnahmen nach deinem Geschmack formatieren lassen. Bei spezielleren Bedürfnissen hilft möglicherweise das Modul traceback.
Protokollmeldungen sprechen lassen¶
Es kann Situationen geben, in denen Protokollmeldungen besser hörbar als sichtbar ausgegeben werden. Das ist leicht möglich, wenn dein System Sprachsynthese (Text-to-Speech, TTS) bietet, selbst wenn es dafür keine Python-Anbindung gibt. Die meisten TTS-Systeme haben ein Befehlszeilenprogramm, das du ausführen kannst, und das lässt sich aus einem Handler heraus mit subprocess aufrufen. Hier wird angenommen, dass TTS-Befehlszeilenprogramme keine Interaktion mit Benutzern erwarten und nicht lange brauchen, dass die Protokollmeldungen nicht so häufig sind, dass der Benutzer von Meldungen überschwemmt wird, und dass es annehmbar ist, die Meldungen eine nach der anderen statt nebenläufig sprechen zu lassen. Die Beispielumsetzung unten wartet, bis eine Meldung gesprochen wurde, bevor die nächste verarbeitet wird. Das kann dazu führen, dass andere Handler warten müssen. Hier ein kurzes Beispiel für den Ansatz, das voraussetzt, dass das TTS-Paket espeak vorhanden ist:
import logging
import subprocess
import sys
class TTSHandler(logging.Handler):
def emit(self, record):
msg = self.format(record)
# Speak slowly in a female English voice
cmd = ['espeak', '-s150', '-ven+f3', msg]
p = subprocess.Popen(cmd, stdout=subprocess.PIPE,
stderr=subprocess.STDOUT)
# wait for the program to finish
p.communicate()
def configure_logging():
h = TTSHandler()
root = logging.getLogger()
root.addHandler(h)
# the default formatter just returns the message
root.setLevel(logging.DEBUG)
def main():
logging.info('Hello')
logging.debug('Goodbye')
if __name__ == '__main__':
configure_logging()
sys.exit(main())
Beim Ausführen sollte dieses Skript mit weiblicher Stimme „Hello“ und dann „Goodbye“ sagen.
Der obige Ansatz lässt sich natürlich auf andere TTS-Systeme und sogar auf ganz andere Systeme übertragen, die Meldungen über externe, von einer Befehlszeile gestartete Programme verarbeiten können.
Protokollmeldungen puffern und bedingt ausgeben¶
Es kann Situationen geben, in denen du Meldungen zunächst in einem Zwischenbereich protokollieren und nur dann ausgeben willst, wenn eine bestimmte Bedingung eintritt. Du willst zum Beispiel in einer Funktion Debug-Ereignisse protokollieren und, wenn die Funktion ohne Fehler durchläuft, das Protokoll nicht mit den gesammelten Debug-Informationen zumüllen – tritt aber ein Fehler auf, sollen alle Debug-Informationen zusammen mit dem Fehler ausgegeben werden.
Hier ein Beispiel, das zeigt, wie du das mit einem Dekorator für die Funktionen erreichen kannst, bei denen sich die Protokollierung so verhalten soll. Es nutzt logging.handlers.MemoryHandler, der protokollierte Ereignisse puffert, bis eine Bedingung eintritt. Dann werden die gepufferten Ereignisse flushed, also geleert und zur Verarbeitung an einen anderen Handler (den target-Handler) übergeben. Standardmäßig leert der MemoryHandler seinen Puffer, wenn dieser voll ist oder ein Ereignis auftritt, dessen Schweregrad größer oder gleich einer angegebenen Schwelle ist. Willst du ein eigenes Leerungsverhalten, kannst du dieses Rezept mit einer spezialisierteren Unterklasse von MemoryHandler verwenden.
Das Beispielskript hat eine einfache Funktion foo, die einfach alle Protokollierungsstufen durchläuft, auf sys.stderr schreibt, auf welcher Stufe sie als Nächstes protokolliert, und dann tatsächlich eine Meldung auf dieser Stufe protokolliert. Du kannst foo einen Parameter übergeben, der, wenn er wahr ist, auch auf den Stufen ERROR und CRITICAL protokolliert – andernfalls protokolliert sie nur auf den Stufen DEBUG, INFO und WARNING.
Das Skript sorgt einfach dafür, dass foo mit einem Dekorator versehen wird, der die gewünschte bedingte Protokollierung übernimmt. Der Dekorator nimmt einen Logger als Parameter und hängt für die Dauer des Aufrufs der dekorierten Funktion einen Memory-Handler an. Der Dekorator lässt sich zusätzlich über einen Ziel-Handler, eine Stufe, bei der geleert werden soll, und eine Kapazität für den Puffer (die Anzahl gepufferter Datensätze) parametrisieren. Die Vorgaben dafür sind ein StreamHandler, der auf sys.stderr schreibt, logging.ERROR und 100.
Hier das Skript:
import logging
from logging.handlers import MemoryHandler
import sys
logger = logging.getLogger(__name__)
logger.addHandler(logging.NullHandler())
def log_if_errors(logger, target_handler=None, flush_level=None, capacity=None):
if target_handler is None:
target_handler = logging.StreamHandler()
if flush_level is None:
flush_level = logging.ERROR
if capacity is None:
capacity = 100
handler = MemoryHandler(capacity, flushLevel=flush_level, target=target_handler)
def decorator(fn):
def wrapper(*args, **kwargs):
logger.addHandler(handler)
try:
return fn(*args, **kwargs)
except Exception:
logger.exception('call failed')
raise
finally:
super(MemoryHandler, handler).flush()
logger.removeHandler(handler)
return wrapper
return decorator
def write_line(s):
sys.stderr.write('%s\n' % s)
def foo(fail=False):
write_line('about to log at DEBUG ...')
logger.debug('Actually logged at DEBUG')
write_line('about to log at INFO ...')
logger.info('Actually logged at INFO')
write_line('about to log at WARNING ...')
logger.warning('Actually logged at WARNING')
if fail:
write_line('about to log at ERROR ...')
logger.error('Actually logged at ERROR')
write_line('about to log at CRITICAL ...')
logger.critical('Actually logged at CRITICAL')
return fail
decorated_foo = log_if_errors(logger)(foo)
if __name__ == '__main__':
logger.setLevel(logging.DEBUG)
write_line('Calling undecorated foo with False')
assert not foo(False)
write_line('Calling undecorated foo with True')
assert foo(True)
write_line('Calling decorated foo with False')
assert not decorated_foo(False)
write_line('Calling decorated foo with True')
assert decorated_foo(True)
Beim Ausführen dieses Skripts sollte folgende Ausgabe zu sehen sein:
Calling undecorated foo with False
about to log at DEBUG ...
about to log at INFO ...
about to log at WARNING ...
Calling undecorated foo with True
about to log at DEBUG ...
about to log at INFO ...
about to log at WARNING ...
about to log at ERROR ...
about to log at CRITICAL ...
Calling decorated foo with False
about to log at DEBUG ...
about to log at INFO ...
about to log at WARNING ...
Calling decorated foo with True
about to log at DEBUG ...
about to log at INFO ...
about to log at WARNING ...
about to log at ERROR ...
Actually logged at DEBUG
Actually logged at INFO
Actually logged at WARNING
Actually logged at ERROR
about to log at CRITICAL ...
Actually logged at CRITICAL
Wie du siehst, entsteht tatsächliche Protokollausgabe nur dann, wenn ein Ereignis mit Schweregrad ERROR oder höher protokolliert wird – in diesem Fall werden dann aber auch alle vorherigen Ereignisse mit niedrigerem Schweregrad protokolliert.
Natürlich kannst du auch die herkömmliche Art der Dekoration verwenden:
@log_if_errors(logger)
def foo(fail=False):
...
Protokollmeldungen gepuffert per E-Mail senden¶
Um zu zeigen, wie du Protokollmeldungen per E-Mail senden kannst, sodass eine festgelegte Anzahl von Meldungen je E-Mail verschickt wird, kannst du eine Unterklasse von BufferingHandler bilden. Im folgenden Beispiel, das du an deine eigenen Bedürfnisse anpassen kannst, ist ein einfaches Testgerüst enthalten, mit dem du das Skript mit Befehlszeilenargumenten starten kannst, die angeben, was du üblicherweise zum Versenden über SMTP brauchst. (Starte das heruntergeladene Skript mit dem Argument -h, um die erforderlichen und die optionalen Argumente zu sehen.)
import logging
import logging.handlers
import smtplib
class BufferingSMTPHandler(logging.handlers.BufferingHandler):
def __init__(self, mailhost, port, username, password, fromaddr, toaddrs,
subject, capacity):
logging.handlers.BufferingHandler.__init__(self, capacity)
self.mailhost = mailhost
self.mailport = port
self.username = username
self.password = password
self.fromaddr = fromaddr
if isinstance(toaddrs, str):
toaddrs = [toaddrs]
self.toaddrs = toaddrs
self.subject = subject
self.setFormatter(logging.Formatter("%(asctime)s %(levelname)-5s %(message)s"))
def flush(self):
if len(self.buffer) > 0:
try:
smtp = smtplib.SMTP(self.mailhost, self.mailport)
smtp.starttls()
smtp.login(self.username, self.password)
msg = "From: %s\r\nTo: %s\r\nSubject: %s\r\n\r\n" % (self.fromaddr, ','.join(self.toaddrs), self.subject)
for record in self.buffer:
s = self.format(record)
msg = msg + s + "\r\n"
smtp.sendmail(self.fromaddr, self.toaddrs, msg)
smtp.quit()
except Exception:
if logging.raiseExceptions:
raise
self.buffer = []
if __name__ == '__main__':
import argparse
ap = argparse.ArgumentParser()
aa = ap.add_argument
aa('host', metavar='HOST', help='SMTP server')
aa('--port', '-p', type=int, default=587, help='SMTP port')
aa('user', metavar='USER', help='SMTP username')
aa('password', metavar='PASSWORD', help='SMTP password')
aa('to', metavar='TO', help='Addressee for emails')
aa('sender', metavar='SENDER', help='Sender email address')
aa('--subject', '-s',
default='Test Logging email from Python logging module (buffering)',
help='Subject of email')
options = ap.parse_args()
logger = logging.getLogger()
logger.setLevel(logging.DEBUG)
h = BufferingSMTPHandler(options.host, options.port, options.user,
options.password, options.sender,
options.to, options.subject, 10)
logger.addHandler(h)
for i in range(102):
logger.info("Info index = %d", i)
h.flush()
h.close()
Führst du dieses Skript aus und ist dein SMTP-Server richtig eingerichtet, solltest du feststellen, dass elf E-Mails an die von dir angegebene Adresse gehen. Die ersten zehn E-Mails enthalten jeweils zehn Protokollmeldungen, die elfte zwei. Das ergibt die 102 Meldungen, die im Skript angegeben sind.
Zeiten über die Konfiguration in UTC (GMT) formatieren¶
Manchmal willst du Zeiten in UTC formatieren. Das lässt sich mit einer Klasse wie UTCFormatter erreichen, die unten gezeigt wird:
import logging
import time
class UTCFormatter(logging.Formatter):
converter = time.gmtime
und du kannst dann in deinem Code den UTCFormatter statt Formatter verwenden. Willst du das über die Konfiguration erreichen, kannst du die API dictConfig() mit einem Ansatz verwenden, den das folgende vollständige Beispiel zeigt:
import logging
import logging.config
import time
class UTCFormatter(logging.Formatter):
converter = time.gmtime
LOGGING = {
'version': 1,
'disable_existing_loggers': False,
'formatters': {
'utc': {
'()': UTCFormatter,
'format': '%(asctime)s %(message)s',
},
'local': {
'format': '%(asctime)s %(message)s',
}
},
'handlers': {
'console1': {
'class': 'logging.StreamHandler',
'formatter': 'utc',
},
'console2': {
'class': 'logging.StreamHandler',
'formatter': 'local',
},
},
'root': {
'handlers': ['console1', 'console2'],
}
}
if __name__ == '__main__':
logging.config.dictConfig(LOGGING)
logging.warning('The local time is %s', time.asctime())
Beim Ausführen dieses Skripts sollte etwa Folgendes ausgegeben werden:
2015-10-17 12:53:29,501 The local time is Sat Oct 17 13:53:29 2015
2015-10-17 13:53:29,501 The local time is Sat Oct 17 13:53:29 2015
was zeigt, wie die Zeit sowohl als Ortszeit als auch in UTC formatiert wird, je einmal pro Handler.
Einen Kontextmanager für gezielte Protokollierung verwenden¶
Manchmal wäre es nützlich, die Protokollierungskonfiguration zeitweise zu ändern und sie nach einer Aktion wieder zurückzusetzen. Dafür ist ein Kontextmanager der naheliegendste Weg, den Protokollierungskontext zu sichern und wiederherzustellen. Hier ein einfaches Beispiel für einen solchen Kontextmanager, mit dem du wahlweise den Schweregrad ändern und einen Protokollierungs-Handler hinzufügen kannst, und zwar nur im Geltungsbereich des Kontextmanagers:
import logging
import sys
class LoggingContext:
def __init__(self, logger, level=None, handler=None, close=True):
self.logger = logger
self.level = level
self.handler = handler
self.close = close
def __enter__(self):
if self.level is not None:
self.old_level = self.logger.level
self.logger.setLevel(self.level)
if self.handler:
self.logger.addHandler(self.handler)
def __exit__(self, et, ev, tb):
if self.level is not None:
self.logger.setLevel(self.old_level)
if self.handler:
self.logger.removeHandler(self.handler)
if self.handler and self.close:
self.handler.close()
# implicit return of None => don't swallow exceptions
Gibst du einen Wert für den Schweregrad an, wird der Schweregrad des Loggers im Geltungsbereich des with-Blocks, den der Kontextmanager umfasst, auf diesen Wert gesetzt. Gibst du einen Handler an, wird er beim Betreten des Blocks dem Logger hinzugefügt und beim Verlassen entfernt. Du kannst den Manager außerdem bitten, den Handler beim Verlassen des Blocks für dich zu schließen – das kannst du tun, wenn du den Handler nicht mehr brauchst.
Um zu zeigen, wie das arbeitet, können wir den folgenden Codeblock an das Obige anhängen:
if __name__ == '__main__':
logger = logging.getLogger('foo')
logger.addHandler(logging.StreamHandler())
logger.setLevel(logging.INFO)
logger.info('1. This should appear just once on stderr.')
logger.debug('2. This should not appear.')
with LoggingContext(logger, level=logging.DEBUG):
logger.debug('3. This should appear once on stderr.')
logger.debug('4. This should not appear.')
h = logging.StreamHandler(sys.stdout)
with LoggingContext(logger, level=logging.DEBUG, handler=h, close=True):
logger.debug('5. This should appear twice - once on stderr and once on stdout.')
logger.info('6. This should appear just once on stderr.')
logger.debug('7. This should not appear.')
Zunächst setzen wir den Schweregrad des Loggers auf INFO, Meldung #1 erscheint also und Meldung #2 nicht. Dann ändern wir den Grad im folgenden with-Block zeitweise auf DEBUG, deshalb erscheint Meldung #3. Nach dem Verlassen des Blocks ist der Schweregrad des Loggers wieder INFO, deshalb erscheint Meldung #4 nicht. Im nächsten with-Block setzen wir den Grad erneut auf DEBUG und fügen zusätzlich einen Handler hinzu, der auf sys.stdout schreibt. Dadurch erscheint Meldung #5 zweimal auf der Konsole (einmal über stderr und einmal über stdout). Nach dem Abschluss der with-Anweisung ist der Zustand wie vorher, deshalb erscheint Meldung #6 (wie Meldung #1), Meldung #7 aber nicht (genau wie Meldung #2).
Führen wir das entstandene Skript aus, ergibt sich Folgendes:
$ python logctx.py
1. This should appear just once on stderr.
3. This should appear once on stderr.
5. This should appear twice - once on stderr and once on stdout.
5. This should appear twice - once on stderr and once on stdout.
6. This should appear just once on stderr.
Führen wir es erneut aus, leiten aber stderr nach /dev/null, sehen wir Folgendes – die einzige Meldung, die auf stdout geschrieben wird:
$ python logctx.py 2>/dev/null
5. This should appear twice - once on stderr and once on stdout.
Und noch einmal, diesmal mit stdout nach /dev/null geleitet, erhalten wir:
$ python logctx.py >/dev/null
1. This should appear just once on stderr.
3. This should appear once on stderr.
5. This should appear twice - once on stderr and once on stdout.
6. This should appear just once on stderr.
In diesem Fall erscheint die Meldung #5, die auf stdout ausgegeben wird, wie erwartet nicht.
Natürlich lässt sich der hier beschriebene Ansatz verallgemeinern, etwa um zeitweise Protokollierungsfilter anzuhängen. Beachte, dass der obige Code sowohl in Python 2 als auch in Python 3 funktioniert.
Eine Vorlage für den Start einer CLI-Anwendung¶
Hier ein Beispiel, das zeigt, wie du
einen Schweregrad anhand von Befehlszeilenargumenten verwendest
an mehrere Unterbefehle in getrennten Dateien verteilst, die alle auf demselben Grad und auf einheitliche Weise protokollieren
eine einfache, knappe Konfiguration nutzt
Nehmen wir an, wir haben eine Befehlszeilenanwendung, deren Aufgabe es ist, bestimmte Dienste zu stoppen, zu starten oder neu zu starten. Zur Veranschaulichung ließe sich das als Datei app.py gestalten, die das Hauptskript der Anwendung ist, während die einzelnen Befehle in start.py, stop.py und restart.py umgesetzt sind. Nehmen wir weiter an, wir wollen die Gesprächigkeit der Anwendung über ein Befehlszeilenargument steuern, mit logging.INFO als Vorgabe. So ließe sich app.py schreiben:
import argparse
import importlib
import logging
import os
import sys
def main(args=None):
scriptname = os.path.basename(__file__)
parser = argparse.ArgumentParser(scriptname)
levels = ('DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL')
parser.add_argument('--log-level', default='INFO', choices=levels)
subparsers = parser.add_subparsers(dest='command',
help='Available commands:')
start_cmd = subparsers.add_parser('start', help='Start a service')
start_cmd.add_argument('name', metavar='NAME',
help='Name of service to start')
stop_cmd = subparsers.add_parser('stop',
help='Stop one or more services')
stop_cmd.add_argument('names', metavar='NAME', nargs='+',
help='Name of service to stop')
restart_cmd = subparsers.add_parser('restart',
help='Restart one or more services')
restart_cmd.add_argument('names', metavar='NAME', nargs='+',
help='Name of service to restart')
options = parser.parse_args()
# the code to dispatch commands could all be in this file. For the purposes
# of illustration only, we implement each command in a separate module.
try:
mod = importlib.import_module(options.command)
cmd = getattr(mod, 'command')
except (ImportError, AttributeError):
print('Unable to find the code for command \'%s\'' % options.command)
return 1
# Could get fancy here and load configuration from file or dictionary
logging.basicConfig(level=options.log_level,
format='%(levelname)s %(name)s %(message)s')
cmd(options)
if __name__ == '__main__':
sys.exit(main())
Und die Befehle start, stop und restart lassen sich in getrennten Modulen umsetzen, zum Starten etwa so:
# start.py
import logging
logger = logging.getLogger(__name__)
def command(options):
logger.debug('About to start %s', options.name)
# actually do the command processing here ...
logger.info('Started the \'%s\' service.', options.name)
und damit zum Stoppen so:
# stop.py
import logging
logger = logging.getLogger(__name__)
def command(options):
n = len(options.names)
if n == 1:
plural = ''
services = '\'%s\'' % options.names[0]
else:
plural = 's'
services = ', '.join('\'%s\'' % name for name in options.names)
i = services.rfind(', ')
services = services[:i] + ' and ' + services[i + 2:]
logger.debug('About to stop %s', services)
# actually do the command processing here ...
logger.info('Stopped the %s service%s.', services, plural)
und entsprechend zum Neustarten:
# restart.py
import logging
logger = logging.getLogger(__name__)
def command(options):
n = len(options.names)
if n == 1:
plural = ''
services = '\'%s\'' % options.names[0]
else:
plural = 's'
services = ', '.join('\'%s\'' % name for name in options.names)
i = services.rfind(', ')
services = services[:i] + ' and ' + services[i + 2:]
logger.debug('About to restart %s', services)
# actually do the command processing here ...
logger.info('Restarted the %s service%s.', services, plural)
Führen wir diese Anwendung mit dem Standard-Schweregrad aus, erhalten wir eine Ausgabe wie diese:
$ python app.py start foo
INFO start Started the 'foo' service.
$ python app.py stop foo bar
INFO stop Stopped the 'foo' and 'bar' services.
$ python app.py restart foo bar baz
INFO restart Restarted the 'foo', 'bar' and 'baz' services.
Das erste Wort ist der Schweregrad, das zweite der Modul- oder Paketname der Stelle, an der das Ereignis protokolliert wurde.
Ändern wir den Schweregrad, ändern wir damit die Informationen, die ins Protokoll gehen. Wollen wir zum Beispiel mehr Informationen:
$ python app.py --log-level DEBUG start foo
DEBUG start About to start foo
INFO start Started the 'foo' service.
$ python app.py --log-level DEBUG stop foo bar
DEBUG stop About to stop 'foo' and 'bar'
INFO stop Stopped the 'foo' and 'bar' services.
$ python app.py --log-level DEBUG restart foo bar baz
DEBUG restart About to restart 'foo', 'bar' and 'baz'
INFO restart Restarted the 'foo', 'bar' and 'baz' services.
Und wollen wir weniger:
$ python app.py --log-level WARNING start foo
$ python app.py --log-level WARNING stop foo bar
$ python app.py --log-level WARNING restart foo bar baz
In diesem Fall geben die Befehle nichts auf der Konsole aus, weil sie nichts auf dem Grad WARNING oder darüber protokollieren.
Eine Qt-GUI für die Protokollierung¶
Eine Frage, die immer wieder auftaucht, ist die, wie man in eine GUI-Anwendung protokolliert. Das Framework Qt ist ein verbreitetes plattformübergreifendes UI-Framework mit Python-Anbindungen über die Bibliotheken PySide2 oder PyQt5.
Das folgende Beispiel zeigt, wie man in eine Qt-GUI protokolliert. Es führt eine einfache Klasse QtHandler ein, die ein aufrufbares Objekt nimmt. Dieses sollte ein Slot im Haupt-Thread sein, der die GUI aktualisiert. Außerdem wird ein Arbeiter-Thread erzeugt, um zu zeigen, wie du sowohl aus der Benutzeroberfläche selbst (über eine Schaltfläche für manuelle Protokollierung) als auch aus einem Arbeiter-Thread, der im Hintergrund arbeitet (hier protokolliert er einfach Meldungen auf zufälligen Graden mit zufälligen kurzen Pausen dazwischen), in die GUI protokollieren kannst.
Der Arbeiter-Thread ist mit Qts Klasse QThread umgesetzt und nicht mit dem Modul threading, denn es gibt Umstände, in denen man QThread verwenden muss, das sich besser in andere Qt-Bestandteile einfügt.
Der Code sollte mit neueren Ausgaben von PySide6, PyQt6, PySide2 oder PyQt5 funktionieren. Den Ansatz solltest du auf frühere Qt-Versionen übertragen können. Ausführlichere Hinweise findest du in den Kommentaren im Codeausschnitt.
import logging
import random
import sys
import time
# Deal with minor differences between different Qt packages
try:
from PySide6 import QtCore, QtGui, QtWidgets
Signal = QtCore.Signal
Slot = QtCore.Slot
except ImportError:
try:
from PyQt6 import QtCore, QtGui, QtWidgets
Signal = QtCore.pyqtSignal
Slot = QtCore.pyqtSlot
except ImportError:
try:
from PySide2 import QtCore, QtGui, QtWidgets
Signal = QtCore.Signal
Slot = QtCore.Slot
except ImportError:
from PyQt5 import QtCore, QtGui, QtWidgets
Signal = QtCore.pyqtSignal
Slot = QtCore.pyqtSlot
logger = logging.getLogger(__name__)
#
# Signals need to be contained in a QObject or subclass in order to be correctly
# initialized.
#
class Signaller(QtCore.QObject):
signal = Signal(str, logging.LogRecord)
#
# Output to a Qt GUI is only supposed to happen on the main thread. So, this
# handler is designed to take a slot function which is set up to run in the main
# thread. In this example, the function takes a string argument which is a
# formatted log message, and the log record which generated it. The formatted
# string is just a convenience - you could format a string for output any way
# you like in the slot function itself.
#
# You specify the slot function to do whatever GUI updates you want. The handler
# doesn't know or care about specific UI elements.
#
class QtHandler(logging.Handler):
def __init__(self, slotfunc, *args, **kwargs):
super().__init__(*args, **kwargs)
self.signaller = Signaller()
self.signaller.signal.connect(slotfunc)
def emit(self, record):
s = self.format(record)
self.signaller.signal.emit(s, record)
#
# This example uses QThreads, which means that the threads at the Python level
# are named something like "Dummy-1". The function below gets the Qt name of the
# current thread.
#
def ctname():
return QtCore.QThread.currentThread().objectName()
#
# Used to generate random levels for logging.
#
LEVELS = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,
logging.CRITICAL)
#
# This worker class represents work that is done in a thread separate to the
# main thread. The way the thread is kicked off to do work is via a button press
# that connects to a slot in the worker.
#
# Because the default threadName value in the LogRecord isn't much use, we add
# a qThreadName which contains the QThread name as computed above, and pass that
# value in an "extra" dictionary which is used to update the LogRecord with the
# QThread name.
#
# This example worker just outputs messages sequentially, interspersed with
# random delays of the order of a few seconds.
#
class Worker(QtCore.QObject):
@Slot()
def start(self):
extra = {'qThreadName': ctname() }
logger.debug('Started work', extra=extra)
i = 1
# Let the thread run until interrupted. This allows reasonably clean
# thread termination.
while not QtCore.QThread.currentThread().isInterruptionRequested():
delay = 0.5 + random.random() * 2
time.sleep(delay)
try:
if random.random() < 0.1:
raise ValueError('Exception raised: %d' % i)
else:
level = random.choice(LEVELS)
logger.log(level, 'Message after delay of %3.1f: %d', delay, i, extra=extra)
except ValueError as e:
logger.exception('Failed: %s', e, extra=extra)
i += 1
#
# Implement a simple UI for this cookbook example. This contains:
#
# * A read-only text edit window which holds formatted log messages
# * A button to start work and log stuff in a separate thread
# * A button to log something from the main thread
# * A button to clear the log window
#
class Window(QtWidgets.QWidget):
COLORS = {
logging.DEBUG: 'black',
logging.INFO: 'blue',
logging.WARNING: 'orange',
logging.ERROR: 'red',
logging.CRITICAL: 'purple',
}
def __init__(self, app):
super().__init__()
self.app = app
self.textedit = te = QtWidgets.QPlainTextEdit(self)
# Set whatever the default monospace font is for the platform
f = QtGui.QFont('nosuchfont')
if hasattr(f, 'Monospace'):
f.setStyleHint(f.Monospace)
else:
f.setStyleHint(f.StyleHint.Monospace) # for Qt6
te.setFont(f)
te.setReadOnly(True)
PB = QtWidgets.QPushButton
self.work_button = PB('Start background work', self)
self.log_button = PB('Log a message at a random level', self)
self.clear_button = PB('Clear log window', self)
self.handler = h = QtHandler(self.update_status)
# Remember to use qThreadName rather than threadName in the format string.
fs = '%(asctime)s %(qThreadName)-12s %(levelname)-8s %(message)s'
formatter = logging.Formatter(fs)
h.setFormatter(formatter)
logger.addHandler(h)
# Set up to terminate the QThread when we exit
app.aboutToQuit.connect(self.force_quit)
# Lay out all the widgets
layout = QtWidgets.QVBoxLayout(self)
layout.addWidget(te)
layout.addWidget(self.work_button)
layout.addWidget(self.log_button)
layout.addWidget(self.clear_button)
self.setFixedSize(900, 400)
# Connect the non-worker slots and signals
self.log_button.clicked.connect(self.manual_update)
self.clear_button.clicked.connect(self.clear_display)
# Start a new worker thread and connect the slots for the worker
self.start_thread()
self.work_button.clicked.connect(self.worker.start)
# Once started, the button should be disabled
self.work_button.clicked.connect(lambda : self.work_button.setEnabled(False))
def start_thread(self):
self.worker = Worker()
self.worker_thread = QtCore.QThread()
self.worker.setObjectName('Worker')
self.worker_thread.setObjectName('WorkerThread') # for qThreadName
self.worker.moveToThread(self.worker_thread)
# This will start an event loop in the worker thread
self.worker_thread.start()
def kill_thread(self):
# Just tell the worker to stop, then tell it to quit and wait for that
# to happen
self.worker_thread.requestInterruption()
if self.worker_thread.isRunning():
self.worker_thread.quit()
self.worker_thread.wait()
else:
print('worker has already exited.')
def force_quit(self):
# For use when the window is closed
if self.worker_thread.isRunning():
self.kill_thread()
# The functions below update the UI and run in the main thread because
# that's where the slots are set up
@Slot(str, logging.LogRecord)
def update_status(self, status, record):
color = self.COLORS.get(record.levelno, 'black')
s = '<pre><font color="%s">%s</font></pre>' % (color, status)
self.textedit.appendHtml(s)
@Slot()
def manual_update(self):
# This function uses the formatted message passed in, but also uses
# information from the record to format the message in an appropriate
# color according to its severity (level).
level = random.choice(LEVELS)
extra = {'qThreadName': ctname() }
logger.log(level, 'Manually logged!', extra=extra)
@Slot()
def clear_display(self):
self.textedit.clear()
def main():
QtCore.QThread.currentThread().setObjectName('MainThread')
logging.getLogger().setLevel(logging.DEBUG)
app = QtWidgets.QApplication(sys.argv)
example = Window(app)
example.show()
if hasattr(app, 'exec'):
rc = app.exec()
else:
rc = app.exec_()
sys.exit(rc)
if __name__=='__main__':
main()
Mit Unterstützung für RFC5424 in syslog protokollieren¶
RFC 5424 stammt zwar aus dem Jahr 2009, die meisten syslog-Server sind aber standardmäßig auf das ältere RFC 3164 von 2001 eingestellt. Als logging 2003 zu Python kam, unterstützte es das damals frühere (und einzige vorhandene) Protokoll. Weil RFC 5424 seit seinem Erscheinen in syslog-Servern nicht auf breiter Front eingesetzt wird, wurde die Funktionalität von SysLogHandler nicht aktualisiert.
RFC 5424 enthält einige nützliche Eigenschaften, etwa die Unterstützung strukturierter Daten. Musst du an einen syslog-Server protokollieren, der das unterstützt, dann geht das mit einem abgeleiteten Handler, der etwa so aussieht:
import datetime as dt
import logging.handlers
import re
import socket
import time
class SysLogHandler5424(logging.handlers.SysLogHandler):
tz_offset = re.compile(r'([+-]\d{2})(\d{2})$')
escaped = re.compile(r'([\]"\\])')
def __init__(self, *args, **kwargs):
self.msgid = kwargs.pop('msgid', None)
self.appname = kwargs.pop('appname', None)
super().__init__(*args, **kwargs)
def format(self, record):
version = 1
asctime = dt.datetime.fromtimestamp(record.created).isoformat()
m = self.tz_offset.prefixmatch(time.strftime('%z'))
has_offset = False
if m and time.timezone:
hrs, mins = m.groups()
if int(hrs) or int(mins):
has_offset = True
if not has_offset:
asctime += 'Z'
else:
asctime += f'{hrs}:{mins}'
try:
hostname = socket.gethostname()
except Exception:
hostname = '-'
appname = self.appname or '-'
procid = record.process
msgid = '-'
msg = super().format(record)
sdata = '-'
if hasattr(record, 'structured_data'):
sd = record.structured_data
# This should be a dict where the keys are SD-ID and the value is a
# dict mapping PARAM-NAME to PARAM-VALUE (refer to the RFC for what these
# mean)
# There's no error checking here - it's purely for illustration, and you
# can adapt this code for use in production environments
parts = []
def replacer(m):
g = m.groups()
return '\\' + g[0]
for sdid, dv in sd.items():
part = f'[{sdid}'
for k, v in dv.items():
s = str(v)
s = self.escaped.sub(replacer, s)
part += f' {k}="{s}"'
part += ']'
parts.append(part)
sdata = ''.join(parts)
return f'{version} {asctime} {hostname} {appname} {procid} {msgid} {sdata} {msg}'
Um den obigen Code vollständig zu verstehen, musst du mit RFC 5424 vertraut sein, und möglicherweise hast du etwas andere Bedürfnisse (etwa, wie du strukturierte Daten an das Protokoll übergibst). Dennoch sollte sich das Obige auf deine Bedürfnisse anpassen lassen. Mit dem obigen Handler übergibst du strukturierte Daten etwa so:
sd = {
'foo@12345': {'bar': 'baz', 'baz': 'bozz', 'fizz': r'buzz'},
'foo@54321': {'rab': 'baz', 'zab': 'bozz', 'zzif': r'buzz'}
}
extra = {'structured_data': sd}
i = 1
logger.debug('Message %d', i, extra=extra)
Wie man einen Logger wie einen Ausgabestrom behandelt¶
Manchmal musst du eine API eines Dritten anbinden, die ein dateiartiges Objekt zum Schreiben erwartet, willst die Ausgabe der API aber in einen Logger lenken. Das geht mit einer Klasse, die einen Logger in eine dateiartige API hüllt. Hier ein kurzes Skript, das eine solche Klasse zeigt:
import logging
class LoggerWriter:
def __init__(self, logger, level):
self.logger = logger
self.level = level
def write(self, message):
if message != '\n': # avoid printing bare newlines, if you like
self.logger.log(self.level, message)
def flush(self):
# doesn't actually do anything, but might be expected of a file-like
# object - so optional depending on your situation
pass
def close(self):
# doesn't actually do anything, but might be expected of a file-like
# object - so optional depending on your situation. You might want
# to set a flag so that later calls to write raise an exception
pass
def main():
logging.basicConfig(level=logging.DEBUG)
logger = logging.getLogger('demo')
info_fp = LoggerWriter(logger, logging.INFO)
debug_fp = LoggerWriter(logger, logging.DEBUG)
print('An INFO message', file=info_fp)
print('A DEBUG message', file=debug_fp)
if __name__ == "__main__":
main()
Beim Ausführen gibt dieses Skript aus
INFO:demo:An INFO message
DEBUG:demo:A DEBUG message
Du könntest LoggerWriter auch verwenden, um sys.stdout und sys.stderr umzuleiten, etwa so:
import sys
sys.stdout = LoggerWriter(logger, logging.INFO)
sys.stderr = LoggerWriter(logger, logging.WARNING)
Das solltest du tun, nachdem du die Protokollierung nach deinen Bedürfnissen konfiguriert hast. Im obigen Beispiel tut das der Aufruf von basicConfig() (er verwendet den Wert von sys.stderr, bevor er von einer LoggerWriter-Instanz überschrieben wird). Dann erhältst du ein Ergebnis dieser Art:
>>> print('Foo')
INFO:demo:Foo
>>> print('Bar', file=sys.stderr)
WARNING:demo:Bar
>>>
Die obigen Beispiele zeigen die Ausgabe natürlich in dem Format, das basicConfig() verwendet, aber du kannst beim Konfigurieren der Protokollierung einen anderen Formatter nehmen.
Beachte, dass du mit dem obigen Verfahren einigermaßen der Pufferung und der Folge der Schreibaufrufe ausgeliefert bist, die du abfängst. Hast du zum Beispiel mit der obigen Festlegung von LoggerWriter den Ausschnitt
sys.stderr = LoggerWriter(logger, logging.WARNING)
1 / 0
dann ergibt das Ausführen des Skripts
WARNING:demo:Traceback (most recent call last):
WARNING:demo: File "/home/runner/cookbook-loggerwriter/test.py", line 53, in <module>
WARNING:demo:
WARNING:demo:main()
WARNING:demo: File "/home/runner/cookbook-loggerwriter/test.py", line 49, in main
WARNING:demo:
WARNING:demo:1 / 0
WARNING:demo:ZeroDivisionError
WARNING:demo::
WARNING:demo:division by zero
Wie du siehst, ist diese Ausgabe nicht ideal. Das liegt daran, dass der zugrunde liegende Code, der auf sys.stderr schreibt, mehrere Schreibvorgänge ausführt, von denen jeder zu einer eigenen Protokollzeile führt (etwa die letzten drei Zeilen oben). Um dieses Problem zu umgehen, musst du puffern und Protokollzeilen nur dann ausgeben, wenn Zeilenumbrüche auftreten. Nehmen wir eine etwas bessere Umsetzung von LoggerWriter:
class BufferingLoggerWriter(LoggerWriter):
def __init__(self, logger, level):
super().__init__(logger, level)
self.buffer = ''
def write(self, message):
if '\n' not in message:
self.buffer += message
else:
parts = message.split('\n')
if self.buffer:
s = self.buffer + parts.pop(0)
self.logger.log(self.level, s)
self.buffer = parts.pop()
for part in parts:
self.logger.log(self.level, part)
Die puffert einfach, bis ein Zeilenumbruch auftritt, und protokolliert dann vollständige Zeilen. Mit diesem Ansatz erhältst du eine bessere Ausgabe:
WARNING:demo:Traceback (most recent call last):
WARNING:demo: File "/home/runner/cookbook-loggerwriter/main.py", line 55, in <module>
WARNING:demo: main()
WARNING:demo: File "/home/runner/cookbook-loggerwriter/main.py", line 52, in main
WARNING:demo: 1/0
WARNING:demo:ZeroDivisionError: division by zero
Wie man Zeilenumbrüche in der Protokollausgabe einheitlich behandelt¶
Üblicherweise bestehen protokollierte Meldungen (etwa auf der Konsole oder in einer Datei) aus einer einzigen Textzeile. Manchmal müssen aber Meldungen mit mehreren Zeilen behandelt werden – sei es, weil eine Formatzeichenkette der Protokollierung Zeilenumbrüche enthält, oder weil die protokollierten Daten Zeilenumbrüche enthalten. Willst du solche Meldungen einheitlich behandeln, sodass jede Zeile der protokollierten Meldung so einheitlich formatiert erscheint, als wäre sie einzeln protokolliert worden, dann geht das mit einem Handler-Mixin, wie im folgenden Ausschnitt:
# Assume this is in a module mymixins.py
import copy
class MultilineMixin:
def emit(self, record):
s = record.getMessage()
if '\n' not in s:
super().emit(record)
else:
lines = s.splitlines()
rec = copy.copy(record)
rec.args = None
for line in lines:
rec.msg = line
super().emit(rec)
Das Mixin kannst du so verwenden wie im folgenden Skript:
import logging
from mymixins import MultilineMixin
logger = logging.getLogger(__name__)
class StreamHandler(MultilineMixin, logging.StreamHandler):
pass
if __name__ == '__main__':
logging.basicConfig(level=logging.DEBUG, format='%(asctime)s %(levelname)-9s %(message)s',
handlers = [StreamHandler()])
logger.debug('Single line')
logger.debug('Multiple lines:\nfool me once ...')
logger.debug('Another single line')
logger.debug('Multiple lines:\n%s', 'fool me ...\ncan\'t get fooled again')
Beim Ausführen gibt das Skript etwa Folgendes aus:
2025-07-02 13:54:47,234 DEBUG Single line
2025-07-02 13:54:47,234 DEBUG Multiple lines:
2025-07-02 13:54:47,234 DEBUG fool me once ...
2025-07-02 13:54:47,234 DEBUG Another single line
2025-07-02 13:54:47,234 DEBUG Multiple lines:
2025-07-02 13:54:47,234 DEBUG fool me ...
2025-07-02 13:54:47,234 DEBUG can't get fooled again
Machst du dir dagegen Sorgen wegen Log Injection, dann kannst du einen Formatter verwenden, der Zeilenumbrüche maskiert, wie im folgenden Beispiel:
import logging
logger = logging.getLogger(__name__)
class EscapingFormatter(logging.Formatter):
def format(self, record):
s = super().format(record)
return s.replace('\n', r'\n')
if __name__ == '__main__':
h = logging.StreamHandler()
h.setFormatter(EscapingFormatter('%(asctime)s %(levelname)-9s %(message)s'))
logging.basicConfig(level=logging.DEBUG, handlers = [h])
logger.debug('Single line')
logger.debug('Multiple lines:\nfool me once ...')
logger.debug('Another single line')
logger.debug('Multiple lines:\n%s', 'fool me ...\ncan\'t get fooled again')
Du kannst natürlich jedes Maskierungsverfahren verwenden, das für dich am sinnvollsten ist. Beim Ausführen sollte das Skript eine Ausgabe wie diese erzeugen:
2025-07-09 06:47:33,783 DEBUG Single line
2025-07-09 06:47:33,783 DEBUG Multiple lines:\nfool me once ...
2025-07-09 06:47:33,783 DEBUG Another single line
2025-07-09 06:47:33,783 DEBUG Multiple lines:\nfool me ...\ncan't get fooled again
Dieses Maskierungsverhalten kann nicht die Vorgabe der Standardbibliothek sein, weil es die Verträglichkeit mit früheren Versionen brechen würde.
Muster, die man vermeiden sollte¶
Die vorangehenden Abschnitte haben Wege beschrieben, Dinge zu tun, die du möglicherweise tun oder bewältigen musst. Es lohnt sich aber, einige Nutzungsmuster zu erwähnen, die nicht hilfreich sind und die man daher in den meisten Fällen vermeiden sollte. Die folgenden Abschnitte stehen in keiner bestimmten Reihenfolge.
Dieselbe Protokolldatei mehrmals öffnen¶
Unter Windows kannst du dieselbe Datei in der Regel nicht mehrmals öffnen, weil das zu einem Fehler „Datei wird von einem anderen Prozess verwendet“ führt. Auf POSIX-Plattformen erhältst du dagegen keine Fehler, wenn du dieselbe Datei mehrmals öffnest. Das kann versehentlich geschehen, zum Beispiel durch:
mehrfaches Hinzufügen eines Datei-Handlers, der dieselbe Datei anspricht (etwa durch Kopieren, Einfügen und Vergessen, etwas zu ändern).
Öffnen von zwei Dateien, die wegen ihrer unterschiedlichen Namen verschieden aussehen, aber dieselbe sind, weil eine ein symbolischer Verweis auf die andere ist.
Abspalten eines Prozesses, wonach Eltern- und Kindprozess einen Verweis auf dieselbe Datei haben. Das kann zum Beispiel durch die Verwendung des Moduls
multiprocessinggeschehen.
Eine Datei mehrmals zu öffnen scheint meist zu funktionieren, kann in der Praxis aber zu einer Reihe von Problemen führen:
Die Protokollausgabe kann durcheinandergeraten, weil mehrere Threads oder Prozesse in dieselbe Datei schreiben wollen. Die Protokollierung schützt zwar davor, dass mehrere Threads dieselbe Handler-Instanz gleichzeitig nutzen, aber es gibt keinen solchen Schutz, wenn zwei verschiedene Threads über zwei verschiedene Handler-Instanzen gleichzeitig schreiben, die zufällig auf dieselbe Datei zeigen.
Ein Versuch, eine Datei zu löschen (etwa während der Dateirotation), schlägt stillschweigend fehl, weil ein weiterer Verweis auf sie zeigt. Das kann zu Verwirrung und verlorener Zeit bei der Fehlersuche führen – Protokolleinträge landen an unerwarteten Stellen oder gehen ganz verloren. Oder eine Datei, die verschoben werden sollte, bleibt liegen und wächst unerwartet, obwohl eine größenabhängige Rotation eingerichtet sein sollte.
Verwende die unter Aus mehreren Prozessen in eine einzige Datei protokollieren beschriebenen Techniken, um solche Probleme zu umgehen.
Logger als Attribute einer Klasse verwenden oder sie als Parameter übergeben¶
Es mag ungewöhnliche Fälle geben, in denen du das brauchst, aber im Allgemeinen hat es keinen Sinn, weil Logger Singletons sind. Code kommt mit logging.getLogger(name) immer über den Namen an eine bestimmte Logger-Instanz, Instanzen herumzugeben und als Instanzattribute zu halten ist also zwecklos. Beachte, dass Logger in anderen Sprachen wie Java und C# oft statische Klassenattribute sind. In Python ergibt dieses Muster aber keinen Sinn, denn hier ist das Modul (und nicht die Klasse) die Einheit, in die Software zerlegt wird.
Andere Handler als NullHandler an einen Logger in einer Bibliothek hängen¶
Die Protokollierung durch Hinzufügen von Handlern, Formattern und Filtern zu konfigurieren, ist Aufgabe des Anwendungsentwicklers, nicht des Bibliotheksentwicklers. Betreust du eine Bibliothek, dann achte darauf, an keinen deiner Logger einen anderen Handler als eine NullHandler-Instanz zu hängen.
Viele Logger erzeugen¶
Logger sind Singletons, die während der Ausführung eines Skripts nie freigegeben werden. Viele Logger zu erzeugen verbraucht also Speicher, der danach nicht freigegeben werden kann. Erzeuge nicht etwa einen Logger je verarbeiteter Datei oder je aufgebauter Netzverbindung, sondern verwende die vorhandenen Mechanismen, um Kontextinformationen in deine Protokolle zu bringen, und beschränke die erzeugten Logger auf solche, die Bereiche innerhalb deiner Anwendung beschreiben (im Allgemeinen Module, gelegentlich etwas feiner).
Weitere Quellen¶
Siehe auch
- Modul
logging API-Referenz für das Modul logging.
- Modul
logging.config Konfigurations-API für das Modul logging.
- Modul
logging.handlers Nützliche Handler, die mit dem Modul logging ausgeliefert werden.