[JS Scripting] All scripts stop working when upgrading to 3.4.0.M4

laursen · November 13, 2022, 11:06am

Reading through thread - was root cause found? I also have this with M4:

2022-11-13 11:04:57.282 [ERROR] [.internal.OpenhabGraalJSScriptEngine] - Could not inject global script
javax.script.ScriptException: org.graalvm.polyglot.PolyglotException: SyntaxError: arraycopy: last destination index 45 out of bounds for byte[44]
        at com.oracle.truffle.js.scriptengine.GraalJSScriptEngine.toScriptException(GraalJSScriptEngine.java:503) ~[?:?]
        at com.oracle.truffle.js.scriptengine.GraalJSScriptEngine.eval(GraalJSScriptEngine.java:480) ~[?:?]
        at com.oracle.truffle.js.scriptengine.GraalJSScriptEngine.eval(GraalJSScriptEngine.java:446) ~[?:?]
        at javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:264) ~[java.scripting:?]
        at org.openhab.automation.jsscripting.internal.scriptengine.DelegatingScriptEngineWithInvocableAndAutocloseable.eval(DelegatingScriptEngineWithInvocableAndAutocloseable.java:54) ~[?:?]
        at org.openhab.automation.jsscripting.internal.scriptengine.InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.eval(InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.java:69) ~[?:?]
        at org.openhab.automation.jsscripting.internal.OpenhabGraalJSScriptEngine.beforeInvocation(OpenhabGraalJSScriptEngine.java:218) ~[?:?]
        at org.openhab.automation.jsscripting.internal.scriptengine.InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.eval(InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.java:78) ~[?:?]
        at org.openhab.automation.jsscripting.internal.scriptengine.DelegatingScriptEngineWithInvocableAndAutocloseable.eval(DelegatingScriptEngineWithInvocableAndAutocloseable.java:59) ~[?:?]
        at org.openhab.automation.jsscripting.internal.scriptengine.InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.eval(InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.java:79) ~[?:?]
        at org.openhab.core.automation.module.script.internal.ScriptEngineManagerImpl.loadScript(ScriptEngineManagerImpl.java:189) ~[?:?]
        at org.openhab.core.automation.module.script.rulesupport.loader.ScriptFileWatcher.createAndLoad(ScriptFileWatcher.java:251) ~[?:?]
        at org.openhab.automation.jsscripting.internal.fs.watch.JSScriptFileWatcher.createAndLoad(JSScriptFileWatcher.java:57) ~[?:?]
        at org.openhab.core.automation.module.script.rulesupport.loader.ScriptFileWatcher.importFile(ScriptFileWatcher.java:231) ~[?:?]
        at org.openhab.core.automation.module.script.rulesupport.loader.ScriptFileWatcher.lambda$2(ScriptFileWatcher.java:223) ~[?:?]
        at java.util.Optional.ifPresent(Optional.java:183) ~[?:?]
        at org.openhab.core.automation.module.script.rulesupport.loader.ScriptFileWatcher.importFileWhenReady(ScriptFileWatcher.java:221) ~[?:?]
        at org.openhab.core.automation.module.script.rulesupport.loader.ScriptFileWatcher.importResources(ScriptFileWatcher.java:168) ~[?:?]
        at org.openhab.core.automation.module.script.rulesupport.loader.ScriptFileWatcher.importInitialResources(ScriptFileWatcher.java:142) ~[?:?]
        at org.openhab.core.automation.module.script.rulesupport.loader.ScriptFileWatcher.lambda$6(ScriptFileWatcher.java:305) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:829) [?:?]

I have only two scripts since I haven’t yet migrated to JS:

openhabian@openhabian:/etc/openhab $ cat automation/js/test.js

rules.JSRule({
  name: "Reproduce jsscripting issue",
  description: "Reproduce jsscripting issue",
  triggers: [triggers.ItemStateChangeTrigger('Test2', 'OFF', 'ON')],
  execute: data => {
    console.log("Test item triggered: 2");
  }
});

openhabian@openhabian:/etc/openhab $ cat automation/js/danfoss.js

