dxdc/homebridge-blinds

Socket hangup errors when using simultaneously open/close requests

hjkempel opened this issue · 22 comments

hjkempel commented

Hi, I tried to manage 6 shutters by using a homekit automation to open/close the shutters simultaneously. But it seems that the underlying nodejs layer is not able to handle this number of requests simultaneously ("Error: This callback function has already been called by someone else; it can only be called one time.")

At least this scenario ends in the termination and restart of the homebridge service ("Got SIGTERM, shutting down Homebridge...").

If I reduce the number of shutters to 3 the homekit automation or manually interaction is working as expected. So it seems there is a kind of race condition or ressource limitation using the plugin.

I'm experimenting with an additional homebridge plugin (homebridge-delay-switch) to model a delayed activation cascade for the shutters, seems to work but leads to cluttered automation rules.

So my question is how to avoid or fix this error. I'm not familiar with nodejs so having a first look to the corresponding source lines from the trace back does not lead to a possible solution.

Thanks in advance for any feedback.

Kind regards, hjk

Dez 27 18:00:00 raspberrypi homebridge[25589]: [27.12.2019, 18:00:00] [Schlafzimmer Rechts] Requested Move down (to 12%)
Dez 27 18:00:00 raspberrypi homebridge[25589]: [27.12.2019, 18:00:00] [Schlafzimmer Links] Requested Move down (to 12%)
Dez 27 18:00:00 raspberrypi homebridge[25589]: [27.12.2019, 18:00:00] [Esszimmer Mitte] Requested Move down (to 0%)
Dez 27 18:00:00 raspberrypi homebridge[25589]: [27.12.2019, 18:00:00] [Esszimmer Links] Requested Move down (to 0%)
Dez 27 18:00:00 raspberrypi homebridge[25589]: [27.12.2019, 18:00:00] [Esszimmer Rechts] Requested Move down (to 0%)
Dez 27 18:00:00 raspberrypi homebridge[25589]: [27.12.2019, 18:00:00] [Küche Alle] Requested Move down (to 0%)
Dez 27 18:00:00 raspberrypi homebridge[25589]: [27.12.2019, 18:00:00] [Schlafzimmer Rechts] Move request sent (312 ms), waiting 8.8s (+ 0s response lag)...
Dez 27 18:00:00 raspberrypi homebridge[25589]: [27.12.2019, 18:00:00] [Schlafzimmer Links] Move request sent (531 ms), waiting 8.8s (+ 0s response lag)...
Dez 27 18:00:00 raspberrypi homebridge[25589]: [27.12.2019, 18:00:00] [Esszimmer Mitte] Move request sent (575 ms), waiting 20s (+ 0s response lag)...
Dez 27 18:00:09 raspberrypi homebridge[25589]: [27.12.2019, 18:00:09] [Schlafzimmer Rechts] End Move down (to 12%)
Dez 27 18:00:09 raspberrypi homebridge[25589]: [27.12.2019, 18:00:09] [Schlafzimmer Rechts] Stop request sent
Dez 27 18:00:09 raspberrypi homebridge[25589]: [27.12.2019, 18:00:09] [Schlafzimmer Links] End Move down (to 12%)
Dez 27 18:00:09 raspberrypi homebridge[25589]: [27.12.2019, 18:00:09] [Schlafzimmer Links] Stop request sent
Dez 27 18:00:11 raspberrypi homebridge[25589]: [27.12.2019, 18:00:11] [Esszimmer Links] Error sending request (HTTP status code not defined): Error: socket hang up
Dez 27 18:00:11 raspberrypi homebridge[25589]: [27.12.2019, 18:00:11] [Esszimmer Links] Body: undefined
Dez 27 18:00:11 raspberrypi homebridge[25589]: [27.12.2019, 18:00:11] Error: This callback function has already been called by someone else; it can only be called one time.
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at /usr/local/lib/node_modules/homebridge/node_modules/hap-nodejs/lib/util/once.js:12:13
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at BlindsHTTPAccessory.<anonymous> (/usr/local/lib/node_modules/homebridge-blinds/index.js:113:13)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at BlindsHTTPAccessory.<anonymous> (/usr/local/lib/node_modules/homebridge-blinds/index.js:182:13)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at self.callback (/usr/local/lib/node_modules/homebridge-blinds/node_modules/request/request.js:185:22)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at Request.emit (events.js:189:13)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at Request.onRequestError (/usr/local/lib/node_modules/homebridge-blinds/node_modules/request/request.js:881:8)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at ClientRequest.emit (events.js:189:13)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at Socket.socketOnEnd (_http_client.js:426:9)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at Socket.emit (events.js:194:15)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at endReadableNT (_stream_readable.js:1103:12)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at process._tickCallback (internal/process/next_tick.js:63:19)
Dez 27 18:00:11 raspberrypi homebridge[25589]: [27.12.2019, 18:00:11] [Esszimmer Rechts] Error sending request (HTTP status code not defined): Error: socket hang up
Dez 27 18:00:11 raspberrypi homebridge[25589]: [27.12.2019, 18:00:11] [Esszimmer Rechts] Body: undefined
Dez 27 18:00:11 raspberrypi homebridge[25589]: [27.12.2019, 18:00:11] Error: This callback function has already been called by someone else; it can only be called one time.
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at /usr/local/lib/node_modules/homebridge/node_modules/hap-nodejs/lib/util/once.js:12:13
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at BlindsHTTPAccessory.<anonymous> (/usr/local/lib/node_modules/homebridge-blinds/index.js:113:13)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at BlindsHTTPAccessory.<anonymous> (/usr/local/lib/node_modules/homebridge-blinds/index.js:182:13)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at self.callback (/usr/local/lib/node_modules/homebridge-blinds/node_modules/request/request.js:185:22)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at Request.emit (events.js:189:13)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at Request.onRequestError (/usr/local/lib/node_modules/homebridge-blinds/node_modules/request/request.js:881:8)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at ClientRequest.emit (events.js:189:13)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at Socket.socketOnEnd (_http_client.js:426:9)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at Socket.emit (events.js:194:15)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at endReadableNT (_stream_readable.js:1103:12)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at process._tickCallback (internal/process/next_tick.js:63:19)
Dez 27 18:00:11 raspberrypi homebridge[25589]: [27.12.2019, 18:00:11] [Küche Alle] Error sending request (HTTP status code not defined): Error: socket hang up
Dez 27 18:00:11 raspberrypi homebridge[25589]: [27.12.2019, 18:00:11] [Küche Alle] Body: undefined
Dez 27 18:00:11 raspberrypi homebridge[25589]: [27.12.2019, 18:00:11] Error: This callback function has already been called by someone else; it can only be called one time.
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at /usr/local/lib/node_modules/homebridge/node_modules/hap-nodejs/lib/util/once.js:12:13
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at BlindsHTTPAccessory.<anonymous> (/usr/local/lib/node_modules/homebridge-blinds/index.js:113:13)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at BlindsHTTPAccessory.<anonymous> (/usr/local/lib/node_modules/homebridge-blinds/index.js:182:13)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at self.callback (/usr/local/lib/node_modules/homebridge-blinds/node_modules/request/request.js:185:22)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at Request.emit (events.js:189:13)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at Request.onRequestError (/usr/local/lib/node_modules/homebridge-blinds/node_modules/request/request.js:881:8)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at ClientRequest.emit (events.js:189:13)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at Socket.socketOnEnd (_http_client.js:426:9)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at Socket.emit (events.js:194:15)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at endReadableNT (_stream_readable.js:1103:12)
Dez 27 18:00:11 raspberrypi homebridge[25589]:     at process._tickCallback (internal/process/next_tick.js:63:19)
Dez 27 18:00:11 raspberrypi homebridge[25589]: [27.12.2019, 18:00:11] Got SIGTERM, shutting down Homebridge...
Dez 27 18:00:16 raspberrypi systemd[1]: homebridge.service: Main process exited, code=exited, status=143/n/a
Dez 27 18:00:16 raspberrypi systemd[1]: homebridge.service: Failed with result 'exit-code'.
Dez 27 18:00:26 raspberrypi systemd[1]: homebridge.service: Service RestartSec=10s expired, scheduling restart.
Dez 27 18:00:26 raspberrypi systemd[1]: homebridge.service: Scheduled restart job, restart counter is at 1.
Dez 27 18:00:26 raspberrypi systemd[1]: Stopped Node.js HomeKit Server.
Dez 27 18:00:26 raspberrypi systemd[1]: Started Node.js HomeKit Server.
dxdc commented

