Binding not starting consistently since 6/19 build

mhilbush · June 20, 2016, 1:56pm

I’m seeing some odd behavior at startup in the last 2 nightly builds (6/19 and 6/20).

When starting OH2, the zwave binding starts up, but it doesn’t start it’s discovery process. If I stop and restart OH2, it eventually works. Sometimes it takes a couple restarts. I have a log file that shows the behavior, but I think it’s too long to post here. I can email it to you, if that’s ok.

I see this behavior happening on two separate systems, one of which was a clean install of the 6/20 nightly build. I did not see this behavior in any of the builds from 6/17 or before.

I’m also see a ESH Framework exception at startup, which started with the 6/19 build and also occurs in the 6/20 build. There’s an old ESH issue that looks that looks similar to this. Not sure if this could be related.
https://github.com/eclipse/smarthome/issues/870

And here’s what I’m seeing.

2016-06-20 09:33:41.776 [ERROR] [org.eclipse.smarthome.model.script  ] - [org.eclipse.smarthome.action.transformation.action(90)] Circular reference detected, getService returning null
2016-06-20 09:33:41.835 [WARN ] [org.eclipse.smarthome.model.script  ] - FrameworkEvent WARNING - org.eclipse.smarthome.model.script
org.osgi.framework.ServiceException: org.apache.felix.scr.impl.manager.SingleComponentManager.getService() returned a null service object
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:232)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:496)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:619)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.osgi.util.tracker.ServiceTracker.addingService(ServiceTracker.java:414)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:870)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.trackInitial(AbstractTracked.java:183)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.ServiceTracker.open(ServiceTracker.java:318)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.ServiceTracker.open(ServiceTracker.java:261)[org.osgi.core-6.0.0.jar:]
	at org.eclipse.smarthome.model.script.internal.ScriptActivator.start(ScriptActivator.java:38)
	at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:771)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:1)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at java.security.AccessController.doPrivileged(Native Method)[:1.8.0_91]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.startActivator(BundleContextImpl.java:764)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.start(BundleContextImpl.java:721)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.startWorker0(EquinoxBundle.java:936)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxBundle$EquinoxModule.startWorker(EquinoxBundle.java:319)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.Module.doStart(Module.java:571)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.Module.start(Module.java:439)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.util.SecureAction.start(SecureAction.java:454)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.hooks.EclipseLazyStarter.postFindLocalClass(EclipseLazyStarter.java:107)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.classpath.ClasspathManager.findLocalClass(ClasspathManager.java:531)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.ModuleClassLoader.findLocalClass(ModuleClassLoader.java:324)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:320)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:395)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:345)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:337)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.ModuleClassLoader.loadClass(ModuleClassLoader.java:160)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at java.lang.ClassLoader.loadClass(ClassLoader.java:357)[:1.8.0_91]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.loadClass(EquinoxBundle.java:568)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.initDependencyManagers(AbstractComponentManager.java:952)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.collectDependencies(AbstractComponentManager.java:980)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:812)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:774)[34:org.apache.felix.scr:2.0.2]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:212)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at java.security.AccessController.doPrivileged(Native Method)[:1.8.0_91]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:210)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:496)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:619)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at com.eclipsesource.jaxrs.publisher.internal.ResourceTracker.addingService(ResourceTracker.java:39)[12:com.eclipsesource.jaxrs.publisher:5.3.1.201602281253]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:870)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:229)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:901)[org.osgi.core-6.0.0.jar:]
	at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:914)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:869)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:857)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:133)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:915)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:715)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:399)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.config.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:676)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:339)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:360)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.Activator.access$000(Activator.java:53)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:260)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.utils.extender.AbstractExtender.createExtension(AbstractExtender.java:259)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.utils.extender.AbstractExtender.modifiedBundle(AbstractExtender.java:232)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.utils.extender.AbstractExtender.addingBundle(AbstractExtender.java:192)[34:org.apache.felix.scr:2.0.2]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerAdding(BundleTracker.java:469)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerAdding(BundleTracker.java:415)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:229)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:444)[org.osgi.core-6.0.0.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:902)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:165)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:75)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:67)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:102)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.Module.publishEvent(Module.java:466)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.Module.doStart(Module.java:538)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.Module.start(Module.java:439)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.util.SecureAction.start(SecureAction.java:454)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.hooks.EclipseLazyStarter.postFindLocalClass(EclipseLazyStarter.java:107)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.classpath.ClasspathManager.findLocalClass(ClasspathManager.java:531)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.ModuleClassLoader.findLocalClass(ModuleClassLoader.java:324)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:320)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.sources.SingleSourcePackage.loadClass(SingleSourcePackage.java:36)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:391)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:345)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:337)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.ModuleClassLoader.loadClass(ModuleClassLoader.java:160)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at java.lang.ClassLoader.loadClass(ClassLoader.java:357)[:1.8.0_91]
	at org.eclipse.smarthome.model.rule.RulesStandaloneSetupGenerated.createInjectorAndDoEMFRegistration(RulesStandaloneSetupGenerated.java:21)
	at org.eclipse.smarthome.model.rule.RulesStandaloneSetup.doSetup(RulesStandaloneSetup.java:22)
	at org.eclipse.smarthome.model.rule.runtime.internal.RuleRuntimeActivator.activate(RuleRuntimeActivator.java:33)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_91]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_91]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_91]
	at java.lang.reflect.Method.invoke(Method.java:498)[:1.8.0_91]
	at org.apache.felix.scr.impl.helper.BaseMethod.invokeMethod(BaseMethod.java:222)
	at org.apache.felix.scr.impl.helper.BaseMethod.access$500(BaseMethod.java:37)
	at org.apache.felix.scr.impl.helper.BaseMethod$Resolved.invoke(BaseMethod.java:615)
	at org.apache.felix.scr.impl.helper.BaseMethod.invoke(BaseMethod.java:499)
	at org.apache.felix.scr.impl.helper.ActivateMethod.invoke(ActivateMethod.java:295)
	at org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:302)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:113)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:866)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:833)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:774)[34:org.apache.felix.scr:2.0.2]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:212)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at java.security.AccessController.doPrivileged(Native Method)[:1.8.0_91]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:210)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:496)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:619)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at com.eclipsesource.jaxrs.publisher.internal.ResourceTracker.addingService(ResourceTracker.java:39)[12:com.eclipsesource.jaxrs.publisher:5.3.1.201602281253]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:870)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:229)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:901)[org.osgi.core-6.0.0.jar:]
	at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:914)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:869)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:857)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:133)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:915)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:715)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:399)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.config.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:676)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:339)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:360)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.Activator.access$000(Activator.java:53)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:260)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.utils.extender.AbstractExtender.createExtension(AbstractExtender.java:259)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.utils.extender.AbstractExtender.modifiedBundle(AbstractExtender.java:232)[34:org.apache.felix.scr:2.0.2]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:482)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:415)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:444)[org.osgi.core-6.0.0.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:902)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:165)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:75)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:67)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:102)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.Module.publishEvent(Module.java:466)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.Module.start(Module.java:457)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1582)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1562)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1533)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1476)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]