var notification = require('notification.js');

function getRoomHumidityText(itemName)
{
    let item = items.getItem(itemName);
    let recentHumidity = item.history.historicState(time.ZonedDateTime.now().minusMinutes(22));
    let currentHumidity = item.state;
    let humidityDelta = item.rawState.doubleValue() - recentHumidity.doubleValue();
    let deltaString = "";

    if (humidityDelta < 0)
    {
        deltaString = ` (${humidityDelta.toFixed(1)} %)`;
    }
    else if (HumidityDelta > 0)
    {
        deltaString = ` (+${humidityDelta.toFixed(1)} %)`;
    }

    return `${currentHumidity}${deltaString}`;
}

rules.JSRule({
  name: "Danfoss boost new",
  description: "Push notification when boost is triggered on Danfoss Air",
  triggers: [triggers.ItemStateChangeTrigger('Test', 'OFF', 'ON')],
  execute: data => {
    console.log(body);
  }
});

openhabian@openhabian:/etc/openhab $ cat automation/js/node_modules/notification.js

exports.send = function(title, body) {
        var action = actions.thingActions('pushover', 'pushover:pushover-account:account');
        action.sendMessage(body, title);
}

florian-h05 · November 13, 2022, 11:11am

Unfortunately, no. Most people that could debug are not able to reproduce this, so there is no real chance to fix this issue.

Could you please provide me some platform details?
Please also the Java version!

laursen · November 13, 2022, 11:14am

Raspberry Pi 3:

openhabian@openhabian:/etc/openhab $ uname -a
Linux openhabian 5.15.76-v7+ #1597 SMP Fri Nov 4 12:13:17 GMT 2022 armv7l GNU/Linux

florian-h05 · November 13, 2022, 11:17am

And the Java version? (java --version)

laursen · November 13, 2022, 11:24am

openhabian@openhabian:/etc/openhab $ java --version
openjdk 11.0.16 2022-07-19
OpenJDK Runtime Environment (build 11.0.16+8-post-Raspbian-1deb11u1)
OpenJDK Server VM (build 11.0.16+8-post-Raspbian-1deb11u1, mixed mode)

J-N-K · November 13, 2022, 11:26am

Can you try switching to

which seems to have solved the issue? It could be a bug in the JDK.

laursen · November 13, 2022, 1:10pm

Thanks! I think I’ll wait a bit to not mess too much with my production system right now:

openhabian@openhabian:~ $ sudo apt-get --only-upgrade install openjdk-11-jdk
[sudo] password for openhabian:
Reading package lists... Done
Building dependency tree... Done
Reading state information... Done
openjdk-11-jdk is already the newest version (11.0.16+8-1~deb11u1).
0 upgraded, 0 newly installed, 0 to remove and 1 not upgraded.

Cc @mstormi

mstormi · November 13, 2022, 4:06pm

what do you want to tell ? It’s Raspi OS / Debian to declare an openjdk package to be latest in “release” or not, so if you want anything newer from testing or unstable repo you need to explicitly tell it on install.

laursen · November 13, 2022, 7:55pm

I tagged you for two purposes.

Possibly getting some knowledge from you about the upgrade process, which I got - thanks. When a new version is released upstream, how fast will it usually propagate downstream and become available in openHABian?
To share this issue with you as a heads-up. If it will be confirmed that 11.0.17 resolves the issue, we can hope that it will make it into the distribution in time for 3.4, or alternatively we would somehow need to work around this issue in 11.0.16, as otherwise openHABian users cannot use jsscripting - at least to my understanding.

What would be a safe route (if any) for replacing the openjdk package in openHABian with a newer version without breaking dependencies etc. and messing everything up? With the plan to then revert the upgrade after testing, and go back to default openHABian packages like before.

mstormi · November 13, 2022, 9:26pm

That’s beyond my control unless I explicitly rework things to forcefully install that version.

That in the first place would mean everyone to upgrade 3.4 has to upgrade his java before. The number of OH starters will be marginal compared to that huge number of people affected.
And it wouldn’t only affect openHABian users so we would have to come up with a solution for all others, too.
So if that really was the case I’d rather propose to revert the recent change that made new java become a need, whatever it was.

