Blockly producing multi threaded access

Setup, Configuration and Use Scripts & Rules
1
  • Platform information:
    • Hardware: Proxmox on intel i3
    • OS: debian
    • Java Runtime Environment: which java platform is used and what version
    • openHAB version: 4.2.0
  • Issue of the topic:
    My blockly script says that Multi threaded access requested is not allowed. It’s triggered by many different items, eg: Room1Lamp1_Status and it eventually changes the state of Room1Lamp1Zwang after 5 seconds. Every triggering item gets its own timer e.g. “PrivateTimerRoom1Lamp1_Status”
    The triggering items are likely to change their state together at the same time.

How can I avoid this? Please don’t tell me I need a separate rule for every item pair…

Thank you

var EventItem, LastEventItem, StatusState, ItemNameZwang, ZwangState;


EventItem = event.itemName;
if (cache.private.exists(('PrivateTimer' + String(EventItem))) === false || cache.private.get(('PrivateTimer' + String(EventItem))).hasTerminated()) {
  cache.private.put(('PrivateTimer' + String(EventItem)), actions.ScriptExecution.createTimer(('PrivateTimer' + String(EventItem)), time.ZonedDateTime.now().plusSeconds(5), function (timer_context) {
    LastEventItem = (timer_context);
    StatusState = items.getItem(LastEventItem).state;
    ItemNameZwang = LastEventItem.replaceAll('Status','Zwang').replaceAll('_','');
    ZwangState = items.getItem(ItemNameZwang).state;
    if (ZwangState == '0' && StatusState == 'ON') {
      items.getItem(ItemNameZwang).sendCommand('1');
    } else if (ZwangState == '1' && StatusState == 'OFF') {
      items.getItem(ItemNameZwang).sendCommand('0');
    }
    }, EventItem));
} else {
  cache.private.get(('PrivateTimer' + String(EventItem))).reschedule(time.ZonedDateTime.now().plusSeconds(5));
};
  • If logs where generated please post these here using code fences:
java.lang.IllegalStateException: Multi threaded access requested by thread Thread[OH-scheduler-242,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:1034) ~[bundleFile:?]
	at com.oracle.truffle.polyglot.PolyglotContextImpl.checkAllThreadAccesses(PolyglotContextImpl.java:893) ~[bundleFile:?]
	at com.oracle.truffle.polyglot.PolyglotContextImpl.enterThreadChanged(PolyglotContextImpl.java:723) ~[bundleFile:?]
	at com.oracle.truffle.polyglot.PolyglotEngineImpl.enterCached(PolyglotEngineImpl.java:1991) ~[bundleFile:?]
	at com.oracle.truffle.polyglot.HostToGuestRootNode.execute(HostToGuestRootNode.java:110) ~[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 jdk.proxy1.$Proxy912.run(Unknown Source) ~[?:?]
	at org.openhab.automation.jsscripting.internal.threading.ThreadsafeTimers.lambda$0(ThreadsafeTimers.java:85) ~[bundleFile:?]
	at org.openhab.core.internal.scheduler.SchedulerImpl.lambda$12(SchedulerImpl.java:189) ~[?:?]
	at org.openhab.core.internal.scheduler.SchedulerImpl.lambda$1(SchedulerImpl.java:88) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) [?:?]
	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:1136) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
	at java.lang.Thread.run(Thread.java:840) [?:?]
Caused by: com.oracle.truffle.api.TruffleStackTrace$LazyStackTrace
2

honestly I don’t really know why it’s throwing that error. The code looks good to me.

The only thing I would ask is why you use the timer with the reschedule feature? Does something change if you use the timer without reschedule?

3

I don’t see anything bad here either. I have implemented similar rules myself.

Can you please add logs or simplify the rule step by step to find out what line exactly is causing this issue? I am actually surprised the line isn’t shown in the logs.

4

Thanks for your response, I’ve added some debugging and the thing happened again.

This is the new blockly:

grafik
grafik1173×1690 149 KB

That’s the code:

var Debug, Debug2, EventItem, TimerName, LastEventItem, StatusState, ItemNameZwang, ZwangState;