@hjkempel thanks for your detailed report.

I believe I've traced the issue here, and invite you to update the repo:

  • sudo npm install -g homebridge-blinds
  • restart homebridge so changes will take effect, e.g., pm2 restart homebridge depending on your set up
  • try your scenario again

I think the issue is that in your config.json you had probably omitted stopURL for "Esszimmer Mitte", though I don't have a way to verify this. Because of that, it was failing. Please let me know if this closes the issue! If not, please share your config.json (you can mask URL parameters as needed) so I can troubleshoot further.

hjkempel commented

@dxdc thanks for your fast reply and support.

I have updated the plugin, but that has not fixed my issue.
But meanwhile I have made several additional tests and traced the network communication using wireshark. Good news for you - it's not a problem of your plugin, it seems to be caused by the poor implementation of device control unit for the shutters.

Since my shutters are controlled by Somfy RTS devices my plan was using a homewizard gateway and having a homebridge integration to homekit to do the smart home automation.
Main motivation for using the homewizard gateway was the ability to control the shutters based on their 433MHz protocol without having any additional electrical installation for the shutters.

But my tests displayed the limits of the homewizard gateway implementation when using URL requests in parallel. When using the requests in a sequential way, the szenarios are working OK.
But if you having more than three requests in parallel, the processing got stuck, requests and responses got kicked. I have rebuild the szenarios using simple curl requests, but if I'm using more than three requests in parallel, again the same failures.

