After 24h no Temprature update with Climate Control

[jkarsten]

Hello,

i have the Beta 5 release addon running. My BSH Gateway thing says it is online and my five ClimateControl things are online. After i add the BSH Thing all works fine. The setpoint_temprature and temprature Item become a automatics updates. After i change the value in the Bosch App the setpoint item in OH change his value under one second. After 24h i can change a value and wait for temprature updates but nothing happen.

When i pause the BSH Thing and start it again i can change the values in the Bosch app and all works fine for 24 hours. I made this yesterday and today. In my Log is no error. Yesterday i made the resart at 13:00 today at 14:00. I thing tomorrow at 14:00 i will get no updates.

I am from north of Hamburg. I can describe this better in German when you want.

Jörg

[jkarsten]

Hi, today at 14:06 i had the last Update. 2020-12-31 14:06:34.876 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'ArbeitszimmerTemperatur_Temperature' changed from 20.5 °C to 21.9 °C

But all is Online.

I only need to restard the Bosch Smart Home Controller Thing and all works fine again.

Jörg

[MarkJonas]

After approximately 24 hours the readings from TwinGuards freeze. It can be restarted by shortly stopping and then restarting the Smart Home Controller Thing. Just stopping and restarting a single TwinGuard does not help.

(The artifacts of suddenly dropping and rising again temperatures is described in #66.)

I installed the binding on January 1st.

First freeze after ~24 hours. It was resolved by stop/start of the bridge Thing.

Second freeze after again ~24 hours after restart of the bridge Thing. Also resolved by restarting the bridge Thing.

[coeing]

Hi @jkarsten, Hi @MarkJonas,

Thanks for your reports! This sounds like a valid issue indeed. Does one (or both) of you have the possibility to run openHAB in Debug mode, so we get more logs? Our binding logs a lot of things, one of them might help to find the cause more quickly :)

[coeing]

Just thinking for myself here: We get the updates of the devices from the controller by long polling it. There might be some policy that we do not consider that cancels a long polling registration after 24 hours. So we would have to re-register shortly before the 24 hours are over.

[GerdZanker]

I got once a logged exception regarding "long polling". Perhaps the stack trace supports analysis

[WARN ] [devices.bridge.BoschSHCBridgeHandler] - Long polling failed
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:152) [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

[MarkJonas]

@coeing Yes, I could give it a try with debug mode on openHAB. How do I activate that? Can this be a selective activation such that it will not generate gigabytes of data?

[coeing]

@coeing Yes, I could give it a try with debug mode on openHAB. How do I activate that? Can this be a selective activation such that it will not generate gigabytes of data?

@MarkJonas You can enable logging a specific level for a specific package like described here: https://www.openhab.org/docs/administration/logging.html#defining-what-to-log

[MarkJonas]

@coeing I started the logging with log:set DEBUG org.openhab.binding.boschshc. I can already see *Bosch** debug messages in the log file. This evening the problem will most likely occur again. I'll then send the log file to your email address.

[VL2019]

Hi all,

i had the same isse after a few hours with the Twinguard. Here is my log. But i do not understand what the problem could be. Maybe I have the wrong log detail level?

`2021-01-06 18:47:02.865 [DEBUG] [ices.twinguard.BoschTwinguardHandler] - Parsed switch state of hdm:ZigBee:000d6fxxxxxxx: org.openhab.binding.boschshc.internal.devices.twinguard.dto.AirQualityLevelState@3cb79c

2021-01-06 18:52:02.764 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.twinguard.BoschTwinguardHandler@1148eae - calling processUpdate with {"temperatureRating":"GOOD","humidityRating":"GOOD","purity":740,"comfortZone":{"maxTemperature":25,"minTemperature":20,"custom":false,"name":"LIVINGROOM","maxHumidity":60,"minHumidity":40,"maxPurity":1000},"@type":"airQualityLevelState","purityRating":"GOOD","temperature":21.64,"description":"OK","humidity":49.72,"combinedRating":"GOOD"}

2021-01-06 18:52:02.768 [DEBUG] [ices.twinguard.BoschTwinguardHandler] - Twinguard: received update: AirQualityLevel {"temperatureRating":"GOOD","humidityRating":"GOOD","purity":740,"comfortZone":{"maxTemperature":25,"minTemperature":20,"custom":false,"name":"LIVINGROOM","maxHumidity":60,"minHumidity":40,"maxPurity":1000},"@type":"airQualityLevelState","purityRating":"GOOD","temperature":21.64,"description":"OK","humidity":49.72,"combinedRating":"GOOD"}

2021-01-06 18:52:02.771 [DEBUG] [ices.twinguard.BoschTwinguardHandler] - Parsed switch state of hdm:ZigBee:000d6fxxxxxxx: org.openhab.binding.boschshc.internal.devices.twinguard.dto.AirQualityLevelState@6d8ca4`

EDIT: Since 18:53 there is no update for the Temperature of the Twinguard Log soruce: /var/log/openhab$ cat openhab.log |grep Twinguard

[VL2019]

I also recognized that the window contacts are "online" but there is also no update since yesterday 18:53. The issue is not only the Twinguard temperature

I think this could help: /var/log/openhab$ cat openhab.log |grep DEBUG

2021-01-06 18:52:02.748 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Got update for hdm:ZigBee:000d6fxxxxxxx3cd 2021-01-06 18:52:02.751 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: hdm:ZigBee:000d6f00xxxxxx4dc4 - looking for hdm:ZigBee:000d6fxxxxxxx3cd 2021-01-06 18:52:02.753 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A000009BBxxxxx57 - looking for hdm:ZigBee:000d6fxxxxxxx3cd 2021-01-06 18:52:02.756 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A000009BBxxxxxE57 - looking for hdm:ZigBee:000d6fxxxxxxx3cd 2021-01-06 18:52:02.759 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A000049BBxxxxx33 - looking for hdm:ZigBee:000d6fxxxxxxx3cd 2021-01-06 18:52:02.761 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: hdm:ZigBee:000d6fxxxxxxx3cd - looking for hdm:ZigBee:000d6fxxxxxxx3cd 2021-01-06 18:52:02.764 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.twinguard.BoschTwinguardHandler@1148eae - calling processUpdate with {"temperatureRating":"GOOD","humidityRating":"GOOD","purity":740,"comfortZone":{"maxTemperature":25,"minTemperature":20,"custom":false,"name":"LIVINGROOM","maxHumidity":60,"minHumidity":40,"maxPurity":1000},"@type":"airQualityLevelState","purityRating":"GOOD","temperature":21.64,"description":"OK","humidity":49.72,"combinedRating":"GOOD"} 2021-01-06 18:52:02.768 [DEBUG] [ices.twinguard.BoschTwinguardHandler] - Twinguard: received update: AirQualityLevel {"temperatureRating":"GOOD","humidityRating":"GOOD","purity":740,"comfortZone":{"maxTemperature":25,"minTemperature":20,"custom":false,"name":"LIVINGROOM","maxHumidity":60,"minHumidity":40,"maxPurity":1000},"@type":"airQualityLevelState","purityRating":"GOOD","temperature":21.64,"description":"OK","humidity":49.72,"combinedRating":"GOOD"} 2021-01-06 18:52:02.771 [DEBUG] [ices.twinguard.BoschTwinguardHandler] - Parsed switch state of hdm:ZigBee:000d6fxxxxxxx3cd: org.openhab.binding.boschshc.internal.devices.twinguard.dto.AirQualityLevelState@6d8ca4 2021-01-06 18:52:02.780 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-06 18:52:22.811 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"} 2021-01-06 18:52:22.814 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-06 18:52:42.881 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"} 2021-01-06 18:52:42.885 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-06 18:53:02.914 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"} 2021-01-06 18:53:02.919 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-06 18:53:22.952 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"} 2021-01-06 18:53:22.955 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-06 18:53:43.031 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"} 2021-01-06 18:53:43.035 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-06 18:54:03.063 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"} 2021-01-06 18:54:03.067 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-06 18:54:23.096 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"} 2021-01-06 18:54:23.101 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-06 18:54:43.182 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"} 2021-01-06 18:54:43.186 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-06 18:55:03.228 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"} 2021-01-06 18:55:03.231 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-06 18:55:23.260 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"} 2021-01-06 18:55:23.263 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-06 18:55:43.332 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"} 2021-01-06 18:55:43.336 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-06 18:56:03.365 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"} 2021-01-06 18:56:03.368 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request

