Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[jsscripting] Loading script files crashes openHAB #12577

Closed
jlaur opened this issue Apr 4, 2022 · 25 comments · Fixed by #13824
Closed

[jsscripting] Loading script files crashes openHAB #12577

jlaur opened this issue Apr 4, 2022 · 25 comments · Fixed by #13824
Assignees
Labels
bug An unexpected problem or unintended behavior of an add-on

Comments

@jlaur
Copy link
Contributor

jlaur commented Apr 4, 2022

This is a follow-up bug report similar to #11952 which I was hoping would have been fixed by openhab/openhab-core#2681 and #12022, but the issue seems to remain in 3.4M5.

Expected Behavior

Loading a JS script from a file should not make the system unstable.

Current Behavior

After reloading a script file multiple times the system becomes slower and slower until it ultimately will become very unstable with timeouts.

Steps to Reproduce

Create this file somewhere as test1.sh:

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

And this one as test2.sh:

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

And finally, create this script as reproduce_issue_12577.sh:

#!/bin/bash
echo "Switch Issue12577" > $OPENHAB_CONF/items/issue_12577.items
i=1
while [ $i -lt 50 ]
do
    if [ $((i % 2)) -eq 0 ]
    then
        cp test1.js "$OPENHAB_CONF/automation/js/test.js"
    else
        cp test2.js "$OPENHAB_CONF/automation/js/test.js"
    fi
    sleep 5
    ((i++))
done

Set execute permission:

chmod +x reproduce_issue_12577.sh

Now run this script and wait a few minutes. For me, after running all 50 iterations, the last log items will look something like this:

2022-04-04 22:27:53.195 [INFO ] [rulesupport.loader.ScriptFileWatcher] - Loading script '/etc/openhab/automation/js/test.js'
2022-04-04 22:28:48.771 [INFO ] [org.openhab.automation.script.rules ] - Adding rule: Reproduce jsscripting issue
2022-04-04 22:28:52.169 [INFO ] [rulesupport.loader.ScriptFileWatcher] - Loading script '/etc/openhab/automation/js/test.js'
2022-04-04 22:29:49.940 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@8e17f4' takes more than 5000ms.

After this point the system is no longer usable and a complete openHAB restart is needed. CPU usage of the java process is maxed out. Please note that from loading the script and until the rule was being added, almost a minute passed.

Context

This problem prevents migration from DSL rules to jsscripting, at least for users writing rules in files.

Your Environment

openHABian 1.7, openHAB 3.2-3.3.

@jlaur jlaur added the bug An unexpected problem or unintended behavior of an add-on label Apr 4, 2022
@jlaur
Copy link
Contributor Author

jlaur commented Apr 4, 2022

@jpg0 - I've tried to provide some information for reproducing a stability issue with jsscripting I'm still having with the 3.3 milestone releases. I hope it will be possible to reproduce, otherwise please let me know of any additional details I can provide.

@J-N-K
Copy link
Member

J-N-K commented Apr 6, 2022

I can't reproduce your failure (probably I have too much memory), but I can see an increasing use of heap memory due to rule-related objects not being unloaded properly:

Bildschirmfoto 2022-04-06 um 18 05 14

This is caused by a bug in core which will be fixed by openhab/openhab-core#2897.

@jlaur
Copy link
Contributor Author

jlaur commented Apr 6, 2022

@J-N-K - wow, that was fast! Thanks a lot!

@J-N-K
Copy link
Member

J-N-K commented Apr 6, 2022

But there is at least one other memory leak. The OpenhabGraalJSScriptEngine.beforeInvocation instantiates a ThreadsafeWrappingScriptedAutomationManagerDelegate (indirectly, ScriptExtensionModuleProvider.processValues is called via ScriptExtensionModuleProvider.runtimeModule and ScriptExtensionModuleProvider.locatorFor) which is not cleaned up on rule unload. There are more, but all are internal to the scripting add-on, not in core.

I have no idea how that works, maybe @jpg0 knows.

@jpg0
Copy link
Contributor

jpg0 commented Apr 6, 2022

That wrapper is to try to synchronise access to a script engine. They don't support concurrent access.

