Logging

Ein Log zeichnet Ergebnisse von Vorgängen oder Berechnungen auf und dient der Dokumentation. Anhand eines Logs kann man Programmfehlern auf die Spur kommen oder bestimmte Situationen können im Nachhinein untersucht werden. Je detaillierter ein Log geführt wird, desto einfacher ist die Untersuchung bestimmter Sachverhalte. Je nachdem, was man untersuchen möchte, kann man mit einem Logging Level im Programm vorgeben, wie ernst oder wie wichtig ein bestimmter Logeintrag ist. Innerhalb des Kerns von SmartHomeNG finden sich zum Beispiel Einträge im Programm mit dem Log Level NOTICE, die in einer Logdatei dann im Ergebnis so aufgezeichnet werden:

2021-04-16  21:56:31 NOTICE   lib.smarthome     --------------------   Init SmartHomeNG 1.8.2c.4e0938c2.develop   --------------------

Das ist als Information zu sehen, um bei Problemen Hilfe zu erhalten. Es deutet hier nichts auf Fehler oder Probleme hin. Ein anderer Logging Befehl im Core mit dem Log Level WARNING erzeugt hingehen folgendes:

2021-04-16  21:56:32 WARNING  lib.module        Not loading module Mqtt from section 'mqtt': Module is disabled

Das ist als Warnung gedacht, um darauf hinzuweisen, dass ein Modul nicht geladen wird und in dieser Folge eventuell weitere Fehler oder Probleme auftauchen könnten. Steigerungen von Warnungen sind Log Level ERROR oder CRITICAL. Während ein ERROR also ein Fehler durchaus bedeuten kann, dass SmartHomeNG weiterarbeiten kann, bedeutet ein CRITICAL, also ein kritischer Fehler, dass das Programm beendet werden muss. Fehlt ein für den Kern von SmartHomeNG benötigtes Modul, so stell das einen kritischen Fehler dar.

Die Log Level in der Übersicht, absteigend in der Bedeutung für den Programmablauf:

Log Level

Level	Numerischer Wert	Anmerkung
CRITICAL	50	kritisch, führt zumeist zum Programmabbruch
ERROR	40	Fehler im Programmablauf, Programm kann zumeist weiterlaufen, Funktionalität möglicherweise eingeschränkt
WARNING	30	Warnung, dass etwas Unerwartetes passiert ist aber trotzdem weitergearbeitet werden kann.
NOTICE	29 (31 falls der Level des FileHandler des root Loggers nicht auf NOTICE sondern WARNING konfiguriert ist.)	Ein Hinweis der zur grundlegenden Information dient und nicht als Warnung verstanden werden soll. Dieser Log Level ist spezifisch für SmartHomeNG und ist im Standard Logging von Python nicht vordefiniert.
INFO	20	Eine Ablaufinformation, die nicht unbedingt wichtig ist
DBGHIGH	13	Informationen für die Fehlersuche, die normalerweise nicht benötigt werden
DBGMED	12	Informationen für die Fehlersuche, die normalerweise nicht benötigt werden
DBGLOW	11	Informationen für die Fehlersuche, die normalerweise nicht benötigt werden
DEBUG	10	Informationen für die Fehlersuche, die normalerweise nicht benötigt werden
NOTSET	0	Es wird kein Logeintrag erzeugt

Es können prinzipiell auch weitere eigene Log Level definiert werden, die dann für besondere Situationen benutzt werden können. Ein Beispiel wäre ein Log Level VERBOSE mit dem Wert 8, der für die Fehlersuche in einem bestimmten Bereich eines Plugins Verwendung finden könnte. Für SmartHomeNG ist derzeit nur NOTICE vordefiniert, um informelle Logging Einträge zu erzeugen, die nicht als Warnung verstanden werden sollen.

Konfiguration des Loggings

Auf der Seite Python Logging sind die Konfigurationsmöglichkeiten detailliert beschrieben.

SmartHomeNG lädt beim Start die Konfiguration des Logging aus der Datei etc/logging.yaml. Ist diese Datei nicht vorhanden, so versucht SmartHomeNG, die Datei etc/logging.yaml.default nach etc/logging.yaml zu kopieren und dann daraus die Konfiguration des Loggings zu laden.

Wenn bei der Konfiguration des Loggings etwas schief geht, kann also jederzeit die Datei etc/logging.yaml gelöscht oder besser umbenannt werden und wird dann beim nächsten Neustart durch den Inhalt der etc/logging.yaml.default frisch bereitgestellt.

Ein Beispiel für etc/logging.yaml.default im Folgenden:

../etc/logging.yaml

%YAML 1.1
---
version: 1
disable_existing_loggers: false