florian-h05 · November 13, 2022, 11:37pm

Some news from my side, I just remembered that I had some Raspberry Pi 3B with openHABian installed at home, but it was not used.
So I started it, did a fresh openHAB 3.4.0.M4 install, and I can reproduce the issue.

That means: I can try to find the root cause and fix it!

florian-h05 · November 14, 2022, 1:21pm

Good news: I think that I have fixed the problem.
JS Scripting is now working on my Pi without any problems.
Could any one you please verify that it is working now on your system? @laursen?

The fix PR is now open: [jsscripting] Fix failure on some platforms & JDKs by florian-h05 · Pull Request #13714 · openhab/openhab-addons · GitHub.

Follow these steps to try it yourself:

Uninstall the JS Scripting add-on
Download the artifact from here: !Microsoft OneDrive - Access files anywhere. Create docs with free Office Online.
Place it to the /srv/openhab-addons folder
(Wait a little bit, as the installation takes some time)
(openHAB probably requires a restart)
Try whether your JS scripts are working now

konfetti · November 14, 2022, 3:55pm

After installation of original java version I need to clean tmp and cache! First trial of the installation it seems that there was a crash while installing, but after a reboot it looks better and for now the problems seems to be gone (long term test pending ;)).

Thx!

Br,
Stefan

mark_leonard_tuil · November 14, 2022, 4:08pm

I’m on docker. Followed the above steps. Java seems to work. I did get hit by the timer issue, so cannot test long time.

florian-h05 · November 14, 2022, 4:30pm

But the JS scripts work now?

With timer issue you mean the Multi-thread access requested but now allowed exception, right? FYI: I am also working on fixing this.

mark_leonard_tuil · November 14, 2022, 4:42pm

Yes, JS works. Triggered a lot of stuff to test. Everything worked as expected. Yes. I mean that issue. I saw you are working hard on it. Thanks for your hard work!

florian-h05 · November 14, 2022, 8:33pm

Update: The fix for this bug has been merged.

github.com/openhab/openhab-addons

[jsscripting] Fix failure on some platforms & JDKs

openhab:main ← florian-h05:jsscripting-fix-failure

opened 01:17PM - 14 Nov 22 UTC

florian-h05

+183 -184

## Description The community reported several cases where JS Scripting was no…t working due to some issue with the injection of the global script. This issue seems to only occur on armv7l (e.g. Raspberry Pi 32bit) and OpenJDK 11.0.16. Investigation showed that the occurrence of the problem depends on the GraalJS version, so we have to downgrade the version. (FYI: The version was upgraded in https://github.com/openhab/openhab-addons/pull/13582.) See https://community.openhab.org/t/js-scripting-all-scripts-stop-working-when-upgrading-to-3-4-0-m4/140837. ## Testing/Verification I have verified that JS Scripting is now properly working on my Raspberry Pi 3B: - `uname -a`: ``` Linux homeberrypi 5.10.103-v7+ #1529 SMP Tue Mar 8 12:21:37 GMT 2022 armv7l GNU/Linux ``` - `java --version`: ``` openjdk 11.0.16 2022-07-19 OpenJDK Runtime Environment (build 11.0.16+8-post-Raspbian-1deb10u1) OpenJDK Server VM (build 11.0.16+8-post-Raspbian-1deb10u1, mixed mode) ``` It is still working on my dev system (`Linux florian 5.19.16-200.fc36.x86_64 #1 SMP PREEMPT_DYNAMIC Sun Oct 16 22:50:04 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux`) with `openjdk 11.0.17 2022-10-18`. Anyway, I would prefer that some of the users that reported that problem in the community also verify that it is working now. From 6 users who reported the problem (including myself), until now 4 have verified that the fix works. @jlaur Can you also verify the fix? Artifact download link is at the community.

mstormi · November 15, 2022, 7:40am

Thanks. Does it mean users (or us on behalf of theirs) don’t have to change anything about the java installation ?

florian-h05 · November 15, 2022, 10:53am

