search

stefan-kaestle / openhab2-addons

Add-ons for openHAB 2.x
Eclipse Public License 2.0
16 stars 1 forks source link

After Update and Reboot the Controller the Thing is Offline #74

Closed jkarsten closed 3 years ago

jkarsten commented 3 years ago

Hello,

yesterday i had an Update Message in the Bosch App. After the Update and the Reboot my Controller Thing is Offline. I need to restart the Thing.

I dont know if this will happen when you disconect Power.

Jörg

coeing commented 3 years ago

As @tuxianerDE mentioned in #62 only the state updates stopped working after the controller update. So I hope we get a specific LongPollError in case of an update (the reason might be that the long polling subscription becomes invalid). We should see that in the logs. In that case we can easily restart the long polling as it is done already.

GerdZanker commented 3 years ago

Same happened for me during my SHC update. The Long Polling was stopped and the Bridge Thing was "offline.

A recovery of the Bridge after unusual failures like updated, network outage, etc. is useful. Compare with this comment

coeing commented 3 years ago

A recovery of the Bridge after unusual failures like updated, network outage, etc. is useful. Compare with this comment

Yes, there is already a fallback for the long polling but it does not seem to work. I guess it is for the same reason as #62 (sending a new request within a http thread). I will probably see it in the logs once one of you provided them :)

GerdZanker commented 3 years ago

Here is the log from my controller update

2021-01-26 20:17:19.937 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-26 20:17:19.938 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@18fc7da{STARTED}
2021-01-26 20:17:19.939 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.178.31:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/longPoll","params":["ef5lmcknf-133","20"]}
2021-01-26 20:17:49.946 [WARN ] [devices.bridge.BoschSHCBridgeHandler] - Long polling failed, trying to restart
org.openhab.binding.boschshc.internal.exceptions.LongPollingFailedException: Unexpected exception during long polling request
    at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling$1.onComplete(LongPolling.java:179) [bundleFile:?]
    at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:198) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:190) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:444) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.HttpReceiver.abort(HttpReceiver.java:527) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.HttpChannel.abortResponse(HttpChannel.java:156) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.HttpChannel.abort(HttpChannel.java:149) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.HttpExchange.abort(HttpExchange.java:257) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.HttpConversation.abort(HttpConversation.java:149) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.HttpRequest.abort(HttpRequest.java:768) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.TimeoutCompleteListener.onTimeoutExpired(TimeoutCompleteListener.java:51) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.io.CyclicTimeout$Wakeup.run(CyclicTimeout.java:282) [bundleFile:9.4.20.v20190813]
    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:834) [?:?]
Caused by: java.util.concurrent.TimeoutException: Total timeout 30000 ms elapsed
    ... 8 more
