Logging Cookbook¶
- Autor:
Vinay Sajip <vinay_sajip at red-dove dot com>
Diese Seite enthält eine Reihe von Rezepten im Zusammenhang mit Logging, die sich in der Vergangenheit als nützlich erwiesen haben. Links zu Tutorial- und Referenzinformationen finden Sie unter Weitere Ressourcen.
Logging in mehreren Modulen¶
Mehrere Aufrufe von logging.getLogger('someLogger') geben eine Referenz auf dasselbe Logger-Objekt zurück. Dies gilt nicht nur innerhalb desselben Moduls, sondern auch über Module hinweg, solange sie sich im selben Python-Interpreterprozess befinden. Dies gilt für Referenzen auf dasselbe Objekt; zusätzlich kann Anwendungscode einen Elter-Logger in einem Modul definieren und konfigurieren und einen Kind-Logger in einem separaten Modul erstellen (aber nicht konfigurieren), und alle Logger-Aufrufe an das Kind werden an den Eltern weitergeleitet. Hier ist 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 ist 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()
Logging aus mehreren Threads¶
Logging aus mehreren Threads erfordert keine besonderen Anstrengungen. Das folgende Beispiel zeigt Logging aus dem Haupt-Thread (Anfangsthread) 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
Dies zeigt die Logging-Ausgabe, wie erwartet, unterbrochen. Dieser Ansatz funktioniert natürlich auch für mehr Threads als hier gezeigt.
Mehrere Handler und Formatierer¶
Logger sind einfache Python-Objekte. Die Methode addHandler() hat keine minimale oder maximale Quote für die Anzahl der Handler, die Sie hinzufügen können. Manchmal ist es für eine Anwendung von Vorteil, alle Meldungen aller Schweregrade in eine Textdatei zu protokollieren und gleichzeitig Fehler oder höhere Schweregrade auf der Konsole auszugeben. Um dies einzurichten, konfigurieren Sie einfach die entsprechenden Handler. Die Logging-Aufrufe im Anwendungscode bleiben unverändert. Hier ist eine leichte Modifikation 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')
Beachten Sie, dass der „Anwendungscode“ sich nicht um mehrere Handler kümmert. Alles, was sich geändert hat, war die Hinzufügung und Konfiguration eines neuen Handlers namens *fh*.
Die Möglichkeit, neue Handler mit Filtern für höhere oder niedrigere Schweregrade zu erstellen, kann beim Schreiben und Testen einer Anwendung sehr hilfreich sein. Anstatt viele print-Anweisungen zum Debuggen zu verwenden, verwenden Sie logger.debug: Im Gegensatz zu den print-Anweisungen, die Sie später löschen oder auskommentieren müssen, können die logger.debug-Anweisungen im Quellcode unverändert bleiben und ruhen, bis Sie sie wieder benötigen. Zu diesem Zeitpunkt muss nur der Schweregrad des Loggers und/oder Handlers auf debug geändert werden.
Logging an mehrere Ziele¶
Nehmen wir an, Sie möchten mit unterschiedlichen Nachrichtenformaten und unter verschiedenen Umständen an die Konsole und in eine Datei protokollieren. Sagen wir, Sie möchten Meldungen mit den Schweregraden DEBUG und höher in eine Datei protokollieren, und Meldungen mit dem Schweregrad INFO und höher auf die Konsole. Nehmen wir außerdem an, die Datei soll Zeitstempel enthalten, die Konsolenmeldungen jedoch nicht. Hier erfahren Sie, wie Sie dies erreichen können
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 Sie dies ausführen, sehen Sie 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 sehen Sie etwas wie
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 Sie sehen können, wird die DEBUG-Meldung nur in der Datei angezeigt. Die anderen Meldungen werden an beide Ziele gesendet.
Dieses Beispiel verwendet Konsolen- und Datei-Handler, aber Sie können jede Anzahl und Kombination von Handlern verwenden, die Sie wünschen.
Beachten Sie, dass die obige Wahl des Log-Dateinamens /tmp/myapp.log die Verwendung eines Standardorts für temporäre Dateien auf POSIX-Systemen impliziert. Unter Windows müssen Sie möglicherweise einen anderen Verzeichnisnamen für das Protokoll wählen – stellen Sie einfach sicher, dass das Verzeichnis existiert und Sie die Berechtigung zum Erstellen und Aktualisieren von Dateien darin haben.
Benutzerdefinierte Behandlung von Ebenen¶
Manchmal möchten Sie etwas anderes tun als die Standardbehandlung von Ebenen in Handlern, bei der alle Ebenen über einem Schwellenwert von einem Handler verarbeitet werden. Dazu müssen Sie Filter verwenden. Betrachten wir ein Szenario, in dem Sie die Dinge wie folgt anordnen möchten
Senden von Meldungen der Schweregradstufe
INFOundWARNINGansys.stdoutSenden von Meldungen der Schweregradstufe
ERRORund höher ansys.stderrSenden von Meldungen der Schweregradstufe
DEBUGund höher an die Dateiapp.log
Angenommen, Sie konfigurieren das Logging mit dem folgenden 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, außer dass sys.stdout Meldungen der Schweregradstufe ERROR anzeigt und nur Ereignisse dieser Schweregradstufe und höher verfolgt werden, sowie Meldungen der Schweregradstufe INFO und WARNING. Um dies zu verhindern, können wir einen Filter einrichten, der diese Meldungen ausschließt, und ihn zum entsprechenden Handler hinzufügen. Dies kann durch Hinzufügen eines filters-Abschnitts parallel zu formatters und handlers konfiguriert werden
{
"filters": {
"warnings_and_below": {
"()" : "__main__.filter_maker",
"level": "WARNING"
}
}
}
und den Abschnitt für den stdout-Handler ändern, um ihn hinzuzufügen
{
"stdout": {
"class": "logging.StreamHandler",
"level": "INFO",
"formatter": "simple",
"stream": "ext://sys.stdout",
"filters": ["warnings_and_below"]
}
}
Ein Filter ist nur eine Funktion, daher können wir den filter_maker (eine Fabrikfunktion) wie folgt definieren
def filter_maker(level):
level = getattr(logging, level)
def filter(record):
return record.levelno <= level
return filter
Dies wandelt das als Zeichenkette übergebene Argument in eine numerische Stufe um und gibt eine Funktion zurück, die nur dann True zurückgibt, wenn die Stufe des übergebenen Datensatzes auf oder unter der angegebenen Stufe liegt. Beachten Sie, dass ich in diesem Beispiel den filter_maker in einem Testskript main.py definiert habe, das ich von der Befehlszeile aus ausführe, daher ist sein Modul __main__ – daher __main__.filter_maker in der Filterkonfiguration. Sie müssen dies ändern, wenn Sie es in einem anderen Modul definieren.
Mit dem hinzugefügten Filter können wir main.py ausführen, das im Ganzen lautet
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 nachdem wir es so ausgeführt haben
python main.py 2>stderr.log >stdout.log
können wir sehen, dass die Ergebnisse wie erwartet sind
$ 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 ist ein Beispiel für ein Modul, das den Logging-Konfigurationsserver 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 ist ein Skript, das einen Dateinamen nimmt und diese Datei an den Server sendet, ordnungsgemäß vorangestellt mit der binär-kodierten Länge, als neue Logging-Konfiguration
#!/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')
Umgang mit blockierenden Handlern¶
Manchmal müssen Sie dafür sorgen, dass Ihre Logging-Handler ihre Arbeit verrichten, ohne den Thread, von dem aus Sie protokollieren, zu blockieren. Dies ist in Webanwendungen üblich, tritt aber natürlich auch in anderen Szenarien auf.
Ein häufiger Übeltäter, der träge Verhaltensweisen zeigt, ist der SMTPHandler: das Senden von E-Mails kann aus einer Reihe von Gründen, die außerhalb der Kontrolle des Entwicklers liegen (z. B. eine schlecht funktionierende Mail- oder Netzwerkinfrastruktur), lange dauern. Aber fast jeder netzwerkbasierte Handler kann blockieren: Selbst eine SocketHandler-Operation kann unter der Haube eine DNS-Abfrage durchführen, die zu langsam ist (und diese Abfrage kann tief im Socket-Bibliotheks-Code liegen, unterhalb der Python-Ebene, und außerhalb Ihrer Kontrolle).
Eine Lösung ist ein zweistufiger Ansatz. Im ersten Teil fügen Sie nur einen QueueHandler zu den Loggern hinzu, auf die von performance-kritischen Threads zugegriffen wird. Diese schreiben einfach in ihre Queue, die auf eine ausreichend große Kapazität dimensioniert oder ohne Obergrenze für ihre Größe initialisiert werden kann. Der Schreibvorgang in die Queue wird in der Regel schnell akzeptiert, obwohl Sie wahrscheinlich die Ausnahme queue.Full vorsichtshalber in Ihrem Code abfangen müssen. Wenn Sie ein Bibliotheksentwickler sind, der performance-kritische Threads in seinem Code hat, stellen Sie sicher, dass Sie dies dokumentieren (zusammen mit dem Vorschlag, nur QueueHandlers an Ihre Logger anzuhängen), zum Nutzen anderer Entwickler, die Ihren Code verwenden werden.
Der zweite Teil der Lösung ist QueueListener, der als Gegenstück zu QueueHandler konzipiert wurde. Ein QueueListener ist sehr einfach: ihm wird eine Queue und einige Handler übergeben, und er startet einen internen Thread, der seine Queue auf LogRecords überwacht, die von QueueHandlers (oder einer anderen Quelle von LogRecords) gesendet werden. Die LogRecords werden aus der Queue entfernt und zur Verarbeitung an die Handler übergeben.
Der Vorteil eines separaten QueueListener ist, dass Sie dieselbe Instanz verwenden können, um mehrere QueueHandlers zu bedienen. Dies ist ressourcenschonender, als z. B. Thread-Versionen der vorhandenen Handlerklassen zu haben, die einen Thread pro Handler für keinen besonderen Nutzen verbrauchen würden.
Ein Beispiel für die Verwendung dieser beiden Klassen folgt (Imports 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()
welches beim Ausführen Folgendes ergibt
MainThread: Look out!
Hinweis
Obwohl die frühere Diskussion nicht speziell über asynchronen Code sprach, sondern über langsame Logging-Handler, sollte angemerkt werden, dass beim Logging aus asynchronem Code Netzwerk- und sogar Datei-Handler Probleme (Blockieren der Event-Schleife) verursachen könnten, da ein Teil des Loggings aus asyncio-Interna erfolgt. Es ist am besten, wenn asynchroner Code in einer Anwendung verwendet wird, den obigen Ansatz für das Logging zu verwenden, damit blockierender Code nur im QueueListener-Thread läuft.
Geändert in Version 3.5: Vor Python 3.5 hat der QueueListener jede Nachricht, die er aus der Queue erhielt, immer an jeden Handler weitergeleitet, mit dem er initialisiert wurde. (Dies lag daran, dass angenommen wurde, dass die Ebenenfilterung auf der anderen Seite erfolgt, wo die Queue gefüllt wird.) Ab 3.5 kann dieses Verhalten geändert werden, indem das Schlüsselwortargument respect_handler_level=True an den Konstruktor des Listeners übergeben wird. Wenn dies geschieht, vergleicht der Listener die Ebene jeder Nachricht mit der Ebene des Handlers und leitet eine Nachricht nur dann an einen Handler weiter, wenn dies angemessen ist.
Geändert in Version 3.14: Der QueueListener kann über die with-Anweisung gestartet (und gestoppt) werden. 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.
Senden und Empfangen von Logging-Ereignissen über ein Netzwerk¶
Nehmen wir an, Sie möchten Logging-Ereignisse über ein Netzwerk senden und sie am Empfangsendepunkt verarbeiten. Ein einfacher Weg, dies zu tun, ist das Anhängen einer Instanz von SocketHandler an den Stamm-Logger am Senderende
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 Empfangsendepunkt können Sie einen Empfänger mit dem Modul socketserver einrichten. Hier ist 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()
Führen Sie zuerst den Server und dann den Client aus. Auf der Clientseite wird nichts auf der Konsole ausgegeben; auf der Serverseite sollten Sie etwas wie das Folgende 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.
Beachten Sie, dass es in einigen Szenarien einige Sicherheitsprobleme mit Pickle gibt. Wenn diese Sie betreffen, können Sie ein alternatives Serialisierungsschema verwenden, indem Sie die Methode makePickle() überschreiben und dort Ihre Alternative implementieren, sowie das obige Skript an Ihre alternative Serialisierung anpassen.
Ausführen eines Logging-Socket-Listeners in der Produktion¶
Um einen Logging-Listener in der Produktion auszuführen, müssen Sie möglicherweise ein Prozessmanagement-Tool wie Supervisor verwenden. Hier ist ein Gist, der die grundlegenden Dateien zur Ausführung der obigen Funktionalität mit Supervisor bereitstellt. Er besteht aus den folgenden Dateien
Datei |
Zweck |
|---|---|
|
Ein Bash-Skript zur Vorbereitung der Umgebung für Tests |
|
Die Supervisor-Konfigurationsdatei, die Einträge für den Listener und eine Multiprozess-Webanwendung enthält |
|
Ein Bash-Skript, das sicherstellt, dass Supervisor mit der obigen Konfiguration läuft |
|
Das Socket-Listener-Programm, das Log-Ereignisse empfängt und in eine Datei schreibt |
|
Eine einfache Webanwendung, die Logging über einen Socket durchführt, der mit dem Listener verbunden ist |
|
Eine JSON-Konfigurationsdatei für die Webanwendung |
|
Ein Python-Skript zum Testen der Webanwendung |
Die Webanwendung verwendet Gunicorn, einen beliebten Webanwendungsserver, der mehrere Worker-Prozesse startet, um Anfragen zu bearbeiten. Dieses Beispiel zeigt, wie die Worker ohne Konflikte in dieselbe Log-Datei schreiben können – sie durchlaufen alle den Socket-Listener.
Um diese Dateien zu testen, gehen Sie in einer POSIX-Umgebung wie folgt vor
Laden Sie den Gist als ZIP-Archiv über die Schaltfläche ZIP herunterladen herunter.
Entpacken Sie die obigen Dateien aus dem Archiv in ein temporäres Verzeichnis.
Führen Sie im temporären Verzeichnis
bash prepare.shaus, um die Dinge vorzubereiten. Dies erstellt ein Unterverzeichnisrun, das Supervisor-bezogene und Log-Dateien enthält, sowie ein Unterverzeichnisvenv, das eine virtuelle Umgebung enthält, in diebottle,gunicornundsupervisorinstalliert werden.Führen Sie
bash ensure_app.shaus, um sicherzustellen, dass Supervisor mit der obigen Konfiguration läuft.Führen Sie
venv/bin/python client.pyaus, um die Webanwendung zu testen, was dazu führt, dass Datensätze in das Log geschrieben werden.Untersuchen Sie die Log-Dateien im Unterverzeichnis
run. Sie sollten die neuesten Log-Zeilen in Dateien sehen, die dem Musterapp.log*entsprechen. Sie werden nicht in einer bestimmten Reihenfolge sein, da sie von verschiedenen Worker-Prozessen auf nicht-deterministische Weise gleichzeitig bearbeitet wurden.Sie können den Listener und die Webanwendung herunterfahren, indem Sie
venv/bin/supervisorctl -c supervisor.conf shutdownausführen.
Möglicherweise müssen Sie die Konfigurationsdateien in dem unwahrscheinlichen Fall anpassen, dass die konfigurierten Ports mit etwas anderem in Ihrer Testumgebung kollidieren.
Die Standardkonfiguration verwendet einen TCP-Socket auf Port 9020. Sie können anstelle eines TCP-Sockets einen Unix-Domain-Socket verwenden, indem Sie Folgendes tun
Fügen Sie in
listener.jsoneinen Schlüsselsocketmit dem Pfad zu dem Domain-Socket hinzu, den Sie verwenden möchten. Wenn dieser Schlüssel vorhanden ist, hört der Listener auf dem entsprechenden Domain-Socket und nicht auf einem TCP-Socket (der Schlüsselportwird ignoriert).Ändern Sie in
webapp.jsondas Konfigurationsdictionary des Socket-Handlers so, dass der Wert fürhostder Pfad zum Domain-Socket ist und der Wert fürportaufnullgesetzt wird.
Hinzufügen von Kontextinformationen zur Logging-Ausgabe¶
Manchmal möchten Sie, dass die Logging-Ausgabe neben den an den Logging-Aufruf übergebenen Parametern auch Kontextinformationen enthält. In einer vernetzten Anwendung kann es beispielsweise wünschenswert sein, klientenspezifische Informationen in das Protokoll aufzunehmen (z. B. Benutzername oder IP-Adresse des entfernten Clients). Obwohl Sie den *extra*-Parameter verwenden könnten, um dies zu erreichen, ist es nicht immer praktisch, die Informationen auf diese Weise zu übergeben. Während es verlockend sein mag, Logger-Instanzen pro Verbindung zu erstellen, ist dies keine gute Idee, da diese Instanzen nicht vom Garbage Collector bereinigt werden. Dies ist zwar in der Praxis kein Problem, wenn die Anzahl der Logger-Instanzen von der Granularität abhängt, die Sie beim Logging einer Anwendung verwenden möchten, könnte es schwierig zu verwalten sein, wenn die Anzahl der Logger-Instanzen effektiv unbegrenzt wird.
Verwendung von LoggerAdapters zur Vermittlung von Kontextinformationen¶
Eine einfache Möglichkeit, Kontextinformationen zu übergeben, die zusammen mit den Logging-Ereignisinformationen ausgegeben werden sollen, ist die Verwendung der Klasse LoggerAdapter. Diese Klasse ist so konzipiert, dass sie wie ein Logger aussieht, so dass Sie debug(), info(), warning(), error(), exception(), critical() und log() aufrufen können. Diese Methoden haben dieselben Signaturen wie ihre Gegenstücke in Logger, sodass Sie die beiden Arten von Instanzen austauschbar verwenden können.
Wenn Sie eine Instanz von LoggerAdapter erstellen, übergeben Sie ihr eine Logger-Instanz und ein Dictionary-ähnliches Objekt, das Ihre Kontextinformationen enthält. Wenn Sie eine der Logging-Methoden auf einer Instanz von LoggerAdapter aufrufen, delegiert sie den Aufruf an die zugrundeliegende Instanz von Logger, die an ihren Konstruktor übergeben wurde, und arrangiert, die Kontextinformationen im delegierten Aufruf zu übergeben. Hier ist ein Auszug 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)
Die Methode process() von LoggerAdapter ist der Ort, an dem die Kontextinformationen der Logging-Ausgabe hinzugefügt werden. Ihr werden die Nachricht und die Schlüsselwortargumente des Logging-Aufrufs übergeben, und sie gibt (potenziell) modifizierte Versionen davon zurück, um sie im Aufruf des zugrundeliegenden Loggers zu verwenden. Die Standardimplementierung dieser Methode lässt die Nachricht unverändert, fügt jedoch einen 'extra'-Schlüssel in die Schlüsselwortargumente ein, dessen Wert das an den Konstruktor übergebene Dictionary-ähnliche Objekt ist. Wenn Sie einen 'extra'-Schlüsselwortargument im Aufruf an den Adapter übergeben haben, wird er stillschweigend überschrieben.
Der Vorteil der Verwendung von 'extra' ist, dass die Werte im Dictionary-ähnlichen Objekt in das __dict__ der LogRecord-Instanz eingefügt werden, wodurch Sie benutzerdefinierte Strings mit Ihren Formatter-Instanzen verwenden können, die die Schlüssel des Dictionary-ähnlichen Objekts kennen. Wenn Sie eine andere Methode benötigen, z. B. wenn Sie die Kontextinformationen am Anfang oder Ende des Nachrichtenstrings einfügen möchten, müssen Sie einfach LoggerAdapter unterklassifizieren und process() überschreiben, um das Gewünschte zu tun. Hier ist 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 Sie wie folgt verwenden können
logger = logging.getLogger(__name__)
adapter = CustomAdapter(logger, {'connid': some_conn_id})
Dann werden alle Ereignisse, die Sie an den Adapter protokollieren, den Wert von some_conn_id am Anfang der Log-Nachrichten haben.
Verwendung von Objekten anstelle von Dictionaries zur Übergabe von Kontextinformationen¶
Sie müssen kein tatsächliches Dictionary an einen LoggerAdapter übergeben – Sie könnten eine Instanz einer Klasse übergeben, die __getitem__ und __iter__ implementiert, so dass sie für das Logging wie ein Dictionary aussieht. Dies wäre nützlich, wenn Sie Werte dynamisch generieren möchten (während die Werte in einem Dictionary konstant wären).
Verwendung von Filtern zur Vermittlung von Kontextinformationen¶
Sie können Protokollausgaben auch durch benutzerdefinierte Filter mit Kontextinformationen anreichern. Filter-Instanzen dürfen die an sie übergebenen LogRecords modifizieren, einschließlich des Hinzufügens zusätzlicher Attribute, die dann mit einer geeigneten Formatzeichenkette oder, falls erforderlich, einem benutzerdefinierten Formatter ausgegeben werden können.
Zum Beispiel können in einer Webanwendung die gerade verarbeitete Anfrage (oder zumindest deren interessante Teile) in einer Thread-lokalen (threading.local) Variablen gespeichert und dann von einem Filter abgerufen werden, um dem LogRecord beispielsweise Informationen aus der Anfrage – wie die IP-Adresse des Remote-Hosts und den Benutzernamen des Remote-Benutzers – hinzuzufügen, und zwar mit den Attributnamen „ip“ und „user“ wie im obigen Beispiel mit LoggerAdapter. In diesem Fall kann dieselbe Formatzeichenkette verwendet werden, um eine ähnliche Ausgabe wie oben zu erhalten. Hier ist 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')
das 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 kontextlokale Speicherung, die sowohl für threading als auch für asyncio Verarbeitungsanforderungen funktioniert. Diese Art der Speicherung kann daher generell Thread-lokalen vorzuziehen sein. Das folgende Beispiel zeigt, wie in einer Multithread-Umgebung Protokolle mit Kontextinformationen wie beispielsweise Anfrageattributen, die von Webanwendungen verarbeitet werden, gefüllt werden können.
Zur Veranschaulichung: Nehmen wir an, Sie haben verschiedene Webanwendungen, jede unabhängig von der anderen, aber im selben Python-Prozess laufend und eine gemeinsame Bibliothek nutzend. Wie kann jede dieser Anwendungen ihre eigenen Protokolle haben, bei denen alle Protokollmeldungen von der Bibliothek (und anderem Anfrageverarbeitungscode) an die entsprechende Protokolldatei der Anwendung gesendet werden, während zusätzliche Kontextinformationen wie Client-IP, HTTP-Anfragemethode und Client-Benutzername im Protokoll enthalten sind?
Gehen wir davon aus, dass die Bibliothek durch den folgenden Code simuliert werden kann
# 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)
Wir können die mehreren Webanwendungen mithilfe von zwei einfachen Klassen, Request und WebApp, simulieren. Diese simulieren, wie echte, threadbasierte Webanwendungen funktionieren – 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()
Wenn Sie den obigen Code ausführen, sollten Sie feststellen, dass ungefähr die Hälfte der Anfragen in app1.log und der Rest in app2.log landet und alle Anfragen in app.log protokolliert werden. Jedes Webapp-spezifische Protokoll enthält nur Protokolleinträge für diese Webapp, und die Anfrageinformationen werden konsistent im Protokoll angezeigt (d. h. die Informationen in jeder Dummy-Anfrage erscheinen immer zusammen in einer Protokollzeile). Dies wird durch die folgende Shell-Ausgabe veranschaulicht
~/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 an Handler übermitteln¶
Jeder Handler hat seine eigene Kette von Filtern. Wenn Sie einem LogRecord Kontextinformationen hinzufügen möchten, ohne sie an andere Handler weiterzugeben, können Sie einen Filter verwenden, der einen neuen LogRecord zurückgibt, anstatt ihn direkt zu ändern, wie im folgenden Skript gezeigt
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')
Protokollierung in eine einzelne Datei aus mehreren Prozessen¶
Obwohl die Protokollierung Thread-sicher ist und die Protokollierung in eine einzelne Datei aus mehreren Threads in einem einzelnen Prozess unterstützt wird, wird die Protokollierung in eine einzelne Datei aus *mehreren Prozessen* *nicht* unterstützt, da es keinen Standardweg gibt, den Zugriff auf eine einzelne Datei über mehrere Prozesse in Python zu serialisieren. Wenn Sie aus mehreren Prozessen in eine einzelne Datei protokollieren müssen, ist eine Möglichkeit, dies zu erreichen, dass alle Prozesse in einen SocketHandler protokollieren und ein separater Prozess einen Socket-Server implementiert, der vom Socket liest und in die Datei protokolliert. (Wenn Sie möchten, können Sie einen Thread in einem der vorhandenen Prozesse widmen, um diese Funktion auszuführen.) Dieser Abschnitt dokumentiert diesen Ansatz ausführlicher und enthält einen funktionierenden Socket-Empfänger, der als Ausgangspunkt für Ihre eigenen Anwendungen dienen kann.
Sie könnten auch Ihren eigenen Handler schreiben, der die Lock-Klasse aus dem Modul multiprocessing verwendet, um den Zugriff auf die Datei von Ihren Prozessen zu serialisieren. Die FileHandler und deren Unterklassen aus der Standardbibliothek verwenden kein multiprocessing.
Alternativ können Sie eine Queue und einen QueueHandler verwenden, um alle Protokollereignisse an einen der Prozesse Ihrer Multi-Prozess-Anwendung zu senden. Das folgende Beispielskript zeigt, wie Sie dies tun können. Im Beispiel lauscht ein separater Listener-Prozess auf Ereignisse, die von anderen Prozessen gesendet werden, und protokolliert diese gemäß seiner eigenen Protokollkonfiguration. Obwohl das Beispiel nur eine Möglichkeit demonstriert (z. B. möchten Sie möglicherweise einen Listener-Thread anstelle eines separaten Listener-Prozesses verwenden – die Implementierung wäre analog), ermöglicht es vollständig unterschiedliche Protokollkonfigurationen für den Listener und die anderen Prozesse Ihrer Anwendung und kann als Grundlage für Code dienen, der Ihren spezifischen Anforderungen entspricht.
# 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 Variante des obigen Skripts behält die Protokollierung im Hauptprozess in einem separaten Thread bei
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 Variante zeigt, wie Sie z. B. Konfigurationen für bestimmte Logger anwenden können – z. B. hat der foo-Logger einen speziellen Handler, der alle Ereignisse im foo-Subsystem in einer Datei mplog-foo.log speichert. Dies wird von der Protokollierungsmaschine im Hauptprozess verwendet (auch wenn die Protokollereignisse in den Worker-Prozessen generiert werden), um die Nachrichten an die entsprechenden Ziele zu leiten.
Verwendung von concurrent.futures.ProcessPoolExecutor¶
Wenn Sie concurrent.futures.ProcessPoolExecutor zum Starten Ihrer Worker-Prozesse verwenden möchten, müssen Sie die Warteschlange etwas anders erstellen. Anstatt
queue = multiprocessing.Queue(-1)
sollten Sie verwenden
queue = multiprocessing.Manager().Queue(-1) # also works with the examples above
und Sie können dann die Worker-Erstellung von diesem
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()
zu diesem ändern (und denken Sie 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 bereitstellen¶
Beim Bereitstellen von Webanwendungen mit Gunicorn oder uWSGI (oder ähnlichem) werden mehrere Worker-Prozesse erstellt, um Client-Anfragen zu bearbeiten. Vermeiden Sie in solchen Umgebungen das Erstellen von dateibasierten Handlern direkt in Ihrer Webanwendung. Verwenden Sie stattdessen einen SocketHandler, um von der Webanwendung an einen Listener in einem separaten Prozess zu protokollieren. Dies kann mit einem Prozessmanagement-Tool wie Supervisor eingerichtet werden – siehe Running a logging socket listener in production für weitere Details.
Dateirotation verwenden¶
Manchmal möchten Sie, dass eine Protokolldatei eine bestimmte Größe erreicht, dann eine neue Datei öffnet und dorthin schreibt. Möglicherweise möchten Sie eine bestimmte Anzahl dieser Dateien aufbewahren, und wenn diese Anzahl von Dateien erreicht ist, sollen die Dateien rotiert werden, sodass sowohl die Anzahl der Dateien als auch die Größe der Dateien begrenzt bleiben. Für dieses Nutzungsmuster stellt das Protokollierungsmodul einen RotatingFileHandler bereit
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 separate Dateien sein, jede mit einem Teil der Protokollhistorie 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 aktuellste Datei ist immer logging_rotatingfile_example.out, und jedes Mal, wenn sie die Größenbeschränkung erreicht, wird sie mit dem Suffix .1 umbenannt. Jede der vorhandenen Sicherungsdateien wird umbenannt, um das Suffix zu erhöhen (aus .1 wird .2 usw.), und die Datei .6 wird gelöscht.
Offensichtlich ist die Protokollänge in diesem Beispiel extrem klein gewählt. Sie möchten maxBytes auf einen geeigneten Wert setzen.
Verwendung alternativer Formatierungsstile¶
Als die Protokollierung in die Python-Standardbibliothek aufgenommen wurde, war die einzige Möglichkeit, Nachrichten mit variablem Inhalt zu formatieren, die %-Formatierung zu verwenden. Seitdem hat Python zwei neue Formatierungsansätze erhalten: string.Template (eingeführt in Python 2.4) und str.format() (eingeführt in Python 2.6).
Logging (ab Version 3.2) bietet eine verbesserte Unterstützung für diese beiden zusätzlichen Formatierungsstile. Die Klasse Formatter wurde erweitert, um einen zusätzlichen optionalen Schlüsselwortparameter namens style zu akzeptieren. Dieser hat standardmäßig den Wert '%', aber andere mögliche Werte sind '{' und '$', die den beiden anderen Formatierungsstilen entsprechen. Die Abwärtskompatibilität wird standardmäßig beibehalten (wie Sie erwarten würden), aber durch explizites Angeben eines Stilparameters erhalten Sie die Möglichkeit, Formatzeichenketten anzugeben, die mit str.format() oder string.Template funktionieren. Hier ist eine Beispiel-Konsolensitzung, um die Möglichkeiten zu zeigen
>>> 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
>>>
Beachten Sie, dass die Formatierung von Protokollmeldungen für die endgültige Ausgabe in Protokollen völlig unabhängig davon ist, wie eine einzelne Protokollmeldung konstruiert wird. Diese kann immer noch %-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
>>>
Protokollaufrufe (logger.debug(), logger.info() usw.) akzeptieren nur Positionsargumente für die eigentliche Protokollmeldung selbst, wobei Schlüsselwortargumente nur zur Bestimmung von Optionen zur Handhabung des eigentlichen Protokollaufrufs verwendet werden (z. B. der Schlüsselwortparameter exc_info, um anzugeben, dass Traceback-Informationen protokolliert werden sollen, oder der Schlüsselwortparameter extra, um anzugeben, dass zusätzliche Kontextinformationen zum Protokoll hinzugefügt werden sollen). Sie können also nicht direkt Protokollaufrufe mit str.format() oder string.Template-Syntax verwenden, da das Protokollierungsmodul intern %-Formatierung verwendet, um die Formatzeichenkette und die variablen Argumente zusammenzuführen. Daran ließe sich nichts ändern, ohne die Abwärtskompatibilität zu beeinträchtigen, da alle Protokollaufrufe, die im vorhandenen Code vorhanden sind, %-Formatzeichenketten verwenden.
Es gibt jedoch eine Möglichkeit, mit {}- und $-Formatierung Ihre einzelnen Protokollmeldungen zu konstruieren. Erinnern Sie sich, dass Sie für eine Nachricht ein beliebiges Objekt als Nachrichtenformatzeichenkette verwenden können und dass das Protokollierungsmodul str() für dieses Objekt aufruft, um die tatsächliche Formatzeichenkette zu erhalten. Betrachten Sie 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)
Jede dieser Klassen kann anstelle einer Formatzeichenkette verwendet werden, um die {}- oder $-Formatierung zur Erstellung des eigentlichen „Nachrichtenteils“ zu ermöglichen, der in der formatierten Protokollausgabe anstelle von „%(message)s“ oder „{message}“ oder „$message“ erscheint. Es ist etwas umständlich, die Klassennamen jedes Mal zu verwenden, wenn Sie etwas protokollieren möchten, aber es ist recht erträglich, wenn Sie einen Alias wie __ (doppeltes Unterstrich – nicht zu verwechseln mit _, dem einfachen Unterstrich, der als Synonym/Alias für gettext.gettext() oder seine Geschwister verwendet wird) verwenden.
Die obigen Klassen sind nicht in Python enthalten, obwohl sie einfach genug sind, um sie in Ihren eigenen Code zu kopieren und einzufügen. Sie können wie folgt verwendet werden (angenommen, sie sind in einem Modul namens irgendwo deklariert)
>>> 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
>>>
Während die obigen Beispiele print() verwenden, um zu zeigen, wie die Formatierung funktioniert, würden Sie natürlich logger.debug() oder ähnliches verwenden, um tatsächlich mit diesem Ansatz zu protokollieren.
Eine Sache, die man beachten sollte, ist, dass Sie bei diesem Ansatz keine signifikanten Leistungseinbußen haben: Die eigentliche Formatierung erfolgt nicht, wenn Sie den Protokollaufruf tätigen, sondern wenn (und falls) die protokollierte Nachricht tatsächlich von einem Handler an ein Protokoll ausgegeben wird. Das Einzige, was Sie vielleicht stolpern lässt, ist, dass die Klammern um die Formatzeichenkette und die Argumente gehen, nicht nur um die Formatzeichenkette. Das liegt daran, dass die __-Notation nur Zucker für einen Konstruktoraufruf zu einer der XXXMessage-Klassen ist.
Wenn Sie es vorziehen, können Sie einen LoggerAdapter verwenden, um einen ähnlichen Effekt wie oben zu erzielen, 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 Nachricht Hello, world! protokollieren, wenn es mit Python 3.8 oder neuer ausgeführt wird.
Anpassen von LogRecord¶
Jedes Protokollereignis wird durch eine Instanz von LogRecord dargestellt. Wenn ein Ereignis protokolliert und nicht durch die Stufe eines Loggers gefiltert wird, wird ein LogRecord erstellt, mit Informationen über das Ereignis gefüllt und dann an die Handler für diesen Logger (und seine Vorfahren, bis hin zum Logger, bei dem die weitere Weitergabe in der Hierarchie deaktiviert ist) übergeben. Vor Python 3.2 gab es nur zwei Stellen, an denen diese Erstellung erfolgte
Logger.makeRecord(), die im normalen Prozess der Protokollierung eines Ereignisses aufgerufen wird. Diese riefLogRecorddirekt auf, um eine Instanz zu erstellen.makeLogRecord(), die mit einem Dictionary aufgerufen wird, das Attribute enthält, die dem LogRecord hinzugefügt werden sollen. Dies wird typischerweise aufgerufen, wenn ein entsprechendes Dictionary über das Netzwerk empfangen wurde (z. B. im Pickle-Format über einenSocketHandleroder im JSON-Format über einenHTTPHandler).
Das bedeutete normalerweise, dass Sie, wenn Sie etwas Besonderes mit einem LogRecord machen mussten, eines der folgenden Dinge tun mussten.
Erstellen Sie Ihre eigene
Logger-Unterklasse, dieLogger.makeRecord()überschreibt, und setzen Sie sie mitsetLoggerClass(), bevor irgendwelche Logger, die Sie interessieren, instanziiert werden.Fügen Sie einen
Filterzu einem Logger oder Handler hinzu, der die notwendige spezielle Manipulation vornimmt, wenn seinefilter()-Methode aufgerufen wird.
Der erste Ansatz wäre im Szenario, in dem (sagen wir) mehrere verschiedene Bibliotheken unterschiedliche Dinge tun möchten, etwas umständlich. Jede würde versuchen, ihre eigene Logger-Unterklasse zu setzen, und diejenige, die dies zuletzt tut, würde gewinnen.
Der zweite Ansatz funktioniert für viele Fälle recht gut, erlaubt aber nicht z. B. die Verwendung einer spezialisierten Unterklasse von LogRecord. Bibliotheksentwickler können einen geeigneten Filter auf ihre Logger setzen, müssten aber daran denken, dies jedes Mal zu tun, wenn sie einen neuen Logger einführen (was sie einfach durch Hinzufügen neuer Pakete oder Module und das Ausführen von
logger = logging.getLogger(__name__)
auf Modulebene tun würden). Das sind wahrscheinlich zu viele Dinge, über die man nachdenken muss. Entwickler könnten auch einen Filter zu einem NullHandler hinzufügen, der an ihren Top-Level-Logger angehängt ist, aber dieser würde nicht aufgerufen, wenn ein Anwendungsentwickler einen Handler an einen Library-Logger auf niedrigerer Ebene anhängt – die Ausgabe dieses Handlers würde also nicht die Absichten des Library-Entwicklers widerspiegeln.
In Python 3.2 und höher wird die Erstellung von LogRecord über eine Factory abgewickelt, die Sie angeben können. Die Factory ist nur ein aufrufbares Objekt, das Sie mit setLogRecordFactory() einstellen und mit getLogRecordFactory() abfragen können. Die Factory wird mit derselben Signatur wie der Konstruktor von LogRecord aufgerufen, da LogRecord die Standardeinstellung für die Factory ist.
Dieser Ansatz ermöglicht einer benutzerdefinierten Factory, alle Aspekte der LogRecord-Erstellung zu steuern. Sie könnten beispielsweise eine Unterklasse zurückgeben oder einfach einige zusätzliche Attribute zum Record hinzufügen, sobald er erstellt ist, mit einem Muster, das diesem hier ähnelt
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 ermöglicht es verschiedenen Bibliotheken, Factories zu verketten, und solange sie sich nicht gegenseitig Attribute überschreiben oder versehentlich die Standardattribute überschreiben, sollte es keine Überraschungen geben. Es ist jedoch zu bedenken, dass jedes Glied in der Kette Laufzeit-Overhead für alle Protokolloperationen verursacht und die Technik nur verwendet werden sollte, wenn die Verwendung eines Filter nicht das gewünschte Ergebnis liefert.
QueueHandler und QueueListener unterklassifizieren – ein ZeroMQ-Beispiel¶
QueueHandler unterklassifizieren¶
Sie können eine Unterklasse von QueueHandler verwenden, um Nachrichten an andere Arten von Queues zu senden, z. B. an einen ZeroMQ „publish“-Socket. Im folgenden Beispiel wird der Socket separat erstellt und an den Handler übergeben (als dessen „queue“)
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 Möglichkeiten, dies zu organisieren, zum Beispiel das Übergeben der Daten, die der Handler benötigt, um den Socket zu erstellen
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()
QueueListener unterklassifizieren¶
Sie können auch QueueListener unterklassifizieren, um Nachrichten von anderen Arten von Queues zu empfangen, z. B. von einem ZeroMQ „subscribe“-Socket. Hier ist 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)
QueueHandler und QueueListener unterklassifizieren – ein pynng-Beispiel¶
Ähnlich wie im obigen Abschnitt können wir einen Listener und Handler mit pynng implementieren, das eine Python-Bindung zu NNG ist, das als spiritueller Nachfolger von ZeroMQ angepriesen wird. Die folgenden Snippets veranschaulichen dies – Sie können sie in einer Umgebung testen, in der pynng installiert ist. Nur zur Abwechslung präsentieren wir zuerst den Listener.
QueueListener unterklassifizieren¶
# listener.py
import json
import logging
import logging.handlers
import pynng
DEFAULT_ADDR = "tcp://:13232"
interrupted = False
class NNGSocketListener(logging.handlers.QueueListener):
def __init__(self, uri, /, *handlers, **kwargs):
# Have a timeout for interruptability, 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()
QueueHandler unterklassifizieren¶
# sender.py
import json
import logging
import logging.handlers
import time
import random
import pynng
DEFAULT_ADDR = "tcp://: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)
Sie können die beiden obigen Snippets in separaten Kommandozeilen ausführen. Wenn wir den Listener in einer Shell ausführen und den Sender in zwei separaten Shells ausführen, sollten wir etwas Ähnliches wie das Folgende sehen. In der ersten Sender-Shell
$ 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)
In der zweiten Sender-Shell
$ 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)
In der Listener-Shell
$ 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 Sie sehen können, sind die Protokolle der beiden Sender-Prozesse in der Ausgabe des Listeners verschachtelt.
Ein Beispiel für eine wörterbuchbasierte Konfiguration¶
Unten ist ein Beispiel für ein Protokollkonfigurationswörterbuch – es stammt aus der Dokumentation des Django-Projekts. Dieses Wörterbuch wird an dictConfig() übergeben, um die Konfiguration in Kraft zu setzen
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']
}
}
}
Für weitere Informationen zu dieser Konfiguration können Sie sich den relevanten Abschnitt der Django-Dokumentation ansehen.
Verwendung eines Rotators und Namers zur Anpassung der Log-Rotationsverarbeitung¶
Ein Beispiel dafür, wie Sie einen Namer und Rotator definieren können, finden Sie im folgenden ausführbaren Skript, das die Gzip-Kompression der Protokolldatei zeigt
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}')
Nachdem Sie dies ausgeführt haben, sehen Sie 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 aufwändigeres Multiprocessing-Beispiel¶
Das folgende funktionierende Beispiel zeigt, wie Logging mit Multiprocessing unter Verwendung von Konfigurationsdateien genutzt werden kann. Die Konfigurationen sind recht einfach, dienen aber dazu, zu veranschaulichen, wie komplexere Konfigurationen in einem realen Multiprocessing-Szenario implementiert werden könnten.
Im Beispiel erzeugt der Hauptprozess einen Listener-Prozess und einige Worker-Prozesse. Jeder der Hauptprozesse, der Listener und die Worker haben drei separate Konfigurationen (die Worker teilen sich alle die gleiche Konfiguration). Wir sehen Logging im Hauptprozess, wie die Worker in einen QueueHandler protokollieren und wie der Listener einen QueueListener und eine komplexere Protokollkonfiguration implementiert und Ereignisse, die über die Warteschlange empfangen werden, an die in der Konfiguration angegebenen Handler weiterleitet. Beachten Sie, dass diese Konfigurationen rein illustrativ sind, aber Sie sollten dieses Beispiel an Ihr eigenes Szenario anpassen können.
Hier ist das Skript – die Docstrings und Kommentare erklären hoffentlich, wie es funktioniert
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()
Einfügen eines BOM in Nachrichten, die an SysLogHandler gesendet werden¶
RFC 5424 verlangt, dass eine Unicode-Nachricht an einen Syslog-Daemon als Byte-Sequenz gesendet wird, die folgende Struktur hat: eine optionale reine ASCII-Komponente, gefolgt von einem UTF-8 Byte Order Mark (BOM), gefolgt von Unicode, das mittels UTF-8 kodiert ist. (Siehe den relevanten Abschnitt der Spezifikation.)
In Python 3.1 wurde Code zu SysLogHandler hinzugefügt, um einen BOM in die Nachricht einzufügen, aber leider wurde er falsch implementiert, sodass der BOM am Anfang der Nachricht erschien und somit keine reine ASCII-Komponente davor stehen konnte.
Da dieses Verhalten fehlerhaft ist, wird der fehlerhafte BOM-Einfügungscode ab Python 3.2.4 entfernt. Er wird jedoch nicht ersetzt, und wenn Sie RFC 5424-konforme Nachrichten erstellen möchten, die einen BOM, eine optionale reine ASCII-Sequenz davor und beliebiges Unicode danach, alles in UTF-8 kodiert, enthalten, müssen Sie Folgendes tun
Fügen Sie eine Instanz von
Formatteran Ihre Instanz vonSysLogHandleran, mit einer Formatzeichenkette wie'ASCII section\ufeffUnicode section'
Der Unicode-Codepunkt U+FEFF wird, wenn er mit UTF-8 kodiert wird, als UTF-8 BOM kodiert – die Byte-Sequenz
b'\xef\xbb\xbf'.Ersetzen Sie den ASCII-Teil durch beliebige Platzhalter, aber stellen Sie sicher, dass die Daten, die dort nach der Ersetzung erscheinen, immer ASCII sind (dadurch bleiben sie nach der UTF-8-Kodierung unverändert).
Ersetzen Sie den Unicode-Teil durch beliebige Platzhalter; wenn die Daten, die dort nach der Ersetzung erscheinen, Zeichen außerhalb des ASCII-Bereichs enthalten, ist das in Ordnung – sie werden mit UTF-8 kodiert.
Die formatierte Nachricht wird von SysLogHandler mittels UTF-8-Kodierung kodiert. Wenn Sie die obigen Regeln befolgen, sollten Sie RFC 5424-konforme Nachrichten erstellen können. Wenn Sie dies nicht tun, wird Logging möglicherweise nicht meckern, aber Ihre Nachrichten werden nicht RFC 5424-konform sein, und Ihr Syslog-Daemon könnte meckern.
Implementierung von strukturiertem Logging¶
Obwohl die meisten Protokollmeldungen für die Lesbarkeit durch Menschen bestimmt sind und daher nicht ohne Weiteres maschinell auswertbar sind, kann es Umstände geben, unter denen Sie Meldungen in einem strukturierten Format ausgeben möchten, das von einem Programm *ausgewertet* werden kann (ohne komplexe reguläre Ausdrücke zum Parsen der Protokollmeldung zu benötigen). Dies ist mit dem Logging-Paket einfach zu erreichen. Es gibt eine Reihe von Möglichkeiten, wie dies erreicht werden könnte, aber der folgende Ansatz ist ein einfacher, der JSON zur Serialisierung des Ereignisses in einer maschinenlesbaren Weise verwendet
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))
Wenn das obige Skript ausgeführt wird, gibt es Folgendes aus
message 1 >>> {"fnum": 123.456, "num": 123, "bar": "baz", "foo": "bar"}
Beachten Sie, dass die Reihenfolge der Elemente je nach Python-Version unterschiedlich sein kann.
Wenn Sie eine speziellere Verarbeitung benötigen, können Sie einen benutzerdefinierten JSON-Encoder 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()
Wenn das obige Skript ausgeführt wird, gibt es Folgendes aus
message 1 >>> {"snowman": "\u2603", "set_value": [1, 2, 3]}
Beachten Sie, dass die Reihenfolge der Elemente je nach Python-Version unterschiedlich sein kann.
Anpassen von Handlern mit dictConfig()¶
Es gibt Zeiten, in denen Sie Protokollhandler auf besondere Weise anpassen möchten, und wenn Sie dictConfig() verwenden, können Sie dies möglicherweise tun, ohne zu unterklassifizieren. Als Beispiel betrachten wir, dass Sie den Eigentümer einer Protokolldatei festlegen möchten. Unter POSIX lässt sich dies leicht mit shutil.chown() bewerkstelligen, aber die Dateihandler in der Standardbibliothek bieten keine integrierte Unterstützung. Sie können die Handler-Erstellung mit einer einfachen Funktion wie dieser anpassen
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)
Sie können dann in einer Protokollkonfiguration, die an dictConfig() übergeben wird, angeben, dass ein Protokollhandler durch Aufrufen dieser Funktion erstellt werden soll
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 Besitz mit dem Benutzer und der Gruppe pulse, nur zu Illustrationszwecken. Zusammengefügt in ein funktionierendes Skript, 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 dies auszuführen, müssen Sie es wahrscheinlich als root ausführen
$ 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
Beachten Sie, dass dieses Beispiel Python 3.3 verwendet, da dort shutil.chown() auftaucht. Dieser Ansatz sollte mit jeder Python-Version funktionieren, die dictConfig() unterstützt - nämlich Python 2.7, 3.2 oder neuer. Mit Versionen vor 3.3 müssten Sie die eigentliche Besitzänderung z. B. mit os.chown() implementieren.
In der Praxis kann sich die Handler-Erzeugungsfunktion irgendwo in Ihrem Projekt in einem Utility-Modul befinden. Anstelle der Zeile in der Konfiguration
'()': owned_file_handler,
könnten Sie z. B. verwenden
'()': 'ext://project.util.owned_file_handler',
wobei project.util durch den tatsächlichen Namen des Pakets ersetzt werden kann, in dem sich die Funktion befindet. Im obigen funktionierenden Skript sollte die Verwendung von 'ext://__main__.owned_file_handler' funktionieren. Hier wird der eigentliche aufrufbare Wert von dictConfig() aus der ext://-Spezifikation aufgelöst.
Dieses Beispiel weist hoffentlich auch den Weg, wie Sie andere Arten von Dateiänderungen - z. B. das Setzen spezifischer POSIX-Berechtigungsbits - auf dieselbe Weise mit os.chmod() implementieren könnten.
Selbstverständlich könnte der Ansatz auch auf andere Handler-Typen als einen FileHandler erweitert werden - zum Beispiel auf einen der rotierenden Dateihandler oder auf einen ganz anderen Handler-Typ.
Verwendung bestimmter Formatierungsstile in Ihrer gesamten Anwendung¶
In Python 3.2 erhielt der Formatter einen Schlüsselwortparameter style, der, obwohl er aus Kompatibilitätsgründen standardmäßig auf % gesetzt war, die Angabe von { oder $ ermöglichte, um die von str.format() und string.Template unterstützten Formatierungsansätze zu unterstützen. Beachten Sie, dass dies die Formatierung von Protokollnachrichten für die endgültige Ausgabe in Protokolldateien steuert und völlig unabhängig davon ist, wie eine einzelne Protokollnachricht konstruiert wird.
Logging-Aufrufe (debug(), info() etc.) nehmen nur Positionsargumente für die eigentliche Protokollnachricht selbst entgegen, wobei Schlüsselwortargumente nur zur Bestimmung von Optionen für die Behandlung des Protokollaufrufs verwendet werden (z. B. der Schlüsselwortparameter exc_info, um anzuzeigen, dass Traceback-Informationen protokolliert werden sollen, oder der Schlüsselwortparameter extra, um zusätzliche Kontextinformationen anzugeben, die zum Protokoll hinzugefügt werden sollen). Sie können also nicht direkt Protokollaufrufe mit der Syntax von str.format() oder string.Template tätigen, da das Logging-Paket intern %-Formatierung verwendet, um die Formatzeichenkette und die variablen Argumente zusammenzuführen. Daran würde nichts geändert werden können, um die Abwärtskompatibilität zu erhalten, da alle Protokollaufrufe, die in bestehendem Code vorhanden sind, %-Formatzeichenketten verwenden werden.
Es gab Vorschläge, Formatierungsstile bestimmten Loggern zuzuordnen, aber dieser Ansatz stößt ebenfalls auf Probleme mit der Abwärtskompatibilität, da jeder vorhandene Code einen bestimmten Loggernamen und %-Formatierung verwenden könnte.
Damit das Logging interoperabel zwischen Drittanbieterbibliotheken und Ihrem Code funktioniert, müssen Entscheidungen über die Formatierung auf der Ebene des einzelnen Protokollaufrufs getroffen werden. Dies eröffnet einige Möglichkeiten, alternative Formatierungsstile unterzubringen.
Verwendung von LogRecord-Fabriken¶
In Python 3.2 erhielt das Logging-Paket zusammen mit den oben genannten Änderungen am Formatter die Möglichkeit, eigene LogRecord-Unterklassen mithilfe der Funktion setLogRecordFactory() festzulegen. Sie können dies verwenden, um Ihre eigene Unterklasse von LogRecord festzulegen, die das Richtige tut, indem sie die Methode getMessage() überschreibt. Die Implementierung dieser Methode in der Basisklasse ist der Ort, an dem die Formatierung msg % args stattfindet und wo Sie Ihre alternativen Formate einfügen können. Sie sollten jedoch darauf achten, alle Formatierungsstile zu unterstützen und die %-Formatierung als Standard zuzulassen, um die Interoperabilität mit anderem Code zu gewährleisten. Es sollte auch darauf geachtet werden, str(self.msg) aufzurufen, genau wie die Basisimplementierung.
Weitere Informationen finden Sie in der Referenzdokumentation zu setLogRecordFactory() und LogRecord.
Verwendung benutzerdefinierter Nachrichtenobjekte¶
Es gibt eine weitere, vielleicht einfachere Möglichkeit, {}- und $-Formatierungen zu verwenden, um Ihre einzelnen Protokollnachrichten zu erstellen. Sie erinnern sich vielleicht (aus Verwendung beliebiger Objekte als Nachrichten), dass Sie beim Protokollieren ein beliebiges Objekt als Nachrichtenformatzeichenkette verwenden können und dass das Logging-Paket str() auf dieses Objekt aufruft, um die tatsächliche Formatzeichenkette zu erhalten. Betrachten Sie die folgenden beiden 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)
Jeder dieser beiden kann anstelle einer Formatzeichenkette verwendet werden, um die Verwendung von {}- oder $-Formatierungen zur Erstellung der eigentlichen "Nachricht" zu ermöglichen, die in der formatierten Protokollausgabe anstelle von "%(message)s" oder "{message}" oder "$message" erscheint. Wenn Sie es etwas umständlich finden, die Klassennamen zu verwenden, wann immer Sie etwas protokollieren möchten, können Sie es erträglicher machen, wenn Sie einen Alias wie M oder _ für die Nachricht verwenden (oder vielleicht __, wenn Sie _ für die Lokalisierung verwenden).
Beispiele für diesen Ansatz finden Sie unten. Erstens, 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)
Zweitens, Formatierung mit string.Template
>>> __ = DollarMessage
>>> print(__('Message with $num $what', num=2, what='placeholders'))
Message with 2 placeholders
>>>
Eine Sache zu beachten ist, dass Sie bei diesem Ansatz keine signifikanten Leistungseinbußen haben: die eigentliche Formatierung erfolgt nicht, wenn Sie den Protokollaufruf tätigen, sondern wenn (und ob) die protokollierte Nachricht tatsächlich von einem Handler ausgegeben wird. Das einzig etwas Ungewöhnliche, das Sie stolpern lassen könnte, ist, dass die Klammern um die Formatzeichenkette und die Argumente gehen, nicht nur um die Formatzeichenkette. Das liegt daran, dass die __-Notation nur eine syntaktische Zuckerung für einen Konstruktoraufruf einer der oben gezeigten XXXMessage-Klassen ist.
Konfiguration von Filtern mit dictConfig()¶
Sie *können* Filter mit dictConfig() konfigurieren, obwohl es auf den ersten Blick vielleicht nicht offensichtlich ist, wie das geht (daher dieses Rezept). Da Filter die einzige Filterklasse ist, die in der Standardbibliothek enthalten ist, und diese unwahrscheinlich viele Anforderungen erfüllt (sie ist nur als Basisklasse vorhanden), müssen Sie typischerweise Ihre eigene Filter-Unterklasse mit einer überschriebenen filter()-Methode definieren. Um dies zu tun, geben Sie den Schlüssel () im Konfigurationswörterbuch für den Filter an, das einen Aufruf angibt, der zur Erstellung des Filters verwendet wird (eine Klasse ist am offensichtlichsten, aber Sie können jeden Aufruf bereitstellen, der eine Instanz von Filter zurückgibt). Hier ist 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 Sie Konfigurationsdaten an den Aufruf übergeben können, der die Instanz konstruiert, in Form von Schlüsselwortparametern. Beim Ausführen druckt das obige Skript
changed: hello
was zeigt, dass der Filter wie konfiguriert funktioniert.
Ein paar zusätzliche Punkte, die zu beachten sind
Wenn Sie den Aufruf nicht direkt in der Konfiguration referenzieren können (z. B. wenn er sich in einem anderen Modul befindet und Sie ihn nicht direkt dort importieren können, wo sich das Konfigurationswörterbuch befindet), können Sie die Form
ext://...verwenden, wie in Zugriff auf externe Objekte beschrieben. Zum Beispiel hätten Sie anstelle vonMyFilterim obigen Beispiel den Text'ext://__main__.MyFilter'verwenden können.Neben Filtern kann diese Technik auch zur Konfiguration benutzerdefinierter Handler und Formatierer verwendet werden. Siehe Benutzerdefinierte Objekte für weitere Informationen darüber, wie Logging die Verwendung benutzerdefinierter Objekte in seiner Konfiguration unterstützt, und siehe das andere Cookbook-Rezept Benutzerdefinierte Handler mit dictConfig() oben.
Benutzerdefinierte Ausnahmeformatierung¶
Es kann vorkommen, dass Sie eine benutzerdefinierte Ausnahmeformatierung wünschen - sagen wir, um ein Beispiel zu geben, dass Sie genau eine Zeile pro protokolliertem Ereignis wünschen, selbst wenn Ausnahminformationen vorhanden sind. Dies können Sie mit einer benutzerdefinierten Formatter-Klasse tun, wie im folgenden Beispiel gezeigt
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 erzeugt dies 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'|
Während die obige Behandlung vereinfacht ist, weist sie den Weg, wie Ausnahminformationen nach Ihren Wünschen formatiert werden können. Das Modul traceback kann für spezialisiertere Bedürfnisse hilfreich sein.
Protokollnachrichten sprechen lassen¶
Es kann Situationen geben, in denen es wünschenswert ist, Protokollnachrichten akustisch statt visuell darzustellen. Dies ist einfach möglich, wenn Text-to-Speech (TTS)-Funktionalität in Ihrem System verfügbar ist, auch wenn diese keine Python-Bindung hat. Die meisten TTS-Systeme verfügen über ein Kommandozeilenprogramm, das Sie ausführen können, und dieses kann von einem Handler aus mit subprocess aufgerufen werden. Hier wird davon ausgegangen, dass Kommandozeilenprogramme für TTS keine Interaktion mit Benutzern erwarten oder lange zur Fertigstellung benötigen, und dass die Häufigkeit der protokollierten Nachrichten nicht so hoch ist, dass der Benutzer mit Nachrichten überflutet wird, und dass es akzeptabel ist, dass die Nachrichten nacheinander und nicht gleichzeitig gesprochen werden. Die nachfolgende Beispielimplementierung wartet, bis eine Nachricht gesprochen wurde, bevor die nächste verarbeitet wird, und dies könnte dazu führen, dass andere Handler warten müssen. Hier ist ein kurzes Beispiel, das den Ansatz zeigt, der davon ausgeht, dass das espeak TTS-Paket verfügbar 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 dieses Skripts sollte "Hello" und dann "Goodbye" in einer weiblichen Stimme gesprochen werden.
Der obige Ansatz kann natürlich an andere TTS-Systeme und sogar an andere Systeme angepasst werden, die Nachrichten über externe Programme verarbeiten können, die über die Kommandozeile ausgeführt werden.
Protokollnachrichten puffern und bedingt ausgeben¶
Es kann Situationen geben, in denen Sie Nachrichten in einem temporären Bereich protokollieren und sie nur ausgeben möchten, wenn eine bestimmte Bedingung eintritt. Sie möchten vielleicht Debug-Ereignisse in einer Funktion protokollieren, und wenn die Funktion ohne Fehler abgeschlossen wird, möchten Sie das Protokoll nicht mit den gesammelten Debug-Informationen überladen, aber wenn ein Fehler auftritt, möchten Sie alle Debug-Informationen sowie den Fehler ausgeben.
Hier ist ein Beispiel, das zeigt, wie Sie dies mit einem Dekorator für Ihre Funktionen tun könnten, bei denen das Protokollieren auf diese Weise verhalten soll. Es nutzt den logging.handlers.MemoryHandler, der das Puffern von protokollierten Ereignissen ermöglicht, bis eine bestimmte Bedingung eintritt, zu welchem Zeitpunkt die gepufferten Ereignisse flushed werden - an einen anderen Handler (den target-Handler) zur Verarbeitung weitergeleitet werden. Standardmäßig wird der MemoryHandler geleert, wenn sein Puffer voll ist oder ein Ereignis mit einem Pegel, der größer oder gleich einem angegebenen Schwellenwert ist, gesehen wird. Sie können dieses Rezept mit einer spezialisierteren Unterklasse von MemoryHandler verwenden, wenn Sie ein benutzerdefiniertes Leerungsverhalten wünschen.
Das Beispielskript enthält eine einfache Funktion, foo, die einfach alle Protokollierungsstufen durchläuft und nach sys.stderr schreibt, um zu sagen, auf welcher Stufe sie protokollieren wird, und dann tatsächlich eine Nachricht auf dieser Stufe protokolliert. Sie können einen Parameter an foo übergeben, der, wenn er wahr ist, auf den Stufen ERROR und CRITICAL protokolliert - andernfalls protokolliert er nur auf den Stufen DEBUG, INFO und WARNING.
Das Skript arrangiert lediglich, foo mit einem Dekorator zu versehen, der die erforderliche bedingte Protokollierung vornimmt. Der Dekorator nimmt einen Logger als Parameter entgegen und fügt während der Dauer des Aufrufs der dekorierten Funktion einen Speicherhandler hinzu. Der Dekorator kann zusätzlich mit einem Zielhandler, einer Stufe, auf der geleert werden soll, und einer Kapazität für den Puffer (Anzahl der gepufferten Datensätze) parametrisiert werden. Diese sind standardmäßig ein StreamHandler, der nach sys.stderr schreibt, logging.ERROR und 100 jeweils.
Hier ist 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)
Wenn dieses Skript ausgeführt wird, sollte die folgende Ausgabe beobachtet werden
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 Sie sehen, erfolgt die eigentliche Protokollausgabe nur, wenn ein Ereignis protokolliert wird, dessen Schweregrad ERROR oder höher ist, aber in diesem Fall werden auch alle vorherigen Ereignisse mit niedrigeren Schweregraden protokolliert.
Sie können natürlich die üblichen Mittel der Dekoration verwenden
@log_if_errors(logger)
def foo(fail=False):
...
Protokollnachrichten per E-Mail senden, mit Pufferung¶
Um zu veranschaulichen, wie Sie Protokollnachrichten per E-Mail senden können, sodass eine bestimmte Anzahl von Nachrichten pro E-Mail gesendet wird, können Sie von BufferingHandler ableiten. Im folgenden Beispiel, das Sie an Ihre spezifischen Bedürfnisse anpassen können, wird ein einfacher Test-Harness bereitgestellt, der es Ihnen ermöglicht, das Skript mit Kommandozeilenargumenten auszuführen, die angeben, was Sie typischerweise zum Versenden von Dingen über SMTP benötigen. (Führen Sie das heruntergeladene Skript mit dem Argument -h aus, um die erforderlichen und 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()
Wenn Sie dieses Skript ausführen und Ihr SMTP-Server korrekt eingerichtet ist, sollten Sie feststellen, dass es elf E-Mails an den von Ihnen angegebenen Empfänger sendet. Die ersten zehn E-Mails enthalten jeweils zehn Protokollnachrichten, und die elfte enthält zwei Nachrichten. Das ergibt 102 Nachrichten, wie im Skript angegeben.
Zeiten mit UTC (GMT) über die Konfiguration formatieren¶
Manchmal möchten Sie Zeiten mit UTC formatieren, was mit einer Klasse wie UTCFormatter, wie unten gezeigt, erfolgen kann
import logging
import time
class UTCFormatter(logging.Formatter):
converter = time.gmtime
und Sie können dann die UTCFormatter in Ihrem Code anstelle von Formatter verwenden. Wenn Sie dies über die Konfiguration tun möchten, können Sie die dictConfig() API mit einem Ansatz verwenden, der durch das folgende vollständige Beispiel veranschaulicht wird
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())
Wenn dieses Skript ausgeführt wird, sollte es etwas ausgeben wie
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 lokale Zeit als auch als UTC formatiert wird, eine für jeden Handler.
Verwendung eines Kontextmanagers für selektives Logging¶
Es gibt Zeiten, in denen es nützlich wäre, die Protokollkonfiguration vorübergehend zu ändern und sie nach Abschluss einer Aktion wiederherzustellen. Dafür ist ein Kontextmanager der offensichtlichste Weg, den Protokollkontext zu speichern und wiederherzustellen. Hier ist ein einfaches Beispiel für einen solchen Kontextmanager, der es Ihnen ermöglicht, optional die Protokollierungsstufe zu ändern und einen Protokollhandler rein im Gültigkeitsbereich des Kontextmanagers hinzuzufügen
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
Wenn Sie einen Pegelwert angeben, wird der Pegel des Loggers im Gültigkeitsbereich des With-Blocks auf diesen Wert gesetzt, der vom Kontextmanager abgedeckt wird. Wenn Sie einen Handler angeben, wird er beim Eintritt in den Block zum Logger hinzugefügt und beim Austritt aus dem Block entfernt. Sie können den Manager auch bitten, den Handler für Sie beim Blockaustritt zu schließen - Sie könnten dies tun, wenn Sie den Handler nicht mehr benötigen.
Um zu veranschaulichen, wie es funktioniert, können wir den folgenden Codeblock zum obigen hinzufügen
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.')
Wir setzen zunächst den Pegel des Loggers auf INFO, sodass Nachricht #1 erscheint und Nachricht #2 nicht. Dann ändern wir den Pegel vorübergehend auf DEBUG im folgenden with-Block, und so erscheint Nachricht #3. Nach dem Austritt aus dem Block wird der Logger-Pegel wieder auf INFO gesetzt, und so erscheint Nachricht #4 nicht. Im nächsten with-Block ändern wir den Pegel wieder auf DEBUG, fügen aber auch einen Handler hinzu, der nach sys.stdout schreibt. Daher erscheint Nachricht #5 zweimal auf der Konsole (einmal über stderr und einmal über stdout). Nach Abschluss der with-Anweisung ist der Status wie zuvor, sodass Nachricht #6 erscheint (wie Nachricht #1), während Nachricht #7 nicht erscheint (genau wie Nachricht #2).
Wenn wir das resultierende Skript ausführen, erhalten wir folgendes Ergebnis
$ 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.
Wenn wir es noch einmal ausführen, aber stderr nach /dev/null umleiten, sehen wir folgendes, was die einzige auf stdout geschriebene Nachricht ist
$ python logctx.py 2>/dev/null
5. This should appear twice - once on stderr and once on stdout.
Noch einmal, aber indem stdout nach /dev/null umgeleitet wird, 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 auf stdout ausgegebene Nachricht #5 nicht, wie erwartet.
Selbstverständlich kann der hier beschriebene Ansatz verallgemeinert werden, zum Beispiel um temporär Protokollfilter anzuhängen. Beachten Sie, dass der obige Code sowohl in Python 2 als auch in Python 3 funktioniert.
Eine Vorlage für CLI-Anwendungsstarter¶
Hier ist ein Beispiel, das zeigt, wie Sie
Einen Protokollierungspegel basierend auf Kommandozeilenargumenten verwenden
An mehrere Unterbefehle in separaten Dateien verteilen, die alle auf dem gleichen Pegel und auf konsistente Weise protokollieren
Einfache, minimale Konfiguration nutzen
Nehmen wir an, wir haben eine Kommandozeilenanwendung, deren Aufgabe es ist, Dienste zu stoppen, zu starten oder neu zu starten. Dies könnte zur Veranschaulichung als Datei app.py organisiert werden, die das Hauptskript für die Anwendung ist, wobei einzelne Befehle in start.py, stop.py und restart.py implementiert sind. Nehmen wir weiter an, wir möchten die Ausführlichkeit der Anwendung über ein Kommandozeilenargument steuern, standardmäßig auf logging.INFO. Hier ist eine Möglichkeit, wie app.py geschrieben werden könnte
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 können in separaten Modulen implementiert werden, wie hier für das Starten
# 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 somit für das Stoppen
# 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 ähnlich für das 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)
Wenn wir diese Anwendung mit dem Standard-Log-Pegel ausführen, 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 Protokollierungspegel, und das zweite Wort ist der Modul- oder Paketname der Stelle, an der das Ereignis protokolliert wurde.
Wenn wir den Protokollierungspegel ändern, können wir die an das Protokoll gesendeten Informationen ändern. Zum Beispiel, wenn wir mehr Informationen wünschen
$ 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 wenn wir weniger wollen
$ 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, da von ihnen nichts auf dem Pegel WARNING oder höher protokolliert wird.
Ein Qt-GUI für Logging¶
Eine Frage, die von Zeit zu Zeit auftaucht, ist, wie man in eine GUI-Anwendung protokolliert. Das Qt-Framework ist ein beliebtes plattformübergreifendes UI-Framework mit Python-Bindungen, das die Bibliotheken PySide2 oder PyQt5 verwendet.
Das folgende Beispiel zeigt, wie man in eine Qt-GUI protokolliert. Dies führt eine einfache Klasse QtHandler ein, die einen Aufruf entgegennimmt, der ein Slot im Hauptthread sein sollte, der GUI-Updates durchführt. Ein Worker-Thread wird ebenfalls erstellt, um zu zeigen, wie man sowohl von der UI selbst (über eine Schaltfläche zum manuellen Protokollieren) als auch von einem Hintergrund-Worker-Thread (hier nur zufällige Nachrichten auf zufälligen Pegeln mit zufälligen kurzen Verzögerungen dazwischen) in die GUI protokollieren kann.
Der Worker-Thread wird mithilfe der QThread-Klasse von Qt anstelle des Moduls threading implementiert, da es Umstände gibt, unter denen man QThread verwenden muss, was eine bessere Integration mit anderen Qt-Komponenten bietet.
Der Code sollte mit aktuellen Versionen von PySide6, PyQt6, PySide2 oder PyQt5 funktionieren. Sie sollten den Ansatz an frühere Versionen von Qt anpassen können. Bitte beachten Sie die Kommentare im Code-Snippet für detailliertere Informationen.
import datetime
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()
Logging nach Syslog mit RFC5424-Unterstützung¶
Obwohl RFC 5424 aus dem Jahr 2009 stammt, sind die meisten Syslog-Server standardmäßig für die Verwendung des älteren RFC 3164 aus dem Jahr 2001 konfiguriert. Als logging im Jahr 2003 in Python aufgenommen wurde, unterstützte es das frühere (und damals einzige existierende) Protokoll. Seit der Veröffentlichung von RFC5424 und mangels weit verbreiteter Einführung in Syslog-Servern wurde die Funktionalität von SysLogHandler nicht aktualisiert.
RFC 5424 enthält einige nützliche Funktionen wie die Unterstützung für strukturierte Daten, und wenn Sie in einem Syslog-Server mit Unterstützung dafür protokollieren müssen, können Sie dies mit einem abgeleiteten Handler tun, der ungefähr so aussieht
import datetime
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 = datetime.datetime.fromtimestamp(record.created).isoformat()
m = self.tz_offset.match(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}'
Sie müssen mit RFC 5424 vertraut sein, um den obigen Code vollständig zu verstehen, und es kann sein, dass Sie leicht abweichende Anforderungen haben (z. B. wie Sie strukturelle Daten an das Protokoll übergeben). Dennoch sollte das Obige an Ihre spezifischen Bedürfnisse anpassbar sein. Mit dem obigen Handler würden Sie strukturierte Daten ungefähr so übergeben
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 müssen Sie mit einer Drittanbieter-API Schnittstellen erstellen, die ein dateiähnliches Objekt zum Schreiben erwartet, Sie aber die Ausgabe der API an einen Logger leiten möchten. Dies können Sie mit einer Klasse tun, die einen Logger mit einer dateiähnlichen API umschließt. Hier ist ein kurzes Skript, das eine solche Klasse veranschaulicht
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()
Wenn dieses Skript ausgeführt wird, gibt es Folgendes aus
INFO:demo:An INFO message
DEBUG:demo:A DEBUG message
Sie könnten LoggerWriter auch verwenden, um sys.stdout und sys.stderr umzuleiten, indem Sie etwas wie dieses tun
import sys
sys.stdout = LoggerWriter(logger, logging.INFO)
sys.stderr = LoggerWriter(logger, logging.WARNING)
Dies sollten Sie *nach* der Konfiguration des Loggings für Ihre Bedürfnisse tun. Im obigen Beispiel tut der Aufruf basicConfig() dies (unter Verwendung des Wertes von sys.stderr, *bevor* er durch eine LoggerWriter-Instanz überschrieben wird). Dann erhalten Sie diese Art von Ergebnis
>>> print('Foo')
INFO:demo:Foo
>>> print('Bar', file=sys.stderr)
WARNING:demo:Bar
>>>
Selbstverständlich zeigen die obigen Beispiele die Ausgabe gemäß dem von basicConfig() verwendeten Format, aber Sie können bei der Konfiguration des Loggings einen anderen Formatter verwenden.
Beachten Sie, dass Sie bei dem obigen Schema etwas von der Pufferung und der Reihenfolge der Schreibaufrufe abhängig sind, die Sie abfangen. Zum Beispiel, mit der Definition von LoggerWriter oben, wenn Sie den Ausschnitt haben
sys.stderr = LoggerWriter(logger, logging.WARNING)
1 / 0
dann führt die Ausführung des Skripts zu
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 Sie sehen, ist diese Ausgabe nicht ideal. Das liegt daran, dass der zugrundeliegende Code, der nach sys.stderr schreibt, mehrere Schreibvorgänge durchführt, die jeweils zu einer separaten protokollierten Zeile führen (z. B. die letzten drei Zeilen oben). Um dieses Problem zu umgehen, müssen Sie Dinge puffern und Protokollzeilen nur ausgeben, wenn Zeilenumbrüche gesehen werden. Lassen Sie uns eine etwas bessere Implementierung von LoggerWriter verwenden
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)
Dies puffert einfach Dinge, bis ein Zeilenumbruch gesehen wird, und protokolliert dann vollständige Zeilen. Mit diesem Ansatz erhalten Sie 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¶
Normalerweise bestehen protokollierte Nachrichten (z. B. auf der Konsole oder in einer Datei) aus einer einzigen Textzeile. Manchmal besteht jedoch die Notwendigkeit, Nachrichten mit mehreren Zeilen zu behandeln - sei es, weil eine Protokollformatzeichenkette Zeilenumbrüche enthält oder weil protokollierte Daten Zeilenumbrüche enthalten. Wenn Sie solche Nachrichten einheitlich behandeln möchten, sodass jede Zeile in der protokollierten Nachricht einheitlich formatiert erscheint, als wäre sie separat protokolliert worden, können Sie dies mit einem Handler-Mixin tun, wie im folgenden Schnipsel gezeigt
# 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)
Sie können das Mixin wie im folgenden Skript verwenden
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')
Das Skript gibt beim Ausführen etwas aus wie
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
Wenn Sie sich hingegen um Log-Injection sorgen, können Sie einen Formatter verwenden, der Zeilenumbrüche maskiert, gemäß dem 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')
Sie können natürlich jedes Maskierungsschema verwenden, das für Sie am sinnvollsten ist. Das Skript sollte beim Ausführen 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
Das Maskierungsverhalten kann nicht der Standard der Standardbibliothek sein, da es die Abwärtskompatibilität brechen würde.
Zu vermeidende Muster¶
Obwohl die vorherigen Abschnitte Wege zur Lösung von Problemen beschrieben haben, die Sie möglicherweise benötigen, ist es erwähnenswert, einige Nutzungsmuster zu nennen, die *unhilfreich* sind und daher in den meisten Fällen vermieden werden sollten. Die folgenden Abschnitte sind in keiner bestimmten Reihenfolge.
Das gleiche Log-Datei mehrmals öffnen¶
Unter Windows können Sie in der Regel nicht dieselbe Datei mehrmals öffnen, da dies zu einem Fehler "Datei wird von einem anderen Prozess verwendet" führt. Unter POSIX-Plattformen erhalten Sie jedoch keine Fehler, wenn Sie dieselbe Datei mehrmals öffnen. Dies könnte versehentlich geschehen, zum Beispiel durch
Ein Dateihandler wird mehr als einmal hinzugefügt, der sich auf dieselbe Datei bezieht (z. B. durch einen Kopier-/Einfüge-/Vergess-zu-ändern-Fehler).
Zwei Dateien werden geöffnet, die unterschiedlich aussehen, da sie unterschiedliche Namen haben, aber dieselbe sind, weil die eine ein symbolischer Link zur anderen ist.
Ein Prozess wird verzweigt, wonach sowohl Eltern- als auch Kindprozess eine Referenz auf dieselbe Datei haben. Dies kann beispielsweise durch die Verwendung des Moduls
multiprocessinggeschehen.
Das mehrmalige Öffnen einer Datei *scheint* meistens zu funktionieren, kann aber in der Praxis zu einer Reihe von Problemen führen.
Die Protokollausgabe kann durcheinander geraten, da mehrere Threads oder Prozesse versuchen, in dieselbe Datei zu schreiben. Obwohl die Protokollierung vor gleichzeitiger Nutzung derselben Handler-Instanz durch mehrere Threads schützt, gibt es keinen solchen Schutz, wenn gleichzeitige Schreibvorgänge von zwei verschiedenen Threads versucht werden, die zwei verschiedene Handler-Instanzen verwenden, die zufällig auf dieselbe Datei zeigen.
Ein Versuch, eine Datei zu löschen (z. B. während der Dateirotation), schlägt stillschweigend fehl, da eine andere Referenz darauf zeigt. Dies kann zu Verwirrung und verschwendeter Debugging-Zeit führen – Protokolleinträge landen an unerwarteten Stellen oder gehen ganz verloren. Oder eine Datei, die verschoben werden sollte, bleibt an Ort und Stelle und wächst unerwartet, obwohl eine größenbasierte Rotation angeblich vorhanden ist.
Verwenden Sie die in Logging to a single file from multiple processes (Protokollierung in eine einzige Datei aus mehreren Prozessen) beschriebenen Techniken, um solche Probleme zu umgehen.
Verwendung von Loggern als Attribute in einer Klasse oder Übergabe als Parameter¶
Obwohl es ungewöhnliche Fälle geben mag, in denen Sie dies tun müssen, hat es im Allgemeinen keinen Sinn, da Logger Singletons sind. Code kann über logging.getLogger(name) immer auf eine bestimmte Logger-Instanz über ihren Namen zugreifen, sodass das Übergeben von Instanzen und das Speichern als Instanzattribute sinnlos ist. Beachten Sie, dass in anderen Sprachen wie Java und C# Logger oft statische Klassenattribute sind. Dieses Muster ist jedoch in Python, wo das Modul (und nicht die Klasse) die Einheit der Softwarezerlegung ist, nicht sinnvoll.
Hinzufügen von Handlern außer NullHandler zu einem Logger in einer Bibliothek¶
Die Konfiguration der Protokollierung durch Hinzufügen von Handlern, Formatierern und Filtern ist die Verantwortung des Anwendungsentwicklers, nicht des Bibliotheksentwicklers. Wenn Sie eine Bibliothek warten, stellen Sie sicher, dass Sie keinen anderen Handlern zu Ihren Loggern hinzufügen als einer Instanz von NullHandler.
Erstellen einer großen Anzahl von Loggern¶
Logger sind Singletons, die während der Ausführung eines Skripts nie freigegeben werden. Das Erstellen vieler Logger verbraucht also Speicher, der dann nicht freigegeben werden kann. Anstatt einen Logger pro z. B. verarbeiteter Datei oder hergestellter Netzwerkverbindung zu erstellen, verwenden Sie die vorhandenen Mechanismen zum Übergeben von Kontextinformationen in Ihre Protokolle und beschränken Sie die erstellten Logger auf solche, die Bereiche innerhalb Ihrer Anwendung beschreiben (im Allgemeinen Module, aber gelegentlich etwas feingranularer).
Andere Ressourcen¶
Siehe auch
- Modul
logging API-Referenz für das Logging-Modul.
- Modul
logging.config Konfigurations-API für das Logging-Modul.
- Modul
logging.handlers Nützliche Handler, die im Logging-Modul enthalten sind.