EcmaScript fails unpredictably and silently

  • Platform information:
    • Hardware: _ Ryzen 5 5600X / 16GB DDR4 / 1TB SSD_
    • OS: Host: Debian 11 - Docker Image openhab:3.3.0-snapshot-alpine
    • Java Runtime Environment: Docker Image openhab:3.3.0-snapshot-alpine
    • openHAB version: 3.3.0-snapshot-alpine
  • Issue of the topic: it is difficult to write a script that works reliably for me.

I try to change the state (color) of a zigbee rgb-lamp via ConBee binding over time controlled by a script. I have JSScript installed and use ECMAScript (ECMAScript 262 Edition 11).

So I have the related color item
var light = items.getItem("BadlichtSpiegelMLI_Farbe");

Sending a command like this appears to be working most of the time:
light.sendCommand("25,50,50")

I tried to turn the light off with light.sendCommand("0,0,0") or light.sendCommand("1,1,0") from within a function that is called with setTimeout and a delay.
This succeeded several times, but at some point it just stopped working.
Debugging it with print statements, judging from log output, sendCommand call is the point where the script simply stops execution. Wrapping in try
catch does nothing, catch and finally blocks that do nothing but print statements are apparently not even executed. No line after and including the sendCommand line in the function is executed anymore (print statements do not get logged anmore).

This didn’t just happen with sendCommand but also other things, for example I tried to do something with jodatime-js, and apparently as soon as I try to reference constants like ChronoField the script just fails without error output. Generally it seems that as soon as a line where there is a problem is about to be executed, the execution is just terminated silently, no stacktrace, no hint for me to know even where the failure might have happened.

It is really hard to tell if the source of a problem is with my script (and what/where), or the connection or the device.
Is there any way to get some useful debugging output for scripts when they fail?
is Debug mide (./start_debug.sh) for actual development on OpenHab itsself, or should I also use that to debug scripts?

Firstly, you can turn off a Color Item and a Dimmer Item with sendCommand('OFF'). That’s not relevant to your problem but wanted to mention it as being an option.

I can’t find where setTimeout and cancelTimeout are implemented. It appears they are implemented in the add-on and not the helper library.

You might get more information if you put the JS Scripting add-on into debug or trace level logging. I’ve never had a rule not report errors to the log when they fail so I couldn’t imagine how this is happening here.

Also, put the RuleStatusInfoEvent into INFO level logging and you’ll see log entries added to events.log when a rule starts and stops running. It’s possible, especially when working with Timers, that something is getting blocked and there hasn’t been an error but a resource conflict where everything is waiting for a lock or something to be released that never will happen. Note that each rule gets its own thread, but it only gets the one thread. So even the timers created in that one rule need access to the one thread to run. If that thread gets blocked, nothing will run. Though that doesn’t sound like what is happening here.

1 Like

Thanks.
How do I put the JS Scripting add-on into debug mode? Settings give me only the options

  • Use Built-in Variables
  • Do Not Use Built-in Variables

How do I change the log level of Events such as the RuleStatusInfoEvent?
I suppose I should use the Console for that (haden’t used it before so far)?
Something like this?

log:set INFO RuleStatusInfoEvent

(I don’t get any feedback when I enter that command)

with log:tail I see for example this output:

18:59:39.249 [INFO ] [openhab.event.ItemCommandEvent ] - Item ‘BadlichtSpiegelMLI_Farbe’ received command 25,50,100
18:59:39.249 [INFO ] [openhab.event.ItemStatePredictedEvent] - Item ‘BadlichtSpiegelMLI_Farbe’ predicted to become 25,50,100
18:59:59.250 [INFO ] [openhab.event.ItemCommandEvent ] - Item ‘BadlichtSpiegelMLI_Farbe’ received command 1,1,0
18:59:59.251 [INFO ] [openhab.event.ItemStatePredictedEvent] - Item ‘BadlichtSpiegelMLI_Farbe’ predicted to become 1,1,0
18:59:59.251 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item ‘BadlichtSpiegelMLI_Farbe’ changed from 25,50,100 to 1,1,0

But the physical light does not actually change the color to “1,1,0” (i.e. off) at the moment.

The logging namespace will be org.openhab.automation.jsscripting.

Yes but you need the full namespace: openhab.event.RuleStatusInfoEvent, or edit the log4j2.xml file itself where there is already a line for it. Just change the "ERROR" to "INFO".

log:set INFO openhab.event.RuleStatusInfoEvent
1 Like