Debug = true;
Debug2 = true;
EventItem = event.itemName;
TimerName = 'PrivateTimer' + String(EventItem);
if (Debug) {
  console.info((['Rule start: ','Item triggered: ',EventItem,' Timer: ',TimerName,' Active:',cache.private.exists(TimerName) && cache.private.get(TimerName).isActive(),' Running:',cache.private.exists(TimerName) && cache.private.get(TimerName).isRunning(),' Terminated:',cache.private.exists(TimerName) && cache.private.get(TimerName).hasTerminated()].join('')));
}
if (cache.private.exists(TimerName) === false || cache.private.get(TimerName).hasTerminated()) {
  cache.private.put(TimerName, actions.ScriptExecution.createTimer(TimerName, time.ZonedDateTime.now().plusSeconds(5), function (timer_context) {
    LastEventItem = (timer_context);
    StatusState = items.getItem(LastEventItem).state;
    if (Debug) {
      console.info(('Item timer done: ' + String(LastEventItem)));
    }
    ItemNameZwang = LastEventItem.replaceAll('Status','Zwang').replaceAll('_','');
    if (Debug) {
      console.info(('Zwang item name: ' + String(ItemNameZwang)));
    }
    ZwangState = items.getItem(ItemNameZwang).state;
    if (ZwangState == '0' && StatusState == 'ON') {
      items.getItem(ItemNameZwang).sendCommand('1');
      if (Debug2) {
        console.info((['Zwang item name: ',ItemNameZwang,' nachgestellt auf automatisch an'].join('')));
      }
    } else if (ZwangState == '1' && StatusState == 'OFF') {
      items.getItem(ItemNameZwang).sendCommand('0');
      if (Debug2) {
        console.info((['Zwang item name: ',ItemNameZwang,' nachgestellt auf automatisch aus'].join('')));
      }
    }
    }, EventItem));
} else {
  cache.private.get(TimerName).reschedule(time.ZonedDateTime.now().plusSeconds(5));
};
if (Debug) {
  console.info((['Rule ended: ','Item triggered: ',EventItem,' Timer: ',TimerName,' Active:',cache.private.exists(TimerName) && cache.private.get(TimerName).isActive(),' Running:',cache.private.exists(TimerName) && cache.private.get(TimerName).isRunning(),' Terminated:',cache.private.exists(TimerName) && cache.private.get(TimerName).hasTerminated()].join('')));
}

And here are my log entries:

2024-10-01 13:30:06.978 [INFO ] [automation.script.ui.TestNachstellen] - Rule start: Item triggered: KnxDevice171_E07LD01Status Timer: PrivateTimerKnxDevice171_E07LD01Status Active:false Running:false Terminated:true
2024-10-01 13:30:06.979 [INFO ] [automation.script.ui.TestNachstellen] - Rule ended: Item triggered: KnxDevice171_E07LD01Status Timer: PrivateTimerKnxDevice171_E07LD01Status Active:true Running:false Terminated:false
2024-10-01 13:30:06.998 [INFO ] [automation.script.ui.TestNachstellen] - Rule start: Item triggered: KnxDevice171_E11LD01Status Timer: PrivateTimerKnxDevice171_E11LD01Status Active:false Running:false Terminated:true
2024-10-01 13:30:06.999 [INFO ] [automation.script.ui.TestNachstellen] - Rule ended: Item triggered: KnxDevice171_E11LD01Status Timer: PrivateTimerKnxDevice171_E11LD01Status Active:true Running:false Terminated:false
2024-10-01 13:30:07.019 [INFO ] [automation.script.ui.TestNachstellen] - Rule start: Item triggered: KnxDevice171_E10LD01Status Timer: PrivateTimerKnxDevice171_E10LD01Status Active:false Running:false Terminated:true
2024-10-01 13:30:07.020 [INFO ] [automation.script.ui.TestNachstellen] - Rule ended: Item triggered: KnxDevice171_E10LD01Status Timer: PrivateTimerKnxDevice171_E10LD01Status Active:true Running:false Terminated:false
2024-10-01 13:30:07.040 [INFO ] [automation.script.ui.TestNachstellen] - Rule start: Item triggered: KnxDevice171_E08LD01Status Timer: PrivateTimerKnxDevice171_E08LD01Status Active:false Running:false Terminated:true
2024-10-01 13:30:07.041 [INFO ] [automation.script.ui.TestNachstellen] - Rule ended: Item triggered: KnxDevice171_E08LD01Status Timer: PrivateTimerKnxDevice171_E08LD01Status Active:true Running:false Terminated:false
2024-10-01 13:30:07.080 [INFO ] [automation.script.ui.TestNachstellen] - Rule start: Item triggered: KnxDevice171_E04LD01Status Timer: PrivateTimerKnxDevice171_E04LD01Status Active:false Running:false Terminated:true
2024-10-01 13:30:07.081 [INFO ] [automation.script.ui.TestNachstellen] - Rule ended: Item triggered: KnxDevice171_E04LD01Status Timer: PrivateTimerKnxDevice171_E04LD01Status Active:true Running:false Terminated:false
2024-10-01 13:30:07.961 [INFO ] [automation.script.ui.TestNachstellen] - Item timer done: KnxDevice171_E01SD01Status
2024-10-01 13:30:07.961 [INFO ] [automation.script.ui.TestNachstellen] - Zwang item name: KnxDevice171E01SD01Zwang
2024-10-01 13:30:10.010 [INFO ] [automation.script.ui.TestNachstellen] - Rule start: Item triggered: KnxDevice171_E13LW02Status Timer: PrivateTimerKnxDevice171_E13LW02Status Active:false Running:false Terminated:true
2024-10-01 13:30:10.011 [INFO ] [automation.script.ui.TestNachstellen] - Rule ended: Item triggered: KnxDevice171_E13LW02Status Timer: PrivateTimerKnxDevice171_E13LW02Status Active:true Running:false Terminated:false
2024-10-01 13:30:11.978 [INFO ] [automation.script.ui.TestNachstellen] - Item timer done: KnxDevice171_E07LD01Status
2024-10-01 13:30:11.978 [INFO ] [automation.script.ui.TestNachstellen] - Zwang item name: KnxDevice171E07LD01Zwang
2024-10-01 13:30:11.998 [INFO ] [automation.script.ui.TestNachstellen] - Item timer done: KnxDevice171_E11LD01Status
2024-10-01 13:30:11.998 [INFO ] [automation.script.ui.TestNachstellen] - Zwang item name: KnxDevice171E11LD01Zwang
2024-10-01 13:30:12.019 [INFO ] [automation.script.ui.TestNachstellen] - Item timer done: KnxDevice171_E10LD01Status
2024-10-01 13:30:12.019 [INFO ] [automation.script.ui.TestNachstellen] - Zwang item name: KnxDevice171E10LD01Zwang
2024-10-01 13:30:12.040 [INFO ] [automation.script.ui.TestNachstellen] - Item timer done: KnxDevice171_E08LD01Status
2024-10-01 13:30:12.040 [INFO ] [automation.script.ui.TestNachstellen] - Zwang item name: KnxDevice171E08LD01Zwang
2024-10-01 13:30:12.080 [INFO ] [automation.script.ui.TestNachstellen] - Item timer done: KnxDevice171_E04LD01Status
2024-10-01 13:30:12.080 [INFO ] [automation.script.ui.TestNachstellen] - Zwang item name: KnxDevice171E04LD01Zwang
2024-10-01 13:30:14.743 [INFO ] [automation.script.ui.TestNachstellen] - Rule start: Item triggered: KnxDevice171_E06LD01Status Timer: PrivateTimerKnxDevice171_E06LD01Status Active:false Running:false Terminated:true
2024-10-01 13:30:14.743 [INFO ] [automation.script.ui.TestNachstellen] - Rule ended: Item triggered: KnxDevice171_E06LD01Status Timer: PrivateTimerKnxDevice171_E06LD01Status Active:true Running:false Terminated:false
2024-10-01 13:30:15.010 [INFO ] [automation.script.ui.TestNachstellen] - Item timer done: KnxDevice171_E13LW02Status
2024-10-01 13:30:15.010 [INFO ] [automation.script.ui.TestNachstellen] - Zwang item name: KnxDevice171E13LW02Zwang
2024-10-01 13:30:19.743 [INFO ] [automation.script.ui.TestNachstellen] - Item timer done: KnxDevice171_E06LD01Status
2024-10-01 13:30:19.743 [INFO ] [automation.script.ui.TestNachstellen] - Zwang item name: KnxDevice171E06LD01Zwang
2024-10-01 13:30:20.981 [INFO ] [automation.script.ui.TestNachstellen] - Rule start: Item triggered: KnxDevice171_E14SD05Status Timer: PrivateTimerKnxDevice171_E14SD05Status Active:false Running:false Terminated:true
2024-10-01 13:30:20.981 [INFO ] [automation.script.ui.TestNachstellen] - Rule ended: Item triggered: KnxDevice171_E14SD05Status Timer: PrivateTimerKnxDevice171_E14SD05Status Active:true Running:false Terminated:false
2024-10-01 13:30:22.006 [INFO ] [automation.script.ui.TestNachstellen] - Rule start: Item triggered: KnxDevice171_E11SD01Status Timer: PrivateTimerKnxDevice171_E11SD01Status Active:false Running:false Terminated:true
2024-10-01 13:30:22.008 [INFO ] [automation.script.ui.TestNachstellen] - Rule ended: Item triggered: KnxDevice171_E11SD01Status Timer: PrivateTimerKnxDevice171_E11SD01Status Active:true Running:false Terminated:false
2024-10-01 13:30:25.980 [INFO ] [automation.script.ui.TestNachstellen] - Item timer done: KnxDevice171_E14SD05Status
2024-10-01 13:30:25.981 [INFO ] [automation.script.ui.TestNachstellen] - Zwang item name: KnxDevice171E14SD05Zwang
2024-10-01 13:30:27.008 [INFO ] [automation.script.ui.TestNachstellen] - Item timer done: KnxDevice171_E11SD01Status
2024-10-01 13:30:27.008 [INFO ] [automation.script.ui.TestNachstellen] - Zwang item name: KnxDevice171E11SD01Zwang
2024-10-01 13:30:43.979 [INFO ] [automation.script.ui.TestNachstellen] - Rule start: Item triggered: KnxDevice171_E07LW03Status Timer: PrivateTimerKnxDevice171_E07LW03Status Active:false Running:false Terminated:true
2024-10-01 13:30:43.979 [INFO ] [automation.script.ui.TestNachstellen] - Rule ended: Item triggered: KnxDevice171_E07LW03Status Timer: PrivateTimerKnxDevice171_E07LW03Status Active:true Running:false Terminated:false
2024-10-01 13:30:44.799 [INFO ] [automation.script.ui.TestNachstellen] - Rule start: Item triggered: KnxDevice171_E06LD01Status Timer: PrivateTimerKnxDevice171_E06LD01Status Active:false Running:false Terminated:true
2024-10-01 13:30:44.800 [INFO ] [automation.script.ui.TestNachstellen] - Rule ended: Item triggered: KnxDevice171_E06LD01Status Timer: PrivateTimerKnxDevice171_E06LD01Status Active:true Running:false Terminated:false
2024-10-01 13:30:48.979 [INFO ] [automation.script.ui.TestNachstellen] - Item timer done: KnxDevice171_E07LW03Status
2024-10-01 13:30:48.979 [INFO ] [automation.script.ui.TestNachstellen] - Zwang item name: KnxDevice171E07LW03Zwang
2024-10-01 13:30:49.799 [INFO ] [automation.script.ui.TestNachstellen] - Item timer done: KnxDevice171_E06LD01Status
2024-10-01 13:30:49.799 [INFO ] [automation.script.ui.TestNachstellen] - Zwang item name: KnxDevice171E06LD01Zwang


