Deconz switches reporting "click" twice

dklinger commented 1 year ago

Hey. From time to time, the adapter starts to reports clicks on switches twice. I have Friends of Hue Switches, connected to deconz. When I click a Button, it reports the button click within ioBroker. Restarting the adapter in ioBroker fixes the issue. That's the reason I don't think it's a problem of the switches or deconz. See screenshot of history adapter below, the line from left to right marks the time when I did a reboot of the adapter instance in ioBroker.

Jey-Cee commented 1 year ago

A long time ago there was a bug where the websocket connection was opened more than once. But it was fixed.

It would be nice if you can provide a log with the instance running in log level debug, while this is happen.

dklinger commented 1 year ago

@Jey-Cee Thanks. Please see log below. It's currently happening again. Let me know if you need more. I am trying to no restart the adapter for the next 24-48 hours.

deconz.0 2022-11-07 12:43:48.368 debug Websocket message: {"e":"changed","id":"37","r":"sensors","state":{"buttonevent":3002,"lastupdated":"2022-11-07T11:43:48.366"},"t":"event","uniqueid":"00:00:00:00:01:75:34:7e-f2"}

deconz.0 2022-11-07 12:43:48.367 debug Websocket message: {"e":"changed","id":"37","r":"sensors","state":{"buttonevent":3002,"lastupdated":"2022-11-07T11:43:48.366"},"t":"event","uniqueid":"00:00:00:00:01:75:34:7e-f2"}

deconz.0 2022-11-07 12:43:48.126 debug Websocket message: {"e":"changed","id":"37","r":"sensors","state":{"buttonevent":3000,"lastupdated":"2022-11-07T11:43:48.125"},"t":"event","uniqueid":"00:00:00:00:01:75:34:7e-f2"}

deconz.0 2022-11-07 12:43:46.540 debug Event has attr-Tag

deconz.0 2022-11-07 12:43:46.539 debug Websocket message: {"attr":{"id":"15","lastannounced":"2022-10-09T17:23:55Z","lastseen":"2022-11-07T11:43Z","manufacturername":"innr","modelid":"SP 220","name":"Katzenbrunnen","swversion":"2.3","type":"On/Off plug-in unit","uniqueid":"0c:43:14:ff:fe:e0:10:09-01"},"e":"changed","id":"15","r":"lights","t":"event","uniqueid":"0c:43:14:ff:fe:e0:10:09-01"}

deconz.0 2022-11-07 12:43:46.539 debug Event has attr-Tag

deconz.0 2022-11-07 12:43:46.538 debug Websocket message: {"attr":{"id":"15","lastannounced":"2022-10-09T17:23:55Z","lastseen":"2022-11-07T11:43Z","manufacturername":"innr","modelid":"SP 220","name":"Katzenbrunnen","swversion":"2.3","type":"On/Off plug-in unit","uniqueid":"0c:43:14:ff:fe:e0:10:09-01"},"e":"changed","id":"15","r":"lights","t":"event","uniqueid":"0c:43:14:ff:fe:e0:10:09-01"}

deconz.0 2022-11-07 12:43:41.830 debug Websocket message: {"e":"changed","id":"37","r":"sensors","state":{"buttonevent":4002,"lastupdated":"2022-11-07T11:43:41.829"},"t":"event","uniqueid":"00:00:00:00:01:75:34:7e-f2"}

deconz.0 2022-11-07 12:43:41.639 debug Websocket message: {"e":"changed","id":"37","r":"sensors","state":{"buttonevent":4000,"lastupdated":"2022-11-07T11:43:41.638"},"t":"event","uniqueid":"00:00:00:00:01:75:34:7e-f2"}

deconz.0 2022-11-07 12:43:41.638 debug Websocket message: {"e":"changed","id":"37","r":"sensors","state":{"buttonevent":4000,"lastupdated":"2022-11-07T11:43:41.638"},"t":"event","uniqueid":"00:00:00:00:01:75:34:7e-f2"}

dklinger commented 1 year ago

But it looks like 2 open connections, as it gets every event twice.

dklinger commented 1 year ago

Can't we just check on the ws object between 576 and 577 if it's null and, if not, terminate the prior socket before creating a new one? It's not going to solve the root cause, but it should mitigate the issue, right?

I mean, as far as I can see, this is the only place where a new socket is created. Which means, for whatever reason, either user, host or port is null.

https://github.com/Jey-Cee/ioBroker.deconz/blob/7d3c67cb32ec8697739eecf6b21c8badbe80af61/main.js#L576-L577

Jey-Cee commented 1 year ago

The root cause here is that the adapter renews the websocket connection every 60 seconds, while there is no possibility to check if the connection is still working.

Your idea could be a soulution if the connection wasn't terminated before for any reason.

dklinger commented 1 year ago

Got it. How about these lines? https://github.com/Jey-Cee/ioBroker.deconz/blob/7d3c67cb32ec8697739eecf6b21c8badbe80af61/main.js#L67-L73

I think they could be changed to below, getting the 2nd if out of the 1st if: if(reconnect !== null){ clearTimeout(reconnect); } if(ws !== null){ ws.terminate(); } await getAutoUpdates();

I am not pretty sure. But can't it be that, right at the start of the instance, "reconnect" is not yet initiated but an onStateChange is fired. Leading to a new call to getAutoUpdates(), without terminating the previous connection? It's not happening often so it must be something happening rarely, maybe based on bad timing. Or how about putting a ws.terminate(); right in front of below line? https://github.com/Jey-Cee/ioBroker.deconz/blob/7d3c67cb32ec8697739eecf6b21c8badbe80af61/main.js#L577

Jey-Cee commented 1 year ago

Does your change work as solution?

dklinger commented 1 year ago

@Jey-Cee: Yes, looks like. I have no issues since I use my fork.

kopierschnitte commented 1 month ago

I'm seeing huge delays when using my FoH (Senic) switches. It takes up to 5sec for ioBroker to fire an event. This only happens with those kind of switches and only in conjunction with the ioBroker-adapter. Group events which are directly managed by DeConz are working fine without any delays.

DeConz' API viewer also immediately shows the press event ... but then it gets delayed. Could it be related?

Jey-Cee commented 1 month ago

@kopierschnitte i don't think this issue is related to your subject. If you think this is an issue with the adapter open a new issue. Add relevant information like debug log, screenshot of the switch object tree, ...

Jey-Cee / ioBroker.deconz

Deconz switches reporting "click" twice #316