Kochbuch zur Protokollierung
****************************

Diese Seite enthält eine Reihe von Rezepten rund um die
Protokollierung, die sich in der Vergangenheit als nützlich erwiesen
haben. Verweise auf Tutorial- und Referenzinformationen findest du
unter Weitere Quellen.


Protokollierung in mehreren Modulen verwenden
=============================================

Mehrere Aufrufe von "logging.getLogger('someLogger')" geben einen
Verweis auf dasselbe Logger-Objekt zurück.  Das gilt nicht nur
innerhalb desselben Moduls, sondern auch über Module hinweg, solange
es derselbe Prozess des Python-Interpreters ist.  Es gilt für Verweise
auf dasselbe Objekt. Darüber hinaus kann Anwendungscode in einem Modul
einen Eltern-Logger festlegen und konfigurieren und in einem anderen
Modul einen Kind-Logger erzeugen (aber nicht konfigurieren), und alle
Logger-Aufrufe am Kind werden an den Eltern-Logger weitergegeben.
Hier ein Hauptmodul:

   import logging
   import auxiliary_module

   # create logger with 'spam_application'
   logger = logging.getLogger('spam_application')
   logger.setLevel(logging.DEBUG)
   # create file handler which logs even debug messages
   fh = logging.FileHandler('spam.log')
   fh.setLevel(logging.DEBUG)
   # create console handler with a higher log level
   ch = logging.StreamHandler()
   ch.setLevel(logging.ERROR)
   # create formatter and add it to the handlers
   formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
   fh.setFormatter(formatter)
   ch.setFormatter(formatter)
   # add the handlers to the logger
   logger.addHandler(fh)
   logger.addHandler(ch)

   logger.info('creating an instance of auxiliary_module.Auxiliary')
   a = auxiliary_module.Auxiliary()
   logger.info('created an instance of auxiliary_module.Auxiliary')
   logger.info('calling auxiliary_module.Auxiliary.do_something')
   a.do_something()
   logger.info('finished auxiliary_module.Auxiliary.do_something')
   logger.info('calling auxiliary_module.some_function()')
   auxiliary_module.some_function()
   logger.info('done with auxiliary_module.some_function()')

Hier das Hilfsmodul:

   import logging

   # create logger
   module_logger = logging.getLogger('spam_application.auxiliary')

   class Auxiliary:
       def __init__(self):
           self.logger = logging.getLogger('spam_application.auxiliary.Auxiliary')
           self.logger.info('creating an instance of Auxiliary')

       def do_something(self):
           self.logger.info('doing something')
           a = 1 + 1
           self.logger.info('done doing something')

   def some_function():
       module_logger.info('received a call to "some_function"')

Die Ausgabe sieht so aus:

   2005-03-23 23:47:11,663 - spam_application - INFO -
      creating an instance of auxiliary_module.Auxiliary
   2005-03-23 23:47:11,665 - spam_application.auxiliary.Auxiliary - INFO -
      creating an instance of Auxiliary
   2005-03-23 23:47:11,665 - spam_application - INFO -
      created an instance of auxiliary_module.Auxiliary
   2005-03-23 23:47:11,668 - spam_application - INFO -
      calling auxiliary_module.Auxiliary.do_something
   2005-03-23 23:47:11,668 - spam_application.auxiliary.Auxiliary - INFO -
      doing something
   2005-03-23 23:47:11,669 - spam_application.auxiliary.Auxiliary - INFO -
      done doing something
   2005-03-23 23:47:11,670 - spam_application - INFO -
      finished auxiliary_module.Auxiliary.do_something
   2005-03-23 23:47:11,671 - spam_application - INFO -
      calling auxiliary_module.some_function()
   2005-03-23 23:47:11,672 - spam_application.auxiliary - INFO -
      received a call to 'some_function'
   2005-03-23 23:47:11,673 - spam_application - INFO -
      done with auxiliary_module.some_function()


Aus mehreren Threads protokollieren
===================================

Aus mehreren Threads zu protokollieren erfordert keinen besonderen
Aufwand. Das folgende Beispiel zeigt die Protokollierung aus dem
Haupt-Thread (dem ersten) und einem weiteren Thread:

   import logging
   import threading
   import time

   def worker(arg):
       while not arg['stop']:
           logging.debug('Hi from myfunc')
           time.sleep(0.5)

   def main():
       logging.basicConfig(level=logging.DEBUG, format='%(relativeCreated)6d %(threadName)s %(message)s')
       info = {'stop': False}
       thread = threading.Thread(target=worker, args=(info,))
       thread.start()
       while True:
           try:
               logging.debug('Hello from main')
               time.sleep(0.75)
           except KeyboardInterrupt:
               info['stop'] = True
               break
       thread.join()

   if __name__ == '__main__':
       main()

Beim Ausführen sollte das Skript etwa Folgendes ausgeben:

      0 Thread-1 Hi from myfunc
      3 MainThread Hello from main
    505 Thread-1 Hi from myfunc
    755 MainThread Hello from main
   1007 Thread-1 Hi from myfunc
   1507 MainThread Hello from main
   1508 Thread-1 Hi from myfunc
   2010 Thread-1 Hi from myfunc
   2258 MainThread Hello from main
   2512 Thread-1 Hi from myfunc
   3009 MainThread Hello from main
   3013 Thread-1 Hi from myfunc
   3515 Thread-1 Hi from myfunc
   3761 MainThread Hello from main
   4017 Thread-1 Hi from myfunc
   4513 MainThread Hello from main
   4518 Thread-1 Hi from myfunc

Das zeigt die Protokollausgabe ineinander verschränkt, wie man es
erwarten würde. Dieser Ansatz funktioniert natürlich auch mit mehr
Threads als hier gezeigt.


Mehrere Handler und Formatter
=============================

Logger sind gewöhnliche Python-Objekte.  Die Methode "addHandler()"
hat keine Mindest- oder Höchstzahl für die Handler, die du hinzufügen
darfst.  Manchmal ist es für eine Anwendung sinnvoll, alle Meldungen
aller Schweregrade in eine Textdatei zu protokollieren und
gleichzeitig Fehler und Schlimmeres auf der Konsole zu protokollieren.
Dazu konfigurierst du einfach die passenden Handler.  Die
Protokollierungsaufrufe im Anwendungscode bleiben unverändert.  Hier
eine kleine Abwandlung des vorherigen einfachen, modulbasierten
Konfigurationsbeispiels:

   import logging

   logger = logging.getLogger('simple_example')
   logger.setLevel(logging.DEBUG)
   # create file handler which logs even debug messages
   fh = logging.FileHandler('spam.log')
   fh.setLevel(logging.DEBUG)
   # create console handler with a higher log level
   ch = logging.StreamHandler()
   ch.setLevel(logging.ERROR)
   # create formatter and add it to the handlers
   formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
   ch.setFormatter(formatter)
   fh.setFormatter(formatter)
   # add the handlers to logger
   logger.addHandler(ch)
   logger.addHandler(fh)

   # 'application' code
   logger.debug('debug message')
   logger.info('info message')
   logger.warning('warn message')
   logger.error('error message')
   logger.critical('critical message')

Beachte, dass den „Anwendungs“-Code die mehreren Handler nicht
interessieren.  Geändert hat sich nur, dass ein neuer Handler namens
*fh* hinzugekommen und konfiguriert worden ist.

Neue Handler mit Filtern für höhere oder niedrigere Schweregrade
anlegen zu können, kann beim Schreiben und Testen einer Anwendung sehr
hilfreich sein. Verwende zur Fehlersuche statt vieler
"print"-Anweisungen "logger.debug": Anders als die print-Anweisungen,
die du später löschen oder auskommentieren musst, können die logger
.debug-Anweisungen im Quellcode stehen bleiben und ruhen dort, bis du
sie wieder brauchst.  Dann musst du nur noch den Schweregrad des
Loggers und/oder des Handlers auf debug ändern.


An mehrere Ziele protokollieren
===============================

Nehmen wir an, du willst mit unterschiedlichen Meldungsformaten und
unter unterschiedlichen Umständen auf die Konsole und in eine Datei
protokollieren. Nehmen wir an, du willst Meldungen mit den
Schweregraden DEBUG und höher in eine Datei und die Meldungen mit
Schweregrad INFO und höher auf die Konsole protokollieren. Nehmen wir
weiter an, die Datei soll Zeitstempel enthalten, die Meldungen auf der
Konsole aber nicht. So erreichst du das:

   import logging

   # set up logging to file - see previous section for more details
   logging.basicConfig(level=logging.DEBUG,
                       format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s',
                       datefmt='%m-%d %H:%M',
                       filename='/tmp/myapp.log',
                       filemode='w')
   # define a Handler which writes INFO messages or higher to the sys.stderr
   console = logging.StreamHandler()
   console.setLevel(logging.INFO)
   # set a format which is simpler for console use
   formatter = logging.Formatter('%(name)-12s: %(levelname)-8s %(message)s')
   # tell the handler to use this format
   console.setFormatter(formatter)
   # add the handler to the root logger
   logging.getLogger().addHandler(console)

   # Now, we can log to the root logger, or any other logger. First the root...
   logging.info('Jackdaws love my big sphinx of quartz.')

   # Now, define a couple of other loggers which might represent areas in your
   # application:

   logger1 = logging.getLogger('myapp.area1')
   logger2 = logging.getLogger('myapp.area2')

   logger1.debug('Quick zephyrs blow, vexing daft Jim.')
   logger1.info('How quickly daft jumping zebras vex.')
   logger2.warning('Jail zesty vixen who grabbed pay from quack.')
   logger2.error('The five boxing wizards jump quickly.')

Wenn du das ausführst, siehst du auf der Konsole

   root        : INFO     Jackdaws love my big sphinx of quartz.
   myapp.area1 : INFO     How quickly daft jumping zebras vex.
   myapp.area2 : WARNING  Jail zesty vixen who grabbed pay from quack.
   myapp.area2 : ERROR    The five boxing wizards jump quickly.

und in der Datei siehst du etwa

   10-22 22:19 root         INFO     Jackdaws love my big sphinx of quartz.
   10-22 22:19 myapp.area1  DEBUG    Quick zephyrs blow, vexing daft Jim.
   10-22 22:19 myapp.area1  INFO     How quickly daft jumping zebras vex.
   10-22 22:19 myapp.area2  WARNING  Jail zesty vixen who grabbed pay from quack.
   10-22 22:19 myapp.area2  ERROR    The five boxing wizards jump quickly.

Wie du siehst, erscheint die DEBUG-Meldung nur in der Datei. Die
anderen Meldungen gehen an beide Ziele.

Dieses Beispiel verwendet einen Konsolen- und einen Datei-Handler, du
kannst aber beliebig viele Handler in beliebiger Kombination
verwenden.

Beachte, dass die obige Wahl des Protokolldateinamens "/tmp/myapp.log"
einen Standardort für temporäre Dateien auf POSIX-Systemen
voraussetzt. Unter Windows musst du für das Protokoll möglicherweise
einen anderen Verzeichnisnamen wählen – achte nur darauf, dass das
Verzeichnis existiert und du darin Dateien anlegen und ändern darfst.


Eigene Behandlung von Schweregraden
===================================

Manchmal willst du etwas anderes als die übliche Behandlung von
Schweregraden in Handlern, bei der ein Handler alle Grade oberhalb
einer Schwelle verarbeitet. Dazu musst du Filter verwenden. Sehen wir
uns einen Fall an, in dem du es folgendermaßen einrichten willst:

* Meldungen mit Schweregrad "INFO" und "WARNING" an "sys.stdout"
  senden

* Meldungen mit Schweregrad "ERROR" und höher an "sys.stderr" senden

* Meldungen mit Schweregrad "DEBUG" und höher in die Datei "app.log"
  senden

Nehmen wir an, du konfigurierst die Protokollierung mit folgendem
JSON:

   {
       "version": 1,
       "disable_existing_loggers": false,
       "formatters": {
           "simple": {
               "format": "%(levelname)-8s - %(message)s"
           }
       },
       "handlers": {
           "stdout": {
               "class": "logging.StreamHandler",
               "level": "INFO",
               "formatter": "simple",
               "stream": "ext://sys.stdout"
           },
           "stderr": {
               "class": "logging.StreamHandler",
               "level": "ERROR",
               "formatter": "simple",
               "stream": "ext://sys.stderr"
           },
           "file": {
               "class": "logging.FileHandler",
               "formatter": "simple",
               "filename": "app.log",
               "mode": "w"
           }
       },
       "root": {
           "level": "DEBUG",
           "handlers": [
               "stderr",
               "stdout",
               "file"
           ]
       }
   }

Diese Konfiguration tut *fast* das, was wir wollen, nur würde
"sys.stdout" auch Meldungen mit Schweregrad "ERROR" anzeigen, und es
würden neben den "INFO"- und "WARNING"-Meldungen auch Ereignisse
dieses und höheren Schweregrades verfolgt. Um das zu verhindern,
können wir einen Filter einrichten, der diese Meldungen ausschließt,
und ihn dem betreffenden Handler hinzufügen. Das lässt sich
konfigurieren, indem wir einen Abschnitt "filters" parallel zu
"formatters" und "handlers" ergänzen:

   {
       "filters": {
           "warnings_and_below": {
               "()" : "__main__.filter_maker",
               "level": "WARNING"
           }
       }
   }

und den Abschnitt zum Handler "stdout" so ändern, dass er ihn
aufnimmt:

   {
       "stdout": {
           "class": "logging.StreamHandler",
           "level": "INFO",
           "formatter": "simple",
           "stream": "ext://sys.stdout",
           "filters": ["warnings_and_below"]
       }
   }

Ein Filter ist einfach eine Funktion, wir können "filter_maker" (eine
Factory-Funktion) also so festlegen:

   def filter_maker(level):
       level = getattr(logging, level)

       def filter(record):
           return record.levelno <= level

       return filter

Das wandelt das übergebene Zeichenkettenargument in einen numerischen
Schweregrad um und gibt eine Funktion zurück, die nur dann "True"
zurückgibt, wenn der Schweregrad des übergebenen Datensatzes auf oder
unter dem angegebenen Grad liegt. Beachte, dass ich "filter_maker" in
diesem Beispiel in einem Testskript "main.py" festgelegt habe, das ich
von der Befehlszeile aus starte. Sein Modul ist damit "__main__" –
daher das "__main__.filter_maker" in der Filterkonfiguration. Das
musst du ändern, wenn du es in einem anderen Modul festlegst.

Mit dem ergänzten Filter können wir "main.py" ausführen, das
vollständig so aussieht:

   import json
   import logging
   import logging.config

   CONFIG = '''
   {
       "version": 1,
       "disable_existing_loggers": false,
       "formatters": {
           "simple": {
               "format": "%(levelname)-8s - %(message)s"
           }
       },
       "filters": {
           "warnings_and_below": {
               "()" : "__main__.filter_maker",
               "level": "WARNING"
           }
       },
       "handlers": {
           "stdout": {
               "class": "logging.StreamHandler",
               "level": "INFO",
               "formatter": "simple",
               "stream": "ext://sys.stdout",
               "filters": ["warnings_and_below"]
           },
           "stderr": {
               "class": "logging.StreamHandler",
               "level": "ERROR",
               "formatter": "simple",
               "stream": "ext://sys.stderr"
           },
           "file": {
               "class": "logging.FileHandler",
               "formatter": "simple",
               "filename": "app.log",
               "mode": "w"
           }
       },
       "root": {
           "level": "DEBUG",
           "handlers": [
               "stderr",
               "stdout",
               "file"
           ]
       }
   }
   '''

   def filter_maker(level):
       level = getattr(logging, level)

       def filter(record):
           return record.levelno <= level

       return filter

   logging.config.dictConfig(json.loads(CONFIG))
   logging.debug('A DEBUG message')
   logging.info('An INFO message')
   logging.warning('A WARNING message')
   logging.error('An ERROR message')
   logging.critical('A CRITICAL message')

Und nach einem Aufruf wie diesem:

   python main.py 2>stderr.log >stdout.log

sehen wir, dass die Ergebnisse den Erwartungen entsprechen:

   $ more *.log
   ::::::::::::::
   app.log
   ::::::::::::::
   DEBUG    - A DEBUG message
   INFO     - An INFO message
   WARNING  - A WARNING message
   ERROR    - An ERROR message
   CRITICAL - A CRITICAL message
   ::::::::::::::
   stderr.log
   ::::::::::::::
   ERROR    - An ERROR message
   CRITICAL - A CRITICAL message
   ::::::::::::::
   stdout.log
   ::::::::::::::
   INFO     - An INFO message
   WARNING  - A WARNING message


Beispiel für einen Konfigurationsserver
=======================================

Hier ein Beispiel für ein Modul, das den Konfigurationsserver der
Protokollierung verwendet:

   import logging
   import logging.config
   import time
   import os

   # read initial config file
   logging.config.fileConfig('logging.conf')

   # create and start listener on port 9999
   t = logging.config.listen(9999)
   t.start()

   logger = logging.getLogger('simpleExample')

   try:
       # loop through logging calls to see the difference
       # new configurations make, until Ctrl+C is pressed
       while True:
           logger.debug('debug message')
           logger.info('info message')
           logger.warning('warn message')
           logger.error('error message')
           logger.critical('critical message')
           time.sleep(5)
   except KeyboardInterrupt:
       # cleanup
       logging.config.stopListening()
       t.join()

Und hier ein Skript, das einen Dateinamen nimmt und diese Datei –
korrekt um die binär kodierte Länge vorangestellt – als neue
Protokollierungskonfiguration an den Server sendet:

   #!/usr/bin/env python
   import socket, sys, struct

   with open(sys.argv[1], 'rb') as f:
       data_to_send = f.read()

   HOST = 'localhost'
   PORT = 9999
   s = socket.socket(socket.AF_INET, socket.SOCK_STREAM)
   print('connecting...')
   s.connect((HOST, PORT))
   print('sending config...')
   s.send(struct.pack('>L', len(data_to_send)))
   s.send(data_to_send)
   s.close()
   print('complete')


Mit Handlern umgehen, die blockieren
====================================

Manchmal musst du dafür sorgen, dass deine Protokollierungs-Handler
ihre Arbeit tun, ohne den Thread zu blockieren, aus dem du
protokollierst. Das kommt in Webanwendungen häufig vor, tritt
natürlich aber auch in anderen Fällen auf.

Ein häufiger Übeltäter mit träger Arbeitsweise ist "SMTPHandler": Das
Versenden von E-Mails kann aus einer Reihe von Gründen außerhalb der
Kontrolle des Entwicklers lange dauern (etwa eine schlecht arbeitende
Mail- oder Netzinfrastruktur). Aber fast jeder netzbasierte Handler
kann blockieren: Selbst eine Operation von "SocketHandler" nimmt unter
der Haube möglicherweise eine DNS-Abfrage vor, die zu langsam ist (und
diese Abfrage kann tief im Code der Socket-Bibliothek liegen,
unterhalb der Python-Schicht und außerhalb deiner Kontrolle).

Eine Lösung besteht in einem zweiteiligen Ansatz. Für den ersten Teil
hängst du an die Logger, auf die aus geschwindigkeitskritischen
Threads zugegriffen wird, nur einen "QueueHandler". Die schreiben
einfach in ihre Warteschlange, die groß genug bemessen oder ganz ohne
Obergrenze angelegt werden kann. Das Schreiben in die Warteschlange
wird üblicherweise schnell angenommen, auch wenn du in deinem Code
vorsichtshalber wahrscheinlich die Ausnahme "queue.Full" abfangen
musst. Bist du Bibliotheksentwickler und hast
geschwindigkeitskritische Threads in deinem Code, dann dokumentiere
das unbedingt (zusammen mit der Empfehlung, an deine Logger nur
"QueueHandlers" zu hängen), damit andere Entwickler, die deinen Code
verwenden, davon profitieren.

Der zweite Teil der Lösung ist "QueueListener", der als Gegenstück zu
"QueueHandler" entworfen wurde.  Ein "QueueListener" ist sehr einfach:
Ihm werden eine Warteschlange und einige Handler übergeben, und er
startet einen internen Thread, der an seiner Warteschlange auf
LogRecords lauscht, die von "QueueHandlers" gesendet werden (oder, was
das betrifft, von jeder anderen Quelle von "LogRecords"). Die
"LogRecords" werden aus der Warteschlange genommen und zur
Verarbeitung an die Handler übergeben.

Der Vorteil einer eigenen Klasse "QueueListener" ist, dass du dieselbe
Instanz für mehrere "QueueHandlers" nutzen kannst. Das ist
ressourcenschonender als etwa Thread-Varianten der bestehenden
Handler-Klassen, die ohne besonderen Nutzen einen Thread je Handler
verbrauchen würden.