2024-10-01 13:30:56.034 [INFO ] [automation.script.ui.TestNachstellen] - Rule start: Item triggered: KnxDevice171_E04SD01Status Timer: PrivateTimerKnxDevice171_E04SD01Status Active:false Running:false Terminated:true
2024-10-01 13:30:56.035 [INFO ] [automation.script.ui.TestNachstellen] - Rule ended: Item triggered: KnxDevice171_E04SD01Status Timer: PrivateTimerKnxDevice171_E04SD01Status Active:true Running:false Terminated:false


2024-10-01 13:31:00.097 [INFO ] [automation.script.ui.TestNachstellen] - Rule start: Item triggered: KnxDevice171_E05LW03Status Timer: PrivateTimerKnxDevice171_E05LW03Status Active:false Running:false Terminated:true
2024-10-01 13:31:00.098 [INFO ] [automation.script.ui.TestNachstellen] - Rule ended: Item triggered: KnxDevice171_E05LW03Status Timer: PrivateTimerKnxDevice171_E05LW03Status Active:true Running:false Terminated:false
2024-10-01 13:31:01.033 [INFO ] [automation.script.ui.TestNachstellen] - Rule start: Item triggered: KnxDevice171_E09SD01Status Timer: PrivateTimerKnxDevice171_E09SD01Status Active:false Running:false Terminated:true
2024-10-01 13:31:01.034 [INFO ] [automation.script.ui.TestNachstellen] - Rule ended: Item triggered: KnxDevice171_E09SD01Status Timer: PrivateTimerKnxDevice171_E09SD01Status Active:true Running:false Terminated:false


