Binding not starting consistently since 6/19 build

[MikeD (Mike Dilger)]

i have rfxcom, astro, mqtt, ntp, zwave running.

Pretty sure that I have the same issue with rfxcom.

I will go and do a few restarts and report back shortly

[Kai (Kai Kreuzer)]

I also cannot say what is going wrong, I will need time to analyze things in detail.

Messages like

org.osgi.framework.ServiceException: org.apache.felix.scr.impl.manager.SingleComponentManager.getService() returned a null service object

are due to this issue. As this has pretty weird implications, I could imagine that your problems might also be (partially) related to it. So my first priority would be to solve this (again).

[MikeD (Mike Dilger)]

@Chris,

I just restarted a couple of times. 2 x fail, 1 x OK.

In the fail situation, MQTT and Astro are working but both zwave and RFXCOM are not.

I then restarted again. MQTT, RFXCOM and zwave are working but this time Astro:Moon is not.

5th restart and everything seems to be working OK. I don’t think the issue is with the zwave binding.

Hope this helps.

Mike

[chris (Chris Jackson)]

Thanks.

I’ve restarted 6 times this morning, and haven’t had the system start properly at all (ie the ZWave binding, which is the only binding in my main system, hasn’t started each time)…

[maggu2810]

If it is really caused by the circular reference, then I would give it a try to use Apache Felix instead of Eclipse Equinox. Can you test it @chris ? It is not my personal intention to change the used OSGi framework, but I realized that the “circular reference” does not occur if the other one is used. As long as we do not know the root cause, you can give it a try.
If this solves the problem for you, it should be resolved for Equinox as soon as the circular reference could be removed.

[mhilbush (Mark)]

I’d be happy to try it, as well. What needs to be changed to enable Felix? Is it as simple as commenting out this line in runtime/karaf/etc/custom.properties?

karaf.framework=equinox

Would the steps be:

• stop openhab
• change custom.properties
• start openhab

[maggu2810]

Commenting out that lines should be enough.
You can also add:
karaf.framework=felix
to the file (if comment out is not enough – but it should)

Normally if you change the OSGi framework all bundles will be reinstalled but it would perhaps me a cleaner approach to start a clean one (delete the old karaf data folder).

[mhilbush (Mark)]

Ok, sounds good. I saw that the default (Felix) was specified in config.properties, so I figured commenting out the entry in custom.properties would be enough.

I have an installation on three separate systems, two of which are “production”, and the other one is used for testing. I can use my test system to start with a clean install. I’ll also make a backup of my current test setup, which currently is exhibiting the startup issue.

Thanks for the help.

[maggu2810]

Thanks for the help.

Perhaps nothing will be changed.

Thanks for testing and I am waiting eagerly for the result.

[mhilbush (Mark)]

Result: I continued to see initialization not working consistently. Sometimes it would start up normally, sometimes not.

Here’s what I did:

• I did my normal “update” process, which is to remove the runtime directory, and the userdata/cache and userdata/tmp directories, then unzip the latest nightly.
• Then I commented out the equinox line in runtime/karaf/etc/custom.properties
• Then started openHAB

The Circular reference exception no longer occurred, but I did see several NPEs right at startup – perhaps something looking for equinox things that are no longer there??

