yenoiwesa / homebridge-connexoon

A homebridge plugin to integrate Somfy blinds with the Connexoon RTS hub
Apache License 2.0
27 stars 2 forks source link

Polling question #22

Closed sddgit closed 3 years ago

sddgit commented 3 years ago

First of all, thank you for this invaluable plugin. I have a couple of questions regarding polling:

What exactly is being polled? Is it the Connexxon hub on my Lan, or the Somfy remote server?

Since I will only be controlling my blinds from Homekit, I thought it would be good to set polling to 0. This is acknowledged via the startup log for the plugin. However, I'm still getting a great deal of polling of my 7 blinds going on in the log, sometimes every minute or so. I don't have the Home app displaying on any device, although it could, of course, be running in the background. Is all this polling a concern?

Thank you.

yenoiwesa commented 3 years ago

Hey @sddgit 👋

So the Connexoon box unfortunately offers no way to send requests directly over the LAN (a huge shame). One must send requests to the Somfy cloud, that will then send commands to the Connexoon box. Lots of round trips happening...

So what the plugin polls is really the Somfy cloud's state. As you saw, when polling is disabled, it tells you so in the logs, during the platform startup. Additionally, there is a debug log entry before each poll event: https://github.com/yenoiwesa/homebridge-connexoon/blob/16b3c174887485620ec098cf89d4dc06da533eda/src/connexoon-platform.js#L186

But, without having seen your logs, I suspect that what you are seeing is not linked to the polling feature, but just the standard HomeKit implementation for the hub and Home apps to refresh the state when necessary. This is totally outside of my control and depends solely on Apple's implementation.

If you think that could be causing too many calls to the Somfy cloud with your credentials, maybe check if you have the devices as widgets on your phone, or scenes that require the device status to decide if the scene is on/off.

sddgit commented 3 years ago

Thank you very much for the quick response. I would agree that the "polling" is caused by Homekit itself, but I'm not sure why it happens so often. Here's a log snippet:

[12/20/2020, 11:21:32 PM] [Connexoon] Get Elephant Blind current position success: 100
[12/20/2020, 11:21:32 PM] [Connexoon] Get Elephant Blind target position success: 100
[12/20/2020, 11:21:32 PM] [Connexoon] Get Kitchen 3 current position success: 100
[12/20/2020, 11:21:32 PM] [Connexoon] Get Kitchen 3 target position success: 100
[12/20/2020, 11:21:32 PM] [Connexoon] Get Lounge 3 current position success: 100
[12/20/2020, 11:21:32 PM] [Connexoon] Get Lounge 3 target position success: 100
[12/20/2020, 11:21:32 PM] [Connexoon] Get Kitchen 1 current position success: 100
[12/20/2020, 11:21:32 PM] [Connexoon] Get Kitchen 1 target position success: 100
[12/20/2020, 11:21:32 PM] [Connexoon] Get Lounge 1 current position success: 100
[12/20/2020, 11:21:32 PM] [Connexoon] Get Lounge 1 target position success: 100
[12/20/2020, 11:21:32 PM] [Connexoon] Get Lounge 2 current position success: 100
[12/20/2020, 11:21:32 PM] [Connexoon] Get Lounge 2 target position success: 100
[12/20/2020, 11:21:32 PM] [Connexoon] Get Kitchen 2 current position success: 100
[12/20/2020, 11:21:32 PM] [Connexoon] Get Kitchen 2 target position success: 100
[12/20/2020, 11:22:50 PM] [Connexoon] Get Elephant Blind current position success: 100
[12/20/2020, 11:22:50 PM] [Connexoon] Get Elephant Blind target position success: 100
[12/20/2020, 11:22:50 PM] [Connexoon] Get Kitchen 4 current position success: 100
[12/20/2020, 11:22:50 PM] [Connexoon] Get Kitchen 4 target position success: 100
[12/20/2020, 11:22:50 PM] [Connexoon] Get Kitchen 3 current position success: 100
[12/20/2020, 11:22:50 PM] [Connexoon] Get Kitchen 3 target position success: 100
[12/20/2020, 11:22:50 PM] [Connexoon] Get Lounge 3 current position success: 100
[12/20/2020, 11:22:50 PM] [Connexoon] Get Lounge 3 target position success: 100
[12/20/2020, 11:22:50 PM] [Connexoon] Get Kitchen 1 current position success: 100
[12/20/2020, 11:22:50 PM] [Connexoon] Get Kitchen 1 target position success: 100
[12/20/2020, 11:22:50 PM] [Connexoon] Get Kitchen 2 current position success: 100
[12/20/2020, 11:22:50 PM] [Connexoon] Get Kitchen 2 target position success: 100
[12/20/2020, 11:22:50 PM] [Connexoon] Get Lounge 1 current position success: 100
[12/20/2020, 11:22:50 PM] [Connexoon] Get Lounge 1 target position success: 100
[12/20/2020, 11:22:50 PM] [Connexoon] Get Lounge 2 current position success: 100
[12/20/2020, 11:22:50 PM] [Connexoon] Get Lounge 2 target position success: 100
[12/20/2020, 11:22:54 PM] [Connexoon] Get Elephant Blind current position success: 100
[12/20/2020, 11:22:54 PM] [Connexoon] Get Elephant Blind target position success: 100
[12/20/2020, 11:22:54 PM] [Connexoon] Get Kitchen 4 current position success: 100
[12/20/2020, 11:22:54 PM] [Connexoon] Get Kitchen 4 target position success: 100
[12/20/2020, 11:22:54 PM] [Connexoon] Get Kitchen 3 current position success: 100
[12/20/2020, 11:22:54 PM] [Connexoon] Get Kitchen 3 target position success: 100
[12/20/2020, 11:22:54 PM] [Connexoon] Get Lounge 3 current position success: 100
[12/20/2020, 11:22:54 PM] [Connexoon] Get Lounge 3 target position success: 100
[12/20/2020, 11:22:54 PM] [Connexoon] Get Kitchen 1 current position success: 100
[12/20/2020, 11:22:54 PM] [Connexoon] Get Kitchen 1 target position success: 100
[12/20/2020, 11:22:54 PM] [Connexoon] Get Kitchen 2 current position success: 100
[12/20/2020, 11:22:54 PM] [Connexoon] Get Kitchen 2 target position success: 100
[12/20/2020, 11:22:54 PM] [Connexoon] Get Lounge 1 current position success: 100
[12/20/2020, 11:22:54 PM] [Connexoon] Get Lounge 1 target position success: 100
[12/20/2020, 11:22:54 PM] [Connexoon] Get Lounge 2 current position success: 100
[12/20/2020, 11:22:54 PM] [Connexoon] Get Lounge 2 target position success: 100

As you can see, it sometimes happens very often. I don't have phone widgets, but have scenes with various blinds in the Home app in a few devices. I suppose there are also scenes in the pull down iOS Control Centre that appear automatically. There are also a few Apple TVs in the house. I'm not sure if they could be involved in keeping the state up to date. I'm not really comfortable with this much traffic going backwards and forward to the Somfy cloud, so if you have any other suggestions, I'd be grateful!

yenoiwesa commented 3 years ago

@sddgit it would be good for you to investigate what causes Homebridge to receive so many requests for up to date state from Homekit.

Either way, I have done a change to allow configuring some caches in the config. Try this unreleased version:

sudo npm install -g yenoiwesa/homebridge-connexoon#a9d8c61bba7fc0477d52c4f17df55b76a788a2eb

With this one, you can add the following config per blind:

{
    "platforms": [
        {
            "platform": "Connexoon",
            "...": "...",

            "devices": {
                "Elephant Blind": {
                    "positionsCacheMaxAge": 300000
                }
            }
        }
    ]
}

The effect this will have is that when Homekit will request the position of the blind, the plugin will make a request to the server, and then cache that result for 300000 ms, i.e. 5 * 60 * 1000 5 min.

I will be honest I have not tested how that will impact the functionality of the platform, but give it a try, and let me know 🙂

sddgit commented 3 years ago

Funny, I was thinking some caching might be useful! If a new request comes in and changes the state of the blind, will the cache be invalidated and reinstated? Are there any new log messages that would indicate the cache is being used instead of a server request? That might be handy for checking the processing is correct.

Now you've gone to all this trouble, I need to tell you that at 1.15am the day after I reported the problem, all the spurious activity ceased. It has been behaving impeccably ever since. The only activity occurs when a Home app is opened, a Control Centre swiped into etc. But I'm keeping an eye on it to see if it happens again.

sddgit commented 3 years ago

Back into this after the holiday break!

Just went to test the new version, but the install failed (on a Mac). Log attached. 2020-12-29T02_59_11_011Z-debug.log

I also did a test on the current version with polling enabled. I adjusted the blinds using the Connexoon app, and waited for the status of the blinds to change in Homekit. It did seem to work, but there were no entries in the Homebridge log showing that the Connexoon server was contacted. Should there be polling entries in the log?

Thanks for your help.

yenoiwesa commented 3 years ago

Hey @sddgit, you must not have git installed on your machine. Do git --help in a terminal and macOS should prompt you to install developer tools (which include git).

I am glad that your overall traffic has suddenly reduced!

If a new request comes in and changes the state of the blind, will the cache be invalidated and reinstated? Are there any new log messages that would indicate the cache is being used instead of a server request? That might be handy for checking the processing is correct.

The cache setting for positionsCacheMaxAge acts at the level of the Connexoon layer. It retrieves the commands history and the currently executed commands to infer the current position of the blinds. However I do not reset that cache if a command has been executed (because it normally has a very short lifespan anyway), which means that you could see the value in Homekit revert back to a stale value if you close and reopen the app (Homekit asking for the position again would receive a stale one).

I could make sure it's properly reset, if we decide to go forward with that cache solution for your problem.

Should there be polling entries in the log?

For either contacting the Connexoon API or polling, the log entries are only at debug level. You would need to restart your homebridge server with the debug option -D to see these log entries.

sddgit commented 3 years ago

As you can tell - I'm new to the whole GIT environment, so thanks for the handholding. git --help gets a similar error, but I've read that xcode-select --install will do it.

