openHAB2 und knx-Binding: träge Reaktion

[migal]

Hallo zusammen,

folgender Herausforderung stehe ich gegenüber:

Im Haus läuft und funktioniert ein openHAB1 mit knx-Binding auf einem RPi 2. Ich würde jetzt ganz gerne auf openHAB2 umsteigen.

Testweise habe ich openHAB2 auf einem RPi3 installiert (openHABian) und die openHAB1-files (items, sitemap, rules etc) eingespielt.
Das Ergebnis ist insoweit unbefriedigend, als daß jede Aktion stark verzögert ausgeführt wird. Die Verzögerung liegt zwischen wenigen Sekunden bis zu einer Minute, und kommt immer.
Ich habe dann items und sitemap auf ein Minimum (drei Schalter) reduziert, alle rules rausgenommen, keine persistence mehr - leider ohne Erfolg, die Verzögerung bleibt.

Mit dem Pi2 und openHAB1 funktioniert es super, mit klick auf die Maus schaltet sofort die Leuchte oder fährt der Rolladen. Mit dem Pi3 und openHAB2 ... nicht

Die knx.cfg sollte ok sein (IPs und busaddresse eingetragen, ignorelocalevents=true, type=TUNNEL). Das knx-Binding hatte ich mit PaperUI installiert (binding-knx1 - 1.9.0).

Hat jemand eine Idee, wo hier das Problem liegen könnte?

[zaphood]

Hi Migal,

das Verhalten habe ich hier mit OH2 auch. Jeder KNX Event generiert 2 Replys (sieht man auf der Konsole). Wenn deine Anbindung über Tunnel läuft, generiert das da Traffic und der bremst.
Bei mir hat die Umstellung auf ROUTER Mode das Problem etwas entspannt. Die Meldungen sind noch da, aber OH2 scheint das (da es keine ACK Pakete bei ROUTER gibt) nicht mehr so zu bremsen.

Cu
Frank

[migal]

Hi Frank,

danke für die Info. Das werde ich mal testen.

Ich habe gerade das Problem mit OH1 auch. Verzögerung, doppelte Meldungen etc. Das gab es vorher monatelang nicht, es trat erst auf, nachdem ich mit OH2 rumgespielt hatte. Mal sehen, ob ich die Jung IP-Schnittstelle resetten kann.

[udo1toni]

Habt ihr dem knx Binding auch eine (freie) Busadresse gegeben? Ohne diese ist ignorelocalevents wirkungslos.

[migal]

Ja, ich habe 15.15.255 vergeben, die war laut ETS nicht vergeben.
Mich wundert eben, daß die vorher noch völlig stressfrei funktionierende Konfiguration sich plötzlich auch komisch verhält.

[migal]

Reset der IP-Schnittstelle, erneutes Prüfen der Bussadresse hatte keine Veränderung zur Folge.
Den Modus ROUTER kann ich leider nicht nutzen, vermutlich unterstützt meine Schnittstelle den nicht.

[migal]

Im log sehe ich jede Menge warnings, im Prinzip löst das jede Aktion aus. Was mir auffällt sind die response timeouts - kann da jemand etwas mehr herauslesen?