[coeing]

@VL2019 Thanks for your logs! The long polling does not receive any data, but does not receive any error neither :/ This makes it pretty hard to fix. Let's wait for the logs from @MarkJonas, maybe he has a different log output.

[coeing]

@VL2019 Oh, just saw that you grepped just the DEBUG output. Could you do a grep boschshc, so we get all logs from our binding and not only the DEBUG logs? There might be some WARN or ERROR log in between :)

[VL2019]

@coeing

cat openhab.log |grep boschshc

2021-01-06 17:50:03.248 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Initializing Bosch SHC Bridge: org.openhab.binding.boschshc.internal.devices.bridge.BoschSHCBridgeHandler@f0c0eb - HTTP client is: BoschHttpClient@12bf5dd{STARTED} - version: 2020-04-05 2021-01-06 18:07:03.233 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.twinguard.BoschTwinguardHandler@1148eae - calling processUpdate with {"temperatureRating":"GOOD","humidityRating":"GOOD","purity":720,"comfortZone":{"maxTemperature":25,"minTemperature":20,"custom":false,"name":"LIVINGROOM","maxHumidity":60,"minHumidity":40,"maxPurity":1000},"@type":"airQualityLevelState","purityRating":"GOOD","temperature":21.5,"description":"OK","humidity":49.67,"combinedRating":"GOOD"} 2021-01-06 18:07:03.248 [DEBUG] [ices.twinguard.BoschTwinguardHandler] - Parsed switch state of hdm:ZigBee:000d6fxxxxxxx63cd: org.openhab.binding.boschshc.internal.devices.twinguard.dto.AirQualityLevelState@9a2cec 2021-01-06 18:09:34.506 [DEBUG] [nwallswitch.BoschInWallSwitchHandler] - Handle command for: boschshc:in-wall-switch:BoschSmartHomeController:SteckdoseHausflur - REFRESH 2021-01-06 18:09:34.509 [WARN ] [nwallswitch.BoschInWallSwitchHandler] - Received refresh request for unsupported channel: boschshc:in-wall-switch:BoschSmartHomeController:SteckdoseHausflur:power-switch 2021-01-06 18:10:03.664 [DEBUG] [ices.twinguard.BoschTwinguardHandler] - Handle command for: boschshc:twinguard:BoschSmartHomeController:TwinGuardWZ - REFRESH 2021-01-06 18:10:19.238 [DEBUG] [ices.twinguard.BoschTwinguardHandler] - Handle command for: boschshc:twinguard:BoschSmartHomeController:TwinGuardWZ - REFRESH 2021-01-06 18:12:03.169 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.twinguard.BoschTwinguardHandler@1148eae - calling processUpdate with {"temperatureRating":"GOOD","humidityRating":"GOOD","purity":760,"comfortZone":{"maxTemperature":25,"minTemperature":20,"custom":false,"name":"LIVINGROOM","maxHumidity":60,"minHumidity":40,"maxPurity":1000},"@type":"airQualityLevelState","purityRating":"GOOD","temperature":21.52,"description":"OK","humidity":49.64,"combinedRating":"GOOD"} 2021-01-06 18:12:03.175 [DEBUG] [ices.twinguard.BoschTwinguardHandler] - Parsed switch state of hdm:ZigBee:000d6fxxxxxxx3cd: org.openhab.binding.boschshc.internal.devices.twinguard.dto.AirQualityLevelState@1bd74e4 2021-01-06 18:17:03.109 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.twinguard.BoschTwinguardHandler@1148eae - calling processUpdate with {"temperatureRating":"GOOD","humidityRating":"GOOD","purity":720,"comfortZone":{"maxTemperature":25,"minTemperature":20,"custom":false,"name":"LIVINGROOM","maxHumidity":60,"minHumidity":40,"maxPurity":1000},"@type":"airQualityLevelState","purityRating":"GOOD","temperature":21.54,"description":"OK","humidity":49.61,"combinedRating":"GOOD"} 2021-01-06 18:17:03.116 [DEBUG] [ices.twinguard.BoschTwinguardHandler] - Parsed switch state of hdm:ZigBee:000d6fxxxxxxx3cd: org.openhab.binding.boschshc.internal.devices.twinguard.dto.AirQualityLevelState@1432a14 2021-01-06 18:21:44.275 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.motiondetector.MotionDetectorHandler@13af26 - calling processUpdate with {"latestMotionDetected":"2021-01-06T17:21:44.158Z","@type":"latestMotionState"} 2021-01-06 18:22:03.041 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.twinguard.BoschTwinguardHandler@1148eae - calling processUpdate with {"temperatureRating":"GOOD","humidityRating":"GOOD","purity":730,"comfortZone":{"maxTemperature":25,"minTemperature":20,"custom":false,"name":"LIVINGROOM","maxHumidity":60,"minHumidity":40,"maxPurity":1000},"@type":"airQualityLevelState","purityRating":"GOOD","temperature":21.54,"description":"OK","humidity":49.6,"combinedRating":"GOOD"} 2021-01-06 18:22:03.048 [DEBUG] [ices.twinguard.BoschTwinguardHandler] - Parsed switch state of hdm:ZigBee:000d6fxxxxxxx3cd: org.openhab.binding.boschshc.internal.devices.twinguard.dto.AirQualityLevelState@3dd92d 2021-01-06 18:27:02.992 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.twinguard.BoschTwinguardHandler@1148eae - calling processUpdate with {"temperatureRating":"GOOD","humidityRating":"GOOD","purity":730,"comfortZone":{"maxTemperature":25,"minTemperature":20,"custom":false,"name":"LIVINGROOM","maxHumidity":60,"minHumidity":40,"maxPurity":1000},"@type":"airQualityLevelState","purityRating":"GOOD","temperature":21.55,"description":"OK","humidity":49.59,"combinedRating":"GOOD"} 2021-01-06 18:27:03.000 [DEBUG] [ices.twinguard.BoschTwinguardHandler] - Parsed switch state of hdm:ZigBee:000d6fxxxxxxx3cd: org.openhab.binding.boschshc.internal.devices.twinguard.dto.AirQualityLevelState@fa2a5a 2021-01-06 18:32:02.991 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.twinguard.BoschTwinguardHandler@1148eae - calling processUpdate with {"temperatureRating":"GOOD","humidityRating":"GOOD","purity":720,"comfortZone":{"maxTemperature":25,"minTemperature":20,"custom":false,"name":"LIVINGROOM","maxHumidity":60,"minHumidity":40,"maxPurity":1000},"@type":"airQualityLevelState","purityRating":"GOOD","temperature":21.57,"description":"OK","humidity":49.59,"combinedRating":"GOOD"} 2021-01-06 18:32:02.997 [DEBUG] [ices.twinguard.BoschTwinguardHandler] - Parsed switch state of hdm:ZigBee:000d6fxxxxxxx3cd: org.openhab.binding.boschshc.internal.devices.twinguard.dto.AirQualityLevelState@520db6 2021-01-06 18:32:09.933 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.motiondetector.MotionDetectorHandler@13af26 - calling processUpdate with {"latestMotionDetected":"2021-01-06T17:32:09.816Z","@type":"latestMotionState"} 2021-01-06 18:35:30.549 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.motiondetector.MotionDetectorHandler@13af26 - calling processUpdate with {"latestMotionDetected":"2021-01-06T17:35:30.407Z","@type":"latestMotionState"} 2021-01-06 18:37:02.902 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.twinguard.BoschTwinguardHandler@1148eae - calling processUpdate with {"temperatureRating":"GOOD","humidityRating":"GOOD","purity":700,"comfortZone":{"maxTemperature":25,"minTemperature":20,"custom":false,"name":"LIVINGROOM","maxHumidity":60,"minHumidity":40,"maxPurity":1000},"@type":"airQualityLevelState","purityRating":"GOOD","temperature":21.59,"description":"OK","humidity":49.56,"combinedRating":"GOOD"} 2021-01-06 18:37:02.909 [DEBUG] [ices.twinguard.BoschTwinguardHandler] - Parsed switch state of hdm:ZigBee:000d6fxxxxxxx3cd: org.openhab.binding.boschshc.internal.devices.twinguard.dto.AirQualityLevelState@13f10e0 2021-01-06 18:42:02.847 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.twinguard.BoschTwinguardHandler@1148eae - calling processUpdate with {"temperatureRating":"GOOD","humidityRating":"GOOD","purity":750,"comfortZone":{"maxTemperature":25,"minTemperature":20,"custom":false,"name":"LIVINGROOM","maxHumidity":60,"minHumidity":40,"maxPurity":1000},"@type":"airQualityLevelState","purityRating":"GOOD","temperature":21.6,"description":"OK","humidity":49.61,"combinedRating":"GOOD"} 2021-01-06 18:42:02.853 [DEBUG] [ices.twinguard.BoschTwinguardHandler] - Parsed switch state of hdm:ZigBee:000d6fxxxxxxx3cd: org.openhab.binding.boschshc.internal.devices.twinguard.dto.AirQualityLevelState@f20198 2021-01-06 18:47:02.859 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.twinguard.BoschTwinguardHandler@1148eae - calling processUpdate with {"temperatureRating":"GOOD","humidityRating":"GOOD","purity":760,"comfortZone":{"maxTemperature":25,"minTemperature":20,"custom":false,"name":"LIVINGROOM","maxHumidity":60,"minHumidity":40,"maxPurity":1000},"@type":"airQualityLevelState","purityRating":"GOOD","temperature":21.62,"description":"OK","humidity":49.66,"combinedRating":"GOOD"} 2021-01-06 18:47:02.865 [DEBUG] [ices.twinguard.BoschTwinguardHandler] - Parsed switch state of hdm:ZigBee:000d6fxxxxxxx3cd: org.openhab.binding.boschshc.internal.devices.twinguard.dto.AirQualityLevelState@3cb79c 2021-01-06 18:52:02.764 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.twinguard.BoschTwinguardHandler@1148eae - calling processUpdate with {"temperatureRating":"GOOD","humidityRating":"GOOD","purity":740,"comfortZone":{"maxTemperature":25,"minTemperature":20,"custom":false,"name":"LIVINGROOM","maxHumidity":60,"minHumidity":40,"maxPurity":1000},"@type":"airQualityLevelState","purityRating":"GOOD","temperature":21.64,"description":"OK","humidity":49.72,"combinedRating":"GOOD"} 2021-01-06 18:52:02.771 [DEBUG] [ices.twinguard.BoschTwinguardHandler] - Parsed switch state of hdm:ZigBee:000d6fxxxxxxx3cd: org.openhab.binding.boschshc.internal.devices.twinguard.dto.AirQualityLevelState@6d8ca4 2021-01-06 18:56:10.148 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.motiondetector.MotionDetectorHandler@13af26 - calling processUpdate with {"latestMotionDetected":"2021-01-06T17:47:27.138Z","@type":"latestMotionState"} 2021-01-06 18:56:10.175 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.motiondetector.MotionDetectorHandler@13af26 - calling processUpdate with {"@type":"walkTestState","walkState":"WALK_TEST_STOPPED","petImmunityState":"PET_IMMUNITY_ENABLED"} 2021-01-06 19:37:06.597 [DEBUG] [nwallswitch.BoschInWallSwitchHandler] - Handle command for: boschshc:in-wall-switch:BoschSmartHomeController:SteckdoseHausflur - ON 2021-01-06 19:37:15.854 [DEBUG] [nwallswitch.BoschInWallSwitchHandler] - Handle command for: boschshc:in-wall-switch:BoschSmartHomeController:SteckdoseHausflur - OFF

