search

eclipse-archived / smarthome

Eclipse SmartHome™ project
https://www.eclipse.org/smarthome/
Eclipse Public License 2.0
861 stars 784 forks source link

[Automation] Triggering a rule through Paper UI causes an exception if the rule has not already been triggered elsewhere, and contains an import for a core action in the Action #6406

Open 5iver opened 5 years ago

5iver commented 5 years ago

EDIT: At first I thought this was recently introduced, but it was not. Steps to reproduce in this post. The same occurs when using the REST API /rules/{ruleUID}/runnow (which is what Paper UI is sending).

Try modifying the rule, doesn’t matter what you change… could be the name. Save the rule and DON"T execute from Paper UI. Trigger the rule though the Item. I use smarthome:send Test_Switch_1 ON from Karaf. No exception. Then try triggering the rule through Paper UI. No exception.

To reproduce the exception, modify/save the rule, then execute through Paper UI. Exception. Trigger through Item. Exception.

Seems the first trigger must not be through Paper UI, or you will get the exception. Once triggered from something other than Paper UI, you can then trigger through Paper UI. AND I have only seen the exception if the Rule Action contains Javascript with a Core Action.

If everything in the Action is commented out but the LoggerFactory import and the log statement, the exception does not occur. There looks to be an issue in the getContext when the rule has not already been triggered by an event. Here is the JS Action:

'use strict';
var log = Java.type("org.slf4j.LoggerFactory").getLogger("org.eclipse.smarthome.model.script.Rules");
var Exec = Java.type("org.eclipse.smarthome.model.script.actions.Exec");
var test = Exec.executeCommandLine("echo hello world", 5000);
log.info("JSR223: JS: Test executeCommandLine [" + test + "]");
Rule saved in Paper UI:
2018-10-25 00:16:32.611 [TRACE] [ation.core.internal.RuleEventFactory] - creating ruleEvent of type: RuleUpdatedEvent
2018-10-25 00:16:32.612 [DEBUG] [pse.smarthome.automation.module.core] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.events.EventSubscriber}={service.id=445, service.bundleid=235, service.scope=singleton, event.topics=smarthome/items/Test_Switch_1/command} - org.eclipse.smarthome.automation.module.core
2018-10-25 00:16:32.614 [TRACE] [ation.core.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
2018-10-25 00:16:32.614 [TRACE] [l.factory.ScriptModuleHandlerFactory] - create 2 -> script.ScriptAction
2018-10-25 00:16:32.615 [TRACE] [ore.factory.CoreModuleHandlerFactory] - create 1 -> core.ItemCommandTrigger : cd1cce1b-f559-48ef-a955-210d019586ad
2018-10-25 00:16:32.616 [DEBUG] [pse.smarthome.automation.module.core] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventSubscriber}={service.id=446, service.bundleid=235, service.scope=singleton, event.topics=smarthome/items/Test_Switch_1/command} - org.eclipse.smarthome.automation.module.core
2018-10-25 00:16:32.617 [TRACE] [ation.core.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent

Rule triggered through Item (successful):
2018-10-25 00:16:49.075 [TRACE] [re.handler.ItemCommandTriggerHandler] - ->FILTER: smarthome/items/Test_Switch_1/command:Test_Switch_1
2018-10-25 00:16:49.076 [TRACE] [re.handler.ItemCommandTriggerHandler] - Received Event: Source: null Topic: smarthome/items/Test_Switch_1/command Type: ItemCommandEvent  Payload: {"type":"OnOff","value":"ON"}
2018-10-25 00:16:49.078 [DEBUG] [omation.core.internal.RuleEngineImpl] - The trigger '1' of rule 'cd1cce1b-f559-48ef-a955-210d019586ad' is triggered.
2018-10-25 00:16:49.079 [TRACE] [ation.core.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
2018-10-25 00:16:49.153 [INFO ] [eclipse.smarthome.model.script.Rules] - JSR223: JS: Test executeCommandLine [hello world]
2018-10-25 00:16:49.153 [DEBUG] [omation.core.internal.RuleEngineImpl] - The rule 'cd1cce1b-f559-48ef-a955-210d019586ad' is executed.
2018-10-25 00:16:49.154 [TRACE] [ation.core.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent

Rule triggered through Paper UI (successful):
2018-10-25 00:17:02.827 [TRACE] [ation.core.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
2018-10-25 00:17:02.880 [INFO ] [eclipse.smarthome.model.script.Rules] - JSR223: JS: Test executeCommandLine [hello world]
2018-10-25 00:17:02.881 [DEBUG] [omation.core.internal.RuleEngineImpl] - The rule 'cd1cce1b-f559-48ef-a955-210d019586ad' is executed.
2018-10-25 00:17:02.882 [TRACE] [ation.core.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent

Rule name changed and saved through Paper UI:
2018-10-25 00:18:10.884 [TRACE] [ation.core.internal.RuleEventFactory] - creating ruleEvent of type: RuleUpdatedEvent
2018-10-25 00:18:10.885 [DEBUG] [pse.smarthome.automation.module.core] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.events.EventSubscriber}={service.id=446, service.bundleid=235, service.scope=singleton, event.topics=smarthome/items/Test_Switch_1/command} - org.eclipse.smarthome.automation.module.core
2018-10-25 00:18:10.887 [TRACE] [l.factory.ScriptModuleHandlerFactory] - create 2 -> script.ScriptAction
2018-10-25 00:18:10.887 [TRACE] [ore.factory.CoreModuleHandlerFactory] - create 1 -> core.ItemCommandTrigger : cd1cce1b-f559-48ef-a955-210d019586ad
2018-10-25 00:18:10.889 [DEBUG] [pse.smarthome.automation.module.core] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventSubscriber}={service.id=447, service.bundleid=235, service.scope=singleton, event.topics=smarthome/items/Test_Switch_1/command} - org.eclipse.smarthome.automation.module.core
2018-10-25 00:18:10.891 [TRACE] [ation.core.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
2018-10-25 00:18:10.892 [TRACE] [ation.core.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent

Rule triggered through Paper UI (exception):
2018-10-25 00:18:20.020 [TRACE] [ation.core.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
2018-10-25 00:18:20.040 [WARN ] [omation.core.internal.RuleEngineImpl] - Fail to execute action: 2
java.lang.RuntimeException: java.lang.ClassNotFoundException: org.eclipse.smarthome.model.script.actions.Exec cannot be found by com.eclipsesource.jaxrs.publisher_5.3.1.201602281253
    at jdk.nashorn.internal.runtime.ScriptRuntime.apply(ScriptRuntime.java:397) ~[?:?]
    at jdk.nashorn.api.scripting.NashornScriptEngine.evalImpl(NashornScriptEngine.java:449) ~[?:?]
    at jdk.nashorn.api.scripting.NashornScriptEngine.evalImpl(NashornScriptEngine.java:406) ~[?:?]
    at jdk.nashorn.api.scripting.NashornScriptEngine.evalImpl(NashornScriptEngine.java:402) ~[?:?]
    at jdk.nashorn.api.scripting.NashornScriptEngine.eval(NashornScriptEngine.java:155) ~[?:?]
    at javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:264) ~[?:?]
    at org.eclipse.smarthome.automation.module.script.internal.handler.ScriptActionHandler.lambda$0(ScriptActionHandler.java:60) ~[?:?]
    at java.util.Optional.ifPresent(Optional.java:159) ~[?:?]
    at org.eclipse.smarthome.automation.module.script.internal.handler.ScriptActionHandler.execute(ScriptActionHandler.java:57) ~[?:?]
    at org.eclipse.smarthome.automation.core.internal.RuleEngineImpl.executeActions(RuleEngineImpl.java:1198) [234:org.eclipse.smarthome.automation.core:0.10.0.201810180807]
    at org.eclipse.smarthome.automation.core.internal.RuleEngineImpl.runNow(RuleEngineImpl.java:1055) [234:org.eclipse.smarthome.automation.core:0.10.0.201810180807]
    at org.eclipse.smarthome.automation.core.internal.RuleEngineImpl.runNow(RuleEngineImpl.java:1071) [234:org.eclipse.smarthome.automation.core:0.10.0.201810180807]
    at org.eclipse.smarthome.automation.rest.internal.RuleResource.runNow(RuleResource.java:288) [243:org.eclipse.smarthome.automation.rest:0.10.0.201810180807]
    at sun.reflect.GeneratedMethodAccessor32.invoke(Unknown Source) ~[?:?]
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
    at org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$1.invoke(ResourceMethodInvocationHandlerFactory.java:81) [171:org.glassfish.jersey.core.jersey-server:2.22.2]
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1.run(AbstractJavaResourceMethodDispatcher.java:144) [171:org.glassfish.jersey.core.jersey-server:2.22.2]
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.invoke(AbstractJavaResourceMethodDispatcher.java:161) [171:org.glassfish.jersey.core.jersey-server:2.22.2]
    at org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker.doDispatch(JavaResourceMethodDispatcherProvider.java:160) [171:org.glassfish.jersey.core.jersey-server:2.22.2]
    at org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher.dispatch(AbstractJavaResourceMethodDispatcher.java:99) [171:org.glassfish.jersey.core.jersey-server:2.22.2]
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:389) [171:org.glassfish.jersey.core.jersey-server:2.22.2]
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:347) [171:org.glassfish.jersey.core.jersey-server:2.22.2]
    at org.glassfish.jersey.server.model.ResourceMethodInvoker.apply(ResourceMethodInvoker.java:102) [171:org.glassfish.jersey.core.jersey-server:2.22.2]
    at org.glassfish.jersey.server.ServerRuntime$2.run(ServerRuntime.java:326) [171:org.glassfish.jersey.core.jersey-server:2.22.2]
    at org.glassfish.jersey.internal.Errors$1.call(Errors.java:271) [170:org.glassfish.jersey.core.jersey-common:2.22.2]
    at org.glassfish.jersey.internal.Errors$1.call(Errors.java:267) [170:org.glassfish.jersey.core.jersey-common:2.22.2]
    at org.glassfish.jersey.internal.Errors.process(Errors.java:315) [170:org.glassfish.jersey.core.jersey-common:2.22.2]
    at org.glassfish.jersey.internal.Errors.process(Errors.java:297) [170:org.glassfish.jersey.core.jersey-common:2.22.2]
    at org.glassfish.jersey.internal.Errors.process(Errors.java:267) [170:org.glassfish.jersey.core.jersey-common:2.22.2]
    at org.glassfish.jersey.process.internal.RequestScope.runInScope(RequestScope.java:317) [170:org.glassfish.jersey.core.jersey-common:2.22.2]
    at org.glassfish.jersey.server.ServerRuntime.process(ServerRuntime.java:305) [171:org.glassfish.jersey.core.jersey-server:2.22.2]
    at org.glassfish.jersey.server.ApplicationHandler.handle(ApplicationHandler.java:1154) [171:org.glassfish.jersey.core.jersey-server:2.22.2]
    at org.glassfish.jersey.servlet.WebComponent.serviceImpl(WebComponent.java:473) [168:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
    at org.glassfish.jersey.servlet.WebComponent.service(WebComponent.java:427) [168:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
    at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:388) [168:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
    at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:341) [168:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
    at org.glassfish.jersey.servlet.ServletContainer.service(ServletContainer.java:228) [168:org.glassfish.jersey.containers.jersey-container-servlet-core:2.22.2]
    at com.eclipsesource.jaxrs.publisher.internal.ServletContainerBridge.service(ServletContainerBridge.java:76) [20:com.eclipsesource.jaxrs.publisher:5.3.1.201602281253]
    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:865) [85:org.eclipse.jetty.servlet:9.4.11.v20180605]
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:535) [85:org.eclipse.jetty.servlet:9.4.11.v20180605]
    at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:71) [185:org.ops4j.pax.web.pax-web-jetty:7.2.3]
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146) [84:org.eclipse.jetty.server:9.4.11.v20180605]
    at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548) [82:org.eclipse.jetty.security:9.4.11.v20180605]
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) [84:org.eclipse.jetty.server:9.4.11.v20180605]
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257) [84:org.eclipse.jetty.server:9.4.11.v20180605]
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595) [84:org.eclipse.jetty.server:9.4.11.v20180605]
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) [84:org.eclipse.jetty.server:9.4.11.v20180605]
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1317) [84:org.eclipse.jetty.server:9.4.11.v20180605]
    at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:293) [185:org.ops4j.pax.web.pax-web-jetty:7.2.3]
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203) [84:org.eclipse.jetty.server:9.4.11.v20180605]
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473) [85:org.eclipse.jetty.servlet:9.4.11.v20180605]
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564) [84:org.eclipse.jetty.server:9.4.11.v20180605]
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201) [84:org.eclipse.jetty.server:9.4.11.v20180605]
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1219) [84:org.eclipse.jetty.server:9.4.11.v20180605]
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144) [84:org.eclipse.jetty.server:9.4.11.v20180605]
    at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:80) [185:org.ops4j.pax.web.pax-web-jetty:7.2.3]
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) [84:org.eclipse.jetty.server:9.4.11.v20180605]
    at org.eclipse.jetty.server.Server.handle(Server.java:531) [84:org.eclipse.jetty.server:9.4.11.v20180605]
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:352) [84:org.eclipse.jetty.server:9.4.11.v20180605]
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260) [84:org.eclipse.jetty.server:9.4.11.v20180605]
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:281) [75:org.eclipse.jetty.io:9.4.11.v20180605]
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102) [75:org.eclipse.jetty.io:9.4.11.v20180605]
    at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118) [75:org.eclipse.jetty.io:9.4.11.v20180605]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333) [87:org.eclipse.jetty.util:9.4.11.v20180605]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310) [87:org.eclipse.jetty.util:9.4.11.v20180605]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168) [87:org.eclipse.jetty.util:9.4.11.v20180605]
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126) [87:org.eclipse.jetty.util:9.4.11.v20180605]
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366) [87:org.eclipse.jetty.util:9.4.11.v20180605]
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:762) [87:org.eclipse.jetty.util:9.4.11.v20180605]
    at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:680) [87:org.eclipse.jetty.util:9.4.11.v20180605]
    at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: java.lang.ClassNotFoundException: org.eclipse.smarthome.model.script.actions.Exec cannot be found by com.eclipsesource.jaxrs.publisher_5.3.1.201602281253
    at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:484) ~[?:?]
    at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:395) ~[?:?]
    at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:387) ~[?:?]
    at org.eclipse.osgi.internal.loader.ModuleClassLoader.loadClass(ModuleClassLoader.java:150) ~[?:?]
    at java.lang.ClassLoader.loadClass(ClassLoader.java:357) ~[?:?]
    at org.eclipse.osgi.internal.framework.EquinoxBundle.loadClass(EquinoxBundle.java:564) ~[?:?]
    at org.ops4j.pax.swissbox.core.BundleClassLoader.findClass(BundleClassLoader.java:176) ~[185:org.ops4j.pax.web.pax-web-jetty:7.2.3]
    at java.lang.ClassLoader.loadClass(ClassLoader.java:424) ~[?:?]
    at org.ops4j.pax.swissbox.core.BundleClassLoader.loadClass(BundleClassLoader.java:192) ~[185:org.ops4j.pax.web.pax-web-jetty:7.2.3]
    at java.lang.ClassLoader.loadClass(ClassLoader.java:357) ~[?:?]
    at java.lang.Class.forName0(Native Method) ~[?:?]
    at java.lang.Class.forName(Class.java:348) ~[?:?]
    at jdk.nashorn.internal.runtime.Context.findClass(Context.java:1051) ~[?:?]
    at jdk.nashorn.internal.objects.NativeJava.simpleType(NativeJava.java:498) ~[?:?]
    at jdk.nashorn.internal.objects.NativeJava.type(NativeJava.java:322) ~[?:?]
    at jdk.nashorn.internal.objects.NativeJava.type(NativeJava.java:314) ~[?:?]
    at jdk.nashorn.internal.objects.NativeJava.type(NativeJava.java:310) ~[?:?]
    at jdk.nashorn.internal.scripts.Script$68$\^eval\_.:program(<eval>:3) ~[?:?]
    at jdk.nashorn.internal.runtime.ScriptFunctionData.invoke(ScriptFunctionData.java:637) ~[?:?]
    at jdk.nashorn.internal.runtime.ScriptFunction.invoke(ScriptFunction.java:494) ~[?:?]
    at jdk.nashorn.internal.runtime.ScriptRuntime.apply(ScriptRuntime.java:393) ~[?:?]
    ... 71 more
2018-10-25 00:18:20.043 [DEBUG] [omation.core.internal.RuleEngineImpl] - The rule 'cd1cce1b-f559-48ef-a955-210d019586ad' is executed.
2018-10-25 00:18:20.043 [TRACE] [ation.core.internal.RuleEventFactory] - creating ruleEvent of type: RuleStatusInfoEvent
kaikreuzer commented 5 years ago

Just a note: In general, the new rule engine does not know anything about the old one and thus does not and should not have a dependency on the (1.x) actions. With https://github.com/eclipse/smarthome/pull/6398, we will hopefully soon have a replacement for 1.x actions for the new rule engine and I could imagine that we can leverage this feature to make the 1.x actions available to the new rule engine through the openHAB compatibility layer.