Non-deterministic order of startup rule execution and thing initialization

[Pete2 (Pete)]

• Platform information:

  • Hardware: Raspberry Pi 3 Model B (armv7l) / 1 GB RAM / 7 GB storage

  • OS: DietPi v8.4.2

  • Java Runtime Environment: openjdk 11.0.11 2021-04-20 LTS
    OpenJDK Runtime Environment Zulu11.48+21-CA (build 11.0.11+9-LTS)
    OpenJDK Client VM Zulu11.48+21-CA (build 11.0.11+9-LTS, mixed mode)

  • openHAB version: 3.1.0 (Build)

• Issue: A ‘System started’ rule sometimes runs before the ‘local sun thing’ of the Astro binding is initialized which causes the rule to fail. The rule depends on the ‘local sun thing’ being initialized.

I am using a file based configuration because the OH2 UI was pretty unusable for my requirements at the time when the system was set up.

This is my Astro binding thing to determine the current sun / darkness state:

Thing astro:sun:local "Local Sun" [geolocation="XXX,XXX,0", interval=300] {
    Channels:
        Type rangeEvent: civilDusk#event [
            offset=20,
            earliest="17:30",
            latest="22:00"
        ]
}

Here is the rule that initializes the “Darkness” item on startup:

rule "Init: Set darkness value"
when
        System started
then
        // determine wether it is day or night at startup
        val sunActions = getActions("astro", "astro:sun:local")
        if (sunActions === null) {
                logError("actions", "sunActions not found, check thing ID")
                return
        } else {
                val sunRise = sunActions.getEventTime("SUN_RISE", now, "START")
                val sunSet  = sunActions.getEventTime("SUN_SET", now, "END")

                if (now.isAfter(sunRise) && now.isBefore(sunSet)) {
                        Darkness.sendCommand(OFF)
                } else {
                        Darkness.sendCommand(ON)
                }
        }
end

I think that I copied this rule in some form from this forum over a year ago. Today was the first time that I experienced an issue during startup with this.

I absolutely never want to restart the OH service. But very rarely I have to because of a kernel update or a thing refuses to update its configuration after I changed the .thing file.

Usually a restart works as expected:

2022-05-06 18:34:46.384 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Berlin'.
2022-05-06 18:34:46.447 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to 'XXX,XXX'.
2022-05-06 18:34:46.451 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'en_DE'.
2022-05-06 18:34:46.454 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Measurement system set to 'SI'.
2022-05-06 18:35:00.255 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'gpio.items'
...
2022-05-06 18:35:16.655 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'alarm.rules'
2022-05-06 18:35:23.527 [INFO ] [org.openhab.ui.internal.UIService   ] - Started UI on port 8080
2022-05-06 18:35:23.707 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'astro:sun:local' to inbox.
2022-05-06 18:35:28.917 [INFO ] [penhab.core.model.script.Garage Door] - Trying to sync switch state NULL
2022-05-06 18:35:29.784 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started.
2022-05-06 18:35:36.520 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2022-05-06 18:35:41.816 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2022-05-06 18:35:41.821 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.

But now there is an error during startup. You can see that the rule engine was started before the astro thing was added:

2022-05-06 23:49:18.858 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Berlin'.
2022-05-06 23:49:18.915 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Location set to 'XXX,XXX'.
2022-05-06 23:49:18.919 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'en_DE'.
2022-05-06 23:49:18.922 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Measurement system set to 'SI'.
2022-05-06 23:49:31.897 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'gpio.items'
...
2022-05-06 23:49:47.686 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'alarm.rules'
2022-05-06 23:49:55.395 [ERROR] [rg.openhab.core.model.script.actions] - sunActions not found, check thing ID
2022-05-06 23:49:55.412 [INFO ] [penhab.core.model.script.Garage Door] - Trying to sync switch state NULL
2022-05-06 23:49:56.239 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started.
2022-05-06 23:49:57.423 [INFO ] [org.openhab.ui.internal.UIService   ] - Started UI on port 8080
2022-05-06 23:49:57.618 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'astro:sun:local' to inbox.
2022-05-06 23:50:09.820 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2022-05-06 23:50:15.105 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2022-05-06 23:50:15.109 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.

This discussion seems related:

Rule Initialization - Slow first run after startup workaround

Platform information: Hardware: Pi3B - ARM Cortex-A53 1.2GHz/1GB Ram/120GB SDD over USB OS: OpenHabian 3.2 (Raspian GNU/Linux 9) Java Runtime Environment: Zulu 11 Open JDK 32-bit openHAB version: 3.2 The first time rules execute after a reboot they take much longer than subsequent executions. On my Pi3B a button press based rule would take 4-5 seconds before taking action the first time the rule was called after a reboot vs less than a second after. From my searching on the subject it looks…

Startlevels seem to be a solution but the manual states that startlevels are not available in text based rules.

So my rule should not trigger because of a system startup but because of a thing initialization instead?:

Rules

Having the rule engine start executing without making sure that all things have already been ininitialized might seem like an extremely poor design choice, but the nature of OSGI/Karaf probably dictates that it is done in this non-deterministic way?

Was this done because a new thing can pop up anytime during the whole runtime of the system? So it should be expected that things are unavailable when the rule engine starts?

My current solution would be to change the rule condition from ‘System started’ to

Thing "astro:sun:local" changed to ONLINE

I would like to know if this is right approach and maybe have this information here for reference as this communitiy is an excellent source of information and OH would be completely unusable for me otherwise. Thank you!

[hafniumzinc (T)]

@Pete2

or a thing refuses to update its configuration after I changed the .thing file.

I can’t answer your actual question, but on this: you don’t have to restart openHAB just for this. You can restart just the binding via the console, or I do this as I’m already in the code editor..

[mhilbush (Mark)]

@Pete2

Startlevels seem to be a solution but the manual states that startlevels are not available in text based rules.

That functionality was added to DSL rules in the PR referenced below. But you might want to read the conversation from the PR to understand the limitations.

"System reached start level XX" trigger for DSL rules

You could try using start level 100. I did that and it seemed to make a slight improvement in the order of execution of some of my startup rules. But it’s still a bit non-deterministic.

[Pete2 (Pete)]

@hafniumzinc

You can restart just the binding via the console

Thanks for the tips. Corrupting the .things file seems to work. I will also try restarting the binding in the console as that seems to be the cleanest and non-disruptive solution.

@mhilbush

But it’s still a bit non-deterministic.

Thank you for the response. This is appreciated. Unfortunately I would have to update the OH installation for that. I already did this once and it was a nightmare. That was during the testing phase.

The system is in production now and mostly works the way I want it to. A disruption of service for an unknown time is not something I want to bother the owner of the house with.

My change in the rule with waiting for the Thing to change to ONLINE seems to work as expected. But working with start levels still might be an extremely valuable addition for other users.