[jkarsten]

Hi, i set debug on with "log:set DEBUG org.openhab.binding.boschshc" and restart the Binding at 16:25 At the moment it shows with "cat /var/log/openhab/openhab.log |grep boschshc > /root/Schreibtisch/output.txt" this file output.txt

I will grep a log tomorrow at 16:25 again. Do you need the /var/log/openhab/events.log too?

Thank you, Jörg

[coeing]

@VL2019 @jkarsten Thanks for your logs! But grepping boschshc does not seem to be the correct filter as it is not included in all logs :/ Would it be possible for you to upload all your logs around the point of time when the updating stops?

[MarkJonas]

@coeing Since ~ 30 minutes the readings of my TwinGuards are frozen. I sent the openhab.log to you personally by email.

[jkarsten]

Hi, i will upload the Logs but i see this debug error after 24h ==> /var/log/openhab/openhab.log <== 2021-01-08 16:25:17.953 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-08 16:25:18.011 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"jsonrpc":"2.0","error":{"code":-32001,"message":"No subscription with id: eebi62mc3-207"}}

[coeing]

Hi, i will upload the Logs but i see this debug error after 24h ==> /var/log/openhab/openhab.log <== 2021-01-08 16:25:17.953 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-08 16:25:18.011 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"jsonrpc":"2.0","error":{"code":-32001,"message":"No subscription with id: eebi62mc3-207"}}

This is a great finding! :) It confirms what I thought, that the subscription is removed by the controller after 24h automatically. Could you send me the whole openhab.log (at least the minutes around 16:25 where the error occurred) via mail?

[coeing]

@coeing Since ~ 30 minutes the readings of my TwinGuards are frozen. I sent the openhab.log to you personally by email.

I found the same error response within your logs:

2021-01-07 19:40:39.947 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-07 19:40:40.007 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"jsonrpc":"2.0","error":{"code":-32001,"message":"No subscription with id: eeb57n4ke-26"}}

It should be possible to re-subscribe for long polling once this error is received, so the long polling is restarted.

[GerdZanker]

Hello @coeing,

In the meantime my BoschSHC setup is up and running also only for 24h. I see the "Long poll response" from line 175 with the JSON error content.

But I see no other log entry for the Bosch SHC code afterwards. E.g. the Warning from line 183 is not logged.

What is happening between the two statements?

[coeing]

Hello @coeing,

