Set current state with a 'state_url'

Hi,

Currently, even when the target position of the blinds is specifically set through an up/down URL (e.g. http://1.1.1.1/set?target_position=100) and the current position of the blinds is specifically received through a position URL (e.g. http://1.1.1.1/get?current_position), the state (opening, closed, stopped) of the blinds is still emulated using 'motion_time'.

As per the README:

Ensure that the motion time is configured properly, even when "position_url" is set, as it is used to obtain an estimate of blind position to avoid multiple web requests to the position_url. (After the estimated position is reached, the position will be confirmed).

As my blinds take longer to open and close at certain heights, the emulated tracking does not perform very well, and the blinds report that they are still opening/closing a few seconds after they have stopped in real life. However I have the ability to detect the state of my blinds over http, (i.e. http://1.1.1.1/get?current_state), such that:

0: the blinds are closing
1: the blinds are opening
2: the blinds are stopped

Just wondering if an optional "state_url" would be appropriate, where the current state (opening, closing, stopped) can be queried at an interval by the plugin when opening/closing the blinds. This could co-exist with the current "position_url" and provide more accurate tracking for the blinds state in Homebridge.

Also, if this is a bad idea or there are other approaches please let me know!

Thanks!

Thanks for the support @SupImDos !

Currently, even when the target position of the blinds is specifically set through an up/down URL (e.g. http://1.1.1.1/set?target_position=100) and the current position of the blinds is specifically received through a position URL (e.g. http://1.1.1.1/get?current_position), the state (opening, closed, stopped) of the blinds is still emulated using 'motion_time'.

I'll explain why I implemented it this way. We need to poll your blinds to get the current position. We have several options about how often to poll. For example, every 0.1 sec, every 0.5 sec, etc. Because everyone's blinds are different, I think it makes more sense to only poll once we expect the blinds have reached the desired position.

As my blinds take longer to open and close at certain heights, the emulated tracking does not perform very well, and the blinds report that they are still opening/closing a few seconds after they have stopped in real life.

If the blinds are not tracking exactly, you can use a trick - just reduce motion time by 10% - and it will poll slightly sooner. You can decrease it further of course, but I would try reducing by 10% at a time until the performance is as you expect. Let me know if this solves the issue.

Just wondering if an optional "state_url" would be appropriate, where the current state (opening, closing, stopped) can be queried at an interval by the plugin when opening/closing the blinds. This could co-exist with the current "position_url" and provide more accurate tracking for the blinds state in Homebridge.

We can implement this, of course, but it's a bit complicated because Homekit uses these states as implied too. What I mean is, Homebridge calculates the state from the current vs. target position. If the current and target position don't match, it will figure that it's moving up or down and show the icon accordingly.

If it's just a few seconds after real life, there are many possible reasons. First is that, the iOS app doesn't update instantaneously either. Sometimes, force quitting the Home app and going back in refreshes these icons in a better way. I've seen this behavior as well on occasion. It would be helpful to see your logs and coordinate the exact timestamps of when things are happening. For example, if the blinds report in the logs as stopped at 9:45:02 and you observe them in the app only at 9:45:05 then there's nothing more that a state url would help with.

The other complexity here is that it gives us yet another URL to poll, and we don't even need this information. We have the target position and the current position and we can determine the blinds state based on that (current > target = 0; current < target = 1; current == target = 2). Each URL polling takes some amount of time which depends on your network speed and also the device's response. I've tried to add enough robustness to the code to properly tell Homekit that Stop is enabled after all key events.

Open to adding it if it would be helpful of course, but the only way I could see doing this in a practical way would be on a one-time basis (e.g., webhook). Still, since the state is set based on the current vs. target position by Homekit, I'm just not sure this will be extremely valuable and may even confuse the issue. If it's not reporting as stopped then that's certainly something we should figure out as to why.

I'll explain why I implemented it this way. We need to poll your blinds to get the current position. We have several options about how often to poll. For example, every 0.1 sec, every 0.5 sec, etc. Because everyone's blinds are different, I think it makes more sense to only poll once we expect the blinds have reached the desired position.

Makes sense, thanks for clarifying!

If the blinds are not tracking exactly, you can use a trick - just reduce motion time by 10% - and it will poll slightly sooner. You can decrease it further of course, but I would try reducing by 10% at a time until the performance is as you expect. Let me know if this solves the issue.

I'll definitely try this. Would you be able to explain any downsides (other than excessive polling) to me setting the motion time to much less than the actual real life motion time? For example, if my blinds take 20 seconds to open/close, what are the drawbacks of setting motion time to 10 seconds (i.e. 10000ms)? Does this mean that it will simply start polling for the currentPosition from the positionURL earlier than it needs to? Or will this cause it to prematurely display "Open" or "Closed" as its state?

We can implement this, of course, but it's a bit complicated because Homekit uses these states as implied too. What I mean is, Homebridge calculates the state from the current vs. target position. If the current and target position don't match, it will figure that it's moving up or down and show the icon accordingly.

Thanks so much for clarifying this as well. I didn't realise Homekit calculates the state on its own anyway - so we do have all the information we need already anyway.

Sorry for the double comment, but I seem to have a good example of what I mean here. For example, here I have set the "motion_time" to 16000 when the actual motion time in real life is 20000:

[4/15/2020, 03:14:39] [Roller Shutters] Requested Move up (to 100%)
[4/15/2020, 03:14:39] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 03:14:39] [Roller Shutters] Body (204): 100
[4/15/2020, 03:14:39] [Roller Shutters] Move request sent (20 ms), waiting 16s (+ 0s response lag)...
[4/15/2020, 03:14:39] [Roller Shutters] Stop command will be skipped; exact position specified
[4/15/2020, 03:14:39] [Roller Shutters] Timeout finished
[4/15/2020, 03:14:56] [Roller Shutters] Requested CurrentPosition: 100%
[4/15/2020, 03:14:56] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 03:14:56] [Roller Shutters] Body (200): 74
[4/15/2020, 03:14:56] [Roller Shutters] End Move up to 100% (target 100%)

Here it seems, after the 16s has passed, my blinds have been polled, and have reported that they are at '74' as per above. However instead of polling again until it has reached '100' it seems to end there. The blinds are then reported "Open" in homekit ~4 seconds before they are actually open.

Am I doing something wrong? Is it reading my http response correctly when it is using the positionURL?

My configuration is as per below:

{
    "accessory": "BlindsHTTP",
    "name": "Roller Shutters",
    "up_url": {
        "url": "http://192.168.1.129:8080/set?target_position=%%POS%%",
        "method": "POST",
        "maxAttempts": 5,
        "retryDelay": 2000
    },
    "down_url": {
        "url": "http://192.168.1.129:8080/set?target_position=%%POS%%",
        "method": "POST",
        "maxAttempts": 5,
        "retryDelay": 2000
    },
    "position_url": {
        "url": "http://192.168.1.129:8080/get?current_position",
        "method": "GET",
        "maxAttempts": 5,
        "retryDelay": 2000
    },
    "success_codes": [
        200,
        204
    ],
    "motion_time": 16000,
    "response_lag": 0,
    "use_same_url_for_stop": false,
    "show_stop_button": false,
    "show_toggle_button": false,
    "trigger_stop_at_boundaries": false,
    "verbose": true
}

Thanks!

@SupImDos

Thanks for the feedback. Actually, I have no way of checking currentUrl because my blinds don't support this feature, but it does seem like something is amiss.

I added some more logging https://github.com/dxdc/homebridge-blinds/commit/e1b3e8632d07ef00ab0bc10eca71deec31c5ffd8. Can you re-install the plugin using this latest commit and try again using the same settings?

For ex: npm -g install https://github.com/dxdc/homebridge-blinds.git

(Don't forget to restart homebridge).

I'll definitely try this. Would you be able to explain any downsides (other than excessive polling) to me setting the motion time to much less than the actual real life motion time? For example, if my blinds take 20 seconds to open/close, what are the drawbacks of setting motion time to 10 seconds (i.e. 10000ms)?

Regarding this, it was designed to keep polling at the (next) expected time. So, it works like this:

Suppose 100% of your blinds takes 20 sec
1% of your blinds takes 0.2 sec
Current position of blinds = 0%

Now, suppose in reality, your blinds take 25 sec, here is how the plugin should do it:

Poll @ 20 sec. Response from blinds = 80
(0.2 sec * 20% remaining) = 4 sec. Poll @ 4 sec. Response from blinds = 96
(0.2 sec * 4% remaining) = 0.8 sec. Poll @ 0.8 sec. Response from blinds = 99
(0.2 sec * 1% remaining) = 0.2 sec. Poll @ 0.2 sec. Response from blinds = 100

I think already in this case we should have used something a bit closer to reality (e.g., 22-23 sec, not 20). Because, you can imagine a bad scenario where it just gets stuck in a loop trying to finish. AND, each polling takes some additional amount of time too... so the above scenario probably would finish after just 2-3 tries.

Still, to prevent infinite loops, I've added some logic that after polling 10x (total) for your blinds position within the course of an adjustment, it will just abort. We can make that (10) a configurable parameter, if needed.

Does this mean that it will simply start polling for the currentPosition from the positionURL earlier than it needs to?

Yes

Or will this cause it to prematurely display "Open" or "Closed" as its state?

No, it shouldn't. Let's figure that part out.

Done, repeated the same test with the new logging:

# Move Down from 100 to 0
[4/15/2020, 05:17:12] [Roller Shutters] Requested Move down (to 0%)
[4/15/2020, 05:17:12] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:17:12] [Roller Shutters] Body (204): 0
[4/15/2020, 05:17:12] [Roller Shutters] Move request sent (24 ms), waiting 16s (+ 0s response lag)...
[4/15/2020, 05:17:12] [Roller Shutters] Stop command will be skipped; exact position specified
[4/15/2020, 05:17:12] [Roller Shutters] Timeout finished
[4/15/2020, 05:17:28] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:17:28] [Roller Shutters] Body (200): 1
[4/15/2020, 05:17:28] [Roller Shutters] Reached target: 0, currentPosition: 0, manualStop: N
[4/15/2020, 05:17:28] [Roller Shutters] End Move down to 0% (target 0%)