Ein Beispiel für die Verwendung dieser beiden Klassen folgt (Importe
weggelassen):

   que = queue.Queue(-1)  # no limit on size
   queue_handler = QueueHandler(que)
   handler = logging.StreamHandler()
   listener = QueueListener(que, handler)
   root = logging.getLogger()
   root.addHandler(queue_handler)
   formatter = logging.Formatter('%(threadName)s: %(message)s')
   handler.setFormatter(formatter)
   listener.start()
   # The log output will display the thread which generated
   # the event (the main thread) rather than the internal
   # thread which monitors the internal queue. This is what
   # you want to happen.
   root.warning('Look out!')
   listener.stop()

was beim Ausführen Folgendes ergibt:

   MainThread: Look out!

Bemerkung:

  Die obige Erörterung sprach nicht ausdrücklich von asynchronem Code,
  sondern von langsamen Protokollierungs-Handlern. Dennoch sei
  angemerkt, dass beim Protokollieren aus asynchronem Code Netz- und
  sogar Datei-Handler zu Problemen führen können (sie blockieren die
  Ereignisschleife), weil ein Teil der Protokollierung aus den Interna
  von "asyncio" erfolgt. Wird in einer Anwendung asynchroner Code
  verwendet, ist es vermutlich am besten, für die Protokollierung den
  oben beschriebenen Ansatz zu nehmen, damit blockierender Code nur im
  Thread des "QueueListener" läuft.

Geändert in Version 3.5: Vor Python 3.5 gab "QueueListener" jede aus
der Warteschlange empfangene Meldung immer an jeden Handler weiter,
mit dem er angelegt worden war. (Das lag daran, dass man annahm, die
Filterung nach Schweregrad finde vollständig auf der anderen Seite
statt, wo die Warteschlange gefüllt wird.) Ab 3.5 lässt sich dieses
Verhalten ändern, indem dem Konstruktor des Listeners das
Schlüsselwortargument "respect_handler_level=True" übergeben wird.
Dann vergleicht der Listener den Schweregrad jeder Meldung mit dem des
Handlers und gibt eine Meldung nur dann an einen Handler weiter, wenn
es angemessen ist.

Geändert in Version 3.14: "QueueListener" lässt sich über die
"with"-Anweisung starten (und stoppen). Zum Beispiel:

   with QueueListener(que, handler) as listener:
       # The queue listener automatically starts
       # when the 'with' block is entered.
       pass
   # The queue listener automatically stops once
   # the 'with' block is exited.


Protokollierungsereignisse über ein Netz senden und empfangen
=============================================================

Nehmen wir an, du willst Protokollierungsereignisse über ein Netz
senden und am Empfangsende verarbeiten. Ein einfacher Weg dazu ist, am
Sendeende eine Instanz von "SocketHandler" an den Wurzel-Logger zu
hängen:

   import logging, logging.handlers

   rootLogger = logging.getLogger()
   rootLogger.setLevel(logging.DEBUG)
   socketHandler = logging.handlers.SocketHandler('localhost',
                       logging.handlers.DEFAULT_TCP_LOGGING_PORT)
   # don't bother with a formatter, since a socket handler sends the event as
   # an unformatted pickle
   rootLogger.addHandler(socketHandler)

   # Now, we can log to the root logger, or any other logger. First the root...
   logging.info('Jackdaws love my big sphinx of quartz.')

   # Now, define a couple of other loggers which might represent areas in your
   # application:

   logger1 = logging.getLogger('myapp.area1')
   logger2 = logging.getLogger('myapp.area2')

   logger1.debug('Quick zephyrs blow, vexing daft Jim.')
   logger1.info('How quickly daft jumping zebras vex.')
   logger2.warning('Jail zesty vixen who grabbed pay from quack.')
   logger2.error('The five boxing wizards jump quickly.')

Am Empfangsende kannst du mit dem Modul "socketserver" einen Empfänger
einrichten. Hier ein einfaches, funktionierendes Beispiel:

   import pickle
   import logging
   import logging.handlers
   import socketserver
   import struct


   class LogRecordStreamHandler(socketserver.StreamRequestHandler):
       """Handler for a streaming logging request.

       This basically logs the record using whatever logging policy is
       configured locally.
       """

       def handle(self):
           """
           Handle multiple requests - each expected to be a 4-byte length,
           followed by the LogRecord in pickle format. Logs the record
           according to whatever policy is configured locally.
           """
           while True:
               chunk = self.connection.recv(4)
               if len(chunk) < 4:
                   break
               slen = struct.unpack('>L', chunk)[0]
               chunk = self.connection.recv(slen)
               while len(chunk) < slen:
                   chunk = chunk + self.connection.recv(slen - len(chunk))
               obj = self.unPickle(chunk)
               record = logging.makeLogRecord(obj)
               self.handleLogRecord(record)

       def unPickle(self, data):
           return pickle.loads(data)

       def handleLogRecord(self, record):
           # if a name is specified, we use the named logger rather than the one
           # implied by the record.
           if self.server.logname is not None:
               name = self.server.logname
           else:
               name = record.name
           logger = logging.getLogger(name)
           # N.B. EVERY record gets logged. This is because Logger.handle
           # is normally called AFTER logger-level filtering. If you want
           # to do filtering, do it at the client end to save wasting
           # cycles and network bandwidth!
           logger.handle(record)

   class LogRecordSocketReceiver(socketserver.ThreadingTCPServer):
       """
       Simple TCP socket-based logging receiver suitable for testing.
       """

       allow_reuse_address = True

       def __init__(self, host='localhost',
                    port=logging.handlers.DEFAULT_TCP_LOGGING_PORT,
                    handler=LogRecordStreamHandler):
           socketserver.ThreadingTCPServer.__init__(self, (host, port), handler)
           self.abort = 0
           self.timeout = 1
           self.logname = None

       def serve_until_stopped(self):
           import select
           abort = 0
           while not abort:
               rd, wr, ex = select.select([self.socket.fileno()],
                                          [], [],
                                          self.timeout)
               if rd:
                   self.handle_request()
               abort = self.abort

   def main():
       logging.basicConfig(
           format='%(relativeCreated)5d %(name)-15s %(levelname)-8s %(message)s')
       tcpserver = LogRecordSocketReceiver()
       print('About to start TCP server...')
       tcpserver.serve_until_stopped()

   if __name__ == '__main__':
       main()

Starte zuerst den Server, dann den Client. Auf der Client-Seite wird
nichts auf der Konsole ausgegeben. Auf der Server-Seite solltest du
etwa Folgendes sehen:

   About to start TCP server...
      59 root            INFO     Jackdaws love my big sphinx of quartz.
      59 myapp.area1     DEBUG    Quick zephyrs blow, vexing daft Jim.
      69 myapp.area1     INFO     How quickly daft jumping zebras vex.
      69 myapp.area2     WARNING  Jail zesty vixen who grabbed pay from quack.
      69 myapp.area2     ERROR    The five boxing wizards jump quickly.

Beachte, dass es in manchen Fällen Sicherheitsprobleme mit pickle
gibt. Betreffen die dich, kannst du ein anderes
Serialisierungsverfahren verwenden. Überschreibe dazu die Methode
"makePickle()", setze dein Verfahren dort um und passe das obige
Skript entsprechend an.


Einen Socket-Listener für die Protokollierung im Produktivbetrieb laufen lassen
-------------------------------------------------------------------------------

Um einen Listener für die Protokollierung im Produktivbetrieb laufen
zu lassen, brauchst du möglicherweise ein Werkzeug zur
Prozessverwaltung wie Supervisor. Hier ist ein Gist mit den nötigsten
Dateien, um die obige Funktionalität mit Supervisor zu betreiben. Es
besteht aus den folgenden Dateien:

+---------------------------+------------------------------------------------------+
| Datei                     | Zweck                                                |
|===========================|======================================================|
| "prepare.sh"              | Ein Bash-Skript, das die Umgebung für Tests          |
|                           | vorbereitet                                          |
+---------------------------+------------------------------------------------------+
| "supervisor.conf"         | Die Konfigurationsdatei von Supervisor mit Einträgen |
|                           | für den Listener und eine Webanwendung mit mehreren  |
|                           | Prozessen                                            |
+---------------------------+------------------------------------------------------+
| "ensure_app.sh"           | Ein Bash-Skript, das sicherstellt, dass Supervisor   |
|                           | mit der obigen Konfiguration läuft                   |
+---------------------------+------------------------------------------------------+
| "log_listener.py"         | Das Socket-Listener-Programm, das                    |
|                           | Protokollierungsereignisse empfängt und in eine      |
|                           | Datei schreibt                                       |
+---------------------------+------------------------------------------------------+
| "main.py"                 | Eine einfache Webanwendung, die über ein mit dem     |
|                           | Listener verbundenes Socket protokolliert            |
+---------------------------+------------------------------------------------------+
| "webapp.json"             | Eine JSON-Konfigurationsdatei für die Webanwendung   |
+---------------------------+------------------------------------------------------+
| "client.py"               | Ein Python-Skript, das die Webanwendung auf Trab     |
|                           | bringt                                               |
+---------------------------+------------------------------------------------------+

Die Webanwendung verwendet Gunicorn, einen verbreiteten
Anwendungsserver für Webanwendungen, der mehrere Arbeiterprozesse
startet, um Anfragen zu bearbeiten. Dieser Beispielaufbau zeigt, wie
die Arbeiter in dieselbe Protokolldatei schreiben können, ohne sich
gegenseitig in die Quere zu kommen --- sie gehen alle über den Socket-
Listener.

Um diese Dateien zu testen, gehe in einer POSIX-Umgebung so vor:

1. Lade das Gist über die Schaltfläche Download ZIP als ZIP-Archiv
   herunter.

2. Entpacke die obigen Dateien aus dem Archiv in ein
   Arbeitsverzeichnis.

3. Führe im Arbeitsverzeichnis "bash prepare.sh" aus, um alles
   vorzubereiten. Das erzeugt ein Unterverzeichnis "run" für die
   Supervisor- und Protokolldateien sowie ein Unterverzeichnis "venv"
   für eine virtuelle Umgebung, in die "bottle", "gunicorn" und
   "supervisor" installiert werden.

4. Führe "bash ensure_app.sh" aus, um sicherzustellen, dass Supervisor
   mit der obigen Konfiguration läuft.

5. Führe "venv/bin/python client.py" aus, um die Webanwendung auf Trab
   zu bringen. Dadurch werden Datensätze ins Protokoll geschrieben.

6. Sieh dir die Protokolldateien im Unterverzeichnis "run" an. Die
   neuesten Protokollzeilen solltest du in Dateien finden, die auf das
   Muster "app.log*" passen. Sie stehen in keiner bestimmten
   Reihenfolge, weil sie von verschiedenen Arbeiterprozessen
   nebenläufig und nicht deterministisch verarbeitet wurden.

7. Den Listener und die Webanwendung fährst du mit
   "venv/bin/supervisorctl -c supervisor.conf shutdown" herunter.

In dem unwahrscheinlichen Fall, dass die konfigurierten Ports mit
etwas anderem in deiner Testumgebung kollidieren, musst du die
Konfigurationsdateien anpassen.

Die Standardkonfiguration verwendet ein TCP-Socket auf Port 9020.
Statt eines TCP-Sockets kannst du folgendermaßen ein Unix-Domain-
Socket verwenden:

1. Ergänze in "listener.json" einen Schlüssel "socket" mit dem Pfad
   zum gewünschten Domain-Socket. Ist dieser Schlüssel vorhanden,
   lauscht der Listener am entsprechenden Domain-Socket und nicht an
   einem TCP-Socket (der Schlüssel "port" wird ignoriert).

2. Ändere in "webapp.json" das Konfigurations-Dictionary des Socket-
   Handlers so, dass der Wert von "host" der Pfad zum Domain-Socket
   ist, und setze den Wert von "port" auf "null".


Kontextinformationen zu deiner Protokollausgabe hinzufügen
==========================================================

Manchmal soll die Protokollausgabe neben den Parametern, die dem
Protokollierungsaufruf übergeben werden, auch Kontextinformationen
enthalten. In einer vernetzten Anwendung kann es zum Beispiel
wünschenswert sein, client-spezifische Informationen ins Protokoll zu
schreiben (etwa den Benutzernamen oder die IP-Adresse des entfernten
Clients). Du könntest das zwar über den Parameter *extra* erreichen,
aber es ist nicht immer bequem, die Informationen auf diesem Weg zu
übergeben. Es mag verlockend sein, "Logger"-Instanzen je Verbindung zu
erzeugen, aber das ist keine gute Idee, denn diese Instanzen werden
nicht von der Speicherbereinigung erfasst. In der Praxis ist das kein
Problem, solange die Anzahl der "Logger"-Instanzen von der gewünschten
Feinheit der Protokollierung einer Anwendung abhängt. Wird die Anzahl
der "Logger"-Instanzen aber praktisch unbegrenzt, kann es schwer zu
handhaben werden.


Mit LoggerAdapter Kontextinformationen mitgeben
-----------------------------------------------

Ein einfacher Weg, Kontextinformationen zu übergeben, die zusammen mit
den Informationen zum Protokollierungsereignis ausgegeben werden, ist
die Klasse "LoggerAdapter". Diese Klasse ist so entworfen, dass sie
wie ein "Logger" aussieht, du kannst also "debug()", "info()",
"warning()", "error()", "exception()", "critical()" und "log()"
aufrufen. Diese Methoden haben dieselben Signaturen wie ihre
Gegenstücke in "Logger", du kannst die beiden Arten von Instanzen also
austauschbar verwenden.

Wenn du eine Instanz von "LoggerAdapter" erzeugst, übergibst du ihr
eine "Logger"-Instanz und ein dict-artiges Objekt mit deinen
Kontextinformationen. Rufst du eine der Protokollierungsmethoden an
einer Instanz von "LoggerAdapter" auf, gibt sie den Aufruf an die
zugrunde liegende "Logger"-Instanz weiter, die ihrem Konstruktor
übergeben wurde, und sorgt dafür, dass die Kontextinformationen im
weitergegebenen Aufruf mitkommen. Hier ein Ausschnitt aus dem Code von
"LoggerAdapter":

   def debug(self, msg, /, *args, **kwargs):
       """
       Delegate a debug call to the underlying logger, after adding
       contextual information from this adapter instance.
       """
       msg, kwargs = self.process(msg, kwargs)
       self.logger.debug(msg, *args, **kwargs)

In der Methode "process()" von "LoggerAdapter" werden die
Kontextinformationen zur Protokollausgabe hinzugefügt. Ihr werden die
Meldung und die Schlüsselwortargumente des Protokollierungsaufrufs
übergeben, und sie gibt (möglicherweise) veränderte Fassungen davon
zurück, die im Aufruf des zugrunde liegenden Loggers verwendet werden.
Die Standardumsetzung dieser Methode lässt die Meldung unangetastet,
fügt aber in den Schlüsselwortargumenten einen Schlüssel „extra“ ein,
dessen Wert das dem Konstruktor übergebene dict-artige Objekt ist.
Hattest du im Aufruf des Adapters natürlich selbst ein
Schlüsselwortargument „extra“ übergeben, wird es stillschweigend
überschrieben.

Der Vorteil von „extra“ ist, dass die Werte im dict-artigen Objekt in
das __dict__ der "LogRecord"-Instanz übernommen werden. Damit kannst
du in deinen "Formatter"-Instanzen eigene Zeichenketten verwenden, die
die Schlüssel des dict-artigen Objekts kennen. Brauchst du ein anderes
Vorgehen, willst du etwa die Kontextinformationen der
Meldungszeichenkette voranstellen oder anhängen, dann musst du nur
eine Unterklasse von "LoggerAdapter" bilden und "process()" so
überschreiben, dass sie tut, was du brauchst. Hier ein einfaches
Beispiel:

   class CustomAdapter(logging.LoggerAdapter):
       """
       This example adapter expects the passed in dict-like object to have a
       'connid' key, whose value in brackets is prepended to the log message.
       """
       def process(self, msg, kwargs):
           return '[%s] %s' % (self.extra['connid'], msg), kwargs

das du so verwenden kannst:

   logger = logging.getLogger(__name__)
   adapter = CustomAdapter(logger, {'connid': some_conn_id})

Alle Ereignisse, die du dann über den Adapter protokollierst, haben
den Wert von "some_conn_id" vor der Protokollmeldung stehen.


Andere Objekte als Dictionarys verwenden, um Kontextinformationen zu übergeben
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Du musst einem "LoggerAdapter" kein echtes Dictionary übergeben – du
könntest eine Instanz einer Klasse übergeben, die "__getitem__" und
"__iter__" umsetzt, sodass sie für die Protokollierung wie ein
Dictionary aussieht. Das ist nützlich, wenn du Werte dynamisch
erzeugen willst (während die Werte in einem Dictionary feststehen
würden).


Mit Filtern Kontextinformationen mitgeben
-----------------------------------------

Du kannst Kontextinformationen auch mit einem selbst festgelegten
"Filter" zur Protokollausgabe hinzufügen. "Filter"-Instanzen dürfen
die ihnen übergebenen "LogRecords" verändern, also auch zusätzliche
Attribute ergänzen, die sich dann über eine passende
Formatzeichenkette oder, falls nötig, über einen eigenen "Formatter"
ausgeben lassen.

In einer Webanwendung lässt sich zum Beispiel die gerade bearbeitete
Anfrage (oder mindestens deren interessante Teile) in einer thread-
lokalen Variablen ("threading.local") ablegen und dann aus einem
"Filter" heraus darauf zugreifen, um etwa Informationen aus der
Anfrage – sagen wir die entfernte IP-Adresse und den Benutzernamen des
entfernten Benutzers – mit den Attributnamen „ip“ und „user“ zum
"LogRecord" hinzuzufügen, wie im obigen "LoggerAdapter"-Beispiel. In
diesem Fall lässt sich dieselbe Formatzeichenkette verwenden, um eine
ähnliche Ausgabe wie oben zu erhalten. Hier ein Beispielskript:

   import logging
   from random import choice

   class ContextFilter(logging.Filter):
       """
       This is a filter which injects contextual information into the log.

       Rather than use actual contextual information, we just use random
       data in this demo.
       """

       USERS = ['jim', 'fred', 'sheila']
       IPS = ['123.231.231.123', '127.0.0.1', '192.168.0.1']

       def filter(self, record):

           record.ip = choice(ContextFilter.IPS)
           record.user = choice(ContextFilter.USERS)
           return True

   if __name__ == '__main__':
       levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)
       logging.basicConfig(level=logging.DEBUG,
                           format='%(asctime)-15s %(name)-5s %(levelname)-8s IP: %(ip)-15s User: %(user)-8s %(message)s')
       a1 = logging.getLogger('a.b.c')
       a2 = logging.getLogger('d.e.f')

       f = ContextFilter()
       a1.addFilter(f)
       a2.addFilter(f)
       a1.debug('A debug message')
       a1.info('An info message with %s', 'some parameters')
       for x in range(10):
           lvl = choice(levels)
           lvlname = logging.getLevelName(lvl)
           a2.log(lvl, 'A message at %s level with %d %s', lvlname, 2, 'parameters')

was beim Ausführen etwa Folgendes ergibt:

   2010-09-06 22:38:15,292 a.b.c DEBUG    IP: 123.231.231.123 User: fred     A debug message
   2010-09-06 22:38:15,300 a.b.c INFO     IP: 192.168.0.1     User: sheila   An info message with some parameters
   2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1       User: sheila   A message at CRITICAL level with 2 parameters
   2010-09-06 22:38:15,300 d.e.f ERROR    IP: 127.0.0.1       User: jim      A message at ERROR level with 2 parameters
   2010-09-06 22:38:15,300 d.e.f DEBUG    IP: 127.0.0.1       User: sheila   A message at DEBUG level with 2 parameters
   2010-09-06 22:38:15,300 d.e.f ERROR    IP: 123.231.231.123 User: fred     A message at ERROR level with 2 parameters
   2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 192.168.0.1     User: jim      A message at CRITICAL level with 2 parameters
   2010-09-06 22:38:15,300 d.e.f CRITICAL IP: 127.0.0.1       User: sheila   A message at CRITICAL level with 2 parameters
   2010-09-06 22:38:15,300 d.e.f DEBUG    IP: 192.168.0.1     User: jim      A message at DEBUG level with 2 parameters
   2010-09-06 22:38:15,301 d.e.f ERROR    IP: 127.0.0.1       User: sheila   A message at ERROR level with 2 parameters
   2010-09-06 22:38:15,301 d.e.f DEBUG    IP: 123.231.231.123 User: fred     A message at DEBUG level with 2 parameters
   2010-09-06 22:38:15,301 d.e.f INFO     IP: 123.231.231.123 User: fred     A message at INFO level with 2 parameters