In the meantime my BoschSHC setup is up and running also only for 24h. I see the "Long poll response" from line 175 with the JSON error content.

But I see no other log entry for the Bosch SHC code afterwards. E.g. the Warning from line 183 is not logged.

What is happening between the two statements?

Hi @GerdZanker !

I just had a look into the issue and think I found the reason. GSON happily returns a LongPollResult, even if the "result" field does not exist. So I check this manually. Please checkout my pull request #69, so I can merge it soon and build a new version :)

[coeing]

I am happy to present our Beta 6 release: https://github.com/stefan-kaestle/openhab2-addons/releases/tag/v1.0-beta.6 :) It should fix this nasty bug. Please send a comment as soon as you checked it out to confirm that our binding runs more than 24 hours (or not, in which case I have to continue my investigations! ;) ).

[MarkJonas]

@coeing Now running for 24 hours and 30 minutes. I think you nailed it! :1st_place_medal:

I plan to check again after 48 hours of continuous operation.

[MarkJonas]

Oh no, it froze again. This must have happened just minutes after my post above. :crying_cat_face:

The "unfreeze" and restart of the binding was on 2021-01-11 at ~ 19:30. It "froze" again at 2021-01-12 20:00.

Is it because the buggy and the new version of the binding are installed at the same time? How do I remove the old version? Removing it from the openhab/addons directory did not help.

232 │ Active │  80 │ 3.0.0.202012261941      │ org.openhab.binding.boschshc
233 │ Active │  80 │ 3.1.0.202101110957      │ org.openhab.binding.boschshc

This is how my openhab.log ends:

2021-01-12 19:57:53.652 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Got update for hdm:ZigBee:000d6XXXXXXXXX09
2021-01-12 19:57:53.654 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: hdm:ZigBee:000d6f000cb95099 - looking for hdm:ZigBee:000d6XXXXXXXXX09
2021-01-12 19:57:53.657 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: hdm:ZigBee:000d6XXXXXXXXX09 - looking for hdm:ZigBee:000d6XXXXXXXXX09
2021-01-12 19:57:53.659 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.twinguard.BoschTwinguardHandler@ce4aa3 - calling processUpdate with {"temperatureRating":"GOOD","humidityRating":"GOOD","purity":890,"comfortZone":{"maxTemperature":25,"minTemperature":20,"custom":false,"name":"HALLWAY","maxHumidity":60,"minHumidity":40,"maxPurity":1000},"@type":"airQualityLevelState","purityRating":"GOOD","temperature":22.69,"description":"OK","humidity":44.31,"combinedRating":"GOOD"}
2021-01-12 19:57:53.662 [DEBUG] [ices.twinguard.BoschTwinguardHandler] - Twinguard: received update: AirQualityLevel {"temperatureRating":"GOOD","humidityRating":"GOOD","purity":890,"comfortZone":{"maxTemperature":25,"minTemperature":20,"custom":false,"name":"HALLWAY","maxHumidity":60,"minHumidity":40,"maxPurity":1000},"@type":"airQualityLevelState","purityRating":"GOOD","temperature":22.69,"description":"OK","humidity":44.31,"combinedRating":"GOOD"}
2021-01-12 19:57:53.665 [DEBUG] [ices.twinguard.BoschTwinguardHandler] - Parsed switch state of hdm:ZigBee:000d6XXXXXXXXX09: org.openhab.binding.boschshc.internal.devices.twinguard.dto.AirQualityLevelState@1393a2c
2021-01-12 19:57:53.682 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: hdm:ZigBee:000d6XXXXXXXXX3c - looking for hdm:ZigBee:000d6XXXXXXXXX09
2021-01-12 19:57:53.686 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: hdm:ZigBee:000d6XXXXXXXXXfd - looking for hdm:ZigBee:000d6XXXXXXXXX09
2021-01-12 19:57:53.689 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: hdm:ZigBee:000d6XXXXXXXXX2c - looking for hdm:ZigBee:000d6XXXXXXXXX09
2021-01-12 19:57:53.692 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-12 19:58:13.714 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-12 19:58:13.717 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-12 19:58:33.778 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-12 19:58:33.780 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-12 19:58:53.848 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-12 19:58:53.853 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-12 19:59:03.008 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-12 19:59:03.011 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-12 19:59:03.078 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"jsonrpc":"2.0","error":{"code":-32001,"message":"No subscription with id: eeb57n4ke-33"}}

2021-01-12 20:12:22.141 [WARN ] [nternal.phonebook.Tr064PhonebookImpl] - Failed to get phonebook with URL https://192.168.74.1:49443/phonebook.lua?sid=06c0cda484fee8c6&pbid=0:
java.util.concurrent.TimeoutException: Total timeout 2000 ms elapsed
    at org.eclipse.jetty.client.TimeoutCompleteListener.onTimeoutExpired(TimeoutCompleteListener.java:51) ~[?:?]
    at org.eclipse.jetty.io.CyclicTimeout$Wakeup.run(CyclicTimeout.java:282) ~[?:?]
    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) [?:?]
2021-01-13 07:14:13.728 [ERROR] [d4j.internal.RRD4jPersistenceService] - Could not create rrd4j database file '/openhab/userdata/persistence/rrd4j/SBBathroom_CurrentPlayingTime.rrd': null

[jkarsten]

Hi, yes its the same here. I will save the Logs and send a eMail.

The last Messages in openhab.log are: `2021-01-12 15:54:47.280 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Got update for roomClimateControl_hz_1 2021-01-12 15:54:47.280 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_4 - looking for roomClimateControl_hz_1 2021-01-12 15:54:47.280 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_1 - looking for roomClimateControl_hz_1 2021-01-12 15:54:47.281 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.climatecontrol.ClimateControlHandler@174b93fc - calling processUpdate with {"@type":"temperatureLevelState","temperature":18.5} 2021-01-12 15:54:47.282 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_3 - looking for roomClimateControl_hz_1 2021-01-12 15:54:47.283 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_5 - looking for roomClimateControl_hz_1 2021-01-12 15:54:47.285 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_2 - looking for roomClimateControl_hz_1 2021-01-12 15:54:47.286 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-12 15:55:07.347 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-12 15:55:07.351 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-12 15:55:27.407 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-12 15:55:27.408 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-12 15:55:47.463 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-12 15:55:47.464 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-12 15:56:07.519 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-12 15:56:07.520 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-12 15:56:27.575 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-12 15:56:27.577 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-12 15:56:27.639 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"jsonrpc":"2.0","error":{"code":-32001,"message":"No subscription with id: eebi62mc3-236"}} `

Jörg

[coeing]

Oh no! :O

The logs look like the old version though, so the version might not be updated correctly. @MarkJonas @jkarsten Do you have access to the openHAB console and can run the command bundle:list? Not sure how to show the active bundles with their versions in the UI (@GerdZanker Do you know it?).

When I started my openHAB instance, it still had the 3.0.0 version of the binding active and did not reload the 3.1.0 version. It might be necessary to restart the bundle (bundle:restart org.openhab.binding.boschshc) or even uninstall and install it again.

Anyway, we should try to find out which version is running in your openHAB installations to really see if the new version does not solve the issue (I am still confident that it does :) ).

Here are information about the Console and the Bundle Management inside it: https://www.openhab.org/docs/administration/bundles.html https://www.openhab.org/docs/administration/console.html

[jkarsten]

Hi,

ok in the past i delete my Bosch Addon in /usr/share/openhab/addons/ i copied the new org.openhab.binding.boschshc-3.1.0-SNAPSHOT.jar in this folder.

