Implemented start level service #1914

kaikreuzer · 2020-12-11T23:47:34Z

This finally implements eclipse-archived/smarthome#1896, fixes a couple of issues that currently exist due to the unpredictable startup sequence and it should also improve the startup performance, since activities do not have to be done multiple times in order to deal with lazy loaded stuff.

This service combines different ReadyMarkers into a new start level ready marker and thus lets other services depend on those, without having to know about the single markers.
This brings an important decoupling, since the set of markers for a certain start level might depend on the individual set up-
The start level service is therefore configurable (see here, so that users have a chance to adapt the conditions upon a certain start level is reached.

Start levels are defined as values between 0 and 100. They carry the following semantics:

00 - OSGi framework has been started.
10 - OSGi application start level has been reached, i.e. bundles are activated.
20 - Model entities (items, things, links, persist config) have been loaded, both from db as well as files.
30 - Item states have been restored from persistence service, where applicable.
40 - Rules are loaded and parsed, both from db as well as dsl and script files.
50 - Rule engine has executed all "system started" rules and is active.
70 - User interface is up and running.
80 - All things have been initialized.
100 - Startup is fully complete.

Note: Levels 70 and 80 are not yet implemented in this PR, but should be added at a later stage.

While still being in a level <50, no events will be logged out anymore, which reduces the logs wrt "item added" and "link added" events tremendously.

I have also further improvements in mind like automatically registering what bundles are installed and for which markers needs to be waited, so that there is less necessity to adapt the configuration, if anybody does not use a "standard" setup of openHAB. Note that for anybody using the normal distro and not removing any essential parts of it, there should be no need to configure anything with the current implementation.

Fixes #1637
Fixes #1777
Fixes #1734
Fixes #1823
Fixes #1808

Might also fix #1365
Might also fix #1829

Signed-off-by: Kai Kreuzer [email protected]

Signed-off-by: Kai Kreuzer <[email protected]>

wborn

Thanks for your awesome work on this! I'm very happy to see this being addressed just in time for OH3. 😃
I only have a few comments and think we should then proceed with merging this so we can start testing it and it makes it into the RC.
Can you also have a look at the failing tests?

...enhab.core.automation/src/main/java/org/openhab/core/automation/internal/RuleEngineImpl.java

bundles/org.openhab.core/src/main/java/org/openhab/core/internal/items/ItemRegistryImpl.java

Signed-off-by: Kai Kreuzer <[email protected]>

kaikreuzer · 2020-12-12T12:57:13Z

Can you also have a look at the failing tests?

Yep, I'm on it.

lolodomo · 2020-12-12T13:17:49Z

Might become one of the major improvements of OH3 over OH2. I like.

kaikreuzer · 2020-12-12T13:32:21Z

@wborn Tests succeeded!

wborn

Thanks a lot! 👍 Let's merge it so we can start testing it.

kaikreuzer · 2020-12-12T13:36:51Z

Let's do testing (and fixing 🤔) until tomorrow evening...

ghys · 2020-12-12T13:37:26Z

@kaikreuzer could you confirm the "system started" rules still have to configured with start level 20? I just implemented some UI helper to abstract this when adding these sorts of triggers yesterday.

kaikreuzer · 2020-12-12T13:42:07Z

@ghys Anything below 50 will do.
I was also thinking about adding an additional "rule loaded" trigger, to bring back the 2.x functionality that a rule is executed once whenever being modified. This is not part of this PR, though, but might actually then be a common choice for users. I wouldn't put a "system started" trigger into the UI, I consider this rather deprecated. The "start level" trigger is more flexible and will allow users in future to also choose start level 80, e.g. if they want to wait for their things to be initialized.

ghys · 2020-12-12T13:47:13Z

Got it. So maybe offer these as options in a list? (or those above 50)

00 - OSGi framework has been started.
10 - OSGi application start level has been reached, i.e. bundles are activated.
20 - Model entities (items, things, links, persist config) have been loaded, both from db as well as files.
30 - Item states have been restored from persistence service, where applicable.
40 - Rules are loaded and parsed, both from db as well as dsl and script files.
50 - Rule engine has executed all "system started" rules and is active.
70 - User interface is up and running.
80 - All things have been initialized.
100 - Startup is fully complete.

(this could also go to the configParameterDescription of the SystemStartlevelTrigger)

kaikreuzer · 2020-12-12T14:15:22Z

Options above 40 make sense, yes. And indeed, they should be provided as configParameterDescription, I didn't do this yet.

lolodomo · 2020-12-12T16:24:37Z

After first startup of snapshot 2066, I noticed in UI that no rules are loaded. I also noticed that I have no item state changes logged.

kaikreuzer · 2020-12-12T16:25:39Z

Same for me. On the second startup, everything went well, though.

lolodomo · 2020-12-12T16:29:20Z

Same for me. On the second startup, everything went well, though.

Yes, second startup looks good, item/thing logging is back, I see no rule errors in log, my "system started" rule is run and without error, all rules are listed in UI.

kaikreuzer · 2020-12-12T16:34:20Z

Sounds great - first sign that I didn't completely destroy the runtime ;-)

For me all further starts (2-4 by now) went smooth as well. I guess the first start is our usual problem that the system runs amok directly after doing an update.

lolodomo · 2020-12-12T16:55:23Z

After few other restarts, I finally got errors of this kind:

17:48:33.113 [ERROR] [.internal.handler.ScriptActionHandler] - Script execution of rule with UID 'maison3-10' failed: The name 'NULL' cannot be resolved to an item or type; line 240, column 23, length 4 in maison3
17:48:33.114 [ERROR] [.internal.handler.ScriptActionHandler] - Script execution of rule with UID 'maison3-7' failed: The name 'NULL' cannot be resolved to an item or type; line 173, column 23, length 4 in maison3

This is failing on lines of this kind:

if (previousState == NULL

while the rule trigger is "item xxxx changed".

lolodomo · 2020-12-12T17:03:20Z

Another example, this time with ON instead of NULL:

17:59:39.019 [ERROR] [.internal.handler.ScriptActionHandler] - Script execution of rule with UID 'maison3-3' failed: The name 'ON' cannot be resolved to an item or type; line 96, column 28, length 2 in maison3

Line 96 is:

	else if (previousState == ON && newState == OFF) {

It looks like errors are related to previousState .

lolodomo · 2020-12-12T17:05:09Z

Errors are certainly occuring at first startup of the rule, while previous state is NULL.

lolodomo · 2020-12-12T17:08:59Z

I even got this one:

18:00:02.577 [ERROR] [.internal.handler.ScriptActionHandler] - Script execution of rule with UID 'maison3-2' failed: The name 'previousState' cannot be resolved to an item or type; line 34, column 6, length 13 in maison3

One time again, it is related to previousState for a rule with a trigger "item xxx changed".

Regarding the run of the rule with "system started", I have always seen this rule run correctly. This case is now working perfectly.

kaikreuzer · 2020-12-12T21:04:39Z

@lolodomo Are those problems with the previousState only temporary during startup, i.e. does the same rule start to work a bit later? Or is it broken until you restart the system? Feel free to create a new bug report for it, ideally some more logs.

lolodomo · 2020-12-12T21:08:25Z

I will check again but I guess it is only temporary during startup.

kaikreuzer · 2020-12-12T21:12:04Z

This would clearly reduce the severity of the issue!

lolodomo · 2020-12-13T11:09:38Z

@kaikreuzer : as you provided several fixes since my tests yesterday, I will try again when a new snapshot is available and create an issue if I still see problems.

lolodomo · 2020-12-17T19:15:31Z

@kaikreuzer : just another positive feedback. With snapshot 2085, I was able to restart openHAB server 5 times without any errors triggered by rules. Super. No need for me to open another issue ;)

kaikreuzer · 2020-12-17T19:38:47Z

Excellent 🎉

maggu2810 · 2020-12-20T07:21:35Z

Hi @kaikreuzer, just a small question without digging deeper into the code changes myself:
Does this change add some dependencies between some modules?
Just an example that you also state above yourself (logging will enabled only at a certain time):
The EventLogger registers a tracker for the rules startlevel and logging will be enabled after that level has been reached.
If the rule engine is not part of the distribution anymore and this marker is not added to the ready service, the logging will not be activated at all. Correct? If that is correct I assume that the rule engine is a mandatory part of the distribution.
Are there other markers and trackers that have a strong dependency?

openhab-bot · 2020-12-24T10:32:44Z