Milestone M5-1
Nashorn rules work but scripts do not work:
2023-07-17 19:35:47.502 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID ‘23d9c11913’ failed: org.graalvm.polyglot.PolyglotException: ReferenceError: “itemRegistry” is not defined
I ran it manually. It works fine in OH 3.4.
If I run it manually in OH4-M5 without changing the automation_rules.json “type”: “application/javascript;version=ECMAScript-5.1” it will error.
If I change “type”: “application/javascript;version=ECMAScript-5.1” then it runs fine just like in OH3.4.
Yes the scripts are rules (apparently) but they are not executing the same way as what I am observing.
Is anyone else seeing this behaviour? Can you replicate what I am seeing?
This is the script. It is nothing fancy:
//need below to log to openhab.log file
var logger = Java.type('org.slf4j.LoggerFactory').getLogger('org.openhab.rule.' + ctx.ruleUID);
//if the counter has not been initialised
if (itemRegistry.getItem("gatecounter").getState() === NULL) {
events.postUpdate("gatecounter", 1);}
else{
//Get the count
var counter = parseFloat(itemRegistry.getItem("gatecounter").getState())
counter=counter+1
events.postUpdate("gatecounter", counter);
}
logger.info('Gate Counter is: ' + counter);
I can swap between a non-edited version of automation_rules.json and one that I have added “type”: “application/javascript;version=ECMAScript-5.1” to and it will fail every time with the non-edited file and will work every time with the edited file.
Below is what I get with the non-edited file:
[2023-07-18 08:51:25.503 [ERROR] [b.automation.script.javascript.stack] - Failed to execute script:
org.graalvm.polyglot.PolyglotException: ReferenceError: "itemRegistry" is not defined
at <js>.:program(<eval>:5) ~[?:?]
at org.graalvm.polyglot.Context.eval(Context.java:399) ~[?:?]
at com.oracle.truffle.js.scriptengine.GraalJSScriptEngine.eval(GraalJSScriptEngine.java:458) ~[?:?]
at com.oracle.truffle.js.scriptengine.GraalJSScriptEngine.eval(GraalJSScriptEngine.java:426) ~[?:?]
at javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:262) ~[java.scripting:?]
at org.openhab.automation.jsscripting.internal.scriptengine.DelegatingScriptEngineWithInvocableAndAutocloseable.eval(DelegatingScriptEngineWithInvocableAndAutocloseable.java:53) ~[?:?]
at org.openhab.automation.jsscripting.internal.scriptengine.InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.eval(InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.java:78) ~[?:?]
at org.openhab.automation.jsscripting.internal.scriptengine.DelegatingScriptEngineWithInvocableAndAutocloseable.eval(DelegatingScriptEngineWithInvocableAndAutocloseable.java:53) ~[?:?]
at org.openhab.automation.jsscripting.internal.scriptengine.InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.eval(InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.java:78) ~[?:?]
at org.openhab.core.automation.module.script.internal.handler.ScriptActionHandler.lambda$0(ScriptActionHandler.java:71) ~[?:?]
at java.util.Optional.ifPresent(Optional.java:178) ~[?:?]
at org.openhab.core.automation.module.script.internal.handler.ScriptActionHandler.execute(ScriptActionHandler.java:68) ~[?:?]
at org.openhab.core.automation.internal.RuleEngineImpl.executeActions(RuleEngineImpl.java:1175) ~[?:?]
at org.openhab.core.automation.internal.RuleEngineImpl.runNow(RuleEngineImpl.java:1026) ~[?:?]
at org.openhab.core.automation.rest.internal.RuleResource.runNow(RuleResource.java:381) ~[?:?]
at org.openhab.core.automation.rest.internal.RuleResource.runNow(RuleResource.java:398) ~[?:?]
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
at java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
at org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:179) ~[bundleFile:3.4.5]
at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96) ~[bundleFile:3.4.5]
at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:201) ~[bundleFile:3.4.5]
at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:104) ~[bundleFile:3.4.5]
at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:59) ~[bundleFile:3.4.5]
at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:96) ~[bundleFile:3.4.5]
at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308) ~[bundleFile:3.4.5]
at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121) ~[bundleFile:3.4.5]
at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:265) ~[bundleFile:3.4.5]
at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:234) ~[bundleFile:3.4.5]
at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:208) ~[bundleFile:3.4.5]
at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:160) ~[bundleFile:3.4.5]
at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:225) ~[bundleFile:3.4.5]
at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:298) ~[bundleFile:3.4.5]
at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doPost(AbstractHTTPServlet.java:217) ~[bundleFile:3.4.5]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:517) ~[bundleFile:4.0.4]
at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:273) ~[bundleFile:3.4.5]
at org.ops4j.pax.web.service.spi.servlet.OsgiInitializedServlet.service(OsgiInitializedServlet.java:102) ~[bundleFile:?]
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1656) ~[bundleFile:9.4.50.v20221201]
at org.ops4j.pax.web.service.spi.servlet.OsgiFilterChain.doFilter(OsgiFilterChain.java:100) ~[bundleFile:?]
at org.ops4j.pax.web.service.jetty.internal.PaxWebServletHandler.doHandle(PaxWebServletHandler.java:310) ~[bundleFile:?]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:600) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:505) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234) ~[bundleFile:9.4.50.v20221201]
at org.ops4j.pax.web.service.jetty.internal.PrioritizedHandlerCollection.handle(PrioritizedHandlerCollection.java:96) ~[bundleFile:?]
at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:722) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) ~[bundleFile:9.4.50.v20221201]
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) ~[bundleFile:9.4.50.v20221201]
at java.lang.Thread.run(Thread.java:833) ~[?:?]
2023-07-18 08:51:25.511 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID '23d9c11913' failed: org.graalvm.polyglot.PolyglotException: ReferenceError: "itemRegistry" is not defined
Thanks. Now I know there is a release note and it is a know issue.
If the updater tool fixed it if there were nashorn scripts/rules then that would be a bonus.
I follow up helmar74’s discussion as I can fully confirm the AVM problem on my Raspberry setup. Only difference is that in my case OH4 MS 1-4 (had them all) were working fine and the problem occurred only since snapshops AFTER Milestone 4 (I guess ca. since Snapshot 353X or 3 weeks ago). In the last weeks I always changed back from the snapshot to MS 4 and it was ok again with AVM-Things and its Energy- and Power channels available. I am running an additional test-Raspberry where exactly the same behavior occurred.
For me a change from the last few weeks could have caused the problem and not the change from OH 3 to 4 as it seems in helmars case. May be it helps finding the cause of the problem.
Some further “channels” issues also occuring with Kodi and Amazon Echocontrol Binding:
2023-07-17 21:11:42.929 [WARN ] [core.thing.internal.ThingManagerImpl] - Channel types or config descriptions for thing 'amazonechocontrol:echo:XXXXXXXXX:XXXXXXXXX' are missing in the respective registry for more than 120s. In case it does not happen immediately after an upgrade, it should be fixed in the binding.
2023-07-17 21:11:42.936 [WARN ] [core.thing.internal.ThingManagerImpl] - Failed to normalize configuration for thing 'amazonechocontrol:echo:XXXXXXXXX:XXXXXXXXX': {thing/channel=Type description amazonechocontrol:lastSpokenText for amazonechocontrol:echo:XXXXXXXXX:XXXXXXXXX:lastSpokenText not found, although we checked the presence before.}
2023-07-17 21:11:42.951 [WARN ] [core.thing.internal.ThingManagerImpl] - Channel types or config descriptions for thing 'amazonechocontrol:echo:XXXXXXXXX:XXXXXXXXX' are missing in the respective registry for more than 120s. In case it does not happen immediately after an upgrade, it should be fixed in the binding.
2023-07-17 21:11:42.956 [WARN ] [core.thing.internal.ThingManagerImpl] - Failed to normalize configuration for thing 'amazonechocontrol:echo:XXXXXXXXX:XXXXXXXXX': {thing/channel=Type description amazonechocontrol:lastSpokenText for amazonechocontrol:echo:XXXXXXXXX:XXXXXXXXX:lastSpokenText not found, although we checked the presence before.}
2023-07-17 21:11:42.975 [WARN ] [core.thing.internal.ThingManagerImpl] - Channel types or config descriptions for thing 'amazonechocontrol:echo:XXXXXXXXX:XXXXXXXXX' are missing in the respective registry for more than 120s. In case it does not happen immediately after an upgrade, it should be fixed in the binding.
2023-07-17 21:11:42.983 [WARN ] [core.thing.internal.ThingManagerImpl] - Failed to normalize configuration for thing 'amazonechocontrol:echo:XXXXXXXXX:XXXXXXXXX': {thing/channel=Type description amazonechocontrol:lastSpokenText for amazonechocontrol:echo:XXXXXXXXX:XXXXXXXXX:lastSpokenText not found, although we checked the presence before.}
2023-07-17 21:11:43.026 [WARN ] [core.thing.internal.ThingManagerImpl] - Channel types or config descriptions for thing 'kodi:kodi:9849245e' are missing in the respective registry for more than 120s. In case it does not happen immediately after an upgrade, it should be fixed in the binding.
2023-07-17 21:11:43.030 [WARN ] [core.thing.internal.ThingManagerImpl] - Failed to normalize configuration for thing 'kodi:kodi:9849245e': {thing/channel=Type description kodi:volume for kodi:kodi:9849245e:volume not found, although we checked the presence before.}
2023-07-17 21:11:42.929 [WARN ] [core.thing.internal.ThingManagerImpl] - Channel types or config descriptions for thing 'amazonechocontrol:echo:XXXXXXXXX:XXXXXXXXX' are missing in the respective registry for more than 120s. In case it does not happen immediately after an upgrade, it should be fixed in the binding.
2023-07-17 21:11:42.936 [WARN ] [core.thing.internal.ThingManagerImpl] - Failed to normalize configuration for thing 'amazonechocontrol:echo:XXXXXXXXX:XXXXXXXXX': {thing/channel=Type description amazonechocontrol:lastSpokenText for amazonechocontrol:echo:XXXXXXXXX:XXXXXXXXX:lastSpokenText not found, although we checked the presence before.}
2023-07-17 21:11:42.951 [WARN ] [core.thing.internal.ThingManagerImpl] - Channel types or config descriptions for thing 'amazonechocontrol:echo:XXXXXXXXX:XXXXXXXXX' are missing in the respective registry for more than 120s. In case it does not happen immediately after an upgrade, it should be fixed in the binding.
2023-07-17 21:11:42.956 [WARN ] [core.thing.internal.ThingManagerImpl] - Failed to normalize configuration for thing 'amazonechocontrol:echo:XXXXXXXXX:XXXXXXXXX': {thing/channel=Type description amazonechocontrol:lastSpokenText for amazonechocontrol:echo:XXXXXXXXX:XXXXXXXXX:lastSpokenText not found, although we checked the presence before.}
2023-07-17 21:11:42.975 [WARN ] [core.thing.internal.ThingManagerImpl] - Channel types or config descriptions for thing 'amazonechocontrol:echo:XXXXXXXXX:XXXXXXXXX' are missing in the respective registry for more than 120s. In case it does not happen immediately after an upgrade, it should be fixed in the binding.
2023-07-17 21:11:42.983 [WARN ] [core.thing.internal.ThingManagerImpl] - Failed to normalize configuration for thing 'amazonechocontrol:echo:XXXXXXXXX:XXXXXXXXX': {thing/channel=Type description amazonechocontrol:lastSpokenText for amazonechocontrol:echo:XXXXXXXXX:XXXXXXXXX:lastSpokenText not found, although we checked the presence before.}
2023-07-17 21:11:43.026 [WARN ] [core.thing.internal.ThingManagerImpl] - Channel types or config descriptions for thing 'kodi:kodi:9849245e' are missing in the respective registry for more than 120s. In case it does not happen immediately after an upgrade, it should be fixed in the binding.
2023-07-17 21:11:43.030 [WARN ] [core.thing.internal.ThingManagerImpl] - Failed to normalize configuration for thing 'kodi:kodi:9849245e': {thing/channel=Type description kodi:volume for kodi:kodi:9849245e:volume not found, although we checked the presence before.}
If I delete and recreate one of the DEC210 Things, I get:
2023-07-18 23:24:19.119 [WARN ] [re.thing.internal.ThingFactoryHelper] - Could not create channel 'energy', because channel type 'system:electric-energy' could not be found.
2023-07-18 23:24:19.139 [ERROR] [.update.UpdateChannelInstructionImpl] - Failed to create channel 'avmfritz:FRITZ_DECT_210:192_168_1_1:d4305fd78c:energy' because channel type 'system:electric-energy' could not be found.
2023-07-18 23:24:19.143 [INFO ] [core.thing.internal.ThingManagerImpl] - Updating 'avmfritz:FRITZ_DECT_210:192_168_1_1:d4305fd78c' from version 1 to 2
As @florian-h05 indicated, as of this writing, changing the MIME types of existing rules is not part of the upgrade process. So you either need to manually change the MIME type so it’s executed with Nashorn or you need modify the code to make it compatible with JS Scripting. I’m hoping this makes it into the upgrade tool before 4.0 release but if not, it’s a breaking change users will have to manage manually and it’s documented in the release notes.
To import itemRegistry and other stuff into a JS Scripting rule so Nashorn style will work:
var {runtime} = require('@runtime');
//need below to log to openhab.log file
var logger = Java.type('org.slf4j.LoggerFactory').getLogger('org.openhab.rule.' + ruleUID);
//if the counter has not been initialised
if (runtime.itemRegistry.getItem("gatecounter").getState() === NULL) {
runtime.events.postUpdate("gatecounter", 1);}
else{
//Get the count
var counter = parseFloat(runtime.itemRegistry.getItem("gatecounter").getState())
counter=counter+1
runtime.events.postUpdate("gatecounter", counter);
}
logger.info('Gate Counter is: ' + counter);
NOTE: I just typed in the above, I might have typos
But if you are going to use JS Scripting, it’s far better to convert it to JS Scripting using the built in helper library.
console.loggerName = 'org.openhab.'+ruleUID; // this is optional, the default logger name is reasonable
var gatecounter = items.gatecounter;
if(gatecounter.isUninitialized) {
gatecounter.postUpdate(1);
}
else {
var counter = gatecounter.numericState + 1;
gatecounter.postUpdate(counter);
}
gatecounter.postUpdate(counter);
console.info('Gate Counter is: ' + counter)
The code is much more concise and easy to read.
It could be made even more so.
var gatecounter = items.gatecounter;
var counter = ((gatecounter.isUninitialized) ? 0 : gatecounter.numericState) + 1;
gatecounter.postUpdate(counter);
console.info('Gate Counter is: ' + counter);
After upgrading from 3.4.4 to 4.0.0 M5 I receive the following error messages from deCONZ.
I have verified the problem on a new 4.0.0 M5 installation where only the deCONZ bridge is installed.
The bridge turns of and off every 2 minutes.
y2023-07-18 16:52:53.526 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started.
==> /var/log/openhab/events.log <==
2023-07-18 16:52:53.533 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'deconz:deconz:Aalborg' changed from UNINITIALIZED (HANDLER_MISSING_ERROR): Handler factory not found to UNINITIALIZED (NOT_YET_READY)
2023-07-18 16:52:54.604 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'deconz:deconz:Aalborg' changed from UNINITIALIZED (NOT_YET_READY) to INITIALIZING
2023-07-18 16:52:54.613 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'deconz:deconz:Aalborg' changed from INITIALIZING to UNKNOWN
2023-07-18 16:53:04.786 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'deconz:deconz:Aalborg' changed from UNKNOWN to ONLINE
2023-07-18 16:55:04.784 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'deconz:deconz:Aalborg' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Watchdog timed out after 120s. Websocket seems to be dead.
2023-07-18 16:55:14.826 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'deconz:deconz:Aalborg' changed from OFFLINE (COMMUNICATION_ERROR): Watchdog timed out after 120s. Websocket seems to be dead. to ONLINE
2023-07-18 16:57:14.828 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'deconz:deconz:Aalborg' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Watchdog timed out after 120s. Websocket seems to be dead.
2023-07-18 16:57:24.848 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'deconz:deconz:Aalborg' changed from OFFLINE (COMMUNICATION_ERROR): Watchdog timed out after 120s. Websocket seems to be dead. to ONLINE
2023-07-18 16:59:24.850 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'deconz:deconz:Aalborg' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Watchdog timed out after 120s. Websocket seems to be dead.
pe or paste code here