# Move Up from 0 to 100
[4/15/2020, 05:17:41] [Roller Shutters] Requested Move up (to 100%)
[4/15/2020, 05:17:41] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:17:41] [Roller Shutters] Body (204): 100
[4/15/2020, 05:17:41] [Roller Shutters] Move request sent (18 ms), waiting 16s (+ 0s response lag)...
[4/15/2020, 05:17:41] [Roller Shutters] Stop command will be skipped; exact position specified
[4/15/2020, 05:17:41] [Roller Shutters] Timeout finished
[4/15/2020, 05:17:57] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:17:57] [Roller Shutters] Body (200): 74
[4/15/2020, 05:17:57] [Roller Shutters] Reached target: 100, currentPosition: 100, manualStop: N
[4/15/2020, 05:17:57] [Roller Shutters] End Move up to 100% (target 100%)

Interesting results. Let me know if there's anything else I can do to help!

Thanks! I'll look into it. Any chance you see different behavior moving from (say) 10%-50% or something that's not 0 or 100?

Just conducted a few more tests:

# 100 to 50
[4/15/2020, 05:28:45] [Roller Shutters] Requested Move down (to 50%)
[4/15/2020, 05:28:45] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:28:45] [Roller Shutters] Body (204): 50
[4/15/2020, 05:28:45] [Roller Shutters] Move request sent (26 ms), waiting 8s (+ 0s response lag)...
[4/15/2020, 05:28:45] [Roller Shutters] Stop command will be skipped; exact position specified
[4/15/2020, 05:28:45] [Roller Shutters] Timeout finished
[4/15/2020, 05:28:49] [Roller Shutters] Requested TargetPosition: 50%
[4/15/2020, 05:28:49] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:28:49] [Roller Shutters] Body (200): 72
[4/15/2020, 05:28:53] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:28:53] [Roller Shutters] Body (200): 50
[4/15/2020, 05:28:53] [Roller Shutters] Reached target: 50, currentPosition: 50, manualStop: N
[4/15/2020, 05:28:53] [Roller Shutters] End Move down to 50% (target 50%)