Since the further development of the homewizard platform seems to be dead, only way to solve my problem is to divide the shutter control into smaller pieces.

Again - as said in the beginning - thanks for your support.
Happy new year and kind regards, hjk

dxdc commented

@hjkempel thanks for your explanation. I was wondering if something like that was happening on your side as well. That being said, the plugin shouldn't force homebridge to restart.

I was mostly concerned about this line:

Error: This callback function has already been called by someone else; it can only be called one time.

I think I finally caught this issue in the latest release. Have you tested how many ms are required between curl requests? I could add an option to randomize the number of ms before sending the initial HTTP request to help people avoid situations like this. It probably doesn't make sense to also do it for the stop request since the timing would be off though. But adding 50-300 ms of delay before sending the initial request could be OK.

I've used Bond (https://bondhome.io/) to send up to 4 simultaneous requests at once, but never had a need for more than that.

peros550 commented

@dxdc I also had some issues with an automation at home which was supposed to close two windows.
Sometimes, only one of the windows received the command leaving the other one open.

Is the 1.3.3 add a new delay between the commands and if yes, is the delay customizable?

dxdc commented

Sometimes, only one of the windows received the command leaving the other one open.

Is this caused by:

  1. The RF transmitting device not receiving the request (timing out, would show in the log files)
  2. The RF receiver (blinds) not receiving the request properly - e.g., because the signal was jammed.

Is it always the same window that doesn't receive the command? Did you try 're-learning' the remote?

Is the 1.3.3 add a new delay between the commands and if yes, is the delay customizable?

@peros550 the feature is not there yet, but I'd consider adding it. The tricky part is that it probably has to be random (and not specified), since different windows could be used in different combinations, so not sure if individually specifying them per window would be helpful or not.

How many ms of delay would be required on your side, do you know?

peros550 commented

@dxdc hi!
RF is not the cause of the issue in my case (although a totally good point for people who use multiple remotes).
In my case, I have used a single esp8266 board which runs a webserver and when receives specific http requests, it controls a 4ch relay board. The relay board is wired to a multi-channel RF remote. For every command, I select channel (emulating next button presses) and then issue the command (UP/STOP/DOWN).
Pic of the board

I can estimate that, I would need up to 2-3sec for my board to issue a full command (4xNEXT, & COMMAND)

