Ah… not really a test script, but Jython and the rule engine should be OK then. Try the HelloWorld.py.
Does the openhab dir and feature list look ok? Wandering why triggering.py has different permissions.
Lookin’ good!
That shouldn’t affect anything, but it’s weird. I see the same on a fresh download.
Same result with HelloWorld.py , I chown and chmod the file to be like the test.py script that works(work only when jar is placed here /usr/share/openhab2/runtime/lib/boot)
Out of playtime for now, will try to take another look later tonight.
Put this in a script and post the output…
from org.slf4j import Logger, LoggerFactory
log = LoggerFactory.getLogger("org.eclipse.smarthome.model.script.Rules")
import sys
log.debug("JSR223: version=[{}]".format(sys.version))
log.debug("JSR223: path=[{}]".format(sys.path))
Here is what I get…
2018-10-08 17:25:34.848 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: version=[2.7.0 (default:9987c746f838, Apr 29 2015, 02:25:11)
[OpenJDK 64-Bit Server VM (Oracle Corporation)]]
2018-10-08 17:25:34.848 [DEBUG] [org.eclipse.smarthome.model.script.Rules] - JSR223: path=[['/opt/openhab2/conf/automation/lib/python', '/opt/openhab2/conf/automation/jython/Lib', '/opt/openhab2/conf/automation/jython/jython-standalone-2.7.0.jar/Lib', '__classpath__', '__pyclasspath__/']]
And please post your start.sh too…
#!/bin/sh
echo
echo Launching the openHAB runtime...
DIRNAME=`dirname "$0"`
export EXTRA_JAVA_OPTS="-Xbootclasspath/a:${DIRNAME}/conf/automation/jython/jython-standalone-2.7.0.jar \
-Dpython.home=${DIRNAME}/conf/automation/jython \
-Dpython.path=${DIRNAME}/conf/automation/lib/python"
exec "${DIRNAME}/runtime/bin/karaf" "${@}"
EDIT:
I’m still curious about these, but I think I know what the issue really is now. I updated to snapshot 1381 and saw something similar when OH was first starting up after updating. I thought it had been resolved, but even JSR223 has startup timing issues, and I think this is what you are seeing. Especially because you are using a Pi.
The way the component scripts and their directory are named, these are the first to load. I had used this script to delay the startup of everything, but you may need to rename the components directory to 100_components. Put this in /automation/jsr223/ and name it something like 000_startup.py
…
import time
from org.slf4j import Logger, LoggerFactory
log = LoggerFactory.getLogger("org.eclipse.smarthome.model.script.Rules")
log.info("JSR223: Startup: Checking for initialized context")
while True:
try:
scriptExtension.importPreset("RuleSupport")
if automationManager != None:
log.info("JSR223: Startup: context initialized... waiting 30s before allowing files to load")
break;
except:
pass
log.info("JSR223: Startup: Context not initialized yet... waiting 10s before checking again")
time.sleep(10)
time.sleep(30)
log.info("JSR223: Startup: Complete")
I got "ScriptEngine for py not available”
start.sh looks like this:
I changed the components directory name to 100_components and added the 000_startup.py script to /automation/jsr223/ then restarted and tested again.
2018-10-09 06:55:05.023 [INFO ] [.dashboard.internal.DashboardService] - Stopped Dashboard
2018-10-09 06:55:27.021 [DEBUG] [se.smarthome.automation.module.media] - BundleEvent [unknown:512] - org.eclipse.smarthome.automation.module.media
2018-10-09 06:55:27.098 [DEBUG] [e.smarthome.automation.module.script] - BundleEvent [unknown:512] - org.eclipse.smarthome.automation.module.script
2018-10-09 06:55:27.135 [DEBUG] [e.smarthome.automation.module.script] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.module.script.ScriptEngineFactory}={service.id=120, service.bundleid=218, service.scope=bundle, component.name=org.eclipse.smarthome.automation.module.script.internal.NashornScriptEngineFactory, component.id=15} - org.eclipse.smarthome.automation.module.script
2018-10-09 06:55:27.153 [DEBUG] [e.smarthome.automation.module.script] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.module.script.ScriptEngineManager}={service.id=122, service.bundleid=218, service.scope=bundle, component.name=org.eclipse.smarthome.automation.module.script.internal.ScriptEngineManagerImpl, component.id=16} - org.eclipse.smarthome.automation.module.script
2018-10-09 06:55:27.159 [DEBUG] [e.smarthome.automation.module.script] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.module.script.internal.ScriptExtensionManager}={service.id=121, service.bundleid=218, service.scope=bundle, component.name=org.eclipse.smarthome.automation.module.script.internal.ScriptExtensionManager, component.id=17} - org.eclipse.smarthome.automation.module.script
2018-10-09 06:55:27.175 [DEBUG] [e.smarthome.automation.module.script] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.handler.ModuleHandlerFactory}={service.id=123, service.bundleid=218, service.scope=bundle, component.name=org.eclipse.smarthome.automation.module.script.internal.factory.ScriptModuleHandlerFactory, component.id=18} - org.eclipse.smarthome.automation.module.script
2018-10-09 06:55:27.180 [DEBUG] [automation.module.script.rulesupport] - BundleEvent [unknown:512] - org.eclipse.smarthome.automation.module.script.rulesupport
2018-10-09 06:55:27.279 [DEBUG] [automation.module.script.rulesupport] - BundleEvent STARTING - org.eclipse.smarthome.automation.module.script.rulesupport
2018-10-09 06:55:27.286 [DEBUG] [automation.module.script.rulesupport] - BundleEvent STARTED - org.eclipse.smarthome.automation.module.script.rulesupport
2018-10-09 06:55:27.301 [DEBUG] [e.smarthome.automation.module.script] - BundleEvent STARTING - org.eclipse.smarthome.automation.module.script
2018-10-09 06:55:27.307 [DEBUG] [e.smarthome.automation.module.script] - BundleEvent STARTED - org.eclipse.smarthome.automation.module.script
2018-10-09 06:55:27.398 [INFO ] [.internal.GenericScriptEngineFactory] - Activated scripting support for ECMAScript
2018-10-09 06:55:27.412 [DEBUG] [.internal.GenericScriptEngineFactory] - Activated scripting support with engine Oracle Nashorn(1.8.0_152) for ECMAScript(ECMA - 262 Edition 5.1) with mimetypes [application/javascript, application/ecmascript, text/javascript, text/ecmascript] and file extensions [js]
2018-10-09 06:55:28.009 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - in queue: {py=[file:/etc/openhab2/automation/jsr223/100_components/000_JythonExtensionProvider.py]}
2018-10-09 06:55:28.024 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - in queue: {py=[file:/etc/openhab2/automation/jsr223/100_components/000_JythonExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/100_ExampleExtensionProvider.py]}
2018-10-09 06:55:28.037 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - in queue: {py=[file:/etc/openhab2/automation/jsr223/100_components/000_JythonExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/100_ExampleExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonTransform.py]}
2018-10-09 06:55:28.051 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - in queue: {py=[file:/etc/openhab2/automation/jsr223/100_components/000_JythonExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonItemProvider.py, file:/etc/openhab2/automation/jsr223/100_components/100_ExampleExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonTransform.py]}
2018-10-09 06:55:28.056 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - in queue: {py=[file:/etc/openhab2/automation/jsr223/100_components/000_JythonThingTypeProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonItemProvider.py, file:/etc/openhab2/automation/jsr223/100_components/100_ExampleExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonTransform.py]}
2018-10-09 06:55:28.060 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - in queue: {py=[file:/etc/openhab2/automation/jsr223/100_components/000_JythonThingTypeProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_Esper.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonItemProvider.py, file:/etc/openhab2/automation/jsr223/100_components/100_ExampleExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonTransform.py]}
2018-10-09 06:55:28.076 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - in queue: {md=[file:/etc/openhab2/automation/jsr223/100_components/README.md], py=[file:/etc/openhab2/automation/jsr223/100_components/000_JythonThingTypeProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_Esper.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonItemProvider.py, file:/etc/openhab2/automation/jsr223/100_components/100_ExampleExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonTransform.py]}
2018-10-09 06:55:28.081 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - in queue: {md=[file:/etc/openhab2/automation/jsr223/100_components/README.md], py=[file:/etc/openhab2/automation/jsr223/100_components/000_DirectoryTrigger.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonThingTypeProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_Esper.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonItemProvider.py, file:/etc/openhab2/automation/jsr223/100_components/100_ExampleExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonTransform.py]}
2018-10-09 06:55:28.085 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - in queue: {md=[file:/etc/openhab2/automation/jsr223/100_components/README.md], py=[file:/etc/openhab2/automation/jsr223/100_components/000_DirectoryTrigger.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonThingTypeProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_Esper.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonItemProvider.py, file:/etc/openhab2/automation/jsr223/100_components/100_ExampleExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonThingProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonTransform.py]}
2018-10-09 06:55:28.093 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - in queue: {md=[file:/etc/openhab2/automation/jsr223/100_components/README.md], py=[file:/etc/openhab2/automation/jsr223/100_components/000_DirectoryTrigger.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonThingTypeProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_Esper.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonItemProvider.py, file:/etc/openhab2/automation/jsr223/100_components/100_ExampleExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonThingProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonBindingInfoProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonTransform.py]}
2018-10-09 06:55:28.100 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - in queue: {md=[file:/etc/openhab2/automation/jsr223/100_components/README.md], py=[file:/etc/openhab2/automation/jsr223/100_components/000_DirectoryTrigger.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonThingTypeProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_StartupTrigger.py, file:/etc/openhab2/automation/jsr223/100_components/000_Esper.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonItemProvider.py, file:/etc/openhab2/automation/jsr223/100_components/100_ExampleExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonThingProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonBindingInfoProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonTransform.py]}
2018-10-09 06:55:28.107 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - in queue: {md=[file:/etc/openhab2/automation/jsr223/100_components/README.md], py=[file:/etc/openhab2/automation/jsr223/100_components/000_DirectoryTrigger.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonThingTypeProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_OsgiEventTrigger.py, file:/etc/openhab2/automation/jsr223/100_components/000_StartupTrigger.py, file:/etc/openhab2/automation/jsr223/100_components/000_Esper.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonItemProvider.py, file:/etc/openhab2/automation/jsr223/100_components/100_ExampleExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonThingProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonBindingInfoProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonTransform.py]}
2018-10-09 06:55:28.112 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - in queue: {md=[file:/etc/openhab2/automation/jsr223/100_components/README.md], py=[file:/etc/openhab2/automation/jsr223/100_components/000_DirectoryTrigger.py, file:/etc/openhab2/automation/jsr223/000_startup.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonThingTypeProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_OsgiEventTrigger.py, file:/etc/openhab2/automation/jsr223/100_components/000_StartupTrigger.py, file:/etc/openhab2/automation/jsr223/100_components/000_Esper.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonItemProvider.py, file:/etc/openhab2/automation/jsr223/100_components/100_ExampleExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonThingProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonBindingInfoProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonTransform.py]}
2018-10-09 06:55:28.117 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - in queue: {md=[file:/etc/openhab2/automation/jsr223/100_components/README.md], py=[file:/etc/openhab2/automation/jsr223/100_components/000_DirectoryTrigger.py, file:/etc/openhab2/automation/jsr223/100_components/000_OsgiEventTrigger.py, file:/etc/openhab2/automation/jsr223/100_components/000_StartupTrigger.py, file:/etc/openhab2/automation/jsr223/000_startup.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonThingTypeProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonExtensionProvider.py, file:/etc/openhab2/automation/jsr223/test.py, file:/etc/openhab2/automation/jsr223/100_components/000_Esper.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonItemProvider.py, file:/etc/openhab2/automation/jsr223/100_components/100_ExampleExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonThingProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonBindingInfoProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonTransform.py]}
2018-10-09 06:55:28.161 [DEBUG] [automation.module.script.rulesupport] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.module.script.rulesupport.internal.ScriptedCustomModuleHandlerFactory}={service.id=124, service.bundleid=220, service.scope=bundle, component.name=org.eclipse.smarthome.automation.module.script.rulesupport.internal.ScriptedCustomModuleHandlerFactory, component.id=21} - org.eclipse.smarthome.automation.module.script.rulesupport
2018-10-09 06:55:28.191 [DEBUG] [automation.module.script.rulesupport] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.type.ModuleTypeProvider, org.eclipse.smarthome.automation.module.script.rulesupport.internal.ScriptedCustomModuleTypeProvider}={service.id=125, service.bundleid=220, service.scope=bundle, component.name=org.eclipse.smarthome.automation.module.script.rulesupport.internal.ScriptedCustomModuleTypeProvider, component.id=22} - org.eclipse.smarthome.automation.module.script.rulesupport
2018-10-09 06:55:28.213 [DEBUG] [automation.module.script.rulesupport] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.handler.ModuleHandlerFactory, org.eclipse.smarthome.automation.module.script.rulesupport.internal.ScriptedPrivateModuleHandlerFactory}={service.id=126, service.bundleid=220, service.scope=bundle, component.name=org.eclipse.smarthome.automation.module.script.rulesupport.internal.ScriptedPrivateModuleHandlerFactory, component.id=23} - org.eclipse.smarthome.automation.module.script.rulesupport
2018-10-09 06:55:28.226 [DEBUG] [automation.module.script.rulesupport] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.RuleProvider, org.eclipse.smarthome.automation.module.script.rulesupport.shared.ScriptedRuleProvider}={service.id=127, service.bundleid=220, service.scope=bundle, component.name=org.eclipse.smarthome.automation.module.script.rulesupport.shared.ScriptedRuleProvider, component.id=24} - org.eclipse.smarthome.automation.module.script.rulesupport
2018-10-09 06:55:31.372 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2018-10-09 06:55:31.489 [INFO ] [ebuilder.internal.HomeBuilderServlet] - Started Home Builder at /homebuilder
2018-10-09 06:55:31.773 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to '30.970544333076077,-88.28427383194284'.
2018-10-09 06:55:32.852 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://10.0.1.26:8080
2018-10-09 06:55:32.857 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://10.0.1.26:8443
2018-10-09 06:55:33.768 [DEBUG] [se.smarthome.automation.module.media] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.type.ModuleTypeProvider}={service.id=191, service.bundleid=217, service.scope=bundle, component.name=org.eclipse.smarthome.automation.module.media.internal.MediaActionTypeProvider, component.id=12} - org.eclipse.smarthome.automation.module.media
2018-10-09 06:55:33.780 [DEBUG] [se.smarthome.automation.module.media] - BundleEvent STARTING - org.eclipse.smarthome.automation.module.media
2018-10-09 06:55:33.789 [DEBUG] [se.smarthome.automation.module.media] - BundleEvent STARTED - org.eclipse.smarthome.automation.module.media
2018-10-09 06:55:37.402 [DEBUG] [se.smarthome.automation.module.media] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.handler.ModuleHandlerFactory}={service.id=224, service.bundleid=217, service.scope=bundle, component.name=org.eclipse.smarthome.automation.module.media.internal.MediaModuleHandlerFactory, component.id=13} - org.eclipse.smarthome.automation.module.media
2018-10-09 06:55:37.430 [DEBUG] [se.smarthome.automation.module.media] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.module.script.ScriptExtensionProvider}={service.id=225, service.bundleid=217, service.scope=bundle, component.name=org.eclipse.smarthome.automation.module.media.internal.MediaScriptScopeProvider, component.id=14} - org.eclipse.smarthome.automation.module.media
2018-10-09 06:55:51.917 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2018-10-09 06:55:56.387 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2018-10-09 06:55:56.706 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2018-10-09 06:55:57.927 [DEBUG] [org.eclipse.smarthome.automation.api] - BundleEvent STARTING - org.eclipse.smarthome.automation.api
2018-10-09 06:55:57.946 [DEBUG] [org.eclipse.smarthome.automation.api] - BundleEvent STARTED - org.eclipse.smarthome.automation.api
2018-10-09 06:55:57.957 [DEBUG] [clipse.smarthome.automation.commands] - BundleEvent STARTING - org.eclipse.smarthome.automation.commands
2018-10-09 06:55:57.991 [DEBUG] [clipse.smarthome.automation.commands] - BundleEvent STARTED - org.eclipse.smarthome.automation.commands
2018-10-09 06:55:58.004 [DEBUG] [rg.eclipse.smarthome.automation.core] - BundleEvent STARTING - org.eclipse.smarthome.automation.core
2018-10-09 06:55:58.047 [DEBUG] [rg.eclipse.smarthome.automation.core] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.type.ModuleTypeRegistry}={service.id=349, service.bundleid=215, service.scope=bundle, component.name=org.eclipse.smarthome.automation.core.internal.type.ModuleTypeRegistryImpl, component.id=215} - org.eclipse.smarthome.automation.core
2018-10-09 06:55:58.156 [DEBUG] [rg.eclipse.smarthome.automation.core] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.RuleManager, org.eclipse.smarthome.core.common.registry.RegistryChangeListener}={service.id=352, service.bundleid=215, service.scope=bundle, component.name=org.eclipse.smarthome.automation.core.internal.RuleEngineImpl, component.id=216} - org.eclipse.smarthome.automation.core
2018-10-09 06:55:58.262 [DEBUG] [omation.core.internal.RuleEngineImpl] - ModuleHandlerFactory added.
2018-10-09 06:55:58.269 [DEBUG] [omation.core.internal.RuleEngineImpl] - ModuleHandlerFactory added.
2018-10-09 06:55:58.275 [DEBUG] [omation.core.internal.RuleEngineImpl] - ModuleHandlerFactory added.
2018-10-09 06:55:58.292 [DEBUG] [rg.eclipse.smarthome.automation.core] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.RuleRegistry}={service.id=351, service.bundleid=215, service.scope=bundle, rule.reinitialization.delay=500, component.name=org.eclipse.smarthome.automation.core.internal.RuleRegistryImpl, component.id=217} - org.eclipse.smarthome.automation.core
2018-10-09 06:55:58.334 [DEBUG] [automation.module.script.rulesupport] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.module.script.ScriptExtensionProvider}={service.id=353, service.bundleid=220, service.scope=bundle, component.name=org.eclipse.smarthome.automation.module.script.rulesupport.internal.LoaderScriptExtension, component.id=20} - org.eclipse.smarthome.automation.module.script.rulesupport
2018-10-09 06:55:58.391 [DEBUG] [clipse.smarthome.automation.commands] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.type.ModuleTypeProvider}={service.id=355, service.bundleid=214, service.scope=singleton} - org.eclipse.smarthome.automation.commands
2018-10-09 06:55:58.406 [DEBUG] [clipse.smarthome.automation.commands] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.template.RuleTemplateProvider}={service.id=356, service.bundleid=214, service.scope=singleton} - org.eclipse.smarthome.automation.commands
2018-10-09 06:55:58.416 [DEBUG] [clipse.smarthome.automation.commands] - ServiceEvent REGISTERED - {org.eclipse.smarthome.io.console.extensions.ConsoleCommandExtension}={service.id=354, service.bundleid=214, service.scope=bundle, component.name=org.eclipse.smarthome.automation.internal.commands.AutomationCommandsPluggable, component.id=214} - org.eclipse.smarthome.automation.commands
2018-10-09 06:55:58.422 [DEBUG] [rg.eclipse.smarthome.automation.core] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.template.TemplateRegistry, org.eclipse.smarthome.automation.core.internal.template.RuleTemplateRegistry}={service.id=350, service.bundleid=215, service.scope=bundle, component.name=org.eclipse.smarthome.automation.core.internal.template.RuleTemplateRegistry, component.id=218} - org.eclipse.smarthome.automation.core
2018-10-09 06:55:58.430 [DEBUG] [rg.eclipse.smarthome.automation.core] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventFactory}={service.id=357, service.bundleid=215, service.scope=bundle, component.name=org.eclipse.smarthome.automation.core.internal.RuleEventFactory, component.id=219} - org.eclipse.smarthome.automation.core
2018-10-09 06:55:58.465 [DEBUG] [rg.eclipse.smarthome.automation.core] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.RuleProvider, org.eclipse.smarthome.automation.core.ManagedRuleProvider}={service.id=358, service.bundleid=215, service.scope=bundle, component.name=org.eclipse.smarthome.automation.core.ManagedRuleProvider, component.id=220} - org.eclipse.smarthome.automation.core
2018-10-09 06:55:58.474 [DEBUG] [rg.eclipse.smarthome.automation.core] - BundleEvent STARTED - org.eclipse.smarthome.automation.core
2018-10-09 06:55:58.484 [DEBUG] [pse.smarthome.automation.module.core] - BundleEvent STARTING - org.eclipse.smarthome.automation.module.core
2018-10-09 06:55:58.514 [DEBUG] [omation.core.internal.RuleEngineImpl] - ModuleHandlerFactory added.
2018-10-09 06:55:58.519 [DEBUG] [pse.smarthome.automation.module.core] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.handler.ModuleHandlerFactory}={service.id=359, service.bundleid=216, service.scope=bundle, component.name=org.eclipse.smarthome.automation.module.core.factory.CoreModuleHandlerFactory, component.id=221} - org.eclipse.smarthome.automation.module.core
2018-10-09 06:55:58.531 [DEBUG] [pse.smarthome.automation.module.core] - BundleEvent STARTED - org.eclipse.smarthome.automation.module.core
2018-10-09 06:55:58.540 [DEBUG] [utomation.module.script.defaultscope] - BundleEvent STARTING - org.eclipse.smarthome.automation.module.script.defaultscope
2018-10-09 06:55:58.605 [DEBUG] [utomation.module.script.defaultscope] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.module.script.ScriptExtensionProvider}={service.id=360, service.bundleid=219, service.scope=bundle, component.name=org.eclipse.smarthome.automation.module.script.globals, component.id=222} - org.eclipse.smarthome.automation.module.script.defaultscope
2018-10-09 06:55:58.614 [DEBUG] [utomation.module.script.defaultscope] - BundleEvent STARTED - org.eclipse.smarthome.automation.module.script.defaultscope
2018-10-09 06:55:58.623 [DEBUG] [se.smarthome.automation.module.timer] - BundleEvent STARTING - org.eclipse.smarthome.automation.module.timer
2018-10-09 06:55:58.636 [DEBUG] [omation.core.internal.RuleEngineImpl] - ModuleHandlerFactory added.
2018-10-09 06:55:58.640 [DEBUG] [se.smarthome.automation.module.timer] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.handler.ModuleHandlerFactory}={service.id=361, service.bundleid=221, service.scope=singleton} - org.eclipse.smarthome.automation.module.timer
2018-10-09 06:55:58.647 [DEBUG] [tion.module.timer.internal.Activator] - started bundle timer.module
2018-10-09 06:55:58.653 [DEBUG] [se.smarthome.automation.module.timer] - BundleEvent STARTED - org.eclipse.smarthome.automation.module.timer
2018-10-09 06:55:58.661 [DEBUG] [pse.smarthome.automation.parser.gson] - BundleEvent STARTING - org.eclipse.smarthome.automation.parser.gson
2018-10-09 06:55:58.698 [DEBUG] [pse.smarthome.automation.parser.gson] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.parser.Parser}={service.id=362, service.bundleid=222, service.scope=bundle, parser.type=parser.rule, component.name=org.eclipse.smarthome.automation.parser.gson.rule, format=json, component.id=223} - org.eclipse.smarthome.automation.parser.gson
2018-10-09 06:55:58.712 [DEBUG] [pse.smarthome.automation.parser.gson] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.parser.Parser}={service.id=363, service.bundleid=222, service.scope=bundle, parser.type=parser.module.type, component.name=org.eclipse.smarthome.automation.parser.gson.moduletype, format=json, component.id=224} - org.eclipse.smarthome.automation.parser.gson
2018-10-09 06:55:58.725 [DEBUG] [pse.smarthome.automation.parser.gson] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.parser.Parser}={service.id=364, service.bundleid=222, service.scope=bundle, parser.type=parser.template, component.name=org.eclipse.smarthome.automation.parser.gson.template, format=json, component.id=225} - org.eclipse.smarthome.automation.parser.gson
2018-10-09 06:55:58.733 [DEBUG] [pse.smarthome.automation.parser.gson] - BundleEvent STARTED - org.eclipse.smarthome.automation.parser.gson
2018-10-09 06:55:58.746 [DEBUG] [lipse.smarthome.automation.providers] - BundleEvent STARTING - org.eclipse.smarthome.automation.providers
2018-10-09 06:55:58.783 [DEBUG] [lipse.smarthome.automation.providers] - ServiceEvent REGISTERED - {org.osgi.util.tracker.BundleTrackerCustomizer}={service.id=365, service.bundleid=223, service.scope=bundle, Parser.target=(parser.type=parser.rule), Provider.target=(provider.type=bundle), component.name=org.eclipse.smarthome.automation.internal.core.provider.AutomationResourceBundlesTracker, component.id=226} - org.eclipse.smarthome.automation.providers
2018-10-09 06:55:59.370 [DEBUG] [.AutomationResourceBundlesEventQueue] - Process bundle event 2, for automation bundle 'org.eclipse.smarthome.automation.module.core'
2018-10-09 06:55:59.382 [DEBUG] [.AutomationResourceBundlesEventQueue] - Process bundle event 2, for automation bundle 'org.eclipse.smarthome.automation.module.script'
2018-10-09 06:55:59.386 [DEBUG] [.provider.RuleResourceBundleImporter] - Parse rules from bundle 'org.eclipse.smarthome.automation.module.core'
2018-10-09 06:55:59.389 [DEBUG] [.AutomationResourceBundlesEventQueue] - Process bundle event 2, for automation bundle 'org.eclipse.smarthome.automation.module.script.rulesupport'
2018-10-09 06:55:59.393 [DEBUG] [.provider.RuleResourceBundleImporter] - Parse rules from bundle 'org.eclipse.smarthome.automation.module.script'
2018-10-09 06:55:59.393 [DEBUG] [.AutomationResourceBundlesEventQueue] - Process bundle event 2, for automation bundle 'org.eclipse.smarthome.automation.module.timer'
2018-10-09 06:55:59.398 [DEBUG] [.provider.RuleResourceBundleImporter] - Parse rules from bundle 'org.eclipse.smarthome.automation.module.script.rulesupport'
2018-10-09 06:55:59.401 [DEBUG] [.provider.RuleResourceBundleImporter] - Parse rules from bundle 'org.eclipse.smarthome.automation.module.timer'
2018-10-09 06:55:59.426 [DEBUG] [lipse.smarthome.automation.providers] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.type.ModuleTypeProvider, org.eclipse.smarthome.core.common.registry.Provider}={service.id=366, provider.type=bundle, service.bundleid=223, service.scope=bundle, Parser.target=(parser.type=parser.module.type), component.name=org.eclipse.smarthome.automation.internal.core.provider.ModuleTypeResourceBundleProvider, component.id=227} - org.eclipse.smarthome.automation.providers
2018-10-09 06:55:59.459 [DEBUG] [lipse.smarthome.automation.providers] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.template.RuleTemplateProvider, org.eclipse.smarthome.core.common.registry.Provider}={service.id=367, provider.type=bundle, service.bundleid=223, service.scope=bundle, Parser.target=(parser.type=parser.template), component.name=org.eclipse.smarthome.automation.internal.core.provider.TemplateResourceBundleProvider, component.id=228} - org.eclipse.smarthome.automation.providers
2018-10-09 06:55:59.472 [DEBUG] [lipse.smarthome.automation.providers] - BundleEvent STARTED - org.eclipse.smarthome.automation.providers
2018-10-09 06:55:59.478 [DEBUG] [rg.eclipse.smarthome.automation.rest] - BundleEvent STARTING - org.eclipse.smarthome.automation.rest
2018-10-09 06:55:59.519 [DEBUG] [rg.eclipse.smarthome.automation.rest] - ServiceEvent REGISTERED - {org.eclipse.smarthome.io.rest.RESTResource}={service.id=368, service.bundleid=224, service.scope=bundle, component.name=org.eclipse.smarthome.automation.rest.internal.ModuleTypeResource, component.id=229} - org.eclipse.smarthome.automation.rest
2018-10-09 06:55:59.558 [DEBUG] [rg.eclipse.smarthome.automation.rest] - ServiceEvent REGISTERED - {org.eclipse.smarthome.io.rest.RESTResource}={service.id=369, service.bundleid=224, service.scope=bundle, component.name=org.eclipse.smarthome.automation.rest.internal.RuleResource, component.id=230} - org.eclipse.smarthome.automation.rest
2018-10-09 06:55:59.585 [DEBUG] [rg.eclipse.smarthome.automation.rest] - ServiceEvent REGISTERED - {org.eclipse.smarthome.io.rest.RESTResource}={service.id=370, service.bundleid=224, service.scope=bundle, component.name=org.eclipse.smarthome.automation.rest.internal.TemplateResource, component.id=231} - org.eclipse.smarthome.automation.rest
2018-10-09 06:55:59.593 [DEBUG] [rg.eclipse.smarthome.automation.rest] - BundleEvent STARTED - org.eclipse.smarthome.automation.rest
2018-10-09 06:58:50.083 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - in queue: {md=[file:/etc/openhab2/automation/jsr223/100_components/README.md], py=[file:/etc/openhab2/automation/jsr223/100_components/000_DirectoryTrigger.py, file:/etc/openhab2/automation/jsr223/100_components/000_OsgiEventTrigger.py, file:/etc/openhab2/automation/jsr223/100_components/000_StartupTrigger.py, file:/etc/openhab2/automation/jsr223/000_startup.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonThingTypeProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonExtensionProvider.py, file:/etc/openhab2/automation/jsr223/test.py, file:/etc/openhab2/automation/jsr223/100_components/000_Esper.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonItemProvider.py, file:/etc/openhab2/automation/jsr223/100_components/100_ExampleExtensionProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonThingProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonBindingInfoProvider.py, file:/etc/openhab2/automation/jsr223/100_components/000_JythonTransform.py]}
2018-10-09 06:58:50.091 [INFO ] [rt.internal.loader.ScriptFileWatcher] - ScriptEngine for py not available
I copied the jar file back to /usr/share/openhab2/runtime/lib/boot, renamed 000_components and all the file inside to 100_… then restarted with this log.
2018-10-09 07:48:20.910 [INFO ] [eclipse.smarthome.model.script.Rules] - JSR223: Startup: Checking for initialized context
2018-10-09 07:48:20.936 [INFO ] [eclipse.smarthome.model.script.Rules] - JSR223: Startup: context initialized... waiting 30s before allowing files to load
2018-10-09 07:48:50.941 [INFO ] [eclipse.smarthome.model.script.Rules] - JSR223: Startup: Complete
2018-10-09 07:48:50.947 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - Script loaded: 000_startup.py
2018-10-09 07:48:50.952 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script '100_components/100_DirectoryTrigger.py'
2018-10-09 07:48:51.402 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/etc/openhab2/automation/jsr223/100_components/100_DirectoryTrigger.py': ImportError: No module named openhab in <script> at line number 8
2018-10-09 07:48:51.405 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - Script loaded: 100_components/100_DirectoryTrigger.py
2018-10-09 07:48:51.409 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script '100_components/100_Esper.py'
2018-10-09 07:48:53.300 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/etc/openhab2/automation/jsr223/100_components/100_Esper.py': ImportError: No module named esper in <script> at line number 3
2018-10-09 07:48:53.306 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - Script loaded: 100_components/100_Esper.py
2018-10-09 07:48:53.310 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script '100_components/100_ExampleExtensionProvider.py'
2018-10-09 07:48:53.467 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/etc/openhab2/automation/jsr223/100_components/100_ExampleExtensionProvider.py': ImportError: No module named openhab in <script> at line number 1
2018-10-09 07:48:53.470 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - Script loaded: 100_components/100_ExampleExtensionProvider.py
2018-10-09 07:48:53.474 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script '100_components/100_JythonBindingInfoProvider.py'
2018-10-09 07:48:53.666 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/etc/openhab2/automation/jsr223/100_components/100_JythonBindingInfoProvider.py': ImportError: No module named openhab in <script> at line number 3
2018-10-09 07:48:53.669 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - Script loaded: 100_components/100_JythonBindingInfoProvider.py
2018-10-09 07:48:53.676 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script '100_components/100_JythonExtensionProvider.py'
2018-10-09 07:48:57.432 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/etc/openhab2/automation/jsr223/100_components/100_JythonExtensionProvider.py': ImportError: No module named openhab in <script> at line number 3
2018-10-09 07:48:57.436 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - Script loaded: 100_components/100_JythonExtensionProvider.py
2018-10-09 07:48:57.440 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script '100_components/100_JythonItemProvider.py'
2018-10-09 07:48:57.599 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/etc/openhab2/automation/jsr223/100_components/100_JythonItemProvider.py': ImportError: No module named openhab in <script> at line number 3
2018-10-09 07:48:57.602 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - Script loaded: 100_components/100_JythonItemProvider.py
2018-10-09 07:48:57.605 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script '100_components/100_JythonThingProvider.py'
2018-10-09 07:48:57.762 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/etc/openhab2/automation/jsr223/100_components/100_JythonThingProvider.py': ImportError: No module named openhab in <script> at line number 3
2018-10-09 07:48:57.764 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - Script loaded: 100_components/100_JythonThingProvider.py
2018-10-09 07:48:57.768 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script '100_components/100_JythonThingTypeProvider.py'
2018-10-09 07:48:57.909 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/etc/openhab2/automation/jsr223/100_components/100_JythonThingTypeProvider.py': ImportError: No module named openhab in <script> at line number 3
2018-10-09 07:48:57.966 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - Script loaded: 100_components/100_JythonThingTypeProvider.py
2018-10-09 07:48:57.969 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script '100_components/100_JythonTransform.py'
2018-10-09 07:48:58.196 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/etc/openhab2/automation/jsr223/100_components/100_JythonTransform.py': ImportError: No module named openhab in <script> at line number 3
2018-10-09 07:48:58.199 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - Script loaded: 100_components/100_JythonTransform.py
2018-10-09 07:48:58.203 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script '100_components/100_OsgiEventTrigger.py'
2018-10-09 07:48:59.513 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/etc/openhab2/automation/jsr223/100_components/100_OsgiEventTrigger.py': ImportError: No module named openhab in <script> at line number 10
2018-10-09 07:48:59.515 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - Script loaded: 100_components/100_OsgiEventTrigger.py
2018-10-09 07:48:59.519 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script '100_components/100_StartupTrigger.py'
2018-10-09 07:48:59.653 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/etc/openhab2/automation/jsr223/100_components/100_StartupTrigger.py': ImportError: No module named openhab in <script> at line number 4
2018-10-09 07:48:59.655 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - Script loaded: 100_components/100_StartupTrigger.py
2018-10-09 07:48:59.659 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'test.py'
2018-10-09 07:48:59.762 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - Script loaded: test.py
2018-10-09 07:48:59.766 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'test1.py'
2018-10-09 07:48:59.799 [INFO ] [clipse.smarthome.automation.examples] - Hello world!
2018-10-09 07:48:59.802 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - Script loaded: test1.py
The hello world and the time out script worked but nothing from:
from org.slf4j import Logger, LoggerFactory
log = LoggerFactory.getLogger("org.eclipse.smarthome.model.script.Rules")
import sys
log.debug("JSR223: version=[{}]".format(sys.version))
log.debug("JSR223: path=[{}]".format(sys.path))
I’ve been able to reproduce this on a clean install… still investigating…
I noticed in post #17 inside python you have openhab only and I have esper and openhab. Not sure what that means but moving it to a temp dir didn’t seem to change anything.
Here’s what it looks like now, notice the openhab2-conf (this may be due to samba share)
I’ve also tried changing permission in automation/lib/python/openhab for all files so they matched triggering.py (chmod a+x on all) No change.
Did you notice my earlier log, at the top, BundleEvent [unknown:512]?
I have some free time so I’ll keep poking around, can’t break broke.
This is what causes the log entry, but I haven’t figured out why the script engine wouldn’t be loaded.
My gut is telling me it is a timing issue. My production system is running the same OH and does not have the issue. I may try loading up the test system to slow down the startup.
The only way I’ve been able to get the logs above is having .jar in /usr/share/openhab2/runtime/boot. I guess this is OK for now?
Any idea what may be causing “ImportError: No module named openhab in <script> at line number 4” on all scripts in jsr223/000_components?
Same issue. You moved the Jython jar into the classpath, but OH is not able to see the modules. You will want to go back to the way it is described in the doc. Just need to figure out why the engine isn’t loading.
I tried doing JSR223 about a month ago and ended up messing up the entire OH install.
Ready to try again, fresh Openhabian install on PI3B. Have reviewed many threads on how to do it but there seems to be conflicting information and I am not sure what to do.
Python3 is installed on the PI from using another program. Its installed in /usr/lib/python3
Do I need to upgrade from OH2.3? What JAR do I need?
Mike
I’m happy to help, but there may be an issue in the latest snapshot. You will want to be on a recent snapshot or milestone build. This is where I suggest to start…
… so you can use this…
Hi Scott,
Still a relative OH and Linux newbie…so bare with me…
I am on 2.3 - Release Build. Do I need to be on the 2.4 package?
The only stupid question is the one you don’t ask… unless it was if I’d like a !
Need… no. Want… yes. I tried to explain in the readme. The Automation API has been pretty well reworked in the OH 2.4 snapshot builds, which some has made into the test/milestone builds. The decorators I wrote will need the updated API.
ok, i’ll upgrade to the snap shot build.
@5iver I’m testing on a RPI 2 maybe Michael’s RPI 3 will work?
Another piece to the puzzle… Javascript rules are working.