After restart bundle:list shows both versions ????? 253 │ Resolved │ 80 │ 3.0.0.202012261941 │ openHAB Add-ons :: Bundles :: BoschSHC Binding 255 │ Resolved │ 80 │ 3.1.0.202101110957 │ openHAB Add-ons :: Bundles :: BoschSHC Binding

i delete the addon again and then i made in the console openhab> bundle:uninstall 255 openhab> bundle:uninstall 253

i copied the binding again and restart openhab.

Now it shows only 256 │ Resolved │ 80 │ 3.1.0.202101110957 │ openHAB Add-ons :: Bundles :: BoschSHC Binding

[coeing]

Hi,

ok in the past i delete my Bosch Addon in /usr/share/openhab/addons/ i copied the new org.openhab.binding.boschshc-3.1.0-SNAPSHOT.jar in this folder.

After restart bundle:list shows both versions ????? 253 │ Resolved │ 80 │ 3.0.0.202012261941 │ openHAB Add-ons :: Bundles :: BoschSHC Binding 255 │ Resolved │ 80 │ 3.1.0.202101110957 │ openHAB Add-ons :: Bundles :: BoschSHC Binding

i delete the addon again and then i made in the console openhab> bundle:uninstall 255 openhab> bundle:uninstall 253

i copied the binding again and restart openhab.

Now it shows only 256 │ Resolved │ 80 │ 3.1.0.202101110957 │ openHAB Add-ons :: Bundles :: BoschSHC Binding

Hi @jkarsten,

This is the same behaviour that showed up for me (having both versions after the first restart of openHAB). I guess openHAB reads the new .jar from the addons folder and keeps the old .jar from its internal cache (somewhere inside userdata). Uninstalling it removes it from the cache as well.

Now you should only have the newest version. Please keep an eye on the behaviour after the 24 hours, hopefully the long polling continues to work :)

[MarkJonas]

@coeing I fear this issue needs to be reopened. I uninstalled the old binding and restarted OH. I think this time it ran for ~36 hours and now it is frozen again. I think @tuxianerDE reported the same in https://github.com/stefan-kaestle/openhab2-addons/issues/66#issuecomment-760046514 .

In the bundle list there is only one instance of the boschshc binding.

233 │ Active │  80 │ 3.1.0.202101110957      │ org.openhab.binding.boschshc

This is now my openhab.log ends. Give me a shout when you want more from the log.

2021-01-14 19:34:23.328 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-14 19:34:23.330 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-14 19:34:43.401 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-14 19:34:43.408 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-14 19:35:03.478 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-14 19:35:03.482 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-14 19:35:23.548 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-14 19:35:23.550 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-14 19:35:43.616 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-14 19:35:43.621 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-14 19:36:03.688 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-14 19:36:03.694 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-14 19:36:23.758 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-14 19:36:23.760 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-14 19:36:33.209 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[{"path":"/devices/hdm:ZigBee:000d6XXXXXXXXX3c/services/AirQualityLevel","@type":"DeviceServiceData","id":"AirQualityLevel","state":{"temperatureRating":"GOOD","humidityRating":"GOOD","purity":810,"comfortZone":{"maxTemperature":25,"minTemperature":20,"custom":false,"name":"KIDS","maxHumidity":60,"minHumidity":40,"maxPurity":1000},"@type":"airQualityLevelState","purityRating":"GOOD","temperature":22.34,"description":"OK","humidity":45.37,"combinedRating":"GOOD"},"deviceId":"hdm:ZigBee:000d6XXXXXXXXX3c"}],"jsonrpc":"2.0"}

2021-01-14 19:36:33.212 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Got update for hdm:ZigBee:000d6XXXXXXXXX3c
2021-01-14 19:36:33.214 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: hdm:ZigBee:000d6XXXXXXXXX99 - looking for hdm:ZigBee:000d6XXXXXXXXX3c
2021-01-14 19:36:33.217 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: hdm:ZigBee:000d6XXXXXXXXX09 - looking for hdm:ZigBee:000d6XXXXXXXXX3c
2021-01-14 19:36:33.219 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: hdm:ZigBee:000d6XXXXXXXXX3c - looking for hdm:ZigBee:000d6XXXXXXXXX3c
2021-01-14 19:36:33.221 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.twinguard.BoschTwinguardHandler@1cd2d6f - calling processUpdate with {"temperatureRating":"GOOD","humidityRating":"GOOD","purity":810,"comfortZone":{"maxTemperature":25,"minTemperature":20,"custom":false,"name":"KIDS","maxHumidity":60,"minHumidity":40,"maxPurity":1000},"@type":"airQualityLevelState","purityRating":"GOOD","temperature":22.34,"description":"OK","humidity":45.37,"combinedRating":"GOOD"}
2021-01-14 19:36:33.223 [DEBUG] [ices.twinguard.BoschTwinguardHandler] - Twinguard: received update: AirQualityLevel {"temperatureRating":"GOOD","humidityRating":"GOOD","purity":810,"comfortZone":{"maxTemperature":25,"minTemperature":20,"custom":false,"name":"KIDS","maxHumidity":60,"minHumidity":40,"maxPurity":1000},"@type":"airQualityLevelState","purityRating":"GOOD","temperature":22.34,"description":"OK","humidity":45.37,"combinedRating":"GOOD"}
2021-01-14 19:36:33.226 [DEBUG] [ices.twinguard.BoschTwinguardHandler] - Parsed switch state of hdm:ZigBee:000d6XXXXXXXXX3c: org.openhab.binding.boschshc.internal.devices.twinguard.dto.AirQualityLevelState@1731de2
2021-01-14 19:36:33.243 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: hdm:ZigBee:000d6XXXXXXXXXfd - looking for hdm:ZigBee:000d6XXXXXXXXX3c
2021-01-14 19:36:33.246 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: hdm:ZigBee:000d6XXXXXXXXX2c - looking for hdm:ZigBee:000d6XXXXXXXXX3c
2021-01-14 19:36:33.249 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-14 19:36:33.378 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-14 19:36:33.380 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-14 19:36:33.448 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"jsonrpc":"2.0","error":{"code":-32001,"message":"No subscription with id: eeb57n4ke-37"}}

2021-01-14 19:36:33.450 [WARN ] [.internal.devices.bridge.LongPolling] - Long poll response contained no results: {"jsonrpc":"2.0","error":{"code":-32001,"message":"No subscription with id: eeb57n4ke-37"}}