Thanks.

chris · June 20, 2016, 2:14pm

I don’t see anything in the logs here about ZWave at all so I’m afraid I can’t really comment on what the binding is doing. I would suspect that the issue might be elsewhere rather than a specific problem with zwave…

I would suggest maybe trying a completely fresh install to see if that sorts itself out…

mhilbush · June 20, 2016, 2:51pm

I installed last night’s build (OH and HABmin) and did a completely clean install. I have just the zwave binding installed. I installed the zwave binding by putting it in addons.cfg, not through the UI. There are two nodes configured on the zwave stick.

At startup, I see this, then nothing. It may take a couple restarts of OH for the discover process to occur.

2016-06-20 10:38:38.058 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2016-06-20 10:38:39.731 [INFO ] [ore.internal.i18n.LocaleProviderImpl] - LOCALE: no language is set, keep old: en_US
2016-06-20 10:38:39.738 [INFO ] [ore.internal.i18n.LocaleProviderImpl] - LOCALE: no language is set, keep old: en_US
2016-06-20 10:38:43.574 [ERROR] [org.eclipse.smarthome.model.script  ] - [org.eclipse.smarthome.action.transformation.action(89)] Circular reference detected, getService returning null
2016-06-20 10:38:43.635 [WARN ] [org.eclipse.smarthome.model.script  ] - FrameworkEvent WARNING - org.eclipse.smarthome.model.script
org.osgi.framework.ServiceException: org.apache.felix.scr.impl.manager.SingleComponentManager.getService() returned a null service object
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:232)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:496)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:619)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.osgi.util.tracker.ServiceTracker.addingService(ServiceTracker.java:414)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:870)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.trackInitial(AbstractTracked.java:183)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.ServiceTracker.open(ServiceTracker.java:318)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.ServiceTracker.open(ServiceTracker.java:261)[org.osgi.core-6.0.0.jar:]
	at org.eclipse.smarthome.model.script.internal.ScriptActivator.start(ScriptActivator.java:38)
	at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:771)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:1)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at java.security.AccessController.doPrivileged(Native Method)[:1.8.0_91]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.startActivator(BundleContextImpl.java:764)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.start(BundleContextImpl.java:721)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.startWorker0(EquinoxBundle.java:936)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxBundle$EquinoxModule.startWorker(EquinoxBundle.java:319)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.Module.doStart(Module.java:571)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.Module.start(Module.java:439)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.util.SecureAction.start(SecureAction.java:454)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.hooks.EclipseLazyStarter.postFindLocalClass(EclipseLazyStarter.java:107)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.classpath.ClasspathManager.findLocalClass(ClasspathManager.java:531)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.ModuleClassLoader.findLocalClass(ModuleClassLoader.java:324)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:320)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:395)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:345)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:337)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.ModuleClassLoader.loadClass(ModuleClassLoader.java:160)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at java.lang.ClassLoader.loadClass(ClassLoader.java:357)[:1.8.0_91]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.loadClass(EquinoxBundle.java:568)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.initDependencyManagers(AbstractComponentManager.java:952)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.collectDependencies(AbstractComponentManager.java:980)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:812)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:774)[34:org.apache.felix.scr:2.0.2]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:212)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at java.security.AccessController.doPrivileged(Native Method)[:1.8.0_91]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:210)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:496)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:619)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at com.eclipsesource.jaxrs.publisher.internal.ResourceTracker.addingService(ResourceTracker.java:39)[12:com.eclipsesource.jaxrs.publisher:5.3.1.201602281253]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:870)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:229)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:901)[org.osgi.core-6.0.0.jar:]
	at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:914)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:869)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:857)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:133)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:915)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:715)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:399)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.config.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:676)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:339)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:360)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.Activator.access$000(Activator.java:53)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:260)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.utils.extender.AbstractExtender.createExtension(AbstractExtender.java:259)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.utils.extender.AbstractExtender.modifiedBundle(AbstractExtender.java:232)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.utils.extender.AbstractExtender.addingBundle(AbstractExtender.java:192)[34:org.apache.felix.scr:2.0.2]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerAdding(BundleTracker.java:469)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerAdding(BundleTracker.java:415)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:229)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:444)[org.osgi.core-6.0.0.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:902)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:165)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:75)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:67)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:102)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.Module.publishEvent(Module.java:466)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.Module.doStart(Module.java:538)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.Module.start(Module.java:439)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.util.SecureAction.start(SecureAction.java:454)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.hooks.EclipseLazyStarter.postFindLocalClass(EclipseLazyStarter.java:107)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.classpath.ClasspathManager.findLocalClass(ClasspathManager.java:531)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.ModuleClassLoader.findLocalClass(ModuleClassLoader.java:324)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:320)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.sources.SingleSourcePackage.loadClass(SingleSourcePackage.java:36)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:391)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:345)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:337)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.loader.ModuleClassLoader.loadClass(ModuleClassLoader.java:160)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at java.lang.ClassLoader.loadClass(ClassLoader.java:357)[:1.8.0_91]
	at org.eclipse.smarthome.model.rule.RulesStandaloneSetupGenerated.createInjectorAndDoEMFRegistration(RulesStandaloneSetupGenerated.java:21)
	at org.eclipse.smarthome.model.rule.RulesStandaloneSetup.doSetup(RulesStandaloneSetup.java:22)
	at org.eclipse.smarthome.model.rule.runtime.internal.RuleRuntimeActivator.activate(RuleRuntimeActivator.java:33)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)[:1.8.0_91]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)[:1.8.0_91]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_91]
	at java.lang.reflect.Method.invoke(Method.java:498)[:1.8.0_91]
	at org.apache.felix.scr.impl.helper.BaseMethod.invokeMethod(BaseMethod.java:222)
	at org.apache.felix.scr.impl.helper.BaseMethod.access$500(BaseMethod.java:37)
	at org.apache.felix.scr.impl.helper.BaseMethod$Resolved.invoke(BaseMethod.java:615)
	at org.apache.felix.scr.impl.helper.BaseMethod.invoke(BaseMethod.java:499)
	at org.apache.felix.scr.impl.helper.ActivateMethod.invoke(ActivateMethod.java:295)
	at org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:302)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:113)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:866)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:833)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:774)[34:org.apache.felix.scr:2.0.2]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:212)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at java.security.AccessController.doPrivileged(Native Method)[:1.8.0_91]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:210)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:496)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:619)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at com.eclipsesource.jaxrs.publisher.internal.ResourceTracker.addingService(ResourceTracker.java:39)[12:com.eclipsesource.jaxrs.publisher:5.3.1.201602281253]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:941)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.ServiceTracker$Tracked.customizerAdding(ServiceTracker.java:870)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.trackAdding(AbstractTracked.java:256)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:229)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.ServiceTracker$Tracked.serviceChanged(ServiceTracker.java:901)[org.osgi.core-6.0.0.jar:]
	at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:109)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:914)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:862)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:801)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:127)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:225)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.registerService(BundleContextImpl.java:464)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:869)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager$3.register(AbstractComponentManager.java:857)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.RegistrationManager.changeRegistration(RegistrationManager.java:133)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.registerService(AbstractComponentManager.java:915)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.activateInternal(AbstractComponentManager.java:715)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.manager.AbstractComponentManager.enable(AbstractComponentManager.java:399)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.config.ConfigurableComponentHolder.enableComponents(ConfigurableComponentHolder.java:676)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.BundleComponentActivator.initialEnable(BundleComponentActivator.java:339)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.Activator.loadComponents(Activator.java:360)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.Activator.access$000(Activator.java:53)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.scr.impl.Activator$ScrExtension.start(Activator.java:260)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.utils.extender.AbstractExtender.createExtension(AbstractExtender.java:259)[34:org.apache.felix.scr:2.0.2]
	at org.apache.felix.utils.extender.AbstractExtender.modifiedBundle(AbstractExtender.java:232)[34:org.apache.felix.scr:2.0.2]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:482)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.BundleTracker$Tracked.customizerModified(BundleTracker.java:415)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.AbstractTracked.track(AbstractTracked.java:232)[org.osgi.core-6.0.0.jar:]
	at org.osgi.util.tracker.BundleTracker$Tracked.bundleChanged(BundleTracker.java:444)[org.osgi.core-6.0.0.jar:]
	at org.eclipse.osgi.internal.framework.BundleContextImpl.dispatchEvent(BundleContextImpl.java:902)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEventPrivileged(EquinoxEventPublisher.java:165)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:75)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxEventPublisher.publishBundleEvent(EquinoxEventPublisher.java:67)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor.publishModuleEvent(EquinoxContainerAdaptor.java:102)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.Module.publishEvent(Module.java:466)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.Module.start(Module.java:457)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1582)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1562)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1533)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1476)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:340)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
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
2016-06-20 10:38:51.449 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2016-06-20 10:38:51.493 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app

