[velux] New OpenHAB2 binding - feedback welcome!

gs4711 · August 18, 2021, 1:51pm

even if my installation runs well for several month, I tried to scrutinize what is happening during the shutdown. In fact, I’m astonished about the log entries:

# openhab-cli  stop

A systemd service configuration exists...
Use 'sudo /bin/systemctl stop openhab2.service' to stop an openHAB service
Stopping any instance of openHAB...
root@home-pi06:/etc/openhab2/rules# 2021-08-18 15:40:40.438 [INFO ] [.internal.handler.VeluxBridgeHandler] - Shutting down Velux Bridge 'velux:klf200:home'.
2021-08-18 15:40:40.441 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Shutting down Velux bridge connection.
2021-08-18 15:40:40.763 [DEBUG] [penhab.io.transport.cul.CULActivator] - CUL transport has been stopped.
2021-08-18 15:40:41.071 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI
2021-08-18 15:40:46.283 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler VeluxBridgeHandler of thing velux:klf200:home tried checking if channel status is linked although the handler was already disposed.
2021-08-18 15:40:46.283 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.
2021-08-18 15:40:46.285 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler VeluxBridgeHandler of thing velux:klf200:home tried checking if channel reload is linked although the handler was already disposed.

This is reproducible behavior when shutting down via openhab-cli: The system restarts itself. Only using the systemctl stop openhab2 command on its own, the OH2 shuts down properly.

AndrewFG · August 18, 2021, 4:51pm

Hmm.

Guenther, to be honest I never tried the openhab-cli stop command before; but I guess that when you give that command, you cause two things to happen sequentially..

The user initiated openhab-cli stop does indeed shut down openHAB.
The systemd service manager detects that the OH service has stopped, and automatically starts it again.

In other words, I think the systemd service manager is doing exactly what it is supposed to do.

IMHO the openhab-cli stop console message (below) is a clear and strong indication NOT to use this command.

"Use 'sudo systemctl stop openhab2.service' to stop an openHAB service"

Conclusions

OpenHAB Framework: I am surprised the OH framework allows openhab-cli stop to (try to) do anything when the systemd service manager is running. The command rightly gives the above warning, but it should then terminate, and NOT (try to) stop the system. => I think this is a bug in the OH core framework.
Velux Binding: You didn’t say if the Velux binding went into a zombie state after openhab-cli stop (please advise) [#1]. However if it did cleanly stop and then cleanly restart, I would say that the binding is doing exactly what it is supposed to do.

[#1] I tried this openhab-cli stop command on my OH3 system, and I can confirm that everything did indeed cleanly stop and then cleanly restart again.

PS for those people running OH3, the correct shutdown command is..

sudo systemctl stop openhab.service

gs4711 · August 18, 2021, 8:53pm

Even with the unwanted and unexpected behaviour of the openhab-cli stop, the Velux binding has handled the shutdown and restart gracefully… everything went fine (congrats!).

AndrewFG · August 19, 2021, 6:04pm

I will look at this tomorrow, and perhaps open an Issue to report it as a bug…

AndrewFG · August 23, 2021, 11:27am

I had opened an issue on GitHub concerning this problem, and @fwolter gave me this response => @gs4711, @Lolodomo, do you have any thoughts on this?

AndrewFG · August 23, 2021, 12:59pm

gs4711:

I’m astonished about the log entries:

# openhab-cli  stop

A systemd service configuration exists...
Use 'sudo /bin/systemctl stop openhab2.service' to stop an openHAB service
Stopping any instance of openHAB...

I created a PR that should fix this issue..

github.com/openhab/openhab-linuxpkg

If appropriate daemon tool exists, issue warning => and exit

main ← andrewfg:exit-cli

opened 12:57PM - 23 Aug 21 UTC

andrewfg

+2 -0

**Background:** When one issues the `openhab-cli stop` command, the script give…s the warning below. However, after the warning, the script continues anyway (as shown below). ``` A systemd service configuration exists... Use 'sudo /bin/systemctl stop openhab2.service' to stop an openHAB service .. Stopping any instance of openHAB... ``` **Problem:** As a consequence the following two things happen one after the other.. - First of all `openhab-cli stop` does stop the OH service - Then the daemon detects that OH has stopped, -- **_and re-starts OH again!_** This is clearly stupid, and confusing to users. **Solution:** After issuing the warning message, the script should `exit 1` instead of continuing. Signed-off-by: Andrew Fiddian-Green <software@whitebear.ch>

gs4711 · September 7, 2021, 10:16am

github.com/openhab/openhab-core

Bad implementations of ThingHandler.dispose() that are blocking

opened 03:29PM - 15 Aug 21 UTC

closed 06:20PM - 25 Apr 22 UTC

andrewfg

awaiting feedback

**Note:** I am posting this issue under `openhab-core` rather `openhab-addons` …because it relates either a) to an underlying shutdown issue in the core, or b) to a non compliance of some binding developers to the OH coding rules. **Background:** The Velux binding suffers from a particularly sensitive communication issue on shutdown: If the TCP socket between OH and the Velux KLF hub is 'hard killed' the hub goes into a zombie state; and it requires a specific and orderly shutdown sequence to prevent this. **Symptoms:** I have been doing some tests, and found out the following… 1. From the time that the user issues a console command to stop the openHAB service, the OH framework takes a variable time of between 0 and 8 seconds before the Velux binding dispose() method is called. 2. From the time that Velux dispose() method is called, the actual Velux binding code takes a fairly stable time of 3.5 seconds for it to physically shut down the KLF comms. I guess that our problem is the variable 0 to 8 seconds delay in step 1. above: – If the delay gets too long then the OH framework will already be trying to tear down its underlying TCP socket system (hard close) before the poor Velux dispose() method has had a chance to finish its soft close. Obviously the OH framework calls dispose() on all its Things, UI, and other services, in no particular time sequence. Sometimes Velux dispose() gets called early in the sequence and everything is good; but sometimes Thing/service dispose() methods are called before Velux dispose(), and then there can be problems for us. Particularly problematic are those Things which (against the openHAB coding rules) are blocking for a long time in their dispose() method. e.g. the ZWave binding dispose() blocks for more 5 seconds; the framework gives a warning after 5 seconds, but it probably blocks longer than that, so it is likely to be guilty of a large proportion, if not all, of the ‘problem period’ of 8 seconds… **Solutions:** I see two potential solutions.. 1. Force the developers of all bindings which are guilty of breaking the openHAB coding rules, by blocking in their ThingHandler.dispose() methods, to fix their code. 2. Implement a layer in OH core to de-serialize its calls to ThingHandler.dispose().. https://community.openhab.org/t/velux-new-openhab2-binding-feedback-welcome/32926/1311?u=andrewfg

