Neues Database Plugin

[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]

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]

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 : 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]

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]

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]

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.

[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]

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

[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.

[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

[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....

[wvhn]

Ich denke, wir haben hier zwei Probleme (gehabt ? ):

• die Beobachtung von Onkelandy zeigt negative durations im Bereich weniger 100 Miikrosekunden. Wenn man sich ansieht, an wie vielen Stellen in shNG und SV aktuelle Zeitstempel mit einer Funktion ähnlich
  

  	timestamp = new Date(now)

  generiert werden und dann unterschiedliche Rechenzeiten in den jeweiligen Modulen annehmen, dann müssen zwangsläufig solche Differenzen auftreten. Abhilfe wäre aus meiner Sicht möglich mit einer Rundung auf volle Sekunden - oder meinetwegen 100 ms.
• das zweite Problem mit wesentlich größeren negativen durations und den durations mit Wert "None" ist ja gerade in Bearbeitung. Die von aschwith gezeigten Abweichungen scheinen mir zu groß, um "nur" aus der Wiederherstellung der Attribute zu stammen.
  Dazu ein Ansatz: grundsätzlich steht der aktuelle Wert jedes items immer mit duration=None in der Datenbank, bis der nächste Wert herein kommt und die duration berechnet werden kann. IMHO muss nochmal geprüft werden, inwiefern nach Abstürzen, Neustarts oder Timeouts wirklich sicher gestellt wird, dass durations nachgetragen werden (lieber falsche als gar keine).

Wenn wir mit dem Thema durch sind, müssen wir uns nochmal die Werte ansehen, die künstlich hinten an die series angehängt werden. Siehe diesen Beitrag und (viele) fortfolgende.

[aschwith]

Hallo wvhn ,

Du hast recht. Mir waren die Differenzen bei Onkelandy im Milisekundenbereich nicht aufgefallen. Es kann sich wirklich um zwei Ursachen handeln. Bei mir tritt das Problem momentan allerdings nicht auf, deshalb kann ich nicht weiter Debuggen.
Dein zweiter Aspekt ist auch korrekt: Es ist normal, dass der aktuelle Wert in der Datenbank mit Duration=None gehalten wird. In der Tat läuft hier manchmal was schief, so dass diese Werte in der Datenbank verbleiben. Solange der Messwert 0 ist fällt das häufig nicht auf. Ist diese Wert aber ungleich Null, fällt das z.B. beim Aufintegrieren durch völlig überhöhte Werte auf.
Ich nutze z.B. das 'integrate' feature des database plugins, um Momentanleistungen in der DB zu Verbrächen aufzuintegrieren. Der SQL Code dazu findet sich im database plugin, Zeile 705:

'integrate': 'MIN(time), SUM(val_num * duration)',

Dort schlagen die Durations=None leider als echte Werte zu. Kennt jemand einen Weg, diese None Durations im SQL Format bei der Summenbildung auszuschließen?

[aschwith]

wvhn zu Deinem anderen Thema für series mit Start und Endzeitpunkt in der Zukunft: Diese Option für Abfragen in der Zukunft hatten wir hier in der Community mal vor einigen Jahren mit eingebaut. Usecase war unter anderem die Möglichkeit, z.B. Vorhersagen für z.B. Bewässerungssysteme zu berechnen, in die Datenbank zu schreiben und dann plotten zu können. Alles für Zeitpunkte mit Start und Endzeitpunkten in der Zukunft.

VG