HTTP Umstellung V1 => V3

[udo1toni]

Määp- Das kann aber nicht stimmen. Die Logs sind nicht in chronologischer Reihenfolge.

[wosch]

Ah jo, oben ist openhab-log unten event-log Sorry, das hätte ich deutlich(er) machen können...
Beim event-log habe ich der Übersichtlichkeit wegen 2 oder 3 Zeilen rausgeschmissen, da zwei andere items zeitlich dazwischen kamen.

[udo1toni]

Ja, aber das passt halt trotzdem nicht. Du musst schon die Ereignisse in der chronologischen Reihenfolge betrachten. Wenn die Rule ausgibt, dass sie ein Komma ersetzt hat, interessiert mich nicht, was vorher ins Item geschrieben wurde,

[wosch]

Sorry, ich stehe total auf dem Schlauch
Ich versuche es nochmal mit einem neuen log und packe dieses Mal mehr Zeilen vorher und nachher rein:

event-log:

Code: Alles auswählen

2021-09-08 14:35:55.179 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LWZHochdruck_IN' changed from 22,82 to 23,20
[...]
2021-09-08 14:35:55.210 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LWZHochdruck_OUT' changed from 2320 to 23.2
[...]
2021-09-08 14:36:59.520 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LWZHochdruck_OUT' changed from 23.2 to 2320
[...]
2021-09-08 14:37:59.513 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LWZHochdruck_OUT' changed from 2320 to 2340
2021-09-08 14:37:59.513 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LWZHochdruck_IN' changed from 23,20 to 23,40
[...]
2021-09-08 14:37:59.560 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LWZHochdruck_OUT' changed from 2340 to 23.4

openhab-log:

Code: Alles auswählen

2021-09-08 14:34:59.602 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - Triggerndes Item: LWZHochdruck_IN
2021-09-08 14:34:59.602 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - Triggerndes Item: 22,82
2021-09-08 14:34:59.618 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - Item Out: LWZHochdruck_OUT
2021-09-08 14:34:59.618 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - stringValue: 22.82 Value: 22.82
[...]
2021-09-08 14:35:55.210 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - Triggerndes Item: LWZHochdruck_IN
2021-09-08 14:35:55.210 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - Triggerndes Item: 23,20
2021-09-08 14:35:55.210 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - Item Out: LWZHochdruck_OUT
2021-09-08 14:35:55.210 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - stringValue: 23.20 Value: 23.2
[...]
2021-09-08 14:37:59.544 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - Triggerndes Item: LWZHochdruck_IN
2021-09-08 14:37:59.544 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - Triggerndes Item: 23,40
2021-09-08 14:37:59.560 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - Item Out: LWZHochdruck_OUT
2021-09-08 14:37:59.560 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - stringValue: 23.40 Value: 23.4

Anmerkung: [...] beschreibt weggelassene Zeilen, die nichts mit dem Item LWZHochdruck zu tun haben. Ist zwischen Zeilen kein [...] stehen die auch genau so in den logs.

Was mir auffällt: Um 14:36:59.520 ändert sich das Number-Item (_OUT) - hier auf den falschen Wert ohne Punkt - obwohl die rule gar nicht durchläuft! Ich habe das mehrmals überprüft, es gibt im openhab-log keine Einträge zu diesem Zeitpunkt und zu diesem Item!
Auch um 14:37:59.513 ändert sich das _OUT-Item ohne Durchlaufen der rule. Exakt zeitgleich ändert sich das _IN-Item, wodurch die rule dann getriggert wird und daraufhin kurze Zeit später auch der Wert in _OUT wieder passt.

D.h. die rule selbst passt. Nur ändert sich das Number-Item (_OUT) selbstständig zwischendurch?! Wie kann das denn sein?
Ich habe gerade nochmal alle rules durchgeschaut - es wird definitiv nirgends sonst auf LWZ-Items getriggert. Abgesehen davon, dass dann ja auch in den logs auftauchen müsste...

[udo1toni]

So, jetzt schauen wir uns das mal korrekt sortiert an...

Code: Alles auswählen

2021-09-08 14:34:59.602 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - Triggerndes Item: 22,82
2021-09-08 14:34:59.602 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - Triggerndes Item: LWZHochdruck_IN
2021-09-08 14:34:59.618 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - Item Out: LWZHochdruck_OUT
2021-09-08 14:34:59.618 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - stringValue: 22.82 Value: 22.82
2021-09-08 14:35:55.179 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LWZHochdruck_IN' changed from 22,82 to 23,20
2021-09-08 14:35:55.210 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - Item Out: LWZHochdruck_OUT
2021-09-08 14:35:55.210 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - Triggerndes Item: 23,20
2021-09-08 14:35:55.210 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - Triggerndes Item: LWZHochdruck_IN
2021-09-08 14:35:55.210 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - stringValue: 23.20 Value: 23.2
2021-09-08 14:35:55.210 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LWZHochdruck_OUT' changed from 2320 to 23.2
2021-09-08 14:36:59.520 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LWZHochdruck_OUT' changed from 23.2 to 2320
2021-09-08 14:37:59.513 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LWZHochdruck_IN' changed from 23,20 to 23,40
2021-09-08 14:37:59.513 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LWZHochdruck_OUT' changed from 2320 to 2340
2021-09-08 14:37:59.544 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - Triggerndes Item: 23,40
2021-09-08 14:37:59.544 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - Triggerndes Item: LWZHochdruck_IN
2021-09-08 14:37:59.560 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - Item Out: LWZHochdruck_OUT
2021-09-08 14:37:59.560 [INFO ] [nhab.core.model.script.LWZKommaPunkt] - stringValue: 23.40 Value: 23.4
2021-09-08 14:37:59.560 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LWZHochdruck_OUT' changed from 2340 to 23.4