2021-01-14 19:36:33.460 [WARN ] [.internal.devices.bridge.LongPolling] - Got long poll error: No subscription with id: eeb57n4ke-37 (code: -32001)
2021-01-14 19:36:33.462 [WARN ] [.internal.devices.bridge.LongPolling] - Subscription eeb57n4ke-37 became invalid, subscribing again
2021-01-14 19:36:33.465 [DEBUG] [.internal.devices.bridge.LongPolling] - Subscribe: Sending request: {"jsonrpc":"2.0","method":"RE/subscribe","params":["com/bosch/sh/remote/*",null]} - using httpClient BoschHttpClient@5fb4e6{STARTED}
2021-01-15 00:00:59.538 [INFO ] [ng.tr064.internal.soap.SOAPConnector] - Failed to get Tr064ChannelConfig{channelType=wanAccessType, getAction=GetCommonLinkProperties, dataType='string, parameter='null'}: java.util.concurrent.TimeoutException: Total timeout 2000 ms elapsed
2021-01-15 06:26:09.976 [ERROR] [d4j.internal.RRD4jPersistenceService] - Could not create rrd4j database file '/openhab/userdata/persistence/rrd4j/SBDining_CurrentPlayingTime.rrd': null

[jkarsten]

Hi, i have the same problem. I think it is still after 24 hours.

Here are my Log: ` 2021-01-14 11:11:10.308 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Got update for hdm:HomeMaticIP:3014F711A000005BB85E1B04 2021-01-14 11:11:10.309 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_2 - looking for hdm:HomeMaticIP:3014F711A000005BB85E1B04 2021-01-14 11:11:10.310 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_1 - looking for hdm:HomeMaticIP:3014F711A000005BB85E1B04 2021-01-14 11:11:10.311 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_4 - looking for hdm:HomeMaticIP:3014F711A000005BB85E1B04 2021-01-14 11:11:10.311 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_5 - looking for hdm:HomeMaticIP:3014F711A000005BB85E1B04 2021-01-14 11:11:10.312 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_3 - looking for hdm:HomeMaticIP:3014F711A000005BB85E1B04 2021-01-14 11:11:10.313 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-14 11:11:10.379 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[{"path":"/devices/roomClimateControl_hz_4/services/TemperatureLevel","@type":"DeviceServiceData","id":"TemperatureLevel","state":{"@type":"temperatureLevelState","temperature":14.3},"deviceId":"roomClimateControl_hz_4"}],"jsonrpc":"2.0"}

2021-01-14 11:11:10.380 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Got update for roomClimateControl_hz_4 2021-01-14 11:11:10.381 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_2 - looking for roomClimateControl_hz_4 2021-01-14 11:11:10.382 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_1 - looking for roomClimateControl_hz_4 2021-01-14 11:11:10.383 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_4 - looking for roomClimateControl_hz_4 2021-01-14 11:11:10.383 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.climatecontrol.ClimateControlHandler@75d087e0 - calling processUpdate with {"@type":"temperatureLevelState","temperature":14.3} 2021-01-14 11:11:10.385 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_5 - looking for roomClimateControl_hz_4 2021-01-14 11:11:10.387 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_3 - looking for roomClimateControl_hz_4 2021-01-14 11:11:10.387 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-14 11:11:30.451 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-14 11:11:30.452 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-14 11:11:36.151 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[{"path":"/devices/hdm:HomeMaticIP:3014F711A000005BB85E1B0B/services/TemperatureLevel","@type":"DeviceServiceData","id":"TemperatureLevel","state":{"@type":"temperatureLevelState","temperature":17.5},"deviceId":"hdm:HomeMaticIP:3014F711A000005BB85E1B0B"}],"jsonrpc":"2.0"}

2021-01-14 11:11:36.175 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Got update for hdm:HomeMaticIP:3014F711A000005BB85E1B0B 2021-01-14 11:11:36.175 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_2 - looking for hdm:HomeMaticIP:3014F711A000005BB85E1B0B 2021-01-14 11:11:36.176 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_1 - looking for hdm:HomeMaticIP:3014F711A000005BB85E1B0B 2021-01-14 11:11:36.176 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_4 - looking for hdm:HomeMaticIP:3014F711A000005BB85E1B0B 2021-01-14 11:11:36.176 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_5 - looking for hdm:HomeMaticIP:3014F711A000005BB85E1B0B 2021-01-14 11:11:36.176 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_3 - looking for hdm:HomeMaticIP:3014F711A000005BB85E1B0B 2021-01-14 11:11:36.176 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-14 11:11:36.247 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[{"path":"/devices/roomClimateControl_hz_3/services/TemperatureLevel","@type":"DeviceServiceData","id":"TemperatureLevel","state":{"@type":"temperatureLevelState","temperature":17.5},"deviceId":"roomClimateControl_hz_3"}],"jsonrpc":"2.0"}

2021-01-14 11:11:36.248 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Got update for roomClimateControl_hz_3 2021-01-14 11:11:36.249 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_2 - looking for roomClimateControl_hz_3 2021-01-14 11:11:36.249 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_1 - looking for roomClimateControl_hz_3 2021-01-14 11:11:36.250 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_4 - looking for roomClimateControl_hz_3 2021-01-14 11:11:36.250 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_5 - looking for roomClimateControl_hz_3 2021-01-14 11:11:36.251 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: roomClimateControl_hz_3 - looking for roomClimateControl_hz_3 2021-01-14 11:11:36.251 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.climatecontrol.ClimateControlHandler@714b463d - calling processUpdate with {"@type":"temperatureLevelState","temperature":17.5} 2021-01-14 11:11:36.253 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-14 11:11:56.311 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-14 11:11:56.325 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-14 11:12:06.631 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-14 11:12:06.646 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-01-14 11:12:06.703 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"jsonrpc":"2.0","error":{"code":-32001,"message":"No subscription with id: eebi62mc3-251"}}

2021-01-14 11:12:06.707 [WARN ] [.internal.devices.bridge.LongPolling] - Long poll response contained no results: {"jsonrpc":"2.0","error":{"code":-32001,"message":"No subscription with id: eebi62mc3-251"}}

2021-01-14 11:12:06.717 [WARN ] [.internal.devices.bridge.LongPolling] - Got long poll error: No subscription with id: eebi62mc3-251 (code: -32001) 2021-01-14 11:12:06.717 [WARN ] [.internal.devices.bridge.LongPolling] - Subscription eebi62mc3-251 became invalid, subscribing again 2021-01-14 11:12:06.718 [DEBUG] [.internal.devices.bridge.LongPolling] - Subscribe: Sending request: {"jsonrpc":"2.0","method":"RE/subscribe","params":["com/bosch/sh/remote/*",null]} - using httpClient BoschHttpClient@4756fa7b{STARTED} 2021-01-14 11:12:16.728 [WARN ] [devices.bridge.BoschSHCBridgeHandler] - Long polling failed org.openhab.binding.boschshc.internal.exceptions.LongPollingFailedException: Error on subscribe request at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling.subscribe(LongPolling.java:120) ~[bundleFile:?] at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling.onLongPollResponse(LongPolling.java:195) [bundleFile:?] at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling$1.onComplete(LongPolling.java:162) [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.responseSuccess(HttpReceiver.java:390) [bundleFile:9.4.20.v20190813] at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.messageComplete(HttpReceiverOverHTTP.java:316) [bundleFile:9.4.20.v20190813] at org.eclipse.jetty.http.HttpParser.parseFields(HttpParser.java:1139) [bundleFile:9.4.20.v20190813] at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1498) [bundleFile:9.4.20.v20190813] at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.parse(HttpReceiverOverHTTP.java:172) [bundleFile:9.4.20.v20190813] at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:135) [bundleFile:9.4.20.v20190813] at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:73) [bundleFile:9.4.20.v20190813] at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:133) [bundleFile:9.4.20.v20190813] at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:154) [bundleFile:9.4.20.v20190813] at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.20.v20190813] at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) [bundleFile:9.4.20.v20190813] at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:426) [bundleFile:9.4.20.v20190813] at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:320) [bundleFile:9.4.20.v20190813] at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:158) [bundleFile:9.4.20.v20190813] at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) [bundleFile:9.4.20.v20190813] at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) [bundleFile:9.4.20.v20190813] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) [bundleFile:9.4.20.v20190813] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) [bundleFile:9.4.20.v20190813] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) [bundleFile:9.4.20.v20190813] at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) [bundleFile:9.4.20.v20190813] at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:367) [bundleFile:9.4.20.v20190813] at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782) [bundleFile:9.4.20.v20190813] at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918) [bundleFile:9.4.20.v20190813] at java.lang.Thread.run(Thread.java:834) [?:?] Caused by: java.util.concurrent.TimeoutException: Total timeout 10000 ms elapsed at org.eclipse.jetty.client.TimeoutCompleteListener.onTimeoutExpired(TimeoutCompleteListener.java:51) ~[?:?] at org.eclipse.jetty.io.CyclicTimeout$Wakeup.run(CyclicTimeout.java:282) ~[?:?] 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) ~[?:?] ... 1 more 2021-01-14 20:10:55.248 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: undefined 2021-01-14 20:12:02.705 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: undefined 2021-01-14 20:31:19.120 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: undefined 2021-01-14 20:31:20.258 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: undefined 2021-01-14 20:31:22.985 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: undefined 2021-01-14 20:34:59.852 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: undefined 2021-01-14 20:41:31.997 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: undefined 2021-01-15 11:50:01.071 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: undefined 2021-01-15 17:37:16.069 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: undefined `

[coeing]

@MarkJonas @jkarsten Thanks a lot for your reports and your logs. In the logs I can see that my last fix worked (regarding the long poll error), but the re-subscription afterwards failed due to a time out. I will re-open this bug nonetheless as the result is the same.

I have to check what might go wrong there.

[GerdZanker]

Today it happend with my hardware that the SHC bridge wasn't able to renew the Subscribtioin Here my log

2021-01-17 17:17:02.337 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-17 17:17:02.400 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[...last valid content...],"jsonrpc":"2.0"}
2021-01-17 17:17:02.403 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-17 17:17:21.408 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}
2021-01-17 17:17:21.410 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-17 17:17:21.435 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"jsonrpc":"2.0","error":{"code":-32001,"message":"No subscription with id: eemhd16nh-86"}}
2021-01-17 17:17:21.438 [WARN ] [.internal.devices.bridge.LongPolling] - Long poll response contained no results: {"jsonrpc":"2.0","error":{"code":-32001,"message":"No subscription with id: eemhd16nh-86"}}
2021-01-17 17:17:21.450 [WARN ] [.internal.devices.bridge.LongPolling] - Got long poll error: No subscription with id: eemhd16nh-86 (code: -32001)
2021-01-17 17:17:21.453 [WARN ] [.internal.devices.bridge.LongPolling] - Subscription eemhd16nh-86 became invalid, subscribing again
2021-01-17 17:17:21.456 [DEBUG] [.internal.devices.bridge.LongPolling] - Subscribe: Sending request: {"jsonrpc":"2.0","method":"RE/subscribe","params":["com/bosch/sh/remote/*",null]} - using httpClient BoschHttpClient@fc6e9b{STARTED}