Let me give a few examples:
The following command>>
http://192.168.0.10/UP-1
will emulate the following button presses:
NEXT,UP
This command:
http://192.168.0.10/DOWN-3
will emulate the following button presses:
NEXT,NEXT,NEXT,DOWN

dxdc commented

@peros550 hmm. I would suggest instead then having the web server on your esp8266 board cache the requests and issue them 4 seconds later. I think it would be easier.

The plugin has no knowledge of how many simultaneous requests are being issued. Therefore, I think it could get very complicated in your case to reduce the probability of a "collision". Modifying the webserver code seems simpler.

The other option could be to insert a separate plugin which essentially does the same job. In other words:

All sent in parallel. Then, the receiving server will redirect them - one at a time (with 4 sec delay in between) - to your esp8266 board.

dxdc commented

(Note that in any of the above cases with your set up, the use of a STOP command wouldn't make much sense most likely.)

peros550 commented

I'm already using a queue object to cache incoming requests, but I have a feeling that some of them may get lost therefore not in the queue to process. That's why I asked about the potential new feature of adding a customizable delay between commands.

dxdc commented

@peros550 the problem is we don't know how many requests are being sent. For example, if 2 blinds are sent up and 2 down vs. 8 requests, how should we properly stagger the delays? Without some kind of more sophisticated tracking of requests, there is no way for the plugin to know how many requests were made simultaneously.

So, there are a few options:

  1. A pre-defined ms for each blinds such that two requests could never overlap. In other words, if you had 6 blinds and wanted 4 sec each, you could do: a) 0 sec delay; b) 4 sec delay; c) 8 sec delay; d) 12 sec delay, e) 16 sec delay; f) 20 sec delay. Not sure it's practical? But it would prevent overlaps.

  2. A random ms for each blinds such that two requests have a low probability of collision.

  3. A more sophisticated variant where the number of simultaneous requests is tracked.

Are you preferential to one of the options? PR's are welcome as well :)

hjkempel commented

@dxdc Hi,
I made some additional tests including your latest code change.
This change prevents crashing the homebridge service, nevertheless the execution of more than 3 parallel requests against my homewizard device will cause failures, but no more crashes. Thanks for that fix.

Before plugin update

[1.1.2020, 14:27:22] [Schlafzimmer Links] Requested Move up (to 100%)
[1.1.2020, 14:27:22] [Esszimmer Links] Requested Move up (to 100%)
[1.1.2020, 14:27:22] [Schlafzimmer Rechts] Requested Move up (to 100%)
[1.1.2020, 14:27:22] [Esszimmer Rechts] Requested Move up (to 100%)
[1.1.2020, 14:27:22] [Schlafzimmer Links] Move request sent (268 ms), waiting 10s (+ 0s response lag)...
[1.1.2020, 14:27:22] [Esszimmer Links] Move request sent (410 ms), waiting 10s (+ 0s response lag)...
[1.1.2020, 14:27:22] [Esszimmer Links] Timeout finished
[1.1.2020, 14:27:22] [Schlafzimmer Rechts] Move request sent (552 ms), waiting 10s (+ 0s response lag)...
[1.1.2020, 14:27:32] [Schlafzimmer Links] End Move up (to 100%)
[1.1.2020, 14:27:32] [Esszimmer Links] End Move up (to 100%)
[1.1.2020, 14:27:32] [Schlafzimmer Rechts] End Move up (to 100%)
[1.1.2020, 14:27:33] [Esszimmer Rechts] Error sending request (HTTP status code not defined): Error: socket hang up
[1.1.2020, 14:27:33] [Esszimmer Rechts] Body: undefined
[1.1.2020, 14:27:33] Error: This callback function has already been called by someone else; it can only be called one time.
    at /usr/local/lib/node_modules/homebridge/node_modules/hap-nodejs/lib/util/once.js:12:13
    at BlindsHTTPAccessory.<anonymous> (/usr/local/lib/node_modules/homebridge-blinds/index.js:113:13)
    at BlindsHTTPAccessory.<anonymous> (/usr/local/lib/node_modules/homebridge-blinds/index.js:186:13)
    at self.callback (/usr/local/lib/node_modules/homebridge-blinds/node_modules/request/request.js:185:22)
    at Request.emit (events.js:189:13)
    at Request.onRequestError (/usr/local/lib/node_modules/homebridge-blinds/node_modules/request/request.js:881:8)
    at ClientRequest.emit (events.js:189:13)
    at Socket.socketOnEnd (_http_client.js:426:9)
    at Socket.emit (events.js:194:15)
    at endReadableNT (_stream_readable.js:1103:12)
    at process._tickCallback (internal/process/next_tick.js:63:19)
