Rule-Trigger "When the system has reached start level 40" not working to deactivate rules during openHAB startup

Cplant · November 16, 2021, 9:55pm

Platform information:

openHAB Hardware: Raspi 3 B+ (Raspian OS 10)
openHAB Software: 3.1.0 Release Build, running on Docker / Portainer 2.9.2
openHAB Bindings: Homematic Binding (logging the heating, controlling lights and blinds), Gardena Binding for Gardena Gateway / smart irrigation control (logging soil humidity), Alexa Binding (controlling the Homematic lights)
Homematic IP Hardware: CCU2 (2.59.7), multiple Homematic IP devices
Other Hardware: Amber Wireless AMB8465 stick to read out Wireless M-Bus from water & heat meter

I’m using this approach to check and notify me in case a thing goes on- or offline. Obviously, during startup, things go online as well, so this currently floods my openHAB iOS App with messages.

I tried to solve this the following:

Temporarily deactivate the two rules during startup (the one for “checking the thing-states”, the other for “notifying me”)…
… with two two new rules being triggered during startup:
One rule, triggered as early as possible (when System Start Level 40 is reached), to temporarily deactivate the “checking-thing-state”- rule and the “notifiy about thing-state”-rule (to save me from being flooded with “thing-goes-online”-messages)

triggers:
  - id: "1"
    configuration:
      startlevel: 40
    type: core.SystemStartlevelTrigger
conditions: []
actions:
  - inputs: {}
    id: "2"
    configuration:
      enable: false
      ruleUIDs:
        - thing_status_check
        - thing_status_notification
    type: core.RuleEnablementAction
  - inputs: {}
    id: "3"
    configuration:
      type: application/javascript
      script: >-
        var logger =
        Java.type('org.slf4j.LoggerFactory').getLogger('org.openhab.rule.' +
        ctx.ruleUID);
        logger.warn("Disable Rule: Executed.");
    type: script.ScriptAction

… and one rule, triggered when startup is complete (when System Start Level 100 is reached), to activate those two rules again (which should then also be the normal operation mode)

triggers:
  - id: "1"
    configuration:
      startlevel: 100
    type: core.SystemStartlevelTrigger
conditions: []
actions:
  - inputs: {}
    id: "2"
    configuration:
      enable: true
      ruleUIDs:
        - thing_status_check
        - thing_status_notification
    type: core.RuleEnablementAction
  - inputs: {}
    id: "3"
    configuration:
      type: application/javascript
      script: >-
        var logger =
        Java.type('org.slf4j.LoggerFactory').getLogger('org.openhab.rule.' +
        ctx.ruleUID);

        logger.warn("Enable Rule: Executed.");
    type: script.ScriptAction

I included a log-entry for both the “deactivating-rule” as well as the “activating-rule”, so that I can check in the log when both rules were executed.

Strangely, only the rule that’s activating the two rules (System Start Level 100) gets executed (pretty much towards the end of the openHAB startup as it should be). The rule that should deactivate the two rules early in the startup (to avoid the flooding, executed at System Start Level 40), however, does not get executed and, thus, the two rules remain active during the entire startup, flooding my iOS App.

Two questions:

Am I missing something here on what “System Start Level 40” means? I also tried Level 50 (same) and 70 (too late, first things are already online).
Is there another way to achieve what I aim to achieve? I found this, but, well, it’s more like a workaround than a solution, so I’d like to avoid this.

I also considered having the notifications only being sent if the “System uptime” (via the “System Info Binding”) is, say > 2 minutes. But, given that openHAB offers such a neat “System Start Level”-function, this would be a very ugly solution.

rossko57 · November 16, 2021, 10:50pm

I’m pretty sure you have understood correctly

github.com/openhab/openhab-core

Implemented start level service

openhab:master ← kaikreuzer:sls

opened 11:47PM - 11 Dec 20 UTC

kaikreuzer

+722 -145