> 2016-07-04 11:15:16.553 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
> 2016-07-04 11:15:16.667 [ERROR] [org.eclipse.equinox.registry        ] - FrameworkEvent ERROR - org.eclipse.equinox.registry
> java.lang.NullPointerException
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.checkForNLSFiles(EclipseBundleListener.java:217)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.checkForNLSFragment(EclipseBundleListener.java:198)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.addBundle(EclipseBundleListener.java:154)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.bundleChanged(EclipseBundleListener.java:79)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:916)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:835)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:517)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:4541)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.StatefulResolver.fireResolvedEvents(StatefulResolver.java:1241)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.StatefulResolver.resolve(StatefulResolver.java:465)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.resolveBundleRevision(Felix.java:4106)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.startBundle(Felix.java:2117)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.setActiveStartLevel(Felix.java:1371)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.FrameworkStartLevelImpl.run(FrameworkStartLevelImpl.java:308)[org.apache.felix.framework-5.4.0.jar:]
> 	at java.lang.Thread.run(Thread.java:745)[:1.8.0_91]
> 2016-07-04 11:15:16.674 [ERROR] [org.eclipse.equinox.registry        ] - FrameworkEvent ERROR - org.eclipse.equinox.registry
> java.lang.NullPointerException
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.checkForNLSFiles(EclipseBundleListener.java:217)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.checkForNLSFragment(EclipseBundleListener.java:198)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.addBundle(EclipseBundleListener.java:154)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.bundleChanged(EclipseBundleListener.java:79)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:916)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:835)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:517)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:4541)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.StatefulResolver.fireResolvedEvents(StatefulResolver.java:1244)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.StatefulResolver.resolve(StatefulResolver.java:465)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.resolveBundleRevision(Felix.java:4106)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.startBundle(Felix.java:2117)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.setActiveStartLevel(Felix.java:1371)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.FrameworkStartLevelImpl.run(FrameworkStartLevelImpl.java:308)[org.apache.felix.framework-5.4.0.jar:]
> 	at java.lang.Thread.run(Thread.java:745)[:1.8.0_91]
> 2016-07-04 11:15:16.829 [ERROR] [org.eclipse.equinox.registry        ] - FrameworkEvent ERROR - org.eclipse.equinox.registry
> java.lang.NullPointerException
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.checkForNLSFiles(EclipseBundleListener.java:217)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.checkForNLSFragment(EclipseBundleListener.java:198)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.addBundle(EclipseBundleListener.java:154)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.bundleChanged(EclipseBundleListener.java:79)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:916)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:835)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:517)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:4541)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.StatefulResolver.fireResolvedEvents(StatefulResolver.java:1244)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.StatefulResolver.resolve(StatefulResolver.java:465)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.resolveBundleRevision(Felix.java:4106)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.startBundle(Felix.java:2117)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.setActiveStartLevel(Felix.java:1371)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.FrameworkStartLevelImpl.run(FrameworkStartLevelImpl.java:308)[org.apache.felix.framework-5.4.0.jar:]
> 	at java.lang.Thread.run(Thread.java:745)[:1.8.0_91]
> 2016-07-04 11:15:16.830 [ERROR] [org.eclipse.equinox.registry        ] - FrameworkEvent ERROR - org.eclipse.equinox.registry
> java.lang.NullPointerException
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.checkForNLSFiles(EclipseBundleListener.java:217)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.checkForNLSFragment(EclipseBundleListener.java:198)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.addBundle(EclipseBundleListener.java:154)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.bundleChanged(EclipseBundleListener.java:79)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:916)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:835)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:517)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:4541)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.StatefulResolver.fireResolvedEvents(StatefulResolver.java:1241)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.StatefulResolver.resolve(StatefulResolver.java:465)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.resolveBundleRevision(Felix.java:4106)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.startBundle(Felix.java:2117)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.setActiveStartLevel(Felix.java:1371)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.FrameworkStartLevelImpl.run(FrameworkStartLevelImpl.java:308)[org.apache.felix.framework-5.4.0.jar:]
> 	at java.lang.Thread.run(Thread.java:745)[:1.8.0_91]
> 2016-07-04 11:15:16.838 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui
> 2016-07-04 11:15:16.919 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
> 2016-07-04 11:15:17.026 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent RESOLVED - org.openhab.binding.zwave
> 2016-07-04 11:15:17.028 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTING - org.openhab.binding.zwave
> 2016-07-04 11:15:17.030 [DEBUG] [inding.zwave.internal.ZWaveActivator] - Z-Wave binding started. Version 2.0.0.201607030102
> 2016-07-04 11:15:17.031 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTED - org.openhab.binding.zwave
> 2016-07-04 11:15:17.037 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - [org.eclipse.smarthome.config.core.ConfigOptionProvider, org.eclipse.smarthome.config.core.ConfigDescriptionProvider] - org.openhab.binding.zwave
> 2016-07-04 11:15:17.076 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - [org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory] - org.openhab.binding.zwave
> 2016-07-04 11:15:17.084 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - [org.eclipse.smarthome.core.thing.binding.ThingHandler] - org.openhab.binding.zwave
> 2016-07-04 11:15:17.087 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - [org.eclipse.smarthome.config.core.status.ConfigStatusProvider] - org.openhab.binding.zwave
> 2016-07-04 11:15:17.089 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - [org.eclipse.smarthome.core.thing.binding.ThingHandler] - org.openhab.binding.zwave
> 2016-07-04 11:15:17.090 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - [org.eclipse.smarthome.config.core.status.ConfigStatusProvider] - org.openhab.binding.zwave
> 2016-07-04 11:15:17.094 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - [org.eclipse.smarthome.core.thing.binding.ThingHandler] - org.openhab.binding.zwave
> 2016-07-04 11:15:17.648 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
> 2016-07-04 11:15:17.654 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
> 2016-07-04 11:15:17.707 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.sitemap'
> 2016-07-04 11:15:17.771 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rrd4j.persist'
> 2016-07-04 11:15:17.810 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mysql.persist'
> 2016-07-04 11:15:17.824 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test.rules'
> 2016-07-04 11:15:17.987 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'systeminfo.items'
> 2016-07-04 11:15:18.143 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test.items'
> 2016-07-04 11:15:18.155 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Command received zwave:device:15573c1286e:node3:sensor_binary --> REFRESH
> 2016-07-04 11:15:18.155 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
> 2016-07-04 11:15:18.156 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Command received zwave:device:15573c1286e:node3:sensor_temperature --> REFRESH
> 2016-07-04 11:15:18.156 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
> 2016-07-04 11:15:18.157 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Command received zwave:device:15573c1286e:node3:sensor_relhumidity --> REFRESH
> 2016-07-04 11:15:18.158 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
> 2016-07-04 11:15:18.159 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Command received zwave:device:15573c1286e:node3:sensor_luminance --> REFRESH
> 2016-07-04 11:15:18.159 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
> 2016-07-04 11:15:18.160 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Command received zwave:device:15573c1286e:node3:sensor_ultraviolet --> REFRESH
> 2016-07-04 11:15:18.160 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
> 2016-07-04 11:15:18.161 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Command received zwave:device:15573c1286e:node3:battery-level --> REFRESH
> 2016-07-04 11:15:18.161 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
> 2016-07-04 11:15:18.163 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Command received zwave:device:15573c1286e:node3:alarm_general --> REFRESH
> 2016-07-04 11:15:18.163 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
> 2016-07-04 11:15:18.164 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Command received zwave:device:15573c1286e:node4:sensor_binary --> REFRESH
> 2016-07-04 11:15:18.164 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
> 2016-07-04 11:15:18.165 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Command received zwave:device:15573c1286e:node4:sensor_temperature --> REFRESH
> 2016-07-04 11:15:18.165 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
> 2016-07-04 11:15:18.166 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Command received zwave:device:15573c1286e:node4:sensor_seismicintensity --> REFRESH
> 2016-07-04 11:15:18.166 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
> 2016-07-04 11:15:18.167 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Command received zwave:device:15573c1286e:node4:sensor_luminance --> REFRESH
> 2016-07-04 11:15:18.167 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
> 2016-07-04 11:15:18.168 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Command received zwave:device:15573c1286e:node4:battery-level --> REFRESH
> 2016-07-04 11:15:18.168 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
> 2016-07-04 11:15:18.169 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Command received zwave:device:15573c1286e:node4:alarm_general --> REFRESH
> 2016-07-04 11:15:18.170 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
> 2016-07-04 11:15:18.171 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 0: Command received zwave:device:15573c1286e:node4:alarm_burglar --> REFRESH
> 2016-07-04 11:15:18.171 [WARN ] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
> 2016-07-04 11:15:18.753 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ntp.items'
> 2016-07-04 11:15:21.998 [WARN ] [thome.binding.ntp.handler.NtpHandler] - ntp:ntp:local couldn't establish network connection [host '0.ubuntu.pool.ntp.org'] -> returning current sytem time instead.