Verwendung von "contextvars"
============================

Seit Python 3.7 bietet das Modul "contextvars" einen kontextlokalen
Speicher, der sowohl für Verarbeitung mit "threading" als auch mit
"asyncio" funktioniert. Diese Art Speicher ist thread-lokalen
Variablen daher allgemein vorzuziehen. Das folgende Beispiel zeigt,
wie sich Protokolle in einer Umgebung mit mehreren Threads mit
Kontextinformationen füllen lassen, etwa mit Attributen von Anfragen,
die Webanwendungen bearbeiten.

Nehmen wir zur Veranschaulichung an, du hast verschiedene
Webanwendungen, jede unabhängig von der anderen, die aber im selben
Python-Prozess laufen und eine gemeinsame Bibliothek verwenden. Wie
kann jede dieser Anwendungen ihr eigenes Protokoll haben, in dem alle
Protokollmeldungen aus der Bibliothek (und aus dem übrigen Code zur
Anfragebearbeitung) in die Protokolldatei der jeweiligen Anwendung
gelenkt werden und zugleich zusätzliche Kontextinformationen wie
Client-IP, HTTP-Anfragemethode und Client-Benutzername im Protokoll
stehen?

Nehmen wir an, die Bibliothek lässt sich durch folgenden Code
nachbilden:

   # webapplib.py
   import logging
   import time

   logger = logging.getLogger(__name__)

   def useful():
       # Just a representative event logged from the library
       logger.debug('Hello from webapplib!')
       # Just sleep for a bit so other threads get to run
       time.sleep(0.01)

Die mehreren Webanwendungen können wir mit zwei einfachen Klassen
nachbilden, "Request" und "WebApp". Die bilden nach, wie echte
Webanwendungen mit Threads arbeiten – jede Anfrage wird von einem
Thread bearbeitet:

   # main.py
   import argparse
   from contextvars import ContextVar
   import logging
   import os
   from random import choice
   import threading
   import webapplib

   logger = logging.getLogger(__name__)
   root = logging.getLogger()
   root.setLevel(logging.DEBUG)

   class Request:
       """
       A simple dummy request class which just holds dummy HTTP request method,
       client IP address and client username
       """
       def __init__(self, method, ip, user):
           self.method = method
           self.ip = ip
           self.user = user

   # A dummy set of requests which will be used in the simulation - we'll just pick
   # from this list randomly. Note that all GET requests are from 192.168.2.XXX
   # addresses, whereas POST requests are from 192.16.3.XXX addresses. Three users
   # are represented in the sample requests.

   REQUESTS = [
       Request('GET', '192.168.2.20', 'jim'),
       Request('POST', '192.168.3.20', 'fred'),
       Request('GET', '192.168.2.21', 'sheila'),
       Request('POST', '192.168.3.21', 'jim'),
       Request('GET', '192.168.2.22', 'fred'),
       Request('POST', '192.168.3.22', 'sheila'),
   ]

   # Note that the format string includes references to request context information
   # such as HTTP method, client IP and username

   formatter = logging.Formatter('%(threadName)-11s %(appName)s %(name)-9s %(user)-6s %(ip)s %(method)-4s %(message)s')

   # Create our context variables. These will be filled at the start of request
   # processing, and used in the logging that happens during that processing

   ctx_request = ContextVar('request')
   ctx_appname = ContextVar('appname')

   class InjectingFilter(logging.Filter):
       """
       A filter which injects context-specific information into logs and ensures
       that only information for a specific webapp is included in its log
       """
       def __init__(self, app):
           self.app = app

       def filter(self, record):
           request = ctx_request.get()
           record.method = request.method
           record.ip = request.ip
           record.user = request.user
           record.appName = appName = ctx_appname.get()
           return appName == self.app.name

   class WebApp:
       """
       A dummy web application class which has its own handler and filter for a
       webapp-specific log.
       """
       def __init__(self, name):
           self.name = name
           handler = logging.FileHandler(name + '.log', 'w')
           f = InjectingFilter(self)
           handler.setFormatter(formatter)
           handler.addFilter(f)
           root.addHandler(handler)
           self.num_requests = 0

       def process_request(self, request):
           """
           This is the dummy method for processing a request. It's called on a
           different thread for every request. We store the context information into
           the context vars before doing anything else.
           """
           ctx_request.set(request)
           ctx_appname.set(self.name)
           self.num_requests += 1
           logger.debug('Request processing started')
           webapplib.useful()
           logger.debug('Request processing finished')

   def main():
       fn = os.path.splitext(os.path.basename(__file__))[0]
       adhf = argparse.ArgumentDefaultsHelpFormatter
       ap = argparse.ArgumentParser(formatter_class=adhf, prog=fn,
                                    description='Simulate a couple of web '
                                                'applications handling some '
                                                'requests, showing how request '
                                                'context can be used to '
                                                'populate logs')
       aa = ap.add_argument
       aa('--count', '-c', type=int, default=100, help='How many requests to simulate')
       options = ap.parse_args()

       # Create the dummy webapps and put them in a list which we can use to select
       # from randomly
       app1 = WebApp('app1')
       app2 = WebApp('app2')
       apps = [app1, app2]
       threads = []
       # Add a common handler which will capture all events
       handler = logging.FileHandler('app.log', 'w')
       handler.setFormatter(formatter)
       root.addHandler(handler)

       # Generate calls to process requests
       for i in range(options.count):
           try:
               # Pick an app at random and a request for it to process
               app = choice(apps)
               request = choice(REQUESTS)
               # Process the request in its own thread
               t = threading.Thread(target=app.process_request, args=(request,))
               threads.append(t)
               t.start()
           except KeyboardInterrupt:
               break

       # Wait for the threads to terminate
       for t in threads:
           t.join()

       for app in apps:
           print('%s processed %s requests' % (app.name, app.num_requests))

   if __name__ == '__main__':
       main()

Führst du das Obige aus, solltest du feststellen, dass etwa die Hälfte
der Anfragen in "app1.log" landet und der Rest in "app2.log", und dass
alle Anfragen in "app.log" protokolliert werden. Jedes
anwendungsspezifische Protokoll enthält nur Einträge dieser einen
Webanwendung, und die Informationen zur Anfrage werden im Protokoll
einheitlich angezeigt (die Informationen jeder Pseudo-Anfrage
erscheinen also immer gemeinsam in einer Protokollzeile). Das zeigt
die folgende Shell-Ausgabe:

   ~/logging-contextual-webapp$ python main.py
   app1 processed 51 requests
   app2 processed 49 requests
   ~/logging-contextual-webapp$ wc -l *.log
     153 app1.log
     147 app2.log
     300 app.log
     600 total
   ~/logging-contextual-webapp$ head -3 app1.log
   Thread-3 (process_request) app1 __main__  jim    192.168.3.21 POST Request processing started
   Thread-3 (process_request) app1 webapplib jim    192.168.3.21 POST Hello from webapplib!
   Thread-5 (process_request) app1 __main__  jim    192.168.3.21 POST Request processing started
   ~/logging-contextual-webapp$ head -3 app2.log
   Thread-1 (process_request) app2 __main__  sheila 192.168.2.21 GET  Request processing started
   Thread-1 (process_request) app2 webapplib sheila 192.168.2.21 GET  Hello from webapplib!
   Thread-2 (process_request) app2 __main__  jim    192.168.2.20 GET  Request processing started
   ~/logging-contextual-webapp$ head app.log
   Thread-1 (process_request) app2 __main__  sheila 192.168.2.21 GET  Request processing started
   Thread-1 (process_request) app2 webapplib sheila 192.168.2.21 GET  Hello from webapplib!
   Thread-2 (process_request) app2 __main__  jim    192.168.2.20 GET  Request processing started
   Thread-3 (process_request) app1 __main__  jim    192.168.3.21 POST Request processing started
   Thread-2 (process_request) app2 webapplib jim    192.168.2.20 GET  Hello from webapplib!
   Thread-3 (process_request) app1 webapplib jim    192.168.3.21 POST Hello from webapplib!
   Thread-4 (process_request) app2 __main__  fred   192.168.2.22 GET  Request processing started
   Thread-5 (process_request) app1 __main__  jim    192.168.3.21 POST Request processing started
   Thread-4 (process_request) app2 webapplib fred   192.168.2.22 GET  Hello from webapplib!
   Thread-6 (process_request) app1 __main__  jim    192.168.3.21 POST Request processing started
   ~/logging-contextual-webapp$ grep app1 app1.log | wc -l
   153
   ~/logging-contextual-webapp$ grep app2 app2.log | wc -l
   147
   ~/logging-contextual-webapp$ grep app1 app.log | wc -l
   153
   ~/logging-contextual-webapp$ grep app2 app.log | wc -l
   147


Kontextinformationen in Handlern mitgeben
=========================================

Jeder "Handler" hat seine eigene Kette von Filtern. Willst du
Kontextinformationen zu einem "LogRecord" hinzufügen, ohne dass sie zu
anderen Handlern durchsickern, kannst du einen Filter verwenden, der
einen neuen "LogRecord" zurückgibt statt ihn an seinem Platz zu
verändern, wie das folgende Skript zeigt:

   import copy
   import logging

   def filter(record: logging.LogRecord):
       record = copy.copy(record)
       record.user = 'jim'
       return record

   if __name__ == '__main__':
       logger = logging.getLogger()
       logger.setLevel(logging.INFO)
       handler = logging.StreamHandler()
       formatter = logging.Formatter('%(message)s from %(user)-8s')
       handler.setFormatter(formatter)
       handler.addFilter(filter)
       logger.addHandler(handler)

       logger.info('A log message')


Aus mehreren Prozessen in eine einzige Datei protokollieren
===========================================================

Die Protokollierung ist zwar threadsicher, und das Protokollieren aus
mehreren Threads eines Prozesses in eine einzige Datei *wird*
unterstützt, das Protokollieren aus *mehreren Prozessen* in eine
einzige Datei aber *nicht*, weil es in Python keinen Standardweg gibt,
den Zugriff auf eine einzige Datei über mehrere Prozesse hinweg zu
serialisieren. Musst du aus mehreren Prozessen in eine einzige Datei
protokollieren, dann lässt sich das zum Beispiel so lösen, dass alle
Prozesse in einen "SocketHandler" protokollieren und ein eigener
Prozess einen Socket-Server umsetzt, der vom Socket liest und in die
Datei protokolliert. (Wenn du magst, kannst du für diese Aufgabe auch
einen Thread in einem der bestehenden Prozesse abstellen.) Dieser
Abschnitt beschreibt diesen Ansatz ausführlicher und enthält einen
funktionierenden Socket-Empfänger, den du als Ausgangspunkt für eigene
Anwendungen anpassen kannst.

Du könntest auch einen eigenen Handler schreiben, der mit der Klasse
"Lock" aus dem Modul "multiprocessing" den Zugriff deiner Prozesse auf
die Datei serialisiert. "FileHandler" und seine Unterklassen aus der
Standardbibliothek verwenden "multiprocessing" nicht.

Alternativ kannst du eine "Queue" und einen "QueueHandler" verwenden,
um alle Protokollierungsereignisse an einen der Prozesse deiner
Anwendung mit mehreren Prozessen zu senden. Das folgende
Beispielskript zeigt, wie das geht. Im Beispiel lauscht ein eigener
Listener-Prozess auf Ereignisse, die andere Prozesse senden, und
protokolliert sie nach seiner eigenen Protokollierungskonfiguration.
Das Beispiel zeigt zwar nur einen Weg (du willst vielleicht einen
Listener-Thread statt eines eigenen Listener-Prozesses verwenden – die
Umsetzung wäre entsprechend), es erlaubt aber völlig unterschiedliche
Protokollierungskonfigurationen für den Listener und die übrigen
Prozesse deiner Anwendung und lässt sich als Grundlage für Code
nehmen, der deine eigenen Anforderungen erfüllt:

   # You'll need these imports in your own code
   import logging
   import logging.handlers
   import multiprocessing

   # Next two import lines for this demo only
   from random import choice, random
   import time

   #
   # Because you'll want to define the logging configurations for listener and workers, the
   # listener and worker process functions take a configurer parameter which is a callable
   # for configuring logging for that process. These functions are also passed the queue,
   # which they use for communication.
   #
   # In practice, you can configure the listener however you want, but note that in this
   # simple example, the listener does not apply level or filter logic to received records.
   # In practice, you would probably want to do this logic in the worker processes, to avoid
   # sending events which would be filtered out between processes.
   #
   # The size of the rotated files is made small so you can see the results easily.
   def listener_configurer():
       root = logging.getLogger()
       h = logging.handlers.RotatingFileHandler('mptest.log', 'a', 300, 10)
       f = logging.Formatter('%(asctime)s %(processName)-10s %(name)s %(levelname)-8s %(message)s')
       h.setFormatter(f)
       root.addHandler(h)

   # This is the listener process top-level loop: wait for logging events
   # (LogRecords)on the queue and handle them, quit when you get a None for a
   # LogRecord.
   def listener_process(queue, configurer):
       configurer()
       while True:
           try:
               record = queue.get()
               if record is None:  # We send this as a sentinel to tell the listener to quit.
                   break
               logger = logging.getLogger(record.name)
               logger.handle(record)  # No level or filter logic applied - just do it!
           except Exception:
               import sys, traceback
               print('Whoops! Problem:', file=sys.stderr)
               traceback.print_exc(file=sys.stderr)

   # Arrays used for random selections in this demo

   LEVELS = [logging.DEBUG, logging.INFO, logging.WARNING,
             logging.ERROR, logging.CRITICAL]

   LOGGERS = ['a.b.c', 'd.e.f']

   MESSAGES = [
       'Random message #1',
       'Random message #2',
       'Random message #3',
   ]

   # The worker configuration is done at the start of the worker process run.
   # Note that on Windows you can't rely on fork semantics, so each process
   # will run the logging configuration code when it starts.
   def worker_configurer(queue):
       h = logging.handlers.QueueHandler(queue)  # Just the one handler needed
       root = logging.getLogger()
       root.addHandler(h)
       # send all messages, for demo; no other level or filter logic applied.
       root.setLevel(logging.DEBUG)

   # This is the worker process top-level loop, which just logs ten events with
   # random intervening delays before terminating.
   # The print messages are just so you know it's doing something!
   def worker_process(queue, configurer):
       configurer(queue)
       name = multiprocessing.current_process().name
       print('Worker started: %s' % name)
       for i in range(10):
           time.sleep(random())
           logger = logging.getLogger(choice(LOGGERS))
           level = choice(LEVELS)
           message = choice(MESSAGES)
           logger.log(level, message)
       print('Worker finished: %s' % name)

   # Here's where the demo gets orchestrated. Create the queue, create and start
   # the listener, create ten workers and start them, wait for them to finish,
   # then send a None to the queue to tell the listener to finish.
   def main():
       queue = multiprocessing.Queue(-1)
       listener = multiprocessing.Process(target=listener_process,
                                          args=(queue, listener_configurer))
       listener.start()
       workers = []
       for i in range(10):
           worker = multiprocessing.Process(target=worker_process,
                                            args=(queue, worker_configurer))
           workers.append(worker)
           worker.start()
       for w in workers:
           w.join()
       queue.put_nowait(None)
       listener.join()

   if __name__ == '__main__':
       main()

Eine Abwandlung des obigen Skripts behält die Protokollierung im
Hauptprozess, in einem eigenen Thread:

   import logging
   import logging.config
   import logging.handlers
   from multiprocessing import Process, Queue
   import random
   import threading
   import time

   def logger_thread(q):
       while True:
           record = q.get()
           if record is None:
               break
           logger = logging.getLogger(record.name)
           logger.handle(record)


   def worker_process(q):
       qh = logging.handlers.QueueHandler(q)
       root = logging.getLogger()
       root.setLevel(logging.DEBUG)
       root.addHandler(qh)
       levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,
                 logging.CRITICAL]
       loggers = ['foo', 'foo.bar', 'foo.bar.baz',
                  'spam', 'spam.ham', 'spam.ham.eggs']
       for i in range(100):
           lvl = random.choice(levels)
           logger = logging.getLogger(random.choice(loggers))
           logger.log(lvl, 'Message no. %d', i)

   if __name__ == '__main__':
       q = Queue()
       d = {
           'version': 1,
           'formatters': {
               'detailed': {
                   'class': 'logging.Formatter',
                   'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'
               }
           },
           'handlers': {
               'console': {
                   'class': 'logging.StreamHandler',
                   'level': 'INFO',
               },
               'file': {
                   'class': 'logging.FileHandler',
                   'filename': 'mplog.log',
                   'mode': 'w',
                   'formatter': 'detailed',
               },
               'foofile': {
                   'class': 'logging.FileHandler',
                   'filename': 'mplog-foo.log',
                   'mode': 'w',
                   'formatter': 'detailed',
               },
               'errors': {
                   'class': 'logging.FileHandler',
                   'filename': 'mplog-errors.log',
                   'mode': 'w',
                   'level': 'ERROR',
                   'formatter': 'detailed',
               },
           },
           'loggers': {
               'foo': {
                   'handlers': ['foofile']
               }
           },
           'root': {
               'level': 'DEBUG',
               'handlers': ['console', 'file', 'errors']
           },
       }
       workers = []
       for i in range(5):
           wp = Process(target=worker_process, name='worker %d' % (i + 1), args=(q,))
           workers.append(wp)
           wp.start()
       logging.config.dictConfig(d)
       lp = threading.Thread(target=logger_thread, args=(q,))
       lp.start()
       # At this point, the main process could do some useful work of its own
       # Once it's done that, it can wait for the workers to terminate...
       for wp in workers:
           wp.join()
       # And now tell the logging thread to finish up, too
       q.put(None)
       lp.join()

Diese Abwandlung zeigt, wie du zum Beispiel eine Konfiguration für
bestimmte Logger anwenden kannst – etwa hat der Logger "foo" einen
besonderen Handler, der alle Ereignisse des Teilsystems "foo" in einer
Datei "mplog-foo.log" ablegt. Die Protokollierungsmaschinerie im
Hauptprozess nutzt das (auch wenn die Protokollierungsereignisse in
den Arbeiterprozessen entstehen), um die Meldungen an die passenden
Ziele zu lenken.


concurrent.futures.ProcessPoolExecutor verwenden
------------------------------------------------

Willst du deine Arbeiterprozesse mit
"concurrent.futures.ProcessPoolExecutor" starten, musst du die
Warteschlange etwas anders anlegen. Statt

   queue = multiprocessing.Queue(-1)

solltest du

   queue = multiprocessing.Manager().Queue(-1)  # also works with the examples above

verwenden, und die Erzeugung der Arbeiter ersetzt du dann von dieser
Fassung:

   workers = []
   for i in range(10):
       worker = multiprocessing.Process(target=worker_process,
                                        args=(queue, worker_configurer))
       workers.append(worker)
       worker.start()
   for w in workers:
       w.join()

durch diese (und denkst daran, zuerst "concurrent.futures" zu
importieren):

   with concurrent.futures.ProcessPoolExecutor(max_workers=10) as executor:
       for i in range(10):
           executor.submit(worker_process, queue, worker_configurer)


Webanwendungen mit Gunicorn und uWSGI ausliefern
------------------------------------------------

Lieferst du Webanwendungen mit Gunicorn oder uWSGI (oder Ähnlichem)
aus, werden mehrere Arbeiterprozesse erzeugt, um Client-Anfragen zu
bearbeiten. Vermeide es in solchen Umgebungen, dateibasierte Handler
direkt in deiner Webanwendung zu erzeugen. Verwende stattdessen einen
"SocketHandler", um aus der Webanwendung an einen Listener in einem
eigenen Prozess zu protokollieren. Das lässt sich mit einem Werkzeug
zur Prozessverwaltung wie Supervisor einrichten – näheres unter Einen
Socket-Listener für die Protokollierung im Produktivbetrieb laufen
lassen.


Dateirotation verwenden
=======================

Manchmal willst du eine Protokolldatei bis zu einer bestimmten Größe
wachsen lassen, dann eine neue Datei anlegen und in diese
protokollieren. Vielleicht willst du eine bestimmte Anzahl dieser
Dateien behalten und sie, sobald so viele angelegt wurden, rotieren,
damit Anzahl und Größe der Dateien beide beschränkt bleiben. Für
dieses Nutzungsmuster bietet das Paket logging einen
"RotatingFileHandler":

   import glob
   import logging
   import logging.handlers

   LOG_FILENAME = 'logging_rotatingfile_example.out'

   # Set up a specific logger with our desired output level
   my_logger = logging.getLogger('MyLogger')
   my_logger.setLevel(logging.DEBUG)

   # Add the log message handler to the logger
   handler = logging.handlers.RotatingFileHandler(
                 LOG_FILENAME, maxBytes=20, backupCount=5)

   my_logger.addHandler(handler)

   # Log some messages
   for i in range(20):
       my_logger.debug('i = %d' % i)

   # See what files are created
   logfiles = glob.glob('%s*' % LOG_FILENAME)

   for filename in logfiles:
       print(filename)