formatters:

    # The following sections define the output formats to be used in the different logs
    #
    shng_simple:
        format: '%(asctime)s %(levelname)-8s %(name)-19s %(message)s'
        datefmt: '%Y-%m-%d  %H:%M:%S'

    shng_detail1:
        format: '%(asctime)s %(levelname)-8s %(module)-17s %(threadName)-12s %(message)s  --  (%(filename)s:%(funcName)s:%(lineno)d)'
        datefmt: '%Y-%m-%d %H:%M:%S %Z'

    shng_detail2:
        format: '%(asctime)s %(levelname)-8s %(name)-19s %(module)-19s %(funcName)-12s ln:%(lineno)-3d %(message)s  ----  %(threadName)-12s '
        datefmt: '%Y-%m-%d %H:%M:%S %Z'

    shng_items:
        format: '%(asctime)s %(levelname)-8s %(module)-12s %(message)s'
        datefmt: '%Y-%m-%d %H:%M:%S'

    shng_busmonitor:
        # This formatter must be enabled when busmonitor logging from the knx plugin should be used.
        format: '%(asctime)s;%(message)s;'
        datefmt: '%Y-%m-%d;%H:%M:%S'


filters:

    # The following sections define filters that can be used for different logs
    #
    knx_filter:
        # This filter must be enabled when busmonitor logging from the knx plugin should be used.
        # It filters all log entries coming from the logger named knx_busmonitor (that is initialized in the KNX plugin)
        (): lib.logutils.Filter
        name: knx_busmonitor

    filter_example:
        # This filter hides all messages from logger module "item" with messages containing "This is a very nice filter"
        (): lib.logutils.Filter
        module: item
        msg: "This is a very nice filter"
        # The next invert: True parameter would ONLY show messages matching both module and msg parameters and nothing else
        #invert: True


handlers:

    shng_warnings_file:
        # This handler writes only entries with level NOTICE/WARNING and above
        # to the file. This allows for a quick check if all is running smooth.
        #
        # To keep the warnings file easy readable, the level should always be NOTICE!
        #
        # The TimedRotatingFileHandler seperates the logentries by day and
        # keeps the entries of the last seven days in seperate files.
        #
        #class: logging.handlers.TimedRotatingFileHandler
        (): lib.log.ShngTimedRotatingFileHandler
        formatter: shng_simple
        level: NOTICE
        utc: false
        when: midnight
        backupCount: 7
        filename: ./var/log/smarthome-warnings.log
        encoding: utf8

    shng_details_file:
        # This handler writes all entries to the details-file. Log entries with level WARNING
        # and above are additionally written to the warnings-file (through the root logger).
        #
        # The TimedRotatingFileHandler seperates the logentries by day and
        # keeps the entries of the last seven days in seperate files.
        #
        (): lib.log.ShngTimedRotatingFileHandler
        formatter: shng_simple
        level: DEBUG
        utc: false
        when: midnight
        backupCount: 7
        filename: ./var/log/smarthome-details.log
        encoding: utf8
        filters: [knx_filter]

    #develop_file:
    #    # This handler should be used for development purposes. It writes all entries to
    #    # the develop-file. Log entries with level WARNING and above are additionally written
    #    # to the warnings-file (through the root logger).
    #    #
    #    # The TimedRotatingFileHandler seperates the logentries by day and
    #    # keeps the entries of the last seven days in seperate files.
    #    #
    #    (): lib.log.ShngTimedRotatingFileHandler
    #    formatter: shng_detail
    #    level: DEBUG
    #    utc: false
    #    when: midnight
    #    backupCount: 7
    #    filename: ./var/log/smarthome-develop.log
    #    encoding: utf8
    #    filters: [filter_example]

    #shng_busmonitor_file:
    #    # This handler must be enabled when busmonitor logging from the knx plugin should be used.
    #    #
    #    (): lib.log.ShngTimedRotatingFileHandler
    #    formatter: shng_busmonitor
    #    level: DEBUG
    #    when: midnight
    #    backupCount: 7
    #    encoding: utf8
    #    filename: ./var/log/knx_busmonitor.log

    #shng_items_file:
    #    # This handler is an example for logging item-value changes to a seperate log file
    #    #
    #    (): lib.log.ShngTimedRotatingFileHandler
    #    formatter: shng_items
    #    when: midnight
    #    backupCount: 7
    #    filename: ./var/log/item-value-change.log
    #    encoding: utf8

    #console:
    #    class: logging.StreamHandler
    #    formatter: shng_simple
    #    stream: ext://sys.stdout