chris · June 20, 2016, 2:58pm

This should normally happen when the binding starts, but please remember that the binding doesn’t start when OH starts. There are a number of processes that occur first, and the binding only gets started by the framework once these have completed.

In the first log, there is nothing showing the the ZWave binding is starting - not even that the XML files are loaded. Until the XML files are loaded (which is not done by the ZWave binding - it’s done by the framework) the binding won’t start.

So, I don’t think that discovery not starting is an issue with ZWave - my guess is that one of the many exceptions is causing a more general problem.

chris · June 20, 2016, 3:52pm

I see Kai just reopened the circular reference bug…

Kai · June 20, 2016, 3:59pm

Yeah, because I just saw the same log message on my RPi

mhilbush · June 20, 2016, 4:03pm

Sorry, I thought the org.openhab.binding.zwave debug messages were an indication that the binding had started.

BTW, I’ve seen the handler callback missing exceptions occur again, also starting with the 6/19 build. I’ve not been able to consistently reproduce, so I’m hesitant to open an issue. It also might make sense to wait until the above-mentioned problem is resolved to see if those also go away.

chris · June 20, 2016, 4:06pm

Hmmm - sorry - but there aren’t any in the first log at least - or none that I can find and I did do a search (I copied the log into a file and searched, and there was nothing at all about zwave in the log above ).