# 50 to 10
[4/15/2020, 05:30:01] [Roller Shutters] Requested Move down (to 10%)
[4/15/2020, 05:30:01] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:30:01] [Roller Shutters] Body (204): 10
[4/15/2020, 05:30:01] [Roller Shutters] Move request sent (24 ms), waiting 6.4s (+ 0s response lag)...
[4/15/2020, 05:30:01] [Roller Shutters] Stop command will be skipped; exact position specified
[4/15/2020, 05:30:01] [Roller Shutters] Timeout finished
[4/15/2020, 05:30:08] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:30:08] [Roller Shutters] Body (200): 10
[4/15/2020, 05:30:08] [Roller Shutters] Reached target: 10, currentPosition: 10, manualStop: N
[4/15/2020, 05:30:08] [Roller Shutters] End Move down to 10% (target 10%)

# 10 to 50
[4/15/2020, 05:30:31] [Roller Shutters] Requested Move up (to 50%)
[4/15/2020, 05:30:31] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:30:31] [Roller Shutters] Body (204): 50
[4/15/2020, 05:30:31] [Roller Shutters] Move request sent (20 ms), waiting 6.4s (+ 0s response lag)...
[4/15/2020, 05:30:31] [Roller Shutters] Stop command will be skipped; exact position specified
[4/15/2020, 05:30:31] [Roller Shutters] Timeout finished
[4/15/2020, 05:30:37] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:30:37] [Roller Shutters] Body (200): 50
[4/15/2020, 05:30:37] [Roller Shutters] Reached target: 50, currentPosition: 50, manualStop: N
[4/15/2020, 05:30:37] [Roller Shutters] End Move up to 50% (target 50%)

