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 8c71899a688..ccf6164dd0c 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 @@ package org.openhab.automation.jsscripting.internal; 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 @@ import org.slf4j.LoggerFactory; * @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 @@ class DebuggingGraalScriptEngine 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 class OpenhabGraalJSScriptEngine 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 class OpenhabGraalJSScriptEngine 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 @@ public class OpenhabGraalJSScriptEngine 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 @@ public class OpenhabGraalJSScriptEngine // 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 @@ public class OpenhabGraalJSScriptEngine @Override public void lock() { lock.lock(); + logger.debug("Lock acquired."); } @Override @@ -373,6 +384,14 @@ public class OpenhabGraalJSScriptEngine @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 1d7ea89e595..faf3a8278f0 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.automation.module.script.action.Timer; 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 @@ import org.openhab.core.scheduler.SchedulerTemporalAdjuster; * 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 class ThreadsafeTimers { 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 class ThreadsafeTimers { 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 class ThreadsafeTimers { 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);