[1.1.2020, 14:27:33] Got SIGTERM, shutting down Homebridge...
homebridge.service: Main process exited, code=exited, status=143/n/a
homebridge.service: Failed with result 'exit-code'.

After plugin update

[1.1.2020, 14:42:40] [Schlafzimmer Links] Requested Move up (to 100%)
[1.1.2020, 14:42:40] [Esszimmer Rechts] Requested Move up (to 100%)
[1.1.2020, 14:42:40] [Schlafzimmer Rechts] Requested Move up (to 100%)
[1.1.2020, 14:42:40] [Esszimmer Links] Requested Move up (to 100%)
[1.1.2020, 14:42:40] [Schlafzimmer Links] Move request sent (329 ms), waiting 10s (+ 0s response lag)...
[1.1.2020, 14:42:40] [Esszimmer Rechts] Move request sent (454 ms), waiting 10s (+ 0s response lag)...
[1.1.2020, 14:42:40] [Esszimmer Rechts] Timeout finished
[1.1.2020, 14:42:41] [Schlafzimmer Rechts] Move request sent (594 ms), waiting 10s (+ 0s response lag)...
[1.1.2020, 14:42:50] [Schlafzimmer Links] End Move up (to 100%)
[1.1.2020, 14:42:51] [Esszimmer Rechts] End Move up (to 100%)
[1.1.2020, 14:42:51] [Schlafzimmer Rechts] End Move up (to 100%)
[1.1.2020, 14:42:51] [Esszimmer Links] Error sending request (HTTP status code not defined): Error: socket hang up
[1.1.2020, 14:42:51] [Esszimmer Links] Body: undefined
hjkempel commented

Have you tested how many ms are required between curl requests?

I have made further experiments with delayed curl requests.
With a delay of 200 ms between the request, the processing is stable - no requests and replys are getting lost. If I reduce the delay in further steps down to 50 ms, the processing of requests starts to fail.

So from my side an additional config option (e.g. delay) to specify a minimum delay between the execution of commands would perfect fit. I agree your previous statements not to add complex logic since the plugin should not care about how many requests can be executed simultaneously.
I have no need to specify different delays for the down, up or stop command - may be this could be a further step of extension the plugin. Regarding the processing the delay should be used to asure a minimal time distance between the execution of commands and no been applied to any command execution before.

Since I have stated before I'm not familiar with NodeJS, so providing a PR would be hard for me - sorry. But I can surely offer support for testing additional plugin features.

Kind regards, hjk

dxdc commented

I have made further experiments with delayed curl requests.

Thank you for these details @hjkempel, and glad to know the plugin is not crashing anymore.

I have some good news for you and @peros550. I felt inspired with a solution to the above issues, and have released a new version that I think addresses your concerns.

I've implemented a node module called requestretry that has allowed the addition of 2 new parameters for config.json:

  • max_http_attempts
  • retry_delay

It allows us to define the maximum number of HTTP attempts (default = 5), and the maximum time between requests before considering them 'failed' (default = 2000 ms). I think this may be the best of both worlds. It won't care about why the request failed, it will just retry the request after the prescribed time interval, and it will only retry in the event of 5xx error or network timeout/socket hangup.

I think it should work for most people with the default options (no need to change config.json), so please try as follows:

  • sudo npm install -g homebridge-blinds
  • restart homebridge so changes will take effect, e.g., pm2 restart homebridge depending on your set up
  • try your scenario again
dxdc commented

Also @peros550:

I'm already using a queue object to cache incoming requests, but I have a feeling that some of them may get lost therefore not in the queue to process

I intended the solution here to still take advantage of your queue. Trying to queue the requests within the plugin is a lot more effort, but at least this should keep any requests from dropping if there is a network timeout.

