Start level issues

Erik_Backlund · April 12, 2024, 3:14pm

Platform information:
- Hardware: Raspberry Pi 4 Model B Rev 1.5
- OS: Linux openhabian 6.1.21-v8+ #1642 SMP PREEMPT Mon Apr 3 17:24:16 BST 2023 aarch64 GNU/Linux
- Java Runtime Environment: openjdk 17.0.10 2024-01-16
- openHAB version: 4.1.2

During an effort to start over with a new OpenHAB installation I want to make sure all things are running smoothly from the very beginning. So, after installing a few bindings, I started tracking the OpenHAB system Start Level to make sure things (including Things) are initialized properly. A few things come to my attention:

The order is not monotonic, it seems like 80 comes before 60 and 70, and 100 (fully started) comes before 90. So, it seems like 100 is not the final Start Level.
Start levels appear in two sets, where the second set has the same order as the first but occurs a few seconds later. Interesting…
The documentation (Rules | openHAB) is not updated?!

Anyone who can shine som light on this?

See rules and log output below.

Rule to print start levels (note all levels 00, 10, 20, 30 merged into rule for start level 40), startlevel.rules:

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

where start level description is copied from Rules | openHAB.

Filtered (“start level”) output of openhab.log and events.log during OpenHAB startup:

2024-04-12 16:21:56.155 [INFO ] [rg.openhab.core.model.script.OpenHAB] - Start level reached 10: OSGi application start level has been reached, i.e. bundles are activated.
2024-04-12 16:21:56.156 [INFO ] [rg.openhab.core.model.script.OpenHAB] - Start level reached 20: Model entities (items, things, links, persist config) have been loaded, both from db as well as files.
2024-04-12 16:21:56.158 [INFO ] [rg.openhab.core.model.script.OpenHAB] - Start level reached 30: Item states have been restored from persistence service, where applicable.
2024-04-12 16:21:56.159 [INFO ] [rg.openhab.core.model.script.OpenHAB] - Start level reached 40: Rules are loaded and parsed, both from db as well as dsl and script files.
2024-04-12 16:21:56.164 [INFO ] [rg.openhab.core.model.script.OpenHAB] - Start level reached 50: Rule engine has executed all SYSTEM STARTED  rules and is active.
2024-04-12 16:21:56.227 [INFO ] [rg.openhab.core.model.script.OpenHAB] - Start level reached 80: All things have been initialized.
2024-04-12 16:21:56.228 [INFO ] [rg.openhab.core.model.script.OpenHAB] - Start level reached 60: TBD.
2024-04-12 16:21:56.230 [INFO ] [rg.openhab.core.model.script.OpenHAB] - Start level reached 70: User interface is up and running.
2024-04-12 16:21:56.236 [INFO ] [rg.openhab.core.model.script.OpenHAB] - Start level reached 100: Startup is fully complete.
2024-04-12 16:21:56.243 [INFO ] [rg.openhab.core.model.script.OpenHAB] - Start level reached 90: TBD.
2024-04-12 16:21:56.152 [INFO ] [rg.openhab.core.model.script.OpenHAB] - Start level reached 00: OSGi framework has been started.
2024-04-12 16:21:56.155 [INFO ] [rg.openhab.core.model.script.OpenHAB] - Start level reached 10: OSGi application start level has been reached, i.e. bundles are activated.
2024-04-12 16:21:56.156 [INFO ] [rg.openhab.core.model.script.OpenHAB] - Start level reached 20: Model entities (items, things, links, persist config) have been loaded, both from db as well as files.
2024-04-12 16:21:56.158 [INFO ] [rg.openhab.core.model.script.OpenHAB] - Start level reached 30: Item states have been restored from persistence service, where applicable.
2024-04-12 16:21:56.159 [INFO ] [rg.openhab.core.model.script.OpenHAB] - Start level reached 40: Rules are loaded and parsed, both from db as well as dsl and script files.
2024-04-12 16:21:56.164 [INFO ] [rg.openhab.core.model.script.OpenHAB] - Start level reached 50: Rule engine has executed all SYSTEM STARTED  rules and is active.
2024-04-12 16:21:56.227 [INFO ] [rg.openhab.core.model.script.OpenHAB] - Start level reached 80: All things have been initialized.
2024-04-12 16:21:56.228 [INFO ] [rg.openhab.core.model.script.OpenHAB] - Start level reached 60: TBD.
2024-04-12 16:21:56.230 [INFO ] [rg.openhab.core.model.script.OpenHAB] - Start level reached 70: User interface is up and running.
2024-04-12 16:21:56.236 [INFO ] [rg.openhab.core.model.script.OpenHAB] - Start level reached 100: Startup is fully complete.
2024-04-12 16:21:56.243 [INFO ] [rg.openhab.core.model.script.OpenHAB] - Start level reached 90: TBD.

rlkoshak · April 12, 2024, 3:40pm

How are you determining the order of the start levels?

There is an actual event published to the event bus for each start level. You can enable those to be logged to events.log by setting the following in log4j2.xml (or through the karaf console).

<Logger level="INFO" name="openhab.event.StartlevelEvent"/>

I’ve had this enabled for quite some time and I’ve never seen them occur out of order. This is really the only reliable way to determine when the start levels occur because if you are using rules or inferring the start level based on the logs there is too much lag and everything is happening in parallel which can cause stuff to appear out of order.

Especially, since you are trying to measure this with rules, it can take some time for the rule engine to come up and the .rules files to be parsed and the rule enabled. In short, your rules are probably not actually showing you what’s really going on. There is no guarantee that these separate rules will trigger and run in the order of the events that triggered them occurred. It would be a little more reliable to use just a single rule instead of separate rules as in that case the rule triggers will queue up and be worked off in the order they occurred. However you can’t trust the timing.

As for the second running of the rules, that could be caused if the .rules file is loaded again or .items file is loaded after the .rules file is loaded. Any time a rule is created, if the startlevel even has already occurred, even if it was days ago, the rule will immediately trigger. You don’t show the full logs in context so .

tl;dr: the way you are measuring the start levels with file based rules is never going to give you the information you are after.

Erik_Backlund · April 12, 2024, 4:29pm

I assumed, wrongly I guess, that the monotonic list of start levels in the documentation was reflecting the designed startup behavior. My initial guess was that the log printout from executed rules was reflecting the truth.

As for the second running of the rules, my rules-files are loaded only once and approximately 6-7 seconds after the items-files. So my initial guess is that it is separated enough in time to state that “items files are not loaded after rules files”. Well, all according to the log file timestamps of course. So, I still find it a bit odd that they fire twice.

I will definitely check into the log4j2.xml log settings. As I understand, that is the only sensible way of determining the start level.

Thanks for pointing me in a much better direction.

rlkoshak · April 12, 2024, 4:31pm

The loading of the .items files causes a reload of the .rules files. So I would not be surprised that these rules fire twice in that case since the .items happened long enough after the .rules to influence them.

Erik_Backlund · April 12, 2024, 4:45pm

Hmm, interesting. So, what you are saying is that the rules files are actually loaded before the items files, but that is not logged to log files, and then they are loaded once more, now being logged. If that is the case, I guess the startup procedure could be slimmed further if the reload of rules files would not happen until actually needed. However, I guess there is so much I don’t grasp here that there is no point digging any more

Erik_Backlund · April 12, 2024, 4:57pm

Oh, I must point out that the .rules files were loaded long after the .items files according to the log.