@J-N-K
Copy link
Member

J-N-K commented Apr 6, 2022

Yes, but someone still holds a reference to that after the script has been unloaded. That‘s not correct.

@jpg0
Copy link
Contributor

jpg0 commented Apr 6, 2022

Absolutely - I'll take a look at that.

@jlaur
Copy link
Contributor Author

jlaur commented May 2, 2022

I have re-run this test after upgrading to 3.3M4 and the problem can still be reproduced.

@jpg0
Copy link
Contributor

jpg0 commented May 12, 2022

I took a look at this today. I did find a leak, which I have removed in #12725.

@jlaur
Copy link
Contributor Author

jlaur commented Jun 5, 2022

I have re-run this test after upgrading to 3.3M6 (with #12725), and unfortunately the problem can still be reproduced.

@J-N-K
Copy link
Member

J-N-K commented Jun 6, 2022

I can confirm that it is still there, 50 iterations of the script above result in the following:

Bildschirmfoto 2022-06-06 um 11 25 26

So still the ScriptEngines are not garbage collected since someone holds a reference to them.

@jpg0
Copy link
Contributor

jpg0 commented Jun 6, 2022

@J-N-K any chance you could post the heap dump anywhere?

@J-N-K
Copy link
Member

J-N-K commented Jun 6, 2022

I sent you an email with the link.

@jpg0
Copy link
Contributor

jpg0 commented Jun 6, 2022

Thanks for that. Looking at the dump has only confused me however.

  • If I use eclipse MAT, then it seems to think that jvisualvm is hanging on to everything; possibly this is what you used to create the dump and can be ignored
  • If I use jvisualvm I don't have this problem, and I can see the 50 loaded instances.
    • 49 of them have no GC root, suggesting that they are in fact eligible for GC, but haven't yet been collected
    • The only incoming references they have are from inside Graal, so either the above is true, or Graal is doing something funny - possibly with finalizers, or I am missing something

@J-N-K
Copy link
Member

J-N-K commented Jun 6, 2022

I did see that 49 of them did not have a GC root, too. However, waiting an hour or manually performing GC from VisualVM did not remove them.

I'll do another test and let the system add far more rules and see if the GC kicks in at some point. It's quite time consuming for me because MacOS is slow on detecting file changes (another issue I'm working on) and I need at least 15s between two rule changes.

@J-N-K
Copy link
Member

J-N-K commented Jun 8, 2022

If I run even more (250), I get the following exception:

17:30:16.471 [ERROR] [g.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) ~[?:?]
	at com.oracle.truffle.js.scriptengine.GraalJSScriptEngine.eval(GraalJSScriptEngine.java:460) ~[?:?]
	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:51) ~[?:?]
	at org.openhab.automation.jsscripting.internal.scriptengine.InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.eval(InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.java:69) ~[?:?]
	at org.openhab.automation.jsscripting.internal.OpenhabGraalJSScriptEngine.beforeInvocation(OpenhabGraalJSScriptEngine.java:209) ~[?:?]
	at org.openhab.automation.jsscripting.internal.scriptengine.InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.eval(InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.java:78) ~[?:?]
	at org.openhab.automation.jsscripting.internal.scriptengine.DelegatingScriptEngineWithInvocableAndAutocloseable.eval(DelegatingScriptEngineWithInvocableAndAutocloseable.java:56) ~[?:?]
	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:265) ~[?:?]
	at org.openhab.core.automation.module.script.rulesupport.loader.ScriptFileWatcher.lambda$1(ScriptFileWatcher.java:243) ~[?:?]
	at java.util.Optional.ifPresent(Optional.java:178) ~[?:?]
	at org.openhab.core.automation.module.script.rulesupport.loader.ScriptFileWatcher.importFileWhenReady(ScriptFileWatcher.java:241) ~[?:?]
	at org.openhab.core.automation.module.script.rulesupport.loader.ScriptFileWatcher.processWatchEvent(ScriptFileWatcher.java:215) ~[?:?]
	at org.openhab.automation.jsscripting.internal.fs.watch.JSScriptFileWatcher.processWatchEvent(JSScriptFileWatcher.java:48) ~[?:?]
	at org.openhab.core.service.WatchQueueReader.lambda$5(WatchQueueReader.java:356) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) [?:?]
	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:1136) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
	at java.lang.Thread.run(Thread.java:833) [?:?]