Afterwards I got no log messages anymore for about one hour before I stopped and started the bridge.

[coeing]

Today it happend with my hardware that the SHC bridge wasn't able to renew the Subscribtioin Here my log

2021-01-17 17:17:02.337 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-17 17:17:02.400 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[...last valid content...],"jsonrpc":"2.0"}
2021-01-17 17:17:02.403 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-17 17:17:21.408 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}
2021-01-17 17:17:21.410 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-17 17:17:21.435 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"jsonrpc":"2.0","error":{"code":-32001,"message":"No subscription with id: eemhd16nh-86"}}
2021-01-17 17:17:21.438 [WARN ] [.internal.devices.bridge.LongPolling] - Long poll response contained no results: {"jsonrpc":"2.0","error":{"code":-32001,"message":"No subscription with id: eemhd16nh-86"}}
2021-01-17 17:17:21.450 [WARN ] [.internal.devices.bridge.LongPolling] - Got long poll error: No subscription with id: eemhd16nh-86 (code: -32001)
2021-01-17 17:17:21.453 [WARN ] [.internal.devices.bridge.LongPolling] - Subscription eemhd16nh-86 became invalid, subscribing again
2021-01-17 17:17:21.456 [DEBUG] [.internal.devices.bridge.LongPolling] - Subscribe: Sending request: {"jsonrpc":"2.0","method":"RE/subscribe","params":["com/bosch/sh/remote/*",null]} - using httpClient BoschHttpClient@fc6e9b{STARTED}

Afterwards I got no log messages anymore for about one hour before I stopped and started the bridge.

@GerdZanker Could you enable the TRACE logging for your installation? I think I need even more detailed logs than the ones from the DEBUG logging, especially if nothing is logged for you after the re-subscribe request. I would at least expect an error there. Or maybe that warning was filtered out? It has the identifier devices.bridge.BoschSHCBridgeHandler instead of .internal.devices.bridge.LongPolling.

[GerdZanker]

Today after about 24h later I got a "long polling failed" error in openhab UI, but no debug output in the console. Now TRACE logging is active - let's wait.

[coeing]

Today after about 24h later I got a "long polling failed" error in openhab UI, but no debug output in the console. Now TRACE logging is active - let's wait.

That's really strange that it did not occur in your logs. But at least it seems to occur at all. I guess it is the same TimeOut exception that @jkarsten had, but hopefully the TRACE logging will give me some idea why the TimeOut happens at all.

Btw: I got the confirmation from the Bosch developers that a subscription is canceled after 24 hours: https://github.com/BoschSmartHome/bosch-shc-api-docs/issues/44#issuecomment-762270046

[MarkJonas]

@coeing Inspired by @GerdZanker I also enabled TRACE logging on my system. This is what is looks like when the long polling eventually fails:

2021-01-19 19:12:02.120 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-19 19:12:02.122 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.74.76:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/longPoll","params":["ef5ldngam-2","20"]}
2021-01-19 19:12:22.188 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-19 19:12:22.191 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-19 19:12:22.194 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.74.76:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/longPoll","params":["ef5ldngam-2","20"]}
2021-01-19 19:12:37.907 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-01-19 19:12:37.911 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-01-19 19:12:37.913 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.74.76:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/longPoll","params":["ef5ldngam-2","20"]}
2021-01-19 19:12:38.007 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"jsonrpc":"2.0","error":{"code":-32001,"message":"No subscription with id: ef5ldngam-2"}}

2021-01-19 19:12:38.010 [WARN ] [.internal.devices.bridge.LongPolling] - Long poll response contained no results: {"jsonrpc":"2.0","error":{"code":-32001,"message":"No subscription with id: ef5ldngam-2"}}

