From e6056d3142d3f5a5b3e699f32c57db08d82cdad5 Mon Sep 17 00:00:00 2001 From: Florian Hotze Date: Thu, 24 Oct 2024 19:04:34 +0200 Subject: [PATCH] [jsscripting] Fix multi-threading issues in UI-based scripts (#17510) * [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 --- .../internal/DebuggingGraalScriptEngine.java | 34 +++++++++++++++- .../internal/OpenhabGraalJSScriptEngine.java | 39 ++++++++++++++----- .../internal/threading/ThreadsafeTimers.java | 16 ++++++-- 3 files changed, 75 insertions(+), 14 deletions(-) diff --git a/bundles/org.openhab.automation.jsscripting/src/main/java/org/openhab/automation/jsscripting/internal/DebuggingGraalScriptEngine.java b/bundles/org.openhab.automation.jsscripting/src/main/java/org/openhab/automation/jsscripting/internal/DebuggingGraalScriptEngine.java index 8c71899a6880a..ccf6164dd0c6c 100644 --- a/bundles/org.openhab.automation.jsscripting/src/main/java/org/openhab/automation/jsscripting/internal/DebuggingGraalScriptEngine.java +++ b/bundles/org.openhab.automation.jsscripting/src/main/java/org/openhab/automation/jsscripting/internal/DebuggingGraalScriptEngine.java @@ -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; @@ -36,7 +38,7 @@ * @author Florian Hotze - Improve logger name, Fix memory leak caused by exception logging */ class DebuggingGraalScriptEngine - extends InvocationInterceptingScriptEngineWithInvocableAndCompilableAndAutoCloseable { + extends InvocationInterceptingScriptEngineWithInvocableAndCompilableAndAutoCloseable implements Lock { private static final int STACK_TRACE_LENGTH = 5; @@ -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(); + } } diff --git a/bundles/org.openhab.automation.jsscripting/src/main/java/org/openhab/automation/jsscripting/internal/OpenhabGraalJSScriptEngine.java b/bundles/org.openhab.automation.jsscripting/src/main/java/org/openhab/automation/jsscripting/internal/OpenhabGraalJSScriptEngine.java index 94b89666318b0..5cca25dccde4c 100644 --- a/bundles/org.openhab.automation.jsscripting/src/main/java/org/openhab/automation/jsscripting/internal/OpenhabGraalJSScriptEngine.java +++ b/bundles/org.openhab.automation.jsscripting/src/main/java/org/openhab/automation/jsscripting/internal/OpenhabGraalJSScriptEngine.java @@ -74,7 +74,6 @@ public class OpenhabGraalJSScriptEngine extends InvocationInterceptingScriptEngineWithInvocableAndCompilableAndAutoCloseable implements Lock { - private static final Logger LOGGER = LoggerFactory.getLogger(OpenhabGraalJSScriptEngine.class); private static final Source GLOBAL_SOURCE; static { try { @@ -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; @@ -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) @@ -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; @@ -257,7 +259,7 @@ protected void beforeInvocation() { Consumer localScriptDependencyListener = (Consumer) 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; @@ -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); } @@ -353,6 +363,7 @@ private static Reader getFileAsReader(String fileName) throws IOException { @Override public void lock() { lock.lock(); + logger.debug("Lock acquired."); } @Override @@ -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 diff --git a/bundles/org.openhab.automation.jsscripting/src/main/java/org/openhab/automation/jsscripting/internal/threading/ThreadsafeTimers.java b/bundles/org.openhab.automation.jsscripting/src/main/java/org/openhab/automation/jsscripting/internal/threading/ThreadsafeTimers.java index 1d7ea89e59594..faf3a8278f003 100644 --- a/bundles/org.openhab.automation.jsscripting/src/main/java/org/openhab/automation/jsscripting/internal/threading/ThreadsafeTimers.java +++ b/bundles/org.openhab.automation.jsscripting/src/main/java/org/openhab/automation/jsscripting/internal/threading/ThreadsafeTimers.java @@ -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 (setTimeout(), setInterval() and @@ -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; @@ -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"); } }); } @@ -103,12 +109,14 @@ public long setTimeout(Runnable callback, long delay) { long id = lastId.incrementAndGet(); ScheduledCompletableFuture 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); @@ -146,11 +154,13 @@ public long setInterval(Runnable callback, long delay) { long id = lastId.incrementAndGet(); ScheduledCompletableFuture 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);