[SOLVED]JSR223 jython from IDE: cannot find engine

Bernd_Pfrommer · September 28, 2015, 5:27pm

Can’t get the JSR223 engine to find my jython installation (see error below)
I’m trying to run the JSR223 within the IDE. How do I set the classpath there? I was able to set the python.home variable somewhere in Run configurations, and it does seem to run the java vm with the right parameters:

 ps -efa | grep -i jython

pfrommer 25961 15547 65 13:21 pts/10   00:00:09 /usr/lib/jvm/java-8-oracle/bin/java -Dpython.home=/opt/jython -Declipse.ignoreApp=true -Dosgi.clean=true -Dosgi.noShutdown=true -Dlogback.configurationFile=./configurations/logback_debug.xml -Djava.library.path=./lib -Djetty.home=. -Djava.security.auth.login.config=./etc/login.conf -Dorg.quartz.properties=./etc/quartz.properties -Djetty.port=8080 -Djetty.port.ssl=8443 -Dfelix.fileinstall.dir=addons -Dfelix.fileinstall.filter=.*\.jar -Dfelix.fileinstall.active.level=4 -Dfile.encoding=UTF-8 -classpath /home/pfrommer/workspace/.metadata/.plugins/org.eclipse.pde.core/.bundle_pool/plugins/org.eclipse.equinox.launcher_1.3.0.v20120522-1813.jar org.eclipse.equinox.launcher.Main -application  -data /home/pfrommer/workspace/../runtime-org.openhab.runtime.product.product -configuration file:/home/pfrommer/workspace/.metadata/.plugins/org.eclipse.pde.core/openHAB Runtime Custom/ -dev file:/home/pfrommer/workspace/.metadata/.plugins/org.eclipse.pde.core/openHAB Runtime Custom/dev.properties -os linux -ws gtk -arch x86_64 -nl en_US -consoleLog -console

But it still does not find the jython engine. I did create the link from distribution/openhabhome/lib/ to /opt/jython/jython.jar

Here is the error I get:

osgi> osgi> 13:21:29.056 INFO  o.o.c.internal.CoreActivator[:61] - openHAB runtime has been started (v1.8.0).
13:21:29.418 INFO  o.o.c.s.AbstractActiveService[:169] - InsteonPLM has been started
!SESSION 2015-09-28 13:21:26.363 -----------------------------------------------
eclipse.buildId=unknown
java.version=1.8.0_60
java.vendor=Oracle Corporation
BootLoader constants: OS=linux, ARCH=x86_64, WS=gtk, NL=en_US
Framework arguments:  -application 
Command-line arguments:  -application  -data /home/pfrommer/workspace/../runtime-org.openhab.runtime.product.product -dev file:/home/pfrommer/workspace/.metadata/.plugins/org.eclipse.pde.core/openHAB Runtime Custom/dev.properties -os linux -ws gtk -arch x86_64 -consoleLog -console

!ENTRY org.eclipse.equinox.ds 4 0 2015-09-28 13:21:29.495
!MESSAGE Could not bind a reference of component org.openhab.core.itemregistry. The reference is: Reference[name = ItemProvider, interface = org.openhab.core.items.ItemProvider, policy = dynamic, cardinality = 0..n, target = null, bind = addItemProvider, unbind = removeItemProvider]

!ENTRY org.eclipse.equinox.ds 4 0 2015-09-28 13:21:29.498
!MESSAGE Could not bind a reference of component org.openhab.core.itemregistry. The reference is: Reference[name = ItemProvider, interface = org.openhab.core.items.ItemProvider, policy = dynamic, cardinality = 0..n, target = null, bind = addItemProvider, unbind = removeItemProvider]
13:21:29.512 INFO  o.o.c.j.i.e.s.ScriptManager[:58] - Available engines:
13:21:29.514 INFO  o.o.c.j.i.e.s.ScriptManager[:60] - Oracle Nashorn
13:21:29.517 INFO  o.o.c.j.i.e.s.Script[:81] - Loading Script demo.script
13:21:29.517 WARN  o.o.c.j.i.e.s.ScriptManager[:92] - No Engine found for File: demo.script
13:21:29.518 INFO  o.o.c.j.i.e.s.Script[:81] - Loading Script jsr223_demo.py
13:21:29.518 WARN  o.o.c.j.i.e.s.ScriptManager[:92] - No Engine found for File: jsr223_demo.py