Das Ergebnis sollten 6 einzelne Dateien sein, jede mit einem Teil der
Protokollgeschichte der Anwendung:

   logging_rotatingfile_example.out
   logging_rotatingfile_example.out.1
   logging_rotatingfile_example.out.2
   logging_rotatingfile_example.out.3
   logging_rotatingfile_example.out.4
   logging_rotatingfile_example.out.5

Die jeweils aktuellste Datei ist immer
"logging_rotatingfile_example.out", und jedes Mal, wenn sie die
Größengrenze erreicht, wird sie mit der Endung ".1" umbenannt. Jede
der vorhandenen Sicherungsdateien wird mit um eins erhöhter Endung
umbenannt (".1" wird zu ".2" und so weiter), und die Datei ".6" wird
gelöscht.

Dieses Beispiel setzt die Protokolllänge natürlich viel zu klein, um
ein Extrem zu zeigen.  Du würdest *maxBytes* auf einen angemessenen
Wert setzen.


Andere Formatierungsstile verwenden
===================================

Als die Protokollierung in die Python-Standardbibliothek aufgenommen
wurde, war die %-Formatierung die einzige Möglichkeit, Meldungen mit
veränderlichem Inhalt zu formatieren. Seitdem hat Python zwei neue
Formatierungsansätze erhalten: "string.Template" (hinzugekommen in
Python 2.4) und "str.format()" (hinzugekommen in Python 2.6).

Die Protokollierung bietet (seit 3.2) bessere Unterstützung für diese
beiden zusätzlichen Formatierungsstile. Die Klasse "Formatter" wurde
um einen zusätzlichen, optionalen Schlüsselwortparameter namens
"style" erweitert. Dessen Vorgabe ist "'%'", möglich sind aber auch
die Werte "'{'" und "'$'", die den beiden anderen Formatierungsstilen
entsprechen. Die Verträglichkeit mit früheren Versionen bleibt
standardmäßig erhalten (wie zu erwarten), aber indem du einen style-
Parameter ausdrücklich angibst, kannst du Formatzeichenketten
verwenden, die mit "str.format()" oder "string.Template" arbeiten.
Hier eine Beispielsitzung in der Konsole, die die Möglichkeiten zeigt:

   >>> import logging
   >>> root = logging.getLogger()
   >>> root.setLevel(logging.DEBUG)
   >>> handler = logging.StreamHandler()
   >>> bf = logging.Formatter('{asctime} {name} {levelname:8s} {message}',
   ...                        style='{')
   >>> handler.setFormatter(bf)
   >>> root.addHandler(handler)
   >>> logger = logging.getLogger('foo.bar')
   >>> logger.debug('This is a DEBUG message')
   2010-10-28 15:11:55,341 foo.bar DEBUG    This is a DEBUG message
   >>> logger.critical('This is a CRITICAL message')
   2010-10-28 15:12:11,526 foo.bar CRITICAL This is a CRITICAL message
   >>> df = logging.Formatter('$asctime $name ${levelname} $message',
   ...                        style='$')
   >>> handler.setFormatter(df)
   >>> logger.debug('This is a DEBUG message')
   2010-10-28 15:13:06,924 foo.bar DEBUG This is a DEBUG message
   >>> logger.critical('This is a CRITICAL message')
   2010-10-28 15:13:11,494 foo.bar CRITICAL This is a CRITICAL message
   >>>

Beachte, dass die Formatierung von Protokollmeldungen für die
endgültige Ausgabe in die Protokolle völlig unabhängig davon ist, wie
eine einzelne Protokollmeldung aufgebaut wird. Die kann weiterhin
%-Formatierung verwenden, wie hier gezeigt:

   >>> logger.error('This is an%s %s %s', 'other,', 'ERROR,', 'message')
   2010-10-28 15:19:29,833 foo.bar ERROR This is another, ERROR, message
   >>>

Protokollierungsaufrufe ("logger.debug()", "logger.info()" und so
weiter) nehmen für die eigentliche Protokollmeldung nur
positionsbezogene Parameter; Schlüsselwortparameter dienen nur dazu,
Optionen für die Behandlung des Protokollierungsaufrufs festzulegen
(etwa der Schlüsselwortparameter "exc_info", der anzeigt, dass
Traceback-Informationen protokolliert werden sollen, oder der
Schlüsselwortparameter "extra", der zusätzliche Kontextinformationen
für das Protokoll anzeigt). Du kannst Protokollierungsaufrufe also
nicht unmittelbar in der Syntax von "str.format()" oder
"string.Template" machen, weil das Paket logging intern %-Formatierung
verwendet, um Formatzeichenkette und veränderliche Argumente
zusammenzuführen. Daran ließe sich nichts ändern, ohne die
Verträglichkeit mit früheren Versionen aufzugeben, denn alle
Protokollierungsaufrufe im vorhandenen Code verwenden
%-Formatzeichenketten.

Es gibt allerdings einen Weg, {}- und $-Formatierung zu nutzen, um
deine einzelnen Protokollmeldungen aufzubauen. Denk daran, dass du als
Formatzeichenkette einer Meldung ein beliebiges Objekt verwenden
kannst und dass das Paket logging "str()" auf dieses Objekt anwendet,
um die eigentliche Formatzeichenkette zu erhalten. Betrachte die
folgenden zwei Klassen:

   class BraceMessage:
       def __init__(self, fmt, /, *args, **kwargs):
           self.fmt = fmt
           self.args = args
           self.kwargs = kwargs

       def __str__(self):
           return self.fmt.format(*self.args, **self.kwargs)

   class DollarMessage:
       def __init__(self, fmt, /, **kwargs):
           self.fmt = fmt
           self.kwargs = kwargs

       def __str__(self):
           from string import Template
           return Template(self.fmt).substitute(**self.kwargs)

Beide lassen sich anstelle einer Formatzeichenkette verwenden, sodass
sich der eigentliche „Meldungs“-Teil, der in der formatierten
Protokollausgabe anstelle von „%(message)s“, „{message}“ oder
„$message“ erscheint, mit {}- oder $-Formatierung aufbauen lässt. Die
Klassennamen jedes Mal zu schreiben, wenn du etwas protokollieren
willst, ist etwas sperrig, aber durchaus erträglich, wenn du einen
Alias wie __ verwendest (doppelter Unterstrich --- nicht zu
verwechseln mit _, dem einfachen Unterstrich, der als Synonym bzw.
Alias für "gettext.gettext()" und Verwandte dient).

Die obigen Klassen sind nicht Teil von Python, lassen sich aber leicht
in deinen eigenen Code kopieren. Sie lassen sich so verwenden (unter
der Annahme, dass sie in einem Modul namens "wherever" deklariert
sind):

   >>> from wherever import BraceMessage as __
   >>> print(__('Message with {0} {name}', 2, name='placeholders'))
   Message with 2 placeholders
   >>> class Point: pass
   ...
   >>> p = Point()
   >>> p.x = 0.5
   >>> p.y = 0.5
   >>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})',
   ...       point=p))
   Message with coordinates: (0.50, 0.50)
   >>> from wherever import DollarMessage as __
   >>> print(__('Message with $num $what', num=2, what='placeholders'))
   Message with 2 placeholders
   >>>

Die obigen Beispiele verwenden "print()", um die Arbeitsweise der
Formatierung zu zeigen. Zum eigentlichen Protokollieren mit diesem
Ansatz würdest du natürlich "logger.debug()" oder Ähnliches verwenden.

Festzuhalten ist, dass du mit diesem Ansatz keinen bedeutsamen
Geschwindigkeitsnachteil hast: Die eigentliche Formatierung findet
nicht beim Protokollierungsaufruf statt, sondern dann (und nur dann),
wenn die protokollierte Meldung von einem Handler tatsächlich in ein
Protokoll geschrieben werden soll. Das einzige leicht Ungewöhnliche,
über das du stolpern könntest, ist, dass die Klammern um die
Formatzeichenkette *und* die Argumente stehen, nicht nur um die
Formatzeichenkette. Das liegt daran, dass die __-Schreibweise nur
Zuckerguss für einen Konstruktoraufruf einer der Klassen
"*XXX*Message" ist.

Wenn du magst, kannst du mit einem "LoggerAdapter" eine ähnliche
Wirkung wie oben erreichen, wie im folgenden Beispiel:

   import logging

   class Message:
       def __init__(self, fmt, args):
           self.fmt = fmt
           self.args = args

       def __str__(self):
           return self.fmt.format(*self.args)

   class StyleAdapter(logging.LoggerAdapter):
       def log(self, level, msg, /, *args, stacklevel=1, **kwargs):
           if self.isEnabledFor(level):
               msg, kwargs = self.process(msg, kwargs)
               self.logger.log(level, Message(msg, args), **kwargs,
                               stacklevel=stacklevel+1)

   logger = StyleAdapter(logging.getLogger(__name__))

   def main():
       logger.debug('Hello, {}', 'world!')

   if __name__ == '__main__':
       logging.basicConfig(level=logging.DEBUG)
       main()

Das obige Skript sollte die Meldung "Hello, world!" protokollieren,
wenn es mit Python 3.8 oder neuer ausgeführt wird.


"LogRecord" anpassen
====================

Jedes Protokollierungsereignis wird durch eine "LogRecord"-Instanz
dargestellt. Wird ein Ereignis protokolliert und nicht durch den
Schweregrad eines Loggers herausgefiltert, so wird ein "LogRecord"
erzeugt, mit Informationen über das Ereignis gefüllt und dann an die
Handler dieses Loggers übergeben (und an die seiner Vorfahren, bis
einschließlich zu dem Logger, bei dem die weitere Weitergabe in der
Hierarchie abgeschaltet ist). Vor Python 3.2 gab es nur zwei Stellen,
an denen diese Erzeugung geschah:

* "Logger.makeRecord()", die im normalen Ablauf der Protokollierung
  eines Ereignisses aufgerufen wird. Sie rief "LogRecord" unmittelbar
  auf, um eine Instanz zu erzeugen.

* "makeLogRecord()", die mit einem Dictionary aufgerufen wird, das
  Attribute enthält, die dem LogRecord hinzugefügt werden sollen. Das
  wird üblicherweise aufgerufen, wenn ein passendes Dictionary über
  das Netz empfangen wurde (etwa in pickle-Form über einen
  "SocketHandler" oder in JSON-Form über einen "HTTPHandler").

Das bedeutete meist, dass du eines der Folgenden tun musstest, wenn du
mit einem "LogRecord" etwas Besonderes vorhattest.

* Eine eigene Unterklasse von "Logger" anlegen, die
  "Logger.makeRecord()" überschreibt, und sie mit "setLoggerClass()"
  setzen, bevor irgendeiner der Logger, um die es dir geht, angelegt
  wird.

* Einem Logger oder Handler einen "Filter" hinzufügen, der beim Aufruf
  seiner Methode "filter()" die nötige besondere Bearbeitung vornimmt.

Der erste Ansatz wäre etwas sperrig in dem Fall, dass (sagen wir)
mehrere verschiedene Bibliotheken Unterschiedliches vorhaben. Jede
würde versuchen, ihre eigene Unterklasse von "Logger" zu setzen, und
die, die das zuletzt täte, würde gewinnen.

Der zweite Ansatz funktioniert in vielen Fällen recht gut, erlaubt dir
aber zum Beispiel nicht, eine besondere Unterklasse von "LogRecord" zu
verwenden. Bibliotheksentwickler können einen passenden Filter an
ihren Loggern setzen, müssten aber daran denken, das jedes Mal zu tun,
wenn sie einen neuen Logger einführen (was sie schon dadurch tun, dass
sie neue Pakete oder Module hinzufügen und

   logger = logging.getLogger(__name__)

auf Modulebene schreiben). Das ist vermutlich eine Sache zu viel, an
die man denken muss. Entwickler könnten den Filter auch einem
"NullHandler" hinzufügen, der an ihrem obersten Logger hängt, aber der
würde nicht aufgerufen, wenn ein Anwendungsentwickler einen Handler an
einen tieferliegenden Bibliotheks-Logger hängt --- die Ausgabe dieses
Handlers würde dann also nicht die Absichten des
Bibliotheksentwicklers widerspiegeln.

In Python 3.2 und neuer geschieht die Erzeugung von "LogRecord" über
eine Factory, die du angeben kannst. Die Factory ist einfach ein
aufrufbares Objekt, das du mit "setLogRecordFactory()" setzen und mit
"getLogRecordFactory()" abfragen kannst. Die Factory wird mit
derselben Signatur wie der Konstruktor von "LogRecord" aufgerufen,
denn "LogRecord" ist die Standardeinstellung für die Factory.

Dieser Ansatz erlaubt einer eigenen Factory, alle Aspekte der
Erzeugung eines LogRecord zu steuern. Du könntest zum Beispiel eine
Unterklasse zurückgeben oder dem erzeugten Datensatz einfach einige
zusätzliche Attribute hinzufügen, nach einem Muster wie diesem:

   old_factory = logging.getLogRecordFactory()

   def record_factory(*args, **kwargs):
       record = old_factory(*args, **kwargs)
       record.custom_attribute = 0xdecafbad
       return record

   logging.setLogRecordFactory(record_factory)

Dieses Muster erlaubt verschiedenen Bibliotheken, Factorys
aneinanderzuketten, und solange sie nicht die Attribute der jeweils
anderen oder versehentlich die standardmäßig vorhandenen Attribute
überschreiben, sollte es keine Überraschungen geben. Allerdings ist zu
bedenken, dass jedes Glied der Kette allen Protokollierungsoperationen
Laufzeitaufwand hinzufügt. Die Technik sollte nur dann eingesetzt
werden, wenn ein "Filter" nicht das gewünschte Ergebnis liefert.


Unterklassen von QueueHandler und QueueListener bilden – ein ZeroMQ-Beispiel
============================================================================


Unterklasse von "QueueHandler"
------------------------------

Mit einer Unterklasse von "QueueHandler" kannst du Meldungen an andere
Arten von Warteschlangen senden, etwa an ein „publish“-Socket von
ZeroMQ. Im Beispiel unten wird das Socket getrennt erzeugt und dem
Handler (als seine „queue“) übergeben:

   import zmq   # using pyzmq, the Python binding for ZeroMQ
   import json  # for serializing records portably

   ctx = zmq.Context()
   sock = zmq.Socket(ctx, zmq.PUB)  # or zmq.PUSH, or other suitable value
   sock.bind('tcp://*:5556')        # or wherever

   class ZeroMQSocketHandler(QueueHandler):
       def enqueue(self, record):
           self.queue.send_json(record.__dict__)


   handler = ZeroMQSocketHandler(sock)

Natürlich gibt es andere Wege, das zu gestalten, etwa indem die Daten
übergeben werden, die der Handler zum Erzeugen des Sockets braucht:

   class ZeroMQSocketHandler(QueueHandler):
       def __init__(self, uri, socktype=zmq.PUB, ctx=None):
           self.ctx = ctx or zmq.Context()
           socket = zmq.Socket(self.ctx, socktype)
           socket.bind(uri)
           super().__init__(socket)

       def enqueue(self, record):
           self.queue.send_json(record.__dict__)

       def close(self):
           self.queue.close()


Unterklasse von "QueueListener"
-------------------------------

Du kannst auch eine Unterklasse von "QueueListener" bilden, um
Meldungen aus anderen Arten von Warteschlangen zu holen, etwa aus
einem „subscribe“-Socket von ZeroMQ. Hier ein Beispiel:

   class ZeroMQSocketListener(QueueListener):
       def __init__(self, uri, /, *handlers, **kwargs):
           self.ctx = kwargs.get('ctx') or zmq.Context()
           socket = zmq.Socket(self.ctx, zmq.SUB)
           socket.setsockopt_string(zmq.SUBSCRIBE, '')  # subscribe to everything
           socket.connect(uri)
           super().__init__(socket, *handlers, **kwargs)

       def dequeue(self):
           msg = self.queue.recv_json()
           return logging.makeLogRecord(msg)


Unterklassen von QueueHandler und QueueListener bilden – ein "pynng"-Beispiel
=============================================================================

Ähnlich wie im obigen Abschnitt können wir einen Listener und einen
Handler mit pynng umsetzen, einer Python-Anbindung an NNG, das als
geistiger Nachfolger von ZeroMQ angekündigt wird. Die folgenden
Ausschnitte zeigen das -- du kannst sie in einer Umgebung testen, in
der "pynng" installiert ist. Der Abwechslung halber stellen wir den
Listener zuerst vor.


Unterklasse von "QueueListener"
-------------------------------

   # listener.py
   import json
   import logging
   import logging.handlers

   import pynng

   DEFAULT_ADDR = "tcp://localhost:13232"

   interrupted = False

   class NNGSocketListener(logging.handlers.QueueListener):

       def __init__(self, uri, /, *handlers, **kwargs):
           # Have a timeout for interruptibility, and open a
           # subscriber socket
           socket = pynng.Sub0(listen=uri, recv_timeout=500)
           # The b'' subscription matches all topics
           topics = kwargs.pop('topics', None) or b''
           socket.subscribe(topics)
           # We treat the socket as a queue
           super().__init__(socket, *handlers, **kwargs)

       def dequeue(self, block):
           data = None
           # Keep looping while not interrupted and no data received over the
           # socket
           while not interrupted:
               try:
                   data = self.queue.recv(block=block)
                   break
               except pynng.Timeout:
                   pass
               except pynng.Closed:  # sometimes happens when you hit Ctrl-C
                   break
           if data is None:
               return None
           # Get the logging event sent from a publisher
           event = json.loads(data.decode('utf-8'))
           return logging.makeLogRecord(event)

       def enqueue_sentinel(self):
           # Not used in this implementation, as the socket isn't really a
           # queue
           pass

   logging.getLogger('pynng').propagate = False
   listener = NNGSocketListener(DEFAULT_ADDR, logging.StreamHandler(), topics=b'')
   listener.start()
   print('Press Ctrl-C to stop.')
   try:
       while True:
           pass
   except KeyboardInterrupt:
       interrupted = True
   finally:
       listener.stop()


Unterklasse von "QueueHandler"
------------------------------

   # sender.py
   import json
   import logging
   import logging.handlers
   import time
   import random

   import pynng

   DEFAULT_ADDR = "tcp://localhost:13232"

   class NNGSocketHandler(logging.handlers.QueueHandler):

       def __init__(self, uri):
           socket = pynng.Pub0(dial=uri, send_timeout=500)
           super().__init__(socket)

       def enqueue(self, record):
           # Send the record as UTF-8 encoded JSON
           d = dict(record.__dict__)
           data = json.dumps(d)
           self.queue.send(data.encode('utf-8'))

       def close(self):
           self.queue.close()

   logging.getLogger('pynng').propagate = False
   handler = NNGSocketHandler(DEFAULT_ADDR)
   # Make sure the process ID is in the output
   logging.basicConfig(level=logging.DEBUG,
                       handlers=[logging.StreamHandler(), handler],
                       format='%(levelname)-8s %(name)10s %(process)6s %(message)s')
   levels = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,
             logging.CRITICAL)
   logger_names = ('myapp', 'myapp.lib1', 'myapp.lib2')
   msgno = 1
   while True:
       # Just randomly select some loggers and levels and log away
       level = random.choice(levels)
       logger = logging.getLogger(random.choice(logger_names))
       logger.log(level, 'Message no. %5d' % msgno)
       msgno += 1
       delay = random.random() * 2 + 0.5
       time.sleep(delay)

Du kannst die obigen zwei Ausschnitte in getrennten Befehlsfenstern
ausführen. Lassen wir den Listener in einem Fenster laufen und den
Sender in zwei weiteren Fenstern, sollten wir etwa Folgendes sehen. Im
ersten Senderfenster:

   $ python sender.py
   DEBUG         myapp    613 Message no.     1
   WARNING  myapp.lib2    613 Message no.     2
   CRITICAL myapp.lib2    613 Message no.     3
   WARNING  myapp.lib2    613 Message no.     4
   CRITICAL myapp.lib1    613 Message no.     5
   DEBUG         myapp    613 Message no.     6
   CRITICAL myapp.lib1    613 Message no.     7
   INFO     myapp.lib1    613 Message no.     8
   (and so on)