2024-10-01 13:31:01.035 [WARN ] [ore.internal.scheduler.SchedulerImpl] - Scheduled job 'PrivateTimerKnxDevice171_E04SD01Status' failed and stopped
java.lang.IllegalStateException: Multi threaded access requested by thread Thread[OH-scheduler-245,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:1034) ~[bundleFile:?]
	at com.oracle.truffle.polyglot.PolyglotContextImpl.checkAllThreadAccesses(PolyglotContextImpl.java:893) ~[bundleFile:?]
	at com.oracle.truffle.polyglot.PolyglotContextImpl.enterThreadChanged(PolyglotContextImpl.java:723) ~[bundleFile:?]
	at com.oracle.truffle.polyglot.PolyglotEngineImpl.enterCached(PolyglotEngineImpl.java:1991) ~[bundleFile:?]
	at com.oracle.truffle.polyglot.HostToGuestRootNode.execute(HostToGuestRootNode.java:110) ~[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 jdk.proxy1.$Proxy912.run(Unknown Source) ~[?:?]
	at org.openhab.automation.jsscripting.internal.threading.ThreadsafeTimers.lambda$0(ThreadsafeTimers.java:85) ~[bundleFile:?]
	at org.openhab.core.internal.scheduler.SchedulerImpl.lambda$12(SchedulerImpl.java:189) ~[?:?]
	at org.openhab.core.internal.scheduler.SchedulerImpl.lambda$1(SchedulerImpl.java:88) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) [?:?]
	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:1136) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
	at java.lang.Thread.run(Thread.java:840) [?:?]
Caused by: com.oracle.truffle.api.TruffleStackTrace$LazyStackTrace