As an aside, I’m not sure what’s going on with the ntp errors. If I run ntpdate, it seems to be taking >8 seconds to return. I see the NTP binding has a 5 second timeout on the transaction, so that’s probably what’s happening.

I probably should try a complete from-scratch install next.

[mhilbush (Mark)]

This time I started with a completely clean installation.

• Deleted everything in openhab directory
• Unzipped the nightly snapshot
• copied HABmin jar into addons
• copied my items, rules, sitemap, etc files into conf directory
• started up openhab - wait for bundles to be loaded
• configure zwave port
• shutdown openhab
• started up openhab

I’m still seeing the same NPEs on startup, but not the circular reference exception.

> 2016-07-04 12:22:44.323 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
> 2016-07-04 12:22:44.520 [ERROR] [org.eclipse.equinox.registry        ] - FrameworkEvent ERROR - org.eclipse.equinox.registry
> java.lang.NullPointerException
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.checkForNLSFiles(EclipseBundleListener.java:217)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.checkForNLSFragment(EclipseBundleListener.java:198)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.addBundle(EclipseBundleListener.java:154)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.bundleChanged(EclipseBundleListener.java:79)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:916)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:835)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:517)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:4541)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.StatefulResolver.fireResolvedEvents(StatefulResolver.java:1244)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.StatefulResolver.resolve(StatefulResolver.java:465)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.resolveBundleRevision(Felix.java:4106)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.startBundle(Felix.java:2117)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.setActiveStartLevel(Felix.java:1371)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.FrameworkStartLevelImpl.run(FrameworkStartLevelImpl.java:308)[org.apache.felix.framework-5.4.0.jar:]
> 	at java.lang.Thread.run(Thread.java:745)[:1.8.0_91]
> 2016-07-04 12:22:44.533 [ERROR] [org.eclipse.equinox.registry        ] - FrameworkEvent ERROR - org.eclipse.equinox.registry
> java.lang.NullPointerException
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.checkForNLSFiles(EclipseBundleListener.java:217)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.checkForNLSFragment(EclipseBundleListener.java:198)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.addBundle(EclipseBundleListener.java:154)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.bundleChanged(EclipseBundleListener.java:79)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:916)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:835)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:517)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:4541)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.StatefulResolver.fireResolvedEvents(StatefulResolver.java:1241)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.StatefulResolver.resolve(StatefulResolver.java:465)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.resolveBundleRevision(Felix.java:4106)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.startBundle(Felix.java:2117)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.setActiveStartLevel(Felix.java:1371)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.FrameworkStartLevelImpl.run(FrameworkStartLevelImpl.java:308)[org.apache.felix.framework-5.4.0.jar:]
> 	at java.lang.Thread.run(Thread.java:745)[:1.8.0_91]
> 2016-07-04 12:22:44.692 [ERROR] [org.eclipse.equinox.registry        ] - FrameworkEvent ERROR - org.eclipse.equinox.registry
> java.lang.NullPointerException
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.checkForNLSFiles(EclipseBundleListener.java:217)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.checkForNLSFragment(EclipseBundleListener.java:198)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.addBundle(EclipseBundleListener.java:154)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.bundleChanged(EclipseBundleListener.java:79)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:916)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:835)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:517)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:4541)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.StatefulResolver.fireResolvedEvents(StatefulResolver.java:1244)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.StatefulResolver.resolve(StatefulResolver.java:465)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.resolveBundleRevision(Felix.java:4106)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.startBundle(Felix.java:2117)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.setActiveStartLevel(Felix.java:1371)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.FrameworkStartLevelImpl.run(FrameworkStartLevelImpl.java:308)[org.apache.felix.framework-5.4.0.jar:]
> 	at java.lang.Thread.run(Thread.java:745)[:1.8.0_91]
> 2016-07-04 12:22:44.707 [ERROR] [org.eclipse.equinox.registry        ] - FrameworkEvent ERROR - org.eclipse.equinox.registry
> java.lang.NullPointerException
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.checkForNLSFiles(EclipseBundleListener.java:217)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.checkForNLSFragment(EclipseBundleListener.java:198)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.addBundle(EclipseBundleListener.java:154)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.eclipse.core.internal.registry.osgi.EclipseBundleListener.bundleChanged(EclipseBundleListener.java:79)[66:org.eclipse.equinox.registry:3.6.0.v20150318-1503]
> 	at org.apache.felix.framework.util.EventDispatcher.invokeBundleListenerCallback(EventDispatcher.java:916)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.util.EventDispatcher.fireEventImmediately(EventDispatcher.java:835)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.util.EventDispatcher.fireBundleEvent(EventDispatcher.java:517)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.fireBundleEvent(Felix.java:4541)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.StatefulResolver.fireResolvedEvents(StatefulResolver.java:1241)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.StatefulResolver.resolve(StatefulResolver.java:465)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.resolveBundleRevision(Felix.java:4106)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.startBundle(Felix.java:2117)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.Felix.setActiveStartLevel(Felix.java:1371)[org.apache.felix.framework-5.4.0.jar:]
> 	at org.apache.felix.framework.FrameworkStartLevelImpl.run(FrameworkStartLevelImpl.java:308)[org.apache.felix.framework-5.4.0.jar:]
> 	at java.lang.Thread.run(Thread.java:745)[:1.8.0_91]
> 2016-07-04 12:22:44.708 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui
> 2016-07-04 12:22:44.806 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
> 2016-07-04 12:22:44.881 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent RESOLVED - org.openhab.binding.zwave
> 2016-07-04 12:22:44.882 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTING - org.openhab.binding.zwave
> 2016-07-04 12:22:44.886 [DEBUG] [inding.zwave.internal.ZWaveActivator] - Z-Wave binding started. Version 2.0.0.201607030102
> 2016-07-04 12:22:44.912 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - [org.eclipse.smarthome.config.core.ConfigOptionProvider, org.eclipse.smarthome.config.core.ConfigDescriptionProvider] - org.openhab.binding.zwave
> 2016-07-04 12:22:44.914 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - [org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory] - org.openhab.binding.zwave
> 2016-07-04 12:22:44.923 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - [org.eclipse.smarthome.core.thing.binding.ThingHandler] - org.openhab.binding.zwave
> 2016-07-04 12:22:44.925 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - [org.eclipse.smarthome.config.core.status.ConfigStatusProvider] - org.openhab.binding.zwave
> 2016-07-04 12:22:44.953 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - [org.eclipse.smarthome.core.thing.binding.ThingHandler] - org.openhab.binding.zwave
> 2016-07-04 12:22:44.954 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTED - org.openhab.binding.zwave
> 2016-07-04 12:22:45.393 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.sitemap'
> 2016-07-04 12:22:45.461 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rrd4j.persist'
> 2016-07-04 12:22:45.500 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mysql.persist'
> 2016-07-04 12:22:45.513 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test.rules'
> 2016-07-04 12:22:45.514 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
> 2016-07-04 12:22:45.520 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
> 2016-07-04 12:22:45.696 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'systeminfo.items'
> 2016-07-04 12:22:45.745 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'test.items'
> 2016-07-04 12:22:45.790 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'ntp.items'