2017-01-28 15:52:18.837 [WARN ] [.binding.knx.internal.bus.KNXBinding] - Value 'OFF' could not be sent to the KNX bus using datapoint 'command DP 1/1/62 LiOGGast2, DPT main 0 id 1.001, low priority' - retrying one time: no confirmation reply received for L-Data.req from 15.15.16 to 1/1/62, low priority hop count 6 repeat tpdu 00 80
2017-01-28 15:52:18.839 [WARN ] [tuwien.auto.calimero ] - KNXnet/IP Tunneling 192.168.1.181:3671: response timeout waiting for confirmation
tuwien.auto.calimero.exception.KNXTimeoutException : no confirmation reply received for L-Data.req from 15.15.16 to 1/1/62, low priority hop count 6 repeat tpdu 00 80
at tuwien.auto.calimero.knxnetip.ClientConnection.doE xtraBlockingModes(ClientConnection.java:236)[209rg.openhab.binding.knx:1.9.0]
at tuwien.auto.calimero.knxnetip.ConnectionBase.send( ConnectionBase.java:269)[209rg.openhab.binding.knx:1.9.0]
at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send( KNXnetIPTunnel.java:149)[209rg.openhab.binding.knx:1.9.0]
at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend( KNXNetworkLinkIP.java:263)[209rg.openhab.binding.knx:1.9.0]
at tuwien.auto.calimero.link.AbstractLink.send(Abstra ctLink.java:304)[209rg.openhab.binding.knx:1.9.0]
at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendReq uestWait(KNXNetworkLinkIP.java:240)[209rg.openhab.binding.knx:1.9.0]
at tuwien.auto.calimero.process.ProcessCommunicatorIm pl.write(ProcessCommunicatorImpl.java:466)[209rg.openhab.binding.knx:1.9.0]
at tuwien.auto.calimero.process.ProcessCommunicatorIm pl.write(ProcessCommunicatorImpl.java:438)[209rg.openhab.binding.knx:1.9.0]
at org.openhab.binding.knx.internal.bus.KNXBinding.wr iteToKNX(KNXBinding.java:149)[209rg.openhab.binding.knx:1.9.0]
at org.openhab.binding.knx.internal.bus.KNXBinding.in ternalReceiveCommand(KNXBinding.java:112)[209rg.openhab.binding.knx:1.9.0]
at org.openhab.core.binding.AbstractBinding.receiveCo mmand(AbstractBinding.java:97)[176rg.openhab.core.compat1x:2.0.0]
at org.openhab.core.events.AbstractEventSubscriber.ha ndleEvent(AbstractEventSubscriber.java:42)[176rg.openhab.core.compat1x:2.0.0]
at org.apache.felix.eventadmin.impl.handler.EventHand lerProxy.sendEvent(EventHandlerProxy.java:415)[6rg.apache.karaf.services.eventadmin:4.0.8]
at org.apache.felix.eventadmin.impl.tasks.HandlerTask .run(HandlerTask.java:90)[6rg.apache.karaf.services.eventadmin:4.0.8]
at java.util.concurrent.Executors$RunnableAdapter.cal l(Executors.java:511)[:1.8.0_121]
at java.util.concurrent.FutureTask.run(FutureTask.jav a:266)[:1.8.0_121]
at java.util.concurrent.ThreadPoolExecutor.runWorker( ThreadPoolExecutor.java:1142)[:1.8.0_121]
at java.util.concurrent.ThreadPoolExecutor$Worker.run (ThreadPoolExecutor.java:617)[:1.8.0_121]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
2017-01-28 15:52:21.838 [WARN ] [tuwien.auto.calimero ] - KNXnet/IP Tunneling 192.168.1.181:3671: response timeout waiting for confirmation
tuwien.auto.calimero.exception.KNXTimeoutException : no confirmation reply received for L-Data.req from 15.15.16 to 1/2/120, low priority hop count 6 repeat tpdu 00 00
at tuwien.auto.calimero.knxnetip.ClientConnection.doE xtraBlockingModes(ClientConnection.java:236)[209rg.openhab.binding.knx:1.9.0]
at tuwien.auto.calimero.knxnetip.ConnectionBase.send( ConnectionBase.java:269)[209rg.openhab.binding.knx:1.9.0]
at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send( KNXnetIPTunnel.java:149)[209rg.openhab.binding.knx:1.9.0]
at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend( KNXNetworkLinkIP.java:263)[209rg.openhab.binding.knx:1.9.0]
at tuwien.auto.calimero.link.AbstractLink.send(Abstra ctLink.java:304)[209rg.openhab.binding.knx:1.9.0]
at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendReq uestWait(KNXNetworkLinkIP.java:240)[209rg.openhab.binding.knx:1.9.0]
at tuwien.auto.calimero.process.ProcessCommunicatorIm pl.readFromGroup(ProcessCommunicatorImpl.java:486)[209rg.openhab.binding.knx:1.9.0]
at tuwien.auto.calimero.process.ProcessCommunicatorIm pl.read(ProcessCommunicatorImpl.java:422)[209rg.openhab.binding.knx:1.9.0]
at org.openhab.binding.knx.internal.bus.KNXBindingDat apointReaderTask.readFromKNXBus(KNXBindingDatapoin tReaderTask.java:99)[209rg.openhab.binding.knx:1.9.0]
at org.openhab.binding.knx.internal.bus.KNXBindingDat apointReaderTask.run(KNXBindingDatapointReaderTask .java:67)[209rg.openhab.binding.knx:1.9.0]