2024-10-01 13:31:05.097 [INFO ] [automation.script.ui.TestNachstellen] - Item timer done: KnxDevice171_E05LW03Status
2024-10-01 13:31:05.097 [INFO ] [automation.script.ui.TestNachstellen] - Zwang item name: KnxDevice171E05LW03Zwang
2024-10-01 13:31:06.033 [INFO ] [automation.script.ui.TestNachstellen] - Item timer done: KnxDevice171_E09SD01Status
2024-10-01 13:31:06.033 [INFO ] [automation.script.ui.TestNachstellen] - Zwang item name: KnxDevice171E09SD01Zwang
2024-10-01 13:31:06.982 [INFO ] [automation.script.ui.TestNachstellen] - Rule start: Item triggered: KnxDevice171_E07LD01Status Timer: PrivateTimerKnxDevice171_E07LD01Status Active:false Running:false Terminated:true
2024-10-01 13:31:06.983 [INFO ] [automation.script.ui.TestNachstellen] - Rule ended: Item triggered: KnxDevice171_E07LD01Status Timer: PrivateTimerKnxDevice171_E07LD01Status Active:true Running:false Terminated:false
2024-10-01 13:31:07.002 [INFO ] [automation.script.ui.TestNachstellen] - Rule start: Item triggered: KnxDevice171_E11LD01Status Timer: PrivateTimerKnxDevice171_E11LD01Status Active:false Running:false Terminated:true
2024-10-01 13:31:07.003 [INFO ] [automation.script.ui.TestNachstellen] - Rule ended: Item triggered: KnxDevice171_E11LD01Status Timer: PrivateTimerKnxDevice171_E11LD01Status Active:true Running:false Terminated:false
2024-10-01 13:31:07.023 [INFO ] [automation.script.ui.TestNachstellen] - Rule start: Item triggered: KnxDevice171_E10LD01Status Timer: PrivateTimerKnxDevice171_E10LD01Status Active:false Running:false Terminated:true
2024-10-01 13:31:07.024 [INFO ] [automation.script.ui.TestNachstellen] - Rule ended: Item triggered: KnxDevice171_E10LD01Status Timer: PrivateTimerKnxDevice171_E10LD01Status Active:true Running:false Terminated:false
2024-10-01 13:31:07.043 [INFO ] [automation.script.ui.TestNachstellen] - Rule start: Item triggered: KnxDevice171_E08LD01Status Timer: PrivateTimerKnxDevice171_E08LD01Status Active:false Running:false Terminated:true
2024-10-01 13:31:07.044 [INFO ] [automation.script.ui.TestNachstellen] - Rule ended: Item triggered: KnxDevice171_E08LD01Status Timer: PrivateTimerKnxDevice171_E08LD01Status Active:true Running:false Terminated:false
2024-10-01 13:31:07.084 [INFO ] [automation.script.ui.TestNachstellen] - Rule start: Item triggered: KnxDevice171_E04LD01Status Timer: PrivateTimerKnxDevice171_E04LD01Status Active:false Running:false Terminated:true
2024-10-01 13:31:07.085 [INFO ] [automation.script.ui.TestNachstellen] - Rule ended: Item triggered: KnxDevice171_E04LD01Status Timer: PrivateTimerKnxDevice171_E04LD01Status Active:true Running:false Terminated:false
2024-10-01 13:31:11.982 [INFO ] [automation.script.ui.TestNachstellen] - Item timer done: KnxDevice171_E07LD01Status
2024-10-01 13:31:11.982 [INFO ] [automation.script.ui.TestNachstellen] - Zwang item name: KnxDevice171E07LD01Zwang
2024-10-01 13:31:12.002 [INFO ] [automation.script.ui.TestNachstellen] - Item timer done: KnxDevice171_E11LD01Status
2024-10-01 13:31:12.002 [INFO ] [automation.script.ui.TestNachstellen] - Zwang item name: KnxDevice171E11LD01Zwang
2024-10-01 13:31:12.023 [INFO ] [automation.script.ui.TestNachstellen] - Item timer done: KnxDevice171_E10LD01Status
2024-10-01 13:31:12.023 [INFO ] [automation.script.ui.TestNachstellen] - Zwang item name: KnxDevice171E10LD01Zwang
2024-10-01 13:31:12.043 [INFO ] [automation.script.ui.TestNachstellen] - Item timer done: KnxDevice171_E08LD01Status
2024-10-01 13:31:12.043 [INFO ] [automation.script.ui.TestNachstellen] - Zwang item name: KnxDevice171E08LD01Zwang
2024-10-01 13:31:12.084 [INFO ] [automation.script.ui.TestNachstellen] - Item timer done: KnxDevice171_E04LD01Status
2024-10-01 13:31:12.084 [INFO ] [automation.script.ui.TestNachstellen] - Zwang item name: KnxDevice171E04LD01Zwang

As I’m posting this I’ve noticed that my debug variable seems to be undefined in the timer context, but I don’t think that’s the issue I’m searching for as it works most of the time… To be sure I removed the debug variables and now I’m waiting again…

5

As expected it didn’t help to remove the debug variables…

grafik
grafik1360×1677 338 KB

2024-10-01 18:09:47.376 [INFO ] [automation.script.ui.TestNachstellen] - Rule start: Item triggered: KnxDevice171_E04SD01Status Timer: PrivateTimerKnxDevice171_E04SD01Status Active:false Running:false Terminated:true
2024-10-01 18:09:47.377 [INFO ] [automation.script.ui.TestNachstellen] - Rule ended: Item triggered: KnxDevice171_E04SD01Status Timer: PrivateTimerKnxDevice171_E04SD01Status Active:true Running:false Terminated:false

2024-10-01 18:09:48.444 [INFO ] [automation.script.ui.TestNachstellen] - Rule start: Item triggered: KnxDevice171_E06LD01Status Timer: PrivateTimerKnxDevice171_E06LD01Status Active:false Running:false Terminated:true
2024-10-01 18:09:48.445 [INFO ] [automation.script.ui.TestNachstellen] - Rule ended: Item triggered: KnxDevice171_E06LD01Status Timer: PrivateTimerKnxDevice171_E06LD01Status Active:true Running:false Terminated:false
2024-10-01 18:09:52.374 [INFO ] [automation.script.ui.TestNachstellen] - Rule start: Item triggered: KnxDevice171_E09SD01Status Timer: PrivateTimerKnxDevice171_E09SD01Status Active:false Running:false Terminated:true
2024-10-01 18:09:52.375 [INFO ] [automation.script.ui.TestNachstellen] - Rule ended: Item triggered: KnxDevice171_E09SD01Status Timer: PrivateTimerKnxDevice171_E09SD01Status Active:true Running:false Terminated:false