And, I still see the intermittent startup behavior. Not sure where this leaves us…

[marcel_verpaalen (Marcel)]

@chris

What other bindings are you running? Is it just ZWave that doesn’t start, or are others unreliable as well?

I experience the same with MAX! binding… most restarts no initiation of the things

I’m àlso seeing plenty of

2016-07-05 00:45:40.977 [DEBUG] [c.c.QueueingThreadPoolExecutor:174  ] - Executing queued task of thread pool 'items'.
2016-07-05 00:45:40.977 [DEBUG] [c.c.QueueingThreadPoolExecutor:174  ] - Executing queued task of thread pool 'items'.
2016-07-05 00:45:42.978 [DEBUG] [c.c.QueueingThreadPoolExecutor:191  ] - Queue for thread pool 'items' fully processed - terminating queue thread.

lines… not sure if that is anything related. I don’t recall seeing this before

[chris (Chris Jackson)]

@marcel_verpaalen

I experience the same with MAX! binding… most restarts no initiation of the things

Thanks - at least it’s not just ZWave (although I’m sure that’s no consolation to you).

[mhilbush (Mark)]

@chris No luck with last night’s build. Out of about 10 restarts, in 4 of them the binding did not start successfully.

I did see that there’s a new exception occurring in this build. Out of the 10 restarts, I saw this exception on 2 of the restarts. However, in the 2 cases where this exception occurred, the binding started successfully.

