[jsscripting] Fix multi-threading issues in UI-based scripts (openhab#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 <[email protected]>

Author: florian-h05

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<T extends ScriptEngine & Invocable & AutoCloseable & Compilable & Lock>
-        extends InvocationInterceptingScriptEngineWithInvocableAndCompilableAndAutoCloseable<T> {
+        extends InvocationInterceptingScriptEngineWithInvocableAndCompilableAndAutoCloseable<T> 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();
+    }
 }

bundles/org.openhab.automation.jsscripting/src/main/java/org/openhab/automation/jsscripting/internal/OpenhabGraalJSScriptEngine.java

@@ -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 {
@@ -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<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;
@@ -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

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 (<code>setTimeout()</code>, <code>setInterval()</code> 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<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);
@@ -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);