..index:: Logging

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, das ein Module 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 das SmartHomeNG weiterarbeiten kann, bedeutet ein CRITICAL also ein kritischer Fehler das 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

50

CRITICAL

kritisch, führt zumeist zum Programmabbruch

40

ERROR

Fehler im Programmablauf, Programm kann zumeist weiterlaufen, Funktionalität möglicherweise eingeschränkt

31

NOTICE

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.

30

WARNING

Warnung das etwas unerwartetes passiert ist aber trotzdem weitergearbeitet werden kann

20

INFO

Eine Ablaufinformation die nicht unbedingt wichtig ist

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 zu kopieren nach etc/logging.yaml 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 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 WARNING!
        #
        # 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: WARNING
        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: INFO

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

    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 WARNING  lib.smarthome   --------------------   Init SmartHomeNG 1.8.0   --------------------
        # 2020-12-29  11:35:34 WARNING  lib.smarthome   Running in Python interpreter 'v3.8.3 final' in virtual environment
        # 2020-12-29  11:35:34 WARNING  lib.smarthome    - on Linux-4.9.0-6-amd64-x86_64-with-glibc2.17 (pid=24407)
        # 2020-12-29  11:35:35 WARNING  lib.smarthome    - Nutze Feiertage für Land 'DE', Provinz 'HH', 1 benutzerdefinierte(r) Feiertag(e) definiert
        # 2020-12-29  11:36:54 WARNING  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: WARNING

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

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

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

    # plugins.cli:
    #     # Example for changing the loglevel for a specific plugin (cli plugin)
    #     # a handler should only be specified, if logging should be done to
    #     # another destination, otherwise duplicate log entries could be produced.
    #     level: INFO

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

    logics:
        # Default logger for SmartHomeNG logics
        # to change the loglevel for all logics, the level can be changed.
        # Alternatively individual loggers for certain logics can be added.
        handlers: [shng_details_file]
        level: WARNING

    # logics.ex_logging:
    #     # Example of a logger for a specific logic (configured as ex_logging in logics.yaml)
    #     #
    #     level: INFO

    # logics.ex_logging2:
    #     # Example of a logger for a specific logic (configured as ex_logging2 in logics.yaml)
    #     # This logger logs info for the logic to another file (logics_file). (WARNINGs will still be
    #     # logged to shng_details_file.
    #     #
    #     handlers: [logics_file]
    #     level: INFO

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

    # items.temperatures:
    #     # Logging items with configuration: log_change: temperatures
    #     #
    #     handlers: [shng_details_file]
    #     level: INFO

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

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

    # 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
    # ----------------

    __main__:
        handlers: [shng_details_file]
        level: WARNING


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) - timestamp: Uhrzeit/Datum (z.B. „23:00“) - 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 und was mit diesen Einträgen passiert, 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:

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.

Für die Entwickler von Logiken: Verwendet man zur Instanziierung 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

Logging der Veränderung von Items

Die Veränderung von Item Werten kann am einfachsten geloggt werden, indem bei dem Item das Attribut log_change gesetzt wird und auf einen entsprechenden Item Logger verweist. Der Item Logger muss in der etc/logging.yaml mit Level INFO oder DEBUG definiert sein.

items/items.yaml
 test:
     item:
         log_change: <Logger-Name>

und

etc/logging.yaml
 ...-

 logger:
     items_<Logger-Name>:
         level: INFO
         handlers: [shng_details_file]

 ...

Best Practices

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