Caused by: org.graalvm.polyglot.PolyglotException: Java heap space
	at com.oracle.truffle.polyglot.PolyglotMapAndFunction.apply(PolyglotMapAndFunction.java:46) ~[?:?]
	at org.openhab.automation.jsscripting.internal.OpenhabGraalJSScriptEngine.lambda$7(OpenhabGraalJSScriptEngine.java:201) ~[?:?]
	at org.openhab.automation.jsscripting.internal.OpenhabGraalJSScriptEngine$$Lambda$1363/0x0000000300e36b70.get(Unknown Source) ~[?:?]
	at java.util.Optional.orElseGet(Optional.java:364) ~[?:?]
	at <js>.:program(test.js:1) ~[?:?]
17:30:31.434 [ERROR] [ab.automation.script.javascript.stack] - Failed to execute script:
org.graalvm.polyglot.PolyglotException: ReferenceError: "rules" is not defined
	at <js>.:program(test.js:1) ~[?:?]
	at org.graalvm.polyglot.Context.eval(Context.java:379) ~[?:?]
	at com.oracle.truffle.js.scriptengine.GraalJSScriptEngine.eval(GraalJSScriptEngine.java:458) ~[?:?]
	at com.oracle.truffle.js.scriptengine.GraalJSScriptEngine.eval(GraalJSScriptEngine.java:400) ~[?:?]
	at javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:247) ~[java.scripting:?]
	at org.openhab.automation.jsscripting.internal.scriptengine.DelegatingScriptEngineWithInvocableAndAutocloseable.eval(DelegatingScriptEngineWithInvocableAndAutocloseable.java:56) ~[?:?]
	at org.openhab.automation.jsscripting.internal.scriptengine.InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.eval(InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.java:79) ~[?:?]
	at org.openhab.automation.jsscripting.internal.scriptengine.DelegatingScriptEngineWithInvocableAndAutocloseable.eval(DelegatingScriptEngineWithInvocableAndAutocloseable.java:56) ~[?:?]
	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:265) ~[?:?]
	at org.openhab.core.automation.module.script.rulesupport.loader.ScriptFileWatcher.lambda$1(ScriptFileWatcher.java:243) ~[?:?]
	at java.util.Optional.ifPresent(Optional.java:178) ~[?:?]
	at org.openhab.core.automation.module.script.rulesupport.loader.ScriptFileWatcher.importFileWhenReady(ScriptFileWatcher.java:241) ~[?:?]
	at org.openhab.core.automation.module.script.rulesupport.loader.ScriptFileWatcher.processWatchEvent(ScriptFileWatcher.java:215) ~[?:?]
	at org.openhab.automation.jsscripting.internal.fs.watch.JSScriptFileWatcher.processWatchEvent(JSScriptFileWatcher.java:48) ~[?:?]
	at org.openhab.core.service.WatchQueueReader.lambda$5(WatchQueueReader.java:356) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) [?:?]
	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:1136) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
	at java.lang.Thread.run(Thread.java:833) [?:?]