mhilbush · June 20, 2016, 4:11pm

I snipped a few lines from what I posted above.

Edit: From what I can tell, there is never a “Initializing zwave thing handler” log message like there is when it starts up cleanly.

   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
    2016-06-20 10:38:51.449 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
    2016-06-20 10:38:51.493 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app> indent preformatted text by 4 spaces

When you say “first log”, were you referring to the one I emailed you?

chris · June 20, 2016, 4:17pm

Ok - clearly we’re looking at different logs as the one at the top of this email is at 09:33 and this snippit seems to be at 10:38…

No - I don’t have access to email at the moment. By “first log” I mean the one you posted right at the top of this thread when you reported the problem and I replied “I don’t see anything in the logs here about ZWave”…

I’m reading this on my phone, so sorry if I’ve missed something.

mhilbush · June 20, 2016, 4:59pm

I’m sorry. Let me try to explain.

In my original post, the debug log was too big to include in the post, so I emailed it to you. It was the email attachment that contained references to the zwave binding. My apologies, as I didn’t realize you didn’t have access to email. The small snippet from the log in my original post was to illustrate the Framework exception just in case that was relevant to the behavior I was seeing.

In my subsequent post, I had done a completely clean install with just the zwave binding. I did this to verify the problem occurred on a clean install (it did), and to remove other bindings from the mix in case they were contributing to the problem (there weren’t). That log is posted above, and is the one that contains entries for the zwave binding.

