I’m trying to use the JSR223 rule engine with Jython (I also tried Javascript for testing) and noted that the rule is not correctly loaded at startup:
13:11:33.040 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/etc/openhab2/automation/jsr223/log.py': NameError: name 'SimpleRule' is not defined in <script> at line number 4
13:11:33.053 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - Script loaded: log.py
It seems that the necessary bundles are loaded a little bit later, but there are still some errors:
13:12:02.915 [DEBUG] [org.eclipse.smarthome.automation.api] - BundleEvent STARTING - org.eclipse.smarthome.automation.api
13:12:02.929 [DEBUG] [org.eclipse.smarthome.automation.api] - BundleEvent STARTED - org.eclipse.smarthome.automation.api
13:12:02.962 [DEBUG] [clipse.smarthome.automation.commands] - BundleEvent STARTING - org.eclipse.smarthome.automation.commands
13:12:02.970 [DEBUG] [clipse.smarthome.automation.commands] - BundleEvent STARTED - org.eclipse.smarthome.automation.commands
13:12:03.038 [DEBUG] [rg.eclipse.smarthome.automation.core] - BundleEvent STARTING - org.eclipse.smarthome.automation.core
13:12:03.046 [DEBUG] [rg.eclipse.smarthome.automation.core] - BundleEvent STARTED - org.eclipse.smarthome.automation.core
13:12:03.142 [DEBUG] [rg.eclipse.smarthome.automation.core] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.RuleProvider, org.eclipse.smarthome.automation.ManagedRuleProvider}={component.name=org.eclipse.smarthome.automation.managedruleprovider, component.id=213, service.id=336, service.bundleid=263, service.scope=bundle} - org.eclipse.smarthome.automation.core
13:12:03.147 [INFO ] [marthome.event.ItemStateChangedEvent] - lab_signal changed from 52 to 50
13:12:03.175 [INFO ] [marthome.event.ItemStateChangedEvent] - lab_uptime changed from 318625 to 318685
13:12:03.250 [DEBUG] [rg.eclipse.smarthome.automation.core] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.type.ModuleTypeRegistry}={component.name=org.eclipse.smarthome.automation.type.moduletyperegistry, component.id=214, service.id=337, service.bundleid=263, service.scope=bundle} - org.eclipse.smarthome.automation.core
13:12:03.398 [INFO ] [marthome.event.ItemStateChangedEvent] - ian_b_signal changed from 28 to 26
13:12:03.438 [INFO ] [marthome.event.ItemStateChangedEvent] - ian_b_uptime changed from 318679 to 318739
13:12:03.518 [DEBUG] [rg.eclipse.smarthome.automation.core] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventFactory}={component.name=org.eclipse.smarthome.automation.events.ruleeventfactory, component.id=215, service.id=338, service.bundleid=263, service.scope=bundle} - org.eclipse.smarthome.automation.core
13:12:03.582 [DEBUG] [rg.eclipse.smarthome.automation.core] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.RuleRegistry}={rule.reinitialization.delay=500, component.name=org.eclipse.smarthome.automation.ruleregistry, component.id=216, service.id=340, service.bundleid=263, service.scope=bundle} - org.eclipse.smarthome.automation.core
13:12:03.608 [DEBUG] [automation.module.script.rulesupport] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.module.script.ScriptExtensionProvider}={component.name=org.eclipse.smarthome.automation.module.script.rulesupport.internal.LoaderScriptExtension, component.id=17, service.id=341, service.bundleid=268, service.scope=bundle} - org.eclipse.smarthome.automation.module.script.rulesupport
13:12:03.916 [DEBUG] [.automation.core.internal.RuleEngine] - ModuleHandlerFactory added.
13:12:03.933 [DEBUG] [.automation.core.internal.RuleEngine] - ModuleHandlerFactory added.
13:12:03.945 [DEBUG] [.automation.core.internal.RuleEngine] - ModuleHandlerFactory added.
13:12:03.950 [DEBUG] [.automation.core.internal.RuleEngine] - ModuleHandlerFactory added.
13:12:04.235 [INFO ] [smarthome.event.RuleAddedEvent ] - Rule 'rule_2' has been added.
13:12:04.306 [INFO ] [smarthome.event.RuleStatusInfoEvent ] - rule_2 updated: INITIALIZING
13:12:04.330 [INFO ] [smarthome.event.RuleStatusInfoEvent ] - rule_2 updated: UNINITIALIZED (CONFIGURATION_ERROR): Validation of rule rule_2 has failed! Action Type "core.ItemCommandAction" does not exist!
13:12:04.338 [INFO ] [smarthome.event.RuleAddedEvent ] - Rule 'rule_1' has been added.
13:12:04.348 [INFO ] [smarthome.event.RuleStatusInfoEvent ] - rule_1 updated: INITIALIZING
13:12:04.352 [INFO ] [smarthome.event.RuleStatusInfoEvent ] - rule_1 updated: UNINITIALIZED (CONFIGURATION_ERROR): Validation of rule rule_1 has failed! Action Type "core.ItemCommandAction" does not exist!
13:12:04.716 [DEBUG] [clipse.smarthome.automation.commands] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.type.ModuleTypeProvider}={service.id=343, service.bundleid=262, service.scope=singleton} - org.eclipse.smarthome.automation.commands
13:12:04.767 [DEBUG] [clipse.smarthome.automation.commands] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.template.RuleTemplateProvider}={service.id=344, service.bundleid=262, service.scope=singleton} - org.eclipse.smarthome.automation.commands
13:12:04.788 [DEBUG] [clipse.smarthome.automation.commands] - ServiceEvent REGISTERED - {org.eclipse.smarthome.io.console.extensions.ConsoleCommandExtension}={component.name=org.eclipse.smarthome.automation.commands, component.id=212, service.id=342, service.bundleid=262, service.scope=bundle} - org.eclipse.smarthome.automation.commands
13:12:04.799 [DEBUG] [rg.eclipse.smarthome.automation.core] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.template.TemplateRegistry}={component.name=org.eclipse.smarthome.automation.template.templateregistry, component.id=217, service.id=339, service.bundleid=263, service.scope=bundle} - org.eclipse.smarthome.automation.core
13:12:04.848 [DEBUG] [pse.smarthome.automation.module.core] - BundleEvent STARTING - org.eclipse.smarthome.automation.module.core
13:12:04.858 [DEBUG] [pse.smarthome.automation.module.core] - BundleEvent STARTED - org.eclipse.smarthome.automation.module.core
13:12:05.024 [DEBUG] [.automation.core.internal.RuleEngine] - ModuleHandlerFactory added.
13:12:05.046 [INFO ] [marthome.event.ItemStateChangedEvent] - ian_t_uptime changed from 503159 to 503219
13:12:05.026 [INFO ] [marthome.event.ItemStateChangedEvent] - ian_t_signal changed from 26 to 28
13:12:05.074 [DEBUG] [pse.smarthome.automation.module.core] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.handler.ModuleHandlerFactory}={component.name=org.eclipse.smarthome.automation.module.core.factory.basicmodulehandlerfactory, component.id=218, service.id=345, service.bundleid=264, service.scope=bundle} - org.eclipse.smarthome.automation.module.core
13:12:05.127 [DEBUG] [utomation.module.script.defaultscope] - BundleEvent STARTING - org.eclipse.smarthome.automation.module.script.defaultscope
13:12:05.224 [DEBUG] [utomation.module.script.defaultscope] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.module.script.ScriptExtensionProvider}={component.name=org.eclipse.smarthome.automation.module.script.globals, component.id=219, service.id=346, service.bundleid=267, service.scope=bundle} - org.eclipse.smarthome.automation.module.script.defaultscope
13:12:05.337 [DEBUG] [utomation.module.script.defaultscope] - BundleEvent STARTED - org.eclipse.smarthome.automation.module.script.defaultscope
13:12:05.350 [DEBUG] [se.smarthome.automation.module.timer] - BundleEvent STARTING - org.eclipse.smarthome.automation.module.timer
13:12:05.376 [DEBUG] [.automation.core.internal.RuleEngine] - ModuleHandlerFactory added.
13:12:05.387 [DEBUG] [se.smarthome.automation.module.timer] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.handler.ModuleHandlerFactory}={service.id=347, service.bundleid=269, service.scope=singleton} - org.eclipse.smarthome.automation.module.timer
13:12:05.403 [DEBUG] [tion.module.timer.internal.Activator] - started bundle timer.module
13:12:05.412 [DEBUG] [se.smarthome.automation.module.timer] - BundleEvent STARTED - org.eclipse.smarthome.automation.module.timer
13:12:05.426 [DEBUG] [pse.smarthome.automation.parser.gson] - BundleEvent STARTING - org.eclipse.smarthome.automation.parser.gson
13:12:05.434 [DEBUG] [pse.smarthome.automation.parser.gson] - BundleEvent STARTED - org.eclipse.smarthome.automation.parser.gson
13:12:05.554 [DEBUG] [pse.smarthome.automation.parser.gson] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.parser.Parser}={parser.type=parser.module.type, component.name=org.eclipse.smarthome.automation.parser.gson.moduletype, component.id=220, format=json, service.id=348, service.bundleid=270, service.scope=bundle} - org.eclipse.smarthome.automation.parser.gson
13:12:05.567 [INFO ] [smarthome.event.RuleStatusInfoEvent ] - rule_2 updated: INITIALIZING
13:12:05.627 [INFO ] [smarthome.event.RuleStatusInfoEvent ] - rule_2 updated: UNINITIALIZED (CONFIGURATION_ERROR): Validation of rule rule_2 has failed! Action Type "core.ItemCommandAction" does not exist!
13:12:05.633 [INFO ] [smarthome.event.RuleStatusInfoEvent ] - rule_1 updated: INITIALIZING
13:12:05.647 [DEBUG] [pse.smarthome.automation.parser.gson] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.parser.Parser}={parser.type=parser.rule, component.name=org.eclipse.smarthome.automation.parser.gson.rule, component.id=221, format=json, service.id=349, service.bundleid=270, service.scope=bundle} - org.eclipse.smarthome.automation.parser.gson
13:12:05.695 [DEBUG] [pse.smarthome.automation.parser.gson] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.parser.Parser}={parser.type=parser.template, component.name=org.eclipse.smarthome.automation.parser.gson.template, component.id=222, format=json, service.id=350, service.bundleid=270, service.scope=bundle} - org.eclipse.smarthome.automation.parser.gson
13:12:05.704 [DEBUG] [lipse.smarthome.automation.providers] - BundleEvent STARTING - org.eclipse.smarthome.automation.providers
13:12:05.710 [INFO ] [smarthome.event.RuleStatusInfoEvent ] - rule_1 updated: UNINITIALIZED (CONFIGURATION_ERROR): Validation of rule rule_1 has failed! Action Type "core.ItemCommandAction" does not exist!
13:12:05.712 [DEBUG] [lipse.smarthome.automation.providers] - BundleEvent STARTED - org.eclipse.smarthome.automation.providers
13:12:08.537 [DEBUG] [.AutomationResourceBundlesEventQueue] - Process bundle event 2, for automation bundle 'org.eclipse.smarthome.automation.module.core'
13:12:08.558 [DEBUG] [.AutomationResourceBundlesEventQueue] - Process bundle event 2, for automation bundle 'org.eclipse.smarthome.automation.module.media'
13:12:08.575 [DEBUG] [.AutomationResourceBundlesEventQueue] - Process bundle event 2, for automation bundle 'org.eclipse.smarthome.automation.module.script'
13:12:08.608 [DEBUG] [.AutomationResourceBundlesEventQueue] - Process bundle event 2, for automation bundle 'org.eclipse.smarthome.automation.module.script.rulesupport'
13:12:08.622 [DEBUG] [.provider.RuleResourceBundleImporter] - Parse rules from bundle 'org.eclipse.smarthome.automation.module.core'
13:12:08.631 [DEBUG] [.AutomationResourceBundlesEventQueue] - Process bundle event 2, for automation bundle 'org.eclipse.smarthome.automation.module.timer'
13:12:08.655 [DEBUG] [.provider.RuleResourceBundleImporter] - Parse rules from bundle 'org.eclipse.smarthome.automation.module.media'
13:12:08.657 [DEBUG] [.provider.RuleResourceBundleImporter] - Parse rules from bundle 'org.eclipse.smarthome.automation.module.script'
13:12:08.660 [DEBUG] [.provider.RuleResourceBundleImporter] - Parse rules from bundle 'org.eclipse.smarthome.automation.module.script.rulesupport'
13:12:08.662 [DEBUG] [.provider.RuleResourceBundleImporter] - Parse rules from bundle 'org.eclipse.smarthome.automation.module.timer'
13:12:08.813 [DEBUG] [lipse.smarthome.automation.providers] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.type.ModuleTypeProvider, org.eclipse.smarthome.core.common.registry.Provider}={component.name=org.eclipse.smarthome.automation.provider.ModuleTypeProvider, component.id=224, Parser.target=(parser.type=parser.module.type), provider.type=bundle, service.id=351, service.bundleid=271, service.scope=bundle} - org.eclipse.smarthome.automation.providers
13:12:09.105 [DEBUG] [lipse.smarthome.automation.providers] - ServiceEvent REGISTERED - {org.eclipse.smarthome.automation.template.RuleTemplateProvider, org.eclipse.smarthome.core.common.registry.Provider}={component.name=org.eclipse.smarthome.automation.provider.TemplateProvider, component.id=225, Parser.target=(parser.type=parser.template), provider.type=bundle, service.id=352, service.bundleid=271, service.scope=bundle} - org.eclipse.smarthome.automation.providers
13:12:09.124 [DEBUG] [rg.eclipse.smarthome.automation.rest] - BundleEvent STARTING - org.eclipse.smarthome.automation.rest
13:12:09.159 [DEBUG] [rg.eclipse.smarthome.automation.rest] - BundleEvent STARTED - org.eclipse.smarthome.automation.rest
13:12:09.337 [DEBUG] [rg.eclipse.smarthome.automation.rest] - ServiceEvent REGISTERED - {org.eclipse.smarthome.io.rest.RESTResource}={component.name=org.eclipse.smarthome.automation.rest.moduletype, component.id=226, service.id=353, service.bundleid=272, service.scope=bundle} - org.eclipse.smarthome.automation.rest
13:12:09.424 [DEBUG] [rg.eclipse.smarthome.automation.rest] - ServiceEvent REGISTERED - {org.eclipse.smarthome.io.rest.RESTResource}={component.name=org.eclipse.smarthome.automation.rest.rule, component.id=227, service.id=354, service.bundleid=272, service.scope=bundle} - org.eclipse.smarthome.automation.rest
13:12:09.480 [DEBUG] [rg.eclipse.smarthome.automation.rest] - ServiceEvent REGISTERED - {org.eclipse.smarthome.io.rest.RESTResource}={component.name=org.eclipse.smarthome.automation.rest.template, component.id=228, service.id=355, service.bundleid=272, service.scope=bundle} - org.eclipse.smarthome.automation.rest
After that there are no more rule related messages, althoug the item that triggers the rule has been updated quite often.
After I touch
the rule, it is reloaded and the rule works fine:
13:31:52.028 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - in queue: {}
13:31:52.035 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'log.py'
13:31:52.540 [INFO ] [smarthome.event.RuleAddedEvent ] - Rule 'rule_3' has been added.
13:31:52.548 [INFO ] [smarthome.event.RuleStatusInfoEvent ] - rule_3 updated: INITIALIZING
13:31:52.632 [DEBUG] [pse.smarthome.automation.module.core] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventSubscriber}={event.topics=smarthome/items/aog_t_temp/*, service.id=361, service.bundleid=264, service.scope=singleton} - org.eclipse.smarthome.automation.module.core
13:31:52.671 [INFO ] [smarthome.event.RuleStatusInfoEvent ] - rule_3 updated: IDLE
13:31:52.679 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - Script loaded: log.py
13:31:59.888 [INFO ] [marthome.event.ItemStateChangedEvent] - kueche_uptime changed from 790284766 to 790284826
13:32:02.967 [INFO ] [marthome.event.ItemStateChangedEvent] - kueche_temp changed from 23.32 to 23.31
13:32:03.003 [INFO ] [marthome.event.ItemStateChangedEvent] - kueche_humidity changed from 49.85 to 49.95
13:32:03.219 [INFO ] [marthome.event.ItemStateChangedEvent] - lab_signal changed from 54 to 42
13:32:03.235 [INFO ] [marthome.event.ItemStateChangedEvent] - lab_uptime changed from 319825 to 319885
13:32:03.417 [INFO ] [marthome.event.ItemStateChangedEvent] - ian_b_uptime changed from 319879 to 319939
13:32:04.989 [INFO ] [marthome.event.ItemStateChangedEvent] - ian_t_humidity changed from 49.89 to 50.00
13:32:05.017 [INFO ] [marthome.event.ItemStateChangedEvent] - ian_t_temp changed from 22.77 to 22.87
13:32:05.033 [INFO ] [marthome.event.ItemStateChangedEvent] - ian_t_signal changed from 28 to 26
13:32:05.052 [INFO ] [marthome.event.ItemStateChangedEvent] - ian_t_uptime changed from 504359 to 504419
13:32:18.459 [DEBUG] [.automation.core.internal.RuleEngine] - The trigger 'MyTrigger' of rule 'rule_3' is triggered.
13:32:18.467 [INFO ] [smarthome.event.RuleStatusInfoEvent ] - rule_3 updated: RUNNING
13:32:18.482 [INFO ] [marthome.event.ItemStateChangedEvent] - aog_t_temp changed from 22.55 to 22.56
13:32:18.528 [INFO ] [marthome.event.ItemStateChangedEvent] - aog_t_humidity changed from 47.87 to 47.77
13:32:18.744 [DEBUG] [.automation.core.internal.RuleEngine] - The rule 'rule_3' is executed.
13:32:18.754 [INFO ] [smarthome.event.RuleStatusInfoEvent ] - rule_3 updated: IDLE
However, if I touch the rule again, the old rule can’t be unloaded:
13:33:30.785 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - in queue: {}
13:33:30.789 [INFO ] [ort.shared.ScriptedAutomationManager] - removeAll added handlers
13:33:30.803 [WARN ] [ore.common.registry.AbstractRegistry] - Could not remove element: null
java.lang.NullPointerException
[...]
13:33:30.824 [INFO ] [rt.internal.loader.ScriptFileWatcher] - Loading script 'log.py'
13:33:31.110 [INFO ] [smarthome.event.RuleAddedEvent ] - Rule 'rule_4' has been added.
13:33:31.118 [INFO ] [smarthome.event.RuleStatusInfoEvent ] - rule_4 updated: INITIALIZING
13:33:31.133 [DEBUG] [pse.smarthome.automation.module.core] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventSubscriber}={event.topics=smarthome/items/aog_t_temp/*, service.id=362, service.bundleid=264, service.scope=singleton} - org.eclipse.smarthome.automation.module.core
13:33:31.141 [DEBUG] [rt.internal.loader.ScriptFileWatcher] - Script loaded: log.py
13:33:31.141 [INFO ] [smarthome.event.RuleStatusInfoEvent ] - rule_4 updated: IDLE
13:33:33.168 [INFO ] [marthome.event.ItemStateChangedEvent] - kueche_temp changed from 23.23 to 23.21
13:33:33.191 [INFO ] [marthome.event.ItemStateChangedEvent] - kueche_humidity changed from 49.81 to 50.02
13:33:34.988 [INFO ] [marthome.event.ItemStateChangedEvent] - ian_t_humidity changed from 49.19 to 49.25
13:33:35.005 [INFO ] [marthome.event.ItemStateChangedEvent] - ian_t_temp changed from 22.94 to 22.92
13:33:40.119 [INFO ] [marthome.event.ItemStateChangedEvent] - balkon_signal changed from 22 to 30
13:33:40.155 [INFO ] [marthome.event.ItemStateChangedEvent] - balkon_uptime changed from 224891 to 224951
13:33:44.992 [INFO ] [marthome.event.ItemStateChangedEvent] - aog_t_uptime changed from 7914139 to 7914199
So, when the item is updated again, both (new and old) rules are executed:
13:33:48.667 [DEBUG] [.automation.core.internal.RuleEngine] - The trigger 'MyTrigger' of rule 'rule_3' is triggered.
13:33:48.678 [INFO ] [smarthome.event.RuleStatusInfoEvent ] - rule_3 updated: RUNNING
13:33:48.693 [DEBUG] [.automation.core.internal.RuleEngine] - The rule 'rule_3' is executed.
13:33:48.706 [INFO ] [smarthome.event.RuleStatusInfoEvent ] - rule_3 updated: IDLE
13:33:48.706 [DEBUG] [.automation.core.internal.RuleEngine] - The trigger 'MyTrigger' of rule 'rule_4' is triggered.
13:33:48.736 [INFO ] [marthome.event.ItemStateChangedEvent] - aog_t_temp changed from 22.53 to 22.56
13:33:48.751 [INFO ] [smarthome.event.RuleStatusInfoEvent ] - rule_4 updated: RUNNING
13:33:48.762 [DEBUG] [.automation.core.internal.RuleEngine] - The rule 'rule_4' is executed.
13:33:48.789 [INFO ] [smarthome.event.RuleStatusInfoEvent ] - rule_4 updated: IDLE
More details:
- Openhab-2.1 installed from Debian/Ubuntu repository.
- misc-scriptengine installed via paperui.
- Script “log.py”:
scriptExtension.importPreset("RuleSimple")
scriptExtension.importPreset("RuleSupport")
class MyRule(SimpleRule):
def __init__(self):
self.triggers = [
Trigger("MyTrigger", "core.ItemStateUpdateTrigger",
Configuration({ "itemName": "aog_t_temp"}))
]
def execute(self, module, input):
events.postUpdate("homie_broadcast_notification", "some data")
automationManager.addRule(MyRule())