..index:: Logging

Logging

Zur Konfiguration des Loggings mit SmartHomeNG wird seit der Version 1.2 eine Konfigurationsdatei im YAML Format verwendet.

Konfiguration des Loggings

Die Datei ../etc/logging.yaml befindet sich bereits vorkonfiguriert in dem Verzeichnis.

Die Datei sieht so aus:

../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
    #
    loggerfilter:
        # This filter must be enabled when busmonitor logging from the knx plugin should be used.
        (): lib.logutils.Filter
        name: knx_busmonitor


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
        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.
        #
        class: logging.handlers.TimedRotatingFileHandler
        formatter: shng_simple
        level: DEBUG
        utc: false
        when: midnight
        backupCount: 7
        filename: ./var/log/smarthome-details.log
        encoding: utf8

    #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.
    #    #
    #    class: logging.handlers.TimedRotatingFileHandler
    #    formatter: shng_detail
    #    level: DEBUG
    #    utc: false
    #    when: midnight
    #    backupCount: 7
    #    filename: ./var/log/smarthome-develop.log
    #    encoding: utf8

    #shng_busmonitor_file:
    #    # This handler must be enabled when busmonitor logging from the knx plugin should be used.
    #    #
    #    class: logging.handlers.TimedRotatingFileHandler
    #    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
    #    #
    #    class: logging.handlers.TimedRotatingFileHandler
    #    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.
    #
    lib:
        # Default logger for SmartHomeNG libraries
        handlers: [shng_details_file]
        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__:
        # 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).
        #
        # 2019-02-26  22:42:27 WARNING  __main__            --------------------   Init SmartHomeNG 1.5d.5a01c53f.develop   --------------------
        # 2019-02-26  22:42:27 WARNING  __main__            Running in Python interpreter 'v3.6.5 final' (pid=25878) on linux platform
        #
        handlers: [shng_details_file]
        #handlers: [shng_details_file,shng_develop_file]

        # set to WARNING LEVEL to add ONLY start and stop log-messages to further logfiles
        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]

In die Konfigurationsmöglichkeiten des Python Loggings kann sich hier eingelesen werden: https://docs.python.org/3.4/library/logging.html#module-logging

Die Datei ../etc/logging.yaml hat kein SmartHomeNG spezifisches Format. Sie wird mit der Funktion logging.config.dictConfig() (Bestandteil der Python Standardbibliothek) eingelesen.

Informationen zu dieser Python Funktion und den damit verbundenen Möglichkeiten gibt es hier: https://docs.python.org/3.4/library/logging.config.html#module-logging.config

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 hier 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.
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. Dieses 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.

Plugin Entwicklung

Für die Entwickler von Plugins: Der Logger sollte nun nicht global mit logging.getLogger(‚‘) instanziert werden sondern innerhalb der __init__ Methode mit:

self.logger = logging.getLogger(__name__)

Wobei __name__ ein sogenanntes magic ist. Dies bedeutet, dass Python aus __name__ den Namen des Plugins macht.

So wird aus plugins/cli/ der Name „plugins.cli“, aus lib/scheduler.py wird „lib.scheduler“ Daher muss dann in der Konfiguration des Loggings der Name „plugin.cli“ angegeben werden.

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.

../etc/logging.yaml
loggers:
    DWD:
        level: DEBUG

Auf den Logger kann dann so zugegriffen werden:

self.logger.debug("")
self.logger.info("")

Beispiel:

def __init__(self, smarthome, update='False', ip='127.0.0.1', port=2323):
    self.logger = logging.getLogger(__name__)
    # Logger verwenden:
    self.logger.debug("Debug Message")

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 sucht, der wird hier Logging - Best Practices fündig.