peros550 commented

@dxdc thank you! I will definitely update and report back! Because we are away from home, I will be able to let you know in a few days. Happy New Year!

hjkempel commented

@dxdc Hi,
I have made serveral tests using the new plugin release version.
With this change my automation scenarios are now running stable, sometimes there is a little delay when a request is lost and is retried again - normally no problem, just in case of a lost and therefore repeated stop command, the final shutter position is not correct. But this happens only in rare cases - so I'm fine with the current release version.

I have inserted an additional log statement in my local installation to identify repeated requests to make the automation procedure a bit clearer.
May be you can insert the log statement in your code:
this.log.info(Request successfull processed with attempt ${response.attempts});

The following log shows the automation procedure for 6 shutter devices. Device 1 and 2 should stop when shutter is 90% closed. Requests for device 5, device 4 and device 2 are repeated due to failure.

[4.1.2020, 17:59:59] [ID:1 SleepingRoom Right] Requested Move down (to 10%)
[4.1.2020, 17:59:59] [ID:6 DiningRoom Middle] Requested Move down (to 0%)
[4.1.2020, 17:59:59] [ID:3 Kitchen All] Requested Move down (to 0%)
[4.1.2020, 17:59:59] [ID:5 DiningRoom Right] Requested Move down (to 0%)
[4.1.2020, 17:59:59] [ID:4 DiningRoom Left] Requested Move down (to 0%)
[4.1.2020, 17:59:59] [ID:2 SleepingRoom Left] Requested Move down (to 10%)
[4.1.2020, 17:59:59] [ID:1 SleepingRoom Right] Request successfull processed with attempt 1
[4.1.2020, 17:59:59] [ID:1 SleepingRoom Right] Move request sent (316 ms), waiting 9s (+ 0s response lag)...
[4.1.2020, 17:59:59] [ID:1 SleepingRoom Right] Stop command will be requested
[4.1.2020, 18:00:00] [ID:6 DiningRoom Middle] Request successfull processed with attempt 1
[4.1.2020, 18:00:00] [ID:6 DiningRoom Middle] Move request sent (458 ms), waiting 20s (+ 0s response lag)...
[4.1.2020, 18:00:00] [ID:3 Kitchen All] Request successfull processed with attempt 1
[4.1.2020, 18:00:00] [ID:3 Kitchen All] Move request sent (591 ms), waiting 10s (+ 0s response lag)...
[4.1.2020, 18:00:09] [ID:1 SleepingRoom Right] End Move down (to 10%)
[4.1.2020, 18:00:10] [ID:3 Kitchen All] End Move down (to 0%)
[4.1.2020, 18:00:13] [ID:5 DiningRoom Right] Request successfull processed with attempt 2
[4.1.2020, 18:00:13] [ID:5 DiningRoom Right] Move request sent (13502 ms), waiting 20s (+ 0s response lag)...
[4.1.2020, 18:00:13] [ID:4 DiningRoom Left] Request successfull processed with attempt 2
[4.1.2020, 18:00:13] [ID:4 DiningRoom Left] Move request sent (13588 ms), waiting 20s (+ 0s response lag)...
[4.1.2020, 18:00:13] [ID:2 SleepingRoom Left] Request successfull processed with attempt 2
[4.1.2020, 18:00:13] [ID:2 SleepingRoom Left] Move request sent (13814 ms), waiting 9s (+ 0s response lag)...
[4.1.2020, 18:00:13] [ID:2 SleepingRoom Left] Stop command will be requested
[4.1.2020, 18:00:20] [ID:6 DiningRoom Middle] End Move down (to 0%)
[4.1.2020, 18:00:22] [ID:2 SleepingRoom Left] End Move down (to 10%)
[4.1.2020, 18:00:22] [ID:2 SleepingRoom Left] Request successfull processed with attempt 1
[4.1.2020, 18:00:22] [ID:2 SleepingRoom Left] Stop request sent
[4.1.2020, 18:00:33] [ID:5 DiningRoom Right] End Move down (to 0%)
[4.1.2020, 18:00:33] [ID:4 DiningRoom Left] End Move down (to 0%)