# 50 to 100
[4/15/2020, 05:31:03] [Roller Shutters] Requested Move up (to 100%)
[4/15/2020, 05:31:03] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:31:03] [Roller Shutters] Body (204): 100
[4/15/2020, 05:31:03] [Roller Shutters] Move request sent (19 ms), waiting 8s (+ 0s response lag)...
[4/15/2020, 05:31:03] [Roller Shutters] Stop command will be skipped; exact position specified
[4/15/2020, 05:31:03] [Roller Shutters] Timeout finished
[4/15/2020, 05:31:11] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:31:11] [Roller Shutters] Body (200): 100
[4/15/2020, 05:31:11] [Roller Shutters] Reached target: 100, currentPosition: 100, manualStop: N
[4/15/2020, 05:31:11] [Roller Shutters] End Move up to 100% (target 100%)

First test (100 to 50) seemed to work perfectly! Looks like it polled, got 72, polled again and got 50 and then finished.

Other 3 tests seemed to work as well, but all reported the correct currentPosition on the first poll anyway - so not sure if they're as useful. I can redo the tests with an even lower motion time so that it has to poll earlier (and hopefully poll twice) if required.

Thanks!

@SupImDos Can you pull the latest commit and try again? It's still strange to me that there is some logging that doesn't seem to be coming through. I added one possible fix though to this issue.

For ex: npm -g install https://github.com/dxdc/homebridge-blinds.git