Edit: In rereading what I wrote above, I’m not trying to suggest that the zwave binding is the cause of the problem.

chris · June 20, 2016, 5:30pm

Ah - ok, sorry, I didn’t realise that. So we were referring to different versions of the same log…

In any case, I think the root of the problem is the Circular reference detected error so I don’t think there’s too much else to look at. Looking at the log you emailed (since I’m home now) it looks fine once the binding starts - ie after this error.

mhilbush · June 20, 2016, 6:37pm

Ok. If the circular reference is the cause, I’ll keep an eye on that and, when fixed, I’ll verify that the intermittent behavior on startup also goes away.

Thanks, and sorry for the confusion.

vespaman · July 1, 2016, 3:16pm

So, I tried to update last week-end, as well as today, and I had to go back to an early june snapshot both times, to get things working again.
Is this what is expected? I think I read somewhere that the “circular problem” could be avoided by trying to restart, but I am not successful in this. The zwave binding starts, but I get lots of (timeout-, sending-, can-) errors, and everything is unusable.

So I’m getting (trunkated headlines);

16:52:51.322 [ERROR] [org.eclipse.smarthome.model.script  ] - [org.eclipse.smarthome.action.transformation.action(85)] Circular reference detected, getService returning null
16:52:51.341 [WARN ] [org.eclipse.smarthome.model.script  ] - FrameworkEvent WARNING - org.eclipse.smarthome.model.script
org.osgi.framework.ServiceException: org.apache.felix.scr.impl.manager.SingleComponentManager.getService() returned a null service object
        at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:232)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]

And:-

16:52:54.020 [ERROR] [ui.habmin.internal.servlet.HABminApp] - Error during HABmin servlet startup
org.osgi.service.http.NamespaceException: alias: '/habmin' is already in use in this or another context
        at org.ops4j.pax.web.service.spi.model.ServerModel.addServletModel(ServerModel.java:130)
        at org.ops4j.pax.web.service.internal.HttpServiceStarted.registerServlet(HttpServiceStarted.java:207)
        at org.ops4j.pax.web.service.internal.HttpServiceStarted.registerResources(HttpServiceStarted.java:258)
        at org.ops4j.pax.web.service.internal.HttpServiceProxy.registerResources(HttpServiceProxy.java:71)
        at org.openhab.ui.habmin.internal.servlet.HABminApp.activate(HABminApp.java:30)

