ScriptEngineManagerImpl invoked too early in the startup process

[rkoshak]

Expected Behavior

OH starts without spamming the logs with errors.

Current Behavior

Long before OH reaches start level 40 and apparently before the automation add-ons are loaded and activated ScriptEngineManagerImpl spams the logs with the following error:

2025-08-20 09:04:51.218 [INFO ] [org.openhab.core.Activator          ] - Starting openHAB 5.0.1 (Release Build)
2025-08-20 09:04:52.239 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'America/Denver'.
2025-08-20 09:04:52.246 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to '39.051660101889716,-104.81540679931642'.
2025-08-20 09:04:52.249 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'en_US'.
2025-08-20 09:04:52.250 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Measurement system set to 'US'.
2025-08-20 09:04:55.307 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://argus:8080/rest/events's Observer 
2025-08-20 09:04:55.310 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://argus:8080/rest/events's Observer 
2025-08-20 09:04:55.313 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://argus:8080/rest/events/states's Observer 
2025-08-20 09:04:56.369 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://argus:8080/rest/events's Observer 
2025-08-20 09:04:56.369 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://argus:8080/rest/events's Observer 
2025-08-20 09:04:56.369 [WARN ] [.transport.servlet.ServletController] - Can't find the request for http://argus:8080/rest/events/states's Observer 
2025-08-20 09:05:06.992 [INFO ] [.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2025-08-20 09:05:07.682 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - ScriptEngine for language 'application/javascript' could not be found for identifier: 3ab8b6e3-648e-42b1-9559-68d7e11bcbca
2025-08-20 09:05:07.691 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - ScriptEngine for language 'application/javascript' could not be found for identifier: f34e46ca-afd0-4a62-a42c-5ce76d1f8c8b
2025-08-20 09:05:07.694 [ERROR] [ipt.internal.ScriptEngineManagerImpl] - ScriptEngine for language 'application/javascript' could not be found for identifier: 031deca4-65a1-4a13-ad62-ad99d330eed5
...

In this startup, start level 40 was reached at 9:05:42.

It appears that there is one log entry for each Script Action and Script Condition defined in the JSONDB.

Once start level 40 is reached, startup happens normally and all rules are functional and operating as expected.

Possible Solution

Assess why ScriptEngineManagerImpl is being invoked before the automation add-ons are available and, if possible, log out an identifier that is meaningful to the end user (something including the rule ID perhaps). If this error ever occurs legitimately the user won't have an easy way to identify which rule is the problem.

Steps to Reproduce (for Bugs)

1. Install and run OH 5.0.1 or later
2. Have at least one managed rule defined with a script action or script condition that depends on an automation add-on (e.g. JS Scripting)
3. Restart OH once you are sure that all bundles are installed and active after the cache was cleared.
4. Observe the logs immediately after the LSP starts.

Context

It's freaking out a bunch of users but ultimately does not have an impact on the operation of OH. All rules appear to run as expected once OH reaches the appropriate start levels.

See the release discussion thread and https://community.openhab.org/t/oh-5-0-0-to-oh5-1-0-snaphot-error-scriptengine-for-language-application-javascript-could-not-be-found-for-identifier/165496/27

Your Environment

• Version used: 5.0.1
• Environment name and version (e.g. Chrome 111, Java 17, Node.js 18.15, ...): Official Docker Debian image
• Operating System and version (desktop or mobile, Windows 11, Raspbian Bullseye, ...):Ubuntu 24.04

[openhab-bot]

This issue has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/oh-5-0-0-to-oh5-1-0-snaphot-error-scriptengine-for-language-application-javascript-could-not-be-found-for-identifier/165496/27

[openhab-bot]

This issue has been mentioned on openHAB Community. There might be relevant details there:

https://community.openhab.org/t/openhab-5-0-release-discussion/165032/264

[Nadahar]

I have very little to add, but I'll add the little I have: The identifier listed in the error message is called engineIdentifier internally, and has the following "definition":

engineIdentifier the unique identifier for the ScriptEngine (script file path or UUID)

So, at the very least, this seems to confirm that this comes from managed something, as otherwise it would be a file path. And, all three log entries in the above log have different identifiers/sources.

[Nadahar]

A quick debug session points to the precompilation of scripts as the potential cause of this. Scripts are precompiled early to run quicker when they first run, and arguably this is done too early.

[Nadahar]

Some preliminary investigation indicates that these premature compilation attempts are kicked off by this:

openhab-core/bundles/org.openhab.core.automation/src/main/java/org/openhab/core/automation/internal/RuleEngineImpl.java

Lines 978 to 993 in c4360f3

	* Creates and schedules a re-initialization task for the {@link Rule} with the specified UID.
	*
	* @param rUID the UID of the {@link Rule}.
	*/
	protected void scheduleRuleInitialization(final String rUID) {
	Future<?> f = scheduleTasks.get(rUID);
	if (f == null || f.isDone()) {
	scheduleTasks.put(rUID, getScheduledExecutor().schedule(() -> {
	final WrappedRule managedRule = getManagedRule(rUID);
	if (managedRule == null) {
	return;
	}
	setRule(managedRule);
	}, RULE_INIT_DELAY, TimeUnit.MILLISECONDS));
	}
	}

I don't have the overview over the order or all this, but it seems that it should check some readymarker before kicking off..?

[Nadahar]

Some more investigation shows that scheduleRuleInitialization() is called from addModuleHandlerFactory(), which is called by OSGi (if I understand it correctly) on startlevel 10, when an instance of CoreModuleHandlerFactory is registered. So, pretty early.

addModuleHandlerFactory() enumerates all "known" rules at that point in time, and schedules initialization of the rules that haven't been initialized, which is presumably all "known" rules. I don't think that it's limited to managed rules, however, the "initialization task" in scheduleRuleInitialization() filters out only managed rules, and then calls setRule() on each managed rule.

As the name (scheduleRuleInitialization()) implies, it doesn't invoke the rule initialization directly, instead it's submitted to run in the ruleengine (single) thread pool, which a delay of 500 milliseconds. Since the "pool" is one thread, the tasks will be executed one at a time, in no particular order. Startlevel 10 + 500 milliseconds is still pretty early.

Once the task is executed, setRule() calls activateRule() which again invokes compileRule().

I'm not exactly where the "flaw" is here, I assume that this rule initialization isn't only used during startup, but when rules are created or enabled when the system is up and running as well. Under those circumstances, the compilation is probably desirable, but not before the add-ons are loaded.

There is another mechanism here, there's a compileRules() method that is invoked from onReadyMarkerAdded(). It seems to be called at startlevel 40. compileRules() compiles all enabled rules at that time.

I don't know if startlevel 40 isn't still too early for the add-ons to be up and running and scripting engines registered, but I assume that others know more about this I assume.

In any case, there seems to be two mechanism to compile rules during startup, and one launches very early. It also seems like a waste to compile the rules twice during startup.

Maybe one could do something like not compiling rules in activateRule() if the startlevel is below some limit. But, better yet, what if the rule in question wasn't attempted initialized until the scripting language is uses was registered? It might be more difficult to achieve, but it would certainly work smoother.

@florian-h05 I guess you're the one with the most insight into this logic..?

[rkoshak]

which is presumably all "known" rules. don't think that it's limited to managed rules,

At this point it will only know about the managed rules. The add-ons will need to be loaded for the .js, .rb, et al files to be loaded and those rules known about. These files get loaded by the add-ons and executed to create the rules and that can't happen until the add-on is up and running.

If the add-on were up and running at this point, we wouldn't see the errors.

I'm not sure how .rules files are handled though since Rules DSL is part of core it might be available earlier so some of those file based rules might be there.

I don't know if startlevel 40 isn't still too early for the add-ons to be up and running and scripting engines registered, but I assume that others know more about this I assume.

After a clearing of the cache this is often too early. However in normal circumstances 40 is fine. I think this is one of the main reasons why the standard procedure is to upgrade or clear the cache, wait for things to settle, then restart OH. It's the main reason I do this anyway.

40 means the rule engine has started and rules will start being triggered whether all the automation add-ons are up and running or not. We see a similar error (if not exactly the same error) in this case.

There are other similar problems that can occur. For example, restoreOnStartup might happen late if the persistence add-ons are not yet available at runlevel 30 (I think that's the right runlevel). Things coming online can be delayed. etc. I'm not sure why OH doesn't block advancing through the start levels until all the configured bundles are loaded and available but I can guess at some problems.

what if the rule in question wasn't attempted initialized until the scripting language is uses was registered?

If I understand what you mean, this becomes challenging because you cannot guarantee that the specific automation add will ever be loaded. The user may have accidentally or deliberately removed the add-on. That's why I hint at maybe not advancing past start level 10 until all the configured add-ons and bundles are loaded. That probably won't solve this specific error message since it happens at 10, but it can keep OH from forging ahead without bundles being ready. But that's probably something to address in another issue instead of here.

[Nadahar]

These files get loaded by the add-ons and executed to create the rules and that can't happen until the add-on is up and running.

I know that add-on provided rules won't be available, but if #4633 is ever merged, file-based rules might be available early. However, it won't matter with the current logic, as it explicitly filters out managed rules only.

It's the main reason I do this anyway.

My question is if it would hurt to do it later. But, for rules that trigger on startlevel 40, there's probably no time to waste. They will fail to run if things aren't ready in time though.

If I understand what you mean, this becomes challenging because you cannot guarantee that the specific automation add will ever be loaded.

By preventing that it's run at startlevel 10 + 500 ms, you won't prevent the error from ever appearing, but you would prevent it from always appearing.

A better, but probably much more complicated approach, would be to make the rule initialization wait until whatever scripting language(s) it relies on is/are ready. But, this is all pretty complicated, and messing with it can easily cause other issues, so a careful study of the whole mechanism would be needed to attempt such a thing.

My idea was that by preventing the "startlevel 10" run, you would at least limit this error to situations where the add-ons aren't ready "when they usually are", instead of logging it every single startup. I'd said that if the user has removed the add-on, the error log is actually warranted/desirable. The user should be made aware that the rule won't work in that situation. It's the situation where everything is really OK, but because of OH's startup sequence, it doesn't always appear so, that is problematic/undesirable as I see it.

[rkoshak]

A better, but probably much more complicated approach, would be to make the rule initialization wait until whatever scripting language(s) it relies on is/are ready.

But that's my point. There's no guarantee it will ever be ready. The add-on might not be configured to be installed. We can't block all rules because one depends on an add-on that isn't available.

It's the situation where everything is really OK, but because of OH's startup sequence, it doesn't always appear so, that is problematic/undesirable as I see it.

Agreed. I can't offer anything as to whether not compiling the scripts so early would be a problem or not. But either it didn't use to do this or it didn't used to log the errors. Something changed in 5.0.1 to cause these error logs to appear.

[Nadahar]

But that's my point. There's no guarantee it will ever be ready. The add-on might not be configured to be installed. We can't block all rules because one depends on an add-on that isn't available.

It would have to a have a timeout which would somehow guesstimate when OH was up and running and all missing stuff would have been installed and initialized. It couldn't just wait forever, and when the error finally came then, it would actually be "correct" in that this language isn't available.

The initialization is on an individual rule basis, so the delay would only apply for the rules where the language(s) weren't ready. Other rules would initialize "normally".

But, as I said, I consider this a quite complicated solution, I don't know how easy it would be to make that bug-free.

But either it didn't use to do this or it didn't used to log the errors. Something changed in 5.0.1 to cause these error logs to appear.

The precompilation was added in 4.3.0, and then further tweaked for 5.0 I believe. This was done to improve performance when the rules do run.

What I don't know is what happens to a rule if it's asked to run when it isn't precompiled. If that only means that the rule will then first be compiled and then run, this could be made much simpler. If that's the case, there's simply no "rush" to precompile them, so much happens during startup anyway that it's probably not the most efficient time to do so. The precompilation could be done in "peace and quiet" well after startlevel 100 has been reached. But, if the introduced changes mean that rules that aren't precompiled, fail to run, then everything must be done much more precisely.

[Nadahar]

Relevant changes:
2689f5f (#4922)
d83d35c (#4893)
e157448 (#4329)
f631f1b (#4319)
918b4fa (#4289)