[velux] Fix synchronisation of handler initialization and disposal

[andrewfg]

The Velux hub initialization and shutdown processes are very slow and deliberate. And sometimes when OH reloads the binding, it was possible for a newly created VeluxBridgeHandler instance's .initialize() method to be called before the prior VeluxBridgeHandler instance's .dispose() method had finished processing i.e. it was attempting to shut down and re-start the hub communication at the same time!

See this forum post

Therefore this PR introduces the following fixes resp. improvements:

• The .initialize() / .dispose() methods now defer slow processes to scheduled tasks, so the OH caller thread returns faster.
• The .initializeScheduled() method now waits for the Future<> result of a prior .disposeScheduled() (if any) before proceeding.
• If a socket timeout occurs during the shut down process, the communication polling loop will exit faster.
• Cleaned up the logging a bit, to eliminate un- needed logger.info() reports, and make others more easily understandable.
• Cleaned up the initialization of the Velux Binding Info thing.

Signed-off-by: Andrew Fiddian-Green software@whitebear.ch

[andrewfg]

@gs4711 feedback appreciated

[openhab-bot]

This pull request has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/velux-new-openhab2-binding-feedback-welcome/32926/1261

[gs4711]

Question: Are your sure to remove the synchronized of the dispose method?

[andrewfg]

Are your sure to remove the synchronized of the dispose method?

Hmm. I have never actually observed OH calling dispose() on the same class instance more than once. Also the dispose() method of the parent class (that is overridden) is not declared synchronized, so I suspect the creators of OH did not foresee multiple calls to be made. ??

The real problem that I am trying to address, is when OH calls dispose() on one (old) class instance, and initialize() on another newly created class instance for the same hub. That is why the Future<> get() is made to cross synchronise the two methods between two separate class instances that relate to the same Bridge (IP address).

However, do you have a specific reason why it should be synchronized?

[andrewfg]

Guenther, some more thoughts on this..

• If any method should be synchronized, it should really be disposeScheduled().
• And since that is a scheduled task, it is possible that the thread scheduler would serialize the execution of the two tasks anyway.
• However perhaps an even safer approach would be for disposeSceduled() to set a boolean flag disposeAlreadyDone and use it to shortcut any subsequent calls to disposeScheduled()..

[gs4711]

Go for it for the time being!

But, in fact, IMHO it should be fixed in the framework.

[andrewfg]

@gs4711 I have a question concerning a potential a problem also with the Velux_Binding_Handler class.

During a jar reload I saw VeluxBindingHandler.initialize() being called before VeluxBridgeHandler.disposeScheduled() had completed (see log below) i.e. well before VeluxBridgeHandler.initializeScheduled() had completed. And since VeluxBindingHandler has Channels that depend on the state and quantity of the VeluxBridgeHandler's Channels, I think its call to updateVisibleInformation() might also interfere with the disposal and re-initialization sequence of the respective Bridges. Or??

So I think I should also defer the execution of VeluxBindingHandler.initialize() (resp. updateVisibleInformation()) until all of the respective Bridges have been cleanly disposed and re-initialized? What do you think?

2021-04-06 13:37:45.822 [INFO ] [internal.handler.VeluxBindingHandler] - Initializing VeluxBindingHandler for 'velux:binding:org_openhab_binding_velux'.
2021-04-06 13:37:46.068 [INFO ] [.internal.handler.VeluxBridgeHandler] - Velux Bridge 'velux:klf200:g24' shut down completed.

[andrewfg]

updateVisibleInformation() might also interfere with the disposal and re-initialization sequence of the respective Bridges

No, it does not actually interfere with the disposal and re-initialization. However the Velux Binding Handler Thing(s) display the wrong information because the respective Velux Bridge Handler Thing(s) have not had time to fully discover all their Things.

defer the execution .. until all of the respective Bridges have been cleanly disposed and re-initialized

My last three commits defer the binding information update until after the Bridges & Things are disposed and re-initialized.

[kaikreuzer]

@andrewfg Thanks for your refactoring here.
Looking at the code, I noticed that there are still many info logs that should indeed be debug level instead. I see that they were in there before, but as you cleaned up the logging, it would be nice if you could address those, too.

[fwolter]

Thanks for fixing the log levels!

[andrewfg]

raise a sh*t storm, that Velux fixes this bug :)

We have tried this. But Velux won't even answer the emails. They say it is provided "as is"..

[andrewfg]

keep in mind that everything you do, does delay the execution of systemctl stop openhab

Yes I know that; and I can see it in my tests; in my case 'stop' takes about 15 seconds; whereby I have 17 bindings, and I am not sure if the delay is due to the Velux or something else..

Anyway, let me think about this overnight, and I will eventually push another change. I will ping you back when I am done.

[andrewfg]

I will eventually push another change. I will ping you back when I am done

I made another commit just now with the following changes..

• Instead of synchronizing initializeSchedulerJob() and disposeSchedulerJob() tasks via a Future<> it now synchronizes them via the Strings.intern() object of the bridge's IP address. This is a much, much better solution since it prevents multiple/cross, initialization/disposal, via same/different class instances, to the same physical bridge (IP address).
• Instead of shutdown() it now uses shutdownNow() to avoid waiting for scheduled communications tasks that have not yet been started.
• To prevent OH systemctl stop openhab.service from stalling, the call to awaitTermination() times out after an explicitly declared constant period of COMMUNICATION_TASK_MAX_WAIT_SECS = 10 seconds.
• The dispose() method additionally sends a disable House Status Monitor command to the bridge; thus stopping it queueing fresh events in its send buffer.

@fwolter I have tested start/ stop combinations of a) OH itself, b) the binding, and c) specific bridges, so I think you can complete your review of the new code now if you want. But notwithstanding this I set the 'Additional Testing Required' flag, so I can let it run for a few days in my live system; so please don't actually merge the PR until I clear that flag again.

[andrewfg]

The dispose() method additionally sends a disable House Status Monitor command to the bridge; thus stopping it queueing fresh events in its send buffer

@gs4711 this might (finally) be the key that resolves the 'zombie socket' problem. => What do you think?

[andrewfg]

@fwolter I have been pressure testing this for a few days now, and it is all good to go.

[fwolter]

LGTM