OpenhabGraalJSScriptEngine does not start

Add-ons Other
1

Hey everyone,

I have a strange issue with my OH 4.3 Installation since two days ago. My JavaScripting Engine won’t start (or something like that…) but spam the logs continually. Here you find an extract of what happens after a reboot:

...
2025-05-22 20:49:26.074 [DEBUG] [al.scope.OSGiScriptExtensionProvider] - bundle org.openhab.automation.jsscripting:4.3.5 (285)[org.openhab.automation.jsscrip>
2025-05-22 20:49:26.074 [DEBUG] [al.scope.OSGiScriptExtensionProvider] - bundle org.openhab.automation.jsscripting:4.3.5 (285)[org.openhab.automation.jsscrip>
2025-05-22 20:49:26.074 [DEBUG] [al.scope.OSGiScriptExtensionProvider] - bundle org.openhab.automation.jsscripting:4.3.5 (285)[org.openhab.automation.jsscrip>
2025-05-22 20:49:26.074 [DEBUG] [al.scope.OSGiScriptExtensionProvider] - bundle org.openhab.automation.jsscripting:4.3.5 (285)[org.openhab.automation.jsscrip>
2025-05-22 20:49:26.075 [DEBUG] [al.scope.OSGiScriptExtensionProvider] - bundle org.openhab.automation.jsscripting:4.3.5 (285)[org.openhab.automation.jsscrip>
2025-05-22 20:49:26.075 [DEBUG] [al.scope.OSGiScriptExtensionProvider] - bundle org.openhab.automation.jsscripting:4.3.5 (285)[org.openhab.automation.jsscrip>
2025-05-22 20:49:26.075 [DEBUG] [al.scope.OSGiScriptExtensionProvider] - bundle org.openhab.automation.jsscripting:4.3.5 (285)[org.openhab.automation.jsscrip>
2025-05-22 20:49:27.938 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock acquired.
2025-05-22 20:49:27.938 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock acquired.
2025-05-22 20:49:27.939 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock acquired.
2025-05-22 20:49:27.939 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock acquired.
2025-05-22 20:49:27.974 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 20:49:27.974 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 20:49:27.977 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Initializing GraalJS script engine...
2025-05-22 20:49:27.978 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock acquired before invocation.
2025-05-22 20:49:27.977 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 20:49:27.980 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Initializing GraalJS script engine...
2025-05-22 20:49:27.980 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock acquired before invocation.
2025-05-22 20:49:27.980 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Initializing GraalJS script engine...
2025-05-22 20:49:27.977 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 20:49:27.981 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock acquired before invocation.
2025-05-22 20:49:27.981 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Initializing GraalJS script engine...
2025-05-22 20:49:27.981 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock acquired before invocation.
2025-05-22 20:49:28.012 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Injecting ThreadsafeTimers into the JS runtime...
2025-05-22 20:49:28.012 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Injecting ThreadsafeTimers into the JS runtime...
2025-05-22 20:49:28.013 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Evaluating cached global script...
2025-05-22 20:49:28.013 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Injecting ThreadsafeTimers into the JS runtime...
2025-05-22 20:49:28.013 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Evaluating cached global script...
2025-05-22 20:49:28.014 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Injecting ThreadsafeTimers into the JS runtime...
2025-05-22 20:49:28.016 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Evaluating cached global script...
2025-05-22 20:49:28.016 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Evaluating cached global script...
2025-05-22 20:49:28.261 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Evaluating cached openhab-js injection...
2025-05-22 20:49:28.262 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Evaluating cached openhab-js injection...
2025-05-22 20:49:28.263 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Evaluating cached openhab-js injection...
2025-05-22 20:49:28.266 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Evaluating cached openhab-js injection...
2025-05-22 20:49:30.014 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Successfully initialized GraalJS script engine.
2025-05-22 20:49:30.015 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Successfully initialized GraalJS script engine.
2025-05-22 20:49:30.019 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Successfully initialized GraalJS script engine.
2025-05-22 20:49:30.019 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Successfully initialized GraalJS script engine.
2025-05-22 20:49:30.021 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released after invocation.
2025-05-22 20:49:30.023 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released after invocation.
2025-05-22 20:49:30.023 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler tried updating the thing status although the handler>
2025-05-22 20:49:30.024 [WARN ] [.core.thing.binding.BaseThingHandler] - Handler GenericMQTTThingHandler of thing mqtt:topic:67ea6c01b9:a656b0723a tried upda>
2025-05-22 20:49:30.057 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock acquired.
2025-05-22 20:49:30.071 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 20:49:30.071 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Initializing GraalJS script engine...
2025-05-22 20:49:30.071 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock acquired before invocation.
2025-05-22 20:49:30.072 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Injecting ThreadsafeTimers into the JS runtime...
2025-05-22 20:49:30.072 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Evaluating cached global script...
2025-05-22 20:49:30.072 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Evaluating cached openhab-js injection...
2025-05-22 20:49:30.074 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released after invocation.
2025-05-22 20:49:30.089 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 20:49:30.091 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock acquired.
2025-05-22 20:49:30.092 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 20:49:30.094 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Initializing GraalJS script engine...
2025-05-22 20:49:30.094 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock acquired before invocation.
2025-05-22 20:49:30.097 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released after invocation.
2025-05-22 20:49:30.098 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 20:49:30.099 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released after invocation.
2025-05-22 20:49:30.104 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 20:49:30.109 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock acquired.
2025-05-22 20:49:30.110 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 20:49:30.111 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock acquired.
2025-05-22 20:49:30.111 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Initializing GraalJS script engine...
2025-05-22 20:49:30.111 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock acquired before invocation.
2025-05-22 20:49:30.113 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 20:49:30.117 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Initializing GraalJS script engine...
2025-05-22 20:49:30.117 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock acquired before invocation.
2025-05-22 20:49:30.118 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Injecting ThreadsafeTimers into the JS runtime...
2025-05-22 20:49:30.118 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Evaluating cached global script...
2025-05-22 20:49:30.119 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Evaluating cached openhab-js injection...
2025-05-22 20:49:30.127 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released after invocation.
2025-05-22 20:49:30.128 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
...

And it goes on an on like this forever… Rules seem to work at least partially though… But not all of them do (I suspect rules with timers don’t work?!). Thats how I noticed that theres something wrong…

Any ideas?

2

Just restored a backup from a couple of days back but it looks similar there. However there are only Lock released events:

5-22 21:08:23.514 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:23.675 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:23.677 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:23.856 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:23.859 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:25.178 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:25.179 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:25.362 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:25.363 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:26.686 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:26.688 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:28.189 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:28.192 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:28.384 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:28.386 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:29.706 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:29.707 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:29.896 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:29.898 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:30.701 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:30.725 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:31.213 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:31.214 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:31.403 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:31.404 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:31.503 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:31.504 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:31.505 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:32.719 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:32.720 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:32.910 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:32.912 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.
2025-05-22 21:08:33.413 [DEBUG] [.internal.OpenhabGraalJSScriptEngine] - Lock released.

Is this normal? Does my problem with the rules that aren’t running maybe not even related?

3

Well I guess it seems to be back to the normal behavior now. So I guess that these log statements just pop up after every rule execution

4

I don’t know if these are normal or not. I’ve never really followed the debug level logs for JS Scripting. They are warn level logs so what ever is here isn’t an error as far as the add-on is concerned.

5

Yeah that is true as long as it’s just debug information I shouldn’t be worried too much. However before I restore my backup I also had a lot of these logs which seemed strange to me.

When I read it now it does not seem to be something I should care about at all. It seems to make sense to acquire a lock before executing something :sweat_smile:

I also never looked at these debug logs before. I was just adjusting the levels while I was trying to find out why some of my rules where no longer executed. It seemed that timer events where no longer executed but in the end a restore was just easier than to investigate further. I could see from my persistence when the problems were starting. Still I don’t know what I could have done at that point in time that broke something :man_shrugging:

6

Each time a script is executed, a lock ist aquired before and released after. This happens to synchronize some context initialisations and is normal.

And the reason why you see “Initializing GraalJS script engine” multible times is that multible instances of a graal script engine are created.

  • Tranformation script are using their own instances
  • Rules using their own
  • Collecting all available script engines depends on a temporary instance
  • …
2 Likes
7

Acquiring and releasing locks is a normal thing to do in a multithreaded program, what is not normal is to log it. I’m guessing that there have been some problems with locking, which has led to somebody creating log statements for it, but that’s normally something you do only while troubleshooting an issue. Maybe somebody have forgot to remove them, maybe the problem isn’t solved yet. Regardless, I would definitely log something like this as TRACE, not DEBUG.

So, the lock logging isn’t interesting to you at all. The number of acquire and release statements should match over time, so that all locks are released, but if they don’t, you can’t really do anything about it :wink:

8

DEBUG is already a log level you have to manually enable for debugging purposes. In a default environment you will not see this kind of log level.

9

Absolutely, but if you have a problem, one of the first things I would do is to enable debug logging. With all the acquire/release entries, it might be hard to see what else is going on. I always reserve “spammy logging” for TRACE for this reason.

1 Like