Im zweiten Senderfenster:

   $ python sender.py
   INFO     myapp.lib2    657 Message no.     1
   CRITICAL myapp.lib2    657 Message no.     2
   CRITICAL      myapp    657 Message no.     3
   CRITICAL myapp.lib1    657 Message no.     4
   INFO     myapp.lib1    657 Message no.     5
   WARNING  myapp.lib2    657 Message no.     6
   CRITICAL      myapp    657 Message no.     7
   DEBUG    myapp.lib1    657 Message no.     8
   (and so on)

Im Listener-Fenster:

   $ python listener.py
   Press Ctrl-C to stop.
   DEBUG         myapp    613 Message no.     1
   WARNING  myapp.lib2    613 Message no.     2
   INFO     myapp.lib2    657 Message no.     1
   CRITICAL myapp.lib2    613 Message no.     3
   CRITICAL myapp.lib2    657 Message no.     2
   CRITICAL      myapp    657 Message no.     3
   WARNING  myapp.lib2    613 Message no.     4
   CRITICAL myapp.lib1    613 Message no.     5
   CRITICAL myapp.lib1    657 Message no.     4
   INFO     myapp.lib1    657 Message no.     5
   DEBUG         myapp    613 Message no.     6
   WARNING  myapp.lib2    657 Message no.     6
   CRITICAL      myapp    657 Message no.     7
   CRITICAL myapp.lib1    613 Message no.     7
   INFO     myapp.lib1    613 Message no.     8
   DEBUG    myapp.lib1    657 Message no.     8
   (and so on)

Wie du siehst, ist die Protokollierung der beiden Senderprozesse in
der Ausgabe des Listeners miteinander verschränkt.


Ein Beispiel für eine Dictionary-basierte Konfiguration
=======================================================

Unten ein Beispiel für ein Dictionary zur
Protokollierungskonfiguration – es ist der Dokumentation des Django-
Projekts entnommen. Dieses Dictionary wird "dictConfig()" übergeben,
um die Konfiguration wirksam zu machen:

   LOGGING = {
       'version': 1,
       'disable_existing_loggers': False,
       'formatters': {
           'verbose': {
               'format': '{levelname} {asctime} {module} {process:d} {thread:d} {message}',
               'style': '{',
           },
           'simple': {
               'format': '{levelname} {message}',
               'style': '{',
           },
       },
       'filters': {
           'special': {
               '()': 'project.logging.SpecialFilter',
               'foo': 'bar',
           },
       },
       'handlers': {
           'console': {
               'level': 'INFO',
               'class': 'logging.StreamHandler',
               'formatter': 'simple',
           },
           'mail_admins': {
               'level': 'ERROR',
               'class': 'django.utils.log.AdminEmailHandler',
               'filters': ['special']
           }
       },
       'loggers': {
           'django': {
               'handlers': ['console'],
               'propagate': True,
           },
           'django.request': {
               'handlers': ['mail_admins'],
               'level': 'ERROR',
               'propagate': False,
           },
           'myproject.custom': {
               'handlers': ['console', 'mail_admins'],
               'level': 'INFO',
               'filters': ['special']
           }
       }
   }

Mehr Informationen zu dieser Konfiguration findest du im
entsprechenden Abschnitt der Django-Dokumentation.


Mit einem Rotator und einem Namer die Protokollrotation anpassen
================================================================

Ein Beispiel dafür, wie du einen Namer und einen Rotator festlegen
kannst, gibt das folgende lauffähige Skript, das die Protokolldatei
mit gzip komprimiert:

   import gzip
   import logging
   import logging.handlers
   import os
   import shutil

   def namer(name):
       return name + ".gz"

   def rotator(source, dest):
       with open(source, 'rb') as f_in:
           with gzip.open(dest, 'wb') as f_out:
               shutil.copyfileobj(f_in, f_out)
       os.remove(source)


   rh = logging.handlers.RotatingFileHandler('rotated.log', maxBytes=128, backupCount=5)
   rh.rotator = rotator
   rh.namer = namer

   root = logging.getLogger()
   root.setLevel(logging.INFO)
   root.addHandler(rh)
   f = logging.Formatter('%(asctime)s %(message)s')
   rh.setFormatter(f)
   for i in range(1000):
       root.info(f'Message no. {i + 1}')

Nach dem Ausführen siehst du sechs neue Dateien, von denen fünf
komprimiert sind:

   $ ls rotated.log*
   rotated.log       rotated.log.2.gz  rotated.log.4.gz
   rotated.log.1.gz  rotated.log.3.gz  rotated.log.5.gz
   $ zcat rotated.log.1.gz
   2023-01-20 02:28:17,767 Message no. 996
   2023-01-20 02:28:17,767 Message no. 997
   2023-01-20 02:28:17,767 Message no. 998


Ein ausgefeilteres Beispiel mit multiprocessing
===============================================

Das folgende funktionierende Beispiel zeigt, wie sich die
Protokollierung zusammen mit multiprocessing über
Konfigurationsdateien nutzen lässt. Die Konfigurationen sind recht
einfach, verdeutlichen aber, wie sich komplexere in einem echten
Szenario mit mehreren Prozessen umsetzen ließen.

Im Beispiel erzeugt der Hauptprozess einen Listener-Prozess und einige
Arbeiterprozesse. Hauptprozess, Listener und Arbeiter haben jeweils
drei getrennte Konfigurationen (die Arbeiter teilen sich alle dieselbe
Konfiguration). Wir sehen die Protokollierung im Hauptprozess, wie die
Arbeiter in einen QueueHandler protokollieren und wie der Listener
einen QueueListener und eine komplexere Protokollierungskonfiguration
umsetzt und dafür sorgt, dass über die Warteschlange empfangene
Ereignisse an die in der Konfiguration angegebenen Handler verteilt
werden. Beachte, dass diese Konfigurationen rein zur Veranschaulichung
dienen, du solltest dieses Beispiel aber auf dein eigenes Szenario
anpassen können.

Hier das Skript – die Docstrings und die Kommentare erklären
hoffentlich, wie es arbeitet:

   import logging
   import logging.config
   import logging.handlers
   from multiprocessing import Process, Queue, Event, current_process
   import os
   import random
   import time

   class MyHandler:
       """
       A simple handler for logging events. It runs in the listener process and
       dispatches events to loggers based on the name in the received record,
       which then get dispatched, by the logging system, to the handlers
       configured for those loggers.
       """

       def handle(self, record):
           if record.name == "root":
               logger = logging.getLogger()
           else:
               logger = logging.getLogger(record.name)

           if logger.isEnabledFor(record.levelno):
               # The process name is transformed just to show that it's the listener
               # doing the logging to files and console
               record.processName = '%s (for %s)' % (current_process().name, record.processName)
               logger.handle(record)

   def listener_process(q, stop_event, config):
       """
       This could be done in the main process, but is just done in a separate
       process for illustrative purposes.

       This initialises logging according to the specified configuration,
       starts the listener and waits for the main process to signal completion
       via the event. The listener is then stopped, and the process exits.
       """
       logging.config.dictConfig(config)
       listener = logging.handlers.QueueListener(q, MyHandler())
       listener.start()
       if os.name == 'posix':
           # On POSIX, the setup logger will have been configured in the
           # parent process, but should have been disabled following the
           # dictConfig call.
           # On Windows, since fork isn't used, the setup logger won't
           # exist in the child, so it would be created and the message
           # would appear - hence the "if posix" clause.
           logger = logging.getLogger('setup')
           logger.critical('Should not appear, because of disabled logger ...')
       stop_event.wait()
       listener.stop()

   def worker_process(config):
       """
       A number of these are spawned for the purpose of illustration. In
       practice, they could be a heterogeneous bunch of processes rather than
       ones which are identical to each other.

       This initialises logging according to the specified configuration,
       and logs a hundred messages with random levels to randomly selected
       loggers.

       A small sleep is added to allow other processes a chance to run. This
       is not strictly needed, but it mixes the output from the different
       processes a bit more than if it's left out.
       """
       logging.config.dictConfig(config)
       levels = [logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,
                 logging.CRITICAL]
       loggers = ['foo', 'foo.bar', 'foo.bar.baz',
                  'spam', 'spam.ham', 'spam.ham.eggs']
       if os.name == 'posix':
           # On POSIX, the setup logger will have been configured in the
           # parent process, but should have been disabled following the
           # dictConfig call.
           # On Windows, since fork isn't used, the setup logger won't
           # exist in the child, so it would be created and the message
           # would appear - hence the "if posix" clause.
           logger = logging.getLogger('setup')
           logger.critical('Should not appear, because of disabled logger ...')
       for i in range(100):
           lvl = random.choice(levels)
           logger = logging.getLogger(random.choice(loggers))
           logger.log(lvl, 'Message no. %d', i)
           time.sleep(0.01)

   def main():
       q = Queue()
       # The main process gets a simple configuration which prints to the console.
       config_initial = {
           'version': 1,
           'handlers': {
               'console': {
                   'class': 'logging.StreamHandler',
                   'level': 'INFO'
               }
           },
           'root': {
               'handlers': ['console'],
               'level': 'DEBUG'
           }
       }
       # The worker process configuration is just a QueueHandler attached to the
       # root logger, which allows all messages to be sent to the queue.
       # We disable existing loggers to disable the "setup" logger used in the
       # parent process. This is needed on POSIX because the logger will
       # be there in the child following a fork().
       config_worker = {
           'version': 1,
           'disable_existing_loggers': True,
           'handlers': {
               'queue': {
                   'class': 'logging.handlers.QueueHandler',
                   'queue': q
               }
           },
           'root': {
               'handlers': ['queue'],
               'level': 'DEBUG'
           }
       }
       # The listener process configuration shows that the full flexibility of
       # logging configuration is available to dispatch events to handlers however
       # you want.
       # We disable existing loggers to disable the "setup" logger used in the
       # parent process. This is needed on POSIX because the logger will
       # be there in the child following a fork().
       config_listener = {
           'version': 1,
           'disable_existing_loggers': True,
           'formatters': {
               'detailed': {
                   'class': 'logging.Formatter',
                   'format': '%(asctime)s %(name)-15s %(levelname)-8s %(processName)-10s %(message)s'
               },
               'simple': {
                   'class': 'logging.Formatter',
                   'format': '%(name)-15s %(levelname)-8s %(processName)-10s %(message)s'
               }
           },
           'handlers': {
               'console': {
                   'class': 'logging.StreamHandler',
                   'formatter': 'simple',
                   'level': 'INFO'
               },
               'file': {
                   'class': 'logging.FileHandler',
                   'filename': 'mplog.log',
                   'mode': 'w',
                   'formatter': 'detailed'
               },
               'foofile': {
                   'class': 'logging.FileHandler',
                   'filename': 'mplog-foo.log',
                   'mode': 'w',
                   'formatter': 'detailed'
               },
               'errors': {
                   'class': 'logging.FileHandler',
                   'filename': 'mplog-errors.log',
                   'mode': 'w',
                   'formatter': 'detailed',
                   'level': 'ERROR'
               }
           },
           'loggers': {
               'foo': {
                   'handlers': ['foofile']
               }
           },
           'root': {
               'handlers': ['console', 'file', 'errors'],
               'level': 'DEBUG'
           }
       }
       # Log some initial events, just to show that logging in the parent works
       # normally.
       logging.config.dictConfig(config_initial)
       logger = logging.getLogger('setup')
       logger.info('About to create workers ...')
       workers = []
       for i in range(5):
           wp = Process(target=worker_process, name='worker %d' % (i + 1),
                        args=(config_worker,))
           workers.append(wp)
           wp.start()
           logger.info('Started worker: %s', wp.name)
       logger.info('About to create listener ...')
       stop_event = Event()
       lp = Process(target=listener_process, name='listener',
                    args=(q, stop_event, config_listener))
       lp.start()
       logger.info('Started listener')
       # We now hang around for the workers to finish their work.
       for wp in workers:
           wp.join()
       # Workers all done, listening can now stop.
       # Logging in the parent still works normally.
       logger.info('Telling listener to stop ...')
       stop_event.set()
       lp.join()
       logger.info('All done.')

   if __name__ == '__main__':
       main()


Ein BOM in Meldungen einfügen, die an einen SysLogHandler gehen
===============================================================

**RFC 5424** verlangt, dass eine Unicode-Meldung als Folge von Bytes
mit folgendem Aufbau an einen syslog-Daemon gesendet wird: ein
optionaler reiner ASCII-Teil, gefolgt von einer
UTF-8-Bytereihenfolgemarke (BOM), gefolgt von Unicode, kodiert in
UTF-8. (Siehe den **entsprechenden Abschnitt der Spezifikation**.)

In Python 3.1 wurde "SysLogHandler" um Code ergänzt, der ein BOM in
die Meldung einfügt, der aber leider falsch umgesetzt war: Das BOM
erschien am Anfang der Meldung, sodass davor kein reiner ASCII-Teil
stehen konnte.

Weil dieses Verhalten fehlerhaft ist, wird der falsche Code zum
Einfügen des BOM in Python 3.2.4 und neuer entfernt. Er wird
allerdings nicht ersetzt, und willst du Meldungen gemäß **RFC 5424**
erzeugen, die ein BOM, davor eine optionale reine ASCII-Folge und
danach beliebiges, in UTF-8 kodiertes Unicode enthalten, dann musst du
Folgendes tun:

1. Hänge eine "Formatter"-Instanz an deine "SysLogHandler"-Instanz,
   mit einer Formatzeichenkette wie:

      'ASCII section\ufeffUnicode section'

   Der Unicode-Codepunkt U+FEFF wird, in UTF-8 kodiert, zu einem
   UTF-8-BOM -- der Bytefolge "b'\xef\xbb\xbf'".

2. Ersetze den ASCII-Teil durch beliebige Platzhalter, achte aber
   darauf, dass die Daten, die nach dem Einsetzen dort erscheinen,
   immer ASCII sind (so bleiben sie nach der UTF-8-Kodierung
   unverändert).

3. Ersetze den Unicode-Teil durch beliebige Platzhalter. Enthalten die
   Daten, die dort nach dem Einsetzen erscheinen, Zeichen außerhalb
   des ASCII-Bereichs, ist das in Ordnung -- sie werden in UTF-8
   kodiert.

Die formatierte Meldung *wird* von "SysLogHandler" in UTF-8 kodiert.
Hältst du dich an die obigen Regeln, solltest du Meldungen gemäß **RFC
5424** erzeugen können. Tust du es nicht, beschwert sich die
Protokollierung möglicherweise nicht, aber deine Meldungen entsprechen
nicht RFC 5424, und dein syslog-Daemon beschwert sich möglicherweise
doch.


Strukturierte Protokollierung umsetzen
======================================

Die meisten Protokollmeldungen sind zwar zum Lesen durch Menschen
gedacht und damit nicht ohne Weiteres maschinell zerlegbar, aber es
kann Umstände geben, in denen du Meldungen in einem strukturierten
Format ausgeben willst, das sich von einem Programm zerlegen *lässt*
(ohne komplexe reguläre Ausdrücke zum Zerlegen der Protokollmeldung).
Mit dem Paket logging ist das unkompliziert zu erreichen. Es gibt
dafür mehrere Wege, der folgende ist aber ein einfacher Ansatz, der
das Ereignis mit JSON maschinenlesbar serialisiert:

   import json
   import logging

   class StructuredMessage:
       def __init__(self, message, /, **kwargs):
           self.message = message
           self.kwargs = kwargs

       def __str__(self):
           return '%s >>> %s' % (self.message, json.dumps(self.kwargs))

   _ = StructuredMessage   # optional, to improve readability

   logging.basicConfig(level=logging.INFO, format='%(message)s')
   logging.info(_('message 1', foo='bar', bar='baz', num=123, fnum=123.456))

Wird das obige Skript ausgeführt, gibt es aus:

   message 1 >>> {"fnum": 123.456, "num": 123, "bar": "baz", "foo": "bar"}

Beachte, dass die Reihenfolge der Einträge je nach verwendeter Python-
Version unterschiedlich sein kann.

Brauchst du eine spezialisiertere Verarbeitung, kannst du einen
eigenen JSON-Kodierer verwenden, wie im folgenden vollständigen
Beispiel:

   import json
   import logging


   class Encoder(json.JSONEncoder):
       def default(self, o):
           if isinstance(o, set):
               return tuple(o)
           elif isinstance(o, str):
               return o.encode('unicode_escape').decode('ascii')
           return super().default(o)

   class StructuredMessage:
       def __init__(self, message, /, **kwargs):
           self.message = message
           self.kwargs = kwargs

       def __str__(self):
           s = Encoder().encode(self.kwargs)
           return '%s >>> %s' % (self.message, s)

   _ = StructuredMessage   # optional, to improve readability

   def main():
       logging.basicConfig(level=logging.INFO, format='%(message)s')
       logging.info(_('message 1', set_value={1, 2, 3}, snowman='\u2603'))

   if __name__ == '__main__':
       main()

Wird das obige Skript ausgeführt, gibt es aus:

   message 1 >>> {"snowman": "\u2603", "set_value": [1, 2, 3]}

Beachte, dass die Reihenfolge der Einträge je nach verwendeter Python-
Version unterschiedlich sein kann.


Handler mit "dictConfig()" anpassen
===================================

Manchmal willst du Protokollierungs-Handler auf bestimmte Weise
anpassen, und mit "dictConfig()" gelingt dir das möglicherweise ohne
Unterklassen. Nimm als Beispiel, dass du den Eigentümer einer
Protokolldatei setzen willst. Unter POSIX geht das leicht mit
"shutil.chown()", aber die Datei-Handler der Standardbibliothek
unterstützen das nicht von sich aus. Du kannst die Erzeugung des
Handlers mit einer gewöhnlichen Funktion anpassen, etwa so:

   def owned_file_handler(filename, mode='a', encoding=None, owner=None):
       if owner:
           if not os.path.exists(filename):
               open(filename, 'a').close()
           shutil.chown(filename, *owner)
       return logging.FileHandler(filename, mode, encoding)

In einer Protokollierungskonfiguration, die du "dictConfig()"
übergibst, kannst du dann angeben, dass ein Protokollierungs-Handler
durch den Aufruf dieser Funktion erzeugt wird:

   LOGGING = {
       'version': 1,
       'disable_existing_loggers': False,
       'formatters': {
           'default': {
               'format': '%(asctime)s %(levelname)s %(name)s %(message)s'
           },
       },
       'handlers': {
           'file':{
               # The values below are popped from this dictionary and
               # used to create the handler, set the handler's level and
               # its formatter.
               '()': owned_file_handler,
               'level':'DEBUG',
               'formatter': 'default',
               # The values below are passed to the handler creator callable
               # as keyword arguments.
               'owner': ['pulse', 'pulse'],
               'filename': 'chowntest.log',
               'mode': 'w',
               'encoding': 'utf-8',
           },
       },
       'root': {
           'handlers': ['file'],
           'level': 'DEBUG',
       },
   }

In diesem Beispiel setze ich den Eigentümer, nur zur
Veranschaulichung, auf den Benutzer und die Gruppe "pulse". Zu einem
funktionierenden Skript zusammengesetzt, "chowntest.py":

   import logging, logging.config, os, shutil

   def owned_file_handler(filename, mode='a', encoding=None, owner=None):
       if owner:
           if not os.path.exists(filename):
               open(filename, 'a').close()
           shutil.chown(filename, *owner)
       return logging.FileHandler(filename, mode, encoding)

   LOGGING = {
       'version': 1,
       'disable_existing_loggers': False,
       'formatters': {
           'default': {
               'format': '%(asctime)s %(levelname)s %(name)s %(message)s'
           },
       },
       'handlers': {
           'file':{
               # The values below are popped from this dictionary and
               # used to create the handler, set the handler's level and
               # its formatter.
               '()': owned_file_handler,
               'level':'DEBUG',
               'formatter': 'default',
               # The values below are passed to the handler creator callable
               # as keyword arguments.
               'owner': ['pulse', 'pulse'],
               'filename': 'chowntest.log',
               'mode': 'w',
               'encoding': 'utf-8',
           },
       },
       'root': {
           'handlers': ['file'],
           'level': 'DEBUG',
       },
   }

   logging.config.dictConfig(LOGGING)
   logger = logging.getLogger('mylogger')
   logger.debug('A debug message')

Um das auszuführen, musst du vermutlich als "root" arbeiten:

   $ sudo python3.3 chowntest.py
   $ cat chowntest.log
   2013-11-05 09:34:51,128 DEBUG mylogger A debug message
   $ ls -l chowntest.log
   -rw-r--r-- 1 pulse pulse 55 2013-11-05 09:34 chowntest.log