Correct. It is now working on the default openHABian Java, so there is no Java change or update required.
I am now planning to upgrade the GraalJS version when openHAB makes the switch to Java 17 LTS.

jstro · December 22, 2022, 4:00pm

I’ve also been experiencing this issue since upgrading to 3.4.0.M5 on my Windows box. See log below. I had a previous version of JDK (I think it was 11.0.09) when the problem first occurred. I updated my Java to 11.0.17 but that doesn’t seem to have fixed the problem. I read on Github that this issue is believed to be related to armv7l and OpenJDK 11.0.16, so I’m posting my experience here since I’m using 11.0.17. It happens only intermittently.

Intel(R) Celeron(R) CPU N3450 @ 1.10GHz 1.10 GHz
8.00 GB (7.79 GB usable)
Windows 10 Pro
openjdk version “11.0.17” 2022-10-18 LTS
OpenJDK Runtime Environment Zulu11.60+19-CA (build 11.0.17+8-LTS)
OpenJDK 64-Bit Server VM Zulu11.60+19-CA (build 11.0.17+8-LTS, mixed mode)
OpenHAB 3.4.0.M5

2022-12-21 23:59:08.297 [ERROR] [.internal.OpenhabGraalJSScriptEngine] - Could not inject global script
javax.script.ScriptException: org.graalvm.polyglot.PolyglotException: Java heap space
	at com.oracle.truffle.js.scriptengine.GraalJSScriptEngine.toScriptException(GraalJSScriptEngine.java:483) ~[bundleFile:?]
	at com.oracle.truffle.js.scriptengine.GraalJSScriptEngine.eval(GraalJSScriptEngine.java:460) ~[bundleFile:?]
	at com.oracle.truffle.js.scriptengine.GraalJSScriptEngine.eval(GraalJSScriptEngine.java:426) ~[bundleFile:?]
	at javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:264) ~[java.scripting:?]
	at org.openhab.automation.jsscripting.internal.scriptengine.DelegatingScriptEngineWithInvocableAndAutocloseable.eval(DelegatingScriptEngineWithInvocableAndAutocloseable.java:54) ~[bundleFile:?]
	at org.openhab.automation.jsscripting.internal.scriptengine.InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.eval(InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.java:69) ~[bundleFile:?]
	at org.openhab.automation.jsscripting.internal.OpenhabGraalJSScriptEngine.beforeInvocation(OpenhabGraalJSScriptEngine.java:222) ~[bundleFile:?]
	at org.openhab.automation.jsscripting.internal.scriptengine.InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.eval(InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.java:68) ~[bundleFile:?]
	at org.openhab.automation.jsscripting.internal.scriptengine.DelegatingScriptEngineWithInvocableAndAutocloseable.eval(DelegatingScriptEngineWithInvocableAndAutocloseable.java:54) ~[bundleFile:?]
	at org.openhab.automation.jsscripting.internal.scriptengine.InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.eval(InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.java:69) ~[bundleFile:?]
	at org.openhab.core.automation.module.script.internal.handler.ScriptActionHandler.lambda$0(ScriptActionHandler.java:58) ~[?:?]
	at java.util.Optional.ifPresent(Optional.java:183) [?:?]
	at org.openhab.core.automation.module.script.internal.handler.ScriptActionHandler.execute(ScriptActionHandler.java:55) [bundleFile:?]
	at org.openhab.core.automation.internal.RuleEngineImpl.executeActions(RuleEngineImpl.java:1177) [bundleFile:?]
	at org.openhab.core.automation.internal.RuleEngineImpl.runRule(RuleEngineImpl.java:989) [bundleFile:?]
	at org.openhab.core.automation.internal.TriggerHandlerCallbackImpl$TriggerData.run(TriggerHandlerCallbackImpl.java:89) [bundleFile:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: org.graalvm.polyglot.PolyglotException: Java heap space
	at com.oracle.truffle.polyglot.PolyglotMapAndFunction.apply(PolyglotMapAndFunction.java:46) ~[bundleFile:?]
	at org.openhab.automation.jsscripting.internal.OpenhabGraalJSScriptEngine.lambda$7(OpenhabGraalJSScriptEngine.java:209) ~[bundleFile:?]
	at org.openhab.automation.jsscripting.internal.OpenhabGraalJSScriptEngine$$Lambda$1640/0x000000010148dc40.get(Unknown Source) ~[?:?]
	at java.util.Optional.orElseGet(Optional.java:369) ~[?:?]
	at <js>.:program(<eval>:1) ~[?:?]
2022-12-21 23:59:08.313 [ERROR] [b.automation.script.javascript.stack] - Failed to execute script:
org.graalvm.polyglot.PolyglotException: ReferenceError: "rules" is not defined
	at <js>.:program(<eval>:1) ~[?:?]
	at org.graalvm.polyglot.Context.eval(Context.java:399) ~[bundleFile:?]
	at com.oracle.truffle.js.scriptengine.GraalJSScriptEngine.eval(GraalJSScriptEngine.java:458) ~[bundleFile:?]
	at com.oracle.truffle.js.scriptengine.GraalJSScriptEngine.eval(GraalJSScriptEngine.java:426) ~[bundleFile:?]
	at javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:264) ~[java.scripting:?]
	at org.openhab.automation.jsscripting.internal.scriptengine.DelegatingScriptEngineWithInvocableAndAutocloseable.eval(DelegatingScriptEngineWithInvocableAndAutocloseable.java:54) ~[bundleFile:?]
	at org.openhab.automation.jsscripting.internal.scriptengine.InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.eval(InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.java:69) ~[bundleFile:?]
	at org.openhab.automation.jsscripting.internal.scriptengine.DelegatingScriptEngineWithInvocableAndAutocloseable.eval(DelegatingScriptEngineWithInvocableAndAutocloseable.java:54) ~[bundleFile:?]
	at org.openhab.automation.jsscripting.internal.scriptengine.InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.eval(InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.java:69) ~[bundleFile:?]
	at org.openhab.core.automation.module.script.internal.handler.ScriptActionHandler.lambda$0(ScriptActionHandler.java:58) ~[?:?]
	at java.util.Optional.ifPresent(Optional.java:183) [?:?]
	at org.openhab.core.automation.module.script.internal.handler.ScriptActionHandler.execute(ScriptActionHandler.java:55) [bundleFile:?]
	at org.openhab.core.automation.internal.RuleEngineImpl.executeActions(RuleEngineImpl.java:1177) [bundleFile:?]
	at org.openhab.core.automation.internal.RuleEngineImpl.runRule(RuleEngineImpl.java:989) [bundleFile:?]
	at org.openhab.core.automation.internal.TriggerHandlerCallbackImpl$TriggerData.run(TriggerHandlerCallbackImpl.java:89) [bundleFile:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.lang.Thread.run(Thread.java:829) [?:?]
2022-12-21 23:59:08.313 [ERROR] [internal.handler.ScriptActionHandler] - Script execution of rule with UID 'Goodnight' failed: org.graalvm.polyglot.PolyglotException: ReferenceError: "rules" is not defined

This occurred when I used rules.runRule in my “Goodnight” rule.

configuration: {}
triggers:
  - id: "1"
    configuration:
      time: 23:59
    type: timer.TimeOfDayTrigger
conditions: []
actions:
  - inputs: {}
    id: "2"
    configuration:
      considerConditions: false
      ruleUIDs:
        - AllLightsOff
    type: core.RunRuleAction
  - inputs: {}
    id: "3"
    configuration:
      type: application/javascript;version=ECMAScript-2021
      script: |-
        rules.runRule("LockDoor", {'door': 'Back'});
        rules.runRule("LockDoor", {'door': 'Front'});
    type: script.ScriptAction```

Perhaps not unrelatedly, my Windows box is often very sluggish in responding since I have upgraded to 3.4.0.M5. It used to be quite snappy. I haven’t fully diagnosed why, but I have noticed that Java seems to be sporadically using a monster amount of CPU and memory, which seems like a likely culprit. This morning, after the error occurring at midnight before, it was quite sluggish: