smarthomeNG 1.4.1 - Logging richtig einstellen

[loeserman]

Hallo zusammen,
ich habe soeben auf smarthomeNG 1.4.1 umgestellt und möchte nun auch meine Logger etwas optimieren. Zwei Sachen möchte ich erreichen:

1. KNX Busmonitor Daten in den Extrafile "knx_busmonitor.log" verschieben
2. Von meinem Pugin "viessmann" sollen nur Events >= WARNING in den Hauptlog geloggt werden

In der "plugin.yaml" habe ich bei KNX den busmonitor auf "logger" eingestellt. Diese Einstellung habe ich im Manual gesehen und sollte genau das machen, was ich brauche.
https://www.smarthomeng.de/user/plug...ght=busmonitor

# KNX Verbindung via knxd
knx:
    class_name: KNX
    class_path: plugins.knx
    host: 127.0.0.1
    port: 6720
    busmonitor: 'logger' # log all knx messages, default false
    send_time: 600       # update date/time every 600 seconds, default none
    time_ga: 0/2/0       # default none
    date_ga: 0/2/1       # default none
    # readonly: True     ## don't write to knx bus, default false"
    # instance: default

Habe es auch mit folgenden Einstellungen probiert, aber das Ergebnis war immer gleich.
+ busmonitor: logger
+ busmonitor: 'Logger'
+ busmonitor: knx_busmonitor
+ busmonitor: 'knx_busmonitor'

Meine logger.yaml sieht folgendermaßen aus. Die interessanten Stellen habe ich mal farblich markiert.

