Circular dependencies / startup issues resolved

Kai · July 9, 2016, 9:06am

All,

the latest build #399 now includes a couple of fixes for the startup behavior, which should fix quite some issues like this one.

I strongly recommend to upgrade to this build if you had any issues with your startup rules, etc, in the past as I expect it to be much more reliable during startup.

Best regards,
Kai

chris · July 9, 2016, 9:18am

Hi Kai,
So I’ve upgraded to todays runtime - everything updated to the online version except for retaining the userdata folder.

I then installed the zwave binding, and I get the following logged - this is all. Any thoughts?

openhab> log:display zw
10:14:17.830 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent INSTALLED - org.openhab.binding.zwave
10:14:18.501 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent RESOLVED - org.openhab.binding.zwave
10:14:20.058 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTING - org.openhab.binding.zwave
10:14:20.060 [DEBUG] [inding.zwave.internal.ZWaveActivator] - Z-Wave binding started. Version 2.0.0.201607080102
10:14:20.095 [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=439, service.bundleid=204, service.scope=singleton} - org.openhab.binding.zwave
10:14:20.097 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=440, service.bundleid=204, service.scope=singleton} - org.openhab.binding.zwave
10:14:20.101 [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=441, service.bundleid=204, service.scope=singleton} - org.openhab.binding.zwave
10:14:20.103 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=442, service.bundleid=204, service.scope=singleton} - org.openhab.binding.zwave
10:14:20.106 [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=443, service.bundleid=204, service.scope=singleton} - org.openhab.binding.zwave
10:14:20.108 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=444, service.bundleid=204, service.scope=singleton} - org.openhab.binding.zwave
10:14:20.111 [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=445, service.bundleid=204, service.scope=singleton} - org.openhab.binding.zwave
10:14:20.113 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=446, service.bundleid=204, service.scope=singleton} - org.openhab.binding.zwave
10:14:20.123 [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=447, service.bundleid=204, service.scope=singleton} - org.openhab.binding.zwave
10:14:20.124 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.zwave.internal.ZWaveHandlerFactory, component.id=295, service.id=438, service.bundleid=204, service.scope=bundle} - org.openhab.binding.zwave
10:14:20.195 [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=296, service.id=448, service.bundleid=204, service.scope=bundle} - org.openhab.binding.zwave
10:14:20.197 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTED - org.openhab.binding.zwave

Kai · July 9, 2016, 9:31am

except for retaining the userdata folder.

Then better don’t retain it and see if it makes a difference. I tried the offline distro and Z-Wave seems to start up alright.

chris · July 9, 2016, 9:34am

Ok - I’ll give it a try. I was trying to avoid that as I will need to reinstall all things

chris · July 9, 2016, 9:50am

Ok - that did fix it. I suspect that whatever is/was causing the issue with the callback may also be the issue that was stopping the binding from starting as I also had this on the weather binding.

Anyway - it’s working now, and I just need to reinstall my 50 zwave things . I don’t suppose there’s a way to backup/export the mapdb database?

luotaus · July 9, 2016, 9:55am

Similar situation here:

The update of an existing installation (via the script from this forum) was not working, the console didn’t even start properly.

Installing the online distribution in an empty directory and copy of the conf files worked. And from a first look it seems like the startup issues are resolved.

Kai · July 9, 2016, 11:06am

@chris, did you try to only copy the mapdb folder?

chris · July 9, 2016, 11:08am

Yes - that caused it to die.

chris · July 9, 2016, 11:10am

Ah - and just to confirm that I also copied the other ‘user’ type folders (ie other than log, cache, etc…) and it still works, so I’m pretty confident the issue is in the mapdb.

chris · July 9, 2016, 12:08pm

Hmmm - I’m still seeing an issue with one of my bindings not starting -:

13:01:34.674 [DEBUG] [org.openhab.binding.meteostick      ] - BundleEvent STARTING - org.openhab.binding.meteostick
13:01:34.683 [DEBUG] [org.openhab.binding.meteostick      ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.meteostick.internal.meteostickHandlerFactory, component.id=196, service.id=335, service.bundleid=203, service.scope=bundle} - org.openhab.binding.meteostick
13:01:34.687 [DEBUG] [org.openhab.binding.meteostick      ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=meteostick:meteostick_bridge, thing.id=meteostick:meteostick_bridge:155cf0d3f4e, service.id=336, service.bundleid=203, service.scope=singleton} - org.openhab.binding.meteostick
13:01:34.692 [DEBUG] [org.openhab.binding.meteostick      ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=meteostick:meteostick_davis_iss, thing.id=meteostick:meteostick_davis_iss:155cf0dee5d, service.id=337, service.bundleid=203, service.scope=singleton} - org.openhab.binding.meteostick
13:01:34.694 [DEBUG] [tick.handler.meteostickSensorHandler] - Initializing MeteoStick handler.
13:01:34.695 [DEBUG] [org.openhab.binding.meteostick      ] - BundleEvent STARTED - org.openhab.binding.meteostick