Beachte, dass dieses Beispiel Python 3.3 verwendet, weil dort
"shutil.chown()" auftritt. Dieser Ansatz sollte mit jeder Python-
Version funktionieren, die "dictConfig()" unterstützt – also mit
Python 2.7, 3.2 oder neuer. Mit Versionen vor 3.3 müsstest du den
eigentlichen Eigentümerwechsel zum Beispiel mit "os.chown()" umsetzen.

In der Praxis liegt die Funktion, die den Handler erzeugt,
möglicherweise in einem Hilfsmodul irgendwo in deinem Projekt. Statt
der Zeile in der Konfiguration:

   '()': owned_file_handler,

könntest du zum Beispiel schreiben:

   '()': 'ext://project.util.owned_file_handler',

wobei "project.util" durch den tatsächlichen Namen des Pakets zu
ersetzen ist, in dem die Funktion liegt. Im obigen funktionierenden
Skript sollte "'ext://__main__.owned_file_handler'" arbeiten. Hier
löst "dictConfig()" das eigentliche aufrufbare Objekt aus der
"ext://"-Angabe auf.

Dieses Beispiel weist hoffentlich auch den Weg, wie du auf dieselbe
Weise andere Arten von Dateiänderungen umsetzen könntest – etwa das
Setzen bestimmter POSIX-Rechtebits mit "os.chmod()".

Natürlich ließe sich der Ansatz auch auf andere Handler-Arten als
"FileHandler" ausdehnen – zum Beispiel auf einen der rotierenden
Datei-Handler oder auf eine völlig andere Art von Handler.


In der ganzen Anwendung bestimmte Formatierungsstile verwenden
==============================================================

In Python 3.2 erhielt "Formatter" einen Schlüsselwortparameter
"style", dessen Vorgabe aus Verträglichkeitsgründen "%" ist, der aber
auch "{" oder "$" erlaubt, um die Formatierungsansätze von
"str.format()" und "string.Template" zu unterstützen. Beachte, dass
das die Formatierung von Protokollmeldungen für die endgültige Ausgabe
in die Protokolle steuert und völlig unabhängig davon ist, wie eine
einzelne Protokollmeldung aufgebaut wird.

Protokollierungsaufrufe ("debug()", "info()" und so weiter) nehmen für
die eigentliche Protokollmeldung nur positionsbezogene Parameter;
Schlüsselwortparameter dienen nur dazu, Optionen für die Behandlung
des Protokollierungsaufrufs festzulegen (etwa der
Schlüsselwortparameter "exc_info", der anzeigt, dass Traceback-
Informationen protokolliert werden sollen, oder der
Schlüsselwortparameter "extra", der zusätzliche Kontextinformationen
für das Protokoll anzeigt). Du kannst Protokollierungsaufrufe also
nicht unmittelbar in der Syntax von "str.format()" oder
"string.Template" machen, weil das Paket logging intern %-Formatierung
verwendet, um Formatzeichenkette und veränderliche Argumente
zusammenzuführen. Daran ließe sich nichts ändern, ohne die
Verträglichkeit mit früheren Versionen aufzugeben, denn alle
Protokollierungsaufrufe im vorhandenen Code verwenden
%-Formatzeichenketten.

Es gab Vorschläge, Formatstile mit bestimmten Loggern zu verknüpfen,
aber auch dieser Ansatz läuft in Verträglichkeitsprobleme, weil
vorhandener Code einen gegebenen Loggernamen zusammen mit
%-Formatierung verwenden könnte.

Damit die Protokollierung zwischen Bibliotheken Dritter und deinem
Code zusammenspielt, müssen Entscheidungen über die Formatierung auf
der Ebene des einzelnen Protokollierungsaufrufs fallen. Das eröffnet
ein paar Wege, auf denen sich andere Formatierungsstile unterbringen
lassen.


LogRecord-Factorys verwenden
----------------------------

In Python 3.2 erhielt das Paket logging neben den oben erwähnten
Änderungen an "Formatter" auch die Möglichkeit, dass Benutzer über die
Funktion "setLogRecordFactory()" eigene Unterklassen von "LogRecord"
setzen. Damit kannst du deine eigene Unterklasse von "LogRecord"
setzen, die das Richtige tut, indem sie die Methode "getMessage()"
überschreibt. In der Umsetzung dieser Methode in der Basisklasse
findet die Formatierung "msg % args" statt, und dort kannst du deine
abweichende Formatierung einsetzen. Du solltest allerdings darauf
achten, alle Formatierungsstile zu unterstützen und %-Formatierung als
Vorgabe zuzulassen, damit das Zusammenspiel mit anderem Code
gewährleistet bleibt. Achte außerdem darauf, "str(self.msg)"
aufzurufen, so wie es die Umsetzung in der Basisklasse tut.

Mehr Informationen findest du in der Referenzdokumentation zu
"setLogRecordFactory()" und "LogRecord".


Eigene Meldungsobjekte verwenden
--------------------------------

Es gibt einen weiteren, vielleicht einfacheren Weg, {}- und
$-Formatierung zu nutzen, um deine einzelnen Protokollmeldungen
aufzubauen. Du erinnerst dich vielleicht (aus Beliebige Objekte als
Meldungen verwenden), dass du beim Protokollieren ein beliebiges
Objekt als Formatzeichenkette einer Meldung verwenden kannst und dass
das Paket logging "str()" auf dieses Objekt anwendet, um die
eigentliche Formatzeichenkette zu erhalten. Betrachte die folgenden
zwei Klassen:

   class BraceMessage:
       def __init__(self, fmt, /, *args, **kwargs):
           self.fmt = fmt
           self.args = args
           self.kwargs = kwargs

       def __str__(self):
           return self.fmt.format(*self.args, **self.kwargs)

   class DollarMessage:
       def __init__(self, fmt, /, **kwargs):
           self.fmt = fmt
           self.kwargs = kwargs

       def __str__(self):
           from string import Template
           return Template(self.fmt).substitute(**self.kwargs)

Beide lassen sich anstelle einer Formatzeichenkette verwenden, sodass
sich der eigentliche „Meldungs“-Teil, der in der formatierten
Protokollausgabe anstelle von „%(message)s“, „{message}“ oder
„$message“ erscheint, mit {}- oder $-Formatierung aufbauen lässt.
Findest du es etwas sperrig, die Klassennamen jedes Mal zu schreiben,
wenn du etwas protokollieren willst, kannst du es erträglicher machen,
indem du für die Meldung einen Alias wie "M" oder "_" verwendest (oder
vielleicht "__", wenn du "_" für die Lokalisierung nutzt).

Beispiele für diesen Ansatz folgen unten. Zunächst die Formatierung
mit "str.format()":

   >>> __ = BraceMessage
   >>> print(__('Message with {0} {1}', 2, 'placeholders'))
   Message with 2 placeholders
   >>> class Point: pass
   ...
   >>> p = Point()
   >>> p.x = 0.5
   >>> p.y = 0.5
   >>> print(__('Message with coordinates: ({point.x:.2f}, {point.y:.2f})', point=p))
   Message with coordinates: (0.50, 0.50)

Und zweitens die Formatierung mit "string.Template":

   >>> __ = DollarMessage
   >>> print(__('Message with $num $what', num=2, what='placeholders'))
   Message with 2 placeholders
   >>>

Festzuhalten ist, dass du mit diesem Ansatz keinen bedeutsamen
Geschwindigkeitsnachteil hast: Die eigentliche Formatierung findet
nicht beim Protokollierungsaufruf statt, sondern dann (und nur dann),
wenn die protokollierte Meldung von einem Handler tatsächlich in ein
Protokoll geschrieben werden soll. Das einzige leicht Ungewöhnliche,
über das du stolpern könntest, ist, dass die Klammern um die
Formatzeichenkette *und* die Argumente stehen, nicht nur um die
Formatzeichenkette. Das liegt daran, dass die __-Schreibweise nur
Zuckerguss für einen Konstruktoraufruf einer der oben gezeigten
Klassen "*XXX*Message" ist.


Filter mit "dictConfig()" konfigurieren
=======================================

Du *kannst* Filter mit "dictConfig()" konfigurieren, auch wenn auf den
ersten Blick nicht offensichtlich ist, wie (daher dieses Rezept). Da
"Filter" die einzige Filterklasse in der Standardbibliothek ist und
kaum viele Anforderungen abdeckt (sie ist nur als Basisklasse
gedacht), musst du üblicherweise deine eigene Unterklasse von "Filter"
mit einer überschriebenen Methode "filter()" festlegen. Gib dazu im
Konfigurations-Dictionary für den Filter den Schlüssel "()" an und
nenne darin ein aufrufbares Objekt, mit dem der Filter erzeugt wird
(eine Klasse ist das Naheliegendste, du kannst aber jedes aufrufbare
Objekt angeben, das eine "Filter"-Instanz zurückgibt). Hier ein
vollständiges Beispiel:

   import logging
   import logging.config
   import sys

   class MyFilter(logging.Filter):
       def __init__(self, param=None):
           self.param = param

       def filter(self, record):
           if self.param is None:
               allow = True
           else:
               allow = self.param not in record.msg
           if allow:
               record.msg = 'changed: ' + record.msg
           return allow

   LOGGING = {
       'version': 1,
       'filters': {
           'myfilter': {
               '()': MyFilter,
               'param': 'noshow',
           }
       },
       'handlers': {
           'console': {
               'class': 'logging.StreamHandler',
               'filters': ['myfilter']
           }
       },
       'root': {
           'level': 'DEBUG',
           'handlers': ['console']
       },
   }

   if __name__ == '__main__':
       logging.config.dictConfig(LOGGING)
       logging.debug('hello')
       logging.debug('hello - noshow')

Dieses Beispiel zeigt, wie du dem aufrufbaren Objekt, das die Instanz
erzeugt, Konfigurationsdaten in Form von Schlüsselwortparametern
übergeben kannst. Beim Ausführen gibt das obige Skript aus:

   changed: hello

was zeigt, dass der Filter wie konfiguriert arbeitet.

Noch ein paar zusätzliche Hinweise:

* Kannst du das aufrufbare Objekt in der Konfiguration nicht
  unmittelbar ansprechen (etwa weil es in einem anderen Modul liegt
  und du es dort, wo das Konfigurations-Dictionary steht, nicht
  unmittelbar importieren kannst), dann kannst du die Form "ext://..."
  verwenden, wie unter Access to external objects beschrieben. Du
  hättest im obigen Beispiel zum Beispiel den Text
  "'ext://__main__.MyFilter'" statt "MyFilter" verwenden können.

* Diese Technik lässt sich nicht nur für Filter, sondern auch zum
  Konfigurieren eigener Handler und Formatter verwenden. Unter User-
  defined objects findest du mehr dazu, wie die Protokollierung selbst
  festgelegte Objekte in ihrer Konfiguration unterstützt, und siehe
  auch das andere Rezept Handler mit dictConfig() anpassen weiter oben
  in diesem Kochbuch.


Eigene Formatierung von Ausnahmen
=================================

Manchmal willst du Ausnahmen selbst formatieren – nehmen wir der
Argumentation halber an, du willst genau eine Zeile je protokolliertem
Ereignis, auch wenn Informationen zu einer Ausnahme dabei sind. Das
kannst du mit einer eigenen Formatter-Klasse erreichen, wie das
folgende Beispiel zeigt:

   import logging

   class OneLineExceptionFormatter(logging.Formatter):
       def formatException(self, exc_info):
           """
           Format an exception so that it prints on a single line.
           """
           result = super().formatException(exc_info)
           return repr(result)  # or format into one line however you want to

       def format(self, record):
           s = super().format(record)
           if record.exc_text:
               s = s.replace('\n', '') + '|'
           return s

   def configure_logging():
       fh = logging.FileHandler('output.txt', 'w')
       f = OneLineExceptionFormatter('%(asctime)s|%(levelname)s|%(message)s|',
                                     '%d/%m/%Y %H:%M:%S')
       fh.setFormatter(f)
       root = logging.getLogger()
       root.setLevel(logging.DEBUG)
       root.addHandler(fh)

   def main():
       configure_logging()
       logging.info('Sample message')
       try:
           x = 1 / 0
       except ZeroDivisionError as e:
           logging.exception('ZeroDivisionError: %s', e)

   if __name__ == '__main__':
       main()

Beim Ausführen entsteht eine Datei mit genau zwei Zeilen:

   28/01/2015 07:21:23|INFO|Sample message|
   28/01/2015 07:21:23|ERROR|ZeroDivisionError: division by zero|'Traceback (most recent call last):\n  File "logtest7.py", line 30, in main\n    x = 1 / 0\nZeroDivisionError: division by zero'|

Die obige Behandlung ist zwar vereinfacht, weist aber den Weg, wie
sich Informationen zu Ausnahmen nach deinem Geschmack formatieren
lassen. Bei spezielleren Bedürfnissen hilft möglicherweise das Modul
"traceback".


Protokollmeldungen sprechen lassen
==================================

Es kann Situationen geben, in denen Protokollmeldungen besser hörbar
als sichtbar ausgegeben werden. Das ist leicht möglich, wenn dein
System Sprachsynthese (Text-to-Speech, TTS) bietet, selbst wenn es
dafür keine Python-Anbindung gibt. Die meisten TTS-Systeme haben ein
Befehlszeilenprogramm, das du ausführen kannst, und das lässt sich aus
einem Handler heraus mit "subprocess" aufrufen. Hier wird angenommen,
dass TTS-Befehlszeilenprogramme keine Interaktion mit Benutzern
erwarten und nicht lange brauchen, dass die Protokollmeldungen nicht
so häufig sind, dass der Benutzer von Meldungen überschwemmt wird, und
dass es annehmbar ist, die Meldungen eine nach der anderen statt
nebenläufig sprechen zu lassen. Die Beispielumsetzung unten wartet,
bis eine Meldung gesprochen wurde, bevor die nächste verarbeitet wird.
Das kann dazu führen, dass andere Handler warten müssen. Hier ein
kurzes Beispiel für den Ansatz, das voraussetzt, dass das TTS-Paket
"espeak" vorhanden ist:

   import logging
   import subprocess
   import sys

   class TTSHandler(logging.Handler):
       def emit(self, record):
           msg = self.format(record)
           # Speak slowly in a female English voice
           cmd = ['espeak', '-s150', '-ven+f3', msg]
           p = subprocess.Popen(cmd, stdout=subprocess.PIPE,
                                stderr=subprocess.STDOUT)
           # wait for the program to finish
           p.communicate()

   def configure_logging():
       h = TTSHandler()
       root = logging.getLogger()
       root.addHandler(h)
       # the default formatter just returns the message
       root.setLevel(logging.DEBUG)

   def main():
       logging.info('Hello')
       logging.debug('Goodbye')

   if __name__ == '__main__':
       configure_logging()
       sys.exit(main())

Beim Ausführen sollte dieses Skript mit weiblicher Stimme „Hello“ und
dann „Goodbye“ sagen.

Der obige Ansatz lässt sich natürlich auf andere TTS-Systeme und sogar
auf ganz andere Systeme übertragen, die Meldungen über externe, von
einer Befehlszeile gestartete Programme verarbeiten können.


Protokollmeldungen puffern und bedingt ausgeben
===============================================

Es kann Situationen geben, in denen du Meldungen zunächst in einem
Zwischenbereich protokollieren und nur dann ausgeben willst, wenn eine
bestimmte Bedingung eintritt. Du willst zum Beispiel in einer Funktion
Debug-Ereignisse protokollieren und, wenn die Funktion ohne Fehler
durchläuft, das Protokoll nicht mit den gesammelten Debug-
Informationen zumüllen – tritt aber ein Fehler auf, sollen alle Debug-
Informationen zusammen mit dem Fehler ausgegeben werden.

Hier ein Beispiel, das zeigt, wie du das mit einem Dekorator für die
Funktionen erreichen kannst, bei denen sich die Protokollierung so
verhalten soll. Es nutzt "logging.handlers.MemoryHandler", der
protokollierte Ereignisse puffert, bis eine Bedingung eintritt. Dann
werden die gepufferten Ereignisse "flushed", also geleert und zur
Verarbeitung an einen anderen Handler (den "target"-Handler)
übergeben. Standardmäßig leert der "MemoryHandler" seinen Puffer, wenn
dieser voll ist oder ein Ereignis auftritt, dessen Schweregrad größer
oder gleich einer angegebenen Schwelle ist. Willst du ein eigenes
Leerungsverhalten, kannst du dieses Rezept mit einer spezialisierteren
Unterklasse von "MemoryHandler" verwenden.

Das Beispielskript hat eine einfache Funktion "foo", die einfach alle
Protokollierungsstufen durchläuft, auf "sys.stderr" schreibt, auf
welcher Stufe sie als Nächstes protokolliert, und dann tatsächlich
eine Meldung auf dieser Stufe protokolliert. Du kannst "foo" einen
Parameter übergeben, der, wenn er wahr ist, auch auf den Stufen ERROR
und CRITICAL protokolliert – andernfalls protokolliert sie nur auf den
Stufen DEBUG, INFO und WARNING.

Das Skript sorgt einfach dafür, dass "foo" mit einem Dekorator
versehen wird, der die gewünschte bedingte Protokollierung übernimmt.
Der Dekorator nimmt einen Logger als Parameter und hängt für die Dauer
des Aufrufs der dekorierten Funktion einen Memory-Handler an. Der
Dekorator lässt sich zusätzlich über einen Ziel-Handler, eine Stufe,
bei der geleert werden soll, und eine Kapazität für den Puffer (die
Anzahl gepufferter Datensätze) parametrisieren. Die Vorgaben dafür
sind ein "StreamHandler", der auf "sys.stderr" schreibt,
"logging.ERROR" und "100".

Hier das Skript:

   import logging
   from logging.handlers import MemoryHandler
   import sys

   logger = logging.getLogger(__name__)
   logger.addHandler(logging.NullHandler())

   def log_if_errors(logger, target_handler=None, flush_level=None, capacity=None):
       if target_handler is None:
           target_handler = logging.StreamHandler()
       if flush_level is None:
           flush_level = logging.ERROR
       if capacity is None:
           capacity = 100
       handler = MemoryHandler(capacity, flushLevel=flush_level, target=target_handler)

       def decorator(fn):
           def wrapper(*args, **kwargs):
               logger.addHandler(handler)
               try:
                   return fn(*args, **kwargs)
               except Exception:
                   logger.exception('call failed')
                   raise
               finally:
                   super(MemoryHandler, handler).flush()
                   logger.removeHandler(handler)
           return wrapper

       return decorator

   def write_line(s):
       sys.stderr.write('%s\n' % s)

   def foo(fail=False):
       write_line('about to log at DEBUG ...')
       logger.debug('Actually logged at DEBUG')
       write_line('about to log at INFO ...')
       logger.info('Actually logged at INFO')
       write_line('about to log at WARNING ...')
       logger.warning('Actually logged at WARNING')
       if fail:
           write_line('about to log at ERROR ...')
           logger.error('Actually logged at ERROR')
           write_line('about to log at CRITICAL ...')
           logger.critical('Actually logged at CRITICAL')
       return fail

   decorated_foo = log_if_errors(logger)(foo)

   if __name__ == '__main__':
       logger.setLevel(logging.DEBUG)
       write_line('Calling undecorated foo with False')
       assert not foo(False)
       write_line('Calling undecorated foo with True')
       assert foo(True)
       write_line('Calling decorated foo with False')
       assert not decorated_foo(False)
       write_line('Calling decorated foo with True')
       assert decorated_foo(True)

Beim Ausführen dieses Skripts sollte folgende Ausgabe zu sehen sein:

   Calling undecorated foo with False
   about to log at DEBUG ...
   about to log at INFO ...
   about to log at WARNING ...
   Calling undecorated foo with True
   about to log at DEBUG ...
   about to log at INFO ...
   about to log at WARNING ...
   about to log at ERROR ...
   about to log at CRITICAL ...
   Calling decorated foo with False
   about to log at DEBUG ...
   about to log at INFO ...
   about to log at WARNING ...
   Calling decorated foo with True
   about to log at DEBUG ...
   about to log at INFO ...
   about to log at WARNING ...
   about to log at ERROR ...
   Actually logged at DEBUG
   Actually logged at INFO
   Actually logged at WARNING
   Actually logged at ERROR
   about to log at CRITICAL ...
   Actually logged at CRITICAL

Wie du siehst, entsteht tatsächliche Protokollausgabe nur dann, wenn
ein Ereignis mit Schweregrad ERROR oder höher protokolliert wird – in
diesem Fall werden dann aber auch alle vorherigen Ereignisse mit
niedrigerem Schweregrad protokolliert.