(Don't forget to restart homebridge).

Also @SupImDos can you send your error log (if different?). Wondering if there may be other details/clues there.

Just finished some tests with the latest commit:

# 100 to 0 (Gets stuck at 1)

[4/15/2020, 05:52:47] [Roller Shutters] Requested Move down (to 0%)
[4/15/2020, 05:52:47] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:52:47] [Roller Shutters] Body (204): 0
[4/15/2020, 05:52:47] [Roller Shutters] Move request sent (31 ms), waiting 16s (+ 0s response lag)...
[4/15/2020, 05:52:47] [Roller Shutters] Stop command will be skipped; exact position specified
[4/15/2020, 05:52:47] [Roller Shutters] Timeout finished
[4/15/2020, 05:53:03] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:53:03] [Roller Shutters] Body (200): 1
[4/15/2020, 05:53:03] [Roller Shutters] Requested setCurrentPositionByUrl: 1
[4/15/2020, 05:53:03] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:53:03] [Roller Shutters] Body (200): 1
[4/15/2020, 05:53:03] [Roller Shutters] Requested setCurrentPositionByUrl: 1
[4/15/2020, 05:53:04] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:53:04] [Roller Shutters] Body (200): 1
[4/15/2020, 05:53:04] [Roller Shutters] Requested setCurrentPositionByUrl: 1
[4/15/2020, 05:53:04] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:53:04] [Roller Shutters] Body (200): 1
[4/15/2020, 05:53:04] [Roller Shutters] Requested setCurrentPositionByUrl: 1
[4/15/2020, 05:53:04] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:53:04] [Roller Shutters] Body (200): 1
[4/15/2020, 05:53:04] [Roller Shutters] Requested setCurrentPositionByUrl: 1
[4/15/2020, 05:53:05] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:53:05] [Roller Shutters] Body (200): 1
[4/15/2020, 05:53:05] [Roller Shutters] Requested setCurrentPositionByUrl: 1
[4/15/2020, 05:53:05] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:53:05] [Roller Shutters] Body (200): 1
[4/15/2020, 05:53:05] [Roller Shutters] Requested setCurrentPositionByUrl: 1
[4/15/2020, 05:53:05] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:53:05] [Roller Shutters] Body (200): 1
[4/15/2020, 05:53:05] [Roller Shutters] Requested setCurrentPositionByUrl: 1
[4/15/2020, 05:53:06] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:53:06] [Roller Shutters] Body (200): 1
[4/15/2020, 05:53:06] [Roller Shutters] Requested setCurrentPositionByUrl: 1
[4/15/2020, 05:53:06] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:53:06] [Roller Shutters] Body (200): 1
[4/15/2020, 05:53:06] [Roller Shutters] Requested setCurrentPositionByUrl: 1
[4/15/2020, 05:53:06] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:53:06] [Roller Shutters] Body (200): 1
[4/15/2020, 05:53:06] [Roller Shutters] Requested setCurrentPositionByUrl: 1
[4/15/2020, 05:53:06] [Roller Shutters] Didn't reach target after 11 tries
[4/15/2020, 05:53:06] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:53:06] [Roller Shutters] Body (200): 1
[4/15/2020, 05:53:06] [Roller Shutters] Requested setCurrentPositionByUrl: 1
[4/15/2020, 05:53:06] [Roller Shutters] Reached target: 0, currentPosition: 1, manualStop: Y
[4/15/2020, 05:53:06] [Roller Shutters] End Move down to 1% (target 0%)

# 1 to 0 (Dummy Test, Blinds didn't move as already at 0 in real life)
[4/15/2020, 05:54:12] [Roller Shutters] Requested Move down (to 0%)
[4/15/2020, 05:54:12] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:54:12] [Roller Shutters] Body (204): 0
[4/15/2020, 05:54:12] [Roller Shutters] Move request sent (47 ms), waiting 0.2s (+ 0s response lag)...
[4/15/2020, 05:54:12] [Roller Shutters] Stop command will be skipped; exact position specified
[4/15/2020, 05:54:12] [Roller Shutters] Timeout finished
[4/15/2020, 05:54:13] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:54:13] [Roller Shutters] Body (200): 0
[4/15/2020, 05:54:13] [Roller Shutters] Requested setCurrentPositionByUrl: 0
[4/15/2020, 05:54:13] [Roller Shutters] Reached target: 0, currentPosition: 0, manualStop: N
[4/15/2020, 05:54:13] [Roller Shutters] End Move down to 0% (target 0%)

# 0 to 100
[4/15/2020, 05:54:54] [Roller Shutters] Requested Move up (to 100%)
[4/15/2020, 05:54:54] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:54:54] [Roller Shutters] Body (204): 100
[4/15/2020, 05:54:54] [Roller Shutters] Move request sent (25 ms), waiting 16s (+ 0s response lag)...
[4/15/2020, 05:54:54] [Roller Shutters] Stop command will be skipped; exact position specified
[4/15/2020, 05:54:54] [Roller Shutters] Timeout finished
[4/15/2020, 05:55:10] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:55:10] [Roller Shutters] Body (200): 74
[4/15/2020, 05:55:10] [Roller Shutters] Requested setCurrentPositionByUrl: 74
[4/15/2020, 05:55:15] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:55:15] [Roller Shutters] Body (200): 100
[4/15/2020, 05:55:15] [Roller Shutters] Requested setCurrentPositionByUrl: 100
[4/15/2020, 05:55:15] [Roller Shutters] Reached target: 100, currentPosition: 100, manualStop: N
[4/15/2020, 05:55:15] [Roller Shutters] End Move up to 100% (target 100%)

