Neues Database Plugin

[aschwith]

Msinn : Ich sehe gerade im Log, dass Du nicht nur das log_change Verhalten angepasst hast, sondern auch noch Änderungen für das Wiederherstellen der Atrribute prev_change eingestellt hast. Das sieht sehr gut aus.

Die Reihenfolge, in der vorher die Attribute mit self.shtime.now() wiederhergestellt wurden, haben es ermöglicht, dass dort negative Durations berechnet worden sind.

Ich bin gespannt, ob das Problem nun behoben ist. Ich beobachte das Verhalten weiterhin mit entsichertem Logger....

[aschwith]

Msinn : Top, danke. Das wird mir weiterhelfen. Deine Anpassungen funktionieren. Sieht momentan alles gut und richtig aus.

War ja klar, bei mir tauchen aktuell keine negativen Durations in der Datenbank auf. Ich warte, bis das Problem das nächste Mal auftaucht. Dein Log (log_change) ist locked and loaded. VG

[Msinn]

aschwith Ich habe im develop die lib.item so erweitert, dass wenn das Attribut log_change gesetzt ist, auch während de Initialisierungsphase das setzen des Item Wertes geloggt wird. Das betrifft das setzen des Wertes

• über das initial_value Attribut
• durch lesen eines Cache Wertes
• durch das database: init Attribut

Jetzt müsste es Dir bei der Suche helfen können.

[Msinn]

Schau einfach mal ins Log File (mit cat, tail oder nano)

[Onkelandy]

Hm, ich hab das jetzt so konfiguriert, nur dass ich statt q21 "bewegung" geschrieben hab. Bekomme ein 0B File und folgenden Fehler:

​​​​​​​2020-06-27 20:51:38 WARNING __main__ -------------------- Init SmartHomeNG 1.7.2.master (3828810e) --------------------
2020-06-27 20:51:38 WARNING __main__ Running in Python interpreter 'v3.7.3 final' on Linux-4.19.118-v7+-armv7l-with-debian-10.
2020-06-27 20:59:40 ERROR modules.admin.api_loggers Logger Exception: dictionary changed size during iteration
Traceback (most recent call last):
File "/usr/local/smarthome/modules/admin/api_loggers.py", line 103, in get_active_loggers
for l in logging.Logger.manager.loggerDict:
RuntimeError: dictionary changed size during iteration
2020-06-27 20:59:40 WARNING modules.admin.api_loggers REST_dispatch_execute: None: 8

[Msinn]

Kannst Du das bestätigen?

Nein, muss ich rein schauen.

Das Logging ist zu dem Zeitpunkt auf jeden Fall initialisiert. Da das setzen der Werte bei der Initialisierung aber z.T. auf anderem Wege erfolgt als die normalen Changes, kann es sein, dass das nicht an den Logger geschickt wird. Das würde ich bei Gelegenheit ändern.

[aschwith]

Danke Msinn für den Vorschlag. Ich habe es gerade ausprobiert. Leider scheint der Logger aber zu spät initialisiert zu werden. Die Änderungen durch smarthomeNG init und database init werden nicht mit geloggt. Kannst Du das bestätigen? Damit hilft uns das hier erstmal nicht weiter. Danke trotzdem.

[Msinn]

aschwith, Onkelandy Ich habe noch eine Idee wie ihr euch dem Problem nähern könnt.

Seit einiger Zeit (seit v1.5 oder v1.6) gibt es im Core die Möglichkeit Item Änderungen zu loggen. Ich mache das mit Items, bei denen ich eine History sehen möchte, wer wann das Item verändert hat.

Dazu in der etc/logging.yaml einen weiteren Logger in einrichten. Ich habe den Logger mit einem eigegen Formatter in ein eigenes Logfile schreiben lassen (notwendig ist nur der Logger):

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

handlers:
    ...
    shng_items_file:
        class: logging.handlers.TimedRotatingFileHandler
        formatter: shng_items
        when: midnight
        backupCount: 7
        filename: ./var/log/q21-items.log
        encoding: utf8