Natürlich kannst du auch die herkömmliche Art der Dekoration
verwenden:

   @log_if_errors(logger)
   def foo(fail=False):
       ...


Protokollmeldungen gepuffert per E-Mail senden
==============================================

Um zu zeigen, wie du Protokollmeldungen per E-Mail senden kannst,
sodass eine festgelegte Anzahl von Meldungen je E-Mail verschickt
wird, kannst du eine Unterklasse von "BufferingHandler" bilden. Im
folgenden  Beispiel, das du an deine eigenen Bedürfnisse anpassen
kannst, ist ein einfaches Testgerüst enthalten, mit dem du das Skript
mit Befehlszeilenargumenten starten kannst, die angeben, was du
üblicherweise zum Versenden über SMTP brauchst. (Starte das
heruntergeladene Skript mit dem Argument "-h", um die erforderlichen
und die optionalen Argumente zu sehen.)

   import logging
   import logging.handlers
   import smtplib

   class BufferingSMTPHandler(logging.handlers.BufferingHandler):
       def __init__(self, mailhost, port, username, password, fromaddr, toaddrs,
                    subject, capacity):
           logging.handlers.BufferingHandler.__init__(self, capacity)
           self.mailhost = mailhost
           self.mailport = port
           self.username = username
           self.password = password
           self.fromaddr = fromaddr
           if isinstance(toaddrs, str):
               toaddrs = [toaddrs]
           self.toaddrs = toaddrs
           self.subject = subject
           self.setFormatter(logging.Formatter("%(asctime)s %(levelname)-5s %(message)s"))

       def flush(self):
           if len(self.buffer) > 0:
               try:
                   smtp = smtplib.SMTP(self.mailhost, self.mailport)
                   smtp.starttls()
                   smtp.login(self.username, self.password)
                   msg = "From: %s\r\nTo: %s\r\nSubject: %s\r\n\r\n" % (self.fromaddr, ','.join(self.toaddrs), self.subject)
                   for record in self.buffer:
                       s = self.format(record)
                       msg = msg + s + "\r\n"
                   smtp.sendmail(self.fromaddr, self.toaddrs, msg)
                   smtp.quit()
               except Exception:
                   if logging.raiseExceptions:
                       raise
               self.buffer = []

   if __name__ == '__main__':
       import argparse

       ap = argparse.ArgumentParser()
       aa = ap.add_argument
       aa('host', metavar='HOST', help='SMTP server')
       aa('--port', '-p', type=int, default=587, help='SMTP port')
       aa('user', metavar='USER', help='SMTP username')
       aa('password', metavar='PASSWORD', help='SMTP password')
       aa('to', metavar='TO', help='Addressee for emails')
       aa('sender', metavar='SENDER', help='Sender email address')
       aa('--subject', '-s',
          default='Test Logging email from Python logging module (buffering)',
          help='Subject of email')
       options = ap.parse_args()
       logger = logging.getLogger()
       logger.setLevel(logging.DEBUG)
       h = BufferingSMTPHandler(options.host, options.port, options.user,
                                options.password, options.sender,
                                options.to, options.subject, 10)
       logger.addHandler(h)
       for i in range(102):
           logger.info("Info index = %d", i)
       h.flush()
       h.close()

Führst du dieses Skript aus und ist dein SMTP-Server richtig
eingerichtet, solltest du feststellen, dass elf E-Mails an die von dir
angegebene Adresse gehen. Die ersten zehn E-Mails enthalten jeweils
zehn Protokollmeldungen, die elfte zwei. Das ergibt die 102 Meldungen,
die im Skript angegeben sind.


Zeiten über die Konfiguration in UTC (GMT) formatieren
======================================================

Manchmal willst du Zeiten in UTC formatieren. Das lässt sich mit einer
Klasse wie "UTCFormatter" erreichen, die unten gezeigt wird:

   import logging
   import time

   class UTCFormatter(logging.Formatter):
       converter = time.gmtime

und du kannst dann in deinem Code den "UTCFormatter" statt "Formatter"
verwenden. Willst du das über die Konfiguration erreichen, kannst du
die API "dictConfig()" mit einem Ansatz verwenden, den das folgende
vollständige Beispiel zeigt:

   import logging
   import logging.config
   import time

   class UTCFormatter(logging.Formatter):
       converter = time.gmtime

   LOGGING = {
       'version': 1,
       'disable_existing_loggers': False,
       'formatters': {
           'utc': {
               '()': UTCFormatter,
               'format': '%(asctime)s %(message)s',
           },
           'local': {
               'format': '%(asctime)s %(message)s',
           }
       },
       'handlers': {
           'console1': {
               'class': 'logging.StreamHandler',
               'formatter': 'utc',
           },
           'console2': {
               'class': 'logging.StreamHandler',
               'formatter': 'local',
           },
       },
       'root': {
           'handlers': ['console1', 'console2'],
      }
   }

   if __name__ == '__main__':
       logging.config.dictConfig(LOGGING)
       logging.warning('The local time is %s', time.asctime())

Beim Ausführen dieses Skripts sollte etwa Folgendes ausgegeben werden:

   2015-10-17 12:53:29,501 The local time is Sat Oct 17 13:53:29 2015
   2015-10-17 13:53:29,501 The local time is Sat Oct 17 13:53:29 2015

was zeigt, wie die Zeit sowohl als Ortszeit als auch in UTC formatiert
wird, je einmal pro Handler.


Einen Kontextmanager für gezielte Protokollierung verwenden
===========================================================

Manchmal wäre es nützlich, die Protokollierungskonfiguration zeitweise
zu ändern und sie nach einer Aktion wieder zurückzusetzen. Dafür ist
ein Kontextmanager der naheliegendste Weg, den Protokollierungskontext
zu sichern und wiederherzustellen. Hier ein einfaches Beispiel für
einen solchen Kontextmanager, mit dem du wahlweise den Schweregrad
ändern und einen Protokollierungs-Handler hinzufügen kannst, und zwar
nur im Geltungsbereich des Kontextmanagers:

   import logging
   import sys

   class LoggingContext:
       def __init__(self, logger, level=None, handler=None, close=True):
           self.logger = logger
           self.level = level
           self.handler = handler
           self.close = close

       def __enter__(self):
           if self.level is not None:
               self.old_level = self.logger.level
               self.logger.setLevel(self.level)
           if self.handler:
               self.logger.addHandler(self.handler)

       def __exit__(self, et, ev, tb):
           if self.level is not None:
               self.logger.setLevel(self.old_level)
           if self.handler:
               self.logger.removeHandler(self.handler)
           if self.handler and self.close:
               self.handler.close()
           # implicit return of None => don't swallow exceptions

Gibst du einen Wert für den Schweregrad an, wird der Schweregrad des
Loggers im Geltungsbereich des with-Blocks, den der Kontextmanager
umfasst, auf diesen Wert gesetzt. Gibst du einen Handler an, wird er
beim Betreten des Blocks dem Logger hinzugefügt und beim Verlassen
entfernt. Du kannst den Manager außerdem bitten, den Handler beim
Verlassen des Blocks für dich zu schließen – das kannst du tun, wenn
du den Handler nicht mehr brauchst.

Um zu zeigen, wie das arbeitet, können wir den folgenden Codeblock an
das Obige anhängen:

   if __name__ == '__main__':
       logger = logging.getLogger('foo')
       logger.addHandler(logging.StreamHandler())
       logger.setLevel(logging.INFO)
       logger.info('1. This should appear just once on stderr.')
       logger.debug('2. This should not appear.')
       with LoggingContext(logger, level=logging.DEBUG):
           logger.debug('3. This should appear once on stderr.')
       logger.debug('4. This should not appear.')
       h = logging.StreamHandler(sys.stdout)
       with LoggingContext(logger, level=logging.DEBUG, handler=h, close=True):
           logger.debug('5. This should appear twice - once on stderr and once on stdout.')
       logger.info('6. This should appear just once on stderr.')
       logger.debug('7. This should not appear.')

Zunächst setzen wir den Schweregrad des Loggers auf "INFO", Meldung #1
erscheint also und Meldung #2 nicht. Dann ändern wir den Grad im
folgenden "with"-Block zeitweise auf "DEBUG", deshalb erscheint
Meldung #3. Nach dem Verlassen des Blocks ist der Schweregrad des
Loggers wieder "INFO", deshalb erscheint Meldung #4 nicht. Im nächsten
"with"-Block setzen wir den Grad erneut auf "DEBUG" und fügen
zusätzlich einen Handler hinzu, der auf "sys.stdout" schreibt. Dadurch
erscheint Meldung #5 zweimal auf der Konsole (einmal über "stderr" und
einmal über "stdout"). Nach dem Abschluss der "with"-Anweisung ist der
Zustand wie vorher, deshalb erscheint Meldung #6 (wie Meldung #1),
Meldung #7 aber nicht (genau wie Meldung #2).

Führen wir das entstandene Skript aus, ergibt sich Folgendes:

   $ python logctx.py
   1. This should appear just once on stderr.
   3. This should appear once on stderr.
   5. This should appear twice - once on stderr and once on stdout.
   5. This should appear twice - once on stderr and once on stdout.
   6. This should appear just once on stderr.

Führen wir es erneut aus, leiten aber "stderr" nach "/dev/null", sehen
wir Folgendes – die einzige Meldung, die auf "stdout" geschrieben
wird:

   $ python logctx.py 2>/dev/null
   5. This should appear twice - once on stderr and once on stdout.

Und noch einmal, diesmal mit "stdout" nach "/dev/null" geleitet,
erhalten wir:

   $ python logctx.py >/dev/null
   1. This should appear just once on stderr.
   3. This should appear once on stderr.
   5. This should appear twice - once on stderr and once on stdout.
   6. This should appear just once on stderr.

In diesem Fall erscheint die Meldung #5, die auf "stdout" ausgegeben
wird, wie erwartet nicht.

Natürlich lässt sich der hier beschriebene Ansatz verallgemeinern,
etwa um zeitweise Protokollierungsfilter anzuhängen. Beachte, dass der
obige Code sowohl in Python 2 als auch in Python 3 funktioniert.


Eine Vorlage für den Start einer CLI-Anwendung
==============================================

Hier ein Beispiel, das zeigt, wie du

* einen Schweregrad anhand von Befehlszeilenargumenten verwendest

* an mehrere Unterbefehle in getrennten Dateien verteilst, die alle
  auf demselben Grad und auf einheitliche Weise protokollieren

* eine einfache, knappe Konfiguration nutzt

Nehmen wir an, wir haben eine Befehlszeilenanwendung, deren Aufgabe es
ist, bestimmte Dienste zu stoppen, zu starten oder neu zu starten. Zur
Veranschaulichung ließe sich das als Datei "app.py" gestalten, die das
Hauptskript der Anwendung ist, während die einzelnen Befehle in
"start.py", "stop.py" und "restart.py" umgesetzt sind. Nehmen wir
weiter an, wir wollen die Gesprächigkeit der Anwendung über ein
Befehlszeilenargument steuern, mit "logging.INFO" als Vorgabe. So
ließe sich "app.py" schreiben:

   import argparse
   import importlib
   import logging
   import os
   import sys

   def main(args=None):
       scriptname = os.path.basename(__file__)
       parser = argparse.ArgumentParser(scriptname)
       levels = ('DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL')
       parser.add_argument('--log-level', default='INFO', choices=levels)
       subparsers = parser.add_subparsers(dest='command',
                                          help='Available commands:')
       start_cmd = subparsers.add_parser('start', help='Start a service')
       start_cmd.add_argument('name', metavar='NAME',
                              help='Name of service to start')
       stop_cmd = subparsers.add_parser('stop',
                                        help='Stop one or more services')
       stop_cmd.add_argument('names', metavar='NAME', nargs='+',
                             help='Name of service to stop')
       restart_cmd = subparsers.add_parser('restart',
                                           help='Restart one or more services')
       restart_cmd.add_argument('names', metavar='NAME', nargs='+',
                                help='Name of service to restart')
       options = parser.parse_args()
       # the code to dispatch commands could all be in this file. For the purposes
       # of illustration only, we implement each command in a separate module.
       try:
           mod = importlib.import_module(options.command)
           cmd = getattr(mod, 'command')
       except (ImportError, AttributeError):
           print('Unable to find the code for command \'%s\'' % options.command)
           return 1
       # Could get fancy here and load configuration from file or dictionary
       logging.basicConfig(level=options.log_level,
                           format='%(levelname)s %(name)s %(message)s')
       cmd(options)

   if __name__ == '__main__':
       sys.exit(main())

Und die Befehle "start", "stop" und "restart" lassen sich in
getrennten Modulen umsetzen, zum Starten etwa so:

   # start.py
   import logging

   logger = logging.getLogger(__name__)

   def command(options):
       logger.debug('About to start %s', options.name)
       # actually do the command processing here ...
       logger.info('Started the \'%s\' service.', options.name)

und damit zum Stoppen so:

   # stop.py
   import logging

   logger = logging.getLogger(__name__)

   def command(options):
       n = len(options.names)
       if n == 1:
           plural = ''
           services = '\'%s\'' % options.names[0]
       else:
           plural = 's'
           services = ', '.join('\'%s\'' % name for name in options.names)
           i = services.rfind(', ')
           services = services[:i] + ' and ' + services[i + 2:]
       logger.debug('About to stop %s', services)
       # actually do the command processing here ...
       logger.info('Stopped the %s service%s.', services, plural)

und entsprechend zum Neustarten:

   # restart.py
   import logging

   logger = logging.getLogger(__name__)

   def command(options):
       n = len(options.names)
       if n == 1:
           plural = ''
           services = '\'%s\'' % options.names[0]
       else:
           plural = 's'
           services = ', '.join('\'%s\'' % name for name in options.names)
           i = services.rfind(', ')
           services = services[:i] + ' and ' + services[i + 2:]
       logger.debug('About to restart %s', services)
       # actually do the command processing here ...
       logger.info('Restarted the %s service%s.', services, plural)

Führen wir diese Anwendung mit dem Standard-Schweregrad aus, erhalten
wir eine Ausgabe wie diese:

   $ python app.py start foo
   INFO start Started the 'foo' service.

   $ python app.py stop foo bar
   INFO stop Stopped the 'foo' and 'bar' services.

   $ python app.py restart foo bar baz
   INFO restart Restarted the 'foo', 'bar' and 'baz' services.

Das erste Wort ist der Schweregrad, das zweite der Modul- oder
Paketname der Stelle, an der das Ereignis protokolliert wurde.

Ändern wir den Schweregrad, ändern wir damit die Informationen, die
ins Protokoll gehen. Wollen wir zum Beispiel mehr Informationen:

   $ python app.py --log-level DEBUG start foo
   DEBUG start About to start foo
   INFO start Started the 'foo' service.

   $ python app.py --log-level DEBUG stop foo bar
   DEBUG stop About to stop 'foo' and 'bar'
   INFO stop Stopped the 'foo' and 'bar' services.

   $ python app.py --log-level DEBUG restart foo bar baz
   DEBUG restart About to restart 'foo', 'bar' and 'baz'
   INFO restart Restarted the 'foo', 'bar' and 'baz' services.

Und wollen wir weniger:

   $ python app.py --log-level WARNING start foo
   $ python app.py --log-level WARNING stop foo bar
   $ python app.py --log-level WARNING restart foo bar baz

In diesem Fall geben die Befehle nichts auf der Konsole aus, weil sie
nichts auf dem Grad "WARNING" oder darüber protokollieren.


Eine Qt-GUI für die Protokollierung
===================================

Eine Frage, die immer wieder auftaucht, ist die, wie man in eine GUI-
Anwendung protokolliert. Das Framework Qt ist ein verbreitetes
plattformübergreifendes UI-Framework mit Python-Anbindungen über die
Bibliotheken PySide2 oder PyQt5.

Das folgende Beispiel zeigt, wie man in eine Qt-GUI protokolliert. Es
führt eine einfache Klasse "QtHandler" ein, die ein aufrufbares Objekt
nimmt. Dieses sollte ein Slot im Haupt-Thread sein, der die GUI
aktualisiert. Außerdem wird ein Arbeiter-Thread erzeugt, um zu zeigen,
wie du sowohl aus der Benutzeroberfläche selbst (über eine
Schaltfläche für manuelle Protokollierung) als auch aus einem
Arbeiter-Thread, der im Hintergrund arbeitet (hier protokolliert er
einfach Meldungen auf zufälligen Graden mit zufälligen kurzen Pausen
dazwischen), in die GUI protokollieren kannst.

Der Arbeiter-Thread ist mit Qts Klasse "QThread" umgesetzt und nicht
mit dem Modul "threading", denn es gibt Umstände, in denen man
"QThread" verwenden muss, das sich besser in andere "Qt"-Bestandteile
einfügt.

Der Code sollte mit neueren Ausgaben von "PySide6", "PyQt6", "PySide2"
oder "PyQt5" funktionieren. Den Ansatz solltest du auf frühere Qt-
Versionen übertragen können. Ausführlichere Hinweise findest du in den
Kommentaren im Codeausschnitt.

   import logging
   import random
   import sys
   import time

   # Deal with minor differences between different Qt packages
   try:
       from PySide6 import QtCore, QtGui, QtWidgets
       Signal = QtCore.Signal
       Slot = QtCore.Slot
   except ImportError:
       try:
           from PyQt6 import QtCore, QtGui, QtWidgets
           Signal = QtCore.pyqtSignal
           Slot = QtCore.pyqtSlot
       except ImportError:
           try:
               from PySide2 import QtCore, QtGui, QtWidgets
               Signal = QtCore.Signal
               Slot = QtCore.Slot
           except ImportError:
               from PyQt5 import QtCore, QtGui, QtWidgets
               Signal = QtCore.pyqtSignal
               Slot = QtCore.pyqtSlot

   logger = logging.getLogger(__name__)


   #
   # Signals need to be contained in a QObject or subclass in order to be correctly
   # initialized.
   #
   class Signaller(QtCore.QObject):
       signal = Signal(str, logging.LogRecord)

   #
   # Output to a Qt GUI is only supposed to happen on the main thread. So, this
   # handler is designed to take a slot function which is set up to run in the main
   # thread. In this example, the function takes a string argument which is a
   # formatted log message, and the log record which generated it. The formatted
   # string is just a convenience - you could format a string for output any way
   # you like in the slot function itself.
   #
   # You specify the slot function to do whatever GUI updates you want. The handler
   # doesn't know or care about specific UI elements.
   #
   class QtHandler(logging.Handler):
       def __init__(self, slotfunc, *args, **kwargs):
           super().__init__(*args, **kwargs)
           self.signaller = Signaller()
           self.signaller.signal.connect(slotfunc)

       def emit(self, record):
           s = self.format(record)
           self.signaller.signal.emit(s, record)

   #
   # This example uses QThreads, which means that the threads at the Python level
   # are named something like "Dummy-1". The function below gets the Qt name of the
   # current thread.
   #
   def ctname():
       return QtCore.QThread.currentThread().objectName()


   #
   # Used to generate random levels for logging.
   #
   LEVELS = (logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR,
             logging.CRITICAL)

   #
   # This worker class represents work that is done in a thread separate to the
   # main thread. The way the thread is kicked off to do work is via a button press
   # that connects to a slot in the worker.
   #
   # Because the default threadName value in the LogRecord isn't much use, we add
   # a qThreadName which contains the QThread name as computed above, and pass that
   # value in an "extra" dictionary which is used to update the LogRecord with the
   # QThread name.
   #
   # This example worker just outputs messages sequentially, interspersed with
   # random delays of the order of a few seconds.
   #
   class Worker(QtCore.QObject):
       @Slot()
       def start(self):
           extra = {'qThreadName': ctname() }
           logger.debug('Started work', extra=extra)
           i = 1
           # Let the thread run until interrupted. This allows reasonably clean
           # thread termination.
           while not QtCore.QThread.currentThread().isInterruptionRequested():
               delay = 0.5 + random.random() * 2
               time.sleep(delay)
               try:
                   if random.random() < 0.1:
                       raise ValueError('Exception raised: %d' % i)
                   else:
                       level = random.choice(LEVELS)
                       logger.log(level, 'Message after delay of %3.1f: %d', delay, i, extra=extra)
               except ValueError as e:
                   logger.exception('Failed: %s', e, extra=extra)
               i += 1

   #
   # Implement a simple UI for this cookbook example. This contains:
   #
   # * A read-only text edit window which holds formatted log messages
   # * A button to start work and log stuff in a separate thread
   # * A button to log something from the main thread
   # * A button to clear the log window
   #
   class Window(QtWidgets.QWidget):

       COLORS = {
           logging.DEBUG: 'black',
           logging.INFO: 'blue',
           logging.WARNING: 'orange',
           logging.ERROR: 'red',
           logging.CRITICAL: 'purple',
       }

       def __init__(self, app):
           super().__init__()
           self.app = app
           self.textedit = te = QtWidgets.QPlainTextEdit(self)
           # Set whatever the default monospace font is for the platform
           f = QtGui.QFont('nosuchfont')
           if hasattr(f, 'Monospace'):
               f.setStyleHint(f.Monospace)
           else:
               f.setStyleHint(f.StyleHint.Monospace)  # for Qt6
           te.setFont(f)
           te.setReadOnly(True)
           PB = QtWidgets.QPushButton
           self.work_button = PB('Start background work', self)
           self.log_button = PB('Log a message at a random level', self)
           self.clear_button = PB('Clear log window', self)
           self.handler = h = QtHandler(self.update_status)
           # Remember to use qThreadName rather than threadName in the format string.
           fs = '%(asctime)s %(qThreadName)-12s %(levelname)-8s %(message)s'
           formatter = logging.Formatter(fs)
           h.setFormatter(formatter)
           logger.addHandler(h)
           # Set up to terminate the QThread when we exit
           app.aboutToQuit.connect(self.force_quit)

           # Lay out all the widgets
           layout = QtWidgets.QVBoxLayout(self)
           layout.addWidget(te)
           layout.addWidget(self.work_button)
           layout.addWidget(self.log_button)
           layout.addWidget(self.clear_button)
           self.setFixedSize(900, 400)

           # Connect the non-worker slots and signals
           self.log_button.clicked.connect(self.manual_update)
           self.clear_button.clicked.connect(self.clear_display)

           # Start a new worker thread and connect the slots for the worker
           self.start_thread()
           self.work_button.clicked.connect(self.worker.start)
           # Once started, the button should be disabled
           self.work_button.clicked.connect(lambda : self.work_button.setEnabled(False))

       def start_thread(self):
           self.worker = Worker()
           self.worker_thread = QtCore.QThread()
           self.worker.setObjectName('Worker')
           self.worker_thread.setObjectName('WorkerThread')  # for qThreadName
           self.worker.moveToThread(self.worker_thread)
           # This will start an event loop in the worker thread
           self.worker_thread.start()

       def kill_thread(self):
           # Just tell the worker to stop, then tell it to quit and wait for that
           # to happen
           self.worker_thread.requestInterruption()
           if self.worker_thread.isRunning():
               self.worker_thread.quit()
               self.worker_thread.wait()
           else:
               print('worker has already exited.')

       def force_quit(self):
           # For use when the window is closed
           if self.worker_thread.isRunning():
               self.kill_thread()

       # The functions below update the UI and run in the main thread because
       # that's where the slots are set up

       @Slot(str, logging.LogRecord)
       def update_status(self, status, record):
           color = self.COLORS.get(record.levelno, 'black')
           s = '<pre><font color="%s">%s</font></pre>' % (color, status)
           self.textedit.appendHtml(s)

       @Slot()
       def manual_update(self):
           # This function uses the formatted message passed in, but also uses
           # information from the record to format the message in an appropriate
           # color according to its severity (level).
           level = random.choice(LEVELS)
           extra = {'qThreadName': ctname() }
           logger.log(level, 'Manually logged!', extra=extra)

       @Slot()
       def clear_display(self):
           self.textedit.clear()


   def main():
       QtCore.QThread.currentThread().setObjectName('MainThread')
       logging.getLogger().setLevel(logging.DEBUG)
       app = QtWidgets.QApplication(sys.argv)
       example = Window(app)
       example.show()
       if hasattr(app, 'exec'):
           rc = app.exec()
       else:
           rc = app.exec_()
       sys.exit(rc)

   if __name__=='__main__':
       main()