Other than recompiling periodically, this binding has worked find for the past 8 months or so and this problem started a couple of weeks back. Maybe it’s not related to the previous startup issues, but it’s something I’ve not seen until recently so I’m suspicious.

mhilbush · July 9, 2016, 12:58pm

I did a from-scratch reinstall on my test system using the latest snapshot.

removed everything in /opt/openhab
unzipped last night’s build (#399) pulled from:
https://openhab.ci.cloudbees.com/job/openHAB-Distribution/lastSuccessfulBuild/artifact/distributions/openhab-online/target/openhab-online-2.0.0-SNAPSHOT.zip
copied in HABmin jar into opt/openhab/addons
copied in my items, rules, sitemaps, services (including addons.cfg), etc. from a backup of the /opt/openhab/conf directory

The startup is much cleaner, but I still see cases where the binding initialization does not proceed.

Kai · July 10, 2016, 3:46pm

This seems to be something different then. Do we already have an issue at ESH that describes what exactly “binding initialization does not proceed” means?

mhilbush · July 10, 2016, 4:35pm

I don’t believe so. If you’d like, I can open an ESH issue that describes the behavior that’s outlined in this and other threads.

Kai · July 10, 2016, 6:01pm

Thanks, definitely good to have it entered there to keep track.

mhilbush · July 10, 2016, 6:25pm

I just entered the issue. The title may not be worded all that well, so feel free to edit it.

@chris, Feel free to add/edit based on your observations.

github.com/eclipse-archived/smarthome

Binding initialization stalls during startup (intermittently)

opened 06:21PM - 10 Jul 16 UTC

closed 06:15PM - 13 Jul 16 UTC

mhilbush

bug Core Critical

There have been numerous reports of bindings "stalling" (for lack of a better wo…rd) at startup. I have experienced the problem with the zwave and systeminfo bindings. Others have reported similar behavior with knx, rfxcom, meteostick, and max. I first noticed this behavior with the 6/19 build, and it continues through the most current build (#399). At the time I was installing builds on almost a daily basis, and I do not recall seeing this behavior in the 6/17 and prior builds (I think I skipped installing the 6/18 build, so I don't know about that one). I started this forum thread, which has now become quite long. https://community.openhab.org/t/binding-not-starting-consistently-since-6-19-build/11741 There are other forum threads describing similar behavior. Here. https://community.openhab.org/t/z-wave-binding-things-initializing-after-restart/12173 And here. https://community.openhab.org/t/testing-z-wave-binding-on-openhab-2/7522/1372 This originally was thought to be related to the circular reference issue. However, the problem continues even after the circular reference fix. There may be some relationship to the XML file loading issue, but perhaps not. https://github.com/eclipse/smarthome/issues/1796 Here's the summary of what I'm seeing: Start openhab. Things start out pretty normal. ``` 2016-06-20 10:38:47.723 [INFO ] [smarthome.event.ThingAddedEvent ] - Thing 'zwave:device:1556e3ab04f:node3' has been added. 2016-06-20 10:38:47.800 [INFO ] [smarthome.event.ThingAddedEvent ] - Thing 'zwave:device:1556e3ab04f:node6' has been added. 2016-06-20 10:38:47.807 [INFO ] [smarthome.event.ThingAddedEvent ] - Thing 'zwave:serial_zstick:1556e3ab04f' has been added. 2016-06-20 10:38:47.870 [INFO ] [smarthome.event.ItemAddedEvent ] - Item 'zwave_device_1556e3ab04f_node3_scene_number' has been added. 2016-06-20 10:38:47.872 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_device_1556e3ab04f_node3_scene_number-zwave:device:1556e3ab04f:node3:scene_number' has been added. 2016-06-20 10:38:47.875 [INFO ] [smarthome.event.ItemAddedEvent ] - Item 'zwave_device_1556e3ab04f_node6_scene_number' has been added. 2016-06-20 10:38:47.878 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_device_1556e3ab04f_node6_scene_number-zwave:device:1556e3ab04f:node6:scene_number' has been added. 2016-06-20 10:38:47.886 [INFO ] [smarthome.event.ItemAddedEvent ] - Item 'zwave_device_1556e3ab04f_node6_switch_dimmer' has been added. 2016-06-20 10:38:47.889 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_device_1556e3ab04f_node6_switch_dimmer-zwave:device:1556e3ab04f:node6:switch_dimmer' has been added. 2016-06-20 10:38:47.894 [INFO ] [smarthome.event.ItemAddedEvent ] - Item 'zwave_serial_zstick_1556e3ab04f_serial_ack' has been added. 2016-06-20 10:38:47.896 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_serial_zstick_1556e3ab04f_serial_ack-zwave:serial_zstick:1556e3ab04f:serial_ack' has been added. 2016-06-20 10:38:47.902 [INFO ] [smarthome.event.ItemAddedEvent ] - Item 'zwave_serial_zstick_1556e3ab04f_serial_can' has been added. 2016-06-20 10:38:47.908 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_serial_zstick_1556e3ab04f_serial_can-zwave:serial_zstick:1556e3ab04f:serial_can' has been added. 2016-06-20 10:38:47.917 [INFO ] [smarthome.event.ItemAddedEvent ] - Item 'zwave_serial_zstick_1556e3ab04f_serial_nak' has been added. 2016-06-20 10:38:47.921 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_serial_zstick_1556e3ab04f_serial_nak-zwave:serial_zstick:1556e3ab04f:serial_nak' has been added. 2016-06-20 10:38:47.932 [INFO ] [smarthome.event.ItemAddedEvent ] - Item 'zwave_serial_zstick_1556e3ab04f_serial_oof' has been added. 2016-06-20 10:38:47.934 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_serial_zstick_1556e3ab04f_serial_oof-zwave:serial_zstick:1556e3ab04f:serial_oof' has been added. 2016-06-20 10:38:47.936 [INFO ] [smarthome.event.ItemAddedEvent ] - Item 'zwave_serial_zstick_1556e3ab04f_serial_sof' has been added. 2016-06-20 10:38:47.938 [INFO ] [home.event.ItemChannelLinkAddedEvent] - Link 'zwave_serial_zstick_1556e3ab04f_serial_sof-zwave:serial_zstick:1556e3ab04f:serial_sof' has been added. 2016-06-20 10:38:50.530 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui 2016-06-20 10:38:50.744 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start 2016-06-20 10:38:50.755 [DEBUG] [org.openhab.binding.zwave ] - BundleEvent STARTING - org.openhab.binding.zwave 2016-06-20 10:38:50.760 [DEBUG] [inding.zwave.internal.ZWaveActivator] - ZWave binding started. Version 2.0.0.201606200830 2016-06-20 10:38:51.019 [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=156, service.id=274, service.bundleid=188, service.scope=bundle} - org.openhab.binding.zwave 2016-06-20 10:38:51.029 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.zwave.internal.ZWaveHandlerFactory, component.id=157, service.id=275, service.bundleid=188, service.scope=bundle} - org.openhab.binding.zwave 2016-06-20 10:38:51.094 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=zwave:aeon_dsa03202_00_000, thing.id=zwave:device:1556e3ab04f:node3, service.id=276, service.bundleid=188, service.scope=singleton} - org.openhab.binding.zwave 2016-06-20 10:38:51.106 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:1556e3ab04f:node3' changed from UNINITIALIZED to INITIALIZING 2016-06-20 10:38:51.118 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=277, service.bundleid=188, service.scope=singleton} - org.openhab.binding.zwave 2016-06-20 10:38:51.147 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=zwave:leviton_vrp03_00_000, thing.id=zwave:device:1556e3ab04f:node6, service.id=278, service.bundleid=188, service.scope=singleton} - org.openhab.binding.zwave 2016-06-20 10:38:51.153 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=279, service.bundleid=188, service.scope=singleton} - org.openhab.binding.zwave 2016-06-20 10:38:51.158 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:1556e3ab04f:node6' changed from UNINITIALIZED to INITIALIZING 2016-06-20 10:38:51.195 [DEBUG] [org.openhab.binding.zwave ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandler}={thing.type=zwave:serial_zstick, thing.id=zwave:serial_zstick:1556e3ab04f, service.id=280, service.bundleid=188, service.scope=singleton} - org.openhab.binding.zwave 2016-06-20 10:38:51.213 [DEBUG] [org.openhab.binding.zwave ] - BundleEvent STARTED - org.openhab.binding.zwave 2016-06-20 10:38:51.215 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:serial_zstick:1556e3ab04f' changed from UNINITIALIZED to INITIALIZING ``` But at this point there's nothing. Initialization of the zwave stick and nodes never starts. When things start normally I would see messages like this. ``` 2016-06-20 09:35:30.622 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler. 2016-06-20 09:35:30.631 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:1556de5cdb3:node3' changed from INITIALIZING to OFFLINE 2016-06-20 09:35:30.633 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Controller initialised. ``` The "Initializing ZWave thing handler" message is the first thing called in the ThingHandler's initialize() method, so I'm assuming that the initialize() method is never being called. ``` @Override public void initialize() { logger.debug("Initializing ZWave thing handler."); ``` @cdjackson, please feel free to add to this if you have any additional information.

Kai · July 13, 2016, 8:51pm

Hopefully resolved with build 407 now - please test!

mhilbush · July 13, 2016, 9:21pm

As I reported over on this thread, this build looks really good.

marcel_verpaalen · July 14, 2016, 5:50am

I also can confirm for me the latest build (#408) fixed the startup issues on my side.

@Kai thanks for all the work to find the cause of this and fix it!