loggers:
    ...
    items.q21-items:
        handlers: [shng_items_file]
        level: INFO

Das jeweilige Item muss nur um das Attribute log_change erweitert werden, wo der Name des Loggers festgelegt wird, in den die Änderungen geloggt werden sollen.

            raffstore_pos:
                type: num
                enforce_updates: 'true'
                knx_dpt: 5001
                knx_send: 5/4/9
                knx_cache: 5/5/9
                log_change: q21-items

Das erzeugt bei mir ein Log das folgendermaßen aussieht:

2020-06-27 03:57:37 INFO     item         Item Change: wohnung.schlafen.raffstore_ost.lamellen_pos = 100  -  caller: Logic
2020-06-27 03:57:37 INFO     item         Item Change: wohnung.schlafen.raffstore_nord.lamellen_pos = 100  -  caller: Logic
2020-06-27 03:57:38 INFO     item         Item Change: wohnung.schlafen.raffstore_ost.raffstore_pos = 67.8  -  caller: knx (1.1.223:ga=5/5/9), dest: 5/5/9
2020-06-27 03:57:38 INFO     item         Item Change: wohnung.schlafen.raffstore_ost.raffstore_pos_byte = 67.8  -  caller: knx (1.1.223:ga=5/5/9), dest: 5/5/9
2020-06-27 03:57:38 INFO     item         Item Change: wohnung.schlafen.raffstore_nord.raffstore_pos = 95.7  -  caller: knx (1.1.223:ga=5/5/10), dest: 5/5/10
2020-06-27 03:57:38 INFO     item         Item Change: wohnung.schlafen.raffstore_nord.raffstore_pos_byte = 95.7  -  caller: knx (1.1.223:ga=5/5/10), dest: 5/5/10
2020-06-27 04:27:37 INFO     item         Item Change: wohnung.hauswirtschaft.abluft.stufe1 = True  -  caller: Logic 'abluft'
2020-06-27 04:27:37 INFO     item         Item Change: wohnung.hauswirtschaft.abluft.status = 1  -  caller: Eval (wohnung.hauswirtschaft.abluft.stufe1)
2020-06-27 11:14:11 INFO     item         Item Change: wohnung.bad.abluft.stufe1 = True  -  caller: Logic 'abluft'
2020-06-27 11:14:11 INFO     item         Item Change: wohnung.bad.abluft.status = 1  -  caller: Eval (wohnung.bad.abluft.stufe1)
2020-06-27 11:35:20 INFO     item         Item Change: wohnung.bad.abluft.stufe1 = False  -  caller: Logic 'abluft'
2020-06-27 11:35:20 INFO     item         Item Change: wohnung.bad.abluft.status = 0  -  caller: Eval (wohnung.bad.abluft.stufe1)

VIeleicht hilft euch ein solches Logging ja bei der Eingrenzung weiter.

[aschwith]

Msinn : Du hast recht. Mit den von Dir erklärten Randbedingungen macht ein Sortieren der run() Methoden keinen Sinn.

Nochmal zum Enocean plugin: Hier wird in der --init() noch kein Thread erzeugt, sondern nur das serielle Interface geöffnet und die Locking Mechanismen für einen Thread erzeugt. Der eigentliche Thread (enocean-start-up) wird erst in der run() erzeugt. Das pollen des serial interfaces beginnt auch erst in der run().

[Msinn]

Können wir irgendwie sicherstellen, dass die database run methode vor allen anderen run methoden aufgerufen wird?

Wozu sollte das gut sein? Die Initialisierung der Items bei ``database: init`` geschieht bereits vorher. Die erfolgt in der parse_item() Methode, also bevor die run() Methoden der Plugins aufgerufen werden.

Ich habe mal kurz in das enocean Plugin geschaut. Mir ist aufgefallen, dass der Thread zum Handling bereits in der __init__() Methode erzeugt wird, nicht erst in der run() Methode. Ob das erzeugen des Threads bereits zum Empfang von Daten führt habe ich nicht geprüft.

[aschwith]

