How to Setup Jython

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:

Screenshot%20at%202018-10-09%2007-05-53

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)
Screenshot%20at%202018-10-09%2010-30-35

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.:grin:

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 :beer:!

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.