glen_m
December 22, 2021, 6:50pm
45
Hi there - Thanks for the great work on this release. Most of my integrations have come back to life and are looking good, with the exception of the CBUS binding, which is throwing an exception on startup.
See the discussion at C-Bus binding for more details, however the title does not link it to the 3.2.0 upgrade, as the user was trying to setup cbus integration for the first time since installing 3.2.0, so it would not have been obvious that it was a regression.
I have raised the following bug ticket for this:
opened 06:35PM - 22 Dec 21 UTC
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)
Looking at the changes in the binding for 3.2.0, there are no material changes applied other than the “spotless” & “crowdin” changes applied across all the bindings, so hard to imagine it is anything to do with those, so perhaps more an underlying change in the OpenHAB framework causing the regression? (disclaimer: I’m not a java programmer, so don’t take the above observation as a statement of fact
FYI @jpharvey
Cheers
)