search

stefan-kaestle / openhab2-addons

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

[Bosch Smart Home Binding] Status of Bosch-Items not updated when Bosch-Devices triggert #109

Closed csprang closed 2 years ago

csprang commented 2 years ago

Dear all,

even I have some of the BOSCH and other Smart Home Equipment for a longer time, I'm quite new with Openhab. I like the Bosch Binding for openhab on my Raspi for implementation of more complex automation.

As @endsideX I also have the problem, that the items of the Bosch Bindings are frozen after a while (#98), so the status of the items is not changed anymore if the Bosch devices (inwall-switch, door-contacts, motion detectors etc.) are triggert outside the openhab-environment.

I use OH 3.1 and updated it twice without a success - while I'm looking for a solution, I found this blog and therefore left this comment. Unfortunately I'm still a beginner with openhab therefore I do not have much experiences with the internals ... but will improve ;-)

regards Christoph

Expected Behavior

When Bosch-Devices are triggered, like switching on lights manually per in-wall-Switch or open windows with windowcontacts the respectively status of the Bosch Binding items in openhab 3.1 should be updated

Current Behavior

the status of the Bosch binding items are unchanged, even the status of the Bosch devices was changed manually for example by using the physical in-wall-switch or even with the bosch-app

Your Environment

Raspi 2 openhab 3.1

coeing commented 2 years ago

@csprang Thanks for your report! :)

Could you try the release candidate of our binding? https://github.com/stefan-kaestle/openhab2-addons/releases/tag/v1.2-rc1 There seemed to be an issue with version 1.1 of our binding and openHAB 3.1. It should be fixed with version 1.2.

csprang commented 2 years ago

@coeing, thanks for your quick answer and help!!

I installed your release candidate V1.2 on my openHAB 3.1 ...

my actual test experience is that the WindowContact-Devices are working now, even the Twinguard, but the shown status of in-wall-switch (and plug) is still not reliable, if you chance the device-status outside the openHAB-environment (i.e. by pushing manually the switch).

I deleted the "old items" and created new ones which I bind to the new Bosch Binding (V1.2). At a first glance, it looks that the new items (especially for in-wall-switches) are working but getting out of sync.

That are my first observations but I will have a deeper look why/when the Items stopps working .

best regards Christoph

coeing commented 2 years ago

Hi @csprang,

Thanks for your update. Glad that it at least kind of works for you :) Could you describe concretely what you mean with "getting out of sync". E.g. which device, which channel, what value does it show and which value would you expect? That might help with reproducing the error.

csprang commented 2 years ago

Hi @coeing,

A Short cut from my testszenario...

Environment: I'm using BOSCH-Bridge (newest sW-Version), OpenHAB 3.1 on RASPI 3 with your BOSCH-Binding V1.2.

Test-Setup: I created a Thing from the BOSCH-Binding with the label "BSHSwitch01" as the type "in-wall-switch" and instantiated the Channel called "BSHSwitch01_Betrieb" with a Item called "Lights" (turning on/off the light). The Thing ist online ...

Test-Szenario: 1.) Toggle the Item "lights" to "ON" on openHUB Panel or PaperUI => the physical light in the Room is turn on and you find in the Dieburg the information

2021-08-17 21:25:01.626 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'BSHSwitch01_Betrieb' received command ON 2021-08-17 21:25:01.632 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'BSHSwitch01_Betrieb' predicted to become ON 2021-08-17 21:25:01.637 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'BSHSwitch01_Betrieb' changed from OFF to ON

2.) Toggle the "Light" Item to off, the physical light gets dark and

2021-08-17 21:41:54.556 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'BSHSwitch01_Betrieb' received command OFF 2021-08-17 21:41:54.583 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'BSHSwitch01_Betrieb' predicted to become OFF 2021-08-17 21:41:54.592 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'BSHSwitch01_Betrieb' changed from ON to OFF

Can be found in the debuglist of openhab.

3.) using the physical switch at the Wall => the physical lights turned on/off but NO EVEN.ITEM Statement can be found in the debuglist

