Websocket closes on multiple requests

[dospaquetes]

Hello, I'm having a problem with my basic switches. When asking for multiple (any number above 1) switches to turn on/off more than ~15 seconds after the last successful request/login, only one switch responds and the websocket closes with reason 1006.

No issue arises when only asking for only one basic switch to turn on/off.

As long as my first request is within 15 seconds of websocket login, and I keep making requests within 15 seconds of each other, every command works no matter how many switches are commanded (Well, I have 5 Sonoff Basic Switches so I know it works up to 5). If not, only the first device responds.

Here's the log. You can see two successful requests right after login, but if I wait a little I get a 1006 error

[2019-1-22 05:51:54] [eWeLink] A total of [5] accessories were loaded from the local cache
[2019-1-22 05:51:54] [eWeLink] Sending login request with user credentials: {"email":"xxxxxxxxxxxx","password":"xxxxxxx","version":"6","ts":"1548132714","nonce":"154813271484300","appid":"oeVkj2lYFGnJu5XUtWisfW4utiN4u9Mq","imei":"cfe41b3e-833b-4a74-a30d-6ee0716bf3cf","os":"iOS","model":"iPhone10,6","romVersion":"11.1.2","appVersion":"3.5.3"}
[2019-1-22 05:51:54] [eWeLink] Login signature: AyCHYf5JhuiVgpZ1fI+NOX1KD9JdySyFHP90Axa0V+E=
[2019-1-22 05:51:55] [eWeLink] Authentication token received [402df6e88b65ad14119f72c4883ed9bdad3b8fd8]
[2019-1-22 05:51:55] [eWeLink] WebSocket host received [eu-pconnect2.coolkit.cc]
[2019-1-22 05:51:55] [eWeLink] Requesting a list of devices from eWeLink HTTPS API at [https://eu-api.coolkit.cc:8080]
[2019-1-22 05:51:55] [eWeLink] eWeLink HTTPS API reports that there are a total of [5] devices registered
[2019-1-22 05:51:55] [eWeLink] Evaluating if devices need to be removed...
[2019-1-22 05:51:55] [eWeLink] Verifying that all cached devices are still registered with the API. Devices that are no longer registered with the API will be removed.
[2019-1-22 05:51:55] [eWeLink] Device [Main Lights] is regeistered with API. Nothing to do.
[2019-1-22 05:51:55] [eWeLink] Device [Entrance] is regeistered with API. Nothing to do.
[2019-1-22 05:51:55] [eWeLink] Device [Bathroom] is regeistered with API. Nothing to do.
[2019-1-22 05:51:55] [eWeLink] Device [Bathroom Mirror] is regeistered with API. Nothing to do.
[2019-1-22 05:51:55] [eWeLink] Device [Kitchen] is regeistered with API. Nothing to do.
[2019-1-22 05:51:55] [eWeLink] Evaluating if new devices need to be added...
[2019-1-22 05:51:55] [eWeLink] Device with ID [100060f56b] is already configured. Ensuring that the configuration is current.
[2019-1-22 05:51:55] [eWeLink] Single channel device has been set: PSF-B01-GL
[2019-1-22 05:51:55] [eWeLink] Updating recorded Characteristic.On for [Main Lights] to [false]. No request will be sent to the device.
[2019-1-22 05:51:55] [eWeLink] Setting power state to [off] for device [Main Lights]
[2019-1-22 05:51:55] [eWeLink] Device with ID [100060e721] is already configured. Ensuring that the configuration is current.
[2019-1-22 05:51:55] [eWeLink] Single channel device has been set: PSF-B01-GL
[2019-1-22 05:51:55] [eWeLink] Updating recorded Characteristic.On for [Entrance] to [false]. No request will be sent to the device.
[2019-1-22 05:51:55] [eWeLink] Setting power state to [off] for device [Entrance]
[2019-1-22 05:51:55] [eWeLink] Device with ID [1000614a2d] is already configured. Ensuring that the configuration is current.
[2019-1-22 05:51:55] [eWeLink] Single channel device has been set: PSF-B01-GL
[2019-1-22 05:51:55] [eWeLink] Updating recorded Characteristic.On for [Bathroom] to [true]. No request will be sent to the device.
[2019-1-22 05:51:55] [eWeLink] Setting power state to [on] for device [Bathroom]
[2019-1-22 05:51:55] [eWeLink] Device with ID [10005fa578] is already configured. Ensuring that the configuration is current.
[2019-1-22 05:51:55] [eWeLink] Single channel device has been set: PSF-B01-GL
[2019-1-22 05:51:55] [eWeLink] Updating recorded Characteristic.On for [Bathroom Mirror] to [false]. No request will be sent to the device.
[2019-1-22 05:51:55] [eWeLink] Setting power state to [off] for device [Bathroom Mirror]
[2019-1-22 05:51:55] [eWeLink] Device with ID [10005fe5b6] is already configured. Ensuring that the configuration is current.
[2019-1-22 05:51:55] [eWeLink] Single channel device has been set: PSF-B01-GL
[2019-1-22 05:51:55] [eWeLink] Updating recorded Characteristic.On for [Kitchen] to [false]. No request will be sent to the device.
[2019-1-22 05:51:55] [eWeLink] Setting power state to [off] for device [Kitchen]
[2019-1-22 05:51:55] [eWeLink] API key retrieved from web service is [da979662-3c30-4482-8861-303c50b6221a]
[2019-1-22 05:51:55] [eWeLink] Connecting to the WebSocket API at [wss://eu-pconnect2.coolkit.cc:8080/api/ws]
[2019-1-22 05:51:55] [eWeLink] Sending login request [{"action":"userOnline","userAgent":"app","version":6,"nonce":"154813271554300","apkVesrion":"1.8","os":"ios","at":"402df6e88b65ad14119f72c4883ed9bdad3b8fd8","apikey":"da979662-3c30-4482-8861-303c50b6221a","ts":"1548132715","model":"iPhone10,6","romVersion":"11.1.2","sequence":1548132715543}]
[2019-1-22 05:51:55] [eWeLink] WebSocket messge received:  {"error":0,"apikey":"da979662-3c30-4482-8861-303c50b6221a","config":{"hb":1,"hbInterval":145},"sequence":"1548132715543"}
[2019-1-22 05:51:58] [eWeLink] Setting power state to [on] for device [Bathroom]
[2019-1-22 05:51:58] [eWeLink] Setting power state to [on] for device [Kitchen]
[2019-1-22 05:51:58] [eWeLink] Setting power state to [on] for device [Entrance]
[2019-1-22 05:51:58] [eWeLink] Setting power state to [on] for device [Bathroom Mirror]
[2019-1-22 05:51:58] [eWeLink] Setting power state to [on] for device [Main Lights]
[2019-1-22 05:51:58] [eWeLink] Setting power state to [on] for device [Bathroom]
[2019-1-22 05:51:58] [eWeLink] Setting power state to [on] for device [Kitchen]
[2019-1-22 05:51:58] [eWeLink] Setting power state to [on] for device [Entrance]
[2019-1-22 05:51:58] [eWeLink] Setting power state to [on] for device [Bathroom Mirror]
[2019-1-22 05:51:58] [eWeLink] Setting power state to [on] for device [Main Lights]
[2019-1-22 05:51:58] [eWeLink] WebSocket messge received:  {"error":0,"deviceid":"10005fe5b6","apikey":"da979662-3c30-4482-8861-303c50b6221a","sequence":"1548132718603"}
[2019-1-22 05:51:58] [eWeLink] WebSocket messge received:  {"error":0,"deviceid":"100060f56b","apikey":"da979662-3c30-4482-8861-303c50b6221a","sequence":"1548132718604"}
[2019-1-22 05:51:58] [eWeLink] WebSocket messge received:  {"error":0,"deviceid":"100060e721","apikey":"da979662-3c30-4482-8861-303c50b6221a","sequence":"1548132718604"}
[2019-1-22 05:51:58] [eWeLink] WebSocket messge received:  {"error":0,"deviceid":"10005fa578","apikey":"da979662-3c30-4482-8861-303c50b6221a","sequence":"1548132718604"}
[2019-1-22 05:51:58] [eWeLink] WebSocket messge received:  {"error":0,"deviceid":"1000614a2d","apikey":"da979662-3c30-4482-8861-303c50b6221a","sequence":"1548132718602"}
[2019-1-22 05:52:03] [eWeLink] WebSocket messge received:  {"error":504,"reason":"Request Timeout","deviceid":"100060e721","apikey":"da979662-3c30-4482-8861-303c50b6221a","sequence":"1548132718361"}
[2019-1-22 05:52:03] [eWeLink] WebSocket messge received:  {"error":504,"reason":"Request Timeout","deviceid":"100060f56b","apikey":"da979662-3c30-4482-8861-303c50b6221a","sequence":"1548132718363"}
[2019-1-22 05:52:03] [eWeLink] WebSocket messge received:  {"error":504,"reason":"Request Timeout","deviceid":"10005fa578","apikey":"da979662-3c30-4482-8861-303c50b6221a","sequence":"1548132718362"}
[2019-1-22 05:52:03] [eWeLink] WebSocket messge received:  {"error":504,"reason":"Request Timeout","deviceid":"1000614a2d","apikey":"da979662-3c30-4482-8861-303c50b6221a","sequence":"1548132718359"}
[2019-1-22 05:52:03] [eWeLink] WebSocket messge received:  {"error":504,"reason":"Request Timeout","deviceid":"10005fe5b6","apikey":"da979662-3c30-4482-8861-303c50b6221a","sequence":"1548132718360"}
[2019-1-22 05:52:03] [eWeLink] Setting power state to [off] for device [Bathroom]
[2019-1-22 05:52:03] [eWeLink] Setting power state to [off] for device [Bathroom Mirror]
[2019-1-22 05:52:03] [eWeLink] Setting power state to [off] for device [Main Lights]
[2019-1-22 05:52:03] [eWeLink] Setting power state to [off] for device [Kitchen]
[2019-1-22 05:52:03] [eWeLink] Setting power state to [off] for device [Entrance]
[2019-1-22 05:52:03] [eWeLink] WebSocket messge received:  {"error":0,"deviceid":"10005fa578","apikey":"da979662-3c30-4482-8861-303c50b6221a","sequence":"1548132723492"}
[2019-1-22 05:52:03] [eWeLink] WebSocket messge received:  {"error":0,"deviceid":"1000614a2d","apikey":"da979662-3c30-4482-8861-303c50b6221a","sequence":"1548132723491"}
[2019-1-22 05:52:03] [eWeLink] WebSocket messge received:  {"error":0,"deviceid":"100060f56b","apikey":"da979662-3c30-4482-8861-303c50b6221a","sequence":"1548132723493"}
[2019-1-22 05:52:03] [eWeLink] WebSocket messge received:  {"error":0,"deviceid":"100060e721","apikey":"da979662-3c30-4482-8861-303c50b6221a","sequence":"1548132723494"}
[2019-1-22 05:52:03] [eWeLink] WebSocket messge received:  {"error":0,"deviceid":"10005fe5b6","apikey":"da979662-3c30-4482-8861-303c50b6221a","sequence":"1548132723494"}
[2019-1-22 05:52:32] [eWeLink] Setting power state to [on] for device [Bathroom]
[2019-1-22 05:52:32] [eWeLink] Setting power state to [on] for device [Kitchen]
[2019-1-22 05:52:32] [eWeLink] Setting power state to [on] for device [Entrance]
[2019-1-22 05:52:32] [eWeLink] Setting power state to [on] for device [Bathroom Mirror]
[2019-1-22 05:52:32] [eWeLink] Setting power state to [on] for device [Main Lights]
[2019-1-22 05:52:32] [eWeLink] WebSocket was closed. Reason [1006]
WebSocketClient: reconnecting...
[2019-1-22 05:52:37] [eWeLink] Sending login request [{"action":"userOnline","userAgent":"app","version":6,"nonce":"154813275774500","apkVesrion":"1.8","os":"ios","at":"402df6e88b65ad14119f72c4883ed9bdad3b8fd8","apikey":"da979662-3c30-4482-8861-303c50b6221a","ts":"1548132757","model":"iPhone10,6","romVersion":"11.1.2","sequence":1548132757745}]
[2019-1-22 05:52:37] [eWeLink] WebSocket messge received:  {"error":0,"apikey":"da979662-3c30-4482-8861-303c50b6221a","config":{"hb":1,"hbInterval":145},"sequence":"1548132757745"}

I hope I was as descriptive as possible. I edited out my credentials, obviously

[dospaquetes]

I was thinking maybe adding a slight delay between simultaneous requests would help? Tbh I haven't had my hands in code in a long time so I'm hesitant to get into it myself

[dospaquetes]

Fixed it by adding a 100ms delay after platform.wsc.send(string) in the setPowerState function. Did it super dirty but it works

`if (platform.isSocketOpen) {

    setTimeout(function() {
        platform.wsc.send(string);

        // TODO Here we need to wait for the response to the socket
        var waitTill = new Date(new Date().getTime() + 100);
        while(waitTill > new Date()){}

        callback();
    }, 1);

[howanghk]

Thanks! I will look into this and implement a fix.

[rcapolino]

Fixed it by adding a 100ms delay after platform.wsc.send(string) in the setPowerState function. Did it super dirty but it works

`if (platform.isSocketOpen) {

    setTimeout(function() {
        platform.wsc.send(string);

        // TODO Here we need to wait for the response to the socket
      var waitTill = new Date(new Date().getTime() + 100);
      while(waitTill > new Date()){}

        callback();
    }, 1);

Hi, thanks for support. where do I enter this code?

Thanks..

[howanghk]

Hi @rcapolino, I'm still working on a proper fix for this. In the meantime you may use dospaquetes's fork https://github.com/dospaquetes/homebridge-ewelink

[daveramirez5]

Hello. I can make the dispaquete’s fork to work. I wonder if you have had the chance to merge it into yours? Count me in if you need people to test it out. Regards.

[howanghk]

Hi @daveramirez5, dospaquetes's fork add a small delay to setPowerState, although this may work but this does not 100% address the issue. The proper way to fix this is to implement a request-response mechanism for the websocket messages, and only send the next message after we got response for the previous one. Unfortunately I still don't have time to write code for this yet. If you happen to know programming, please consider contributing to the this project!

[rob0101]

Here's my attempt at a fix.

The approach is to not allow new WebSocket send requests to leave until the previous one has responded. Seems to work for me. Contains extra debugging output that should be removed at a later date.

Thoughts ?

https://github.com/howanghk/homebridge-ewelink/compare/master...rob0101:master

[rob0101]

[01/07/2019, 4:42:24 pm] [eWeLink] Setting power state to [off] for device [eWeSwitch3] [01/07/2019, 4:42:24 pm] [eWeLink] Setting power state to [off] for device [eWeSwitch1] [01/07/2019, 4:42:24 pm] [eWeLink] Setting power state to [off] for device [eWeSwitch4] [01/07/2019, 4:42:24 pm] [eWeLink] WebSocket messge received: {"error":0,"deviceid":"xxxx","apikey":"yyyyyyy","sequence":"1561965144113"} [01/07/2019, 4:42:24 pm] [eWeLink] ========== sendIfSafe Waited 0.5s so far. [01/07/2019, 4:42:24 pm] [eWeLink] ========== sendIfSafe now CLEAR [01/07/2019, 4:42:24 pm] [eWeLink] **** ========== sendIfSafe Waited 0.5s so far. [01/07/2019, 4:42:25 pm] [eWeLink] WebSocket messge received: {"error":0,"deviceid":"xxxx","apikey":"yyyyyyy","sequence":"1561965144113"} [01/07/2019, 4:42:25 pm] [eWeLink] ========== sendIfSafe Waited 1s so far. [01/07/2019, 4:42:25 pm] [eWeLink] *** ========== sendIfSafe now CLEAR **** [01/07/2019, 4:42:25 pm] [eWeLink] WebSocket messge received: {"error":0,"deviceid":"xxxxxxx","apikey":"yyyyyyy","sequence":"1561965144113"}

[rob0101]

I never received any feedback on this fix.

I forgot I had this fix and updated the ewelink-homebridge and immediately lost reliable control over my devices when they are grouped and turned on/off together.

How are other people having any luck without a fix for this in place ?

I merged my code back into the main branch and all works again.

[howanghk]

Hi @rob0101 there's a similar fix https://github.com/howanghk/homebridge-ewelink/pull/66 merged and relased in 0.1.18 on Dec 16, 2019. I looked at your fork the last commit was dated Jun 30, 2019. Is the fix in 0.1.18 not helping your situation?

[danielk117]

Hi @howanghk, I'm using the latest version of your plugin and got the same problem with automation and multiple devices.

[danielk117]

The error exists only for blinds. I was able to correct the error #82.