loggers:
    # The following default loggers should not be changed. If additional logging
    # is required, a logger for the specific lib, module or plugin shoud be added.
    #
    functions:
        handlers: [shng_details_file]
        level: NOTICE

    lib:
        # Default logger for SmartHomeNG libraries
        handlers: [shng_details_file]
        level: NOTICE

    lib.smarthome:
        # Add all logging handlers that should receive the initial log lines after a startup
        # (example below) but leave out the logging handlers that are defined in the root-logger
        # (otherwise log entries will be doubled).
        #
        # 2020-12-29  11:35:34 NOTICE  lib.smarthome   --------------------   Init SmartHomeNG 1.8.0   --------------------
        # 2020-12-29  11:35:34 NOTICE  lib.smarthome   Running in Python interpreter 'v3.8.3 final' in virtual environment
        # 2020-12-29  11:35:34 NOTICE  lib.smarthome    - on Linux-4.9.0-6-amd64-x86_64-with-glibc2.17 (pid=24407)
        # 2020-12-29  11:35:35 NOTICE  lib.smarthome    - Nutze Feiertage für Land 'DE', Provinz 'HH', 1 benutzerdefinierte(r) Feiertag(e) definiert
        # 2020-12-29  11:36:54 NOTICE  lib.smarthome   --------------------   SmartHomeNG initialization finished   --------------------
        #
        # logging to shng_details_file is already enabled in logger lib:
        #handlers: [shng_develop_file]

        # set to WARNING LEVEL to prevent unwanted log entries and add ONLY start and stop log-messages to further logfiles
        level: NOTICE

    modules:
        # Default logger for SmartHomeNG modules
        handlers: [shng_details_file]
        level: NOTICE

    plugins:
        # Default logger for SmartHomeNG plugins
        handlers: [shng_details_file]
        level: NOTICE

    logics:
        # Default logger for SmartHomeNG logics
        handlers: [shng_details_file]
        level: NOTICE

    # ------------------------------------------

    items:
        # Default logger for SmartHomeNG logics
        handlers: [shng_details_file]
        level: NOTICE

    # items.temperatures:
    #     # Logging items with configuration: log_change: temperatures
    #     #
    #     # handlers: [shng_develop_file]   # Hier keinen ererbten Handler (aus items: logger oder root: logger) erneut eintragen
    #     level: INFO

    # items.new_device:
    #     # Logging items with configuration: log_change: new_device
    #     # to a different file
    #     #
    #     handlers: [shng_items_file]
    #     level: DEBUG

    # ------------------------------------------

    # plugins.avm:
    #     # handlers: [shng_develop_file]   # Hier keinen ererbten Handler (aus plugins: logger oder root: logger) erneut eintragen
    #     level: INFO

    # ------------------------------------------

    # knx_busmonitor:
    #     # This logger must be enabled when busmonitor logging from the knx plugin should be used.
    #     level: INFO
    #     handlers: [shng_busmonitor_file]

    # ------------------------------------------

    # Some Python packages log to loggers defined by the package itself. Such
    # loggers could be configured analog to the other loggers described above.
    # Some Examples are listed below.
    #

    # cherrypy.error:
    #     # Error logging for the cherrypy package
    #     handlers: [shng_details_file]
    #     level: INFO

    # jinja2:
    #     # Logger for the Jinja2 template engine
    #
    #     handlers: [shng_details_file]
    #     level: INFO


    # ================
    # special loggers
    # ----------------


root:
    # This is the configuration of the root logger. Additionally to be written to other logs,
    # ALL entries are handed to this logger. To keep the warnings file easy readable,
    # the level should always be WARNING!
    #
    # Logging of details (level INFO and DEBUG) should be handled by other loggers and written
    # to other log files than the warnings file.
    #
    level: WARNING
    handlers: [shng_warnings_file]

Kurzdoku der Einträge in der Konfigurationsdatei

Die einzelnen Konfigurationseinträge haben die folgende Bedeutung:

Abschnitte	Bedeutung
formatters:	Definiert das Ausgabeformat der einzelnen Loggingeinträge. Mehrere unterschiedliche formatter können dazu verwendet werden, um unterschiedlich aussehende Logdateien zu erzeugen. In der Konfigurationsdatei etc/logging.yaml sind die Formatter `simple` und `detail` vorkonfiguriert. Weitere Formatter können bei Bedarf hinzugefügt werden.
handlers:	Handler definieren die Log-Behandlungsroutinen/Ausgabekanäle die verwendet werden. In Python gibt es bereits mehrere vorimplementierte und mächtige Handler-Typen, die in der Python Doku beschrieben sind. Als eigentliche Handler sind in der Konfigurationsdatei etc/logging.yaml die Handler `console` und `file` vordefiniert. Wenn Log-Einträge z.B. in eine andere Datei geschrieben werden sollen, muss ein weiterer Handler definiert werden. Sollen Filter angewendet werden, so sind diese im entsprechenden Handler durch filters: [filtername1, filtername2] anzugeben (siehe filters).
filters:	Filter bestimmen durch Angabe des Loggernamen, -moduls und -eintrags, welche Zeilen aus dem Log angezeigt bzw. versteckt werden sollen. Der Eintrag (z.B. loggerfilter) kann bei den Handlers mittels `filters: [<filtername>]` referenziert werden. Wichtig ist, den Filternamen in eckige Klammern zu setzen, auch wenn nur ein Filter zum Einsatz kommen soll. Jeder Filter kann durch bis zu drei Parameter definiert werden, wobei diese nach AND Logik evaluiert werden: name: Loggername (z.B. lib.item) module: Loggermodul, va. bei Plugins u.U. relevant (z.B. item, metadata, etc. OHNE lib.) timestamp: Uhrzeit/Datum (z.B. „23:00“ oder ein regulärer Ausdruck) msg: Der tatsächliche Logeintrag als RegEx, z.B. „Result = (.*) (for attribute ‚eval‘)“ Durch die Angabe von invert: True werden NUR die passenden Messages geloggt und sonst nichts. Ein Beispiel ist unter Logging - Best Practices zu finden.
loggers:	Hier werden die einzelnen Logger definiert, was mit diesen Einträgen passiert, und welche Handler und formatter verwendet werden. Das Level konfiguriert dabei die Logtiefe für die einzelne Komponente. Bei den Loggern ist es nun möglich, einzelne Plugins oder Libs im Debug protokollieren zu lassen. Dazu sind in der Konfiguration bereits einige Beispiele.
root:	Hier ist die Konfiguration des root Loggers, der für die ganze Anwendung gilt. Dieser root Logger wird für alle Komponenten verwendet auch die, die nicht unter loggers: konfiguriert sind. Da der root Logger ALLE Logeinträge empfängt, sollte der level: unbedingt auf WARNING stehen.

Wenn man Logger definiert, welche die Log-Einträge über zusätzliche Handler ausgeben, ist zu beachten, dass die Ausgabe zusätzlich IMMER durch den Standardhandler (file:) erfolgt. Dies führt dazu, dass die Einträge sowohl in der Standard Log-Datei von SmartHomeNG, als auch in der zusätzlich definierten Log Datei erscheinen, falls der Level des Log Eintrages INFO oder höher ist.

Wenn man möchte, dass im Standard Log nur WARNINGS und ERRORS erscheinen, muss ein zusätzlicher Eintrag im Handler file: erfolgen. Der Eintrag level: WARNING führt dazu, dass über den Handler file: nur Ausgaben für Fehler und Warnungen erfolgen. INFO und DEBUG Ausgaben erfolgen dann nur noch über den zusätzlichen Handler.

Logging Handler und Filter

Zusätzlich zu den Logging Handlern, die im Standard Logging Modul von Python definiert, bringt SmartHomeNG weitere Handler und Filter mit, die bei der Konfiguration in ../etc/logging.yaml verwendet werden können.

Die Beschreibung dieser Handler und Filter ist im Referenz Abschnitt unter Logging zu finden:

• Logging Handler
• Logging Filter

Plugin und Logik Entwicklung

Für die Entwickler von Plugins:

Früher musste in Plugins ein Logger in der Form

import logging
self.logger = logging.getLogger(__name__)

in der __init__ Methode instanziert werden. Das ist inzwischen nicht mehr notwendig. Die SmartPlugin Klasse erzeugt den Logger inzwischen selbst. Ein import logging ist nicht mehr notwendig und die Initialisierung des Loggers in der __init__ Methode sollte auch weggelassen werden.

Der Logger kann/muss in der etc/logging.yaml konfiguriert werden. Der Name des Loggers ist plugins.<Name des Plugins>.

Für die Entwickler von Logiken: Verwendet man zur Instanzierung einen eigenen Namen (nicht empfohlen), wie z.B.

self.logger = logging.getLogger('DWD')

muss in der config auch dieser Name verwendet werden. Ohne plugin. oder logics.

../etc/logging.yaml

loggers:
    DWD:
        level: DEBUG

Standardmäßig haben Logiken bereits einen Logger, der in der etc/logging.yaml konfiguriert werden kann/muss. Der Name des Loggers ist logics.<Name der Logik>, wobei der Name der Logik der in der Konfiguration festgelegte Name ist und nicht der Name des Python Skriptes.

Logging der Veränderung von Items

Ab Version 1.5 von SmartHomeNG erfolgt die Konfiguration des Loggings der Veränderung von Item Werten über Standard Item Attribute, wie es bei den Standardattributen beschrieben ist.

Best Practices

Wer eine brauchbare und leicht konfigurierbare Logging Konfiguration oder Beispiele zum Nutzen von RegEx Ausdrücken sucht, der wird hier Logging - Best Practices fündig.

• Logging - Best Practices