Thanks for your support and kind regards, hjk

dxdc commented

@hjkempel thanks for your support in testing this. Glad to know it's much more functional for these cases.

in case of a lost and therefore repeated stop command, the final shutter position is not correct.

Yes, of course this will be true. It's a function of your network. To help reduce a lack of collisions, you could try to have the motionTime be slightly different for each. For example 10000 vs. 9800. This way, it will reduce the chance of a collision when stop is fired with a negligible change to the overall position. (Note: I chose this value since you said only 200 ms was a required difference).

May be you can insert the log statement in your code:

I modified your concept in the following commit. Can you please test this on your version? I think the logging should not be by default if it succeeded on the first attempt so I modified it as such. If it's working well, I can bundle it with the next release.

2badd7d

hjkempel commented

@dxdc Hi,
I have tested your latest code change concerning the log statements.
Change is working as expected, so you can bundle it with the next release.

Thanks and kind regards, hjk

[5.1.2020, 11:23:05] [ID:2 SleepingRoom Left] Requested Move down (to 10%)
[5.1.2020, 11:23:05] [ID:3 Kitchen All] Requested Move down (to 0%)
[5.1.2020, 11:23:05] [ID:6 DiningRoom Middle] Requested Move down (to 0%)
[5.1.2020, 11:23:05] [ID:5 DiningRoom Right] Requested Move down (to 0%)
[5.1.2020, 11:23:05] [ID:4 DiningRoom Left] Requested Move down (to 0%)
[5.1.2020, 11:23:05] [ID:1 SleepingRoom Right] Requested Move down (to 10%)
[5.1.2020, 11:23:05] [ID:2 SleepingRoom Left] Request succeeded after 1 / 5 attempts
[5.1.2020, 11:23:05] [ID:2 SleepingRoom Left] Move request sent (364 ms), waiting 8.9s (+ 0s response lag)...
[5.1.2020, 11:23:05] [ID:2 SleepingRoom Left] Stop command will be requested
[5.1.2020, 11:23:05] [ID:2 SleepingRoom Left] Timeout finished
[5.1.2020, 11:23:05] [ID:3 Kitchen All] Request succeeded after 1 / 5 attempts
[5.1.2020, 11:23:05] [ID:3 Kitchen All] Move request sent (484 ms), waiting 10s (+ 0s response lag)...
[5.1.2020, 11:23:05] [ID:3 Kitchen All] Timeout finished
[5.1.2020, 11:23:06] [ID:6 DiningRoom Middle] Request succeeded after 1 / 5 attempts
[5.1.2020, 11:23:06] [ID:6 DiningRoom Middle] Move request sent (633 ms), waiting 20s (+ 0s response lag)...
[5.1.2020, 11:23:06] [ID:6 DiningRoom Middle] Timeout finished
[5.1.2020, 11:23:14] [ID:2 SleepingRoom Left] End Move down (to 10%)
[5.1.2020, 11:23:14] [ID:2 SleepingRoom Left] Request succeeded after 1 / 5 attempts
[5.1.2020, 11:23:14] [ID:2 SleepingRoom Left] Stop request sent
[5.1.2020, 11:23:16] [ID:3 Kitchen All] End Move down (to 0%)
[5.1.2020, 11:23:18] [ID:5 DiningRoom Right] Request succeeded after 2 / 5 attempts
[5.1.2020, 11:23:18] [ID:5 DiningRoom Right] Move request sent (13424 ms), waiting 20s (+ 0s response lag)...
[5.1.2020, 11:23:18] [ID:5 DiningRoom Right] Timeout finished
[5.1.2020, 11:23:18] [ID:4 DiningRoom Left] Request succeeded after 2 / 5 attempts
[5.1.2020, 11:23:18] [ID:4 DiningRoom Left] Move request sent (13557 ms), waiting 20s (+ 0s response lag)...
[5.1.2020, 11:23:18] [ID:4 DiningRoom Left] Timeout finished
[5.1.2020, 11:23:19] [ID:1 SleepingRoom Right] Request succeeded after 2 / 5 attempts
[5.1.2020, 11:23:19] [ID:1 SleepingRoom Right] Move request sent (13702 ms), waiting 9.1s (+ 0s response lag)...
[5.1.2020, 11:23:19] [ID:1 SleepingRoom Right] Stop command will be requested
[5.1.2020, 11:23:19] [ID:1 SleepingRoom Right] Timeout finished
[5.1.2020, 11:23:26] [ID:6 DiningRoom Middle] End Move down (to 0%)
[5.1.2020, 11:23:28] [ID:1 SleepingRoom Right] End Move down (to 10%)
[5.1.2020, 11:23:28] [ID:1 SleepingRoom Right] Request succeeded after 1 / 5 attempts
[5.1.2020, 11:23:28] [ID:1 SleepingRoom Right] Stop request sent
[5.1.2020, 11:23:39] [ID:5 DiningRoom Right] End Move down (to 0%)
[5.1.2020, 11:23:39] [ID:4 DiningRoom Left] End Move down (to 0%)
peros550 commented