version: 1
disable_existing_loggers: False
formatters:
[COLOR=#FF0000]  busmonitor_format:
    format: '%(asctime)s;%(message)s;'
    datefmt: '%Y-%m-%d;%H:%M:%S'[/COLOR]
  simple:
    format: '%(asctime)s %(levelname)-8s %(threadName)-12s %(message)s'
    datefmt: '%Y-%m-%d  %H:%M:%S'
  detail:
    format: '%(asctime)s %(levelname)-8s %(module)-12s %(threadName)-12s %(message)s -- %(filename)s:%(funcName)s:%(lineno)d'
    datefmt: '%Y-%m-%d %H:%M:%S'
filters:
[COLOR=#FF0000]  loggerfilter:
    '()': lib.logutils.Filter
    name: 'knx_busmonitor'[/COLOR]
handlers:
  console:
    class: logging.StreamHandler
    formatter: detail
    stream: ext://sys.stdout
  file:
    class: logging.handlers.TimedRotatingFileHandler
    formatter: simple
    filters: [loggerfilter]
    when: midnight
    backupCount: 7
    encoding: utf8
    filename: ./var/log/smarthome.log
[COLOR=#FF0000]  busmonitor_file:
    class: logging.handlers.TimedRotatingFileHandler
    formatter: busmonitor_format
    when: midnight
    backupCount: 7
    encoding: utf8
    filename: ./var/log/knx_busmonitor.log[/COLOR]
loggers:
[COLOR=#FF0000]  knx_busmonitor:
    level: DEBUG
    handlers: [busmonitor_file][/COLOR]
[COLOR=#0000FF]  plugins.viessmann:
    level: WARNING
    handlers: [file][/COLOR]
#  plugins.knx:
#    level: INFO
#  lib.scheduler:
#    level: DEBUG
#  plugins.cli:
#    level: DEBUG

root:
  level: INFO
  handlers: [file, console]

Das Ergebnis ist aber leider immer noch wie folgt im Hauptlogfile "smarthome.log". Der Busmonitor logfile "knx_busmonitor.log" ist immer leer.
Eigentlich sollten die roten Zeilen in den Busmonitor logfile auflaufen und die blauen im Hauptlogfile entfallen, da INFO kleiner ist als WARNING.

[COLOR=#FF0000]2017-12-28  23:09:13 INFO     Main         KNX[default]: 1.1.18 set 1/6/36 to 1.0609999895095825[/COLOR]
2017-12-28  23:09:13 INFO     logics.Rxx_Item_Handler MELDUNG: Trigger by:Item, item=R02.STECKDOSE.HEBEANLAGE.STROMWERT.ACTIVATED, logic=Rxx_Item_Handler
[COLOR=#FF0000]2017-12-28  23:09:13 INFO     Main         KNX[default]: 1.1.18 set 1/6/36 to 1.184999942779541
2017-12-28  23:09:16 INFO     Main         KNX[default]: 1.1.18 set 1/6/36 to 0.42100000381469727[/COLOR]
2017-12-28  23:09:16 INFO     logics.Rxx_Item_Handler MELDUNG: Trigger by:Item, item=R02.STECKDOSE.HEBEANLAGE.STROMWERT.ACTIVATED, logic=Rxx_Item_Handler
[COLOR=#FF0000]2017-12-28  23:09:16 INFO     Main         KNX[default]: 1.1.18 set 1/6/36 to 0.14499999582767487
2017-12-28  23:09:42 INFO     Main         KNX[default]: 1.1.18 set 1/6/30 to 0.0[/COLOR]
[COLOR=#0000FF]2017-12-28  23:09:42 INFO     viessmann    MELDUNG: Plugin viessmann - Wert korrekt gelesen und Item geschrieben. Read value : warmwassersolltemp[/COLOR]
[COLOR=#FF0000]2017-12-28  23:09:42 INFO     Main         KNX[default]: 1.1.18 set 1/6/31 to 0.0[/COLOR]
[COLOR=#0000FF]2017-12-28  23:09:42 INFO     viessmann    MELDUNG: Plugin viessmann - Wert korrekt gelesen und Item geschrieben. Read value : warmwasserpumpe[/COLOR]
[COLOR=#FF0000]2017-12-28  23:09:42 INFO     Main         KNX[default]: 1.1.18 set 1/6/32 to 0.0[/COLOR]

Was mache ich falsch?

[Msinn]

Hast Du dir mal folgenden Teil der Doku zu Gemüte geführt https://www.smarthomeng.de/user/konf...n/logging.html ?

Das sind die Best Practices für das Logging, wie auch im Wiki beschrieben waren, auf den der gepinnte Forumsartikel https://knx-user-forum.de/forum/supp...s-für-logging verwies.

[loeserman]

Hi Msinn,
Danke für Deine Links. Ja das hatte ich gelesen und dahingehend auch versucht meine Einstellungen zu machen, doch leider funktioniert das bei mir nicht. Vielleicht ist auch meine Installation nicht mehr ganz okay und ich muss mal völlig neu aufsetzen.

Selbst wenn ich in meinem Plugin die folgenden Zeilen schreibe erhalte ich als Ausgabe nicht das, was ich erwartet hätte

import logging
import ...

# Plugin Klasse
class viessmann():

    def __init__(self, smarthome, serialport="/dev/ttyUSB_HEIZUNG", update_cycle="900"):
        # Logger festlegen
        self.logger = logging.getLogger(__name__)
        # Eintrag in den Log
        self.logger.info('Plugin viessmann - Initialisierung gestartet')
        ...

Ergebnis:

2017-12-29  10:31:01 INFO     Main         Plugin viessmann - Initialisierung gestartet

Hätte hier nun nicht anstatt "Main" "plugins.viessmann" stehen müssen? So verstehe ich die Dokumentation.
Generell steht hier sehr oft Main bei mir. Auch bei den KNX Meldungen. Nur bei den Logiken steht "logics.xyz", wie es sein soll.

2017-12-29  10:54:03 INFO     Main         Plugin viessmann - Initialisierung gestartet
2017-12-29  10:54:41 INFO     logics.Rxx_Item_Handler MELDUNG: Trigger by:Item, item=R23.HEIZUNG.REGLER.IST_TEMPERATUR, logic=Rxx_Item_Handler
2017-12-29  10:55:01 INFO     Main         KNX[default]: 1.1.18 set 1/6/32 to 0.0

Ggf. wird bei mir dieses magic __name__ nicht richtig aufgelöst.
Kann das sein? Gibt es da etwas zu beachten?

[Msinn]

Nein, zum immer noch auftretenden viessmann log ist die Ursache, dass Du den root Logger noch auf INFO stehen hast. Das Haupt Log verhlt sich anders als die zustzlichen Logs. Lies das bitte auf den von mir genannten Seiten nach.

[grisu911]

Hallo,
bin in diesem Beitrag auf folgendes aufmerksam geworden:

Von meinem Pugin "viessmann" sollen nur Events >= WARNING in den Hauptlog geloggt werden

Kannst du das vielleicht das Plugin genauer vorstellen? Bin seit einigen Wochen immer wieder dabei mich mit v-control (OpenV) zu beschäftigen, je nach Zeit, welche leider sehr knapp ist.
Würde nähmlich gern meine Viessmann Wärmepumpe mit in smarthome.py einbinden.

Gruß Grisu911

[Msinn]

Ich kenne das Plugin nicht. Wende Dich bitte an den Autor des Plugins.

[loeserman]

Hi Msinn,
gestatte mir noch eine letzte Frage. Es geht nur noch um den Busmonitor.

Laut Dokumentation soll ich zur Aktivierung des Busmotitors in einen extra File in der plugin.yaml folgendes angeben. Das habe ich auch gemacht.
plugin.yaml

knx:
    class_name: KNX
    class_path: plugins.knx
    host: 127.0.0.1
    port: 6720
[COLOR=#FF0000]  busmonitor: 'logger'[/COLOR]
    send_time: 600       # update date/time every 600 seconds, default none
    time_ga: 0/2/0       # default none
    date_ga: 0/2/1       # default none

Danach bleibt aber mein busmonitor log immer noch leer.
Gucke ich nun genauer in das knx Plugin stelle ich folgendes fest.

plugins\knx\__init__.py

    def __init__(self, smarthome, time_ga=None, date_ga=None, send_time=False, busmonitor=False, host='127.0.0.1',
                 port=6720, readonly=False, instance='default', enable_stats = True):
        ...

[COLOR=#FF0000]      if self.to_bool(busmonitor,default=busmonitor)[/COLOR]:
            self._busmonitor = self.logger.info
        else:
            self._busmonitor = self.logger.debug

            # write bus messages in a separate logger
            if isinstance(busmonitor, str):
                if busmonitor.lower() in ['logger']:
                    self._bm_separatefile = True
                    self._bm_format = "{0};{1};{2};{3}"
                    self._busmonitor = logging.getLogger("knx_busmonitor").info

Lasse ich den Übergabeparameter "busmonitor" ausgeben, so erhalte ich "logger". Also korrekt. Mit "logger" geht aber die if Abfrage (rot markiert) sofort auf TRUE und setzt den Logger auf info und geht entsprechend nicht in den Else Zweig, der den extra Logger einschalten würde.

Was mache ich nun wieder falsch? Der Parameter kann es eigentlich nicht sein, da dieser ja explizit so abgefragt wird im Else Zweig. Aber den erreiche ich dadurch erst gar nicht, wenn ich nicht das Plugin selbst ändere. Irgendwie checke ich da die Funktion "self.to_bool" nicht.

Vielleicht kannst Du mir hier noch kurz einen Tipp geben. Dann lasse ich euch auch in Ruhe mit dem Logger Kram.

Danke und Gruß
loeserman

[loeserman]

@grisu911:
Das viessmann plugin habe ich mir mal selbst geschrieben. Das kann ich gerne auch mal vorstellen in einem anderen Thread. Mache hierzu mal einen neuen auf. Ich lese mit dem Plugin meine Heizung Vitodens 300 aus. Eventuell kannst du davon etwas übernehmen für deine Heizung.

Gruß
loeserman

[Tontechniker]

Hallo loeserman,
das Viessmann Vitodens 300 würde mich auch interessieren.
Gruß
Hans

[Msinn]

loeserman Zum Busmonitor muss ich selber erstmal schauen. Damit habe ich mich noch nie auseinandergesetzt.

[Morg]

@grisu911:
Das viessmann plugin habe ich mir mal selbst geschrieben. Das kann ich gerne auch mal vorstellen in einem anderen Thread.

Oh ja, tu das bitte unbedingt!

Ich habe (wie wahrscheinlich einige andere auch) eine Kombination von vcontrold, vclient per cron, Template und UDP und network-Plugin laufen, um die Heizungsdaten in sh.py zu bekommen.

Ich hatte gerade heute morgen überlegt, den Versuch zu starten, ein Plugin zu schreiben, das mit vcontrold spricht und mir den Umweg über vclient und Netzwerk zu sparen. Alternativ könnte das Plugin natürlich auch direkt mit USB sprechen, das hätte ich mir aber (inkl. Protokollparser) nicht zugetraut.

Vielleicht können wir dein Plugin ja verwenden oder ggf. anpassen, so dass mehr Nutzer was davon haben. Wenn du nichts dagegen hast...

[loeserman]

Klaro habe ich nichts dagegen!
Habe ein neues Thema aufgemach
Plugin: Viessmann Heizung auslesen (Vitodens200 / 300 mit Vitotronic 200 (HO1))

Und ja, mein Plugin redet direkt mit der USB Schnittstelle.

[fhartlieb]

...

Lasse ich den Übergabeparameter "busmonitor" ausgeben, so erhalte ich "logger". Also korrekt. Mit "logger" geht aber die if Abfrage (rot markiert) sofort auf TRUE und setzt den Logger auf info und geht entsprechend nicht in den Else Zweig, der den extra Logger einschalten würde.

Was mache ich nun wieder falsch? Der Parameter kann es eigentlich nicht sein, da dieser ja explizit so abgefragt wird im Else Zweig. Aber den erreiche ich dadurch erst gar nicht, wenn ich nicht das Plugin selbst ändere. Irgendwie checke ich da die Funktion "self.to_bool" nicht.

Vielleicht kannst Du mir hier noch kurz einen Tipp geben. Dann lasse ich euch auch in Ruhe mit dem Logger Kram.

Danke und Gruß
loeserman

Hallo Loeserman,
konntest du das Problem inzwischen lösen? Ich bekomme auch nicht das extra-Log-file aktiviert