C-Bus binding throws exception under 3.2.0 release

I have just installed the latest stable OpenHAB on a Windows PC which is also running Clipsal CGate.

All went well until I tried to configure the CGate “bridge” - it is stubbornly showing “offline”. I have tried 127.0.0.1 and the 192.168.178.20 (which is PCs IP address). I have tried those both with and without :20023 and :20123. I have both IP addresses listed in CGate’s access.txt file.

Any clues on what I should look at next?

Thanks,

Nick

Tonight I just installed the same C-Bus binding and have the same issue. I don’t see any attempts to connect in the C-Gate logs. The access file is correct and other clients can connect fine.

Thanks for chipping in Kevin. At least now I know it’s not just me. Anyone got any ideas?

Nick - I see a couple of other threads re IP devices not connecting in 3.2. I am new to OH but I’m going to try manually (textually) creating the thing and see if that works.

I can get my C-Bus groups in via MQTT so I’m not dependent on getting this binding working.

Thanks Kevin. So, it sounds like there might be an issue of some kind with the new version - I will wait patiently for a bit. I’m not new to OH - and have has the C-Bus setup working with V2, albeit on a Pi rather than a Windows box. I gave up on that because the USB/Serial port died and I struggled to fix it. Hence trying again on Windows and with the latest version of OH.

Let’s see where it goes. Thanks for the update, Nick.

Not sure if you are seeing any error messages in the openhab.log, but the CBUS bridge (cGate connection) parent device is now offline following an upgrade to openHAB 3.2.0 (Release Build)

I am seeing the following in openhab.log:

2021-12-22 16:31:49.952 [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 @477fbbe9; 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) [?:?]

Setting the logging level for the CBUS binding to TRACE, the following also shows on startup (note this has been truncated, as the last section of the log is repeated for every cbus group).

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

Be interesting to know if you are seeing similar errors. I can look at raising a github issue ticket as required.
Cheers

Hi Glen,

Thanks for helping! Yes, I am seeing that first error too. Not the second lot though, as it’s a new install, so haven’t got as far as creating groups in OH yet,

Cheers,

Nick

Hi Glen,

I’ve just seen your post on the upgrade thread. Again, thanks for helping :slight_smile:

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

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 :slight_smile: ) 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

I have a fix for this but no time to create the pull request. Will see what i can do over the next few days. But it might need to be after Christmas.
I might see if i can share a rebuilt binding that fixes the problem.

1 Like

I have created a Pull Request which includes the fix [cbus] fix exception from threadpool at startup by jpharvey · Pull Request #11846 · openhab/openhab-addons (github.com)

A jar i built can be copied from Microsoft OneDrive - Access files anywhere. Create docs with free Office Online.
This should be copied to /usr/share/openhab/addons
There will be 2 copies of the addon at that point. and the downloaded one will need to be disabled.
ssh to karaf console

then run
bundle:list | grep -i cbus

which should return something like
openhab> bundle:list | grep -i cbus
241 │ Active │ 80 │ 3.3.0.202112220333 │ openHAB Add-ons :: Bundles :: CBus Binding
257 │ Active │ 80 │ 3.3.0.202112222122 │ openHAB Add-ons :: Bundles :: CBus Binding
openhab>
Then stop the original one with
bundle:stop 241
rerunning the list will then show it as Resolved instead of Active.
After this i restarted opehab

Thanks both, all amazingly quick!!
Topic title changed as suggested.
Unfortunately, I am away now until after Christmas, so will be a bit delayed in trying the fix.
I should be OK after that, as the now defunct 2.x version running on my Pi was working well and was rock solid.
Thanks again, Nick.

Great work - Thanks @jpharvey for the amazingly quick turnaround. Have applied the JAR (and the post-steps you list above), and everything under the CBUS binding has gone back online, and I have tested a few basic channel operations, which work well. I will give it more extensive testing tonight (discovery etc).

Cheers - Glen

Updated the JAR and now the CGate connection is online :smiley:

New user to OH and this binding… so probably a silly question. When I add the Project Name and the network number to the C-Bus Network bridge thing should that immediately go online too because it doesn’t.

Totally silly - I didn’t realise I had to kickoff scan and so I manually created the Network Bridges and they didn’t work. All set now

Many thanks for your prompt update John

Hi @jpharvey - As promised, I have run a further (more extended) set of tests, with the results posted on GitHUB:

All functional aspects work well, just a few notes in relation to some further exceptions observed. Whether these are regressions resulting from OH 3.2.0, I unfortunately cannot confirm, but again none appear to impact functionality/operation

Thanks again for the great work.

Thanks John!

I am back home and trying this now.

I couldn’t quite work out what was where on Windows, but I found a CBUS JAR file, deleted it, replaced it with the newly downloaded one (giving it the same name) and all seems to be well now.

Thanks for all the support!

Cheers,

Nick

After issuing bundle:stop on the older bundle all worked and it shows as ‘resolved’, everything worked.

However a few days later the new binding went into error. On looking at the bundles now the old one is ‘active’. I can again stop it to correct this.

What causes a ‘resolved’ bundle to go back to ‘active’ and how can I stop this?

I have tried bundle:uninstall for the time being - hope that’s OK

uninstall should be fine. No idea why it became active again. Mine has been fine since doing it, though i suspect if a new version of the binding is downloaded it may do that.