Tested today latest version 1.3.6. My blinds work perfectly so far. I have noticed the following logs:

Jan 05 14:22:35 raspberrypi homebridge[12713]: [2020-1-5 14:22:35] [Bedroom Window] Already there: 100%, re-sending request
Jan 05 14:22:35 raspberrypi homebridge[12713]: [2020-1-5 14:22:35] [Bedroom Window] Requested Move up (to 100%)
Jan 05 14:22:35 raspberrypi homebridge[12713]: [2020-1-5 14:22:35] [Living Room Window] Move request sent (45 ms), waiting 0s (+ 0s response lag)...
Jan 05 14:22:35 raspberrypi homebridge[12713]: [2020-1-5 14:22:35] [Bedroom Window] Move request sent (55 ms), waiting 0s (+ 0s response lag)...
Jan 05 14:22:35 raspberrypi homebridge[12713]: [2020-1-5 14:22:35] [Living Room Window] End Move up (to 100%)

What do the ms values 45 & 55 represent? By the way thumbs up for the nice logging.

Thanks!

dxdc commented

@hjkempel thanks for the testing!

[5.1.2020, 11:23:14] [ID:2 SleepingRoom Left] Request succeeded after 1 / 5 attempts

Do you have verbose enabled? It shouldn't have shown logging for this line unless you do.

For example 10000 vs. 9800. This way, it will reduce the chance of a collision when stop is fired with a negligible change to the overall position. (Note: I chose this value since you said only 200 ms was a required difference).

Did experimenting with motionTime help for this?

If so, it could be worth making small adjustments to all your motion times and then experimenting with the retry delay as well to achieve a state where it seems to fire on the first time, every time.

@peros550 thanks for the feedback as well.

What do the ms values 45 & 55 represent?

Let's break down the entire sequence:

  1. Send the HTTP request and wait for an OK response (= time noted in log, e.g., 45-55 ms in your case)
  2. See movement on the blinds (= response_lag after OK response)
  3. Wait for blinds to move (= motion_time - response_lag)
  4. Send stop request

This was done because just sending a stop request doesn't necessarily mean the blinds will stop at that moment. So, to calibrate your blinds you can perform the following sequence:

  1. Open blinds and start timer at the same moment
  2. End timer when you see/hear blinds moving
  3. Subtract the HTTP request time
  4. Set this value to response_lag in the config

Let's assume another example scenario of a response_lag = 1000 and motion_time = 10000. So, if we set blinds to 50%, it will send a stop command 4000 ms after HTTP request sent. This should work out so the blinds actually stop at 50%. Let me know if you have questions on this or you feel it could be clearer in the README. I noticed that you have motion_time set to 0, which I don't understand. The purpose of the motion_time is also to help you see that the blinds are actually moving within Homekit.

By the way thumbs up for the nice logging

Thanks, appreciate it!

hjkempel commented

@dxdc Hi,

Do you have verbose enabled?

Yes, I did. verbose is enabled for the moment to get full logging information.

Did experimenting with motionTime help for this?

Yes, I have setup small variations for motionTime to avoid possible conflicts.
Setup is running Ok for the moment, next days will tell the truth.

Kind regards, hjk

dxdc commented

👍