[zaphood]

Hm, also das schaut bei mir anders aus. IGNORELOCALEVENT zieht bei mir, da kommt auch eine entsprechende Meldung über ignorierte Events. Mir scheint, dein Problem ist ein anderes als das (wohl noch bekannte) Problem mit doppelten Events des KNX 1.9 Bindings unter OpenHab2.

Mir fällt der Teil hier auf:
2017-01-28 15:52:18.839 [WARN ] [tuwien.auto.calimero ] - KNXnet/IP Tunneling 192.168.1.181:3671: response timeout waiting for confirmation
tuwien.auto.calimero.exception.KNXTimeoutException : no confirmation reply received for L-Data.req from 15.15.16 to 1/1/62, low priority hop count 6 repeat tpdu 00 80

OpenHab hat 15.15.255, die fehlende Confirmation wird aber von 15.15.16 erwartet. Das dürfte die Tunneladresse des Routers sein. Fragt sich jetzt, ob das der Tunnel für OpenHab oder der für die ETS ist?

Warum gibts da einen "hop count 6"? Hop's kenne ich aus dem Routing, aber bei Tunnelverbindungen irritiert mich das doch etwas. Per ETS kannst du auf den Bus zugreifen? Was sagt denn der Gruppenmonitor bei der Kommunikation?

[migal]

Ich hatte noch mit veränderten Busadress-Einträgen in der config experimentiert und jedesmal die oben schon geposteten log-Einträge bekommen. Die fehlende confirmation wird von der Adresse erwartet, die in der config eingetragen ist.
Ich konnte mit der ETS aber immer ohne Probleme auf den Bus zugreifen. Der Gruppenmonitor zeigte auch keine Auffälligkeiten zB bei Betätigung von Tastern.

Aktuell habe ich aber ein Thema mit der physikalischen Adresse der IP Schnittstelle und den Tunnel-Adressen. Ich hatte die IP Schnittstelle zurückgesetzt. Nun hat sie eine andere physikalische Adresse und ich kann mit der ETS nicht mehr darauf zugreifen. Das Problem muss ich erst lösen ...

[zaphood]

Also dann würde ich den Fehler primär mal in Richtung Schnittstelle suchen gehen und erst sekundär bei OpenHab (das hat sicher seinen Anteil daran, aber in dem konkreten Fall muss man das mal der Reihe nach aufdröseln)....

[migal]

Schnittstelle ist wieder ok.
Phys. Adresse der Schnittstelle 1.1.111
Die 4 Tunnel die sie hat haben 1.1.251 bis 1.1.254
In der openhab.cfg habe ich knx:busaddr=1.1.255

Im Gruppenmonitor der ETS keine Auffälligkeiten.


Das OH Log sieht nun beispielhaft so aus:

15:01:53.441 [DEBUG] [.KNXBindingDatapointReaderTask:60 ] - Autorefresh: Waiting for new item in reader queue
15:01:53.443 [DEBUG] [.KNXBindingDatapointReaderTask:62 ] - Autorefresh: got new item KoEGHaustuer in reader queue
15:01:53.444 [DEBUG] [.KNXBindingDatapointReaderTask:66 ] - Autorefresh: Trying to read from KNX bus: state DP 7/1/15 KoEGHaustuer, DPT main 0 id 1.019, low priority
15:01:53.445 [DEBUG] [.KNXBindingDatapointReaderTask:97 ] - Autorefresh: Sending read request to KNX for item 'KoEGHaustuer' DPT '1.019'
15:01:53.532 [DEBUG] [.b.knx.internal.bus.KNXBinding:184 ] - Received groupWrite Event.
15:01:56.449 [WARN ] [.KNXBindingDatapointReaderTask:112 ] - Autorefresh: Cannot read value for item 'KoEGHaustuer' from KNX bus: no confirmation reply received for L-Data.req from 1.1.255 to 7/1/15, low priority hop count 6 repeat tpdu 00 00: timeout
15:01:56.457 [WARN ] [.KNXBindingDatapointReaderTask:139 ] - Autorefresh: Remaining retries for address '7/1/15' = '1'
15:01:56.459 [DEBUG] [.KNXBindingDatapointReaderTask:72 ] - Autorefresh: DatapointReaderTask Waiting 50 msecs to prevent KNX bus overload
15:01:56.503 [WARN ] [tuwien.auto.calimero :49 ] - KNXnet/IP Tunneling 192.168.1.181:3671: response timeout waiting for confirmation
tuwien.auto.calimero.exception.KNXTimeoutException : no confirmation reply received for L-Data.req from 1.1.255 to 7/1/15, low priority hop count 6 repeat tpdu 00 00
at tuwien.auto.calimero.knxnetip.ClientConnection.doE xtraBlockingModes(ClientConnection.java:236) ~[na:na]
at tuwien.auto.calimero.knxnetip.ConnectionBase.send( ConnectionBase.java:269) ~[na:na]
at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send( KNXnetIPTunnel.java:149) ~[na:na]
at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend( KNXNetworkLinkIP.java:263) ~[na:na]
at tuwien.auto.calimero.link.AbstractLink.send(Abstra ctLink.java:304) ~[na:na]
at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendReq uestWait(KNXNetworkLinkIP.java:240) ~[na:na]
at tuwien.auto.calimero.process.ProcessCommunicatorIm pl.readFromGroup(ProcessCommunicatorImpl.java:486) ~[na:na]
at tuwien.auto.calimero.process.ProcessCommunicatorIm pl.read(ProcessCommunicatorImpl.java:422) ~[na:na]
at org.openhab.binding.knx.internal.bus.KNXBindingDat apointReaderTask.readFromKNXBus(KNXBindingDatapoin tReaderTask.java:99) ~[na:na]
at org.openhab.binding.knx.internal.bus.KNXBindingDat apointReaderTask.run(KNXBindingDatapointReaderTask .java:67) ~[na:na]


Da gibt es weiterhin hops und das timeout.

Ich hatte gedacht/gehofft, das Problem hatte evtl mit einer falsch konfigurierten IP Schnittstelle zu tun, weil ich ja das Problem monatelang überhaupt nicht hatte. Das nervt natürlich enorm...

[zaphood]

Nimm mal die Autorefreshs aus den Items raus, dann ist da erst mal weniger los. Autorefresh hat bei mir auch jede Menge Last produziert im Tunnelmodus, so dass sich mein Raspi kaum noch bedienen lies.

[migal]

Ja, zum Testen eigentlich eine gute Idee, mach ich mal.
Ob mich der ROUTER-Modus voranbringen würde? Kann mein Interface zwar nicht, ich würde mir aber auch einen IP-Router kaufen.

[zaphood]

Also im Tunnel-Mode war OH2 schon etwas zäh. Nach Betätigung einer Taste musste ich so 2-5s warten, bevor ich den nächsten Knopf gedrückt habe. Ansonsten war schon mal Lichtorgel für die nächsten 30s angesagt. An der Stelle hat der Routermodus für etwas mehr "Schwuppdizität" in OH2 gesorgt, geht seitdem alles ohne die Lichtorgel und ich kann auch im Sekundentakt Tasten drücken.

Ob das bei dir die einzige Problematik ist, kann ich dir nicht sagen. Dass sich aber die verschiedenen Interfaces durchaus unterschiedlich verhalten, kann ich mir schon vorstellen (sind sicher nicht überall die selben Prozessoren drin). Von daher kann das dir schon was bringen...

[migal]

Ja, die Schwuppdizität Ich werde da mal ansetzen und einen aktuellen IP-Router ausprobieren. Ob es die einzige Problematik ist - ich sehe es dann ja.
Die refreshs wegzulassen hat mal den Start beschleunigt und zig Überprüfungen vermieden. Das Problem "no confirmation ..." besteht natürlich weiter.

Gerade eben ging meine Außenbeleuchtung an, ganz laangsam nacheinander und nicht wie früher alles auf einmal...