This finally implements https://github.com/eclipse-archived/smarthome/issues/189…6, 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](https://github.com/openhab/openhab-distro/pull/1211/files#diff-6f5d3ba8289d20be508f0997f8b24e4b48962d8f5e56df3e793a566bec2469f1R16-R21), 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 https://github.com/openhab/openhab-core/issues/1637 Fixes https://github.com/openhab/openhab-core/issues/1777 Fixes https://github.com/openhab/openhab-core/issues/1734 Fixes https://github.com/openhab/openhab-core/issues/1823 Fixes https://github.com/openhab/openhab-core/issues/1808 Might also fix https://github.com/openhab/openhab-core/issues/1365 Might also fix https://github.com/openhab/openhab-core/issues/1829 Signed-off-by: Kai Kreuzer <kai@openhab.org>

but - just because you have triggered a rule does not mean it’ll get to execute anything, waiting for resource at this busy time.

You don’t need the hacky file rename stuff; it’s not even going to work with UI entered rules anyway.

Which puts you back to a timer based solution.
One simple way, have a dummy Switch Item called EnableMessages or something. Make sure it is not included in persistence restore-on-startup, so it always starts as NULL state.
Give it an expire of whatever time you want, to state ON.
Have a startup rule update it to OFF (which starts timing)…
Grotty bit, amend your rules to only send messages when Item ON.

rlkoshak · November 16, 2021, 10:51pm

There is a ton of timing issues that could be involved here. I recommend opening /var/lib/openhab/etc/log4j2.xml and changing the logging level for rule to INFO. That will add events to events.log telling you when your rules are running.

That will tell us whether the rule is in-fact running but not working or that the rule is simply failing to run.

Also, there is no guarantee that all your Things will be ONLINE by the time you reach run level 100. But I don’t think that would be a problem here.

I’ve never seen anyone attempt to use the start levels like this but theoretically what you’ve tried should work. There needs to be further research to figure out why.

If changing the log levels is too daunting for you, you can add an additional Script Action with a log statement to each rule to log out when it runs. Just make sure it’s the first action, not the second in case something is going wrong with the disabling of the other rules causing the rule itself to fail silently.

Cplant · November 17, 2021, 10:42pm

So this is interesting:

I assume you meant these entries in log4j2.xml, which I changed the following:

<Logger level=INFO name=openhab.event.RuleStatusInfoEvent/>
<Logger level=INFO name=openhab.event.RuleAddedEvent/>
<Logger level=INFO name=openhab.event.RuleRemovedEvent/>

This now results in a log which, to my surprise, leaves lots of trails on the rule that’s to be executed at start level 100 (“startup_enable_rules”)…

23:11:01.333 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - RolladenProxy-1 updated: RUNNING
23:11:01.337 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - RolladenProxy-1 updated: IDLE
23:11:02.581 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - startup_enable_rules updated: RUNNING
23:11:02.587 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - system_start_notification updated: RUNNING
23:11:02.748 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - RolladenProxy-1 updated: RUNNING
23:11:02.754 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Rolladen_Leo_links_Stop' changed from OFF to NULL
23:11:02.755 [INFO ] [enhab.core.model.script.notifications] - Systemstart abgeschlossen.
23:11:02.762 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - RolladenProxy-1 updated: IDLE
23:11:02.767 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - system_start_notification updated: IDLE
23:11:03.629 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - RolladenProxy-1 updated: RUNNING
23:11:03.634 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Rolladen_Leo_Mitte_Stop' changed from OFF to NULL
23:11:03.641 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - RolladenProxy-1 updated: IDLE
23:11:03.696 [WARN ] [org.openhab.rule.startup_enable_rules] - Enable Rule: Executed.
23:11:03.700 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - startup_enable_rules updated: IDLE
23:11:04.869 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - update_variable_briefkasten updated: RUNNING
23:11:04.879 [INFO ] [openhab.event.ItemCommandEvent       ] - Item 'Variable_Briefkasten' received command REFRESH
23:11:04.882 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - update_variable_briefkasten updated: IDLE

… but no trace at all of the rule that’s supposed to run at start level 40 (“startup_disable_rules”).

Because this looked rather odd to me, I tried the same, but changed the rule from “triggered when level 40 is reached” to “triggered when level 50 is reached”. Surprisingly, same result: Rule not triggered / no trace at all in the log.

Only after having set the rule to “triggered when level 70 is reached” it did get executed (but, as mentioned in my very first post above, too late, as the first of many messages on items were already being fired):