17:30:41.946 [ERROR] [ript.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/Users/jan/Downloads/openhab-3-3/conf/automation/js/test.js': org.graalvm.polyglot.PolyglotException: ReferenceError: "rules" is not defined

I'm not sure if this is helpful, it just shows where the OOM first occurs.

@jlaur
Copy link
Contributor Author

jlaur commented Jul 3, 2022

I've updated the description to reflect that this problem exists in the 3.3 release version also.

@jlaur
Copy link
Contributor Author

jlaur commented Nov 6, 2022

@florian-h05 - I know it's too much to ask. But seeing your recent activity with moving jsscripting forward, I'm really hoping someone will be able to nail this at some point. I was hoping to spend Christmas last year migrating my rules to JS, but this is still is dream for me, since openHABian on a Raspberry Pi 3 will basically become unstable within minutes after starting working on scripts. 😢

@florian-h05
Copy link
Contributor

florian-h05 commented Nov 6, 2022

@jlaur
Could you please check if the issue still persists with the latest milestone (3.4.0.M4)?
I can‘t because I am not really able to reproduce this issue on my dev setup (maybe because I have too much memory?).

I have the hope that this issue is solved because I upgraded GraalJS in one of my latest PRs.

As jpg0 stated back in June:

If I use jvisualvm I don't have this problem, and I can see the 50 loaded instances.

  • 49 of them have no GC root, suggesting that they are in fact eligible for GC, but haven't yet been collected
  • The only incoming references they have are from inside Graal, so either the above is true, or Graal is doing something funny - possibly with finalizers, or I am missing something

If the references really came from inside Graal, that might have been a bug which has been solved in a new version.

@J-N-K
Copy link
Member

J-N-K commented Nov 6, 2022

It‘s only a question of the amount of reloads. My 16GB MacBook shows OOM after 260 reloads. How much memory do you have? And you‘ll see in VisualVM if the number of instances increases, even if it does not crash.

@florian-h05
Copy link
Contributor

My dev system has 32GB of RAM — that explains something here. I guess I would need many many reloads to experience OOM.

@florian-h05
Copy link
Contributor

@jlaur I will try this weekend to have at least a closer look at this.

@florian-h05 florian-h05 changed the title [jsscripting] Loading scripts crashes openHAB [jsscripting] Loading script files crashes openHAB Nov 18, 2022
@florian-h05 florian-h05 self-assigned this Nov 18, 2022
@jlaur
Copy link
Contributor Author

jlaur commented Nov 28, 2022

@florian-h05 - I have now verified that this is still an issue in 3.4M5.

@florian-h05
Copy link
Contributor

florian-h05 commented Dec 2, 2022

First of all, I had to modify the test1.js and test2.js scripts to actually differ, so that the update is recoognized and loaded by openHAB:

JS file for reproducing the issue

test1.js:

const { rules, triggers } = require('openhab');

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

test2.js:

const { rules, triggers } = require('openhab');

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

After looking into this on my machine (Fedora 36, amd64, fixed heap site to 1G), I have noticed the following points:

  • With these modified scripts, I was able to crash openHAB with about 100 iterations of the shell script, which gives me:
Logs
17:06:02.812 [INFO ] [org.openhab.automation.script.rules  ] - Adding rule: Reproduce jsscripting issue 1
17:06:03.070 [INFO ] [port.loader.AbstractScriptFileWatcher] - Loading script '/etc/openhab/automation/js/test.js'
17:06:03.070 [DEBUG] [g.internal.OpenhabGraalJSScriptEngine] - Initializing GraalJS script engine...
17:06:03.074 [DEBUG] [g.internal.OpenhabGraalJSScriptEngine] - Injecting ThreadsafeTimers into the JS runtime...

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "FileSystemWatchService"

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "OH-common-12"

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "SocketListener(fedora.local.)"

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "fileinstall-/var/lib/openhab/etc"
Exception in thread "fileinstall-/usr/share/openhab/addons" Exception in thread "SocketListener(fedora.local.)" Exception in thread "OH-scriptwatcher-1" Exception in thread "SocketListener(fedora.local.)" Exception in thread "OH-eventwatcher-1" Exception in thread "JmDNS(fedora.local.).Timer" Exception in thread "RMI TCP Connection(idle)" Exception in thread "JmDNS(fedora.local.).Timer" java.lang.OutOfMemoryError: Java heap space
Exception in thread "Log4j2-TF-10-Scheduled-3" java.lang.OutOfMemoryError: Java heap space
Exception in thread "JmDNS(fedora.local.).Timer" java.lang.OutOfMemoryError: Java heap space
java.lang.OutOfMemoryError: Java heap space
java.lang.OutOfMemoryError: Java heap space
Exception in thread "Active Thread: Equinox Container: d21b9ba2-4226-4002-a881-1f03cc2a048a" java.lang.OutOfMemoryError: Java heap space
java.lang.OutOfMemoryError: Java heap space
java.lang.OutOfMemoryError: Java heap space
java.lang.OutOfMemoryError: Java heap space
java.lang.OutOfMemoryError: Java heap space
java.lang.OutOfMemoryError: Java heap space
Exception in thread "encryption-3-thread-1" java.lang.OutOfMemoryError: Java heap space
17:07:01.323 [INFO ] [port.loader.AbstractScriptFileWatcher] - Loading script '/etc/openhab/automation/js/test.js'
17:07:01.323 [WARN ] [ommon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.OutOfMemoryError: Java heap space
17:07:01.323 [WARN ] [ommon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.OutOfMemoryError: Java heap space
17:07:01.323 [WARN ] [ommon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.OutOfMemoryError: Java heap space
Exception in thread "OH-common-1" java.lang.OutOfMemoryError: Java heap space
17:07:01.849 [ERROR] [rnal.common.AbstractInvocationHandler] - An error occurred while calling method 'Runnable.run()' on 'org.openhab.core.automation.module.script.internal.ScriptEngineManagerImpl$$Lambda$1505/0x00000001012a0c40@10c923e0': Multi threaded access requested by thread Thread[OH-safeCall-5,5,main] but is not allowed for language(s) js.
java.lang.IllegalStateException: Multi threaded access requested by thread Thread[OH-safeCall-5,5,main] but is not allowed for language(s) js.
        at com.oracle.truffle.polyglot.PolyglotEngineException.illegalState(PolyglotEngineException.java:129) ~[org.graalvm.truffle:?]
        at com.oracle.truffle.polyglot.PolyglotContextImpl.throwDeniedThreadAccess(PolyglotContextImpl.java:1034) ~[org.graalvm.truffle:?]
        at com.oracle.truffle.polyglot.PolyglotContextImpl.checkAllThreadAccesses(PolyglotContextImpl.java:893) ~[org.graalvm.truffle:?]
        at com.oracle.truffle.polyglot.PolyglotContextImpl.enterThreadChanged(PolyglotContextImpl.java:723) ~[org.graalvm.truffle:?]
        at com.oracle.truffle.polyglot.PolyglotEngineImpl.enterCached(PolyglotEngineImpl.java:1991) ~[org.graalvm.truffle:?]
        at com.oracle.truffle.polyglot.PolyglotEngineImpl.enterIfNeeded(PolyglotEngineImpl.java:1919) ~[org.graalvm.truffle:?]
        at com.oracle.truffle.polyglot.PolyglotValueDispatch.hostEnter(PolyglotValueDispatch.java:1227) ~[org.graalvm.truffle:?]
        at com.oracle.truffle.polyglot.PolyglotContextImpl.getBindings(PolyglotContextImpl.java:1040) ~[org.graalvm.truffle:?]
        at com.oracle.truffle.polyglot.PolyglotContextDispatch.getBindings(PolyglotContextDispatch.java:98) ~[org.graalvm.truffle:?]
        at org.graalvm.polyglot.Context.getBindings(Context.java:560) ~[org.graalvm.sdk:?]
        at com.oracle.truffle.js.scriptengine.GraalJSScriptEngine.invokeFunction(GraalJSScriptEngine.java:548) ~[org.graalvm.js.scriptengine:?]
        at org.openhab.automation.jsscripting.internal.scriptengine.DelegatingScriptEngineWithInvocableAndAutocloseable.invokeFunction(DelegatingScriptEngineWithInvocableAndAutocloseable.java:123) ~[?:?]
        at org.openhab.automation.jsscripting.internal.scriptengine.InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.invokeFunction(InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.java:119) ~[?:?]
        at org.openhab.automation.jsscripting.internal.OpenhabGraalJSScriptEngine.invokeFunction(OpenhabGraalJSScriptEngine.java:232) ~[?:?]
        at org.openhab.automation.jsscripting.internal.scriptengine.DelegatingScriptEngineWithInvocableAndAutocloseable.invokeFunction(DelegatingScriptEngineWithInvocableAndAutocloseable.java:123) ~[?:?]
        at org.openhab.automation.jsscripting.internal.scriptengine.InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.invokeFunction(InvocationInterceptingScriptEngineWithInvocableAndAutoCloseable.java:119) ~[?:?]
        at org.openhab.core.automation.module.script.internal.ScriptEngineManagerImpl.lambda$5(ScriptEngineManagerImpl.java:307) ~[?:?]
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
        at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]
        at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
        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) [?:?]
17:07:03.434 [DEBUG] [g.internal.OpenhabGraalJSScriptEngine] - Initializing GraalJS script engine...
17:07:04.540 [DEBUG] [g.internal.OpenhabGraalJSScriptEngine] - Injecting ThreadsafeTimers into the JS runtime...
17:07:04.542 [ERROR] [g.internal.OpenhabGraalJSScriptEngine] - Could not inject global script
javax.script.ScriptException: org.graalvm.polyglot.PolyglotException: Java heap space: failed reallocation of scalar replaced objects
        at com.oracle.truffle.js.scriptengine.GraalJSScriptEngine.toScriptException(GraalJSScriptEngine.java:483) ~[org.graalvm.js.scriptengine:?]
        at com.oracle.truffle.js.scriptengine.GraalJSScriptEngine.eval(GraalJSScriptEngine.java:460) ~[org.graalvm.js.scriptengine:?]
        at com.oracle.truffle.js.scriptengine.GraalJSScriptEngine.eval(GraalJSScriptEngine.java:426) ~[org.graalvm.js.scriptengine:?]
        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:222) ~[?:?]
        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.lambda$2(ScriptEngineManagerImpl.java:194) ~[?:?]
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
        at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]
        at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
        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: failed reallocation of scalar replaced objects
        at com.oracle.truffle.polyglot.PolyglotMapAndFunction.apply(PolyglotMapAndFunction.java:46) ~[org.graalvm.truffle:?]
        at org.openhab.automation.jsscripting.internal.OpenhabGraalJSScriptEngine.lambda$7(OpenhabGraalJSScriptEngine.java:209) ~[?:?]
        at java.util.Optional.orElseGet(Optional.java:369) ~[?:?]
        at org.openhab.automation.jsscripting.internal.OpenhabGraalJSScriptEngine.lambda$5(OpenhabGraalJSScriptEngine.java:209) ~[?:?]
        at <js>.:anonymous(/etc/openhab/automation/js/node_modules/@js-joda/timezone/dist/js-joda-timezone.js:7) ~[?:?]
        at <js>.:anonymous(/etc/openhab/automation/js/node_modules/@js-joda/timezone/dist/js-joda-timezone.js:6) ~[?:?]
        at com.oracle.truffle.polyglot.PolyglotMapAndFunction.apply(PolyglotMapAndFunction.java:46) ~[org.graalvm.truffle:?]
        at org.openhab.automation.jsscripting.internal.OpenhabGraalJSScriptEngine.lambda$7(OpenhabGraalJSScriptEngine.java:209) ~[?:?]
        at java.util.Optional.orElseGet(Optional.java:369) ~[?:?]
        at org.openhab.automation.jsscripting.internal.OpenhabGraalJSScriptEngine.lambda$5(OpenhabGraalJSScriptEngine.java:209) ~[?:?]
        at <js>.:anonymous(/etc/openhab/automation/js/node_modules/openhab/time.js:8) ~[?:?]
        at com.oracle.truffle.polyglot.PolyglotMapAndFunction.apply(PolyglotMapAndFunction.java:46) ~[org.graalvm.truffle:?]
        at org.openhab.automation.jsscripting.internal.OpenhabGraalJSScriptEngine.lambda$7(OpenhabGraalJSScriptEngine.java:209) ~[?:?]
        at java.util.Optional.orElseGet(Optional.java:369) ~[?:?]
        at org.openhab.automation.jsscripting.internal.OpenhabGraalJSScriptEngine.lambda$5(OpenhabGraalJSScriptEngine.java:209) ~[?:?]
        at <js>.:anonymous(/etc/openhab/automation/js/node_modules/openhab/items/item-history.js:2) ~[?:?]
        at com.oracle.truffle.polyglot.PolyglotMapAndFunction.apply(PolyglotMapAndFunction.java:46) ~[org.graalvm.truffle:?]
        at org.openhab.automation.jsscripting.internal.OpenhabGraalJSScriptEngine.lambda$7(OpenhabGraalJSScriptEngine.java:209) ~[?:?]
        at java.util.Optional.orElseGet(Optional.java:369) ~[?:?]
        at org.openhab.automation.jsscripting.internal.OpenhabGraalJSScriptEngine.lambda$5(OpenhabGraalJSScriptEngine.java:209) ~[?:?]
        at <js>.:anonymous(/etc/openhab/automation/js/node_modules/openhab/items/items.js:11) ~[?:?]
        at com.oracle.truffle.polyglot.PolyglotMapAndFunction.apply(PolyglotMapAndFunction.java:46) ~[org.graalvm.truffle:?]
        at org.openhab.automation.jsscripting.internal.OpenhabGraalJSScriptEngine.lambda$7(OpenhabGraalJSScriptEngine.java:209) ~[?:?]
        at java.util.Optional.orElseGet(Optional.java:369) ~[?:?]
        at org.openhab.automation.jsscripting.internal.OpenhabGraalJSScriptEngine.lambda$5(OpenhabGraalJSScriptEngine.java:209) ~[?:?]
        at <js>.:anonymous(/etc/openhab/automation/js/node_modules/openhab/rules/rules.js:50) ~[?:?]
        at com.oracle.truffle.polyglot.PolyglotMapAndFunction.apply(PolyglotMapAndFunction.java:46) ~[org.graalvm.truffle:?]
        at org.openhab.automation.jsscripting.internal.OpenhabGraalJSScriptEngine.lambda$7(OpenhabGraalJSScriptEngine.java:209) ~[?:?]
        at java.util.Optional.orElseGet(Optional.java:369) ~[?:?]
        at org.openhab.automation.jsscripting.internal.OpenhabGraalJSScriptEngine.lambda$5(OpenhabGraalJSScriptEngine.java:209) ~[?:?]
        at <js>.:anonymous(/etc/openhab/automation/js/node_modules/openhab/rules/index.js:1) ~[?:?]
        at com.oracle.truffle.polyglot.PolyglotMapAndFunction.apply(PolyglotMapAndFunction.java:46) ~[org.graalvm.truffle:?]
        at org.openhab.automation.jsscripting.internal.OpenhabGraalJSScriptEngine.lambda$7(OpenhabGraalJSScriptEngine.java:209) ~[?:?]
        at java.util.Optional.orElseGet(Optional.java:369) ~[?:?]
        at org.openhab.automation.jsscripting.internal.OpenhabGraalJSScriptEngine.lambda$5(OpenhabGraalJSScriptEngine.java:209) ~[?:?]
        at <js>.get rules(/etc/openhab/automation/js/node_modules/openhab/index.js:23) ~[?:?]
        at <js>.:program(test.js:1) ~[?:?]
        at org.graalvm.polyglot.Context.eval(Context.java:399) ~[org.graalvm.sdk:?]
        at com.oracle.truffle.js.scriptengine.GraalJSScriptEngine.eval(GraalJSScriptEngine.java:458) ~[org.graalvm.js.scriptengine:?]
        ... 19 more
17:07:05.090 [ERROR] [ript.internal.ScriptEngineManagerImpl] - Error during evaluation of script 'file:/etc/openhab/automation/js/test.js': java.io.IOException: Stream closed
  • Screenshot of the heap usage:
    image
    Seems like GC is able to free heap at some points, but after 17:04 even clicking on "Perform GC" did not help.
  • I have two heap snapshots: First heap snapshot was created on 17:04, the second heap snapshot was created on 17:06.
  • Looking at the first heap snapshot (before OoM), it does not make me any smarter:
    • There is a large number of objects related from com.oracle.truffle.js in the heap, most of them without a GC root.
    • Looking at their references, it seems like they are only referenced from inside Graal.

UPDATE:
I think that I am able to confirm that the memory leak we are encountering has some relation to the host access (also reading oracle/graaljs#121 (comment) and oracle/graaljs#121 (comment)).

@florian-h05
Copy link
Contributor

@jlaur Finally, I have a working fix for this: #13824.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug An unexpected problem or unintended behavior of an add-on
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants