openhab-addons: [jsscripting] Multi threaded access is not allowed for language(s) js.

Using openHAB 3.2 in two /etc/openhab/automation/js/*.js files I have:

class R {
    constructor(z) {
        this.item = items.getItem(z)
    }
    get isOn() {
        return this.item.state == "ON"
    }
    turn(state) {
        this.item.sendCommand(state)
    }
}

const ri = new R('i'), rz = new R('z')

rules.JSRule({
    name: 'ABC',
    description: 'ABC',
    triggers: [
        triggers.ItemStateChangeTrigger('A', null, "0 W", "Y1"),
        triggers.ItemStateChangeTrigger('B', null, "0 W", "Y2")
    ], execute: (data) => {
            console.error('M', ri.isOn, rz.isOn)
            ri.turn('OFF')
            rz.turn('OFF')
            setTimeout(() => console.error('N', ri.isOn, rz.isOn), 1000)
            setTimeout(() => console.error('P', ri.isOn, rz.isOn), 2000)
    }
})

Running the script logs:

2022-06-26 16:56:25.132 [INFO ] [org.openhab.automation.script       ] - M true true
2022-06-26 16:56:28.550 [INFO ] [org.openhab.automation.script       ] - N false false
2022-06-26 16:56:28.504 [WARN ] [ore.internal.scheduler.SchedulerImpl] - Scheduled job failed and stopped                               
java.lang.IllegalStateException: Multi threaded access requested by thread Thread[OH-scheduler-22,5,main] but is not allowed for language(s) js.
        at com.oracle.truffle.polyglot.PolyglotEngineException.illegalState(PolyglotEngineException.java:129) ~[bundleFile:?] 
        at com.oracle.truffle.polyglot.PolyglotContextImpl.throwDeniedThreadAccess(PolyglotContextImpl.java:940) ~[bundleFile:?]
        at com.oracle.truffle.polyglot.PolyglotContextImpl.checkAllThreadAccesses(PolyglotContextImpl.java:799) ~[bundleFile:?]
        at com.oracle.truffle.polyglot.PolyglotContextImpl.enterThreadChanged(PolyglotContextImpl.java:629) ~[bundleFile:?]
        at com.oracle.truffle.polyglot.PolyglotEngineImpl.enterCached(PolyglotEngineImpl.java:1885) ~[bundleFile:?]
        at com.oracle.truffle.polyglot.HostToGuestRootNode.execute(HostToGuestRootNode.java:112) ~[bundleFile:?]
        at com.oracle.truffle.api.impl.DefaultCallTarget.callDirectOrIndirect(DefaultCallTarget.java:85) ~[bundleFile:?]
        at com.oracle.truffle.api.impl.DefaultCallTarget.call(DefaultCallTarget.java:102) ~[bundleFile:?]        
        at com.oracle.truffle.polyglot.PolyglotFunctionProxyHandler.invoke(PolyglotFunctionProxyHandler.java:154) ~[bundleFile:?]
        at com.sun.proxy.$Proxy701.apply(Unknown Source) ~[?:?]
        at org.openhab.core.model.script.actions.ScriptExecution.lambda$1(ScriptExecution.java:100) ~[bundleFile:?]
        at org.openhab.core.internal.scheduler.SchedulerImpl.lambda$12(SchedulerImpl.java:184) ~[?:?]
        at org.openhab.core.internal.scheduler.SchedulerImpl.lambda$1(SchedulerImpl.java:87) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: com.oracle.truffle.api.TruffleStackTrace$LazyStackTrace

(the above is logged twice, since I have in two distinct .js files nearly identical code). The second exception starts with 2022-06-26 16:56:28.522 [WARN ] [ore.internal.scheduler.SchedulerImpl] - Scheduled job failed and stopped and is thus called after the console.log('N') code.

  • The timestamps do not strictly increase in the /var/log/openhab/openhab.log file.
  • There shall be no Multi threaded access requested by thread Thread[OH-scheduler-22,5,main] but is not allowed for language(s) js. exception. JavaScript is single threaded, setTimeout() does not necessary add a new thread.
  • The error message does not suggest which script/JSRule caused the exception.

About this issue

  • Original URL
  • State: closed
  • Created 2 years ago
  • Comments: 33 (21 by maintainers)

Most upvoted comments

I will double the bounty to 200€. @jpg0 would it be possible to add the ‘bounty’ label ?

@tarag: Good news. I got it working without using some MultiTimerMock workaround.

I am using the following script to verify threadsafety of both triggered rules (so that I did not brake anything) and of scheduled jobs/timers:

const { rules, triggers } = require('openhab');

// Create two rules with the extact same trigger to test whether rules are still threadsafe
rules.JSRule({
  name: 'Test Rule 1',
  triggers: triggers.ItemCommandTrigger('test_switch'),
  execute: (event) => {
    console.info('Rule 1 ran');
  }
});

rules.JSRule({
  name: 'Test Rule 2',
  triggers: triggers.ItemCommandTrigger('test_switch'),
  execute: (event) => {
    console.info('Rule 2 ran');
    // Create 100 timers for the same timeout to ensure that timers/scheduled are now threadsafe
    for (let i = 0; i < 100; i++) {
      setTimeout(() => {
        console.info('setTimeout ' + i + ' completed successfully');
      }, 100);
    }
  }
});

As you can see, creating 100 timers with the same timeout would for sure generate many errors if there was not somy sort of synchronization. But, the synchronization avoids that and makes all scheduled jobs run without any issues:

View my logs
12:53:07.540 [INFO ] [openhab.event.ItemCommandEvent       ] - Item 'test_switch' received command OFF
12:53:07.544 [INFO ] [penhab.automation.script.file.test.js] - Rule 2 ran
12:53:07.554 [INFO ] [penhab.automation.script.file.test.js] - Rule 1 ran
12:53:07.646 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 0 completed successfully
12:53:07.647 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 4 completed successfully
12:53:07.648 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 3 completed successfully
12:53:07.648 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 2 completed successfully
12:53:07.649 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 1 completed successfully
12:53:07.649 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 8 completed successfully
12:53:07.649 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 7 completed successfully
12:53:07.650 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 6 completed successfully
12:53:07.650 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 5 completed successfully
12:53:07.650 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 12 completed successfully
12:53:07.651 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 11 completed successfully
12:53:07.651 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 15 completed successfully
12:53:07.651 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 10 completed successfully
12:53:07.652 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 9 completed successfully
12:53:07.652 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 17 completed successfully
12:53:07.652 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 16 completed successfully
12:53:07.653 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 20 completed successfully
12:53:07.653 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 14 completed successfully
12:53:07.653 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 13 completed successfully
12:53:07.654 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 22 completed successfully
12:53:07.654 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 21 completed successfully
12:53:07.654 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 19 completed successfully
12:53:07.655 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 26 completed successfully
12:53:07.655 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 18 completed successfully
12:53:07.655 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 27 completed successfully
12:53:07.655 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 29 completed successfully
12:53:07.656 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 30 completed successfully
12:53:07.656 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 25 completed successfully
12:53:07.656 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 24 completed successfully
12:53:07.657 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 23 completed successfully
12:53:07.657 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 34 completed successfully
12:53:07.657 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 33 completed successfully
12:53:07.658 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 32 completed successfully
12:53:07.658 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 31 completed successfully
12:53:07.658 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 38 completed successfully
12:53:07.659 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 39 completed successfully
12:53:07.659 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 28 completed successfully
12:53:07.659 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 40 completed successfully
12:53:07.660 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 42 completed successfully
12:53:07.660 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 37 completed successfully
12:53:07.661 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 36 completed successfully
12:53:07.661 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 45 completed successfully
12:53:07.661 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 35 completed successfully
12:53:07.662 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 47 completed successfully
12:53:07.662 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 46 completed successfully
12:53:07.662 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 49 completed successfully
12:53:07.663 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 44 completed successfully
12:53:07.663 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 51 completed successfully
12:53:07.663 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 43 completed successfully
12:53:07.664 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 41 completed successfully
12:53:07.664 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 53 completed successfully
12:53:07.665 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 52 completed successfully
12:53:07.665 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 50 completed successfully
12:53:07.665 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 57 completed successfully
12:53:07.666 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 48 completed successfully
12:53:07.666 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 58 completed successfully
12:53:07.667 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 56 completed successfully
12:53:07.667 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 55 completed successfully
12:53:07.667 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 54 completed successfully
12:53:07.668 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 62 completed successfully
12:53:07.668 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 64 completed successfully
12:53:07.668 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 61 completed successfully
12:53:07.669 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 60 completed successfully
12:53:07.669 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 59 completed successfully
12:53:07.670 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 67 completed successfully
12:53:07.670 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 69 completed successfully
12:53:07.670 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 70 completed successfully
12:53:07.671 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 71 completed successfully
12:53:07.671 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 72 completed successfully
12:53:07.671 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 73 completed successfully
12:53:07.672 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 74 completed successfully
12:53:07.672 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 66 completed successfully
12:53:07.672 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 65 completed successfully
12:53:07.673 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 77 completed successfully
12:53:07.673 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 78 completed successfully
12:53:07.673 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 63 completed successfully
12:53:07.674 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 79 completed successfully
12:53:07.674 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 76 completed successfully
12:53:07.675 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 82 completed successfully
12:53:07.675 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 83 completed successfully
12:53:07.675 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 84 completed successfully
12:53:07.676 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 85 completed successfully
12:53:07.676 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 86 completed successfully
12:53:07.676 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 87 completed successfully
12:53:07.677 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 75 completed successfully
12:53:07.677 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 68 completed successfully
12:53:07.677 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 89 completed successfully
12:53:07.678 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 88 completed successfully
12:53:07.678 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 92 completed successfully
12:53:07.678 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 81 completed successfully
12:53:07.679 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 94 completed successfully
12:53:07.679 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 80 completed successfully
12:53:07.679 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 95 completed successfully
12:53:07.680 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 97 completed successfully
12:53:07.680 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 93 completed successfully
12:53:07.681 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 99 completed successfully
12:53:07.681 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 91 completed successfully
12:53:07.681 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 90 completed successfully
12:53:07.682 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 98 completed successfully
12:53:07.682 [INFO ] [penhab.automation.script.file.test.js] - setTimeout 96 completed successfully

@jpg0 My implementation is not exactly what you were talking of in your last comment, I am “only” using a shared lock mechanism for scheduled jobs and rules. I haven’t tried wrapping the Context as I currently don’t see where to do that correctly.

When Graal is running in NodeJS mode presumably this execution then gets added to the event loop and executed. In openHAB where does this go?

That are quite interesting questions, but currently I don’t have the time and I also don’t have the knowledge to investigate that and introduce some sort of event loop.

GraalJS has been adding things quickly, especially in the area of porting NodeJS features to the JS runtime, so there may be something useable already there.

Looking at the changelog, I don’t see changes related to that. Their example for multithread access is also using a lock, so currently I don’t expect GraalJS to have a built-in solution.