Any suggestions what’s going wrong? How can I set the classpath (within the IDE, not a separate script)?

Thanks!
Bernd

steve1 · September 28, 2015, 6:01pm

It appears you need to add the lib/jython.jar file to the classpath. The startup script on the wiki page adds all lib/*.jar files to the classpath before starting OH.

Bernd_Pfrommer · September 28, 2015, 6:23pm

Yes, but how do I add that when running inside the IDE?

steve1 · September 28, 2015, 6:56pm

I haven’t run OH from the IDE (I use remote debugging instead) and I don’t have access to Eclipse at the moment, but a quick Google search gives a couple of possibilities. It looks like the “Bootstrap Entries” in the launch configuration Main tab will allow you to specify classpath entries for the top-level classloader. Another possibility is to set up a custom JRE runtime configuration with a JVM boot classpath option and select the custom JRE configuration in the Main tab of the launcher configuration.

Bernd_Pfrommer · September 28, 2015, 10:33pm

Just putting the name of the jar file into the bootstrap entry did the trick, thank you!

Now I get exceptions that have to do with startup rules being run:

java.lang.reflect.InvocationTargetException
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:497)
	at org.eclipse.equinox.internal.ds.model.ComponentReference.bind(ComponentReference.java:376)
	at org.eclipse.equinox.internal.ds.model.ServiceComponentProp.bindReference(ServiceComponentProp.java:444)
	at org.eclipse.equinox.internal.ds.InstanceProcess.dynamicBind(InstanceProcess.java:416)
	at org.eclipse.equinox.internal.ds.Resolver.getEligible(Resolver.java:334)
	at org.eclipse.equinox.internal.ds.SCRManager.serviceChanged(SCRManager.java:222)
	at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:107)
	at org.eclipse.osgi.framework.internal.core.BundleContextImpl.dispatchEvent(BundleContextImpl.java:861)
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:819)
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:771)
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:130)
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:214)
	at org.eclipse.osgi.framework.internal.core.BundleContextImpl.registerService(BundleContextImpl.java:433)
	at org.eclipse.equinox.internal.ds.InstanceProcess.registerService(InstanceProcess.java:536)
	at org.eclipse.equinox.internal.ds.InstanceProcess.buildComponents(InstanceProcess.java:260)
	at org.eclipse.equinox.internal.ds.Resolver.getEligible(Resolver.java:343)
	at org.eclipse.equinox.internal.ds.SCRManager.serviceChanged(SCRManager.java:222)
	at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:107)
	at org.eclipse.osgi.framework.internal.core.BundleContextImpl.dispatchEvent(BundleContextImpl.java:861)
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:819)
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:771)
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:130)
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:214)
	at org.eclipse.osgi.framework.internal.core.BundleContextImpl.registerService(BundleContextImpl.java:433)
	at org.eclipse.equinox.internal.ds.InstanceProcess.registerService(InstanceProcess.java:536)
	at org.eclipse.equinox.internal.ds.InstanceProcess.buildComponents(InstanceProcess.java:260)
	at org.eclipse.equinox.internal.ds.Resolver.buildNewlySatisfied(Resolver.java:473)
	at org.eclipse.equinox.internal.ds.Resolver.enableComponents(Resolver.java:217)
	at org.eclipse.equinox.internal.ds.SCRManager.startedBundle2(SCRManager.java:657)
	at org.eclipse.equinox.internal.ds.SCRManager.startedBundle(SCRManager.java:578)
	at org.eclipse.equinox.internal.ds.SCRManager.bundleChanged(SCRManager.java:237)
	at org.eclipse.osgi.framework.internal.core.BundleContextImpl.dispatchEvent(BundleContextImpl.java:847)
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)
	at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEventPrivileged(Framework.java:1568)
	at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEvent(Framework.java:1504)
	at org.eclipse.osgi.framework.internal.core.Framework.publishBundleEvent(Framework.java:1499)
	at org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(BundleHost.java:356)
	at org.eclipse.osgi.framework.internal.core.AbstractBundle.start(AbstractBundle.java:300)
	at org.eclipse.osgi.framework.util.SecureAction.start(SecureAction.java:440)
	at org.eclipse.osgi.internal.loader.BundleLoader.setLazyTrigger(BundleLoader.java:263)
	at org.eclipse.core.runtime.internal.adaptor.EclipseLazyStarter.postFindLocalClass(EclipseLazyStarter.java:107)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClass(ClasspathManager.java:469)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.findLocalClass(DefaultClassLoader.java:216)
	at org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:395)
	at org.eclipse.osgi.internal.loader.SingleSourcePackage.loadClass(SingleSourcePackage.java:35)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:452)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:421)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:412)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.loadClass(DefaultClassLoader.java:107)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
	at org.openhab.model.script.internal.ScriptActivator.start(ScriptActivator.java:47)
	at org.eclipse.osgi.framework.internal.core.BundleContextImpl$1.run(BundleContextImpl.java:711)
	at java.security.AccessController.doPrivileged(Native Method)
	at org.eclipse.osgi.framework.internal.core.BundleContextImpl.startActivator(BundleContextImpl.java:702)
	at org.eclipse.osgi.framework.internal.core.BundleContextImpl.start(BundleContextImpl.java:683)
	at org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(BundleHost.java:381)
	at org.eclipse.osgi.framework.internal.core.AbstractBundle.start(AbstractBundle.java:300)
	at org.eclipse.osgi.framework.util.SecureAction.start(SecureAction.java:440)
	at org.eclipse.osgi.internal.loader.BundleLoader.setLazyTrigger(BundleLoader.java:263)
	at org.eclipse.core.runtime.internal.adaptor.EclipseLazyStarter.postFindLocalClass(EclipseLazyStarter.java:107)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClass(ClasspathManager.java:469)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.findLocalClass(DefaultClassLoader.java:216)
	at org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:395)
	at org.eclipse.osgi.internal.loader.SingleSourcePackage.loadClass(SingleSourcePackage.java:35)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:452)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:421)
	at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:412)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.loadClass(DefaultClassLoader.java:107)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
	at org.openhab.core.jsr223.internal.engine.scriptmanager.Script.initializeGeneralGlobals(Script.java:222)
	at org.openhab.core.jsr223.internal.engine.scriptmanager.Script.initializeSciptGlobals(Script.java:99)
	at org.openhab.core.jsr223.internal.engine.scriptmanager.Script.loadScript(Script.java:87)
	at org.openhab.core.jsr223.internal.engine.scriptmanager.Script.<init>(Script.java:76)
	at org.openhab.core.jsr223.internal.engine.scriptmanager.ScriptManager.loadScript(ScriptManager.java:90)
	at org.openhab.core.jsr223.internal.engine.scriptmanager.ScriptManager.loadScripts(ScriptManager.java:79)
	at org.openhab.core.jsr223.internal.engine.scriptmanager.ScriptManager.<init>(ScriptManager.java:68)
	at org.openhab.core.jsr223.internal.engine.Jsr223Engine.activate(Jsr223Engine.java:71)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:497)
	at org.eclipse.equinox.internal.ds.model.ServiceComponent.activate(ServiceComponent.java:235)
	at org.eclipse.equinox.internal.ds.model.ServiceComponentProp.activate(ServiceComponentProp.java:146)
	at org.eclipse.equinox.internal.ds.model.ServiceComponentProp.build(ServiceComponentProp.java:345)
	at org.eclipse.equinox.internal.ds.InstanceProcess.buildComponent(InstanceProcess.java:620)
	at org.eclipse.equinox.internal.ds.InstanceProcess.buildComponents(InstanceProcess.java:197)
	at org.eclipse.equinox.internal.ds.Resolver.getEligible(Resolver.java:343)
	at org.eclipse.equinox.internal.ds.SCRManager.serviceChanged(SCRManager.java:222)
	at org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:107)
	at org.eclipse.osgi.framework.internal.core.BundleContextImpl.dispatchEvent(BundleContextImpl.java:861)
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)
	at org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:819)
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:771)
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:130)
	at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:214)
	at org.eclipse.osgi.framework.internal.core.BundleContextImpl.registerService(BundleContextImpl.java:433)
	at org.eclipse.equinox.internal.ds.InstanceProcess.registerService(InstanceProcess.java:536)
	at org.eclipse.equinox.internal.ds.InstanceProcess.buildComponents(InstanceProcess.java:213)
	at org.eclipse.equinox.internal.ds.Resolver.buildNewlySatisfied(Resolver.java:473)
	at org.eclipse.equinox.internal.ds.Resolver.enableComponents(Resolver.java:217)
	at org.eclipse.equinox.internal.ds.SCRManager.performWork(SCRManager.java:816)
	at org.eclipse.equinox.internal.ds.SCRManager$QueuedJob.dispatch(SCRManager.java:783)
	at org.eclipse.equinox.internal.ds.WorkThread.run(WorkThread.java:89)
	at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.NullPointerException
	at org.openhab.core.jsr223.internal.engine.Jsr223Engine.runStartupRules(Jsr223Engine.java:201)
	at org.openhab.core.jsr223.internal.engine.Jsr223Engine.allItemsChanged(Jsr223Engine.java:116)
	at org.openhab.core.internal.items.ItemRegistryImpl.allItemsChanged(ItemRegistryImpl.java:201)
	at org.openhab.core.internal.items.ItemRegistryImpl.addItemProvider(ItemRegistryImpl.java:138)
	... 113 more

Could be because I return an empty StartupTrigger(), but removing it from the list doesn’t make the error go away.

 def getEventTrigger(self):
        return [
            StartupTrigger(),
            #ChangedEventTrigger("Heating_FF_Child", None, None),
            TimerTrigger("0/50 * * * * ?")
        ]

Couldn’t find any documentation how StartupTrigger() should be used. Does that invoke a method, if yes, which one?

Thanks!

Bernd

steve1 · September 28, 2015, 11:05pm

I haven’t seen that specific error. It looks like you are using StartupTrigger correctly (it is constructing a org.openhab.core.jsr223.internal.shared.StartupTrigger instance, which is a very simple Java trigger class for JSR223 rules). Have you turned on debug (or trace) logging for org.openhab.core.jsr223? That might give some clues about what is happening.

The NPE looks like it could only happen if the scriptManager is null in the Jsr223Engine. Maybe there was an error when it was constructed at bundle activation time?

Bernd_Pfrommer · September 28, 2015, 11:45pm

Script manager seems to be instantiated:

18:14:48.357 INFO o.o.c.j.i.e.s.Script[:81] - Loading Script demo.script
18:14:48.358 WARN o.o.c.j.i.e.s.ScriptManager[:92] - No Engine found for File: demo.script
18:14:48.358 INFO o.o.c.j.i.e.s.Script[:81] - Loading Script jsr223_demo.py
18:14:49.101 INFO o.o.c.j.i.e.s.Script[:86] - EngineName: jython

The timer actually works, I do get callbacks from that:

19:45:00.030 INFO  o.o.c.j.i.e.TimeTriggerJob[:35] - TimeTrigger for rule: org.python.proxies.__builtin__$TestRule$0@3463ff16, scriptName: jsr223_demo.py
yeah
19:45:00.036 INFO  o.o.model.jsr232.TestRule[:111] - available actions: [Exec, Transformation, Ping, HTTP, Audio]

Trying to find out how to switch on debug logging…

Bernd_Pfrommer · September 29, 2015, 12:40am

Got no new insight from the debug log.

I cleaned up my items files though, and now I no longer get the strange exception above. Weird. It’ll probably come back in some other form…

For now case closed, thanks again!

Bernd_Pfrommer · September 30, 2015, 1:36pm

I discovered that I had caught the exception, that’s why I didn’t see it in the log anymore.
And of course it is still happening, and a whole lot of other things are broken too once that exception throws.

The problem is that indeed scriptManager is null. This is due to a cyclic reference:

public void activate() {
		if (activated)
			return;

		activated = true;

		try {
			scheduler = StdSchedulerFactory.getDefaultScheduler();
		} catch (SchedulerException e) {
			logger.error("initializing scheduler throws exception", e);
		}

		logger.debug("activate()");

		triggerManager = new RuleTriggerManager(scheduler);
		scriptManager = new ScriptManager(triggerManager, itemRegistry);

		if (!isEnabled()) {
			logger.info("Jsr232 engine is disabled.");
			return;
		}

		logger.debug("Started Jsr232 engine");

		// register us on all items which are already available in the registry
		for (Item item : itemRegistry.getItems()) {
			internalItemAdded(item);
		}

		runStartupRules();
	}

within the constructor of the ScriptManager() a lot of work is done if an executable script is found. ItemProviders etc are instantiated. I think one of the ItemProviders is the jsr223 engine itself, and in the context of this, the jsr engine’s runStartupRules() is invoked, although the ScriptManager() constructor has not completed running, and so the scriptManager reference is null, causing the NPE. A whole bunch of other ItemProviders aren’t present yet either,

08:20:10.043 [DEBUG] [o.o.c.i.items.ItemRegistryImpl:137  ] - Item provider 'GenericItemProvider' has been added.
08:20:10.273 [INFO ] [c.internal.ModelRepositoryImpl:80   ] - Loading model 'insteonplm.items'
08:20:10.333 [DEBUG] [i.internal.GenericItemProvider:154  ] - Processing binding configs for items from model 'insteonplm.items'
08:20:10.333 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatCoolPoint' of type 'Number'

At the root of the problem was that the jsr223 engine was starting too soon. I had set it to runlevel “default”. Bumping it to 5 (the default is 4) solved the problem.

steve1 · September 30, 2015, 2:42pm

I don’t see a circular dependency between Jsr223Engine and ScriptManager, but I do see a race condition. The Jsr223Engine activate method sets the activated flag at the beginning of the method when it should set it at the end. If there is a callback to Jsr223Engine.allItemsChanged from another thread during the engine activation, the “activated” guard may pass while the activation is in progress and the ScriptManager construction may not have been completed.

I’m wondering if there is another bug here. For items that already existed prior to the Jsr223Engine.allItemsChanged callback, it looks like there would be multiple Jsr223Engine state change callbacks registered. Could this result in duplicate rule invocations for the same state change? When I have some time, I’ll do some investigation.

Bernd_Pfrommer · September 30, 2015, 9:17pm

Here is the stack trace from the exception itself. Looks circular to me
rather than a race condition, but see for yourself:

java.lang.NullPointerException
at
org.openhab.core.jsr223.internal.engine.Jsr223Engine.runStartupRules(Jsr223Engine.java:201)
at
org.openhab.core.jsr223.internal.engine.Jsr223Engine.allItemsChanged(Jsr223Engine.java:116)
at
org.openhab.core.internal.items.ItemRegistryImpl.allItemsChanged(ItemRegistryImpl.java:201)
at
org.openhab.core.internal.items.ItemRegistryImpl.addItemProvider(ItemRegistryImpl.java:138)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at
org.eclipse.equinox.internal.ds.model.ComponentReference.bind(ComponentReference.java:376)
at
org.eclipse.equinox.internal.ds.model.ServiceComponentProp.bindReference(ServiceComponentProp.java:444)
at
org.eclipse.equinox.internal.ds.InstanceProcess.dynamicBind(InstanceProcess.java:416)
at org.eclipse.equinox.internal.ds.Resolver.getEligible(Resolver.java:334)
at
org.eclipse.equinox.internal.ds.SCRManager.serviceChanged(SCRManager.java:222)
at
org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:107)
at
org.eclipse.osgi.framework.internal.core.BundleContextImpl.dispatchEvent(BundleContextImpl.java:861)
at
org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)
at
org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)
at
org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:819)
at
org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:771)
at
org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:130)
at
org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:214)
at
org.eclipse.osgi.framework.internal.core.BundleContextImpl.registerService(BundleContextImpl.java:433)
at
org.eclipse.equinox.internal.ds.InstanceProcess.registerService(InstanceProcess.java:536)
at
org.eclipse.equinox.internal.ds.InstanceProcess.buildComponents(InstanceProcess.java:260)
at org.eclipse.equinox.internal.ds.Resolver.getEligible(Resolver.java:343)
at
org.eclipse.equinox.internal.ds.SCRManager.serviceChanged(SCRManager.java:222)
at
org.eclipse.osgi.internal.serviceregistry.FilteredServiceListener.serviceChanged(FilteredServiceListener.java:107)
at
org.eclipse.osgi.framework.internal.core.BundleContextImpl.dispatchEvent(BundleContextImpl.java:861)
at
org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)
at
org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)
at
org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEventPrivileged(ServiceRegistry.java:819)
at
org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.publishServiceEvent(ServiceRegistry.java:771)
at
org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.register(ServiceRegistrationImpl.java:130)
at
org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.registerService(ServiceRegistry.java:214)
at
org.eclipse.osgi.framework.internal.core.BundleContextImpl.registerService(BundleContextImpl.java:433)
at
org.eclipse.equinox.internal.ds.InstanceProcess.registerService(InstanceProcess.java:536)
at
org.eclipse.equinox.internal.ds.InstanceProcess.buildComponents(InstanceProcess.java:260)
at
org.eclipse.equinox.internal.ds.Resolver.buildNewlySatisfied(Resolver.java:473)
at
org.eclipse.equinox.internal.ds.Resolver.enableComponents(Resolver.java:217)
at
org.eclipse.equinox.internal.ds.SCRManager.startedBundle2(SCRManager.java:657)
at
org.eclipse.equinox.internal.ds.SCRManager.startedBundle(SCRManager.java:578)
at
org.eclipse.equinox.internal.ds.SCRManager.bundleChanged(SCRManager.java:237)
at
org.eclipse.osgi.framework.internal.core.BundleContextImpl.dispatchEvent(BundleContextImpl.java:847)
at
org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:230)
at
org.eclipse.osgi.framework.eventmgr.ListenerQueue.dispatchEventSynchronous(ListenerQueue.java:148)
at
org.eclipse.osgi.framework.internal.core.Framework.publishBundleEventPrivileged(Framework.java:1568)
at
org.eclipse.osgi.framework.internal.core.Framework.publishBundleEvent(Framework.java:1504)
at
org.eclipse.osgi.framework.internal.core.Framework.publishBundleEvent(Framework.java:1499)
at
org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(BundleHost.java:356)
at
org.eclipse.osgi.framework.internal.core.AbstractBundle.start(AbstractBundle.java:300)
at org.eclipse.osgi.framework.util.SecureAction.start(SecureAction.java:440)
at
org.eclipse.osgi.internal.loader.BundleLoader.setLazyTrigger(BundleLoader.java:263)
at
org.eclipse.core.runtime.internal.adaptor.EclipseLazyStarter.postFindLocalClass(EclipseLazyStarter.java:107)
at
org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClass(ClasspathManager.java:469)
at
org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.findLocalClass(DefaultClassLoader.java:216)
at
org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:395)
at
org.eclipse.osgi.internal.loader.SingleSourcePackage.loadClass(SingleSourcePackage.java:35)
at
org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:452)
at
org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:421)
at
org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:412)
at
org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.loadClass(DefaultClassLoader.java:107)
at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
at
org.openhab.model.script.internal.ScriptActivator.start(ScriptActivator.java:47)
at
org.eclipse.osgi.framework.internal.core.BundleContextImpl$1.run(BundleContextImpl.java:711)
at java.security.AccessController.doPrivileged(Native Method)
at
org.eclipse.osgi.framework.internal.core.BundleContextImpl.startActivator(BundleContextImpl.java:702)
at
org.eclipse.osgi.framework.internal.core.BundleContextImpl.start(BundleContextImpl.java:683)
at
org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(BundleHost.java:381)
at
org.eclipse.osgi.framework.internal.core.AbstractBundle.start(AbstractBundle.java:300)
at org.eclipse.osgi.framework.util.SecureAction.start(SecureAction.java:440)
at
org.eclipse.osgi.internal.loader.BundleLoader.setLazyTrigger(BundleLoader.java:263)
at
org.eclipse.core.runtime.internal.adaptor.EclipseLazyStarter.postFindLocalClass(EclipseLazyStarter.java:107)
at
org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClass(ClasspathManager.java:469)
at
org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.findLocalClass(DefaultClassLoader.java:216)
at
org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:395)
at
org.eclipse.osgi.internal.loader.SingleSourcePackage.loadClass(SingleSourcePackage.java:35)
at
org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:452)
at
org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:421)
at
org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:412)
at
org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.loadClass(DefaultClassLoader.java:107)
at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
at
org.openhab.core.jsr223.internal.engine.scriptmanager.Script.initializeGeneralGlobals(Script.java:222)
at
org.openhab.core.jsr223.internal.engine.scriptmanager.Script.initializeSciptGlobals(Script.java:99)
at
org.openhab.core.jsr223.internal.engine.scriptmanager.Script.loadScript(Script.java:87)
at
org.openhab.core.jsr223.internal.engine.scriptmanager.Script.(Script.java:76)
at
org.openhab.core.jsr223.internal.engine.scriptmanager.ScriptManager.loadScript(ScriptManager.java:90)
at
org.openhab.core.jsr223.internal.engine.scriptmanager.ScriptManager.loadScripts(ScriptManager.java:79)
at
org.openhab.core.jsr223.internal.engine.scriptmanager.ScriptManager.(ScriptManager.java:68)
at
org.openhab.core.jsr223.internal.engine.Jsr223Engine.activate(Jsr223Engine.java:71)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at
org.eclipse.equinox.internal.ds.model.ServiceComponent.activate(ServiceComponent.java:235)
at
org.eclipse.equinox.internal.ds.model.ServiceComponentProp.activate(ServiceComponentProp.java:146)
at
org.eclipse.equinox.internal.ds.model.ServiceComponentProp.build(ServiceComponentProp.java:345)
at
org.eclipse.equinox.internal.ds.InstanceProcess.buildComponent(InstanceProcess.java:620)
at
org.eclipse.equinox.internal.ds.InstanceProcess.buildComponents(InstanceProcess.java:197)
at
org.eclipse.equinox.internal.ds.Resolver.buildNewlySatisfied(Resolver.java:473)
at
org.eclipse.equinox.internal.ds.Resolver.enableComponents(Resolver.java:217)
at
org.eclipse.equinox.internal.ds.SCRManager.performWork(SCRManager.java:816)
at
org.eclipse.equinox.internal.ds.SCRManager$QueuedJob.dispatch(SCRManager.java:783)
at org.eclipse.equinox.internal.ds.WorkThread.run(WorkThread.java:89)
at java.lang.Thread.run(Thread.java:745)

steve1 · October 1, 2015, 12:56am

I agree. The stacktrace indicates a very indirect circular dependency. It seems to start at…

org.openhab.core.jsr223.internal.engine.scriptmanager.Script.initializeGeneralGlobals(Script.java:222)

This loads the BusEvent class. From there, the dependency on the ScriptActivator indirectly causes a class load of ModelRepository. After, that I don’t yet see what eventually triggers the ItemProvider injection to the ItemRegistry which calls back into the Jsr223Engine.

FIxing the activation guard would avoid the immediate problem but it might just defer the problem until later if the Jsr223Engine doesn’t get another allItemsChanged callback.

This seems like a serious bug. The BusEvent-related change in the Script class was made after 1.7.1 was released. I’m running 1.7.1 and haven’t seen this problem. I think you should enter an issue for the bug so it can be fixed before the next release.

Bernd_Pfrommer · October 1, 2015, 1:12am

So why does the whole thing not happen if the jsr233 starts later?
Everything goes smoothly if I just bump the runlevel to 5, and the rest of
the system starts at runlevel 4.

Bernd_Pfrommer · October 1, 2015, 1:13am

And BTW, I documented the problem in the wiki so other people to don’t
waste a whole day tracking this down (pat on shoulder).

I submitted an issue on this. We have currently 495 issues open…

steve1 · October 1, 2015, 2:04am

I’d guess it’s because the ItemProvider injection into the ItemRegistry and the related callbacks have already happened by the time the Jsr223Engine is activated.