I guess I strictly speaking don't need the caching solution anymore (things have been running perfectly for days now), but if you'd like to pursue it, I'm happy to test. I do think the cache should be invalidated and reinstated when a new position request comes in though. In theory, if you know you only use Homekit to control the blinds, you could have a very large cache age value and not have to do many calls to the API at all. Let me know what you think.

Without the -D option, I see the following sorts of entries in the log:

[12/29/2020, 2:31:04 PM] [Connexoon] Get Lounge 3 current position success: 100 [12/29/2020, 2:31:04 PM] [Connexoon] Get Lounge 3 target position success: 100 [12/29/2020, 2:31:04 PM] [Connexoon] Get Lounge 2 target position success: 100 [12/29/2020, 2:31:04 PM] [Connexoon] Get Lounge 2 current position success: 100

I thought these were logging API calls, but from what you said, these should only exist with -D. Am I missing something?

Thanks again.

yenoiwesa commented 3 years ago
[12/29/2020, 2:31:04 PM] [Connexoon] Get Lounge 3 current position success: 100
[12/29/2020, 2:31:04 PM] [Connexoon] Get Lounge 3 target position success: 100
[12/29/2020, 2:31:04 PM] [Connexoon] Get Lounge 2 target position success: 100
[12/29/2020, 2:31:04 PM] [Connexoon] Get Lounge 2 current position success: 100

These entries are not showing Connexoon API calls, but Homekit calls to the plugin (Homekit requests to get the current position and target position properties for your accessories. I am logging that this was answered to Homekit with success with the value answered, here, 100).

I feel that most people will be using a combination of Connexoon timers (which are more reliable than Homekit timers because they will still execute if your internet is down) and Homekit commands, hence why I feel it's better to get the value from the Somfy API either way. I probably won't be pursuing long caching, the number of requests has never been an issue before. What do you think?

sddgit commented 3 years ago

Ok, fair enough with the logging. I’ll play with -D just for the hell of it.

I’m happy to not have any caching options, now that thIngs have settled down. If I come across the problem again, maybe we can revisit? How do Connexoon timers work then, if not through their server?

yenoiwesa commented 3 years ago

If I come across the problem again, maybe we can revisit?

Sure, I will keep the branch up and we can come back to it when necessary.

How do Connexoon timers work then, if not through their server?

Lol that is quite the mystery! I have scratched my head over that question for a very long time and I am still not sure how they work. What it seems to be doing is that it stores the timers locally in the Connexoon box after the server tells it too, but it also keeps them server side. There is some type of synchronisation happening.

A construction site next door had (mistakenly) severed our home fibre connection recently, so we were offline for more than 24 hours, and our scheduled opening/closing still went through at the right times. Pretty robust implementation eh!

sddgit commented 3 years ago

OK, great.

Yeh, it’s surprising it works so well then. As you say, it must store timers in the hub for that to work.

yenoiwesa commented 3 years ago

Something else that is convenient with polling is that it forces the plugin to re-login against the Somfy API regularly, which means that you should still be logged in by the time you make your Siri/Home request (sessions are about 30 minutes if I recall). That speeds up the execution of your command quite a lot. Log in is the slowest request of all in the Somfy API for some reason, and personally being in Australia, it all has to go to Singapore where they have their servers.

sddgit commented 3 years ago

That's an interesting point (I'm in Oz too). You can see how slow login is by using the Connexoon app. I didn't realise there's some sort of timeout on the API login. Maybe I should have a 20 minute polling interval. What do you use?

sddgit commented 3 years ago

One more point, although I don't know if it's important. I had reason to restore Homebridge from one of its own backups. When it reinstalled this plugin, I got the following messages, although everything still seems to work ok. I'm sure you already know all this, but thought I'd mention it anyway. Happy New Year!

CMD: npm install -g homebridge-connexoon@2.1.1

npm WARN deprecated request@2.88.2: request has been deprecated, see https://github.com/request/request/issues/3142 npm WARN deprecated request-promise-native@1.0.9: request-promise-native has been deprecated because it extends the now deprecated request package, see https://github.com/request/request/issues/3142 npm WARN deprecated har-validator@5.1.5: this library is no longer supported

yenoiwesa commented 3 years ago

Happy new year @sddgit !

Yes I do know about these deprecations but they have no impact on the functionality and I do not intend to move away from the request library (for now) as it does its job.

Are you happy with me closing that issue or is there something else you'd like me to investigate?

sddgit commented 3 years ago

There was just the question of what you yourself use for the polling interval. Other than that, yes I’m happy for this to be closed. Thank you so much for the plug-in and your help. I’m so happy I’ve implemented Homebridge and can use all these amazing plugins to automate things through Homekit.

yenoiwesa commented 3 years ago

Ah yes my bad @sddgit! I use the default values for everything, as I want to make sure that the plugin works well for people "out of the box", with minimal configuration. So that's the default 10 minutes. I have been using it like that for about a year and a half, with 3 HomePods and 4 RTS Somfy blinds. It's been quite reliable. The only issue I face sometimes is a timeout from the Somfy API.

Do let me know through issues if you encounter issues with the plugin :-)

Cheers!