2024-10-01 18:09:52.375 [WARN ] [ore.internal.scheduler.SchedulerImpl] - Scheduled job 'PrivateTimerKnxDevice171_E04SD01Status' failed and stopped
java.lang.IllegalStateException: Multi threaded access requested by thread Thread[OH-scheduler-1,5,main] but is not allowed for language(s) js.
	at com.oracle.truffle.polyglot.PolyglotEngineException.illegalState(PolyglotEngineException.java:129) ~[?:?]
	at com.oracle.truffle.polyglot.PolyglotContextImpl.throwDeniedThreadAccess(PolyglotContextImpl.java:1034) ~[?:?]
	at com.oracle.truffle.polyglot.PolyglotContextImpl.checkAllThreadAccesses(PolyglotContextImpl.java:893) ~[?:?]
	at com.oracle.truffle.polyglot.PolyglotContextImpl.enterThreadChanged(PolyglotContextImpl.java:723) ~[?:?]
	at com.oracle.truffle.polyglot.PolyglotEngineImpl.enterCached(PolyglotEngineImpl.java:1991) ~[?:?]
	at com.oracle.truffle.polyglot.HostToGuestRootNode.execute(HostToGuestRootNode.java:110) ~[?:?]
	at com.oracle.truffle.api.impl.DefaultCallTarget.callDirectOrIndirect(DefaultCallTarget.java:85) ~[?:?]
	at com.oracle.truffle.api.impl.DefaultCallTarget.call(DefaultCallTarget.java:102) ~[?:?]
	at com.oracle.truffle.polyglot.PolyglotFunctionProxyHandler.invoke(PolyglotFunctionProxyHandler.java:154) ~[?:?]
	at jdk.proxy1.$Proxy1002.run(Unknown Source) ~[?:?]
	at org.openhab.automation.jsscripting.internal.threading.ThreadsafeTimers.lambda$0(ThreadsafeTimers.java:85) ~[?:?]
	at org.openhab.core.internal.scheduler.SchedulerImpl.lambda$12(SchedulerImpl.java:189) ~[?:?]
	at org.openhab.core.internal.scheduler.SchedulerImpl.lambda$1(SchedulerImpl.java:88) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) [?:?]
	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:1136) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
	at java.lang.Thread.run(Thread.java:840) [?:?]
Caused by: com.oracle.truffle.api.TruffleStackTrace$LazyStackTrace

2024-10-01 18:09:53.443 [INFO ] [automation.script.ui.TestNachstellen] - Item timer done: KnxDevice171_E06LD01Status
2024-10-01 18:09:53.443 [INFO ] [automation.script.ui.TestNachstellen] - Zwang item name: KnxDevice171E06LD01Zwang
2024-10-01 18:09:57.373 [INFO ] [automation.script.ui.TestNachstellen] - Item timer done: KnxDevice171_E09SD01Status
2024-10-01 18:09:57.373 [INFO ] [automation.script.ui.TestNachstellen] - Zwang item name: KnxDevice171E09SD01Zwang
6

There is a limitation in embedded GraalVM JS upon which JS Scripting runs, and since Blockly compiles to JS Scripting, this impacts Blockly too. In short, only one thread can access a “context” at a time. When a second thread attempts to access the context while it’s already being accessed by another thread that Multi-threaded excepotion is thrown.

I think even before OH 4.0 release changes were made in openhab-js and the JS Scripting add-on to put a lock around the context so if the context is in use by a rule or by a timer, what ever wants access now has to wait for that lock to be released.

However, even since then I’ve noticed some cases where this lock either doesn’t work as expected or there is something else that happens that needs the context while a rule or timer is running because I still rarely see this exception.

Usually this exception will happen when you have a single rule that gets triggered a lot really fast which create Timers, which is exactly the situation here.

First file an issue so this doesn’t get forgotten. This code may be concise enough to reproduce the error more easily than the rule I have that is generating the exception.

In the mean time, some ideas which should work, though they will require some small deviations from this code. All of these entail keeping a list of those Items to be toggled and using a single timer/rule to toggle them on and off instead of giving them all their own timers.

  • Use the same timer and simply add/remove the Items to toggle every five seconds to that one timer.
  • Instead of a timer, use a separate rule which runse every five seconds to toggle the Items. You can use the shared cache to control the list of Items which should be toggled.
  • Use Looping Timer from openHAB Rules Tools [4.1.0.0;4.9.9.9] to toggle the lights

It’s more book keeping but becuase you don’t have lots of Timers trying to run at the same time it should be very unlikely to have two threads trying to access the context at the same time.

7

Thank you Rich, created the issue here:

I’m sorry, but I don’t get your workaround solutions yet. Could you please push me a bit further in the right direction?

I try to express what I’m trying to achieve:
I control my lighting in 4 control states, which are switched in a repeating sequence by the push of a touch button:
→ Manual OFF → automatic on → Manual ON → automatic off →
<-----------------------------------------------------------------------------------------
The icon on my touch button changes with every control state.
If an automatic mode is selected the corresponding light is switched by a presence detector. The presence detector changes the actuator’s status (of the light) and my icon and control state is updated by openhab after 5s. (switches between automatic on and automatic off)
I need the 5s delay, because when I change the control state with my touch button I don’t want openhab to interrupt my sequence.
That’s why I need a 5s delay for every single actuator status change. I need the time to select the control state that I like to have.

If I understand your solution, you try to start a 5s timer and tell this timer to switch item1, after 3s I recognize that item2 needs a delay and I add it to the list. But then item1 gets the full 5s but item2 gets only 2s delay when the timer has terminated… Have I missed something?

8

@florian-h05 and I are currently looking into it.

As this goes deeply into the lock-mechanism, we would at least needs someone/you to try it out if the fix does work.

Are you able to easily and consistently reproduce the issue?

Would you be able to install a special version via the openhab-cli console when we provide you with jar-file and the commands you need to run?

Which version are you running? Version used: openHab 4.2.0?

1 Like
9

@Gehetzter
You can try out the fix now:

Log into the openhab console (usually with sudo openhab-cli console), default password is habopen.

Get the bundle id:

bundle:list org.openhab.automation.jsscripting

Update the bundle:

bundle:update BUNDLE_ID https://github.com/florian-h05/openhab-addons/releases/download/jsscripting-4.2.3-01/org.openhab.automation.jsscripting-4.2.3-SNAPSHOT.jar
2 Likes
10

Thank you, that was quick

I’m sorry, but I can’t reproduce. It happens sometimes 10x a day and sometimes only once a day.
I’ve never tested what happens when I start creating more KNX state changes on purpose. Could try this first and then update with your fix and then compare.

I’m running 4.2.0 currently, but could first update to 4.2.2 if you wish.

11

Hello @stefan.hoehn and @florian-h05,
I would like to turn to you again and share my latest observations.

I have created a new 4.2.2 openhabian installation on my proxmox server and only installed the KNX items and the one blockly script. On my productive server, I customized the script so that it no longer sends actions, but the timers are still started. I tried to create the problem faster by switching all KNX items, but that didn’t work. After some time, however, I was able to see the error.

I then installed your update in my new installation and observed it again. Since then, however, the problem has reappeared.

Interestingly, the problem occurs on the new and the old openhab instance at the same time. I would have expected it to be random, but I guess it’s not…

Best regards, Jan

12

Hello @Gehetzter,

some additional testing lead to the observation that UI-based scripts have a multi-threading issue while file-based ones don’t have - even though in both places, the same locking mechanism is in place.

I have been able to reproduce the issue very reliably with the following script:

console.log('Sleeping...')
setTimeout(() => {
  console.log('Timer ran.')
}, 1000)
setTimeout(() => {
  console.log('Timer ran.')
}, 2000)
setTimeout(() => {
  console.log('Timer ran.')
}, 3000)
java.lang.Thread.sleep(10000)

Unfortunately, @stefan.hoehn and I do not really understand what is the actual cause of the problem, I would suspect some type of timing issue in the milli-seconds range.
BUT fortunately I have been able to fix/work-around the issue!

We have to discuss my solution among the devs and maintainers, I will report back once we are finished.

Best regards,
Florian

2 Likes