That seems quite likely. I have added some minor logging additions in my private build so I will hopefully learn more.
That’s also why I created the issue - I think it would be worth investing a bit into improving the error handling, so we’ll at least gain more knowledge when something like this happens. It seems in this case an ApiException was thrown without a message?
I’m also monitoring the bridge status, and get notifications on changes.
I have the error again.
I need to say that I do run 3 bridges in total. The error occurred the second time with this specific bridge. Other than the other bridges, this bridge is connected via a WLAN-bridge which is sometimes unstable.
However, I have seen the problem with one of my other bridges as well which is connected via LAN.
Here are my log entries (openhab.log):
2023-08-23 10:43:29.182 [DEBUG] [.hue.internal.connection.Clip2Bridge] - checkAlive()
2023-08-23 10:43:29.183 [DEBUG] [.hue.internal.connection.Clip2Bridge] - fatalError() Clip2Bridge TIMEOUT closing
org.openhab.binding.hue.internal.connection.Clip2Bridge$Http2Exception: HTTP 2 stream timeout
at org.openhab.binding.hue.internal.connection.Clip2Bridge.checkAlive(Clip2Bridge.java:573) ~[?:?]
at org.openhab.binding.hue.internal.connection.Clip2Bridge.lambda$5(Clip2Bridge.java:844) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
2023-08-23 10:43:29.183 [DEBUG] [.hue.internal.connection.Clip2Bridge] - close2()
2023-08-23 10:43:29.183 [DEBUG] [.hue.internal.connection.Clip2Bridge] - closeSession()
2023-08-23 10:43:29.279 [DEBUG] [.hue.internal.connection.Clip2Bridge] - onEventData() data length:308
2023-08-23 10:43:29.279 [DEBUG] [.internal.handler.Clip2BridgeHandler] - onResourcesEventTask() resource count 1
2023-08-23 10:43:29.279 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 01c720ba-e4c0-4f84-9510-5b48306815b1 → updateChannels() from resource id:17cb6eff-650e-455c-bfd2-e6c41e676179, type:zigbee_connectivity
2023-08-23 10:43:29.279 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 01c720ba-e4c0-4f84-9510-5b48306815b1 → updateConnectivityState() thingStatus:ONLINE, zigbeeStatus:Connectivity issue
2023-08-23 10:43:29.280 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 01c720ba-e4c0-4f84-9510-5b48306815b1 → updateState() ‘last-updated’ update with ‘2023-08-23T10:43:29.280012+0200’ (fullUpdate:false, isDefined:true)
2023-08-23 10:43:29.280 [DEBUG] [e.internal.handler.Clip2ThingHandler] - 01c720ba-e4c0-4f84-9510-5b48306815b1 → onResource() consumed resource id:17cb6eff-650e-455c-bfd2-e6c41e676179, type:zigbee_connectivity
2023-08-23 10:43:39.184 [DEBUG] [.internal.handler.Clip2BridgeHandler] - checkConnection()
2023-08-23 10:43:39.184 [DEBUG] [.hue.internal.connection.Clip2Bridge] - testConnectionState()
2023-08-23 10:43:39.184 [DEBUG] [.hue.internal.connection.Clip2Bridge] - openPassive()
2023-08-23 10:43:39.184 [DEBUG] [.hue.internal.connection.Clip2Bridge] - openSession()
2023-08-23 10:43:42.240 [DEBUG] [.hue.internal.connection.Clip2Bridge] - close2()
2023-08-23 10:43:42.240 [DEBUG] [.hue.internal.connection.Clip2Bridge] - closeSession()
2023-08-23 10:43:42.240 [DEBUG] [.internal.handler.Clip2BridgeHandler] - checkConnection() Error opening HTTP 2 session
org.openhab.binding.hue.internal.exceptions.ApiException: Error opening HTTP 2 session
at org.openhab.binding.hue.internal.connection.Clip2Bridge.openSession(Clip2Bridge.java:922) ~[?:?]
at org.openhab.binding.hue.internal.connection.Clip2Bridge.openPassive(Clip2Bridge.java:895) ~[?:?]
at org.openhab.binding.hue.internal.connection.Clip2Bridge.testConnectionState(Clip2Bridge.java:1073) ~[?:?]
at org.openhab.binding.hue.internal.handler.Clip2BridgeHandler.checkConnection(Clip2BridgeHandler.java:168) ~[?:?]
at org.openhab.binding.hue.internal.handler.Clip2BridgeHandler.lambda$6(Clip2BridgeHandler.java:517) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: java.util.concurrent.ExecutionException: java.net.NoRouteToHostException: No route to host
at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:395) ~[?:?]
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2022) ~[?:?]
at org.openhab.binding.hue.internal.connection.Clip2Bridge.openSession(Clip2Bridge.java:919) ~[?:?]
… 10 more
Caused by: java.net.NoRouteToHostException: No route to host
at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) ~[?:?]
at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:777) ~[?:?]
at org.eclipse.jetty.io.SelectorManager.doFinishConnect(SelectorManager.java:355) ~[?:?]
at org.eclipse.jetty.io.ManagedSelector.processConnect(ManagedSelector.java:347) ~[?:?]
at org.eclipse.jetty.io.ManagedSelector.access$1700(ManagedSelector.java:65) ~[?:?]
at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.processSelected(ManagedSelector.java:676) ~[?:?]
at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:535) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:362) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:186) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) ~[?:?]
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) ~[?:?]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) ~[?:?]
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) ~[?:?]
… 1 more
2023-08-23 10:43:59.416 [DEBUG] [.internal.handler.Clip2BridgeHandler] - getResources() id:* , type:room
2023-08-23 10:43:59.487 [DEBUG] [.internal.handler.Clip2BridgeHandler] - getResources() id:* , type:device
2023-08-23 10:43:59.561 [DEBUG] [.internal.handler.Clip2BridgeHandler] - getResources() id:* , type:bridge_home
2023-08-23 10:43:59.623 [DEBUG] [.internal.handler.Clip2BridgeHandler] - getResources() id:* , type:zone
2023-08-23 10:44:02.801 [DEBUG] [.internal.handler.Clip2BridgeHandler] - getResources() id:* , type:room
2023-08-23 10:44:02.816 [DEBUG] [.hue.internal.connection.Clip2Bridge] - checkAlive()
2023-08-23 10:44:02.820 [DEBUG] [.hue.internal.connection.Clip2Bridge] - checkAliveOk()
2023-08-23 10:44:02.830 [DEBUG] [.internal.handler.Clip2BridgeHandler] - getResources() id:* , type:device
2023-08-23 10:44:02.929 [DEBUG] [.internal.handler.Clip2BridgeHandler] - getResources() id:* , type:bridge_home
2023-08-23 10:44:02.989 [DEBUG] [.internal.handler.Clip2BridgeHandler] - getResources() id:* , type:zone
2023-08-23 10:44:33.777 [DEBUG] [.hue.internal.connection.Clip2Bridge] - checkAlive()
2023-08-23 10:44:33.778 [DEBUG] [.hue.internal.connection.Clip2Bridge] - checkAliveOk()
2023-08-23 10:44:42.244 [DEBUG] [.internal.handler.Clip2BridgeHandler] - checkConnection()
2023-08-23 10:44:42.244 [DEBUG] [.hue.internal.connection.Clip2Bridge] - testConnectionState()
2023-08-23 10:44:42.244 [DEBUG] [.hue.internal.connection.Clip2Bridge] - openPassive()
2023-08-23 10:44:42.244 [DEBUG] [.hue.internal.connection.Clip2Bridge] - openSession()
2023-08-23 10:44:42.563 [DEBUG] [.hue.internal.connection.Clip2Bridge] - close2()
2023-08-23 10:44:42.564 [DEBUG] [.hue.internal.connection.Clip2Bridge] - closeSession()
2023-08-23 10:44:42.564 [DEBUG] [.internal.handler.Clip2BridgeHandler] - checkConnection() Error opening HTTP 2 session
org.openhab.binding.hue.internal.exceptions.ApiException: Error opening HTTP 2 session
at org.openhab.binding.hue.internal.connection.Clip2Bridge.openSession(Clip2Bridge.java:922) ~[?:?]
at org.openhab.binding.hue.internal.connection.Clip2Bridge.openPassive(Clip2Bridge.java:895) ~[?:?]
at org.openhab.binding.hue.internal.connection.Clip2Bridge.testConnectionState(Clip2Bridge.java:1073) ~[?:?]
at org.openhab.binding.hue.internal.handler.Clip2BridgeHandler.checkConnection(Clip2BridgeHandler.java:168) ~[?:?]
at org.openhab.binding.hue.internal.handler.Clip2BridgeHandler.lambda$0(Clip2BridgeHandler.java:256) ~[?:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: java.util.concurrent.ExecutionException: java.net.NoRouteToHostException: No route to host
at java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:395) ~[?:?]
at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2022) ~[?:?]
at org.openhab.binding.hue.internal.connection.Clip2Bridge.openSession(Clip2Bridge.java:919) ~[?:?]
… 10 more
Caused by: java.net.NoRouteToHostException: No route to host
at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) ~[?:?]
at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:777) ~[?:?]
at org.eclipse.jetty.io.SelectorManager.doFinishConnect(SelectorManager.java:355) ~[?:?]
at org.eclipse.jetty.io.ManagedSelector.processConnect(ManagedSelector.java:347) ~[?:?]
at org.eclipse.jetty.io.ManagedSelector.access$1700(ManagedSelector.java:65) ~[?:?]
at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.processSelected(ManagedSelector.java:676) ~[?:?]
at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:535) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:362) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:186) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) ~[?:?]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) ~[?:?]
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) ~[?:?]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) ~[?:?]
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) ~[?:?]
… 1 more
2023-08-23 10:45:09.642 [DEBUG] [.hue.internal.connection.Clip2Bridge] - onEventData() data length:308
2023-08-23 10:45:09.642 [DEBUG] [.internal.handler.Clip2BridgeHandler] - onResourcesEventTask() resource count 1
2023-08-23 10:45:09.642 [DEBUG] [e.internal.handler.Clip2ThingHandler] - fea38ab7-8bf0-4cc9-8244-9025b3eb0273 → updateChannels() from resource id:e18cd93d-1c6d-40d1-bb7f-6b8dd4647ba7, type:zigbee_connectivity
2023-08-23 10:45:09.643 [DEBUG] [e.internal.handler.Clip2ThingHandler] - fea38ab7-8bf0-4cc9-8244-9025b3eb0273 → updateConnectivityState() thingStatus:ONLINE, zigbeeStatus:Connectivity issue
2023-08-23 10:45:09.643 [DEBUG] [e.internal.handler.Clip2ThingHandler] - fea38ab7-8bf0-4cc9-8244-9025b3eb0273 → updateState() ‘last-updated’ update with ‘2023-08-23T10:45:09.643348+0200’ (fullUpdate:false, isDefined:true)
2023-08-23 10:45:09.643 [DEBUG] [e.internal.handler.Clip2ThingHandler] - fea38ab7-8bf0-4cc9-8244-9025b3eb0273 → onResource() consumed resource id:e18cd93d-1c6d-40d1-bb7f-6b8dd4647ba7, type:zigbee_connectivity
and events.log
2023-08-23 10:43:42.243 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘hue:bridge-api2:66exxxxxxx’ changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Ein unerwarteter Fehler is
t während der Aktualisierung aufgetreten.
2023-08-23 10:43:42.243 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘hue:device:66exxxxxxx:15’ changed from OFFLINE: Zigbee connectivity issue. to OFFLINE (BRIDGE_OFFLINE)
2023-08-23 10:43:42.243 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘hue:device:66exxxxxxx:13’ changed from OFFLINE: Zigbee connectivity issue. to OFFLINE (BRIDGE_OFFLINE)
2023-08-23 10:43:42.243 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘hue:device:66exxxxxxx:14’ changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2023-08-23 10:43:42.244 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘hue:device:66exxxxxxx:16’ changed from OFFLINE: Zigbee connectivity issue. to OFFLINE (BRIDGE_OFFLINE)
2023-08-23 10:43:42.244 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘hue:device:66exxxxxxx:11’ changed from OFFLINE: Zigbee connectivity issue. to OFFLINE (BRIDGE_OFFLINE)
2023-08-23 10:43:42.244 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘hue:device:66exxxxxxx:12’ changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2023-08-23 10:43:42.244 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘hue:device:66exxxxxxx:8’ changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2023-08-23 10:43:42.244 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘hue:device:66exxxxxxx:7’ changed from OFFLINE: Zigbee connectivity issue. to OFFLINE (BRIDGE_OFFLINE)
2023-08-23 10:43:42.244 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘hue:device:66exxxxxxx:6’ changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2023-08-23 10:43:42.244 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘hue:device:66exxxxxxx:5’ changed from OFFLINE: Zigbee connectivity issue. to OFFLINE (BRIDGE_OFFLINE)
2023-08-23 10:43:42.244 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘hue:device:66exxxxxxx:4’ changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2023-08-23 10:43:42.245 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘hue:room:66exxxxxxx:1’ changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2023-08-23 10:43:42.245 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘hue:room:66exxxxxxx:2’ changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2023-08-23 10:43:42.245 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘hue:device:66exxxxxxx:10’ changed from OFFLINE: Zigbee connectivity issue. to OFFLINE (BRIDGE_OFFLINE)
2023-08-23 10:43:42.245 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing ‘hue:device:66exxxxxxx:9’ changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
Not sure if this will help, but I am also having problems with the Hue bindings in 4.0.2. My bridge is also on 1.51.1959097030
The bridge stays online and most bulbs are working, but I do have two Ikea Tradfri bulbs, one works fine, on FW 1.2.214, and the other one on FW 1.2.217 caused the following:
2023-08-24 18:04:20.653 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'Light_LED_Hue_Hall_Switch' received command ON
2023-08-24 18:04:20.656 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'Light_LED_Hue_Hall_Switch' predicted to become ON
2023-08-24 18:04:20.679 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'hue:0220:001788ae9d76:14' changed from ONLINE to OFFLINE (CONFIGURATION_ERROR): No light with given ID available on Hue Bridge.
All lights work as expected in the Hue App and my bridge stays online. I have removed the binding and tried adding the light as a group item with no success.
The NoRouteToHost exception says it all. This is a routing problem on your WLAN and not a binding issue. I suggest to switch to Ethernet rather than wifi if you can. Also make sure that you have static/reserved IP addresses on everything. And if you cannot avoid wifi then at least make sure the link is using fixed radio channels.
I also have some Ikea lamps on my Hue, which work fine, so I know it is not a generic problem with Ikea.
In both cases, do those lamps appear in the Hue app? (As individual lamps … your comment about ‘groups’ is irrelevant). And are they both controllable from the App?
Otherwise I would need to see a log TRACE containing the JSON of the lamps when the bridge thing is disabled and enabled.
I see that that thing is an API v1 thing. Are you using API v1 or v2 on the bridge thing? If you are trying a mixed combination you know it won’t work. And if it is an all v1 system you may need someone else to help you as I am only an expert on v2…
Your comment pointing out I was still trying to use a v1 thing was of great help. For some reason the binding did not find the V2 things automatically - I removed the binding and all related hue light things, cleared cache, rebooted and reinstall the bindings and things - Everything is now working as expected.
In version 4.02 I have experienced a Fatal Error, and the Hue session is closed. The seems to happen approx. every second day. However, it is usually not a problem, as the binding seems to recover by itself.
However, yesterday I had another error variant, where the binding did not recover. After many hours of no messages in the OH log file, I suddenly see this:
and all Hue devices are not responsive. In OH the bridge is offline, and toggle between offline and online made it work again.
So two bulbs are turned with a few milliseconds between them. Previously, you wrote that you have forced a serial connection where a request must be completed before sending a new one. Would it make sense to add a delay - maybe configurable - just to see if this helps on the behaviour of the hue bridge?
I assume the CLIP2 API is used in the Hue app itself without problems, and no human can turn on or off different entities as fast as shown in the log entries.
Yesterday we merged a new pull request that fixes both these issues. It will be in the latest snapshot and the next milestone release.
EDIT apropos your question about timing: the Hue bridge can get overloaded if more than about 20 commands are sent to it per second; so the binding throttles commands to be sent no more than 1 per 50msec.
@mri0202 - I was curious and explored the API a bit. I have now created an issue for getting back the “last motion” value which can also be seen in the Hue app:
I have been using OH2.5 with the CLIP API 1 for quite some time and have just migrated to OH4 and CLIP 2. In my previous configuration I had hue rooms and zones added as things with the associated items/channels to control color, colour_temperature etc. I notice now with the new binding that the only channel available for rooms and zones is the brightness channel. If I want to control colour and colour_temperature etc I need to add all individual bulbs.
Before I reconfigure and add an extra 60 items to my configuration, can you confirm that what I am saying is correct please?
…and thanks for the great work on this by the way.
I’m not able to get my things online with the new API. I must be doing something wrong but I cannot find it. All my things are configured via text file and are unknown in the UI. Below is how i configured it. As of my knowing, this must be correct but it just doesn’t work.
My hue bridge software version is: 1.59.1959194040