search

openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.86k stars 3.58k forks source link

[velux] Connection Issues after OH Restart #9784

Closed openPhiL closed 3 years ago

openPhiL commented 3 years ago

Hi. I use the velux binding for about a year now, and I continue to have issues with it when I restart openhab while the KLF200 remains online. Somehow, it does not reconnect. I need to unplug it, then deactivate the binding, then plug KLF back to power and then activate the binding. Now I start with OH3 and see the same behavior, so I thought to reach out to you. Here is a log where you can see how I start OH3.. only to receive a READ-Timeout, then a connection refused error. You see some timeouts, that is where the KLF200 is unplugged from power.

I wonder why it's me. Looking at the forum, people do not have my issue. Because I just started with a brand new system only to see the same issues, I expect it to be something "strange" on my side. The only thing I can think of is that my openHAB server(10.0.1.12) is not in the same network as my KLF200 (172.16.10.21).

the rest is pretty normal, using release candidate openHAB3.0.0 on Debian 10 VM that I installed using openhabian. I only have velux and astro binding currently. 

2021-01-11 20:26:51.376 [INFO ] [ab.ui.habpanel.internal.HABPanelTile] - Started HABPanel at /habpanel

2021-01-11 20:26:51.994 [INFO ] [.internal.handler.VeluxBridgeHandler] - Initializing Velux Bridge 'velux:klf200:KLF200'.

2021-01-11 20:26:52.127 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:26:54.107 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started.

2021-01-11 20:26:58.590 [WARN ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: raised an error during connection setup: Read timed out.

2021-01-11 20:26:58.591 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:27:04.626 [WARN ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: raised an error during connection setup: Read timed out.

2021-01-11 20:27:04.627 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:27:04.631 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: Exception occurred during I/O: raised a non-recoverable error during connection setup: Connection refused (Connection refused).

2021-01-11 20:27:12.633 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:27:12.636 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: Exception occurred during I/O: raised a non-recoverable error during connection setup: Connection refused (Connection refused).

2021-01-11 20:27:28.637 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:27:28.640 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: Exception occurred during I/O: raised a non-recoverable error during connection setup: Connection refused (Connection refused).

2021-01-11 20:28:00.641 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:28:06.710 [WARN ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: raised an error during connection setup: Read timed out.

2021-01-11 20:28:06.711 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: socket I/O failed 5 times.

2021-01-11 20:28:06.711 [WARN ] [.internal.handler.VeluxBridgeHandler] - velux bridge login sequence failed; expecting bridge is OFFLINE.

==> /var/log/openhab/events.log <==

2021-01-11 20:28:06.716 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'velux:klf200:KLF200' changed from UNKNOWN to OFFLINE (CONFIGURATION_ERROR): Anmeldung am Kopplungselement fehlgeschlagen.

==> /var/log/openhab/openhab.log <==

2021-01-11 20:28:16.786 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:28:22.814 [WARN ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: raised an error during connection setup: Read timed out.

2021-01-11 20:28:22.815 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:28:22.818 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: Exception occurred during I/O: raised a non-recoverable error during connection setup: Connection refused (Connection refused).

2021-01-11 20:28:26.821 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:28:26.831 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: Exception occurred during I/O: raised a non-recoverable error during connection setup: Connection refused (Connection refused).

2021-01-11 20:28:34.832 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:28:34.836 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: Exception occurred during I/O: raised a non-recoverable error during connection setup: Connection refused (Connection refused).

2021-01-11 20:28:50.838 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:28:50.840 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: Exception occurred during I/O: raised a non-recoverable error during connection setup: Connection refused (Connection refused).

2021-01-11 20:29:22.841 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:29:22.844 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: Exception occurred during I/O: raised a non-recoverable error during connection setup: Connection refused (Connection refused).

2021-01-11 20:30:26.845 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: socket I/O failed 5 times.

2021-01-11 20:30:26.848 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:30:26.856 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: Exception occurred during I/O: raised a non-recoverable error during connection setup: Connection refused (Connection refused).

2021-01-11 20:30:28.860 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:30:28.863 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: Exception occurred during I/O: raised a non-recoverable error during connection setup: Connection refused (Connection refused).

2021-01-11 20:30:32.864 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:30:32.867 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: Exception occurred during I/O: raised a non-recoverable error during connection setup: Connection refused (Connection refused).

2021-01-11 20:30:40.869 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:30:46.876 [WARN ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: raised an error during connection setup: connect timed out.

2021-01-11 20:30:46.877 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:30:52.882 [WARN ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: raised an error during connection setup: connect timed out.

2021-01-11 20:30:52.883 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:30:58.890 [WARN ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: raised an error during connection setup: connect timed out.

2021-01-11 20:30:58.891 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: socket I/O failed 5 times.

2021-01-11 20:30:58.891 [WARN ] [.internal.handler.VeluxBridgeHandler] - velux bridge login sequence failed; expecting bridge is OFFLINE.

2021-01-11 20:30:58.894 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:30:58.909 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: Exception occurred during I/O: raised a non-recoverable error during connection setup: Connection refused (Connection refused).

2021-01-11 20:31:00.911 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:31:00.913 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: Exception occurred during I/O: raised a non-recoverable error during connection setup: Connection refused (Connection refused).

2021-01-11 20:31:04.914 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:31:04.917 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: Exception occurred during I/O: raised a non-recoverable error during connection setup: Connection refused (Connection refused).

2021-01-11 20:31:12.919 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:31:12.923 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: Exception occurred during I/O: raised a non-recoverable error during connection setup: Connection refused (Connection refused).

2021-01-11 20:31:28.924 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:31:28.926 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: Exception occurred during I/O: raised a non-recoverable error during connection setup: Connection refused (Connection refused).

2021-01-11 20:32:00.927 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:32:00.936 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: Exception occurred during I/O: raised a non-recoverable error during connection setup: Connection refused (Connection refused).

2021-01-11 20:33:04.938 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: socket I/O failed 5 times.

2021-01-11 20:33:04.940 [WARN ] [al.handler.utils.Thing2VeluxActuator] - mapThing2Velux(): actuator with uniqueIndex=53:2A:5D:32:13:1C:29:A0 is not registered

2021-01-11 20:33:04.940 [WARN ] [rnal.handler.ChannelActuatorPosition] - handleRefresh(): unknown actuator.

2021-01-11 20:33:04.941 [INFO ] [.internal.handler.VeluxBridgeHandler] - handleCommandScheduled(velux:rollershutter:KLF200:_0:position,REFRESH): updating of item velux:rollershutter:KLF200:_0:position (type velux:rollershutter/position) failed.

2021-01-11 20:33:04.954 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:33:04.966 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: Exception occurred during I/O: raised a non-recoverable error during connection setup: Connection refused (Connection refused).

2021-01-11 20:33:06.968 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:33:06.971 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 172.16.10.21: Exception occurred during I/O: raised a non-recoverable error during connection setup: Connection refused (Connection refused).

2021-01-11 20:33:10.972 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

and this is how it looks like after stopping the binding, power-cycle the KLF200, then starting the binding:

2021-01-11 20:47:47.237 [WARN ] [.internal.handler.VeluxBridgeHandler] - velux bridge login sequence failed; expecting bridge is OFFLINE.

==> /var/log/openhab/events.log <==

2021-01-11 20:47:47.238 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'velux:klf200:KLF200' changed from UNINITIALIZED to OFFLINE (CONFIGURATION_ERROR): Anmeldung am Kopplungselement fehlgeschlagen.

==> /var/log/openhab/openhab.log <==

2021-01-11 20:47:47.244 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

2021-01-11 20:47:52.021 [INFO ] [g.velux.internal.bridge.slip.SClogin] - velux bridge connection successfully established (login succeeded).

2021-01-11 20:47:52.136 [INFO ] [g.velux.internal.bridge.slip.SClogin] - velux bridge connection successfully established (login succeeded).

2021-01-11 20:47:52.444 [INFO ] [.internal.handler.VeluxBridgeHandler] - Found velux scenes:

2021-01-11 20:47:52.681 [INFO ] [.internal.handler.VeluxBridgeHandler] - Found velux actuators:

    Product "#2" / SLIDER_SHUTTER (bridgeIndex=2,serial=53:14:1E:32:13:1E:12:6A,position=F7FF)

    Product "#1" / SLIDER_SHUTTER (bridgeIndex=1,serial=53:14:1E:32:13:1E:0F:53,position=F7FF)

    Product "#0" / SLIDER_SHUTTER (bridgeIndex=0,serial=53:2A:5D:32:13:1C:29:A0,position=F7FF)

    Product "#3" / SLIDER_SHUTTER (bridgeIndex=3,serial=53:2A:5D:32:13:1B:16:70,position=F7FF)  

2021-01-11 20:47:52.900 [INFO ] [.internal.handler.VeluxBridgeHandler] - velux Bridge is online with 0 scenes and 4 actuators, now.

==> /var/log/openhab/events.log <==

2021-01-11 20:47:52.903 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'velux:klf200:KLF200' changed from OFFLINE (CONFIGURATION_ERROR): Anmeldung am Kopplungselement fehlgeschlagen. to ONLINE

2021-01-11 20:47:52.933 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'RollladenHinten_Position' changed from 95 to UNDEF

2021-01-11 20:47:52.961 [INFO ] [hab.event.GroupItemStateChangedEvent] - Item 'RollladenHinten' changed from 95 to UNDEF through RollladenHinten_Position

==> /var/log/openhab/openhab.log <==

2021-01-11 20:47:53.092 [INFO ] [.internal.handler.VeluxBridgeHandler] - Shutting down Velux Bridge 'velux:klf200:KLF200'.

==> /var/log/openhab/events.log <==

2021-01-11 20:47:53.095 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'velux:klf200:KLF200' changed from ONLINE to UNINITIALIZED (HANDLER_MISSING_ERROR)

2021-01-11 20:54:19.819 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'velux:klf200:KLF200' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING

==> /var/log/openhab/openhab.log <==

2021-01-11 20:54:19.836 [INFO ] [.internal.handler.VeluxBridgeHandler] - Initializing Velux Bridge 'velux:klf200:KLF200'.

==> /var/log/openhab/events.log <==

2021-01-11 20:54:19.839 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'velux:klf200:KLF200' changed from INITIALIZING to UNKNOWN

2021-01-11 20:54:19.855 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'velux:rollershutter:KLF200:_1' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING

2021-01-11 20:54:19.861 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'velux:rollershutter:KLF200:_0' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING

2021-01-11 20:54:19.872 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'velux:rollershutter:KLF200:_2' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING

2021-01-11 20:54:19.895 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'velux:rollershutter:KLF200:_3' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING

==> /var/log/openhab/openhab.log <==

2021-01-11 20:54:19.909 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.

==> /var/log/openhab/events.log <==

2021-01-11 20:54:19.921 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'velux:rollershutter:KLF200:_1' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)

2021-01-11 20:54:19.926 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'velux:rollershutter:KLF200:_3' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)

2021-01-11 20:54:19.950 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'velux:rollershutter:KLF200:_2' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)

2021-01-11 20:54:19.954 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'velux:rollershutter:KLF200:_0' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)

==> /var/log/openhab/openhab.log <==

2021-01-11 20:54:24.231 [INFO ] [g.velux.internal.bridge.slip.SClogin] - velux bridge connection successfully established (login succeeded).

2021-01-11 20:54:24.635 [INFO ] [.internal.handler.VeluxBridgeHandler] - Found velux scenes:

2021-01-11 20:54:24.921 [INFO ] [.internal.handler.VeluxBridgeHandler] - Found velux actuators:

    Product "#2" / SLIDER_SHUTTER (bridgeIndex=2,serial=53:14:1E:32:13:1E:12:6A,position=C800)

    Product "#1" / SLIDER_SHUTTER (bridgeIndex=1,serial=53:14:1E:32:13:1E:0F:53,position=C800)

    Product "#0" / SLIDER_SHUTTER (bridgeIndex=0,serial=53:2A:5D:32:13:1C:29:A0,position=B19D)

    Product "#3" / SLIDER_SHUTTER (bridgeIndex=3,serial=53:2A:5D:32:13:1B:16:70,position=BD7A)  

2021-01-11 20:54:25.125 [INFO ] [.internal.handler.VeluxBridgeHandler] - velux Bridge is online with 0 scenes and 4 actuators, now.

==> /var/log/openhab/events.log <==

2021-01-11 20:54:25.128 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'velux:klf200:KLF200' changed from UNKNOWN to ONLINE

2021-01-11 20:54:25.131 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'velux:rollershutter:KLF200:_1' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE

2021-01-11 20:54:25.133 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'velux:rollershutter:KLF200:_0' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE

2021-01-11 20:54:25.136 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'velux:rollershutter:KLF200:_2' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE

2021-01-11 20:54:25.147 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'velux:rollershutter:KLF200:_3' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE

2021-01-11 20:54:35.423 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'RollladenHinten_Position' changed from UNDEF to 95

Thanks for checking!! PhiL

andrewfg commented 3 years ago

@openPhiL please tell us what version of OpenHAB you are running. And what version of the Velux binding?

There were a lot of changes made in OH v2.5.10 and even more in OH v3.x

andrewfg commented 3 years ago

using release candidate openHAB3.0.0

Oops, I see you said what version you are running (but which RC is it actually ??)

You should certainly try OH 3.0.0 FINAL or even today's 3.1.0-SNAPSHOT (Build #2154)

openPhiL commented 3 years ago

ok, will update as soon as 3.1 is out and let you know. Thanks

andrewfg commented 3 years ago

Just to note: the KLF200's connection socket can get into a zombie state if the OH computer is hard powered off, hard rebooted, or hard disconnected from the LAN; which requires you to power cycle the KLF200 to recover. So what you need to do is run the soft OH 'shutdown' or 'systemctl stop openhab' before doing any of those hard things.

openPhiL commented 3 years ago

that sounds like my symtoms. Yes, sometimes connecting issues appear, power goes down or openhab hangs. But... is there nothing you can do about it? I assume that is because of the "experts" at velux.. I just throw in the idea of disconnecting the binding after each request in a "valid" way.. as I personally only have actuators, so I don't need the binding to communicate other when I ask it to send information to the device.

andrewfg commented 3 years ago

You are right that the issue is because the binding uses connection keep-alive. And in theory if one closed the socket after each transaction, this would not be an issue. However, there are two problems with closing after each transaction -- a) the KLF is slooow, it takes 2-3 seconds to establish an SSL connection, and b) after you send commands to the KLF it may send several notification responses (e.g. position notifications when a window is moving) so if you would close the connection after sending the command you would lose the position notifications.

andrewfg commented 3 years ago

will update as soon as 3.1 is out

If you want to try the 3.1 jar already, you can get it here

xzeda75 commented 3 years ago

Would you have any hint for me how to read out/get the serial (8 HEX) of the rollershutter. I'd really appreciate any help.

andrewfg commented 3 years ago

When you install the binding, it will first auto discover the Bridge, then if you create a Bridge Thing, it will auto discover all actuators and scenes in the Bridge. You will see their serial numbers in the openhab.log file, and also in the main UI.

xzeda75 commented 3 years ago

Thanks a lot for the immediate response. I must have missed that because the log shows the actuators by its name given in the klf200.velux interface, e.g., Product "RS3" / SLIDER_SHUTTER (bridgeIndex=0,serial=RS3,position=0091). I thought that the serial is some kind of "mac adress" given by the device (per default)

andrewfg commented 3 years ago

On a real Velux device the serial is indeed something like a mac address. So I suppose that your RS3 device is not from Velux; is it a Somfy device?

xzeda75 commented 3 years ago

you are right, it's a somfy device, but it's still working with the name. thank you!

andrewfg commented 3 years ago

Closed by #10449