C-Bus binding throws exception under 3.2.0 release

glen_m · December 22, 2021, 7:01pm

Hi Nick - I have tagged this post into the openHAB 3.2 Release discussion post, and raised the following bug ticket in github:

github.com/openhab/openhab-addons

[CBUS] Exception after upgrade to OH 3.2.0 release

opened 06:35PM - 22 Dec 21 UTC

closed 03:20PM - 02 Jan 22 UTC

glenm-nz

bug

**Overview:** The CBUS binding is throwing an exception on startup, following u…pgrade to OH 3.2.0. I have not been running any milestone builds for this release, so cannot confirm where this was introduced, but can confirm it worked correctly under 3.1.x, just prior to upgrade. Have tried multiple restarts and clearing the OH cache (via openhab-cli) As a result, the cbus bridges remain offline, and as would then be expected, all 'downstream' cbus things are in an "ERROR:BRIDGE" state. This has also been experienced by another user as well (see https://community.openhab.org/t/c-bus-binding/130366), although they were trying to setup cbus binding from scratch under 3.2.0, not realising this was a regression. **Details:** The following is the TRACE level log on startup for the CBUS binding (I have truncated after the first few things loaded for readability - No other errors beyond the listed exception). `2021-12-22 17:11:14.753 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory] : BundleComponentActivator : ComponentHolder created. 2021-12-22 17:11:14.754 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory] : Component created: DS=DS13, implementation=org.openhab.binding.cbus.internal.CBusHandlerFactory, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[binding.cbus] 2021-12-22 17:11:14.755 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory] : Component Services: scope=singleton, services=[org.openhab.core.thing.binding.ThingHandlerFactory] 2021-12-22 17:11:14.756 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory] : Component Properties: {} 2021-12-22 17:11:14.756 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory] : Querying state disabled 2021-12-22 17:11:14.757 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory] : Querying state disabled 2021-12-22 17:11:14.757 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory] : Component can not be activated since it is in state disabled 2021-12-22 17:11:14.758 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory] : Querying state disabled 2021-12-22 17:11:14.759 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : Updating target filters 2021-12-22 17:11:14.759 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : Changed state from disabled to unsatisfiedReference 2021-12-22 17:11:14.760 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : Component enabled 2021-12-22 17:11:14.760 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : ActivateInternal 2021-12-22 17:11:14.761 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : Querying state unsatisfiedReference 2021-12-22 17:11:14.761 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : Querying state unsatisfiedReference 2021-12-22 17:11:14.762 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : Activating component from state unsatisfiedReference 2021-12-22 17:11:14.762 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : Querying state unsatisfiedReference 2021-12-22 17:11:14.763 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : Querying state unsatisfiedReference 2021-12-22 17:11:14.763 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : Changed state from unsatisfiedReference to satisfied 2021-12-22 17:11:14.764 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : registration change queue [registered] 2021-12-22 17:11:14.765 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : Checking constructor public org.openhab.binding.cbus.internal.CBusHandlerFactory() 2021-12-22 17:11:14.766 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : Found constructor with 0 arguments : public org.openhab.binding.cbus.internal.CBusHandlerFactory() 2021-12-22 17:11:14.767 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : This thread collected dependencies 2021-12-22 17:11:14.767 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : getService (single component manager) dependencies collected. 2021-12-22 17:11:14.768 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : Querying state satisfied 2021-12-22 17:11:14.768 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : Querying state satisfied 2021-12-22 17:11:14.769 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : getting activate: activate 2021-12-22 17:11:14.769 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : Locating method activate in class org.openhab.binding.cbus.internal.CBusHandlerFactory 2021-12-22 17:11:14.770 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : Declared Method org.openhab.binding.cbus.internal.CBusHandlerFactory.activate([interface org.osgi.service.component.ComponentContext]) not found 2021-12-22 17:11:14.771 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : Locating method activate in class org.openhab.core.thing.binding.BaseThingHandlerFactory 2021-12-22 17:11:14.771 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : Found activate method: protected void org.openhab.core.thing.binding.BaseThingHandlerFactory.activate(org.osgi.service.component.ComponentContext) 2021-12-22 17:11:14.772 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : invoking activate: activate: parameters [org.apache.felix.scr.impl.manager.ComponentContextImpl] 2021-12-22 17:11:14.773 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : invoked activate: activate 2021-12-22 17:11:14.773 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : Set implementation object for component 2021-12-22 17:11:14.774 [DEBUG] [ing.cbus.internal.CBusHandlerFactory] - bundle org.openhab.binding.cbus:3.2.0 (266)[org.openhab.binding.cbus.internal.CBusHandlerFactory(410)] : Changed state from satisfied to active 2021-12-22 17:11:14.819 [DEBUG] [inding.cbus.handler.CBusCGateHandler] - Initializing CGate Bridge handler. cbus:cgate cbus:cgate:cgatenetwork 2021-12-22 17:11:14.820 [DEBUG] [inding.cbus.handler.CBusCGateHandler] - Using configuration [ipAddress=127.0.0.1] 2021-12-22 17:11:14.820 [DEBUG] [inding.cbus.handler.CBusCGateHandler] - CGate IP 127.0.0.1. 2021-12-22 17:11:14.826 [DEBUG] [ding.cbus.handler.CBusNetworkHandler] - initialize 2021-12-22 17:11:14.827 [DEBUG] [ding.cbus.handler.CBusNetworkHandler] - Using configuration [id=254, project=FINLAYS, syncInterval=600] 2021-12-22 17:11:14.827 [DEBUG] [ding.cbus.handler.CBusNetworkHandler] - getCBusCGateHandler 2021-12-22 17:11:14.822 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: java.lang.ClassCastException: class org.openhab.core.common.ThreadPoolManager$UnstoppableExecutorService cannot be cast to class java.util.concurrent.ThreadPoolExecutor (org.openhab.core.common.ThreadPoolManager$UnstoppableExecutorService is in unnamed module of loader org.eclipse.osgi.internal.loader.EquinoxClassLoader @51a718c1; java.util.concurrent.ThreadPoolExecutor is in module java.base of loader 'bootstrap') at org.openhab.binding.cbus.internal.CBusThreadPool$CBusThreadPoolExecutor.<init>(CBusThreadPool.java:51) ~[?:?] at org.openhab.binding.cbus.internal.CBusThreadPool.CreateExecutor(CBusThreadPool.java:41) ~[?:?] at com.daveoxley.cbus.Response.SetThreadPool(Response.java:45) ~[?:?] at com.daveoxley.cbus.CGateSession.<init>(CGateSession.java:87) ~[?:?] at com.daveoxley.cbus.CGateInterface.connect(CGateInterface.java:74) ~[?:?] at org.openhab.binding.cbus.handler.CBusCGateHandler.connect(CBusCGateHandler.java:106) ~[?:?] at org.openhab.binding.cbus.handler.CBusCGateHandler.keepAlive(CBusCGateHandler.java:96) ~[?:?] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?] at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[?:?] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?] at java.lang.Thread.run(Thread.java:829) [?:?] 2021-12-22 17:11:14.828 [DEBUG] [ding.cbus.handler.CBusNetworkHandler] - bridge not online 2021-12-22 17:11:14.839 [DEBUG] [ding.cbus.handler.CBusNetworkHandler] - initialize 2021-12-22 17:11:14.840 [DEBUG] [ding.cbus.handler.CBusNetworkHandler] - Using configuration [id=253, project=FINLAYS, syncInterval=600] 2021-12-22 17:11:14.841 [DEBUG] [ding.cbus.handler.CBusNetworkHandler] - getCBusCGateHandler 2021-12-22 17:11:14.842 [DEBUG] [ding.cbus.handler.CBusNetworkHandler] - bridge not online 2021-12-22 17:11:14.851 [DEBUG] [inding.cbus.handler.CBusGroupHandler] - Using configuration [group=13] 2021-12-22 17:11:14.852 [DEBUG] [inding.cbus.handler.CBusGroupHandler] - updateStatus UID: cbus:light:cgatenetwork:cbushomenetwork:Bedroom2CeilingLights applicaton: 56 group: 13 2021-12-22 17:11:14.854 [DEBUG] [inding.cbus.handler.CBusGroupHandler] - Using configuration [group=49] 2021-12-22 17:11:14.855 [DEBUG] [inding.cbus.handler.CBusGroupHandler] - updateStatus UID: cbus:light:cgatenetwork:cbushomenetwork:KitchenBenchLights applicaton: 56 group: 49 2021-12-22 17:11:14.860 [DEBUG] [inding.cbus.handler.CBusGroupHandler] - Using configuration [group=7] 2021-12-22 17:11:14.860 [DEBUG] [inding.cbus.handler.CBusGroupHandler] - Using configuration [group=19] 2021-12-22 17:11:14.860 [DEBUG] [inding.cbus.handler.CBusGroupHandler] - updateStatus UID: cbus:light:cgatenetwork:cbushomenetwork:Bedroom4WIRLights applicaton: 56 group: 7` **Environment:** Ubuntu: 21.10 OpenHAB: 3.2.0 (Release) CBUS Binding: 3.2.0 Java Environment: openjdk 11.0.13 2021-10-19 LTS OpenJDK Runtime Environment Zulu11.52+13-CA (build 11.0.13+8-LTS) OpenJDK 64-Bit Server VM Zulu11.52+13-CA (build 11.0.13+8-LTS, mixed mode)

Maybe if you could edit the title of this post to be something like “C-Bus binding throws exception under 3.2.0 release” (now you know what the issue is ) it may help others in future searches etc.

Now this is where my ability to help runs out, beyond testing any fixes etc, as I’m not a java coder…
However once this is sorted, I can probably help with other general advice on the C-Bus/OpenHAB integration, as you embark on bringing that into your system… Been running it for a while now, and until yesterday, this integration has been rock-solid.

Cheers