4.) using the Orginal BOSCH-APP on my iPhone => Same Result as 3.)

Szenario 1 & 2 are working as expected ... in szenario 3 & 4 the updated Status of the Channel "BSHSwitch01_Betrieb" is missing - the Channel-Status ist still "OFF" Even the Lights are already on (that what I mean with out of Sync).

It Looks that the Communication between BOSCH-Binding and BOSCH-Controller is just unidirectional (CHANNEL to BRIDGE) but no bidirectional.

Same Observation I also did for other BOSCH-Binding-Things, like "Shutter-Control". Moving the Shutter with the Shutter-Item on PaperUI, I found in the Debug-entries

2021-08-17 21:53:13.416 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'BSHShutter01_Level' received command DOWN 2021-08-17 21:53:13.429 [INFO ] [penhab.event.ItemStatePredictedEvent] - Item 'BSHShutter01_Level' predicted to become DOWN 2021-08-17 21:53:13.439 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'BSHShutter01_Level' changed from 0 to 100 2021-08-17 21:53:14.467 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'BSHShutter01_Level' received command STOP

And the shutter is closing. But using the physical Button at the wall, the shutter is also closing but on Entry in the OpenHAB debug.

Hope this Description helps more to find the issue

Regards Christoph

coeing commented 2 years ago

Hi @csprang

Thanks for the details about your setup! It's good that it also occurs for the shutter controls, as I have some in my home as well. So I can try to reproduce your issue. I hope that I find time for it soon.

Cheers Christian

coeing commented 2 years ago

@csprang I had time today to test my rollershutters and they still work fine with version 1.2.

Could you make sure to enable the logs for our binding? On the console this should be possible with:

log:set TRACE org.openhab.binding.boschshc

That should give you many, many information about what is happening in our binding in the openHAB log. Please do your test again then and post your logs. That should give us a good idea what goes wrong in your setup :)

csprang commented 2 years ago

Hi @coeing,

I set the trace and used the shutter-control and in-wall-switch with the OpenHAB-PaperUI and directly after with the physical button at the wall. While you can find entries in the trace below for the PaperUI-Driving actions (Shutter Down/Up, Switch On/Off), there are no entries created for the Commands triggered by the physical Buttons ... it still looks, that the Bosch-binding is Communicating with the Bosch-Controller, But Not vice versa ...

Below the traces for the trial Regards Christoph

Travel using OpenHAB-UI to control the shutter ... no entries for pushing the physical button

