Skip to content

Commit

Permalink
[jsscripting] Fix multi-threading issues in UI-based scripts (#17510)
Browse files Browse the repository at this point in the history 
* [jsscripting] Make logger non-static
* [jsscripting] Log lock acquisition and release
* [jsscripting] Implement Lock in DebuggingGraalScriptEngine so openHAB Core can lock and unlock when executing the pre-compiled script
* [jsscripting] Improve comments in ThreadsafeTimers
* [jsscripting] Add a short sleep after unlocking the lock to fix multi-threading issues with UI-based scripts

Signed-off-by: Florian Hotze <florianh_dev@icloud.com>
  • Loading branch information
@florian-h05
florian-h05 authored Oct 24, 2024
1 parent a6bb537 commit e6056d3
Show file tree
Hide file tree
Showing 3 changed files with 75 additions and 14 deletions.
34 changes: 33 additions & 1 deletion ...src/main/java/org/openhab/automation/jsscripting/internal/DebuggingGraalScriptEngine.java
View file
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
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() {
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
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

0 comments on commit e6056d3

Please sign in to comment.