Msinn Danke für den Hinweis. Allerdings habe ich mir gerade das Enocean plugin angeschaut: Hier werden vor dem Ausführen der run Methode keine Items zugewiesen. Können wir irgendwie sicherstellen, dass die database run methode vor allen anderen run methoden aufgerufen wird?

Onkelandy: Bei Dir tritt das Problem ja mit dem KNX plugin auf. Was mich bei Deiner item config verwundert ist, dass das Problem auch mit einem database: yes auftritt. Ich konnte es bei mir bisher nur mit einem database: init reproduzieren.

[Msinn]

Das könnte evtl. sein. Diverse Plugins sind nicht ganz sauber implementiert. Das Initialisieren der Items findet statt bevor die ganzen run() Methoden aufgerufen werden. Wenn einzelne Plugins jedoch vorher Daten verarbeiten (empfangen und Items zuweisen), kann das zu Nebenwirkungen führen.

[aschwith]

Deine Vermutung ist nicht schlecht. Bei mir tritt das Problem aber z.B. mit diesem Item auf:

power:
type: num
value: 0
enocean_rx_key: VALUE
database: init
enforce_updates: True
visu_acl: ro

Tritt also auch ohne contab auf. Ich habe eher das database init (und damit das verbundene Database Caching) im Verdacht. Kann das Problem vielleicht mit der Reihenfolge beim Start zusammenhängen? Also Beispiel:
1) SmarthomeNG wird gestartet.
2) Ein plugin (bei mir Enocean) wird gestartet und aktualisiert ein item. Der vorherige Wert wird im previous value abgespeichert.
3) Das Database plugin wird gestartet und stellt über den Database Caching mechanismus den previous Wert wieder her? Irgendwie muss dabei der Zeitstempel falsch berechnet werden. Wie ist mir noch nicht klar.

Es ist aber schonmal gut, dass wir sehen, dass es dort ein Problem gibt (was nicht nur bei mir auftritt )

[Onkelandy]

2020-06-24 23:45:32 WARNING plugins.database Negative duration: start: 1593034968604, end 1593034968603, prevChange: 2020-06-24 23:42:48.604280+02:00, lastChange: 2020-06-24 23:42:48.603951+02:00, item: og bewegung
2020-06-24 23:45:32 WARNING plugins.database Negative duration: start: 1593034968604, end 1593034968603, prevChange: 2020-06-24 23:42:48.604280+02:00, lastChange: 2020-06-24 23:42:48.603951+02:00, item: og bewegung
2020-06-24 23:45:32 WARNING plugins.database Negative duration: start: 1593034968604, end 1593034968603, prevChange: 2020-06-24 23:42:48.604280+02:00, lastChange: 2020-06-24 23:42:48.603951+02:00, item: og bewegung
2020-06-24 23:45:32 WARNING plugins.database Negative duration: start: 1593034968604, end 1593034968603, prevChange: 2020-06-24 23:42:48.604280+02:00, lastChange: 2020-06-24 23:42:48.603951+02:00, item: og bewegung

Das item ist ein normales Item, das von KNX Items getriggert wird.

        type: bool
        visu_acl: ro
        database: yes
        influxdb: yes
        crontab: init
        enforce_updates: True
        cycle: 60
        name: og bewegung
        eval: 1 if (sh.bewegung.og.kueche() + sh.bewegung.og.abgang() + sh.bewegung.og.podest()) >= 1 else 0
        eval_trigger:
          - bewegung.og.kueche
          - bewegung.og.abgang
          - bewegung.og.mensch
          - bewegung.og.podest

Möglicherweise vertragen sich hier crontab: init und database: yes nicht so ganz..?

[aschwith]

Onkelandy : Interessant. Bei welchen items taucht das bei Dir auf? Ich habe es bei mir bis jetzt ausschließlich bei Enocean items gesehen.

Wenn Du im Database WebIf nachschaust, solltest Du bei dem entsprechenden Item dort auch die negativen Durations sehen. Die machen natürlich dann Probleme, wenn man Einschaltdauern berechnet oder integriert. VG