Long Polling not receiving any updates after 24 hours

[coeing]

Hi there,

Two of our users have an issue with our openHAB binding for Bosch devices: https://github.com/stefan-kaestle/openhab2-addons/issues/62

I was wondering if there is some requirement for the long polling that we are missing, e.g. a new subscription is necessary after 24 hours?

[hxmelab]

Hi Christian,

I am not sure if there is such a policy. But in any case you could start a new polling in case of an error. You should also consider this in case of a reboot or other connection loss events.

This topic should be documented in the best practice section.

Happy Coding Phil

[coeing]

Hi @hxmelab,

Alright, thanks for the quick answer. We'll have to check with our users if there is an error from the long polling in their log. There should be at least a timeout exception if the long polling does not return a response within 30 seconds (the docs say the response should be send within 20 seconds, but we added a bit to not error too soon).

Cheers Christian

[tschamm]

Hi @coeing, @hxmelab, I'm also not aware of such a policy, neither from documentation nor from experiences while developing the python binding. I did not yet encounter such an issue after 24h which would make a new subscription necessary. Regards, Thomas

[coeing]

Hi @tschamm,

Thanks for sharing your experiences :) Maybe it is an openHAB specific thing, we will have to find out.

[coeing]

Hi there!

Small update from my side: Several users get a long poll error after 24 hours which indicates that the subscription id is not found anymore. The first bug was in our binding as we did not parse the long poll error correctly.

Now we try to re-subscribe when we get that error. Unfortunately the re-subscribe request fails with a time out (after 10 seconds) :/

Here are our logs, any idea why this happens would be great! :)

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

[hxmelab]

You just have to subscribe again to get a new poll id, before you start polling again.

The log points out that the current poll id is not valid anymore.

Hope that helps!

[coeing]

@hxmelab Thanks for the quick response. But we already do a new subscribe request (see "Subscribe: Sending request..." in the logs). That's exactly the one which fails with a timeout exception.

[tschamm]

Subscribing and unsubscribing multiple times in a sequence is not a problem:

DEBUG:urllib3.connectionpool:https://192.168.1.6:8444 "POST /remote/json-rpc HTTP/1.1" 200 None
DEBUG:boschshcpy:Subscribed for long poll. Poll id: eee0llcdm-220
DEBUG:urllib3.connectionpool:https://192.168.1.6:8444 "POST /remote/json-rpc HTTP/1.1" 200 None
DEBUG:boschshcpy:Unsubscribed from long poll w/ poll id eee0llcdm-220
DEBUG:urllib3.connectionpool:https://192.168.1.6:8444 "POST /remote/json-rpc HTTP/1.1" 200 None
DEBUG:boschshcpy:Subscribed for long poll. Poll id: eee0llcdm-221
DEBUG:urllib3.connectionpool:https://192.168.1.6:8444 "POST /remote/json-rpc HTTP/1.1" 200 None
DEBUG:boschshcpy:Unsubscribed from long poll w/ poll id eee0llcdm-221
DEBUG:urllib3.connectionpool:https://192.168.1.6:8444 "POST /remote/json-rpc HTTP/1.1" 200 None
DEBUG:boschshcpy:Subscribed for long poll. Poll id: eee0llcdm-222
DEBUG:boschshcpy:Unsubscribing from long poll
DEBUG:urllib3.connectionpool:https://192.168.1.6:8444 "POST /remote/json-rpc HTTP/1.1" 200 None
DEBUG:urllib3.connectionpool:https://192.168.1.6:8444 "POST /remote/json-rpc HTTP/1.1" 200 None
DEBUG:boschshcpy:Unsubscribed from long poll w/ poll id eee0llcdm-222

Even subscribing without unsubscribing does not lead to a timeout:

DEBUG:urllib3.connectionpool:https://192.168.1.6:8444 "POST /remote/json-rpc HTTP/1.1" 200 None
DEBUG:boschshcpy:Subscribed for long poll. Poll id: eee0llcdm-223
DEBUG:urllib3.connectionpool:https://192.168.1.6:8444 "POST /remote/json-rpc HTTP/1.1" 200 None
DEBUG:boschshcpy:Subscribed for long poll. Poll id: eee0llcdm-224
DEBUG:urllib3.connectionpool:https://192.168.1.6:8444 "POST /remote/json-rpc HTTP/1.1" 200 None
DEBUG:boschshcpy:Subscribed for long poll. Poll id: eee0llcdm-225
DEBUG:boschshcpy:Unsubscribing from long poll
DEBUG:urllib3.connectionpool:https://192.168.1.6:8444 "POST /remote/json-rpc HTTP/1.1" 200 None
DEBUG:urllib3.connectionpool:https://192.168.1.6:8444 "POST /remote/json-rpc HTTP/1.1" 200 None
DEBUG:boschshcpy:Unsubscribed from long poll w/ poll id eee0llcdm-225

Can you check if your session is still valid when this error happens? Maybe some trigger leads to closing the connection after 24h and you have to create a new session first?

[coeing]

@tschamm Thanks for your response. The idea about the session sounds good, maybe our http client has some kind of setting for shutting down after 24 hours. I will check this :)

[sebastianharder]

Hi! Just for clarification: there is a max-age of 24 hours for any long-poll subscription. Clients must re-subscribe afterwards and get a new subscription ID.

And there is another change in the 9.22 release which is currently rolled out: Subscriptions time out after 5 minutes if no read was performed.

In both situations, clients just need to handle the error "invalid/non-existing subscription id" correctly by re-subscribing and using the new subscription ID afterwards.

[hxmelab]

@sebhard: Thank you, good to know.

[coeing]

@sebhard Thanks for the documentation update! :) This helps a lot as the long poll error we receive after 24 hours is to be expected. Now I can focus on checking why the re-subscribe request does not succeed.

[sebastianharder]

Documentation of the long polling mechanism updated.