23:32:11.484 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - startup_disable_rules updated: RUNNING
23:32:11.492 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Bambus_Feuchtigkeitssensor_BatteryLevel' changed from NULL to 81.0
23:32:11.522 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - thing_status_check updated: UNINITIALIZED (DISABLED)
23:32:11.578 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - thing_status_notification updated: UNINITIALIZED (DISABLED)
23:32:11.711 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Lichtsensor_Garten_LowBattery' changed from NULL to OFF
23:32:11.734 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Messstecker_4_Schalter' changed from NULL to OPEN
23:32:11.770 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Thermostat_Garten_Unreach' changed from NULL to OFF
23:32:11.790 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'mRolladenLeoMitte' changed from NULL to ON
23:32:11.801 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Flur_Signalleuchte_Unreach' changed from NULL to OFF
23:32:11.830 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'mKaltwasserzaehler' changed from NULL to ON
23:32:11.841 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Systeminfo_Storage_UsedPercent' changed from NULL to 26.6
23:32:11.860 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'CCU2_Variable_Anwesend' changed from NULL to ON
23:32:11.880 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'mLichtGarten' changed from NULL to ON
23:32:11.900 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Schaltstecker_Lampe_Leo_Unreach' changed from NULL to OFF
23:32:11.930 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Rolladen_Kueche_Links' changed from NULL to 0
23:32:11.957 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Thermostat_Leo_Humidity' changed from NULL to 47
23:32:11.990 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'warmwasserzaehler_gesamt' changed from NULL to 30.41
23:32:12.024 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Licht_Garten_Unreach' changed from NULL to OFF
23:32:12.122 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Rolladen_Bad_Stop' changed from NULL to OFF
23:32:12.149 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Haustur_Taster_1_Kurzer_Druck' changed from NULL to OFF
23:32:12.170 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Lichtschalter_Kueche_Unreach' changed from NULL to OFF
23:32:12.190 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Haustur_Taster_LowBattery' changed from NULL to OFF
23:32:12.202 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Messstecker_4_Leistung_heute' changed from NULL to 0.343
23:32:12.234 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Rolladen_Leo_Rechts' changed from NULL to 100
23:32:12.258 [INFO ] [nhab.event.GroupItemStateChangedEvent] - Item 'Rolladen_Leo' changed from UNDEF to 100 through Rolladen_Leo_Rechts
23:32:12.273 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Dimmstecker_Wohnzimmer_Unreach' changed from NULL to OFF
23:32:12.290 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Rolladen_Schlafzimmer_Stop' changed from NULL to OFF
23:32:12.312 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Rolladen_Wohnzimmer_Rechts_Unreach' changed from NULL to OFF
23:32:12.323 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Stehlampe' changed from NULL to 30
23:32:12.334 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'mLichtschalterKueche' changed from NULL to ON
23:32:12.358 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'mSchaltsteckerLampeLeo' changed from NULL to ON
23:32:12.403 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Systeminfo_CPUTemperature' changed from NULL to 54.2
23:32:12.430 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Rolladen_Kueche_Rechts_Unreach' changed from NULL to OFF
23:32:12.442 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'ThermostatLeo_9_STATE' changed from NULL to 0.0
23:32:12.468 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Messstecker_1_Schalter' changed from NULL to OPEN
23:32:12.484 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'Rolladen_Wohnzimmer_Rechts_Stop' changed from NULL to OFF
23:32:12.517 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'mNousMesssteckerWaschmaschine' changed from NULL to ON
23:32:13.231 [WARN ] [penhab.rule.thing_status_notification] - Gardena Smart System Account - Thing online.
23:32:13.905 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - konvertierung_gardena_ventilstatus updated: IDLE
23:32:13.913 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - konvertierung_gardena_ventilstatus updated: RUNNING
23:32:13.919 [WARN ] [rg.openhab.rule.startup_disable_rules] - Disable Rule: Executed.
23:32:13.943 [INFO ] [openhab.event.RuleStatusInfoEvent    ] - startup_disable_rules updated: IDLE

So my best guess would be: The trigger “when level 40 and 50 is reached” are not working? Though this would be somewhat odd, as I believe someone else would’ve noticed as well by now?

Edit: Just to be absolutely sure that I’m not messing something up myself I just created a completely empty rule, triggered by system state 40. Same here: No trace of the rule being run in the log.

