Strangely, having changed nothing in my system over the past couple of days, I’m now also seeing this…
If I stop/start the binding on the console, then I only see the service registration messages -:
21:36:30.104 [DEBUG] [inding.zwave.internal.ZWaveActivator] - ZWave binding stopped.
21:36:30.105 [DEBUG] [org.openhab.binding.zwave ] - BundleEvent STOPPED - org.openhab.binding.zwave
21:36:33.416 [DEBUG] [org.openhab.binding.zwave ] - BundleEvent STARTING - org.openhab.binding.zwave
21:36:33.417 [DEBUG] [inding.zwave.internal.ZWaveActivator] - Z-Wave binding started. Version 2.0.0.201607020102
21:36:33.422 [DEBUG] [org.openhab.binding.zwave ] - BundleEvent STARTED - org.openhab.binding.zwave
21:36:33.430 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.zwave.internal.ZWaveHandlerFactory, component.id=219, service.id=380, service.bundleid=201, service.scope=bundle} - org.openhab.binding.zwave
21:36:33.433 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=zwave:qubino_zmnhba_00_000, thing.id=zwave:device:1531045fdae:node12, service.id=381, service.bundleid=201, service.scope=singleton} - org.openhab.binding.zwave
21:36:33.435 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=382, service.bundleid=201, service.scope=singleton} - org.openhab.binding.zwave
21:36:33.437 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=zwave:tkb_tz88_00_000, thing.id=zwave:device:1531045fdae:node13, service.id=383, service.bundleid=201, service.scope=singleton} - org.openhab.binding.zwave
21:36:33.440 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=384, service.bundleid=201, service.scope=singleton} - org.openhab.binding.zwave
21:36:33.443 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=zwave:fibaro_fgd211_00_000, thing.id=zwave:device:1531045fdae:node2, service.id=385, service.bundleid=201, service.scope=singleton} - org.openhab.binding.zwave
21:36:33.445 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=386, service.bundleid=201, service.scope=singleton} - org.openhab.binding.zwave
21:36:33.448 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=zwave:fibaro_fgd211_00_000, thing.id=zwave:device:1531045fdae:node4, service.id=387, service.bundleid=201, service.scope=singleton} - org.openhab.binding.zwave
21:36:33.453 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=388, service.bundleid=201, service.scope=singleton} - org.openhab.binding.zwave
21:36:33.455 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=zwave:serial_zstick, thing.id=zwave:serial_zstick:1531045fdae, service.id=389, service.bundleid=201, service.scope=singleton} - org.openhab.binding.zwave
21:36:33.462 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigOptionProvider, org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={component.name=org.openhab.binding.zwave.ConfigDescription, component.id=220, service.id=390, service.bundleid=201, service.scope=bundle} - org.openhab.binding.zwave
The next thing I guess should be the framework reading the XML files, and the binding itself doesn’t actually get started until all the files have been read (in theory!). This doesn’t seem to be happening under Karaf (ie I don’t see the loading XML messages at all), and if I run the system in the IDE, it all works ok, but I’ve just noticed that the XML files are now being loaded AFTER the things are initialised, so it looks like this is now broken.
I suspect this isn’t the problem, but it is known to cause other problems, so also needs to be fixed.
I’ve also tried upgrading to the latest version of everything, and that doesn’t work either, although I do get errors about “no callback” in various places -:
21:43:07.634 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=zwave:tkb_tz88_00_000, thing.id=zwave:device:1531045fdae:node13, service.id=394, service.bundleid=203, service.scope=singleton} - org.openhab.binding.zwave
21:43:07.633 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
21:43:07.643 [ERROR] [ome.core.thing.internal.ThingManager] - Exception occured while initializing handler of thing 'zwave:device:1531045fdae:node4': java.lang.IllegalStateException: Could not update status, because callback is missing
java.util.concurrent.ExecutionException: java.lang.IllegalStateException: Could not update status, because callback is missing
As I understand what’s meant to happen is the service gets added, and the ThingManager should find the thing and add the callback. Looking at the code, there should be a debug message Thing handler for thing '{}' added when the service is registered, but I don’t see this although the framework is saying the service is registered. I would guess this is pointing to something bad in the framework with registering services, but maybe @kai or @maggu2810 can comment?