# 100 to 50
[4/15/2020, 05:55:45] [Roller Shutters] Requested Move down (to 50%)
[4/15/2020, 05:55:45] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:55:45] [Roller Shutters] Body (204): 50
[4/15/2020, 05:55:45] [Roller Shutters] Move request sent (22 ms), waiting 8s (+ 0s response lag)...
[4/15/2020, 05:55:45] [Roller Shutters] Stop command will be skipped; exact position specified
[4/15/2020, 05:55:45] [Roller Shutters] Timeout finished
[4/15/2020, 05:55:53] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:55:53] [Roller Shutters] Body (200): 50
[4/15/2020, 05:55:53] [Roller Shutters] Requested setCurrentPositionByUrl: 50
[4/15/2020, 05:55:53] [Roller Shutters] Reached target: 50, currentPosition: 50, manualStop: N
[4/15/2020, 05:55:53] [Roller Shutters] End Move down to 50% (target 50%)

# 50 to 90
[4/15/2020, 05:56:15] [Roller Shutters] Requested Move up (to 90%)
[4/15/2020, 05:56:15] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:56:15] [Roller Shutters] Body (204): 90
[4/15/2020, 05:56:15] [Roller Shutters] Move request sent (22 ms), waiting 6.4s (+ 0s response lag)...
[4/15/2020, 05:56:15] [Roller Shutters] Stop command will be skipped; exact position specified
[4/15/2020, 05:56:15] [Roller Shutters] Timeout finished
[4/15/2020, 05:56:21] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:56:21] [Roller Shutters] Body (200): 90
[4/15/2020, 05:56:21] [Roller Shutters] Requested setCurrentPositionByUrl: 90
[4/15/2020, 05:56:21] [Roller Shutters] Reached target: 90, currentPosition: 90, manualStop: N
[4/15/2020, 05:56:21] [Roller Shutters] End Move up to 90% (target 90%)

# 90 to 100
[4/15/2020, 05:56:42] [Roller Shutters] Requested Move up (to 100%)
[4/15/2020, 05:56:42] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:56:42] [Roller Shutters] Body (204): 100
[4/15/2020, 05:56:42] [Roller Shutters] Move request sent (38 ms), waiting 1.6s (+ 0s response lag)...
[4/15/2020, 05:56:42] [Roller Shutters] Stop command will be skipped; exact position specified
[4/15/2020, 05:56:42] [Roller Shutters] Timeout finished
[4/15/2020, 05:56:43] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 05:56:43] [Roller Shutters] Body (200): 100
[4/15/2020, 05:56:43] [Roller Shutters] Requested setCurrentPositionByUrl: 100
[4/15/2020, 05:56:43] [Roller Shutters] Reached target: 100, currentPosition: 100, manualStop: N
[4/15/2020, 05:56:43] [Roller Shutters] End Move up to 100% (target 100%)

For test 1, my roller shutters take ~5 seconds to go from 1% to 0%, so its polling 10 (11?) times (quite quickly) and failing. Not sure whether decreasing my motion_time or increasing my motion_time will improve this? Maybe a configurable option for number of times to poll, or just increasing the time between successive polls.

Regardless, this seems to be an improvement from last time?

Any pointers on where to find the error logs? I'm using homebridge-config-ui-x, but have compared those logs with the journalctl -u homebridge.service logs and they seem to be the same. Not sure where the error logs are stored, sorry!

Regardless, this seems to be an improvement from last time?

Indeed. I think it's solved. I've released this as a new version (1.3.18).

100 to 0 (Gets stuck at 1)

This is a problem with your blinds. You requested 0%, but it stopped at 1%. You said it takes 5 seconds to go from 1% to 0% (?). Can you elaborate further on that? This is an issue that isn't going to be trivial to solve, so I think the timeout is actually not a bad option.

We'd almost need a separate kind of timer function for that, which you'd have to calibrate specifically for your blinds. Right now it just assumes that each % of the blinds is equal (time wise).

Maybe a configurable option for number of times to poll, or just increasing the time between successive polls.