2021-01-19 19:12:38.020 [WARN ] [.internal.devices.bridge.LongPolling] - Got long poll error: No subscription with id: ef5ldngam-2 (code: -32001)
2021-01-19 19:12:38.022 [WARN ] [.internal.devices.bridge.LongPolling] - Subscription ef5ldngam-2 became invalid, subscribing again
2021-01-19 19:12:38.025 [DEBUG] [.internal.devices.bridge.LongPolling] - Subscribe: Sending request: {"jsonrpc":"2.0","method":"RE/subscribe","params":["com/bosch/sh/remote/*",null]} - using httpClient BoschHttpClient@425f2b{STARTED}
2021-01-19 19:12:38.028 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.74.76:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/subscribe","params":["com/bosch/sh/remote/*",null]}

I hope this helps. To me it does not look as verbose as I thought it would be.

The Smart Home Controller thing still shows the state 'online' in the GUI. But I think that yesterday it showed some error message that the long poll failed.

[GerdZanker]

Here is my trace from yesterday

2021-01-19 20:56:57.467 [WARN ] [.internal.devices.bridge.LongPolling] - Long poll response contained no results: {"jsonrpc":"2.0","error":{"code":-32001,"message":"No subscription with id: ef5lmcknf-1"}}
2021-01-19 20:56:57.474 [WARN ] [.internal.devices.bridge.LongPolling] - Got long poll error: No subscription with id: ef5lmcknf-1 (code: -32001)
2021-01-19 20:56:57.475 [WARN ] [.internal.devices.bridge.LongPolling] - Subscription ef5lmcknf-1 became invalid, subscribing again
2021-01-19 20:57:07.480 [WARN ] [devices.bridge.BoschSHCBridgeHandler] - Long polling failed
org.openhab.binding.boschshc.internal.exceptions.LongPollingFailedException: Error on subscribe request
    at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling.subscribe(LongPolling.java:120) ~[bundleFile:?]
    at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling.onLongPollResponse(LongPolling.java:195) [bundleFile:?]
    at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling$1.onComplete(LongPolling.java:162) [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.responseSuccess(HttpReceiver.java:390) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.messageComplete(HttpReceiverOverHTTP.java:316) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.http.HttpParser.parseFields(HttpParser.java:1139) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1498) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.parse(HttpReceiverOverHTTP.java:172) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:135) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:73) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:133) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:154) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:426) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:320) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:158) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:367) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782) [bundleFile:9.4.20.v20190813]
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918) [bundleFile:9.4.20.v20190813]
    at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: java.util.concurrent.TimeoutException: Total timeout 10000 ms elapsed
    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) ~[?:?]
    ... 1 more

resulting in a "COMMUNICATION_ERROR"

[MarkJonas]

@coeing The Long polling failed log message appeared on my system after pressing the pause (stop) button on the bridge thing. Afterwards a similar exception was printed. Maybe there is a timeout I should have waited for. If needed I can send you the complete log by email.

[coeing]

@MarkJonas @GerdZanker Thanks for your logs! Unfortunately there was no new information in it, but at least they look similar.

@MarkJonas Would be great if you send me the complete log via mail. I'd like to make sure that the exception is the same as the others. And you have TRACE logs, so maybe there is an additional log in your log file that could help finding the bug.

@GerdZanker I see only warnings in your log, are you sure you enabled the TRACE logging?

[coeing]

Just created a test version with some additional logging: https://github.com/stefan-kaestle/openhab2-addons/releases/tag/v1.0-bugfix.62

Please make sure you have TRACE logging enabled: log:set TRACE org.openhab.binding.boschshc

You can check the log level by running log:list

If that does not provide any additional information, I would suggest to set the log level of org.eclipse.jetty.client to TRACE. That will result in a lot of logging, but it should hopefully tell us more about the cause of the time out. log:set TRACE org.eclipse.jetty.client

[jkarsten]

Hi, i deleted the old jar file and made a uninstall in the console. After restart i have only one active Binding. 257 │ Resolved │ 80 │ 3.1.0.202101200849 │ openHAB Add-ons :: Bundles :: BoschSHC Binding

Log:List is now org.openhab.binding.boschshc │ TRACE

In the Log it said that i need to pair it. So i pressed the Button on the Bosch again and now its online.

Thank you, Jörg

[GerdZanker]

I see only warnings in your log, are you sure you enabled the TRACE logging?

Sorry, I skipp all the "good" log entries.

The test bundle is installed, restarted and I do the TRACE logging...

[MarkJonas]

I sent the logs of the last 36 hours to @coeing.

I am now also running the bugfix.62 test version with TRACE logging enabled.

237 │ Active │  80 │ 3.1.0.202101200849      │ openHAB Add-ons :: Bundles :: BoschSHC Binding

[coeing]

I sent the logs of the last 36 hours to @coeing.

I am now also running the bugfix.62 test version with TRACE logging enabled.

237 │ Active │  80 │ 3.1.0.202101200849      │ openHAB Add-ons :: Bundles :: BoschSHC Binding

Thanks for the complete log. Unfortunately it does not contain further information about what happens. As you already noticed, the last log is about sending the subscribe request and no response is received. It looks like the http client got stuck during the subscribe request, but I have no idea why.

I think it would be best to enable TRACE logging for the HTTP library as well: log:set TRACE org.eclipse.jetty.client

[coeing]

@GerdZanker If the logs of the HTTP library do not give us any new information, I would like to try to create a new HTTP client once the long polling subscription became invalid. Maybe the Bosch home controller does something with the HTTP connection like closing it. What do you think about this idea?

[coeing]

@MarkJonas Could you run a bundle:update org.openhab.binding.boschshc to make sure you are really using the test version? From the logs it looks like you are still on Beta 6.

[GerdZanker]

I had time to analyse my stack trace

2021-01-19 20:57:07.480 [WARN ] [devices.bridge.BoschSHCBridgeHandler] - Long polling failed
org.openhab.binding.boschshc.internal.exceptions.LongPollingFailedException: Error on subscribe request ....

This warning is logged by BoschSHCBridgeHandler.handleLongPollFailure() because the longPoll() failed with a Timeout and will set the bridge offline. The result is visible in my screenshot.

@coeing, your latest code to handle the invalid subscription case longPollError.error.code == LongPollError.SUBSCRIPTION_INVALID starts a new subscription and keeps our "execution loop" up and running. "execution loop" means for me that we call the the scheduler.execute to do the long polling, wait for the onComplete callback and process the result. But because of the Timeout exception this loop is stopped, isn't it?

A possibility is to improve the failure handing in BoschSHCBridgeHandler and schedule the initialAccess() again in case of exception.

The failure handler sets the bridge offline and restarts the loop!

private void handleLongPollFailure(Throwable e) {
    logger.warn("Long polling failed", e);
    updateStatus(ThingStatus.OFFLINE, ThingStatusDetail.OFFLINE.COMMUNICATION_ERROR, "Long polling failed");
    scheduleInitialAccess(this.httpClient);
}

scheduleInitialAccess() will wait 15 seconds and start the initial access, updates the bridge status and executes the long polling again. That's more or less the same what I do after an error - stopping and starting the SHC bridge via the UI.

I will evaluate my idea later, after today's exception in about two hours ...

[MarkJonas]

@coeing Yes, the logs I sent this morning where still with the Beta 6. Afterwards I updated the binding. I hope 3.1.0.202101200849 is the right version number. None the less I did the bundle:update org.openhab.binding.boschshc. Maybe this means I will have to wait 24h from now on.

[coeing]

@coeing, your latest code to handle the invalid subscription case longPollError.error.code == LongPollError.SUBSCRIPTION_INVALID starts a new subscription and keeps our "execution loop" up and running. "execution loop" means for me that we call the the scheduler.execute to do the long polling, wait for the onComplete callback and process the result. But because of the Timeout exception this loop is stopped, isn't it?

That's possible, thanks for the hint! Nevertheless I can not explain why there is a timeout anyway. But I should definitively handle that exception case better. Restarting the long polling makes sense. This could be at least a fallback to keep the long polling running. I would like to find the cause of the timeout anyway...

[coeing]

I created a new version, please download again and switch to that one: https://github.com/stefan-kaestle/openhab2-addons/releases/tag/v1.0-bugfix.62

It tries to restart the long polling now when a failure happens. Not sure if it does fix the issue already (from some logs it looks like the request hangs forever because there is no log after the subscribe request is sent). But maybe it gives us at least new information what might go wrong.

Sorry @all for the guessing and trying here! It is really annoying to not know what exactly goes wrong. Thanks for your patience and help! :)