Issue: Circular dependency in services

[chris (Chris Jackson)]

Yes - I saw this new issue . I probably won’t get to do much if any testing today unfortunately…

[mhilbush (Mark)]

@chris

What other bindings are you running? Is it just ZWave that doesn’t start, or are others unreliable as well?

During my testing this morning, there was at least one case where the Systeminfo binding did not initialize.

[chris (Chris Jackson)]

I managed to do some testing with the latest OH2 runtime tonight - ZWave starts occasionally, as do the other bindings I’m currently running, but both are starting unreliably .

[mhilbush (Mark)]

I installed build #399 this morning on two systems. The startup looks much, much cleaner.

Unfortunately, I am still seeing frequent cases where bindings do not initialize as described by me here:

Binding not starting consistently since 6/19 build

Good suggestion, @chris, @Kai . As a first step, I’m retitling this thread, removing the zwave tag, and summarizing the behavior that I’m seeing. This behavior started with the 6/19 build, and continues through the most current build. At the time I was installing builds on almost a daily basis. This behavior did not occur in the 6/17 and prior builds (I think I skipped installing the 6/18 build, so I don’t know about that one). Here’s the summary of what I’m seeing: Start openhab. First…

And by @chris here:

Binding not starting consistently since 6/19 build

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.bindin…

I’ve seen this occur with the zwave and systeminfo bindings. Others above have reported the behavior with other bindings. I noticed this behavior for the first time in the 6/19 build, although it might’ve been there a little before that and I never noticed it.

I wonder if there were any changes in the mid-June timeframe that might’ve introduced this as a side-effect? It looked like there were a couple commits related to initialization in that timeframe. But, honestly, I don’t know enough about how things work, so take that with a grain of salt.

[chris (Chris Jackson)]

@mhilbush did you also delete the userdata folder (or at least the mapdb folder) and add back all your things? This also seems to be required (at least by me and another user).

[mhilbush (Mark)]

I deleted tmp and cache, but not mapdb. Deleting mapdb will be painful on one of my systems as I have 25+ devices… Ouch.