Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[hue] Bridge (v1) going OFFLINE and then ONLINE frequently due to connection lost #16723

Open
lolodomo opened this issue May 7, 2024 · 14 comments
Open

[hue] Bridge (v1) going OFFLINE and then ONLINE frequently due to connection lost #16723

lolodomo opened this issue May 7, 2024 · 14 comments
Labels
bug An unexpected problem or unintended behavior of an add-on

Comments

@lolodomo
Copy link
Contributor

lolodomo commented May 7, 2024

I found in my logs that my bridge (v1) thing is going OFFLINE frequently, the reason is apparently a lost connection. When it happens, the bridge is going ONLINE 10s later. It happens even during the night when there is no activity in the house. The frequency is not regular.

2024-05-07 02:12:24.915 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hue:bridge:bridge1' changed from ONLINE to OFFLINE: Connexion au pont Hue perdue.
2024-05-07 02:12:35.077 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hue:bridge:bridge1' changed from OFFLINE: Connexion au pont Hue perdue. to ONLINE
2024-05-07 02:48:27.886 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hue:bridge:bridge1' changed from ONLINE to OFFLINE: Connexion au pont Hue perdue.
2024-05-07 02:48:38.057 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hue:bridge:bridge1' changed from OFFLINE: Connexion au pont Hue perdue. to ONLINE
2024-05-07 03:01:56.613 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hue:bridge:bridge1' changed from ONLINE to OFFLINE: Connexion au pont Hue perdue.
2024-05-07 03:02:06.767 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hue:bridge:bridge1' changed from OFFLINE: Connexion au pont Hue perdue. to ONLINE
2024-05-07 04:28:37.726 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hue:bridge:bridge1' changed from ONLINE to OFFLINE: Connexion au pont Hue perdue.
2024-05-07 04:28:48.053 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hue:bridge:bridge1' changed from OFFLINE: Connexion au pont Hue perdue. to ONLINE
2024-05-07 04:47:50.996 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hue:bridge:bridge1' changed from ONLINE to OFFLINE: Connexion au pont Hue perdue.
2024-05-07 04:48:01.152 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hue:bridge:bridge1' changed from OFFLINE: Connexion au pont Hue perdue. to ONLINE
2024-05-07 04:50:28.682 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hue:bridge:bridge1' changed from ONLINE to OFFLINE: Connexion au pont Hue perdue.
2024-05-07 04:50:38.839 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hue:bridge:bridge1' changed from OFFLINE: Connexion au pont Hue perdue. to ONLINE
2024-05-07 04:58:41.334 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hue:bridge:bridge1' changed from ONLINE to OFFLINE: Connexion au pont Hue perdue.
2024-05-07 04:58:51.694 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hue:bridge:bridge1' changed from OFFLINE: Connexion au pont Hue perdue. to ONLINE
2024-05-07 05:20:39.967 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hue:bridge:bridge1' changed from ONLINE to OFFLINE: Connexion au pont Hue perdue.
2024-05-07 05:20:50.122 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hue:bridge:bridge1' changed from OFFLINE: Connexion au pont Hue perdue. to ONLINE
2024-05-07 06:28:13.230 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hue:bridge:bridge1' changed from ONLINE to OFFLINE: Connexion au pont Hue perdue.
2024-05-07 06:28:23.387 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hue:bridge:bridge1' changed from OFFLINE: Connexion au pont Hue perdue. to ONLINE
2024-05-07 07:19:07.552 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hue:bridge:bridge1' changed from ONLINE to OFFLINE: Connexion au pont Hue perdue.
2024-05-07 07:19:17.707 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hue:bridge:bridge1' changed from OFFLINE: Connexion au pont Hue perdue. to ONLINE
@lolodomo lolodomo added the bug An unexpected problem or unintended behavior of an add-on label May 7, 2024
@lolodomo
Copy link
Contributor Author

lolodomo commented May 7, 2024

Here is the line triggering the update of thing to OFFLINE:

openhab-addons/bundles/org.openhab.binding.hue/src/main/java/org/openhab/binding/hue/internal/handler/HueBridgeHandler.java

Line 738 in 283ae59

updateStatus(ThingStatus.OFFLINE, ThingStatusDetail.NONE, "@text/offline.bridge-connection-lost");

@andrewfg
Copy link
Contributor

andrewfg commented May 8, 2024

I guess it is normal for the bridge to indicate offline if the connection is lost.

The real question is what is causing the connection to be lost?

@lolodomo
Copy link
Contributor Author

lolodomo commented May 8, 2024

The real question is what is causing the connection to be lost?

Yes, that is the question,. I will add logs to the binding to understand in which case it happens.
Maybe due to authentication....

@andrewfg
Copy link
Contributor

andrewfg commented May 9, 2024

There was a fairly major firmware update for v2 bridges on Aptil 25th, so maybe they pushed something for v1 at the same time..

https://www.philips-hue.com/en-gb/support/release-notes/bridge

