jsr223 engine throws null pointer exception, breaks system when started at default runlevel within IDE

[berndpfrommer]

If the jsr223 engine plugin is started at the default runlevel, and a script is present (e.g. foo.js is in the scripts directory), the NPE below is thrown, and the system goes into an unusable state (items are no longer found etc).

The reason seems to be a circular reference, the details of which I don't comprehend. Just fixing the NPE (for instance by deferring setting "active" to true at a later time) does not do the trick (I tried), the system will still be in a broken state as far as item discovery is concerned.

The workaround is to bump the runlevel to 5 (with all the other bundles starting at runlevel 4). Somehow that does the trick. Another (hardly practical) workaround is to only copy the scripts into place after startup.

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)

[lewie]

I think I have this Problem sometimes too, but it can not reproduce.

Did you deactivate lazy loading in Manifest.mf for testing? Delete Bundle-ActivationPolicy: lazy or in Eclipse: 'Acticate this plug-in when one of its classes is loaded'.

Rgds Helmut

[berndpfrommer]

I set back the runlevel to 4 in order to trigger the error. Then I unchecked "Activate this plug-in when one of its classes is loaded". That does indeed modify the MANIFEST.MF file, and remove the Bundle-ActivationPolicy: lazy from the file. However, it makes no difference, it still throws an identical exception.

[steve-bate]

I'm trying to reproduce the problem while running from Eclipse (vanilla configuration + Jython) but everything appears to work well. I see the output from the Jython rule in the console. I've tried both Run and Debug configurations, several times each.

[lewie]

@berndpfrommer , please can you tell us more about the OH environment?

• OH-Version, loaded Bundles and the first Events sended of your scriptcode in jsr223
• Architecture and type of Processor (Raspi, Arm, VM, Intel....)
• Operating System and Ram
• Java Version

It seems to be a class-loading Problem resulted by wrong loading order (Events be sent before it can be processed by OH) , but why? Is it really a timing/order or eventually another reason?

While testing a new JDBC Bundle, I started OH hundred times last(next) days, all Tests are javascript in jsr223. In this testing environment I only have jsr223 Errors, when a Item is uninitialized or undefined, similar to xtext. Now I had written a script early loading with 'StartupTrigger'.... will see.

Rgds Helmut

supplement: For using nashorn/javascript, I in principle have to start OH with java directive -Dorg.osgi.framework.bundle.parent=ext, which is future java 8 standard class-loading setting. You should test this, too.

[berndpfrommer]

I running my private copy of openhab (I develop the insteonplm binding). The last time I merged in the main trunk was around September 21st:

commit 4e26448e13edd04368398b771379669554df0b75
Merge: 1633343 e2d0269
Author: Chris Jackson 
Date:   Mon Sep 21 22:26:23 2015 +0100
    Merge pull request #3192 from cdjackson/zwave-database_updates

    Fix whitespace error

Hardware is an intel i7, 32G memory OS is ubuntu 14.04 Java version is oracle 8:

 java -version
java version "1.8.0_60"
Java(TM) SE Runtime Environment (build 1.8.0_60-b27)
Java HotSpot(TM) 64-Bit Server VM (build 25.60-b23, mixed mode)

The file foo.py has this content:

class TestRule(Rule):
    def __init__(self):
        self.logger = oh.getLogger("TestRule")
    def getEventTrigger(self):
        return [
            StartupTrigger(),
            ChangedEventTrigger("gMotionDimmers", None, None),
            ChangedEventTrigger("officeLight", None, None),
#           TimerTrigger("0/50 * * * * ?")
        ]
    def execute(self, event):
        self.logger.debug("event received {}", event)
        if (event.getTriggerType() == TriggerType.TIMER):
            self.logger.debug("got timer event!")
        elif (event.getTriggerType() == TriggerType.CHANGE):
            self.logger.debug("got change event!")
        elif (event.getTriggerType() == TriggerType.UPDATE):
            self.logger.debug("got update event!");
        elif (event.getTriggerType() == TriggerType.STARTUP):
            self.logger.debug("got startup event!");
#        oh.logInfo("TestRule", str(ItemRegistry.getItem("Heating_GF_Corridor")))
#        action = oh.getActions() 
#        oh.logInfo("TestRule", "available actions: " + str(action.keySet()))
#        ping = oh.getAction("Ping")
#        oh.logInfo("TestRule", "internet reachable: " + ("yes" if ping.checkVitality("google.com", 80, 100) else "no"))

#        def whoop():
#            print "yeah"

#        oh.createTimer(DateTime.now().plusSeconds(10), whoop)
def getRules():
    return RuleSet([
        TestRule()
    ])

but it really doesn't matter what I put in there. I took out the StartupTrigger() and everything else, the error still happens.

[berndpfrommer]

This is the openhab.log for a successful startup (runlevel 5 for jsr engine):

07:16:02.842 [DEBUG] [.s.internal.SchedulerActivator:36   ] - Scheduler has been started.
07:16:02.859 [INFO ] [uartz.impl.StdSchedulerFactory:1175 ] - Using default implementation for ThreadExecutor
07:16:02.867 [INFO ] [rtz.core.SchedulerSignalerImpl:61   ] - Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
07:16:02.867 [INFO ] [rg.quartz.core.QuartzScheduler:243  ] - Quartz Scheduler v.2.1.7 created.
07:16:02.867 [INFO ] [org.quartz.simpl.RAMJobStore  :154  ] - RAMJobStore initialized.
07:16:02.868 [INFO ] [rg.quartz.core.QuartzScheduler:268  ] - Scheduler meta-data: Quartz Scheduler (v2.1.7) 'openHAB-job-scheduler' with instanceId 'NON_CLUSTERED'
  Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.
  NOT STARTED.
  Currently in standby mode.
  Number of jobs executed: 0
  Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 2 threads.
  Using job-store 'org.quartz.simpl.RAMJobStore' - which does not support persistence. and is not clustered.
