JSR223 Groovy rule throws exception on startup only (MissingPropertyException: No such property: itemRegistry)

[vbier]

I have a groovy rule that works fine once the system has started, but on startup I
always get:

2017-09-22 11:56:02.935 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/etc/openhab2/automation/jsr223/shading.groovy': javax.script.ScriptException: groovy.lang.MissingPropertyException: No such property: itemRegistry for class: Script1

I have to touch the rule once the system is up and then it works. The rule can be stripped down to one line and still triggers the error:

itemRegistry.get("gShutterLocks")

I have openhabian running and just updated to openHAB 2.2.0 Build #1044 in hope that
the problem will go away, but is still there.

Expected Behavior

The rule should parse without errors on system startup.

Current Behavior

I do get the above mentioned MissingPropertyException.

Steps to Reproduce (for Bugs)

Install openHAB with JSR223 groovy support, add a rule with the above mentioned content and restart openHAB.

Environment

openhabian [master]v1.3-303(0e2437c)
openHAB 2.2.0 Build # 1044

[wborn]

The root cause according to @smerschjohann in #4808 is:

As we don't know when the whole platform is initialized, the ScriptFileWatcher currently waits for 25 seconds before importing the scripts located at the jsr223 directory.

[sjsf]

This however is not really a dependency on "the system", but in this case clearly on the availability of DefaultScriptScopeProvider. I know, code-wise the ScriptFileWatcher couldn't care less about them, but shouldn't it technically have a mandatory dependency on this concrete service instance and presumably also on RuleSupportScriptExtension as they're kind of "API" for the scripts?

I know, potentially there could be an arbitrary, unknown number of ScriptExtensionProvider worth waiting for (this is where #1896 comes into the picture, once again), but this would at least cure the biggest pain immediately.

[HolgerHees]

Hello,

I have a similar issues with javascript and jython. Both jsr223 implementations have similar trouble with not initialized context.

https://community.openhab.org/t/jython-jsr223-not-properly-initialised-during-startup/46031

and a timeout of 25 seconds is far from being enough.

I have a Intel Atom CPU which needs between 2 - 4 minutes to startup my openhab 2.3 system with several hundred items. During this time a I get a lot of errors like rules which are fired to early (before persistence, items, transformation maps), jsr223 context is not properly initialized... Every startup gives different errors, depending what is already loaded and what not. Only the jsr223 error is always the same.

After 2-4 minutes the rules errors are less and less until they are gone. And at the end if i call "touch *" on all jython files, every thing loads fine and the jython scripts are working correctly.

just to give you an impression about my complex setup, you can take a look here

http://www.intranet-of-things.com/smarthome

As I'm a developer too, maybe I can help with debugging, testing, providing limited access to my system/setup

[HolgerHees]

I extended the burntime script a little bit. Instead of waiting a specific amount of time, I'm waiting now until the automationManager is initialized. This works for me, independently how long my openhab startup need to finish.

import time

from org.slf4j import Logger, LoggerFactory
log = LoggerFactory.getLogger("org.eclipse.smarthome.automation")

log.info("jsr223: checking for initialised context")

while True:
    try:
        scriptExtension.importPreset("RuleSupport")
        if automationManager != None:
            break;
    except:
        pass
    log.info("jsr223: context not initialised yet. waiting 10 sec before checking again")
    time.sleep(10)

log.info("jsr223: done")

[5iver]

I had been using @HolgerHees solution, but found in testing that it is no longer needed. I'm currently using OH snapshot 1374. I'm not sure which PR might have corrected this, but I think this issue can be closed. @vbier?

[vbier]

I just updated to 1374 and still have the error:

2018-09-28 11:34:10.404 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/etc/openhab2/automation/jsr223/shading.groovy': javax.script.ScriptException: groovy.lang.MissingPropertyException: No such property: itemRegistry for class: Script1

[5iver]

Strange... my Jython scripts are loading properly without the 'burntime' script, but it was needed before. I must be getting lucky!

[kaikreuzer]

I don't know about your "burntime" script, but that it is now working might be a positive side effect of #6284.

[htreu]

It certainly is: Before #6284 the ScriptEngineManagerImpl could start creating script engines even when ItemRegistry was absent. Now it depends on ScriptExtensionManager which in turn depends on all ScriptExtensionProviders (although dynamically). With the DefaultScriptScopeProvider being one and also depending on the ItemRegistry this should stabilise the start up situation.

[vbier]

For me, it actually has become worse. Previously, things started to work when I touched the script file in a system startup rule, but this does now no longer work. It does give now the same exception that I do get when the file is initially loaded, which means I can no longer use the groovy rules at all.

Edit: forget what I just wrote, it worked as before on the next restart. But the original problem is still there.

[kaikreuzer]

@htreu Any idea how this can still happen? Should @vbier provide some debug logging to see what exactly is going on?

[HolgerHees]

my guess is that the need of the burntime script depends how "heavy" your startup procedure is. With heavy I mean the amount of items, rules, etc. If there are a lot of parallel tasks running and you have a slow server like raspberry or atom based one, the availability of the script engine may take longer.

[htreu]

Yes, there is the chance that the ScriptEngineManagerImpl starts script engines without the DefaultScriptScopeProvider being injected into the ScriptExtensionManager since it is part of the dynamic list:

all ScriptExtensionProviders (although dynamically)

What still holds true is @SJKA's analysis here #4324 (comment): The ScriptExtensionProviders are added dynamically but serve as API for the rules. The ScriptFileWatcher however starts adding new Scripts only depending on available ScriptEngineFactories.

The most reliable way of having everything ready would be a static list of ScriptExtensionProviders on the ScriptExtensionManager. This would however mean the full automation stack would be restarted once a bundle with a ScriptExtensionProvider appears/disappears.

@adimova what is your take on this?

[nils]

I'm also affected by this issue.

Is there anything I can contribute or is the issue already understood well enough to work on a solution?

[5iver]

With the reintegration of ESH into openhab-core, openhab/openhab-core#610 and possibly other issues will need to be addressed before this can be looked into again.