I don't want to increase the time between polls because that defeats the purpose of how this is working. The polling time is dictated per the equation I provided earlier, but namely, 1% of motionTime * % to move.

If we used some kind of backoff algorithm, the timing will become very unpredictable.

A configurable option to the number of polls is possible, but that won't fix your case because it's still going to poll every 0.2 seconds, meaning it would take 50 or so polls to reach the target. If you feel it would be extremely helpful as an option we can add it though.

Not sure where the error logs are stored, sorry!

It will change depending on your set up. You can try looking here...

/var/log/homebridge.log
/var/log/homebridge.err

Indeed. I think it's solved. I've released this as a new version (1.3.18).

Awesome, thanks so much!

You said it takes 5 seconds to go from 1% to 0% (?). Can you elaborate further on that? ... Right now it just assumes that each % of the blinds is equal (time wise).

To further elaborate, the blinds slow down dramatically towards the end, such that not every % of the blinds is equal time wise. Each percentage of the blinds from 100 -> 1 takes about ~150ms, but the final %, 1 -> 0 takes ~5000ms (it sucks I know).

My ESP32 controlling the blinds handles this non-linear tracking itself however.

A configurable option to the number of polls is possible, but that won't fix your case because it's still going to poll every 0.2 seconds, meaning it would take 50 or so polls to reach the target. If you feel it would be extremely helpful as an option we can add it though.

As an added note, I've manually adjusted the hard-coded "positionRetries" maximum threshold from 10 to 25 and my blinds work perfectly now. Generally succeeds around the 15-16th retry when going from 100 to 0, and on the 2nd-3rd retry when going from 0 to 100. Any movements in between (e.g. 10 to 50 or 50 to 10) generally work on the 1st retry.

I guess its not the best work around, as it is spamming the blinds with HTTP GET requests towards the end. However, I'm happy with the current solution unless you had any further suggestions.

/var/log/homebridge.log

/var/log/homebridge.err

Not there for me, probably due to running homebridge/homebridge-config-ui-x as a systemctl service? Not sure if you need them anymore however.

Thanks so much!

My ESP32 controlling the blinds handles this non-linear tracking itself however.

I'm curious what algorithm is used.

I've manually adjusted the hard-coded "positionRetries" maximum threshold from 10 to 25 and my blinds work perfectly now.

Glad to hear it. Still, it's clunky... thought about it, and pushed another commit (you will need to install from github again). Essentially, it does a pseudo-backoff if the position is not changing.

I think it should help enough that you won't need to adjust that positionRetries value.

I'm curious what algorithm is used.

I'd hesitate to even call it an algorithm. Funnily enough, each percent is just handled separately. Meaning, each +=1 step through the currentPosition has a different timeout/delay.

If you're interested, the code for it is here: https://gist.github.com/SupImDos/e2f2c38e59fdb7cff016e0a90c54c2e7

The different delay for each currentPosition step is in the array 'DELTAS' at line 22, such that DELTAS[i] is the time taken to go from (i -> i+1), or (i+1 -> i).

The handling of each currentPosition step is at line 235.

Not pretty and definitely could be improved, but seeing as its specifically for my blinds I don't really mind. I'm also not a great Arduino/C/C++ programmer anyway.

I think it should help enough that you won't need to adjust that positionRetries value.