07:16:02.868 [INFO ] [uartz.impl.StdSchedulerFactory:1324 ] - Quartz scheduler 'openHAB-job-scheduler' initialized from specified file: './etc/quartz.properties'
07:16:02.868 [INFO ] [uartz.impl.StdSchedulerFactory:1328 ] - Quartz scheduler version: 2.1.7
07:16:02.868 [INFO ] [rg.quartz.core.QuartzScheduler:534  ] - Scheduler openHAB-job-scheduler_$_NON_CLUSTERED started.
07:16:02.870 [DEBUG] [o.config.core.ConfigDispatcher:146  ] - Processing openHAB default configuration file '/home/pfrommer/workspace/openhab/distribution/openhabhome/configurations/openhab_default.cfg'.
07:16:02.957 [DEBUG] [o.config.core.ConfigDispatcher:168  ] - Processing openHAB main configuration file '/home/pfrommer/workspace/openhab/distribution/openhabhome/configurations/openhab.cfg'.
07:16:03.028 [DEBUG] [.o.core.internal.CoreActivator:93   ] - UUID file already exists at '/home/pfrommer/workspace/openhab/distribution/openhabhome/webapps/static/uuid' with content '9b153502-2298-4d28-af87-d858b3262076'
07:16:03.030 [DEBUG] [.o.core.internal.CoreActivator:115  ] - Created file '/home/pfrommer/workspace/openhab/distribution/openhabhome/webapps/static/version' with content '1.8.0'
07:16:03.030 [INFO ] [.o.core.internal.CoreActivator:61   ] - openHAB runtime has been started (v1.8.0).
07:16:03.380 [DEBUG] [.i.internal.ItemModelActivator:24   ] - Registered 'item' configuration parser
07:16:03.385 [INFO ] [.service.AbstractActiveService:169  ] - InsteonPLM has been started
07:16:03.412 [DEBUG] [a.internal.AutoUpdateActivator:31   ] - AutoUpdate binding has been started.
07:16:03.522 [DEBUG] [o.o.c.i.items.ItemRegistryImpl:137  ] - Item provider 'GenericItemProvider' has been added.
07:16:03.637 [DEBUG] [.p.i.PersistenceModelActivator:23   ] - Registered 'persistence' configuration parser
07:16:03.667 [DEBUG] [.c.t.i.TransformationActivator:38   ] - Transformation Service has been started.
07:16:03.721 [INFO ] [c.internal.ModelRepositoryImpl:80   ] - Loading model 'insteonplm.items'
07:16:03.726 [DEBUG] [m.internal.MultimediaActivator:34   ] - Multimedia I/O bundle has been started.
07:16:03.756 [DEBUG] [io.rest.internal.RESTActivator:33   ] - REST API has been started.
07:16:03.765 [DEBUG] [.s.i.DiscoveryServiceActivator:27   ] - Discovery service has been started.
07:16:03.772 [INFO ] [o.o.i.s.i.DiscoveryServiceImpl:93   ] - mDNS service has been started
07:16:03.784 [DEBUG] [i.internal.GenericItemProvider:154  ] - Processing binding configs for items from model 'insteonplm.items'
07:16:03.832 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'insteonplm.items'
07:16:03.835 [INFO ] [c.internal.ModelRepositoryImpl:80   ] - Loading model 'groups.items'
07:16:03.853 [INFO ] [o.o.i.s.i.DiscoveryServiceImpl:53   ] - Service Discovery initialization completed.
07:16:03.859 [DEBUG] [i.internal.GenericItemProvider:154  ] - Processing binding configs for items from model 'groups.items'
07:16:03.913 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'insteonplm.items'
07:16:03.915 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'groups.items'
07:16:04.293 [DEBUG] [.r.internal.RuleModelActivator:42   ] - Registered 'rules' configuration parser
07:16:04.303 [DEBUG] [m.r.internal.engine.RuleEngine:77   ] - Started rule engine
07:16:04.310 [DEBUG] [.rrd4j.internal.RRD4jActivator:31   ] - RRD4j persistence bundle has been started.
07:16:04.324 [WARN ] [.p.rrd4j.internal.RRD4jService:389  ] - Unknown property name : org.openhab.persistence.rrd4j
07:16:04.325 [DEBUG] [.p.rrd4j.internal.RRD4jService:358  ] - config 'objectClass' should have the format 'name.configkey'
07:16:04.325 [INFO ] [.p.rrd4j.internal.RRD4jService:401  ] - Removing invalid defintion component = null heartbeat = 0 min/max = 0.0/0.0 step = 0 0 archives(s) = [] 0 items(s) = []
07:16:04.325 [DEBUG] [.p.rrd4j.internal.RRD4jService:399  ] - Created default_other = GAUGE heartbeat = 3600 min/max = NaN/NaN step = 1 6 archives(s) = [ MAX xff = 0.999 steps = 1 rows = 3600 MAX xff = 0.999 steps = 10 rows = 1440 MAX xff = 0.999 steps = 60 rows = 1440 MAX xff = 0.999 steps = 900 rows = 2880 MAX xff = 0.999 steps = 21600 rows = 1460 MAX xff = 0.999 steps = 86400 rows = 3650] 0 items(s) = []
07:16:04.325 [DEBUG] [.p.rrd4j.internal.RRD4jService:399  ] - Created default_numeric = GAUGE heartbeat = 60 min/max = NaN/NaN step = 60 6 archives(s) = [ AVERAGE xff = 0.5 steps = 1 rows = 480 AVERAGE xff = 0.5 steps = 4 rows = 360 AVERAGE xff = 0.5 steps = 14 rows = 644 AVERAGE xff = 0.5 steps = 60 rows = 720 AVERAGE xff = 0.5 steps = 720 rows = 730 AVERAGE xff = 0.5 steps = 10080 rows = 520] 0 items(s) = []
07:16:04.326 [DEBUG] [.p.internal.PersistenceManager:146  ] - Initializing rrd4j persistence service.
07:16:04.327 [DEBUG] [c.internal.ModelRepositoryImpl:64   ] - Configuration model 'rrd4j.persist' can not be found
07:16:04.490 [DEBUG] [.o.m.s.i.SitemapModelActivator:23   ] - Registered 'sitemap' configuration parser
07:16:04.554 [INFO ] [org.atmosphere.util.IOUtils   :370  ] - META-INF/services/org.atmosphere.cpr.AtmosphereFramework not found in class loader
07:16:04.566 [INFO ] [sphere.cpr.AtmosphereFramework:2601 ] - Atmosphere is using org.atmosphere.cpr.DefaultAnnotationProcessor for processing annotation
07:16:04.567 [INFO ] [cpr.DefaultAnnotationProcessor:138  ] - AnnotationProcessor class org.atmosphere.cpr.DefaultAnnotationProcessor$BytecodeBasedAnnotationProcessor being used
07:16:04.573 [WARN ] [cpr.DefaultAnnotationProcessor:178  ] - Unable to detect annotations. Application may fail to deploy.
07:16:04.584 [INFO ] [sphere.cpr.AtmosphereFramework:1891 ] - Auto detecting atmosphere handlers /WEB-INF/classes/
07:16:04.592 [INFO ] [sphere.cpr.AtmosphereFramework:639  ] - Installed AtmosphereHandler org.atmosphere.handler.ReflectorServletProcessor mapped to context-path /* and Broadcaster Class org.atmosphere.jersey.JerseyBroadcaster
07:16:04.593 [INFO ] [sphere.cpr.AtmosphereFramework:1945 ] - Auto detecting WebSocketHandler in /WEB-INF/classes/
07:16:04.593 [INFO ] [sphere.cpr.AtmosphereFramework:1602 ] - Installed WebSocketProtocol org.atmosphere.websocket.protocol.SimpleHttpProtocol 
07:16:04.605 [INFO ] [.a.h.ReflectorServletProcessor:103  ] - Installing Servlet com.sun.jersey.spi.container.servlet.ServletContainer
07:16:04.649 [INFO ] [c.s.j.s.i.a.WebApplicationImpl:815  ] - Initiating Jersey application, version 'Jersey: 1.18.1 02/19/2014 03:28 AM'
07:16:04.652 [INFO ] [c.s.j.s.i.a.WebApplicationImpl:826  ] - Adding the following classes declared in META-INF/services/jersey-server-components to the resource configuration:
  class org.atmosphere.jersey.AtmosphereResourceConfigurator
  class org.atmosphere.jersey.AtmosphereResourceConfigurator
07:16:04.686 [INFO ] [j.s.i.a.DeferredResourceConfig:101  ] - Instantiated the Application class org.openhab.io.rest.RESTApplication
07:16:04.912 [INFO ] [sphere.cpr.AtmosphereFramework:2435 ] - AtmosphereInterceptor CORS Interceptor Support will always be executed first
07:16:04.913 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor CORS Interceptor Support with priority FIRST_BEFORE_DEFAULT 
07:16:04.913 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor Default Response's Headers Interceptor with priority AFTER_DEFAULT 
07:16:04.913 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor Android Interceptor Support with priority AFTER_DEFAULT 
07:16:04.913 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor SSE Interceptor Support with priority AFTER_DEFAULT 
07:16:04.914 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor JSONP Interceptor Support with priority AFTER_DEFAULT 
07:16:04.914 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor Atmosphere JavaScript Protocol with priority AFTER_DEFAULT 
07:16:04.914 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor Browser disconnection detection with priority AFTER_DEFAULT 
07:16:04.916 [INFO ] [sphere.cpr.AtmosphereFramework:935  ] - Using EndpointMapper class org.atmosphere.util.DefaultEndpointMapper
07:16:04.917 [WARN ] [sphere.cpr.AtmosphereFramework:941  ] - No BroadcasterCache configured. Broadcasted message between client reconnection will be LOST. It is recommended to configure the org.atmosphere.cache.UUIDBroadcasterCache
07:16:04.917 [INFO ] [sphere.cpr.AtmosphereFramework:949  ] - Default Broadcaster Class: org.atmosphere.jersey.JerseyBroadcaster
07:16:04.917 [INFO ] [sphere.cpr.AtmosphereFramework:950  ] - Broadcaster Polling Wait Time 100
07:16:04.917 [INFO ] [sphere.cpr.AtmosphereFramework:951  ] - Shared ExecutorService supported: true
07:16:04.917 [INFO ] [sphere.cpr.AtmosphereFramework:958  ] - Messaging Thread Pool Size: 10
07:16:04.917 [INFO ] [sphere.cpr.AtmosphereFramework:968  ] - Async I/O Thread Pool Size: 10
07:16:04.917 [INFO ] [sphere.cpr.AtmosphereFramework:979  ] - Using BroadcasterFactory: org.atmosphere.cpr.DefaultBroadcasterFactory
07:16:04.917 [INFO ] [sphere.cpr.AtmosphereFramework:980  ] - Using WebSocketProcessor: org.atmosphere.websocket.DefaultWebSocketProcessor
07:16:04.917 [INFO ] [sphere.cpr.AtmosphereFramework:990  ] - Invoke AtmosphereInterceptor on WebSocket message true
07:16:04.917 [INFO ] [sphere.cpr.AtmosphereFramework:991  ] - HttpSession supported: false
07:16:04.918 [INFO ] [sphere.cpr.AtmosphereFramework:993  ] - Atmosphere is using DefaultAtmosphereObjectFactory for dependency injection and object creation
07:16:04.918 [INFO ] [sphere.cpr.AtmosphereFramework:994  ] - Atmosphere is using async support: org.atmosphere.container.JettyAsyncSupportWithWebSocket running under container: jetty/8.1.3.v20120522 with WebSocket enabled.
07:16:04.919 [INFO ] [sphere.cpr.AtmosphereFramework:996  ] - Atmosphere Framework 2.2.5 started.
07:16:04.919 [INFO ] [sphere.cpr.AtmosphereFramework:998  ] - 
    For Atmosphere Framework Commercial Support, visit 
    http://www.async-io.org/ or send an email to support@async-io.org
07:16:04.919 [INFO ] [penhab.io.rest.RESTApplication:144  ] - Started REST API at /rest
07:16:04.920 [DEBUG] [o.o.i.s.i.DiscoveryServiceImpl:66   ] - Registering new service _openhab-server._tcp.local. at port 8080
07:16:04.996 [INFO ] [sphere.cpr.AtmosphereFramework:1053 ] - Latest version of Atmosphere's JavaScript Client 2.2.12
07:16:04.996 [INFO ] [sphere.cpr.AtmosphereFramework:1060 ] - 
    Atmosphere Framework Updates:
    Minor Update available (bugs fixes): 2.2.8
07:16:11.476 [DEBUG] [o.o.i.s.i.DiscoveryServiceImpl:66   ] - Registering new service _openhab-server-ssl._tcp.local. at port 8443
07:16:13.982 [INFO ] [c.internal.ModelRepositoryImpl:80   ] - Loading model 'nolen.sitemap'
07:16:14.176 [DEBUG] [p.r.i.charts.RRD4jChartServlet:118  ] - Starting up rrd chart servlet at /rrdchart.png
07:16:14.226 [INFO ] [.o.u.w.i.servlet.WebAppServlet:79   ] - Started Classic UI at /openhab.app
07:16:14.254 [DEBUG] [j.internal.Jsr223CoreActivator:33   ] - Registered 'jsr223' scripting-engine
07:16:14.262 [DEBUG] [j.internal.engine.Jsr223Engine:96   ] - itemRegistry set
07:16:14.263 [DEBUG] [j.internal.engine.Jsr223Engine:68   ] - activate()
07:16:14.267 [INFO ] [o.o.c.j.i.e.s.ScriptManager   :58   ] - Available engines:
07:16:14.271 [INFO ] [o.o.c.j.i.e.s.ScriptManager   :60   ] - Oracle Nashorn
07:16:14.271 [INFO ] [o.o.c.j.i.e.s.ScriptManager   :60   ] - jython
07:16:14.273 [INFO ] [o.c.j.i.e.scriptmanager.Script:81   ] - Loading Script foo.py~
07:16:14.274 [WARN ] [o.o.c.j.i.e.s.ScriptManager   :92   ] - No Engine found for File: foo.py~
07:16:14.274 [INFO ] [o.c.j.i.e.scriptmanager.Script:81   ] - Loading Script foo.py
07:16:15.121 [INFO ] [o.c.j.i.e.scriptmanager.Script:86   ] - EngineName: jython
07:16:15.300 [INFO ] [o.o.c.j.i.e.s.ScriptManager   :95   ] - Engine found for File: foo.py
07:16:15.303 [DEBUG] [j.internal.engine.Jsr223Engine:78   ] - Started Jsr232 engine
07:16:15.335 [DEBUG] [.openhab.model.jsr232.TestRule:-2   ] - event received Event [triggerType=STARTUP, item=null, oldState=null, newState=null, command=null]
07:16:15.336 [DEBUG] [.openhab.model.jsr232.TestRule:-2   ] - got startup event!

[berndpfrommer]

This is how an unsuccessful start looks like. Note that the engine works either way, i.e. the script runs, but none of the items is present.

07:06:10.158 [DEBUG] [.s.internal.SchedulerActivator:36   ] - Scheduler has been started.
07:06:10.173 [INFO ] [uartz.impl.StdSchedulerFactory:1175 ] - Using default implementation for ThreadExecutor
07:06:10.181 [INFO ] [rtz.core.SchedulerSignalerImpl:61   ] - Initialized Scheduler Signaller of type: class org.quartz.core.SchedulerSignalerImpl
07:06:10.182 [INFO ] [rg.quartz.core.QuartzScheduler:243  ] - Quartz Scheduler v.2.1.7 created.
07:06:10.182 [INFO ] [org.quartz.simpl.RAMJobStore  :154  ] - RAMJobStore initialized.
07:06:10.183 [INFO ] [rg.quartz.core.QuartzScheduler:268  ] - Scheduler meta-data: Quartz Scheduler (v2.1.7) 'openHAB-job-scheduler' with instanceId 'NON_CLUSTERED'
  Scheduler class: 'org.quartz.core.QuartzScheduler' - running locally.
  NOT STARTED.
  Currently in standby mode.
  Number of jobs executed: 0
  Using thread pool 'org.quartz.simpl.SimpleThreadPool' - with 2 threads.
  Using job-store 'org.quartz.simpl.RAMJobStore' - which does not support persistence. and is not clustered.
07:06:10.183 [INFO ] [uartz.impl.StdSchedulerFactory:1324 ] - Quartz scheduler 'openHAB-job-scheduler' initialized from specified file: './etc/quartz.properties'
07:06:10.183 [INFO ] [uartz.impl.StdSchedulerFactory:1328 ] - Quartz scheduler version: 2.1.7
07:06:10.183 [INFO ] [rg.quartz.core.QuartzScheduler:534  ] - Scheduler openHAB-job-scheduler_$_NON_CLUSTERED started.
07:06:10.184 [DEBUG] [o.config.core.ConfigDispatcher:146  ] - Processing openHAB default configuration file '/home/pfrommer/workspace/openhab/distribution/openhabhome/configurations/openhab_default.cfg'.
07:06:12.847 [DEBUG] [o.config.core.ConfigDispatcher:168  ] - Processing openHAB main configuration file '/home/pfrommer/workspace/openhab/distribution/openhabhome/configurations/openhab.cfg'.
07:06:14.878 [DEBUG] [.o.core.internal.CoreActivator:93   ] - UUID file already exists at '/home/pfrommer/workspace/openhab/distribution/openhabhome/webapps/static/uuid' with content '9b153502-2298-4d28-af87-d858b3262076'
07:06:14.917 [DEBUG] [.o.core.internal.CoreActivator:115  ] - Created file '/home/pfrommer/workspace/openhab/distribution/openhabhome/webapps/static/version' with content '1.8.0'
07:06:14.917 [INFO ] [.o.core.internal.CoreActivator:61   ] - openHAB runtime has been started (v1.8.0).
07:06:15.289 [DEBUG] [.i.internal.ItemModelActivator:24   ] - Registered 'item' configuration parser
07:06:15.295 [INFO ] [.service.AbstractActiveService:169  ] - InsteonPLM has been started
07:06:15.515 [DEBUG] [a.internal.AutoUpdateActivator:31   ] - AutoUpdate binding has been started.
07:06:15.529 [DEBUG] [j.internal.Jsr223CoreActivator:33   ] - Registered 'jsr223' scripting-engine
07:06:15.540 [DEBUG] [j.internal.engine.Jsr223Engine:96   ] - itemRegistry set
07:06:15.540 [DEBUG] [j.internal.engine.Jsr223Engine:68   ] - activate()
07:06:15.547 [INFO ] [o.o.c.j.i.e.s.ScriptManager   :58   ] - Available engines:
07:06:15.552 [INFO ] [o.o.c.j.i.e.s.ScriptManager   :60   ] - jython
07:06:15.552 [INFO ] [o.o.c.j.i.e.s.ScriptManager   :60   ] - Oracle Nashorn
07:06:15.555 [INFO ] [o.c.j.i.e.scriptmanager.Script:81   ] - Loading Script foo.py~
07:06:15.556 [WARN ] [o.o.c.j.i.e.s.ScriptManager   :92   ] - No Engine found for File: foo.py~
07:06:15.556 [INFO ] [o.c.j.i.e.scriptmanager.Script:81   ] - Loading Script foo.py
07:06:16.248 [INFO ] [o.c.j.i.e.scriptmanager.Script:86   ] - EngineName: jython
07:06:16.547 [DEBUG] [o.o.c.i.items.ItemRegistryImpl:137  ] - Item provider 'GenericItemProvider' has been added.
07:06:17.314 [INFO ] [c.internal.ModelRepositoryImpl:80   ] - Loading model 'insteonplm.items'
07:06:17.410 [DEBUG] [i.internal.GenericItemProvider:154  ] - Processing binding configs for items from model 'insteonplm.items'
07:06:17.410 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatCoolPoint' of type 'Number'
07:06:17.411 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatHeatPoint' of type 'Number'
07:06:17.411 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatSystemMode' of type 'Number'
07:06:17.411 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatFanMode' of type 'Number'
07:06:17.411 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatIsHeating' of type 'Number'
07:06:17.411 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatIsCooling' of type 'Number'
07:06:17.411 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatTempFahren' of type 'Number'
07:06:17.411 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatTempCelsius' of type 'Number'
07:06:17.411 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatHumidity' of type 'Number'
07:06:17.411 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatACDelay' of type 'Number'
07:06:17.411 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatBacklight' of type 'Number'
07:06:17.411 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatStage1' of type 'Number'
07:06:17.411 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatHumidityHigh' of type 'Number'
07:06:17.411 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatHumidityLow' of type 'Number'
07:06:17.411 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'broadcastOnOff' of type 'Switch'
07:06:17.411 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'officeLight' of type 'Switch'
07:06:17.411 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'diningRoomEastDimmerFastOnOff' of type 'Switch'
07:06:17.412 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'diningRoomEastDimmer' of type 'Dimmer'
07:06:17.412 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'diningRoomWestDimmer' of type 'Dimmer'
07:06:17.412 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'computerRoomLightsWestSw' of type 'Dimmer'
07:06:17.412 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'computerRoomLightsEastSw' of type 'Dimmer'
07:06:17.412 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'insteonplm.items'
07:06:17.412 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatCoolPoint' of type 'Number'
07:06:17.412 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatHeatPoint' of type 'Number'
07:06:17.412 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatSystemMode' of type 'Number'
07:06:17.412 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatFanMode' of type 'Number'
07:06:17.412 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatIsHeating' of type 'Number'
07:06:17.412 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatIsCooling' of type 'Number'
07:06:17.412 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatTempFahren' of type 'Number'
07:06:17.412 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatTempCelsius' of type 'Number'
07:06:17.413 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatHumidity' of type 'Number'
07:06:17.413 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatACDelay' of type 'Number'
07:06:17.413 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatBacklight' of type 'Number'
07:06:17.413 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatStage1' of type 'Number'
07:06:17.413 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatHumidityHigh' of type 'Number'
07:06:17.413 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'thermostatHumidityLow' of type 'Number'
07:06:17.413 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'broadcastOnOff' of type 'Switch'
07:06:17.413 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'officeLight' of type 'Switch'
07:06:17.413 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'diningRoomEastDimmerFastOnOff' of type 'Switch'
07:06:17.413 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'diningRoomEastDimmer' of type 'Dimmer'
07:06:17.413 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'diningRoomWestDimmer' of type 'Dimmer'
07:06:17.413 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'computerRoomLightsWestSw' of type 'Dimmer'
07:06:17.413 [DEBUG] [i.internal.GenericItemProvider:419  ] - Couldn't find ItemFactory for item 'computerRoomLightsEastSw' of type 'Dimmer'
07:06:17.419 [ERROR] [.o.m.c.i.folder.FolderObserver:105  ] - An unexpected exception has occured
java.lang.NullPointerException: null
    at org.openhab.core.jsr223.internal.engine.Jsr223Engine.runStartupRules(Jsr223Engine.java:201) ~[na:na]
    at org.openhab.core.jsr223.internal.engine.Jsr223Engine.allItemsChanged(Jsr223Engine.java:116) ~[na:na]
    at org.openhab.core.internal.items.ItemRegistryImpl.allItemsChanged(ItemRegistryImpl.java:201) ~[na:na]
    at org.openhab.model.item.internal.GenericItemProvider.modelChanged(GenericItemProvider.java:393) ~[na:na]
    at org.openhab.model.core.internal.ModelRepositoryImpl.notifyListeners(ModelRepositoryImpl.java:159) ~[na:na]
    at org.openhab.model.core.internal.ModelRepositoryImpl.addOrRefreshModel(ModelRepositoryImpl.java:85) ~[na:na]
    at org.openhab.model.core.internal.folder.FolderObserver.checkFolder(FolderObserver.java:142) ~[na:na]
    at org.openhab.model.core.internal.folder.FolderObserver.run(FolderObserver.java:99) ~[na:na]
07:06:17.476 [INFO ] [o.o.c.j.i.e.s.ScriptManager   :95   ] - Engine found for File: foo.py
07:06:17.479 [DEBUG] [j.internal.engine.Jsr223Engine:78   ] - Started Jsr232 engine
07:06:17.484 [DEBUG] [.openhab.model.jsr232.TestRule:-2   ] - event received Event [triggerType=STARTUP, item=null, oldState=null, newState=null, command=null]
07:06:17.485 [DEBUG] [.openhab.model.jsr232.TestRule:-2   ] - got startup event!
07:06:17.714 [DEBUG] [.p.i.PersistenceModelActivator:23   ] - Registered 'persistence' configuration parser
07:06:17.918 [DEBUG] [.c.t.i.TransformationActivator:38   ] - Transformation Service has been started.
07:06:17.973 [DEBUG] [m.internal.MultimediaActivator:34   ] - Multimedia I/O bundle has been started.
07:06:18.002 [DEBUG] [io.rest.internal.RESTActivator:33   ] - REST API has been started.
07:06:18.010 [DEBUG] [.s.i.DiscoveryServiceActivator:27   ] - Discovery service has been started.
07:06:18.019 [INFO ] [o.o.i.s.i.DiscoveryServiceImpl:93   ] - mDNS service has been started
07:06:18.045 [INFO ] [o.o.i.s.i.DiscoveryServiceImpl:53   ] - Service Discovery initialization completed.
07:06:18.156 [DEBUG] [.r.internal.RuleModelActivator:42   ] - Registered 'rules' configuration parser
07:06:18.166 [DEBUG] [m.r.internal.engine.RuleEngine:77   ] - Started rule engine
07:06:18.172 [DEBUG] [.rrd4j.internal.RRD4jActivator:31   ] - RRD4j persistence bundle has been started.
07:06:18.187 [WARN ] [.p.rrd4j.internal.RRD4jService:389  ] - Unknown property name : org.openhab.persistence.rrd4j
07:06:18.188 [DEBUG] [.p.rrd4j.internal.RRD4jService:358  ] - config 'objectClass' should have the format 'name.configkey'
07:06:18.188 [INFO ] [.p.rrd4j.internal.RRD4jService:401  ] - Removing invalid defintion component = null heartbeat = 0 min/max = 0.0/0.0 step = 0 0 archives(s) = [] 0 items(s) = []
07:06:18.188 [DEBUG] [.p.rrd4j.internal.RRD4jService:399  ] - Created default_other = GAUGE heartbeat = 3600 min/max = NaN/NaN step = 1 6 archives(s) = [ MAX xff = 0.999 steps = 1 rows = 3600 MAX xff = 0.999 steps = 10 rows = 1440 MAX xff = 0.999 steps = 60 rows = 1440 MAX xff = 0.999 steps = 900 rows = 2880 MAX xff = 0.999 steps = 21600 rows = 1460 MAX xff = 0.999 steps = 86400 rows = 3650] 0 items(s) = []
07:06:18.188 [DEBUG] [.p.rrd4j.internal.RRD4jService:399  ] - Created default_numeric = GAUGE heartbeat = 60 min/max = NaN/NaN step = 60 6 archives(s) = [ AVERAGE xff = 0.5 steps = 1 rows = 480 AVERAGE xff = 0.5 steps = 4 rows = 360 AVERAGE xff = 0.5 steps = 14 rows = 644 AVERAGE xff = 0.5 steps = 60 rows = 720 AVERAGE xff = 0.5 steps = 720 rows = 730 AVERAGE xff = 0.5 steps = 10080 rows = 520] 0 items(s) = []
07:06:18.189 [DEBUG] [.p.internal.PersistenceManager:146  ] - Initializing rrd4j persistence service.
07:06:18.190 [DEBUG] [c.internal.ModelRepositoryImpl:64   ] - Configuration model 'rrd4j.persist' can not be found
07:06:18.348 [DEBUG] [.o.m.s.i.SitemapModelActivator:23   ] - Registered 'sitemap' configuration parser
07:06:18.430 [INFO ] [org.atmosphere.util.IOUtils   :370  ] - META-INF/services/org.atmosphere.cpr.AtmosphereFramework not found in class loader
07:06:18.440 [INFO ] [sphere.cpr.AtmosphereFramework:2601 ] - Atmosphere is using org.atmosphere.cpr.DefaultAnnotationProcessor for processing annotation
07:06:18.441 [INFO ] [cpr.DefaultAnnotationProcessor:138  ] - AnnotationProcessor class org.atmosphere.cpr.DefaultAnnotationProcessor$BytecodeBasedAnnotationProcessor being used
07:06:18.446 [WARN ] [cpr.DefaultAnnotationProcessor:178  ] - Unable to detect annotations. Application may fail to deploy.
07:06:18.458 [INFO ] [sphere.cpr.AtmosphereFramework:1891 ] - Auto detecting atmosphere handlers /WEB-INF/classes/
07:06:18.466 [INFO ] [sphere.cpr.AtmosphereFramework:639  ] - Installed AtmosphereHandler org.atmosphere.handler.ReflectorServletProcessor mapped to context-path /* and Broadcaster Class org.atmosphere.jersey.JerseyBroadcaster
07:06:18.467 [INFO ] [sphere.cpr.AtmosphereFramework:1945 ] - Auto detecting WebSocketHandler in /WEB-INF/classes/
07:06:18.467 [INFO ] [sphere.cpr.AtmosphereFramework:1602 ] - Installed WebSocketProtocol org.atmosphere.websocket.protocol.SimpleHttpProtocol 
07:06:18.478 [INFO ] [.a.h.ReflectorServletProcessor:103  ] - Installing Servlet com.sun.jersey.spi.container.servlet.ServletContainer
07:06:18.520 [INFO ] [c.s.j.s.i.a.WebApplicationImpl:815  ] - Initiating Jersey application, version 'Jersey: 1.18.1 02/19/2014 03:28 AM'
07:06:18.523 [INFO ] [c.s.j.s.i.a.WebApplicationImpl:826  ] - Adding the following classes declared in META-INF/services/jersey-server-components to the resource configuration:
  class org.atmosphere.jersey.AtmosphereResourceConfigurator
  class org.atmosphere.jersey.AtmosphereResourceConfigurator
07:06:18.553 [INFO ] [j.s.i.a.DeferredResourceConfig:101  ] - Instantiated the Application class org.openhab.io.rest.RESTApplication
07:06:18.922 [INFO ] [sphere.cpr.AtmosphereFramework:2435 ] - AtmosphereInterceptor CORS Interceptor Support will always be executed first
07:06:18.922 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor CORS Interceptor Support with priority FIRST_BEFORE_DEFAULT 
07:06:18.922 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor Default Response's Headers Interceptor with priority AFTER_DEFAULT 
07:06:18.923 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor Android Interceptor Support with priority AFTER_DEFAULT 
07:06:18.923 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor SSE Interceptor Support with priority AFTER_DEFAULT 
07:06:18.923 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor JSONP Interceptor Support with priority AFTER_DEFAULT 
07:06:18.924 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor Atmosphere JavaScript Protocol with priority AFTER_DEFAULT 
07:06:18.924 [INFO ] [sphere.cpr.AtmosphereFramework:2404 ] - Installed AtmosphereInterceptor Browser disconnection detection with priority AFTER_DEFAULT 
07:06:18.926 [INFO ] [sphere.cpr.AtmosphereFramework:935  ] - Using EndpointMapper class org.atmosphere.util.DefaultEndpointMapper
07:06:18.927 [WARN ] [sphere.cpr.AtmosphereFramework:941  ] - No BroadcasterCache configured. Broadcasted message between client reconnection will be LOST. It is recommended to configure the org.atmosphere.cache.UUIDBroadcasterCache
07:06:18.927 [INFO ] [sphere.cpr.AtmosphereFramework:949  ] - Default Broadcaster Class: org.atmosphere.jersey.JerseyBroadcaster
07:06:18.927 [INFO ] [sphere.cpr.AtmosphereFramework:950  ] - Broadcaster Polling Wait Time 100
07:06:18.927 [INFO ] [sphere.cpr.AtmosphereFramework:951  ] - Shared ExecutorService supported: true
07:06:18.927 [INFO ] [sphere.cpr.AtmosphereFramework:958  ] - Messaging Thread Pool Size: 10
07:06:18.927 [INFO ] [sphere.cpr.AtmosphereFramework:968  ] - Async I/O Thread Pool Size: 10
07:06:18.927 [INFO ] [sphere.cpr.AtmosphereFramework:979  ] - Using BroadcasterFactory: org.atmosphere.cpr.DefaultBroadcasterFactory
07:06:18.928 [INFO ] [sphere.cpr.AtmosphereFramework:980  ] - Using WebSocketProcessor: org.atmosphere.websocket.DefaultWebSocketProcessor
07:06:18.928 [INFO ] [sphere.cpr.AtmosphereFramework:990  ] - Invoke AtmosphereInterceptor on WebSocket message true
07:06:18.928 [INFO ] [sphere.cpr.AtmosphereFramework:991  ] - HttpSession supported: false
07:06:18.928 [INFO ] [sphere.cpr.AtmosphereFramework:993  ] - Atmosphere is using DefaultAtmosphereObjectFactory for dependency injection and object creation
07:06:18.928 [INFO ] [sphere.cpr.AtmosphereFramework:994  ] - Atmosphere is using async support: org.atmosphere.container.JettyAsyncSupportWithWebSocket running under container: jetty/8.1.3.v20120522 with WebSocket enabled.
07:06:18.928 [INFO ] [sphere.cpr.AtmosphereFramework:996  ] - Atmosphere Framework 2.2.5 started.
07:06:18.928 [INFO ] [sphere.cpr.AtmosphereFramework:998  ] - 
    For Atmosphere Framework Commercial Support, visit 
    http://www.async-io.org/ or send an email to support@async-io.org
07:06:18.929 [INFO ] [penhab.io.rest.RESTApplication:144  ] - Started REST API at /rest
07:06:18.931 [DEBUG] [o.o.i.s.i.DiscoveryServiceImpl:66   ] - Registering new service _openhab-server._tcp.local. at port 8080
07:06:19.019 [INFO ] [sphere.cpr.AtmosphereFramework:1053 ] - Latest version of Atmosphere's JavaScript Client 2.2.12
07:06:19.019 [INFO ] [sphere.cpr.AtmosphereFramework:1060 ] - 
    Atmosphere Framework Updates:
    Minor Update available (bugs fixes): 2.2.8
07:06:25.927 [DEBUG] [o.o.i.s.i.DiscoveryServiceImpl:66   ] - Registering new service _openhab-server-ssl._tcp.local. at port 8443
07:06:27.504 [INFO ] [c.internal.ModelRepositoryImpl:80   ] - Loading model 'nolen.sitemap'
07:06:27.580 [INFO ] [c.internal.ModelRepositoryImpl:98   ] - Refreshing model 'insteonplm.items'
07:06:27.583 [DEBUG] [i.internal.GenericItemProvider:154  ] - Processing binding configs for items from model 'insteonplm.items'
07:06:27.598 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'insteonplm.items'
07:06:27.610 [DEBUG] [.openhab.model.jsr232.TestRule:-2   ] - event received Event [triggerType=STARTUP, item=null, oldState=null, newState=null, command=null]
07:06:27.611 [DEBUG] [.openhab.model.jsr232.TestRule:-2   ] - got startup event!
07:06:27.612 [INFO ] [c.internal.ModelRepositoryImpl:80   ] - Loading model 'groups.items'
07:06:27.623 [DEBUG] [i.internal.GenericItemProvider:154  ] - Processing binding configs for items from model 'groups.items'
07:06:27.628 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'insteonplm.items'
07:06:27.629 [DEBUG] [i.internal.GenericItemProvider:133  ] - Read items from model 'groups.items'
07:06:27.633 [DEBUG] [.openhab.model.jsr232.TestRule:-2   ] - event received Event [triggerType=STARTUP, item=null, oldState=null, newState=null, command=null]
07:06:27.634 [DEBUG] [.openhab.model.jsr232.TestRule:-2   ] - got startup event!

[berndpfrommer]

The most obvious difference is the order in which components are registered: In the successful case:

07:16:03.380 [DEBUG] [.i.internal.ItemModelActivator:24   ] - Registered 'item' configuration parser
07:16:03.637 [DEBUG] [.p.i.PersistenceModelActivator:23   ] - Registered 'persistence' configuration parser
07:16:04.293 [DEBUG] [.r.internal.RuleModelActivator:42   ] - Registered 'rules' configuration parser
07:16:04.490 [DEBUG] [.o.m.s.i.SitemapModelActivator:23   ] - Registered 'sitemap' configuration parser
07:16:14.254 [DEBUG] [j.internal.Jsr223CoreActivator:33   ] - Registered 'jsr223' scripting-engine

vs the failure mode:

07:06:15.289 [DEBUG] [.i.internal.ItemModelActivator:24   ] - Registered 'item' configuration parser
07:06:15.529 [DEBUG] [j.internal.Jsr223CoreActivator:33   ] - Registered 'jsr223' scripting-engine
07:06:17.714 [DEBUG] [.p.i.PersistenceModelActivator:23   ] - Registered 'persistence' configuration parser
07:06:18.156 [DEBUG] [.r.internal.RuleModelActivator:42   ] - Registered 'rules' configuration parser
07:06:18.348 [DEBUG] [.o.m.s.i.SitemapModelActivator:23   ] - Registered 'sitemap' configuration parser

What ordering do you see for your runs (when you set the runlevel to default)?

[lewie]

HA, I had a look in my OH Eclipse Environment and in openHAB Runtime.launch jsr223 starts on start-level 5. Had a look in git History, since 4 month Merschjohann has commited jsr223 with start-level 5.

Your failure mode can not work, because jsr223 must have access to some classes of persistence Services! My Startorder with start-level 5:

14:39:46.127 [DEBUG] [.p.i.PersistenceModelActivator:23   ] - Registered 'persistence' configuration parser
14:39:46.378 [DEBUG] [.i.internal.ItemModelActivator:24   ] - Registered 'item' configuration parser
14:39:46.975 [DEBUG] [.o.m.s.i.SitemapModelActivator:23   ] - Registered 'sitemap' configuration parser
14:39:57.010 [DEBUG] [.r.internal.RuleModelActivator:42   ] - Registered 'rules' configuration parser
14:40:00.303 [DEBUG] [j.internal.Jsr223CoreActivator:33   ] - Registered 'jsr223' scripting-engine

All is well now? :-)

Rgds Helmut

[berndpfrommer]

O.k., I must have had the old openHAB Runtime.launch still around. With the new one, everything works.