13:25:38.252 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'BSHShutter01_Level' received command DOWN 13:25:38.299 [INFO ] [openhab.event.ItemStatePredictedEvent] - Item 'BSHShutter01_Level' predicted to become DOWN 13:25:38.314 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'BSHShutter01_Level' changed from 0 to 100 13:25:38.312 [TRACE] [ternal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@1bbee48{STARTED} 13:25:38.324 [TRACE] [ternal.devices.bridge.BoschHttpClient] - create request for https://192.168.178.55:8444/smarthome/devices/hdm:HomeMaticIP:3014F711A00018DA1858ADE9/services/ShutterControl/state and content {"level":0.0,"operationState":"STOPPED","stateType":"shutterControlState","@type":"shutterControlState"} 13:25:40.975 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'BSHShutter01_Level' received command STOP 13:25:40.991 [TRACE] [ternal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@1bbee48{STARTED} 13:25:41.000 [TRACE] [ternal.devices.bridge.BoschHttpClient] - create request for https://192.168.178.55:8444/smarthome/devices/hdm:HomeMaticIP:3014F711A00018DA1858ADE9/services/ShutterControl/state and content {"operationState":"STOPPED","stateType":"shutterControlState","@type":"shutterControlState"} 13:25:42.170 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'HUEMotionSensor01_Beleuchtungsstarke' changed from 764.7156884388348 lx to 413.3329236662004 lx 13:25:42.176 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'HUEMotionSensor01_LetzteAktualisierung' changed from 2021-08-22T13:25:22.000+0200 to 2021-08-22T13:25:40.000+0200 13:25:42.895 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'BSHShutter01_Level' received command UP 13:25:42.903 [INFO ] [openhab.event.ItemStatePredictedEvent] - Item 'BSHShutter01_Level' predicted to become UP 13:25:42.911 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'BSHShutter01_Level' changed from 100 to 0 13:25:42.914 [TRACE] [ternal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@1bbee48{STARTED} 13:25:42.919 [TRACE] [ternal.devices.bridge.BoschHttpClient] - create request for https://192.168.178.55:8444/smarthome/devices/hdm:HomeMaticIP:3014F711A00018DA1858ADE9/services/ShutterControl/state and content {"level":1.0,"operationState":"STOPPED","stateType":"shutterControlState","@type":"shutterControlState"} 13:25:46.889 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'HUEMotionSensor03_Bewegung' changed from OFF to ON

Trace using OpenHAB-UI to switch on/off in-wall-switch ... no entries for pushing the physcial button

13:29:34.093 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'HUEMotionSensor03_LetzteAktualisierung' changed from 2021-08-22T13:28:59.000+0200 to 2021-08-22T13:29:33.000+0200 13:29:56.447 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'HUEMotionSensor03_Bewegung' changed from ON to OFF 13:29:56.521 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'HUEMotionSensor03_LetzteAktualisierung' changed from 2021-08-22T13:29:33.000+0200 to 2021-08-22T13:29:55.000+0200 13:29:56.770 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'BSHSwitch01_Betrieb' received command ON 13:29:56.791 [INFO ] [openhab.event.ItemStatePredictedEvent] - Item 'BSHSwitch01_Betrieb' predicted to become ON 13:29:56.810 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'BSHSwitch01_Betrieb' changed from OFF to ON 13:29:56.811 [TRACE] [ternal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@1bbee48{STARTED} 13:29:56.824 [TRACE] [ternal.devices.bridge.BoschHttpClient] - create request for https://192.168.178.55:8444/smarthome/devices/hdm:HomeMaticIP:3014F711A0001918785A0939/services/PowerSwitch/state and content {"switchState":"ON","stateType":"powerSwitchState","@type":"powerSwitchState"} 13:29:59.253 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'BSHSwitch01_Betrieb' received command OFF 13:29:59.266 [INFO ] [openhab.event.ItemStatePredictedEvent] - Item 'BSHSwitch01_Betrieb' predicted to become OFF 13:29:59.274 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'BSHSwitch01_Betrieb' changed from ON to OFF 13:29:59.277 [TRACE] [ternal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@1bbee48{STARTED} 13:29:59.288 [TRACE] [ternal.devices.bridge.BoschHttpClient] - create request for https://192.168.178.55:8444/smarthome/devices/hdm:HomeMaticIP:3014F711A0001918785A0939/services/PowerSwitch/state and content {"switchState":"OFF","stateType":"powerSwitchState","@type":"powerSwitchState"}

coeing commented 2 years ago

@csprang That's very strange, you should have long polls for the Bosch devices all over the log (every 20 seconds), something like this: 

2021-08-20 19:45:28.453 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request
2021-08-20 19:45:28.454 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@1a8bb7a3{STARTED}
2021-08-20 19:45:28.455 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.178.55:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/longPoll","params":["eikg0gklg-69","20"]}
2021-08-20 19:45:48.530 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

But the long polling (which is the way the things get state updates from the Bosch devices works) does not seem to be active. Could you check if you find any logs from LongPolling in your logs? There might be an error during the subscription for the long polling.

csprang commented 2 years ago

Hi @coeing, I just Look via GREP Thru the Logs to find some LongPolling request but just found 3 entries in OpenHAB.log

openhabian@openhabian:~ $ grep -i long /var/log/openhab/*log /var/log/openhab/openhab.log: at org.openhab.binding.boschshc.internal.devices.bridge.BridgeHandler.handleLongPollResult(BridgeHandler.java:320) ~[?:?] /var/log/openhab/openhab.log: at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling.onLongPollComplete(LongPolling.java:216) ~[?:?] /var/log/openhab/openhab.log: at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling$1.lambda$0(LongPolling.java:172) ~[?:?]

it seems that there are no other longpollings are active ... Regards Christoph

coeing commented 2 years ago

@csprang Alright, thanks. Could you post the whole logs from those locations? Right now you only posted the locations from where the logs where posted. The log messages are probably in the next lines after the ones you posted.

By the way: You can rename or delete the log files before you start openHAB to get smaller log files to search in :)

csprang commented 2 years ago

OHLogs.zip

@coeing, I tried to attached a ZIP-file with the logs from Openhab - hope you have access to the logs. Unfortunately I'm still not so familiar with the whole system therefore I just copied the existing logs, but will try to delete them and create a smaler logfile

coeing commented 2 years ago

@csprang That helped, thank you! :)

Here is the part where the error occurs:

2021-08-13 11:31:43.652 [ERROR] [internal.JSONResponseExceptionMapper] - Unexpected exception occurred while processing REST request.
java.lang.IllegalArgumentException: UID must have at least 2 segments.
    at org.openhab.core.common.AbstractUID.<init>(AbstractUID.java:71) ~[?:?]
    at org.openhab.core.common.AbstractUID.<init>(AbstractUID.java:49) ~[?:?]
    at org.openhab.core.thing.UID.<init>(UID.java:48) ~[?:?]
    at org.openhab.core.thing.ThingTypeUID.<init>(ThingTypeUID.java:35) ~[?:?]
    at org.openhab.core.io.rest.core.internal.thing.ThingTypeResource.getByUID(ThingTypeResource.java:159) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
    at org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:179) ~[bundleFile:3.4.3]
    at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96) ~[bundleFile:3.4.3]
    at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:201) ~[bundleFile:3.4.3]
    at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:104) ~[bundleFile:3.4.3]
    at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:59) ~[bundleFile:3.4.3]
    at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:96) ~[bundleFile:3.4.3]
    at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308) ~[bundleFile:3.4.3]
    at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121) ~[bundleFile:3.4.3]
    at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:265) ~[bundleFile:3.4.3]
    at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:234) ~[bundleFile:3.4.3]
    at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:208) ~[bundleFile:3.4.3]
    at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:160) ~[bundleFile:3.4.3]
    at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:225) ~[bundleFile:3.4.3]
    at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:298) ~[bundleFile:3.4.3]
    at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doGet(AbstractHTTPServlet.java:222) ~[bundleFile:3.4.3]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:687) ~[bundleFile:3.1.0]
    at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:273) ~[bundleFile:3.4.3]
    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:791) ~[bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:550) ~[bundleFile:9.4.40.v20210413]
    at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) ~[bundleFile:?]
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) ~[bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:602) ~[bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624) ~[bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1435) ~[bundleFile:9.4.40.v20210413]
    at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:294) ~[bundleFile:?]
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:501) ~[bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594) ~[bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1350) ~[bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[bundleFile:9.4.40.v20210413]
    at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:82) ~[bundleFile:?]
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:388) ~[bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:633) [bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:380) [bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) [bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) [bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) [bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) [bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) [bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:383) [bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:882) [bundleFile:9.4.40.v20210413]
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1036) [bundleFile:9.4.40.v20210413]
    at java.lang.Thread.run(Thread.java:829) [?:?]
2021-08-13 12:46:03.996 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.NullPointerException: null
    at org.openhab.binding.boschshc.internal.devices.bridge.BridgeHandler.handleLongPollResult(BridgeHandler.java:320) ~[?:?]
    at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling.onLongPollComplete(LongPolling.java:216) ~[?:?]
    at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling$1.lambda$0(LongPolling.java:172) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
    at java.lang.Thread.run(Thread.java:829) [?:?]

It happens right at the start of the long polling, so it does not surprise that you get no state updates. I will have to investigate what the error means, I have not seen such an error before.

coeing commented 2 years ago

@csprang Unfortunately you do not seem to have the TRACE logging for our binding enabled (log:set TRACE org.openhab.binding.boschshc), so I do not see detailed information about what happens. What I will do is to make sure that no NullPointerException occurs at the reported location. But apart from that I can't do much without further information.

xxthunder commented 2 years ago

Hi there, first of all thanks for the binding and keeping the development for it alive. A great contribution to openHAB.

@coeing I would really like to help here. I got the same problem as @csprang , my roller shutters can be controlled from openHAB, but no states are updated when controlled from the in-wall switch itself or the Bosch app. The states of my other devices like window contacts and the wall thermostat are not updated, too. After a reboot it works for approx. 24h and then it suddenly stops. Any further ideas?

xxthunder commented 2 years ago

@coeing Ok, I just rebooted my OpenHAB, tracing is enabled, I get log entries like this every 20 seconds like you said. Here the log entry while I applied the in-wall switch of my office shutters:

2021-10-03 17:32:16.124 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request

2021-10-03 17:32:16.126 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@736fa5{STARTED}

2021-10-03 17:32:16.128 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.178.96:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/longPoll","params":["ejlfh4gbd-537","20"]}

==> /var/log/openhab/events.log <==

2021-10-03 17:32:16.078 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'dOfficeKarstenShutters' changed from 0 to 100

==> /var/log/openhab/openhab.log <==

2021-10-03 17:32:17.852 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[{"path":"/devices/hdm:HomeMaticIP:3014F711A00018DA1858B66F/services/ShutterControl","operations":["decrementOpenLevel","incrementOpenLevel"],"@type":"DeviceServiceData","id":"ShutterControl","state":{"delayCompensationTime":0.7,"referenceMovingTimes":{"movingTimeBottomToTopInMillis":16300,"movingTimeTopToBottomInMillis":15700},"endPositionAutoDetect":true,"delayCompensationSupported":true,"level":0.9,"@type":"shutterControlState","operationState":"STOPPED","endPositionSupported":true,"slatsRunningTimeInMillis":0,"automaticDelayCompensation":false,"calibrated":true},"deviceId":"hdm:HomeMaticIP:3014F711A00018DA1858B66F"}],"jsonrpc":"2.0"}

2021-10-03 17:32:17.855 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Got update for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.857 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A00018DA1858B66F - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.861 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.shuttercontrol.ShutterControlHandler@7ead25 - calling processUpdate (id: ShutterControl) with {"delayCompensationTime":0.7,"referenceMovingTimes":{"movingTimeBottomToTopInMillis":16300,"movingTimeTopToBottomInMillis":15700},"endPositionAutoDetect":true,"delayCompensationSupported":true,"level":0.9,"@type":"shutterControlState","operationState":"STOPPED","endPositionSupported":true,"slatsRunningTimeInMillis":0,"automaticDelayCompensation":false,"calibrated":true}

2021-10-03 17:32:17.864 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A00018D87859B117 - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.867 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A00018DA1858B29B - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.869 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A00018DA1858B33E - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.872 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A00018DA1858B335 - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.874 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A00018DA1859150B - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.876 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A00018DA18591105 - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.879 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A00018DA185914EA - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.881 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A00018DA185B41CF - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.884 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A000009A18592ABF - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.886 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A000009A185903D6 - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.888 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A000009A18590185 - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.890 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A00000987858913A - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.892 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A000009BB8595EE4 - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.894 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A000009A18592AFD - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.896 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A00000987858905B - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.898 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A00000987858916F - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.900 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A000009A185A0DFE - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.902 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A0000096D858976B - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.904 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A000009A185A0DFC - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.906 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A000009A18592AF9 - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.908 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A000009A18592AAE - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.910 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A0000098785891F0 - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.911 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A0000098785891C6 - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.913 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A00000987858916E - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.915 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A000289A185B1D8D - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.917 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request

2021-10-03 17:32:17.919 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@736fa5{STARTED}

2021-10-03 17:32:17.922 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.178.96:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/longPoll","params":["ejlfh4gbd-537","20"]}

==> /var/log/openhab/events.log <==

2021-10-03 17:32:17.870 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'dOfficeKarstenShutters' changed from 100 to 10

==> /var/log/openhab/openhab.log <==

2021-10-03 17:32:37.975 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-10-03 17:32:37.978 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request

2021-10-03 17:32:37.980 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@736fa5{STARTED}

2021-10-03 17:32:37.983 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.178.96:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/longPoll","params":["ejlfh4gbd-537","20"]}

xxthunder commented 2 years ago

Sorry, I am not able to properly format my log file content here ... 🤔

@coeing Now we wait until something bad happens?

coeing commented 2 years ago

Hi @xxthunder,

Thanks a lot for your help! :) Your logs look promising. It looks like the info about the moving of your shutters arrived:

2021-10-03 17:32:17.852 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[{"path":"/devices/hdm:HomeMaticIP:3014F711A00018DA1858B66F/services/ShutterControl","operations":["decrementOpenLevel","incrementOpenLevel"],"@type":"DeviceServiceData","id":"ShutterControl","state":{"delayCompensationTime":0.7,"referenceMovingTimes":{"movingTimeBottomToTopInMillis":16300,"movingTimeTopToBottomInMillis":15700},"endPositionAutoDetect":true,"delayCompensationSupported":true,"level":0.9,"@type":"shutterControlState","operationState":"STOPPED","endPositionSupported":true,"slatsRunningTimeInMillis":0,"automaticDelayCompensation":false,"calibrated":true},"deviceId":"hdm:HomeMaticIP:3014F711A00018DA1858B66F"}],"jsonrpc":"2.0"}

2021-10-03 17:32:17.855 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Got update for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.857 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A00018DA1858B66F - looking for hdm:HomeMaticIP:3014F711A00018DA1858B66F

2021-10-03 17:32:17.861 [DEBUG] [nternal.devices.bridge.BridgeHandler] - Found child: org.openhab.binding.boschshc.internal.devices.shuttercontrol.ShutterControlHandler@7ead25 - calling processUpdate (id: ShutterControl) with {"delayCompensationTime":0.7,"referenceMovingTimes":{"movingTimeBottomToTopInMillis":16300,"movingTimeTopToBottomInMillis":15700},"endPositionAutoDetect":true,"delayCompensationSupported":true,"level":0.9,"@type":"shutterControlState","operationState":"STOPPED","endPositionSupported":true,"slatsRunningTimeInMillis":0,"automaticDelayCompensation":false,"calibrated":true}

It's stranged that it did nothing to the state of the handler. I will look into it.

coeing commented 2 years ago

@csprang @xxthunder It would be great if you could try again with this version: https://github.com/stefan-kaestle/openhab2-addons/releases/tag/v1.2-bugfix.109.1 I added some logs to get more information about where the state update gets stuck.

xxthunder commented 2 years ago

@coeing Wow, thanks for the quick update ... here my latest log, I opened and close a window and applied the shutter via in-wall switch again: openhab.log

csprang commented 2 years ago

@coing, Sorry for Not responding long time… I don‘t have access to my OpenHAB Environment at the Moment, but try ist as soon I have the access reestablished, best regards

xxthunder commented 2 years ago

@coeing Of course, when you measure and trace nothing happens, till now everything looks fine. OpenHAB receives a lot of data from my SHC and is polling every 20 seconds. Stay tuned. 😄

coeing commented 2 years ago

@csprang No problem for the delay, I know we all do it in our free time. And sometimes there's just to little of it :)

@xxthunder Thanks a lot for testing, this really helps!

I changed a tiny piece which might be the root of the bug. Please try out the new version and let me know if the bug still occurs: https://github.com/stefan-kaestle/openhab2-addons/releases/tag/v1.2-bugfix.109.2

xxthunder commented 2 years ago

@coeing you are welcome, I would love to do more, but as you said, so much to code, so little time. Will try your patch release this weekend.

xxthunder commented 2 years ago

@coeing Sorry, vacation and family time ... so far everything worked fine, even without your latest bugfix snapshot. Updated 5 seconds ago, stay tuned. 😄

coeing commented 2 years ago

@xxthunder No problem, thanks for testing! I will close the issue for now, please let us know if the bug still occurs :)

limebond commented 2 years ago

Hey there - im not sure if that issue is identical with this resolved one - so please let me know if i should open a new one.. I also got the issue that "over night" anything happends so every bosch item stops reporting their values.. my grafana show that mostly during the night at 00:30 bosh just stops working (but only inside of OH - in the app everything works as it should..)

Afterwards you'll see the logs: ` 2021-11-05 00:29:01.745 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@1c91c75{STARTED} 2021-11-05 00:29:01.747 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.178.34:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/longPoll","params":["ekfmeiced-7","20"]} 2021-11-05 00:29:01.771 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[{"iconId":"icon_room_living_room","extProperties":{"humidity":"58.9"},"@type":"room","name":"Wohnzimmer","id":"hz_5"}],"jsonrpc":"2.0"}

2021-11-05 00:29:01.772 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-11-05 00:29:01.774 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@1c91c75{STARTED} 2021-11-05 00:29:01.775 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.178.34:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/longPoll","params":["ekfmeiced-7","20"]} 2021-11-05 00:29:21.791 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-11-05 00:29:21.805 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-11-05 00:29:21.808 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@1c91c75{STARTED} 2021-11-05 00:29:21.812 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.178.34:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/longPoll","params":["ekfmeiced-7","20"]} 2021-11-05 00:29:41.837 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[],"jsonrpc":"2.0"}

2021-11-05 00:29:41.843 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-11-05 00:29:41.845 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@1c91c75{STARTED} 2021-11-05 00:29:41.847 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.178.34:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/longPoll","params":["ekfmeiced-7","20"]} 2021-11-05 00:29:46.900 [WARN ] [ng.tr064.internal.soap.SOAPConnector] - Failed to get Tr064ChannelConfig{channelType=wanIpAddress, getAction=GetInfo, dataType='string, parameter='null'}: HTTP-Response-Code 500 (Internal Server Error), SOAP-Fault: 401 (Invalid Action) 2021-11-05 00:30:00.603 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[{"@type":"scenarioTriggered","name":"Gute Nacht","id":"681961da-788e-4e60-9555-3c0709684cc3","lastTimeTriggered":"1636068600374"}],"jsonrpc":"2.0"}

2021-11-05 00:30:00.617 [DEBUG] [.internal.devices.bridge.LongPolling] - Sending long poll request 2021-11-05 00:30:00.619 [TRACE] [ernal.devices.bridge.BoschHttpClient] - Create request for http client BoschHttpClient@1c91c75{STARTED} 2021-11-05 00:30:00.621 [TRACE] [ernal.devices.bridge.BoschHttpClient] - create request for https://192.168.178.34:8444/remote/json-rpc and content {"jsonrpc":"2.0","method":"RE/longPoll","params":["ekfmeiced-7","20"]} 2021-11-05 00:30:00.689 [DEBUG] [.internal.devices.bridge.LongPolling] - Long poll response: {"result":[{"deleted":false,"remainingTimeUntilArmed":963,"@type":"armingState","state":"SYSTEM_ARMING"}],"jsonrpc":"2.0"}

2021-11-05 00:30:00.691 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Got update for null 2021-11-05 00:30:00.692 [DEBUG] [devices.bridge.BoschSHCBridgeHandler] - Registered device: hdm:HomeMaticIP:3014F711A000005BB85A7C8D - looking for null 2021-11-05 00:30:00.694 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: java.lang.NullPointerException: null at org.openhab.binding.boschshc.internal.devices.bridge.BoschSHCBridgeHandler.handleLongPollResult(BoschSHCBridgeHandler.java:320) ~[?:?] at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling.onLongPollComplete(LongPolling.java:215) ~[?:?] at org.openhab.binding.boschshc.internal.devices.bridge.LongPolling$1.lambda$0(LongPolling.java:171) ~[?:?] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?] at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?] at java.lang.Thread.run(Thread.java:829) [?:?] `

So after this null-pointer bosch does not update any item within the OH-System, until i restart the binding.. Fun fact: The rule generating the issue is a Bosch-Rule that triggers itself at 00:30 to start a scenario