Mit Unterstützung für RFC5424 in syslog protokollieren
======================================================

**RFC 5424** stammt zwar aus dem Jahr 2009, die meisten syslog-Server
sind aber standardmäßig auf das ältere **RFC 3164** von 2001
eingestellt. Als "logging" 2003 zu Python kam, unterstützte es das
damals frühere (und einzige vorhandene) Protokoll. Weil RFC 5424 seit
seinem Erscheinen in syslog-Servern nicht auf breiter Front eingesetzt
wird, wurde die Funktionalität von "SysLogHandler" nicht aktualisiert.

RFC 5424 enthält einige nützliche Eigenschaften, etwa die
Unterstützung strukturierter Daten. Musst du an einen syslog-Server
protokollieren, der das unterstützt, dann geht das mit einem
abgeleiteten Handler, der etwa so aussieht:

   import datetime as dt
   import logging.handlers
   import re
   import socket
   import time

   class SysLogHandler5424(logging.handlers.SysLogHandler):

       tz_offset = re.compile(r'([+-]\d{2})(\d{2})$')
       escaped = re.compile(r'([\]"\\])')

       def __init__(self, *args, **kwargs):
           self.msgid = kwargs.pop('msgid', None)
           self.appname = kwargs.pop('appname', None)
           super().__init__(*args, **kwargs)

       def format(self, record):
           version = 1
           asctime = dt.datetime.fromtimestamp(record.created).isoformat()
           m = self.tz_offset.prefixmatch(time.strftime('%z'))
           has_offset = False
           if m and time.timezone:
               hrs, mins = m.groups()
               if int(hrs) or int(mins):
                   has_offset = True
           if not has_offset:
               asctime += 'Z'
           else:
               asctime += f'{hrs}:{mins}'
           try:
               hostname = socket.gethostname()
           except Exception:
               hostname = '-'
           appname = self.appname or '-'
           procid = record.process
           msgid = '-'
           msg = super().format(record)
           sdata = '-'
           if hasattr(record, 'structured_data'):
               sd = record.structured_data
               # This should be a dict where the keys are SD-ID and the value is a
               # dict mapping PARAM-NAME to PARAM-VALUE (refer to the RFC for what these
               # mean)
               # There's no error checking here - it's purely for illustration, and you
               # can adapt this code for use in production environments
               parts = []

               def replacer(m):
                   g = m.groups()
                   return '\\' + g[0]

               for sdid, dv in sd.items():
                   part = f'[{sdid}'
                   for k, v in dv.items():
                       s = str(v)
                       s = self.escaped.sub(replacer, s)
                       part += f' {k}="{s}"'
                   part += ']'
                   parts.append(part)
               sdata = ''.join(parts)
           return f'{version} {asctime} {hostname} {appname} {procid} {msgid} {sdata} {msg}'

Um den obigen Code vollständig zu verstehen, musst du mit RFC 5424
vertraut sein, und möglicherweise hast du etwas andere Bedürfnisse
(etwa, wie du strukturierte Daten an das Protokoll übergibst). Dennoch
sollte sich das Obige auf deine Bedürfnisse anpassen lassen. Mit dem
obigen Handler übergibst du strukturierte Daten etwa so:

   sd = {
       'foo@12345': {'bar': 'baz', 'baz': 'bozz', 'fizz': r'buzz'},
       'foo@54321': {'rab': 'baz', 'zab': 'bozz', 'zzif': r'buzz'}
   }
   extra = {'structured_data': sd}
   i = 1
   logger.debug('Message %d', i, extra=extra)


Wie man einen Logger wie einen Ausgabestrom behandelt
=====================================================

Manchmal musst du eine API eines Dritten anbinden, die ein
dateiartiges Objekt zum Schreiben erwartet, willst die Ausgabe der API
aber in einen Logger lenken. Das geht mit einer Klasse, die einen
Logger in eine dateiartige API hüllt. Hier ein kurzes Skript, das eine
solche Klasse zeigt:

   import logging

   class LoggerWriter:
       def __init__(self, logger, level):
           self.logger = logger
           self.level = level

       def write(self, message):
           if message != '\n':  # avoid printing bare newlines, if you like
               self.logger.log(self.level, message)

       def flush(self):
           # doesn't actually do anything, but might be expected of a file-like
           # object - so optional depending on your situation
           pass

       def close(self):
           # doesn't actually do anything, but might be expected of a file-like
           # object - so optional depending on your situation. You might want
           # to set a flag so that later calls to write raise an exception
           pass

   def main():
       logging.basicConfig(level=logging.DEBUG)
       logger = logging.getLogger('demo')
       info_fp = LoggerWriter(logger, logging.INFO)
       debug_fp = LoggerWriter(logger, logging.DEBUG)
       print('An INFO message', file=info_fp)
       print('A DEBUG message', file=debug_fp)

   if __name__ == "__main__":
       main()

Beim Ausführen gibt dieses Skript aus

   INFO:demo:An INFO message
   DEBUG:demo:A DEBUG message

Du könntest "LoggerWriter" auch verwenden, um "sys.stdout" und
"sys.stderr" umzuleiten, etwa so:

   import sys

   sys.stdout = LoggerWriter(logger, logging.INFO)
   sys.stderr = LoggerWriter(logger, logging.WARNING)

Das solltest du tun, *nachdem* du die Protokollierung nach deinen
Bedürfnissen konfiguriert hast. Im obigen Beispiel tut das der Aufruf
von "basicConfig()" (er verwendet den Wert von "sys.stderr", *bevor*
er von einer "LoggerWriter"-Instanz überschrieben wird). Dann erhältst
du ein Ergebnis dieser Art:

   >>> print('Foo')
   INFO:demo:Foo
   >>> print('Bar', file=sys.stderr)
   WARNING:demo:Bar
   >>>

Die obigen Beispiele zeigen die Ausgabe natürlich in dem Format, das
"basicConfig()" verwendet, aber du kannst beim Konfigurieren der
Protokollierung einen anderen Formatter nehmen.

Beachte, dass du mit dem obigen Verfahren einigermaßen der Pufferung
und der Folge der Schreibaufrufe ausgeliefert bist, die du abfängst.
Hast du zum Beispiel mit der obigen Festlegung von "LoggerWriter" den
Ausschnitt

   sys.stderr = LoggerWriter(logger, logging.WARNING)
   1 / 0

dann ergibt das Ausführen des Skripts

   WARNING:demo:Traceback (most recent call last):

   WARNING:demo:  File "/home/runner/cookbook-loggerwriter/test.py", line 53, in <module>

   WARNING:demo:
   WARNING:demo:main()
   WARNING:demo:  File "/home/runner/cookbook-loggerwriter/test.py", line 49, in main

   WARNING:demo:
   WARNING:demo:1 / 0
   WARNING:demo:ZeroDivisionError
   WARNING:demo::
   WARNING:demo:division by zero

Wie du siehst, ist diese Ausgabe nicht ideal. Das liegt daran, dass
der zugrunde liegende Code, der auf "sys.stderr" schreibt, mehrere
Schreibvorgänge ausführt, von denen jeder zu einer eigenen
Protokollzeile führt (etwa die letzten drei Zeilen oben). Um dieses
Problem zu umgehen, musst du puffern und Protokollzeilen nur dann
ausgeben, wenn Zeilenumbrüche auftreten. Nehmen wir eine etwas bessere
Umsetzung von "LoggerWriter":

   class BufferingLoggerWriter(LoggerWriter):
       def __init__(self, logger, level):
           super().__init__(logger, level)
           self.buffer = ''

       def write(self, message):
           if '\n' not in message:
               self.buffer += message
           else:
               parts = message.split('\n')
               if self.buffer:
                   s = self.buffer + parts.pop(0)
                   self.logger.log(self.level, s)
               self.buffer = parts.pop()
               for part in parts:
                   self.logger.log(self.level, part)

Die puffert einfach, bis ein Zeilenumbruch auftritt, und protokolliert
dann vollständige Zeilen. Mit diesem Ansatz erhältst du eine bessere
Ausgabe:

   WARNING:demo:Traceback (most recent call last):
   WARNING:demo:  File "/home/runner/cookbook-loggerwriter/main.py", line 55, in <module>
   WARNING:demo:    main()
   WARNING:demo:  File "/home/runner/cookbook-loggerwriter/main.py", line 52, in main
   WARNING:demo:    1/0
   WARNING:demo:ZeroDivisionError: division by zero


Wie man Zeilenumbrüche in der Protokollausgabe einheitlich behandelt
====================================================================

Üblicherweise bestehen protokollierte Meldungen (etwa auf der Konsole
oder in einer Datei) aus einer einzigen Textzeile. Manchmal müssen
aber Meldungen mit mehreren Zeilen behandelt werden – sei es, weil
eine Formatzeichenkette der Protokollierung Zeilenumbrüche enthält,
oder weil die protokollierten Daten Zeilenumbrüche enthalten. Willst
du solche Meldungen einheitlich behandeln, sodass jede Zeile der
protokollierten Meldung so einheitlich formatiert erscheint, als wäre
sie einzeln protokolliert worden, dann geht das mit einem Handler-
Mixin, wie im folgenden Ausschnitt:

   # Assume this is in a module mymixins.py
   import copy

   class MultilineMixin:
       def emit(self, record):
           s = record.getMessage()
           if '\n' not in s:
               super().emit(record)
           else:
               lines = s.splitlines()
               rec = copy.copy(record)
               rec.args = None
               for line in lines:
                   rec.msg = line
                   super().emit(rec)

Das Mixin kannst du so verwenden wie im folgenden Skript:

   import logging

   from mymixins import MultilineMixin

   logger = logging.getLogger(__name__)

   class StreamHandler(MultilineMixin, logging.StreamHandler):
       pass

   if __name__ == '__main__':
       logging.basicConfig(level=logging.DEBUG, format='%(asctime)s %(levelname)-9s %(message)s',
                           handlers = [StreamHandler()])
       logger.debug('Single line')
       logger.debug('Multiple lines:\nfool me once ...')
       logger.debug('Another single line')
       logger.debug('Multiple lines:\n%s', 'fool me ...\ncan\'t get fooled again')

Beim Ausführen gibt das Skript etwa Folgendes aus:

   2025-07-02 13:54:47,234 DEBUG     Single line
   2025-07-02 13:54:47,234 DEBUG     Multiple lines:
   2025-07-02 13:54:47,234 DEBUG     fool me once ...
   2025-07-02 13:54:47,234 DEBUG     Another single line
   2025-07-02 13:54:47,234 DEBUG     Multiple lines:
   2025-07-02 13:54:47,234 DEBUG     fool me ...
   2025-07-02 13:54:47,234 DEBUG     can't get fooled again

Machst du dir dagegen Sorgen wegen Log Injection, dann kannst du einen
Formatter verwenden, der Zeilenumbrüche maskiert, wie im folgenden
Beispiel:

   import logging

   logger = logging.getLogger(__name__)

   class EscapingFormatter(logging.Formatter):
       def format(self, record):
           s = super().format(record)
           return s.replace('\n', r'\n')

   if __name__ == '__main__':
       h = logging.StreamHandler()
       h.setFormatter(EscapingFormatter('%(asctime)s %(levelname)-9s %(message)s'))
       logging.basicConfig(level=logging.DEBUG, handlers = [h])
       logger.debug('Single line')
       logger.debug('Multiple lines:\nfool me once ...')
       logger.debug('Another single line')
       logger.debug('Multiple lines:\n%s', 'fool me ...\ncan\'t get fooled again')

Du kannst natürlich jedes Maskierungsverfahren verwenden, das für dich
am sinnvollsten ist. Beim Ausführen sollte das Skript eine Ausgabe wie
diese erzeugen:

   2025-07-09 06:47:33,783 DEBUG     Single line
   2025-07-09 06:47:33,783 DEBUG     Multiple lines:\nfool me once ...
   2025-07-09 06:47:33,783 DEBUG     Another single line
   2025-07-09 06:47:33,783 DEBUG     Multiple lines:\nfool me ...\ncan't get fooled again

Dieses Maskierungsverhalten kann nicht die Vorgabe der
Standardbibliothek sein, weil es die Verträglichkeit mit früheren
Versionen brechen würde.


Muster, die man vermeiden sollte
================================

Die vorangehenden Abschnitte haben Wege beschrieben, Dinge zu tun, die
du möglicherweise tun oder bewältigen musst. Es lohnt sich aber,
einige Nutzungsmuster zu erwähnen, die *nicht hilfreich* sind und die
man daher in den meisten Fällen vermeiden sollte. Die folgenden
Abschnitte stehen in keiner bestimmten Reihenfolge.


Dieselbe Protokolldatei mehrmals öffnen
---------------------------------------

Unter Windows kannst du dieselbe Datei in der Regel nicht mehrmals
öffnen, weil das zu einem Fehler „Datei wird von einem anderen Prozess
verwendet“ führt. Auf POSIX-Plattformen erhältst du dagegen keine
Fehler, wenn du dieselbe Datei mehrmals öffnest. Das kann
versehentlich geschehen, zum Beispiel durch:

* mehrfaches Hinzufügen eines Datei-Handlers, der dieselbe Datei
  anspricht (etwa durch Kopieren, Einfügen und Vergessen, etwas zu
  ändern).

* Öffnen von zwei Dateien, die wegen ihrer unterschiedlichen Namen
  verschieden aussehen, aber dieselbe sind, weil eine ein symbolischer
  Verweis auf die andere ist.

* Abspalten eines Prozesses, wonach Eltern- und Kindprozess einen
  Verweis auf dieselbe Datei haben. Das kann zum Beispiel durch die
  Verwendung des Moduls "multiprocessing" geschehen.

Eine Datei mehrmals zu öffnen *scheint* meist zu funktionieren, kann
in der Praxis aber zu einer Reihe von Problemen führen:

* Die Protokollausgabe kann durcheinandergeraten, weil mehrere Threads
  oder Prozesse in dieselbe Datei schreiben wollen. Die
  Protokollierung schützt zwar davor, dass mehrere Threads dieselbe
  Handler-Instanz gleichzeitig nutzen, aber es gibt keinen solchen
  Schutz, wenn zwei verschiedene Threads über zwei verschiedene
  Handler-Instanzen gleichzeitig schreiben, die zufällig auf dieselbe
  Datei zeigen.

* Ein Versuch, eine Datei zu löschen (etwa während der Dateirotation),
  schlägt stillschweigend fehl, weil ein weiterer Verweis auf sie
  zeigt. Das kann zu Verwirrung und verlorener Zeit bei der
  Fehlersuche führen – Protokolleinträge landen an unerwarteten
  Stellen oder gehen ganz verloren. Oder eine Datei, die verschoben
  werden sollte, bleibt liegen und wächst unerwartet, obwohl eine
  größenabhängige Rotation eingerichtet sein sollte.

Verwende die unter Aus mehreren Prozessen in eine einzige Datei
protokollieren beschriebenen Techniken, um solche Probleme zu umgehen.


Logger als Attribute einer Klasse verwenden oder sie als Parameter übergeben
----------------------------------------------------------------------------

Es mag ungewöhnliche Fälle geben, in denen du das brauchst, aber im
Allgemeinen hat es keinen Sinn, weil Logger Singletons sind. Code
kommt mit "logging.getLogger(name)" immer über den Namen an eine
bestimmte Logger-Instanz, Instanzen herumzugeben und als
Instanzattribute zu halten ist also zwecklos. Beachte, dass Logger in
anderen Sprachen wie Java und C# oft statische Klassenattribute sind.
In Python ergibt dieses Muster aber keinen Sinn, denn hier ist das
Modul (und nicht die Klasse) die Einheit, in die Software zerlegt
wird.


Andere Handler als "NullHandler" an einen Logger in einer Bibliothek hängen
---------------------------------------------------------------------------

Die Protokollierung durch Hinzufügen von Handlern, Formattern und
Filtern zu konfigurieren, ist Aufgabe des Anwendungsentwicklers, nicht
des Bibliotheksentwicklers. Betreust du eine Bibliothek, dann achte
darauf, an keinen deiner Logger einen anderen Handler als eine
"NullHandler"-Instanz zu hängen.


Viele Logger erzeugen
---------------------

Logger sind Singletons, die während der Ausführung eines Skripts nie
freigegeben werden. Viele Logger zu erzeugen verbraucht also Speicher,
der danach nicht freigegeben werden kann. Erzeuge nicht etwa einen
Logger je verarbeiteter Datei oder je aufgebauter Netzverbindung,
sondern verwende die vorhandenen Mechanismen, um Kontextinformationen
in deine Protokolle zu bringen, und beschränke die erzeugten Logger
auf solche, die Bereiche innerhalb deiner Anwendung beschreiben (im
Allgemeinen Module, gelegentlich etwas feiner).


Weitere Quellen
===============

Siehe auch:

  Modul "logging"
     API-Referenz für das Modul logging.

  Modul "logging.config"
     Konfigurations-API für das Modul logging.

  Modul "logging.handlers"
     Nützliche Handler, die mit dem Modul logging ausgeliefert werden.

  Grundlagen-Tutorial

  Fortgeschrittenes Tutorial
