Yesterday night I had the following exception in my openhab log file:
2018-03-14 02:26:06.892 [WARN ] [org.apache.karaf.services.eventadmin] - EventAdmin: Blacklisting ServiceReference [{org.osgi.service.event.EventHandler, tuwien.auto.calimero.process.ProcessListener}={event.topics=openhab/*, component.name=org.openhab.binding.knx, component.id=38, service.id=316, service.bundleid=16, service.scope=bundle} | Bundle(org.openhab.binding.knx_1.11.0.201708271339 [16])] due to timeout!
2018-03-14 02:26:13.502 [WARN ] [nx.internal.connection.KNXConnection] - KNX link has been lost (reason: maximum send attempts on object tunneling link link (closed) 192.168.10.50:3671 TP1 medium, device 1.1.235, hopcount 6)
2018-03-14 02:26:13.847 [INFO ] [nx.internal.connection.KNXConnection] - KNX link will be retried in 30 seconds
2018-03-14 02:26:13.848 [ERROR] [.binding.knx.internal.bus.KNXBinding] - Received detach Event.
2018-03-14 02:26:13.887 [WARN ] [.binding.knx.internal.bus.KNXBinding] - Value '4.8' could not be sent to the KNX bus using datapoint 'command DP 11/2/200 Temperatur_Garten, DPT main 0 id 9.001, low priority' - retrying one time: maximum send attempts, no service acknowledgment received
2018-03-14 02:26:13.350 [ERROR] [tuwien.auto.calimero ] - KNXnet/IP Tunneling 192.168.10.50:3671: close connection - maximum send attempts
tuwien.auto.calimero.exception.KNXAckTimeoutException: maximum send attempts, no service acknowledgment received
at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:261) [16:org.openhab.binding.knx:1.11.0.201708271339]
at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:149) [16:org.openhab.binding.knx:1.11.0.201708271339]
at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:263) [16:org.openhab.binding.knx:1.11.0.201708271339]
at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:304) [16:org.openhab.binding.knx:1.11.0.201708271339]
at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:240) [16:org.openhab.binding.knx:1.11.0.201708271339]
at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:466) [16:org.openhab.binding.knx:1.11.0.201708271339]
at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:438) [16:org.openhab.binding.knx:1.11.0.201708271339]
at org.openhab.binding.knx.internal.bus.KNXBinding.writeToKNX(KNXBinding.java:161) [16:org.openhab.binding.knx:1.11.0.201708271339]
at org.openhab.binding.knx.internal.bus.KNXBinding.internalReceiveCommand(KNXBinding.java:118) [16:org.openhab.binding.knx:1.11.0.201708271339]
at org.openhab.core.binding.AbstractBinding.receiveCommand(AbstractBinding.java:94) [203:org.openhab.core.compat1x:2.2.0]
at org.openhab.core.events.AbstractEventSubscriber.handleEvent(AbstractEventSubscriber.java:45) [203:org.openhab.core.compat1x:2.2.0]
at org.apache.felix.eventadmin.impl.handler.EventHandlerProxy.sendEvent(EventHandlerProxy.java:415) [3:org.apache.karaf.services.eventadmin:4.1.3]
at org.apache.felix.eventadmin.impl.tasks.HandlerTask.run(HandlerTask.java:70) [3:org.apache.karaf.services.eventadmin:4.1.3]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
at java.lang.Thread.run(Thread.java:748) [?:?]
2018-03-14 02:26:23.966 [ERROR] [tuwien.auto.calimero ] - KNXnet/IP Tunneling 192.168.10.50:3671: establishing connection failed, timeout connecting to control endpoint /192.168.10.50:3671
2018-03-14 02:26:23.930 [ERROR] [nx.internal.connection.KNXConnection] - Error connecting to KNX bus: timeout connecting to control endpoint /192.168.10.50:3671
2018-03-14 02:26:23.986 [WARN ] [org.apache.karaf.services.eventadmin] - EventAdmin: Exception during event dispatch [org.osgi.service.event.Event [topic=openhab/command/Temperatur_Garten] {bridgemarker=true, item=Temperatur_Garten, command=4.8} | {org.osgi.service.event.EventHandler, tuwien.auto.calimero.process.ProcessListener}={event.topics=openhab/*, component.name=org.openhab.binding.knx, component.id=38, service.id=316, service.bundleid=16, service.scope=bundle} | Bundle(org.openhab.binding.knx_1.11.0.201708271339 [16])]
tuwien.auto.calimero.exception.KNXIllegalStateException: process communicator detached
at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:465) [16:org.openhab.binding.knx:1.11.0.201708271339]
at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:438) [16:org.openhab.binding.knx:1.11.0.201708271339]
at org.openhab.binding.knx.internal.bus.KNXBinding.writeToKNX(KNXBinding.java:170) [16:org.openhab.binding.knx:1.11.0.201708271339]
at org.openhab.binding.knx.internal.bus.KNXBinding.internalReceiveCommand(KNXBinding.java:118) [16:org.openhab.binding.knx:1.11.0.201708271339]
at org.openhab.core.binding.AbstractBinding.receiveCommand(AbstractBinding.java:94) [203:org.openhab.core.compat1x:2.2.0]
at org.openhab.core.events.AbstractEventSubscriber.handleEvent(AbstractEventSubscriber.java:45) [203:org.openhab.core.compat1x:2.2.0]
at org.apache.felix.eventadmin.impl.handler.EventHandlerProxy.sendEvent(EventHandlerProxy.java:415) [3:org.apache.karaf.services.eventadmin:4.1.3]
at org.apache.felix.eventadmin.impl.tasks.HandlerTask.run(HandlerTask.java:70) [3:org.apache.karaf.services.eventadmin:4.1.3]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
at java.lang.Thread.run(Thread.java:748) [?:?]
2018-03-14 02:26:43.853 [INFO ] [nx.internal.connection.KNXConnection] - Trying to (re-)connect to KNX...
2018-03-14 02:26:53.899 [ERROR] [nx.internal.connection.KNXConnection] - Error connecting to KNX bus: timeout connecting to control endpoint /192.168.10.50:3671
2018-03-14 02:26:53.899 [ERROR] [tuwien.auto.calimero ] - KNXnet/IP Tunneling 192.168.10.50:3671: establishing connection failed, timeout connecting to control endpoint /192.168.10.50:3671
2018-03-14 02:26:53.899 [INFO ] [nx.internal.connection.KNXConnection] - KNX link will be retried in 30 seconds
2018-03-14 02:27:13.854 [INFO ] [nx.internal.connection.KNXConnection] - Trying to (re-)connect to KNX...
2018-03-14 02:27:18.215 [INFO ] [nx.internal.connection.KNXConnection] - Established connection to KNX bus on 192.168.10.50:3671 in mode TUNNEL.
2018-03-14 02:27:18.274 [INFO ] [nx.internal.connection.KNXConnection] - Connected to KNX
I am not sure, why openhab had to reconnect to the KNX bus (I am using eibd on a wiregate as KNX interface), but according to the logs the connection could be reestablished.
In the morning I noticed, that my blinds had not been opened. Further investigation showed:
-
openHAB could receive events from the KNX bus (when switching a light using a wall mounted switch the state change was shown in the user interface)
-
No events where send to the KNX bus ( I tried several items)
-
After a bundle:stop , followed by a bundle:start for the KNX binding (KNX 1.11.0.201708271339) everything was back to normal an openHAB could send events to the KNX bus. No other component had to be restarted.
The last observation make me assume, that the behavior was caused by the KNX binding. Should I file a bug?
Since most of my devices are KNX devices this is really critical for me and I am thinking about a workaround for my next vacation, where I will have to internet access and can not solve the issue via VPN. Otherwise my in-laws would have to come to my house twice a day to open and close all blinds and switch some lights, I would prefer to avoid that.
I am thinking about an KNX echo server (I could implement this functionality in the wiregate server) and a rule, that periodically sends a KNX event to the bus. The echo server will answer with a different KNX group address to make sure, that the answer was received from the KNX bus. If openHAB does not receive these answers for some time, the KNX binding could be restarted by calling a bash script, which does a ssh to the karaf console.
Any thoughts about that?
Thanks for your help in advance!
Juelicher