And

16:52:54.382 [ERROR] [org.glassfish.jersey.internal.Errors] - Following issues have been detected: 
WARNING: A resource model has ambiguous (sub-)resource method for HTTP method GET and input mime-types as defined by"@Consumes" and "@Produces" annotations at Java methods public javax.ws.rs.core.Response org.openhab.ui.habmin.internal.services.dashboard.DashboardResource.httpGetDashboards(javax.ws.rs.core.HttpHeaders) and public javax.ws.rs.core.Response org.openhab.ui.habmin.internal.services.dashboard.DashboardResource.httpGetDashboards(javax.ws.rs.core.HttpHeaders) at matching regular expression /habmin/dashboards. These two methods produces and consumes exactly the same mime-types and therefore their invocation as a resource methods will always fail.

chris · July 1, 2016, 4:12pm

None of these errors seem to be related to ZWave… Maybe it’s worth commenting on the Github issue as I suspect given the title of this thread, you might not otherwise get an answer…

mhilbush · July 2, 2016, 10:48am

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 error in the log is the Framework error.

2016-06-20 10:38:43.635 [WARN ] [org.eclipse.smarthome.model.script ] - FrameworkEvent WARNING - org.eclipse.smarthome.model.script
org.osgi.framework.ServiceException: org.apache.felix.scr.impl.manager.SingleComponentManager.getService() returned a null service object
at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:232)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]

Things seem to continue normally after that. Some Things are added, then some Items are added, then the zwave binding is started. In this case, three Things are added – the zwave stick and 2 zwave nodes. Then some ThingHandlers are created for the stick and two nodes, and their state is set to INITIALIZING.

> 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

After that there’s nothing. Initialization of the 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. Why not?

@Override
public void initialize() {
    logger.debug("Initializing ZWave thing handler.");

Any help on this would be much appreciated.

chris · July 2, 2016, 9:22pm

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?

mhilbush · July 2, 2016, 9:56pm

Yeah, it’s very strange, isn’t it? You got a bit further than me in troubleshooting. That’s good. Hopefully, this will lead to a root cause and solution.

MikeD · July 3, 2016, 4:27am

Looks like I might have the same startup issues. I was used to having to start openHAB 2 twice for the RFXCOM binding to start, but following my update to the latest build as of yesterday I also noticed that the zwave binding was not starting reliably every time.

Extract of the log file follows:

2016-07-02 17:09:36.408 [WARN ] [g.dispatch.internal.ConfigDispatcher] - Could not parse line 'paper,basic,rest,classic'
2016-07-02 17:09:36.408 [WARN ] [g.dispatch.internal.ConfigDispatcher] - Could not parse line 'restdocs'
2016-07-02 17:09:36.455 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2016-07-02 17:09:37.656 [ERROR] [org.eclipse.smarthome.model.script  ] - [org.eclipse.smarthome.action.transformation.action(89)] Circular reference detected, getService returning null
2016-07-02 17:09:37.687 [WARN ] [org.eclipse.smarthome.model.script  ] - FrameworkEvent WARNING - org.eclipse.smarthome.model.script
org.osgi.framework.ServiceException: org.apache.felix.scr.impl.manager.SingleComponentManager.getService() returned a null service object
    at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:232)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
    at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:111)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
    at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:45)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:496)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
    at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:461)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
    at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:619)[org.eclipse.osgi-3.10.2.v20150203-1939.jar:]
    at org.osgi.util.tracker.ServiceTracker.addingService(ServiceTracker.java:414)[org.osgi.core-6.0.0.jar:]

This problem is very repeatable if debug log info is required.

chris · July 3, 2016, 8:47am

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

I’m trying to ascertain if this is a ZWave problem, or the framework - I’m reasonably sure it’s ESH, but it seems a bit funny if it’s only ZWave that has a problem. I went through all the recent changes to ZWave last night and can’t see anything that can cause this. I even created a version of ZWave that reverted a number of changes going back to the 19th June when @mhilbush reckons this started, and it didn’t help.

Currently in my production system I can’t start the ZWave binding at all since I “upgraded” last night (it’s currently the only binding installed) - it runs fine in the IDE though.