Was mir dabei auffällt, ist, dass OUT gesetzt wird, bevor die Rule überhaupt läuft. Das deutet darauf hin, dass Du zwei Rules hast, die sich um diese Items kümmern.

[wosch]

Ja, das war für mich auch naheliegend. Aber nein, ich habe nur die eine rule!
Es lief ja auch vorher, ich habe im VSC auch nichts geändert - alles was ich gemacht habe (Update, bindings usw. neu installiert, ...) lief außerhalb von VSC - und nur da habe ich überhaupt rules angelegt!

Edit: auch das nochmals im Main UI überprüft: alle rules dort sind mit dem Schloss gekennzeichnet (==> VSC). Es taucht auch in keiner anderen rule etwas von den Wärmepumpen-Items auf.

[udo1toni]

Du kannst das einfach verifizieren, indem Du die Rule mal stilllegst (z.B., indem Du in der Rule als erste Zeile nach dem then ein return; einfügst:

Code: Alles auswählen

[...]
then
   return;
   [...]

[wosch]

Im openhab.log taucht dann nichts mehr auf ==> die rule ist also stillgelegt.

Allerdings ändern sich die _IN und _OUT-Items trotzdem wild laufend weiter (event-log):

Code: Alles auswählen

2021-09-08 15:50:57.556 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LWZAussentemperatur_OUT' changed from 232 to 231
2021-09-08 15:50:57.558 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LWZAussentemperatur_IN' changed from 23,2 to 23,1
2021-09-08 15:50:57.563 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LWZRLTemperatur_OUT' changed from 288 to 287
2021-09-08 15:50:57.563 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LWZRLTemperatur_IN' changed from 28,8 to 28,7
2021-09-08 15:50:57.575 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LWZWarmwasserIsttemperatur_OUT' changed from 463 to 462
2021-09-08 15:50:57.576 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'LWZWarmwasserIsttemperatur_IN' changed from 46,3 to 46,2

Kann es sein, dass da noch irgendwo Überbleibsel von vor dem Update / von vor der Neuinstallation der ganzen Addons herumschwirren? Würde ich das mit Löschen des Cache und des temp-Ordners in den Griff bekommen?

[udo1toni]

Der nächste Schritt wäre für mich, das OUT-Item anders zu benennen. Das führt dann eventuell dazu, dass eine NullPointer Exception auftritt (nämlich, wenn der marodierende Code versucht, auf das nicht mehr existente Item zu schreiben) Damit kann man eingrenzen, wo der Code herkommt.

Alternativ kannst Du natürlich auch die Konfiguration sichern, das System platt machen und anschließend die Konfiguration Stück für Stück wiederherstellen. Stück für Stück -> Datei für Datei... nicht einfach restore aufrufen, sondern die Dateien einzeln an die entsprechende Stelle packen.

[wosch]

Puh, ich habe jetzt mal alle _OUT-Items in _OUT2 umbenannt und der Gruppe gOUT2 zugeordnet. Die rule entsprechend angepasst. Damit sollte eine etwaige "falsche" rule - sofern es diese gibt, ins Leere laufen. Zumindest dürften dann meine _OUT2-Items davon dann nicht mehr berührt sein.

Allerdings: ich habe nun das selbe Phänomen mit den OUT2-Items... Wie kann das denn sein?!

Edit: Moment mal! Ich habe die OUT-Items in VSC angelegt und dort einfach nur umbenannt (OUT2) - warum habe ich die OUT-Items dann überhaupt noch?

Edit2: nach einem Neustart sind die _OUT-Items weg, es sind nur noch die _OUT2-Items da. Diese allerdings wieder mal richtig mal falsch (=verlieren den Punkt). Zusätzlich kommt in der Karaf-Konsole folgende Meldung:

Code: Alles auswählen

openhab> Exception in thread "Thread-15" java.lang.IllegalStateException: Executor has been shut down
        at org.apache.sshd.common.util.ValidateUtils.createFormattedException(ValidateUtils.java:213)
        at org.apache.sshd.common.util.ValidateUtils.throwIllegalStateException(ValidateUtils.java:207)
        at org.apache.sshd.common.util.ValidateUtils.checkState(ValidateUtils.java:184)
        at org.apache.sshd.common.util.threads.NoCloseExecutor.execute(NoCloseExecutor.java:100)
        at java.base/sun.nio.ch.AsynchronousChannelGroupImpl.executeOnPooledThread(AsynchronousChannelGroupImpl.java:188)
        at java.base/sun.nio.ch.Invoker.invokeIndirectly(Invoker.java:213)
        at java.base/sun.nio.ch.Invoker.invokeIndirectly(Invoker.java:314)
        at java.base/sun.nio.ch.WindowsAsynchronousServerSocketChannelImpl$AcceptTask.failed(WindowsAsynchronousServerSocketChannelImpl.java:286)
        at java.base/sun.nio.ch.Iocp$EventHandlerTask.run(Iocp.java:389)
        at java.base/java.lang.Thread.run(Thread.java:829)