Bisher haben wir immer nur das basic logging von Python benutzt. Mit logging.config steht uns aber ein sehr viel umfangreicheres und komfortablerer Weg zur Verfügung.
logging.config
logging.config ist ein Modul, dass Python mitliefert. Mit seiner Hilfe kannst du Filter und Handler sehr viel präziser konfigurieren als mit dem basic logging, welches dich auf Console- und Dateilogging beschränkt.
Zunächst wollen wir uns mal anschauen, was im Hintergrund passiert, wenn du einen Logmeldung absetzt.
Workflow
Nachdem logger.info() aufgerufen wurde, wird zuerst geprüft, ob der Loglevel auf INFO eingestellt ist, sonst wird gar nicht weitergemacht. Zunächst wird im weiteren Prozess ein LogRecord erstellt. Dieser enthält alle Informationen, die zu einem Logeintrag gehören (Zeitstempel, Text, Funktionsname usw.) Dieser wird dann an alle konfigurierten Handler weitergereicht, die ihrerseits zunächst den Loglevel überprüfen. Du kannst also für verschiedene Loglevel unterschiedliche Handler benutzen. Jeder Handler kann den LogRecord nach seinen Bedürfnissen filtern. Danach wird der LogRecord für die Verarbeitung formatiert und verarbeitet.
Nachdem alle Handler durchlaufen wurden, wird ggf. ein übergeordneter Handler aufgerufen. Dieser sogenannte root-Logger soll verhindern, dass Meldungen verloren gehen.
Praxisbeispiele
Zunächst wollen wir das bereits bekannte Beispiel aus Tutorial Teil 14 mit logging.config nachbauen:
# File: testlogging.py
import logging
from logging import config
# Logging Konfiguration definieren.
log_config = {
"version":1,
# root-Logger
"root":{
"handlers" : ["console",'file'],
"level": "DEBUG"
},
"handlers":{
#Handler für Console
"console":{
"formatter": "std_out",
"class": "logging.StreamHandler",
"level": "DEBUG"
},
# Handler für Logdatei
"file":{
"formatter":"std_out",
"class":"logging.FileHandler",
"level":"DEBUG",
"filename":"raspithek.log"
},
},
# Format einer Logzeile
"formatters":{
"std_out": {
"format": "%(asctime)s : %(levelname)s : %(module)s : %(funcName)s : %(lineno)d : (Process Details : (%(process)d, %(processName)s), Thread Details : (%(thread)d, %(threadName)s))\nLog : %(message)s",
"datefmt":"%d-%m-%Y %I:%M:%S"
}
},
}
# Config setzen
config.dictConfig(log_config)
# Logging testen
def testlogging():
print('testlogging() aufgerufen.')
logging.debug('DEBUG/Druckdaten werden gesendet.')
logging.info('INFO/Es werden 2 Seiten gedruckt')
logging.warning('WARN/nicht genügend Papier im Drucker')
logging.error('ERROR/Drucker nicht gefunden.')
logging.critical('CRITICAL/Drucker brennt')
if __name__ == '__main__':
testlogging()
Die Konfiguration des Logging geschieht am einfachsten mit einem Dictionary. In dicht_config werden alle Konfigurationsparameter zusammengefasst. Wir konfigurieren hier für den Root Logger die Handler für Console und File. Diese benutzen von Python gelieferte Klassen zur Verarbeitung des LogRecord. Beide Handler benutzen den selben Formatter std_out, um die Logzeile zu erzeugen.
Mit config.dictConfig(log_config) wird das Dictionary mit der Konfiguration an das Logging-System übergeben und gesetzt.
Was hier etwas unschön ist, ist, dass die Konfiguration im Pythoncode liegt, aber darum kümmern wir uns gleich. Jetzt testen wir das Programm erstmal mit python testlogging.py
Filter
Jetzt wollen wir einen eigenen Filter ins Logging konfigurieren, der nur die Zeilen loggt, die das Wort „Druck“ in beliebiger Groß-/Kleinschreibung enthält.
Aber zunächst lagern wir die Logging Config in eine separate Datei log_config.json aus. Das Dictionary von oben kannst einfach in diese Datei kopieren.
{
"version":1,
"filters": {
"drucker":{
"()": "__main__.DruckFilter",
"params": "noshow"
}
},
"formatters":{
"std_out":{
"format": "%(asctime)s : %(levelname)s : %(module)s : %(funcName)s : %(lineno)d : (Process Details : (%(process)d, %(processName)s), Thread Details : (%(thread)d, %(threadName)s))\nLog : %(message)s",
"datefmt":"%d-%m-%Y %I:%M:%S"
}
},
"handlers":{
"console":{
"formatter": "std_out",
"class": "logging.StreamHandler",
"level": "DEBUG",
"filters": ["drucker"]
},
"file":{
"formatter":"std_out",
"class":"logging.FileHandler",
"level":"DEBUG",
"filename" : "raspithek.log"
}
},
"root":{
"handlers":["console","file"],
"level": "DEBUG"
}
}
Neu ist hier nur die Sektion „filters“, die den „drucker“ Filter konfiguriert. Diesen Filter benutzen wir im „console“ Handler. Unser modifiziertes Programm enthält jetzt eine Klasse, mit dem DruckFilter. Außerdem wird die Logging Config als JSON Datei geladen.
#Datei: filterlogging.py
from logging import config
import json
# Filter definieren
class DruckFilter(logging.Filter):
def __init__(self, params=None):
self.param = params
print('Druckfilter initialisiert')
def filter(self, record:logging.LogRecord)-> bool| logging.LogRecord:
# nur Text, der das Wort Druck enthält soll geloggt werden.
return record.getMessage().lower().find('druck') > -1
# Config aus JSON Datei laden und setzen
with open('log_config.json') as file_config:
config.dictConfig(json.load(file_config))
# Logging testen
def testlogging():
print('testlogging() aufgerufen.')
logging.debug('Diese Zeile wird ausgefiltert.')
logging.debug('DEBUG/Druckdaten werden gesendet.')
logging.info('INFO/Es werden 2 Seiten gedruckt')
logging.debug('Diese Zeile wird auch ausgefiltert.')
logging.warning('WARN/nicht genügend Papier im Drucker')
logging.error('ERROR/Drucker nicht gefunden.')
logging.critical('CRITICAL/Drucker brennt')
if __name__ == '__main__':
testlogging()
Die Klasse DruckFilter leitet von logging.Filter ab und besitzt neben der __init__() Methode nur noch die Methode filter(self, record). Letztere bekommt den LogRecord übergeben und gibt ein True zurück, wenn der LogRecord weiterverarbeitet werden soll.
Wenn du das Programm startest, wirst du sehen, du sehen, dass die beiden Logzeilen, die den String „druck“ nicht enthalten, auch nicht in der Ausgabe erscheinen.
JSON Formatter
Ich will dir jetzt noch zeigen, wie du das Logfile im JSON Format schreiben kannst, wenn du es ggf. automatisiert weiterverarbeiten musst. Da dieser Post am 31.10. erscheinen soll, habe ich es etwas an diesen Tag angepasst. Es soll die kostümierten Wesen loggen, die zu Halloween an dir Tür kommen, um Süßigkeiten (Treat) zu erbitten. Das Programm wählt zufällig einen Treat aus der Liste aus und bestimmt eine Menge zwischen 0 und 20. Da ein Unsichtbarer keine Spuren im Logfile hinterlassen will, wird sein LogRecord durch den HalloweenFilter herausgefiltert. Der JsonFormatter sorgt für ein JSON kompatibles Logfile.
import logging
from logging import config
import json
import random
import JSONFormatter
#JSON Formatter
ATTR_TO_JSON = ['created', 'filename', 'funcName', 'levelname', 'lineno', 'module', 'msecs', 'msg', 'name', 'pathname', 'process', 'processName', 'relativeCreated', 'thread', 'threadName']
class JsonFormatter:
def format(self, record):
obj = {attr: getattr(record, attr)
for attr in ATTR_TO_JSON}
return json.dumps(obj, indent=4)
#CustomFilter
class HalloweenFilter(logging.Filter):
def __init__(self, params=None):
self.param = params
print('Halloweenfilter initialisiert')
def filter(self, record:logging.LogRecord)-> bool| logging.LogRecord:
# Der Unsichtbare soll keine Spuren im Logfile hinterlassen.
return record.getMessage().lower().find('unsichtbar') == -1
visitors = ['Werwolf','Gespenst','Hexe','Unsichtbarer','Vampir','Dämon','Gorilla','Monster','Mumie']
treats = ['Bonbons','Twinkies','Lollis','Schokoladen','Kuchen', 'Äpfel']
secrets = random.SystemRandom()
with open('halloween_log_conf.json') as file_config:
config.dictConfig(json.load(file_config))
for v in visitors:
logging.info(f'An der Tür klopft eine gruselige Gestalt: {v}')
number = secrets._randbelow(20)
treat = secrets.choice(treats)
logging.info(f'Du gibst ihr {number} {treat} und sie zieht weiter')Ein eigener Formatter ist im Prinzip nicht viel anders als ein Filter zu implementieren. Die Methode format() bekommt einen LogRecord und gibt den formatierten Text als String zurück. In der Liste ATTR_TO_JSON sind alle Attribute enthalten, die ins Logfile geschrieben werden sollen.Über eine List Comprehension werden diese in obj aufgebaut und danach mit json.dumps() in einen JSON-String umgewandelt.
Ein LogRecord im File sieht so aus:
{
"created": 1728902304.6991022,
"filename": "halloween.py",
"funcName": "<module>",
"levelname": "INFO",
"lineno": 40,
"module": "halloween",
"msecs": 699.0,
"msg": "Du gibst ihr 6 Lollis und sie zieht weiter",
"name": "root",
"pathname": "/home/pi/git/pythonkurs/teil27/halloween.py",
"process": 3078,
"processName": "MainProcess",
"relativeCreated": 48.51651191711426,
"thread": 4152119328,
"threadName": "MainThread"
}
DBHandler
Zum Abschluss dieses Post will ich dir noch zeigen, wie du mit einem eigenen Handler direkt in die Datenbank loggen kannst. Dazu benutze ich die Datenbank pidb, dir ich im Kapitel 17 angelegt hatte. Zunächst benötigen wir die db.ini mit den Verbindungsparametern:
[pidb]
host=database
user=piuser
password=<passwort>
database=pidb
Unser DBHandler soll automatisch die Tabelle logs in der Maria DB anlegen und für jeden LogRecord eine Tabellenzeile schreiben. Als Grundlage nehme ich hier das Programm testlogging.py und baue dort die DBHandler Klasse ein.
# Datei dbhandler.py
import mysql.connector
import datetime
import configparser
import logging
from logging import config
import json
class DBHandler(logging.Handler):
def __init__(self):
logging.Handler.__init__(self)
# Datenbank Konfiguration lesen
confparser = configparser.ConfigParser()
confparser.read('db.ini')
# Verbindung zur DB herstellen
self.connection= mysql.connector.connect(host=confparser['pidb']['host'],user = confparser['pidb']['user'],password = confparser['pidb']['password'],database = confparser['pidb']['database'])
# Tabelle anlegen, falls noch keine existiert.
self.connection.cursor().execute('''CREATE TABLE IF NOT EXISTS logs (
id INTEGER PRIMARY KEY AUTO_INCREMENT,
zeit VARCHAR(50),
level VARCHAR(8),
message VARCHAR(40),
logger_name VARCHAR(25),
filename VARCHAR(60),
line INTEGER)''')
self.connection.commit()
# Bei Löschung der Klasseninstanz, Connection schliessen
def __del__(self):
if self.connection != None:
self.connection.close()
self.connection = None
# LogRecord in die DB schreiben
def emit(self, record):
try:
# Log-Daten in ein Tupel extrahieren
log_entry = (datetime.datetime.utcnow().isoformat(),
record.levelname,
record.getMessage(),
record.name,
record.pathname,
record.lineno)
# Log in die Datenbank einfügen
cursor = self.connection.cursor()
cursor.execute('''INSERT INTO logs (zeit, level, message, logger_name, filename, line)
VALUES (%s, %s, %s, %s, %s, %s)''', log_entry)
self.connection.commit()
cursor.close()
except Exception as e:
# im Fehlerfall den LogRecord nach "oben" weiterreichen.
self.handleError(record)
# Config aus JSON Datei laden und setzen
with open('handler_config.json') as file_config:
config.dictConfig(json.load(file_config))
# Logging testen
def testlogging():
print('testlogging() aufgerufen.')
logging.debug('Diese Zeile wird ausgefiltert.')
logging.debug('DEBUG/Druckdaten werden gesendet.')
logging.info('INFO/Es werden 2 Seiten gedruckt')
logging.debug('Diese Zeile wird auch ausgefiltert.')
logging.warning('WARN/nicht genügend Papier im Drucker')
logging.error('ERROR/Drucker nicht gefunden.')
logging.critical('CRITICAL/Drucker brennt')
if __name__ == '__main__':
testlogging()
Konfiguriert wird der Handler in dieser Datei
# Datei: handler_config.json
{
"version":1,
"formatters":{
"std_out":{
"format": "%(asctime)s : %(levelname)s : %(module)s : %(funcName)s : %(lineno)d : (Process Details : (%(process)d, %(processName)s), Thread Details : (%(thread)d, %(threadName)s))\nLog : %(message)s",
"datefmt":"%d-%m-%Y %I:%M:%S"
}
},
"handlers":{
"console":{
"formatter": "std_out",
"class": "logging.StreamHandler",
"level": "DEBUG"
},
"db":{
"formatter": "std_out",
"()": "__main__.DBHandler",
"level": "DEBUG"
},
"file":{
"formatter":"std_out",
"class":"logging.FileHandler",
"level":"DEBUG",
"filename" : "raspithek.log"
}
},
"root":{
"handlers":["console","file","db"],
"level": "DEBUG"
}
}
In der __init__() Methode legt der Handler automatisch eine neue Datenbanktabelle an. In emit() nehmen wir den LogRecord entgegen und erzeuge die Tabellenzeile. Die Ausgabe auf der Console unterscheidet sich nicht vom obigen Beispiel, auch in der Logdatei stehen die gleichen Werte.
Interessant ist, was in der Datenbank passiert ist:
Fazit
logging.config bietet umfangreiche Möglichkeiten, das Logging zu verbessern. Du solltest allerdings im Hinterkopf behalten, dass dies nur auf Anwendungsebene sinnvoll ist. Es eignet sich nicht für das Logging in Modulen.
Und wie immer am Schluss der Hinweis auf das Git Repository. Das war’s für heute. Happy Halloween 🎃
