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.

Sign up for GitHub

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] Fix multi-threading issues in UI-based scripts #17510

Merged
merged 5 commits into from
Oct 24, 2024
Merged

[jsscripting] Fix multi-threading issues in UI-based scripts #17510

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
082b8ee
[jsscripting] Make logger non-static
florian-h05 Oct 4, 2024
71dd6f1
[jsscripting] Log lock acquisition and release
florian-h05 Oct 4, 2024
c5c0215
[jsscripting] Implement Lock in DebuggingGraalScriptEngine so openHAB…
florian-h05 Oct 4, 2024
d30653d
[jsscripting] Improve comments in ThreadsafeTimers
florian-h05 Oct 4, 2024
4b9b21d
[jsscripting] Add a short sleep after unlocking the lock to fix multi…
florian-h05 Oct 4, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
34 changes: 33 additions & 1 deletion ...src/main/java/org/openhab/automation/jsscripting/internal/DebuggingGraalScriptEngine.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,6 +15,8 @@
import static org.openhab.core.automation.module.script.ScriptTransformationService.OPENHAB_TRANSFORMATION_SCRIPT;

import java.util.Arrays;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.locks.Condition;
import java.util.concurrent.locks.Lock;
import java.util.stream.Collectors;

Expand All @@ -36,7 +38,7 @@
* @author Florian Hotze - Improve logger name, Fix memory leak caused by exception logging
*/
class DebuggingGraalScriptEngine<T extends ScriptEngine & Invocable & AutoCloseable & Compilable & Lock>
extends InvocationInterceptingScriptEngineWithInvocableAndCompilableAndAutoCloseable<T> {
extends InvocationInterceptingScriptEngineWithInvocableAndCompilableAndAutoCloseable<T> implements Lock {

private static final int STACK_TRACE_LENGTH = 5;

Expand Down Expand Up @@ -111,4 +113,34 @@ private void initializeLogger() {

logger = LoggerFactory.getLogger("org.openhab.automation.script.javascript." + identifier);
}

@Override
public void lock() {
delegate.lock();
}

@Override
public void lockInterruptibly() throws InterruptedException {
delegate.lockInterruptibly();
}

@Override
public boolean tryLock() {
return delegate.tryLock();
}

@Override
public boolean tryLock(long l, TimeUnit timeUnit) throws InterruptedException {
return delegate.tryLock(l, timeUnit);
}

@Override
public void unlock() {
delegate.unlock();
}

@Override
public Condition newCondition() {
return delegate.newCondition();
}
}
39 changes: 29 additions & 10 deletions ...src/main/java/org/openhab/automation/jsscripting/internal/OpenhabGraalJSScriptEngine.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -74,7 +74,6 @@ public class OpenhabGraalJSScriptEngine
extends InvocationInterceptingScriptEngineWithInvocableAndCompilableAndAutoCloseable<GraalJSScriptEngine>
implements Lock {

private static final Logger LOGGER = LoggerFactory.getLogger(OpenhabGraalJSScriptEngine.class);
private static final Source GLOBAL_SOURCE;
static {
try {
Expand Down Expand Up @@ -132,6 +131,8 @@ public class OpenhabGraalJSScriptEngine
v -> v.getMember("rawQtyType").as(QuantityType.class), HostAccess.TargetMappingPrecedence.LOW)
.build();

private final Logger logger = LoggerFactory.getLogger(OpenhabGraalJSScriptEngine.class);

/** {@link Lock} synchronization of multi-thread access */
private final Lock lock = new ReentrantLock();
private final JSRuntimeFeatures jsRuntimeFeatures;
Expand All @@ -155,8 +156,6 @@ public OpenhabGraalJSScriptEngine(boolean injectionEnabled, boolean injectionCac
this.injectionCachingEnabled = injectionCachingEnabled;
this.jsRuntimeFeatures = jsScriptServiceUtil.getJSRuntimeFeatures(lock);

LOGGER.debug("Initializing GraalJS script engine...");

delegate = GraalJSScriptEngine.create(ENGINE,
Context.newBuilder("js").allowExperimentalOptions(true).allowAllAccess(true)
.allowHostAccess(HOST_ACCESS)
Expand Down Expand Up @@ -230,7 +229,10 @@ public Path toRealPath(Path path, LinkOption... linkOptions) throws IOException
protected void beforeInvocation() {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

When is this method called (when executing a script)?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It is called everytime before the engine executes code, there is only one exception: When a compiled script is executed, this won't be called (it has been called when the script was compiled, so the setup already happened).

See https://github.com/openhab/openhab-addons/blob/main/bundles/org.openhab.automation.jsscripting/src/main/java/org/openhab/automation/jsscripting/internal/scriptengine/InvocationInterceptingScriptEngineWithInvocableAndCompilableAndAutoCloseable.java, there is beforeInvocation called.

super.beforeInvocation();

logger.debug("Initializing GraalJS script engine...");

lock.lock();
logger.debug("Lock acquired before invocation.");

if (initialized) {
return;
Expand All @@ -257,7 +259,7 @@ protected void beforeInvocation() {
Consumer<String> localScriptDependencyListener = (Consumer<String>) ctx
.getAttribute(CONTEXT_KEY_DEPENDENCY_LISTENER);
if (localScriptDependencyListener == null) {
LOGGER.warn(
logger.warn(
"Failed to retrieve script script dependency listener from engine bindings. Script dependency tracking will be disabled.");
}
scriptDependencyListener = localScriptDependencyListener;
Expand All @@ -274,33 +276,41 @@ protected void beforeInvocation() {

// Injections into the JS runtime
jsRuntimeFeatures.getFeatures().forEach((key, obj) -> {
LOGGER.debug("Injecting {} into the JS runtime...", key);
logger.debug("Injecting {} into the JS runtime...", key);
delegate.put(key, obj);
});

initialized = true;

try {
LOGGER.debug("Evaluating cached global script...");
logger.debug("Evaluating cached global script...");
delegate.getPolyglotContext().eval(GLOBAL_SOURCE);
if (this.injectionEnabled) {
if (this.injectionCachingEnabled) {
LOGGER.debug("Evaluating cached openhab-js injection...");
logger.debug("Evaluating cached openhab-js injection...");
delegate.getPolyglotContext().eval(OPENHAB_JS_SOURCE);
} else {
LOGGER.debug("Evaluating openhab-js injection from the file system...");
logger.debug("Evaluating openhab-js injection from the file system...");
eval(OPENHAB_JS_INJECTION_CODE);
}
}
LOGGER.debug("Successfully initialized GraalJS script engine.");
logger.debug("Successfully initialized GraalJS script engine.");
} catch (ScriptException e) {
LOGGER.error("Could not inject global script", e);
logger.error("Could not inject global script", e);
}
}

@Override
protected Object afterInvocation(Object obj) {
lock.unlock();
logger.debug("Lock released after invocation.");
// Fixes illegal multi-thread access requested in UI-based scripts, where the script is running and a timer is
// waiting to acquire the lock.
try {
Thread.sleep(10);
} catch (InterruptedException e) {
throw new RuntimeException("Thread interrupted while sleeping", e);
}
return super.afterInvocation(obj);
}

Expand Down Expand Up @@ -353,6 +363,7 @@ private static Reader getFileAsReader(String fileName) throws IOException {
@Override
public void lock() {
lock.lock();
logger.debug("Lock acquired.");
}

@Override
Expand All @@ -373,6 +384,14 @@ public boolean tryLock(long l, TimeUnit timeUnit) throws InterruptedException {
@Override
public void unlock() {
lock.unlock();
logger.debug("Lock released.");
// Fixes illegal multi-thread access requested in UI-based scripts, where the script is running and a timer is
// waiting to acquire the lock.
try {
Thread.sleep(10);
} catch (InterruptedException e) {
throw new RuntimeException("Thread interrupted while sleeping", e);
}
}

@Override
Expand Down
16 changes: 13 additions & 3 deletions ...src/main/java/org/openhab/automation/jsscripting/internal/threading/ThreadsafeTimers.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -27,6 +27,8 @@
import org.openhab.core.scheduler.ScheduledCompletableFuture;
import org.openhab.core.scheduler.Scheduler;
import org.openhab.core.scheduler.SchedulerTemporalAdjuster;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

/**
* A polyfill implementation of NodeJS timer functionality (<code>setTimeout()</code>, <code>setInterval()</code> and
Expand All @@ -36,6 +38,8 @@
* Threadsafe reimplementation of the timer creation methods of {@link ScriptExecution}
*/
public class ThreadsafeTimers {
private final Logger logger = LoggerFactory.getLogger(ThreadsafeTimers.class);

private final Lock lock;
private final Scheduler scheduler;
private final ScriptExecution scriptExecution;
Expand Down Expand Up @@ -81,11 +85,13 @@ public Timer createTimer(ZonedDateTime instant, Runnable closure) {
public Timer createTimer(@Nullable String identifier, ZonedDateTime instant, Runnable closure) {
return scriptExecution.createTimer(identifier, instant, () -> {
lock.lock();
logger.debug("Lock acquired before timer execution");
try {
closure.run();
} finally { // Make sure that Lock is unlocked regardless of an exception is thrown or not to avoid
} finally { // Make sure that Lock is unlocked regardless of an exception being thrown or not to avoid
// deadlocks
lock.unlock();
logger.debug("Lock released after timer execution");
}
});
}
Expand All @@ -103,12 +109,14 @@ public long setTimeout(Runnable callback, long delay) {
long id = lastId.incrementAndGet();
ScheduledCompletableFuture<Object> future = scheduler.schedule(() -> {
lock.lock();
logger.debug("Lock acquired before timeout execution");
try {
callback.run();
idSchedulerMapping.remove(id);
} finally { // Make sure that Lock is unlocked regardless of an exception is thrown or not to avoid
} finally { // Make sure that Lock is unlocked regardless of an exception being thrown or not to avoid
// deadlocks
lock.unlock();
logger.debug("Lock released after timeout execution");
}
}, identifier + ".timeout." + id, Instant.now().plusMillis(delay));
idSchedulerMapping.put(id, future);
Expand Down Expand Up @@ -146,11 +154,13 @@ public long setInterval(Runnable callback, long delay) {
long id = lastId.incrementAndGet();
ScheduledCompletableFuture<Object> future = scheduler.schedule(() -> {
lock.lock();
logger.debug("Lock acquired before interval execution");
try {
callback.run();
} finally { // Make sure that Lock is unlocked regardless of an exception is thrown or not to avoid
} finally { // Make sure that Lock is unlocked regardless of an exception being thrown or not to avoid
// deadlocks
lock.unlock();
logger.debug("Lock released after interval execution");
}
}, identifier + ".interval." + id, new LoopingAdjuster(Duration.ofMillis(delay)));
idSchedulerMapping.put(id, future);
Expand Down