you should defer the slow parts of its code to a scheduler thread so that all bindings’ ThingHandler.dispose() methods will be called quickly in turn

Sounds reasonable for me. Then, all bindings have the same opportunity for a graceful termination.

ceedee · December 4, 2021, 2:51pm

I was really glad that there is this binding, thanks so much for creating it!

Got my KLF 200 today. I’m using version 2.5.11 of this binding. My two rollershutters seemed to work initially but suddenly stopped working. I hope, you can help me fixing it!

I’m getting these log messages:

2021-12-04 15:28:29.030 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.
2021-12-04 15:28:34.681 [INFO ] [g.velux.internal.bridge.slip.SClogin] - velux bridge connection successfully established (login succeeded).
2021-12-04 15:29:18.214 [WARN ] [lux.internal.bridge.slip.SCgetScenes] - Gateway response GW_GET_NETWORK_SETUP_CFM (0xe1) cannot be handled at this point of interaction.
2021-12-04 15:29:32.736 [WARN ] [rnal.bridge.slip.SCrunProductCommand] - Gateway response GW_GET_NETWORK_SETUP_CFM (0xe1) cannot be handled at this point of interaction.
2021-12-04 15:29:42.894 [WARN ] [rnal.bridge.slip.SCrunProductCommand] - Gateway response GW_GET_SCENE_LIST_CFM (0x40d) cannot be handled at this point of interaction.
2021-12-04 15:29:51.104 [WARN ] [rnal.bridge.slip.SCrunProductCommand] - Gateway query for SessionID 3364 received unexpected response of SessionID 3366.
2021-12-04 15:29:58.359 [WARN ] [rnal.bridge.slip.SCrunProductCommand] - Gateway query for SessionID 3365 received unexpected response of SessionID 3367.
2021-12-04 15:30:06.832 [WARN ] [rnal.bridge.slip.SCrunProductCommand] - Gateway query for SessionID 3366 received unexpected response of SessionID 3368.
2021-12-04 15:30:09.389 [WARN ] [ux.internal.bridge.slip.SCgetProduct] - Gateway response GW_COMMAND_SEND_CFM (0x301) cannot be handled at this point of interaction.
2021-12-04 15:30:09.411 [WARN ] [ux.internal.bridge.slip.SCgetProduct] - Gateway response GW_COMMAND_SEND_CFM (0x301) cannot be handled at this point of interaction.
2021-12-04 15:31:12.716 [INFO ] [internal.bridge.slip.SlipVeluxBridge] - bridgeDirectCommunicate() on 192.168.0.36: received GW_ACTIVATION_LOG_UPDATED_NTF.
2021-12-04 15:31:13.718 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.36: Exception occurred during I/O: read timeout.
2021-12-04 15:31:14.720 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.
2021-12-04 15:31:20.288 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.36: Exception occurred during I/O: read timeout.
2021-12-04 15:31:22.290 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.
2021-12-04 15:31:22.294 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.36: Exception occurred during I/O: raised a non-recoverable error during connection setup: Connection refused (Connection refused).
2021-12-04 15:31:26.298 [INFO ] [nternal.bridge.slip.io.SSLconnection] - Starting velux bridge connection.
2021-12-04 15:31:26.302 [INFO ] [x.internal.bridge.slip.io.Connection] - io() on 192.168.0.36: Exception occurred during I/O: raised a non-recoverable error during connection setup: Connection refused (Connection refused).