# 100 to 0
[4/15/2020, 08:21:33] [Roller Shutters] Requested TargetPosition: 100%
[4/15/2020, 08:21:33] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 08:21:33] [Roller Shutters] Body (200): 100
[4/15/2020, 08:21:33] [Roller Shutters] Requested setCurrentPositionByUrl: 100
[4/15/2020, 08:21:36] [Roller Shutters] Requested Move down (to 0%)
[4/15/2020, 08:21:36] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 08:21:36] [Roller Shutters] Body (204): 0
[4/15/2020, 08:21:36] [Roller Shutters] Move request sent (26 ms), waiting 15s (+ 0s response lag)...
[4/15/2020, 08:21:36] [Roller Shutters] Stop command will be skipped; exact position specified
[4/15/2020, 08:21:36] [Roller Shutters] Timeout finished
[4/15/2020, 08:21:51] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 08:21:51] [Roller Shutters] Body (200): 1
[4/15/2020, 08:21:51] [Roller Shutters] Requested setCurrentPositionByUrl: 1
[4/15/2020, 08:21:52] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 08:21:52] [Roller Shutters] Body (200): 1
[4/15/2020, 08:21:52] [Roller Shutters] Requested setCurrentPositionByUrl: 1
[4/15/2020, 08:21:52] [Roller Shutters] Blinds position didn't change: skipping 2 cycles
[4/15/2020, 08:21:52] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 08:21:52] [Roller Shutters] Body (200): 1
[4/15/2020, 08:21:52] [Roller Shutters] Requested setCurrentPositionByUrl: 1
[4/15/2020, 08:21:52] [Roller Shutters] Blinds position didn't change: skipping 3 cycles
[4/15/2020, 08:21:53] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 08:21:53] [Roller Shutters] Body (200): 1
[4/15/2020, 08:21:53] [Roller Shutters] Requested setCurrentPositionByUrl: 1
[4/15/2020, 08:21:53] [Roller Shutters] Blinds position didn't change: skipping 4 cycles
[4/15/2020, 08:21:54] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 08:21:54] [Roller Shutters] Body (200): 1
[4/15/2020, 08:21:54] [Roller Shutters] Requested setCurrentPositionByUrl: 1
[4/15/2020, 08:21:54] [Roller Shutters] Blinds position didn't change: skipping 5 cycles
[4/15/2020, 08:21:55] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 08:21:55] [Roller Shutters] Body (200): 1
[4/15/2020, 08:21:55] [Roller Shutters] Requested setCurrentPositionByUrl: 1
[4/15/2020, 08:21:55] [Roller Shutters] Blinds position didn't change: skipping 6 cycles
[4/15/2020, 08:21:56] [Roller Shutters] Request succeeded after 1 / 5 attempts
[4/15/2020, 08:21:56] [Roller Shutters] Body (200): 0
[4/15/2020, 08:21:56] [Roller Shutters] Requested setCurrentPositionByUrl: 0
[4/15/2020, 08:21:56] [Roller Shutters] Reached target: 0, currentPosition: 0, manualStop: N
[4/15/2020, 08:21:56] [Roller Shutters] End Move down to 0% (target 0%)

Seems to work perfectly. Thanks so much for all of the changes, really appreciate everything!

Let me know if I should close the issue, or feel free to close it yourself!

Seems to work perfectly. Thanks so much for all of the changes, really appreciate everything!

Excellent, this is exactly what I was hoping for. Glad it works for you! I've pushed the changes into a new release.

Meaning, each +=1 step through the currentPosition has a different timeout/delay.

I looked through your code, I understand your approach. You also made the assumption in DELTAS that the amount of time to go up 1% and down 1% are identical, but actually gravity plays an important role here and this can vary substantially depending on the weight of your blinds and power of your motor. This is part of the reason I never added this feature, but will consider something like this for future, though it's complicated and not exactly straightforward to measure either. Not to mention... the whole discussion becomes a bit pointless when considering the fact that many blinds are battery operated and their speed will change over time... 😄

Also, from a quick glance at your code, it looks like you're sending an Rf signal every 1%?? That's a lot of Rf being transmitted if so.

Let me know if I should close the issue, or feel free to close it yourself!

Will do... thanks!

Not sure if its bad practice to comment on closed issues, so sorry if this re-opens it.

You also made the assumption in DELTAS that the amount of time to go up 1% and down 1% are identical, but actually gravity plays an important role here and this can vary substantially depending on the weight of your blinds and power of your motor.

For some reason I never thought of this, thanks for the tip! I'll have another look at this if I need to improve the accuracy of the tracking.

Also, from a quick glance at your code, it looks like you're sending an Rf signal every 1%?? That's a lot of Rf being transmitted if so.

It should only transmit if:

currentPosition < targetPosition and currentState != OPENING
currentPosition > targetPosition and currentState != CLOSING

i.e. it should only transmit if the currentState doesn't match the currentPosition vs. targetPosition. After transmitting once it should set the state appropriately to OPENING/CLOSING etc.

Excellent, this is exactly what I was hoping for. Glad it works for you! I've pushed the changes into a new release.

Thanks again!

dxdc / homebridge-blinds

Set current state with a 'state_url' #31