Binding not starting consistently since 6/19 build

[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.

[chris (Chris Jackson)]

@mhilbush

Deleting mapdb will be painful on one of my systems as I have 25

Yes - I share this pain, but unfortunately I had to remove mine for it to work.

[MikeD (Mike Dilger)]

Hi guys, I should get time tomorrow morning (my time) to update to #399. I plan to follow my normal procedure and hope I don’t have to delete the mapdb folder and then reinstall everything. i will report back with my results asap.

[chris (Chris Jackson)]

Good luck

[mhilbush (Mark)]

So you removed the whole userdata directory, or just mapdb?

On my test system, I just removed the mapdb files from the mapdb directory, along with tmp and cache. On this system I have only a few bindings (zwave, systeminfo, ntp), and a couple zwave nodes, so adding these back was not hard. I’m still seeing the problem, so I guess I’ll do a complete from-scratch install just to rule out anything else.

[chris (Chris Jackson)]

I initially removed the whole userdata folder. The system then started. I then added back in my persistence folders, habmin data etc, and it still worked. I then renamed the mapdb folder and put the old one back in, and it stopped working - I put the ‘new’ mapdb folder back, and it works again.