After that “non-recoverable” error, there’s no way to get it working again. Restarting openHAB did not help, I somehow had to re-install the binding.

Here’s my thing configuration:

Bridge velux:klf200:we "Velux KLF200 Hub" @ "SF" [ipAddress="192.168.0.36", password="***", timeoutMsecs="1000", retries="5", refreshMsecs="10000", isSequentialEnforced="no", isProtocolTraceEnabled="no", isBulkRetrievalEnabled="yes"] {
    
}

I added the things for my roller shutters via PaperUI. In my things files I have:

Rollershutter   IdeviceSfWrRollerShutter_Position                       "SfWR Position"                                                                                                                                                                                                                     {channel="velux:rollershutter:we:Arbeitszimmer:position"}
Rollershutter   IdeviceSfWrRollerShutter_LimitMinimum                   "SfWR  Minimum Position"                                                                                                                                                                                                             {channel="velux:rollershutter:we:Arbeitszimmer:limitMinimum"}
Rollershutter   IdeviceSfWrRollerShutter_LimitMaximum                   "SfWR  Maximum Position"                                                                                                                                                                                                             {channel="velux:rollershutter:we:Arbeitszimmer:limitMaximum"}

Rollershutter   IdeviceSfBarRollerShutter_Position          "SfBar Position"                                                                                                                                                                                                                                           {channel="velux:rollershutter:we:Bad:position"}
Rollershutter   IdeviceSfBarRollerShutter_LimitMinimum      "SfBar Minimum Position"                                                                                                                                                                                                                                   {channel="velux:rollershutter:we:Bad:limitMinimum"}
Rollershutter   IdeviceSfBarRollerShutter_LimitMaximum      "SfBar Maximum Position"                                                                                                                                                                                                                                   {channel="velux:rollershutter:we:Bad:limitMaximum"}

In my sitemap I’ve the following:

                Switch item=IdeviceSfWrRollerShutter_Position label="Rollo"
                Slider item=IdeviceSfWrRollerShutter_Position label="Rollo Position"
             ...
                Switch item=IdeviceSfBarRollerShutter_Position label="Rollo"
                Slider item=IdeviceSfBarRollerShutter_Position label="Rollo Position"

I doesn’t make much difference whether I use the switch or slider, after a couple of operations, I get these connections problems.

Can you support me fixing these issues?

Best regards,
ceedee

kleiner-irrer · December 4, 2021, 2:59pm

Try this:
Stop openhab Service.
Reboot klf200
Start openhab Service

ceedee · December 4, 2021, 3:08pm

@kleiner-irrer I could try this, but having to uninstall and reinstall the binding in case of this error is just a side-problem. My main problem is that I can only operate my roller shutters for a few times. Then things stop working.

AndrewFG · December 4, 2021, 6:08pm

For the avoidance of doubt: Whenever the Velux hub does lock up, you do not need to un-install/re-install anything! You “only” need to dis-able/re-enable the hub Thing in OH. (Or as @kleiner-irrer more precisely says dis-able in OH/ power-cycle the hub / re-enable in OH)..

The following log entries are the most unexpected, but don’t really give much clue about what is going on. So let me explain the logs a bit, and then ask you some deeper questions on the context.