@lolodomo
Copy link
Contributor Author

lolodomo commented Jun 8, 2024 •
edited

After adding/updating some logs, looks like a timeout problem when polling the bridge:

2024-06-08 11:49:47.423 [WARN ] [ue.internal.handler.HueBridgeHandler] - Connection to Hue Bridge 192.168.xxx.xxx lost: Total timeout 5000 ms elapsed
org.openhab.core.i18n.CommunicationException: Total timeout 5000 ms elapsed
        at org.openhab.binding.hue.internal.connection.HueBridge.doNetwork(HueBridge.java:1128) ~[bundleFile:?]
        at org.openhab.binding.hue.internal.connection.HueBridge.doNetwork(HueBridge.java:1094) ~[bundleFile:?]
        at org.openhab.binding.hue.internal.connection.HueBridge.get(HueBridge.java:1077) ~[bundleFile:?]
        at org.openhab.binding.hue.internal.connection.HueBridge.getGroups(HueBridge.java:491) ~[bundleFile:?]
        at org.openhab.binding.hue.internal.handler.HueBridgeHandler$2.updateGroups(HueBridgeHandler.java:312) ~[bundleFile:?]
        at org.openhab.binding.hue.internal.handler.HueBridgeHandler$2.doConnectedRun(HueBridgeHandler.java:254) ~[bundleFile:?]
        at org.openhab.binding.hue.internal.handler.HueBridgeHandler$PollingRunnable.run(HueBridgeHandler.java:138) [bundleFile:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) [?:?]
        at java.util.concurrent.FutureTask.runAndReset(Unknown Source) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:?]
        at java.lang.Thread.run(Unknown Source) [?:?]

Maybe 5s is a little short as timeout ? I am going to try with a bigger timeout.

@andrewfg
Copy link
Contributor

andrewfg commented Jun 8, 2024 •
edited

Maybe 5s is a little short as timeout ?

Yes this could indeed be the case. For example: if the Hue Bridge is running a Hue Labs automation such as 'Color Loop' then it responds much slower to HTTP requests.

Note however that the above problem may go away rather soon because Philips / Signify will remove Hue Labs from the bridges at the end of this month (if I recall correctly), and will have replaced it with newer built in Effects such as 'Prism' and/or other built in functions which perform faster.

@lolodomo
Copy link
Contributor Author

lolodomo commented Jun 8, 2024

@andrewfg I am using a bridge v1 so I don't think there will be any change from Philips / Signify in the future.

Trying with 8s as timeout for requests, I have not yet encountered any problem. Lets see if it is reliable after few hours.

@lolodomo
Copy link
Contributor Author

lolodomo commented Jun 8, 2024

It just happened again with 8s timeout.

@andrewfg
Copy link
Contributor

andrewfg commented Jun 8, 2024

@lolodomo I suppose that being a v1 hub, you are using API v1 rather than v2 .. if so, I am pretty sure there was nothing recently changed on the OH side that could have suddenly started your issue after it working for so long. However it seems also unlikely that Philips / Signify has changed the v1 hub firmware. The only thing that I can think of may be the lamp firmware, but this seems unlikely to cause an HTTP comms issue..

@andrewfg
Copy link
Contributor

andrewfg commented Jun 8, 2024

@lolodomo by the way, the API v2 specification states that the Bridge is limited on number of serial HTTP calls per second (as I recall about 20 per second), and number of parallel overlapping HTTP calls (as I recall about 2 or 3). And I suppose that a similar limitation would apply to API v1 resp. the v1 bridge. When I wrote the API v2 code I introduced a throttler to reduce HTTP calls to within the given serial/parallel limits. I did not back-port it to API v1 since I assumed if that if anyone would ever encounter HTTP limitations they could solve it by upgrading to API v2. Yet for your special case you could consider back-porting the throttler -- just a thought..

@lolodomo
Copy link
Contributor Author

lolodomo commented Jun 8, 2024

Problem is unchanged with 10s timeput.

As I have the sensor polling interval set to 0, I should not have concurrent requests, except of course if all requests run when polling lights update sometimes takes more than 10s. I mean maybe the next cycle starts while the previous one is not ended.
In case it is the problem, I could try to increase the refresh interval to see if it helps.

@lolodomo
Copy link
Contributor Author

lolodomo commented Jun 8, 2024

In fact, there is a lock mechanism so concurrent requests when polling data is not possible.

@lolodomo
Copy link
Contributor Author

lolodomo commented Jun 8, 2024 •
edited

One solution or rather a workaround could be to not set the bridge thing to OFFLINE when there is a request timeout during the data polling but rather do it if it happens during two consecutive polls.

@lolodomo
Copy link
Contributor Author

lolodomo commented Jun 8, 2024

I am testing a basic retry mechanism added for GET requests failing in timeout and it seems to work well.
Will see if it is fully reliable after several hours.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug An unexpected problem or unintended behavior of an add-on
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@andrewfg @lolodomo