rossko57 · November 17, 2021, 11:38pm

I doubt that. So long as something happened at startup, it would satisfy most users.

I thought I remembered seeing a github story where start level triggering was problematic, so as a stop-gap all rule triggers were treated as though 100, but I find no trace and likely confused something about old files syntax.

I do think your whole approach here is doomed though; you’ve no way (even with functional start levels) to ensure some particular rule runs before any other, to disable the others.
You need nothing to happen by default at startup, then actively enable messages later.

rlkoshak · November 18, 2021, 4:27pm

Most users I’ve seen use run level 100. They want everything to be up and firing before the rule runs. So you are likely the first to notice. Note that when using files you cannot specify the runlevel, you just get “System started” which, if I recall correctly is 70.

I’d file an issue as it makes no sense to have the option if it’s not going to work. But I agree with @rossko57, even were this to work you likely would not be happy with the reliability of the result.

I’d

Cplant · November 20, 2021, 9:47am

Maybe you meant this one.

You were right: At Startup Level 70, it sometimes worked (e.g. rule ran early enough to disable the other rule early enough), and sometimes didn’t (the first of the x messages got fired). See below the result of 7 identical restarts.

I looked into this, but was a bit reluctant to go for the (from what I understood) dominant option of working with groups that are to be restored on startup). From what I understood, going for this approach would mean that, going forward, I always have to remember to put all new items into this group, to ensure that they’re restored on startup.

Instead, I noticed that a file-based rule might run early enough to deactivate the rule early enough, which is what I’d like to verify. Though I’m struggeling with the Syntax, maybe you can answer two questions:

Surprisingly “When System started” (file-based rule) appears to run early enough (though I assume this is the equivalence to “Start Level 100” (UI-based rule), so not sure why this appears to be running early than start Level 100). What would be the syntax to trigger it file-based by different start levels? There appears to be a gap in the documentation, which is why I’m struggeling.
What’s the syntax to enable / disable rules in file-based rules? My attempt below was what I thought, but obviously it doesn’t work.

rule "Startup - Disable Rules"
when
    System started
then
    RuleManager.setEnabled(things_status_check, false);
    RuleManager.setEnabled(things_status_notification, false);
    logInfo("notifications", "Rules disabled.");
end

rossko57 · November 20, 2021, 11:13am

You’d still be relying on luck, which may run out if you change versions or host box. I just wouldn’t go that way,

rlkoshak · November 22, 2021, 3:07pm

Well yes, if you don’t want all your Items to be restoreOnStartup, you have to individually specify the ones you want to be restored.

There is nothing to make me believe that a file based rule will work any better. The problem is a lot is going on in parallel and you can’t sequence events in the way you need.

No, it’s either RL 40 or 60. I don’t remember exactly which. The System started trigger in file based rules is basically legacy so the RL chose was closest to what it’s been all along before runlevels were even introduced.

You can’t from Rules DSL. You need access to stuff that is not available in Rules DSL. There are ways to get to the RuleManager in JavaScript or any of the other languages but not in Rules DSL.

In JavaScript it looks like

var logger = Java.type("org.slf4j.LoggerFactory").getLogger("org.openhab.model.script.Rules.Examples");

// Find the rule
logger.info("There are " + rules.getAll().length + " rules");
for each (var r in rules.getAll()) {
  logger.info("Rule name = " + r.getName());
  logger.info("Rule UID = " + r.getUID()); 
}
var thisRule = rules.getAll().stream().filter(function(i){ return i.name == "Experiments" }).findFirst().get();
logger.info("This rules UID is " + thisRule.getUID());

// Disable the rule
var FrameworkUtil = Java.type("org.osgi.framework.FrameworkUtil");
var _bundle = FrameworkUtil.getBundle(scriptExtension.class);
var bundle_context = _bundle.getBundleContext()
var classname = "org.openhab.core.automation.RuleManager"
var RuleManager_Ref = bundle_context.getServiceReference(classname);
var RuleManager = bundle_context.getService(RuleManager_Ref);
logger.info("Enabled = " + RuleManager.isEnabled(thisRule.getUID()));
RuleManager.setEnabled(thisRule.getUID(), false);
logger.info("Enabled = " + RuleManager.isEnabled(thisRule.getUID()));