2021-12-04 15:29:18.214 [WARN ] [lux.internal.bridge.slip.SCgetScenes] - Gateway response GW_GET_NETWORK_SETUP_CFM (0xe1) cannot be handled at this point of interaction.
2021-12-04 15:29:32.736 [WARN ] [rnal.bridge.slip.SCrunProductCommand] - Gateway response GW_GET_NETWORK_SETUP_CFM (0xe1) cannot be handled at this point of interaction.
2021-12-04 15:29:42.894 [WARN ] [rnal.bridge.slip.SCrunProductCommand] - Gateway response GW_GET_SCENE_LIST_CFM (0x40d) cannot be handled at this point of interaction.
2021-12-04 15:29:51.104 [WARN ] [rnal.bridge.slip.SCrunProductCommand] - Gateway query for SessionID 3364 received unexpected response of SessionID 3366.
2021-12-04 15:29:58.359 [WARN ] [rnal.bridge.slip.SCrunProductCommand] - Gateway query for SessionID 3365 received unexpected response of SessionID 3367.
2021-12-04 15:30:06.832 [WARN ] [rnal.bridge.slip.SCrunProductCommand] - Gateway query for SessionID 3366 received unexpected response of SessionID 3368.
2021-12-04 15:30:09.389 [WARN ] [ux.internal.bridge.slip.SCgetProduct] - Gateway response GW_COMMAND_SEND_CFM (0x301) cannot be handled at this point of interaction.
2021-12-04 15:30:09.411 [WARN ] [ux.internal.bridge.slip.SCgetProduct] - Gateway response GW_COMMAND_SEND_CFM (0x301) cannot be handled at this point of interaction.

The ‘cannot be handled at this point of interaction’ means the hub is busy doing something else and could not process the request. So my questions are: What are you resp. it doing (trying to) at that time?
The ‘SessionID AAA received unexpected response of SessionID BBB’ mean that the binding received a response Id BBB in answer to its query Id AAA. And since BBB is a higher number than AAA, it seems the intervening response Id were lost somehow. So my questions are: Is your LAN network particularly busy so that packets may be lost? Are you for example running over wi-fi?

It could be, of course that the ‘busy-ness’ that causes the hub to not be able to handle item 1. above, is also the reason why it is dropping the answers to intervening queries..

AndrewFG · December 4, 2021, 6:13pm

PS it might be worth your while to play around with the isSequentialEnforced and/or isBulkRetreivalEnabled Configuration Parameters..

AndrewFG · December 4, 2021, 6:15pm

What version of OH are you running?

ceedee · December 4, 2021, 8:30pm

Thank you very much for explaining the log entries!

To answer your questions:

I was just operating the items in the sitemap I posted above. It happened when I used the up/down controls from the switch and also when moving the slider a couple of times.
My LAN is not busy. It’s a Gigabit-LAN but mostly idling. The Velux KLF 200 and the Raspi with openHAB are on the LAN, so no WLAN is involved.
I’m using openHAB 2.5.11-1

I’ll play around with the settings you mentioned and keep you posted.

How does the communication with the KLF work? It sounds somewhat strange that request/response are somehow mixed up.

Best regards,
ceedee

AndrewFG · December 4, 2021, 10:42pm

Indeed. What you are seeing is really unexpected.

ceedee · December 5, 2021, 2:49pm

I now activated trace logging and disabled any other openHAB logging to find out the cause, but I cannot reproduce the problem. Could be a timing issue which is influenced by logging.

ceedee · December 5, 2021, 6:50pm

@AndrewFG It took some time and the error re-appeared. Actually without doing anything. I just had to wait a couple of hours. Since I’ve activated TRACE level logging for the binding, I can provide detailed logs. Just let me know how to provide them.

AndrewFG · December 8, 2021, 7:31pm

I got your log, thankyou. It confirms that the warning messages are indeed due to overlapping requests and responses.

I think you are still on openHAB v2.5.x – is that correct? After OH v2.5.x was released, I did a lot of work in OH v3.x.x concerning the communication code for pipe-lining the sending of commands and processing of responses. i.e. fixing issues similar to yours.

Unfortunately, therefore, if you want to remain on OH v2.5.x, the only thing I can recommend is to play with the isSequentialEnforced and/or isBulkRetreivalEnabled settings. But this may not work. In which case the only thing I can suggest is that you migrate your OH installation from v2.5.x to v3.x.x.

Obviously a migration is not a trivial exercise. Perhaps you can try creating a minimal OH v3.x.x setup on a spare PC, (other than your operational system), and just install the Velux binding and Things, to see if that fixes your issue.

ceedee · December 9, 2021, 6:29pm

Thank you for the investigation! I’ll try out your recommendations on using isSequentialEnforced and/or isBulkRetrievalEnabled first. Let’s see if I find the time to upgrade to OH3.

Best regards,
ceedee

higgers · December 13, 2021, 6:56pm

If you have spare hardware to install OH3.1 (or 3.2 very soon) you could use the 3.2 install to control your Velux devices and use the remoteopenhab binding to update virtual Velux items on your 2.5 system based on the values in the 3.2 system. In this approach, the 3.2 systyem acts as the engine to control the Velux devices and the 2.5 system continues to be the system that users interact with.