2021-01-26 20:17:50.019 [DEBUG] [.internal.devices.bridge.LongPolling] - Subscribe: Sending request: {"jsonrpc":"2.0","method":"RE/subscribe","params":["com/bosch/sh/remote/*",null]} - using httpClient BoschHttpClient@18fc7da{STARTED}
2021-01-26 20:17:50.020 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@18fc7da{STARTED}
2021-01-26 20:17:50.021 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.178.31:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/subscribe","params":["com/bosch/sh/remote/*",null]}
2021-01-26 20:17:50.022 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Send request: HttpRequest[POST /remote/json-rpc HTTP/1.1]@608c4

Afterwards the bridge was offline.

GerdZanker commented 3 years ago

Here is a log where I disconnected the SHC from the network to check what will happen

2021-01-27 20:06:10.717 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-27 20:06:10.721 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@a6cf34{STARTED}
2021-01-27 20:06:10.724 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.178.31:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/longPoll","params":["ef9ehknk3-18","20"]}
2021-01-27 20:06:40.741 [WARN ] [devices.bridge.BoschSHCBridgeHandler] - Long polling failed, trying to restart
org.openhab.binding.boschshc.internal.exceptions.LongPollingFailedException: Unexpected exception during long polling request
    at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling$1.onComplete(LongPolling.java:179) [bundleFile:?]
    at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:198) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:190) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:444) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.HttpReceiver.abort(HttpReceiver.java:527) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.HttpChannel.abortResponse(HttpChannel.java:156) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.HttpChannel.abort(HttpChannel.java:149) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.HttpExchange.abort(HttpExchange.java:257) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.HttpConversation.abort(HttpConversation.java:149) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.HttpRequest.abort(HttpRequest.java:768) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.TimeoutCompleteListener.onTimeoutExpired(TimeoutCompleteListener.java:51) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.io.CyclicTimeout$Wakeup.run(CyclicTimeout.java:282) [bundleFile:9.4.20.v20190813]
    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:834) [?:?]
Caused by: java.util.concurrent.TimeoutException: Total timeout 30000 ms elapsed
    ... 8 more
2021-01-27 20:06:40.829 [DEBUG] [.internal.devices.bridge.LongPolling] - Subscribe: Sending request: {"jsonrpc":"2.0","method":"RE/subscribe","params":["com/bosch/sh/remote/*",null]} - using httpClient BoschHttpClient@a6cf34{STARTED}
2021-01-27 20:06:40.832 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@a6cf34{STARTED}
2021-01-27 20:06:40.835 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.178.31:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/subscribe","params":["com/bosch/sh/remote/*",null]}
2021-01-27 20:06:40.837 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Send request: HttpRequest[POST /remote/json-rpc HTTP/1.1]@1143d02

looks the same as during the controller update.

The BoschSHCBridgeHandler set the bridge to offline and our long poll loop is stopped 2021-01-27 20_08_37-openHAB

coeing commented 3 years ago

@GerdZanker Disconnecting the controller looks like a good way to test this issue :) It looks like the current running long poll request times out which is expected due to the disconnect of the controller (I hoped that the API will send a specific error code in that case, so we know that the controller restarts, but it does not look like it).

First I will check if the re-subscribe request is send in the correct thread. Another (or a second) reason could be that the controller needs too long to be online again, so the re-subscribe request times out as well. We have to see how long we will try to subscribe before reporting an error.

coeing commented 3 years ago

Thanks to @MarkJonas we have the proof that the update was the reason for the long polling to stop 👍

2021-01-26 19:26:39.069 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[{"path":"/system/services/SoftwareUpdate","@type":"DeviceServiceData","id":"SoftwareUpdate","state":{"swUpdateLastResult":"UPDATE_SUCCESS","@type":"softwareUpdateState","swUpdateState":"UPDATE_IN_PROGRESS","swUpdateAvailableVersion":"9.22.1838-17015-9.22.1834-16690","swInstalledVersion":"9.22.1834-16690","swActivationDate":{"@type":"softwareActivationDate","timeout":604800000}},"deviceId":"xxx"}],"jsonrpc":"2.0"}

I will create a new version to test with.

coeing commented 3 years ago

New version is here: https://github.com/stefan-kaestle/openhab2-addons/releases/tag/v1.0-bugfix.74 I will try it myself with a manual disconnect.

coeing commented 3 years ago

The restart works with the new version. But as expected the re-subscribe request fails with a timeout after 10 seconds:

2021-01-27 20:40:23.822 [WARN ] [devices.bridge.BoschSHCBridgeHandler] - Long polling failed, will try to restart org.openhab.binding.boschshc.internal.exceptions.LongPollingFailedException: Unexpected exception during long polling request at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling.onLongPollComplete(LongPolling.java:199) [bundleFile:?] at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling$1.lambda$0(LongPolling.java:165) [bundleFile:?] 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:834) [?:?] Caused by: java.io.EOFException: HttpConnectionOverHTTP@74627873::DecryptedEndPoint@459b47f6{/192.168.178.55:8444<->/172.17.0.3:52200,OPEN,fill=-,flush=-,to=26958/0} at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.earlyEOF(HttpReceiverOverHTTP.java:335) ~[?:?] at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1526) ~[?:?] at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.shutdown(HttpReceiverOverHTTP.java:209) ~[?:?] at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:147) ~[?:?] at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:73) ~[?:?] at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:133) ~[?:?] at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:154) ~[?:?] at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[?:?] at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) ~[?:?] at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:426) ~[?:?] at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:320) ~[?:?] at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:158) ~[?:?] at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) ~[?:?] at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) ~[?:?] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) ~[?:?] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) ~[?:?] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) ~[?:?] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) ~[?:?] at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:367) ~[?:?] at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782) ~[?:?] at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918) ~[?:?] ... 1 more 2021-01-27 20:40:33.897 [WARN ] [devices.bridge.BoschSHCBridgeHandler] - Long polling restart failed org.openhab.binding.boschshc.internal.exceptions.LongPollingFailedException: Error on subscribe request (Http client: BoschHttpClient@64cb30f3{STARTED}) at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling.subscribe(LongPolling.java:120) ~[bundleFile:?] at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling.start(LongPolling.java:87) ~[bundleFile:?] at org.openhab.binding.boschshc.internal.devices.bridge.BoschSHCBridgeHandler.handleLongPollFailure(BoschSHCBridgeHandler.java:299) [bundleFile:?] at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling.onLongPollComplete(LongPolling.java:198) [bundleFile:?] at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling$1.lambda$0(LongPolling.java:165) [bundleFile:?] 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:834) [?:?] Caused by: java.util.concurrent.TimeoutException: Total timeout 10000 ms elapsed at org.eclipse.jetty.client.HttpDestination$TimeoutTask.onTimeoutExpired(HttpDestination.java:529) ~[?:?] at org.eclipse.jetty.io.CyclicTimeout$Wakeup.run(CyclicTimeout.java:282) ~[?:?] ... 6 more

We should probably increase the timeout there, but the question is to what duration? @GerdZanker Any idea how long the restart during an update takes?

jkarsten commented 3 years ago

Hi, I tested the binding today. I discount the Power and reconnect IT after a Minute. After a Short time the Thing was offline. After about 10 minutes it was online again. Looks Good for me, Jörg

GerdZanker commented 3 years ago

Any idea how long the restart during an update takes?

Sorry I have no idea. The SHC software is Linux and Java/OSGi as far as I know and I would use the SHC LED as an indication to check when the startup phase is finished. My personal guess is >30 seconds, up to 4-5 Minutes which I know best from my RPi.

I not took a look into your code how you @coeing improved it. My current idea in mind is do retries e.g. every 30 seconds if the bridge can connect again.

coeing commented 3 years ago

Any idea how long the restart during an update takes?

Sorry I have no idea. The SHC software is Linux and Java/OSGi as far as I know and I would use the SHC LED as an indication to check when the startup phase is finished. My personal guess is >30 seconds, up to 4-5 Minutes which I know best from my RPi.

I not took a look into your code how you @coeing improved it. My current idea in mind is do retries e.g. every 30 seconds if the bridge can connect again.

Thought about ~5 minutes as well. I will see if one request with such a long timeout is enough or if I have to do retries.

coeing commented 3 years ago

Alright, I think this should work: When long polling fails the bridge is now completely reinitialized by running scheduleInitialAccess again. This way every 15 seconds it is checked if the controller is accessible (@GerdZanker there is a minor bug in it, see #75) and if so the pairing is validated (which should still work) and the long polling is started again.

This sounds like a clean and solid solution. You can test it with the new version from https://github.com/stefan-kaestle/openhab2-addons/releases/tag/v1.0-bugfix.74 (3.1.0.202101281924) by plugging your controller out and in again. It should work again in openHAB after a few minutes (for me it took ~5.5 minutes! So don't be too impatient ;) ).

coeing commented 3 years ago

I already created a pull request (#76), but will wait with the merge until I got some positive feedback from you guys! :)

jkarsten commented 3 years ago

Ok this morning i looked in my Thingslist and the Controller was still online. But the Values are still the same. I looked into the logs and found after he connected again to the controller

2021-01-28 18:36:47.987 [DEBUG] [.internal.devices.bridge.LongPolling] - Canceling long polling for subscription id efabe96ij-1 because it was aborted This are the last 15 Minutes from the log:

`2021-01-28 18:23:09.105 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-28 18:23:09.106 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@37008db3{STARTED} 2021-01-28 18:23:09.107 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.2.204:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/longPoll","params":["ef9e795ch-19","20"]} 2021-01-28 18:23:29.163 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-28 18:23:29.165 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-28 18:23:29.166 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@37008db3{STARTED} 2021-01-28 18:23:29.167 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.2.204:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/longPoll","params":["ef9e795ch-19","20"]} 2021-01-28 18:23:49.223 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-28 18:23:49.226 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-28 18:23:49.227 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@37008db3{STARTED} 2021-01-28 18:23:49.228 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.2.204:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/longPoll","params":["ef9e795ch-19","20"]} 2021-01-28 18:23:54.636 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[{"path":"/devices/hdm:HomeMaticIP:3014F711A000005BB85E1A11/services/TemperatureLevel","@type":"DeviceServiceData","id":"TemperatureLevel","state":{"@type":"temperatureLevelState","temperature":21.3},"deviceId":"hdm:HomeMaticIP:3014F711A000005BB85E1A11"}],"jsonrpc":"2.0"}

2021-01-28 18:23:54.637 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Got update for hdm:HomeMaticIP:3014F711A000005BB85E1A11 2021-01-28 18:23:54.638 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_2 - looking for hdm:HomeMaticIP:3014F711A000005BB85E1A11 2021-01-28 18:23:54.639 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_4 - looking for hdm:HomeMaticIP:3014F711A000005BB85E1A11 2021-01-28 18:23:54.640 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_1 - looking for hdm:HomeMaticIP:3014F711A000005BB85E1A11 2021-01-28 18:23:54.641 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_3 - looking for hdm:HomeMaticIP:3014F711A000005BB85E1A11 2021-01-28 18:23:54.642 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_5 - looking for hdm:HomeMaticIP:3014F711A000005BB85E1A11 2021-01-28 18:23:54.642 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-28 18:23:54.643 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@37008db3{STARTED} 2021-01-28 18:23:54.643 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.2.204:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/longPoll","params":["ef9e795ch-19","20"]} 2021-01-28 18:23:54.698 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[{"path":"/devices/roomClimateControl_hz_2/services/TemperatureLevel","@type":"DeviceServiceData","id":"TemperatureLevel","state":{"@type":"temperatureLevelState","temperature":21.3},"deviceId":"roomClimateControl_hz_2"}],"jsonrpc":"2.0"}

2021-01-28 18:23:54.699 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Got update for roomClimateControl_hz_2 2021-01-28 18:23:54.700 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_2 - looking for roomClimateControl_hz_2 2021-01-28 18:23:54.700 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.climatecontrol.ClimateControlHandler@4b71907c - calling processUpdate with {"@type":"temperatureLevelState","temperature":21.3} 2021-01-28 18:23:54.701 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_4 - looking for roomClimateControl_hz_2 2021-01-28 18:23:54.702 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_1 - looking for roomClimateControl_hz_2 2021-01-28 18:23:54.704 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_3 - looking for roomClimateControl_hz_2 2021-01-28 18:23:54.705 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_5 - looking for roomClimateControl_hz_2 2021-01-28 18:23:54.705 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-28 18:23:54.706 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@37008db3{STARTED} 2021-01-28 18:23:54.706 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.2.204:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/longPoll","params":["ef9e795ch-19","20"]} 2021-01-28 18:24:14.759 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-28 18:24:14.763 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-28 18:24:14.765 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@37008db3{STARTED} 2021-01-28 18:24:14.767 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.2.204:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/longPoll","params":["ef9e795ch-19","20"]} 2021-01-28 18:24:44.774 [WARN ] [devices.bridge.BoschSHCBridgeHandler] - Long polling failed, trying to restart org.openhab.binding.boschshc.internal.exceptions.LongPollingFailedException: Unexpected exception during long polling request at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling.onLongPollComplete(LongPolling.java:199) [bundleFile:?] at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling$1.lambda$0(LongPolling.java:165) [bundleFile:?] 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:834) [?:?] Caused by: java.util.concurrent.TimeoutException: Total timeout 30000 ms elapsed at org.eclipse.jetty.client.TimeoutCompleteListener.onTimeoutExpired(TimeoutCompleteListener.java:51) ~[?:?] at org.eclipse.jetty.io.CyclicTimeout$Wakeup.run(CyclicTimeout.java:282) ~[?:?] ... 6 more 2021-01-28 18:24:44.784 [DEBUG] [.internal.devices.bridge.LongPolling] - Subscribe: Sending request: {"jsonrpc":"2.0","method":"RE/subscribe","params":["com/bosch/sh/remote/",null]} - using httpClient BoschHttpClient@37008db3{STARTED} 2021-01-28 18:24:44.785 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@37008db3{STARTED} 2021-01-28 18:24:44.786 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.2.204:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/subscribe","params":["com/bosch/sh/remote/",null]} 2021-01-28 18:24:44.787 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Send request: HttpRequest[POST /remote/json-rpc HTTP/1.1]@166db718 2021-01-28 18:36:11.507 [DEBUG] [internal.devices.bridge.BoschSslUtil] - Using existing keystore /var/lib/openhab/etc/oss_openhab_binding_192.168.2.204.jks 2021-01-28 18:36:11.548 [WARN ] [ty.util.ssl.SslContextFactory.config] - Trusting all certificates configured for Client@5d793ae[provider=null,keyStore=file:///var/lib/openhab/etc/oss_openhab_binding_192.168.2.204.jks,trustStore=null] 2021-01-28 18:36:11.550 [WARN ] [ty.util.ssl.SslContextFactory.config] - No Client EndPointIdentificationAlgorithm configured for Client@5d793ae[provider=null,keyStore=file:///var/lib/openhab/etc/oss_openhab_binding_192.168.2.204.jks,trustStore=null] 2021-01-28 18:36:26.553 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Initializing Bosch SHC Bridge: org.openhab.binding.boschshc.internal.devices.bridge.BoschSHCBridgeHandler@6d81941d - HTTP client is: BoschHttpClient@1244e5f8{STARTED} - version: 2020-04-05 2021-01-28 18:36:26.556 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@1244e5f8{STARTED} 2021-01-28 18:36:26.558 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.2.204:8444/smarthome/devices 2021-01-28 18:36:27.632 [DEBUG] [ernal.devices.bridge.BoschHttpClient] - Access check response complete: [{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"hdm:HomeMaticIP:3014F711A000005BB85E1B04","deviceServiceIds":["Thermostat","BatteryLevel","ValveTappet","TemperatureLevel","Linking","TemperatureOffset"],"manufacturer":"BOSCH","roomId":"hz_4","deviceModel":"TRV","serial":"3014F711A000005BB85E1B04","profile":"GENERIC","name":"Heizung Büro","status":"AVAILABLE","parentDeviceId":"roomClimateControl_hz_4","childDeviceIds":[]},{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"hdm:HomeMaticIP:3014F711A000005BB85E1B47","deviceServiceIds":["Thermostat","BatteryLevel","ValveTappet","TemperatureLevel","Linking","TemperatureOffset"],"manufacturer":"BOSCH","roomId":"hz_5","deviceModel":"TRV","serial":"3014F711A000005BB85E1B47","profile":"GENERIC","name":"Heizung Schlafzimmer","status":"AVAILABLE","parentDeviceId":"roomClimateControl_hz_5","childDeviceIds":[]},{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"ventilationService","deviceServiceIds":["VentilationDelay"],"manufacturer":"BOSCH","deviceModel":"VENTILATION_SERVICE","serial":"ventilationService","name":"-VentilationService-","status":"AVAILABLE","childDeviceIds":[]},{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"roomClimateControl_hz_2","deviceServiceIds":["TemperatureLevelConfiguration","RoomClimateControl","TemperatureLevel"],"manufacturer":"BOSCH","roomId":"hz_2","deviceModel":"ROOM_CLIMATE_CONTROL","serial":"roomClimateControl_hz_2","iconId":"icon_room_living_room_rcc","name":"-RoomClimateControl-","status":"AVAILABLE","childDeviceIds":["hdm:HomeMaticIP:3014F711A000005BB85E1A11"]},{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"roomClimateControl_hz_5","deviceServiceIds":["TemperatureLevelConfiguration","RoomClimateControl","TemperatureLevel"],"manufacturer":"BOSCH","roomId":"hz_5","deviceModel":"ROOM_CLIMATE_CONTROL","serial":"roomClimateControl_hz_5","iconId":"icon_room_bedroom_rcc","name":"-RoomClimateControl-","status":"AVAILABLE","childDeviceIds":["hdm:HomeMaticIP:3014F711A000005BB85E1B47"]},{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"hdm:PhilipsHueBridge:PhilipsHueBridgeManager","deviceServiceIds":["HueBridgeConnector","HueBridgeSearcher"],"manufacturer":"PHILIPS","deviceModel":"HUE_BRIDGE_MANAGER","profile":"GENERIC","name":"PhilipsHueBridgeManager","status":"AVAILABLE","childDeviceIds":[]},{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"roomClimateControl_hz_4","deviceServiceIds":["TemperatureLevelConfiguration","RoomClimateControl","TemperatureLevel"],"manufacturer":"BOSCH","roomId":"hz_4","deviceModel":"ROOM_CLIMATE_CONTROL","serial":"roomClimateControl_hz_4","iconId":"icon_room_office_rcc","name":"-RoomClimateControl-","status":"AVAILABLE","childDeviceIds":["hdm:HomeMaticIP:3014F711A000005BB85E1B04"]},{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"hdm:HomeMaticIP:3014F711A000005BB85E1B0B","deviceServiceIds":["Thermostat","BatteryLevel","ValveTappet","TemperatureLevel","Linking","TemperatureOffset"],"manufacturer":"BOSCH","roomId":"hz_3","deviceModel":"TRV","serial":"3014F711A000005BB85E1B0B","profile":"GENERIC","name":"Heizung Kinderzimmer","status":"AVAILABLE","parentDeviceId":"roomClimateControl_hz_3","childDeviceIds":[]},{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"hdm:HomeMaticIP:3014F711A000005BB85E1B2C","deviceServiceIds":["Thermostat","BatteryLevel","ValveTappet","TemperatureLevel","Linking","TemperatureOffset"],"manufacturer":"BOSCH","roomId":"hz_1","deviceModel":"TRV","serial":"3014F711A000005BB85E1B2C","profile":"GENERIC","name":"Heizung Badezimmer","status":"AVAILABLE","parentDeviceId":"roomClimateControl_hz_1","childDeviceIds":[]},{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"roomClimateControl_hz_3","deviceServiceIds":["TemperatureLevelConfiguration","RoomClimateControl","TemperatureLevel"],"manufacturer":"BOSCH","roomId":"hz_3","deviceModel":"ROOM_CLIMATE_CONTROL","serial":"roomClimateControl_hz_3","iconId":"icon_room_boy_room_rcc","name":"-RoomClimateControl-","status":"AVAILABLE","childDeviceIds":["hdm:HomeMaticIP:3014F711A000005BB85E1B0B"]},{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"roomClimateControl_hz_1","deviceServiceIds":["TemperatureLevelConfiguration","RoomClimateControl","TemperatureLevel"],"manufacturer":"BOSCH","roomId":"hz_1","deviceModel":"ROOM_CLIMATE_CONTROL","serial":"roomClimateControl_hz_1","iconId":"icon_room_bathroom_rcc","name":"-RoomClimateControl-","status":"AVAILABLE","childDeviceIds":["hdm:HomeMaticIP:3014F711A000005BB85E1B2C"]},{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"hdm:HomeMaticIP:3014F711A000005BB85E1A11","deviceServiceIds":["Thermostat","BatteryLevel","ValveTappet","TemperatureLevel","Linking","TemperatureOffset"],"manufacturer":"BOSCH","roomId":"hz_2","deviceModel":"TRV","serial":"3014F711A000005BB85E1A11","profile":"GENERIC","name":"Heizung Wohnzimmer","status":"AVAILABLE","parentDeviceId":"roomClimateControl_hz_2","childDeviceIds":[]}] - return code: 200 2021-01-28 18:36:27.633 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Sending http request to Bosch to request rooms 2021-01-28 18:36:27.635 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@1244e5f8{STARTED} 2021-01-28 18:36:27.636 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.2.204:8444/smarthome/rooms 2021-01-28 18:36:27.709 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Response complete: [{"@type":"room","id":"hz_5","iconId":"icon_room_bedroom","name":"Schlafzimmer"},{"@type":"room","id":"hz_2","iconId":"icon_room_living_room","name":"Wohnzimmer"},{"@type":"room","id":"hz_3","iconId":"icon_room_boy_room","name":"Kinderzimmer"},{"@type":"room","id":"hz_1","iconId":"icon_room_bathroom","name":"Badezimmer"},{"@type":"room","id":"hz_4","iconId":"icon_room_office","name":"Büro"}] - return code: 200 2021-01-28 18:36:27.712 [INFO ] [devices.bridge.BoschSHCBridgeHandler] - Found room: Schlafzimmer 2021-01-28 18:36:27.713 [INFO ] [devices.bridge.BoschSHCBridgeHandler] - Found room: Wohnzimmer 2021-01-28 18:36:27.715 [INFO ] [devices.bridge.BoschSHCBridgeHandler] - Found room: Kinderzimmer 2021-01-28 18:36:27.717 [INFO ] [devices.bridge.BoschSHCBridgeHandler] - Found room: Badezimmer 2021-01-28 18:36:27.718 [INFO ] [devices.bridge.BoschSHCBridgeHandler] - Found room: Büro 2021-01-28 18:36:27.719 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Sending http request to Bosch to request clients: BoschHttpClient@1244e5f8{STARTED} 2021-01-28 18:36:27.720 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@1244e5f8{STARTED} 2021-01-28 18:36:27.721 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.2.204:8444/smarthome/devices 2021-01-28 18:36:27.812 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Response complete: [{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"hdm:HomeMaticIP:3014F711A000005BB85E1B04","deviceServiceIds":["Thermostat","BatteryLevel","ValveTappet","TemperatureLevel","Linking","TemperatureOffset"],"manufacturer":"BOSCH","roomId":"hz_4","deviceModel":"TRV","serial":"3014F711A000005BB85E1B04","profile":"GENERIC","name":"Heizung Büro","status":"AVAILABLE","parentDeviceId":"roomClimateControl_hz_4","childDeviceIds":[]},{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"hdm:HomeMaticIP:3014F711A000005BB85E1B47","deviceServiceIds":["Thermostat","BatteryLevel","ValveTappet","TemperatureLevel","Linking","TemperatureOffset"],"manufacturer":"BOSCH","roomId":"hz_5","deviceModel":"TRV","serial":"3014F711A000005BB85E1B47","profile":"GENERIC","name":"Heizung Schlafzimmer","status":"AVAILABLE","parentDeviceId":"roomClimateControl_hz_5","childDeviceIds":[]},{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"ventilationService","deviceServiceIds":["VentilationDelay"],"manufacturer":"BOSCH","deviceModel":"VENTILATION_SERVICE","serial":"ventilationService","name":"-VentilationService-","status":"AVAILABLE","childDeviceIds":[]},{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"roomClimateControl_hz_2","deviceServiceIds":["TemperatureLevelConfiguration","RoomClimateControl","TemperatureLevel"],"manufacturer":"BOSCH","roomId":"hz_2","deviceModel":"ROOM_CLIMATE_CONTROL","serial":"roomClimateControl_hz_2","iconId":"icon_room_living_room_rcc","name":"-RoomClimateControl-","status":"AVAILABLE","childDeviceIds":["hdm:HomeMaticIP:3014F711A000005BB85E1A11"]},{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"roomClimateControl_hz_5","deviceServiceIds":["TemperatureLevelConfiguration","RoomClimateControl","TemperatureLevel"],"manufacturer":"BOSCH","roomId":"hz_5","deviceModel":"ROOM_CLIMATE_CONTROL","serial":"roomClimateControl_hz_5","iconId":"icon_room_bedroom_rcc","name":"-RoomClimateControl-","status":"AVAILABLE","childDeviceIds":["hdm:HomeMaticIP:3014F711A000005BB85E1B47"]},{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"hdm:PhilipsHueBridge:PhilipsHueBridgeManager","deviceServiceIds":["HueBridgeConnector","HueBridgeSearcher"],"manufacturer":"PHILIPS","deviceModel":"HUE_BRIDGE_MANAGER","profile":"GENERIC","name":"PhilipsHueBridgeManager","status":"AVAILABLE","childDeviceIds":[]},{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"roomClimateControl_hz_4","deviceServiceIds":["TemperatureLevelConfiguration","RoomClimateControl","TemperatureLevel"],"manufacturer":"BOSCH","roomId":"hz_4","deviceModel":"ROOM_CLIMATE_CONTROL","serial":"roomClimateControl_hz_4","iconId":"icon_room_office_rcc","name":"-RoomClimateControl-","status":"AVAILABLE","childDeviceIds":["hdm:HomeMaticIP:3014F711A000005BB85E1B04"]},{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"hdm:HomeMaticIP:3014F711A000005BB85E1B0B","deviceServiceIds":["Thermostat","BatteryLevel","ValveTappet","TemperatureLevel","Linking","TemperatureOffset"],"manufacturer":"BOSCH","roomId":"hz_3","deviceModel":"TRV","serial":"3014F711A000005BB85E1B0B","profile":"GENERIC","name":"Heizung Kinderzimmer","status":"AVAILABLE","parentDeviceId":"roomClimateControl_hz_3","childDeviceIds":[]},{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"hdm:HomeMaticIP:3014F711A000005BB85E1B2C","deviceServiceIds":["Thermostat","BatteryLevel","ValveTappet","TemperatureLevel","Linking","TemperatureOffset"],"manufacturer":"BOSCH","roomId":"hz_1","deviceModel":"TRV","serial":"3014F711A000005BB85E1B2C","profile":"GENERIC","name":"Heizung Badezimmer","status":"AVAILABLE","parentDeviceId":"roomClimateControl_hz_1","childDeviceIds":[]},{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"roomClimateControl_hz_3","deviceServiceIds":["TemperatureLevelConfiguration","RoomClimateControl","TemperatureLevel"],"manufacturer":"BOSCH","roomId":"hz_3","deviceModel":"ROOM_CLIMATE_CONTROL","serial":"roomClimateControl_hz_3","iconId":"icon_room_boy_room_rcc","name":"-RoomClimateControl-","status":"AVAILABLE","childDeviceIds":["hdm:HomeMaticIP:3014F711A000005BB85E1B0B"]},{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"roomClimateControl_hz_1","deviceServiceIds":["TemperatureLevelConfiguration","RoomClimateControl","TemperatureLevel"],"manufacturer":"BOSCH","roomId":"hz_1","deviceModel":"ROOM_CLIMATE_CONTROL","serial":"roomClimateControl_hz_1","iconId":"icon_room_bathroom_rcc","name":"-RoomClimateControl-","status":"AVAILABLE","childDeviceIds":["hdm:HomeMaticIP:3014F711A000005BB85E1B2C"]},{"@type":"device","rootDeviceId":"64-da-a0-10-04-80","id":"hdm:HomeMaticIP:3014F711A000005BB85E1A11","deviceServiceIds":["Thermostat","BatteryLevel","ValveTappet","TemperatureLevel","Linking","TemperatureOffset"],"manufacturer":"BOSCH","roomId":"hz_2","deviceModel":"TRV","serial":"3014F711A000005BB85E1A11","profile":"GENERIC","name":"Heizung Wohnzimmer","status":"AVAILABLE","parentDeviceId":"roomClimateControl_hz_2","childDeviceIds":[]}] - return code: 200 2021-01-28 18:36:27.819 [INFO ] [devices.bridge.BoschSHCBridgeHandler] - Found device: name=Heizung Büro id=hdm:HomeMaticIP:3014F711A000005BB85E1B04 2021-01-28 18:36:27.819 [INFO ] [devices.bridge.BoschSHCBridgeHandler] - Found device: name=Heizung Schlafzimmer id=hdm:HomeMaticIP:3014F711A000005BB85E1B47 2021-01-28 18:36:27.820 [INFO ] [devices.bridge.BoschSHCBridgeHandler] - Found device: name=-VentilationService- id=ventilationService 2021-01-28 18:36:27.822 [INFO ] [devices.bridge.BoschSHCBridgeHandler] - Found device: name=-RoomClimateControl- id=roomClimateControl_hz_2 2021-01-28 18:36:27.824 [INFO ] [devices.bridge.BoschSHCBridgeHandler] - Found device: name=-RoomClimateControl- id=roomClimateControl_hz_5 2021-01-28 18:36:27.825 [INFO ] [devices.bridge.BoschSHCBridgeHandler] - Found device: name=PhilipsHueBridgeManager id=hdm:PhilipsHueBridge:PhilipsHueBridgeManager 2021-01-28 18:36:27.827 [INFO ] [devices.bridge.BoschSHCBridgeHandler] - Found device: name=-RoomClimateControl- id=roomClimateControl_hz_4 2021-01-28 18:36:27.828 [INFO ] [devices.bridge.BoschSHCBridgeHandler] - Found device: name=Heizung Kinderzimmer id=hdm:HomeMaticIP:3014F711A000005BB85E1B0B 2021-01-28 18:36:27.830 [INFO ] [devices.bridge.BoschSHCBridgeHandler] - Found device: name=Heizung Badezimmer id=hdm:HomeMaticIP:3014F711A000005BB85E1B2C 2021-01-28 18:36:27.831 [INFO ] [devices.bridge.BoschSHCBridgeHandler] - Found device: name=-RoomClimateControl- id=roomClimateControl_hz_3 2021-01-28 18:36:27.832 [INFO ] [devices.bridge.BoschSHCBridgeHandler] - Found device: name=-RoomClimateControl- id=roomClimateControl_hz_1 2021-01-28 18:36:27.833 [INFO ] [devices.bridge.BoschSHCBridgeHandler] - Found device: name=Heizung Wohnzimmer id=hdm:HomeMaticIP:3014F711A000005BB85E1A11 2021-01-28 18:36:27.884 [DEBUG] [.internal.devices.bridge.LongPolling] - Subscribe: Sending request: {"jsonrpc":"2.0","method":"RE/subscribe","params":["com/bosch/sh/remote/",null]} - using httpClient BoschHttpClient@1244e5f8{STARTED} 2021-01-28 18:36:27.885 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@1244e5f8{STARTED} 2021-01-28 18:36:27.885 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.2.204:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/subscribe","params":["com/bosch/sh/remote/",null]} 2021-01-28 18:36:27.886 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Send request: HttpRequest[POST /remote/json-rpc HTTP/1.1]@9e6d305 2021-01-28 18:36:27.918 [DEBUG] [ernal.devices.bridge.BoschHttpClient] - Received response: {"result":"efabe96ij-1","jsonrpc":"2.0"}

coeing commented 3 years ago

@jkarsten Thanks for your logs! The long polling should only be aborted when the binding is stopped. Is it possible for you to reproduce this issue with the latest version by disconnecting the controller manually (either power or network should work)? If the issue is reproducible I can check it on my side.

coeing commented 3 years ago

@GerdZanker Did you have time to check my newest test version by manually disconnecting your controller and connecting it again? If my fix works I'd like to merge it and create a pull request into openHAB as a version 1.1. Afterwards we can fully concentrate on v2.0 :)

MarkJonas commented 3 years ago

@GerdZanker @coeing I just upgraded to OH 3.0.1 and also switched to the test version for bug #74 fd5dc41.

I'll send a complete log to @coeing by email.

GerdZanker commented 3 years ago

I will test the new version today and do the PR review.

GerdZanker commented 3 years ago

Hi @coeing, I tested the new version and the bridge is back "online" after I disconnect and connect the network cable of SHC. So your code fixes #74 for me.

I checked the log context and found some unexpected lines

2021-01-30 17:10:42.971 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@112294f{STARTED}
2021-01-30 17:10:42.976 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.178.31:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/longPoll","params":["ef9ehknk3-55","20"]}
2021-01-30 17:11:12.982 [WARN ] [devices.bridge.BoschSHCBridgeHandler] - Long polling failed, will try to reconnect
org.openhab.binding.boschshc.internal.exceptions.LongPollingFailedException: Unexpected exception during long polling request
    at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling.onLongPollComplete(LongPolling.java:204) [bundleFile:?]
    at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling$1.lambda$0(LongPolling.java:170) [bundleFile:?]
    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:834) [?:?]
Caused by: java.util.concurrent.TimeoutException: Total timeout 30000 ms elapsed
    at org.eclipse.jetty.client.TimeoutCompleteListener.onTimeoutExpired(TimeoutCompleteListener.java:51) ~[?:?]
    at org.eclipse.jetty.io.CyclicTimeout$Wakeup.run(CyclicTimeout.java:282) ~[?:?]
    ... 6 more

! Static version string in SHC code ! ==> 2021-01-30 17:11:28.003 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Initializing Bosch SHC Bridge: org.openhab.binding.boschshc.internal.devices.bridge.BoschSHCBridgeHandler@10c4c72 - HTTP client is: BoschHttpClient@112294f{STARTED} - version: 2020-04-05
2021-01-30 17:11:28.007 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@112294f{STARTED}
2021-01-30 17:11:28.009 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.178.31:8444/smarthome/devices
! Timeout not expected! ==> 2021-01-30 17:11:38.012 [DEBUG] [ernal.devices.bridge.BoschHttpClient] - Access check response failed because of Total timeout 10000 ms elapsed!        
! Pairing due to failed access check ==> 2021-01-30 17:11:38.045 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Starting pairing openHAB Client with Bosch SmartHomeController!               
2021-01-30 17:11:38.047 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Please press the Bosch SHC button until LED starts blinking
2021-01-30 17:11:38.055 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Pairing with SHC 192.168.178.31
2021-01-30 17:11:38.071 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@112294f{STARTED}
2021-01-30 17:11:38.074 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.178.31:8443/smarthome/clients and content ...
! Timeout during pairing not expected ==> 2021-01-30 17:11:48.078 [WARN ] [ernal.devices.bridge.BoschHttpClient] - Pairing failed with exception Total timeout 10000 ms elapsed
2021-01-30 17:12:03.085 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Initializing Bosch SHC Bridge: org.openhab.binding.boschshc.internal.devices.bridge.BoschSHCBridgeHandler@10c4c72 - HTTP client is: BoschHttpClient@112294f{STARTED} - version: 2020-04-05
2021-01-30 17:12:03.087 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@112294f{STARTED}
2021-01-30 17:12:03.089 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.178.31:8444/smarthome/devices
2021-01-30 17:12:03.424 [DEBUG] [ernal.devices.bridge.BoschHttpClient] - Access check response complete: ....

The bridge checks with isAccessPossible() if the SHC is online and if we can access the devices. Two separate checks for isOnline() and isDeviceAccessPossible() are better, because we handle the results differently and e.g. wait if the SHC is not online.

GerdZanker commented 3 years ago

Hello @MarkJonas ,

I can explain some of your observations and logs

At about 14:10 I restarted the SHC by removing power and applying it again. After some time the log as well as the GUI told me that I had to press the SHC's button to bind again and I did so. (I did not expect that I had to rebind. Is that like it should or maybe another issue?)

With the removed power, the old LongPolling failed. The BridgeHandler will receive the error and waits 15 seconds before a new reconnect - due to the improved code. The new reconnect fails most likely because the power is off. The bridge is currently too stupid and tries to pair, visible to you in the UI status. After the power is plugedin in again, the SHC will boot and startup its software - I estimate for this several minutes, which still fits to your duration of about 8 Mins.

During the software startup the server seems to be already active, but can't answer any requests and returns an HTTP error status. Again the BridgeHandler needs to be improved with #75 to detect this, because it continues trying to pair.

After the complete startup the server answers all request as expected and the bridge is able to access device list and doesn't pair anymore and is back online.

coeing commented 3 years ago

The bridge checks with isAccessPossible() if the SHC is online and if we can access the devices. Two separate checks for isOnline() and isDeviceAccessPossible() are better, because we handle the results differently and e.g. wait if the SHC is not online.

@GerdZanker Agree, this is what I had in mind for #75 :) For the current case it would be enough to make isAccessPossible return false if it returns 503, but two methods sound even cleaner.

coeing commented 3 years ago

Should be fixed by #76 We will create a pre-release version 1.1 soon, so everybody can test again if it works as planned :)