OpenHAB3 Start Up Issues - Race Condition? How to Sequence Startup?

nyholm · April 1, 2021, 4:03pm

I have migrated my OpenHAB installation from 2.4.0 to 3.0.1 on Windows 10 computers.
The OH2 installation has been running on a x5-Z8350 and starting up without hiccups for many many months.

The OH3 installation is running on a faster N4020 and has erratic startup behavior:

Sometimes it starts clean as a whistle and runs flawlessly
Sometime it logs "scheduled job failed and stopped ...."
Sometimes it appears global variable are not initialized
Sometime it logs "script execution of rule .... failed: publishMQTT is not a member of ....
Sometimes it logs "script execution of rule .... failed: D != java.lang.String in ...."
Sometimes it appears to hang

I have even tried rebooting the N4020 between restarts.
I think the code is suffering from a start-up race condition. It has an initialization rule that is triggered by System start. This rule initializes global variables, imports binding Actions for the mail and mqtt bindings, resets some items, sends me a notification ,text, and email, etc. The code is also retrieving values from mapdb persistence.

It appears other rules that are triggered by Time cron or Item .. updated or Item ... changed are triggering before persistence has completed, or bindings are ready, or the the initialization rule has exited.

Is there a way to sequence start-up behavior? Maybe
1 - let persistence do its thing
2 - let bindings prepare themselves
3 - let the initialization rule complete

The only way I can think of controlling start-up is to use a global variable as follows

var myGreenFlag = 0

rule "Startup_Initializations"
when 
     System started
then
     myGreenFlag = 0  
     var mqttActions = getActions( blah blah blah ) // Import mqtt Thing Actions
     var mailActions = getActions( blah blah blah ) // Import mail Thing Actions
     Thread::sleep(30000) // pause for 30 seconds to allow persistence to complete and bindings to initialize

// my code

     myGreenFlag = 1
end


rule "Lets_Do_Something"
when
     Time cron ............
     Item xxx changed 
then
     if (myCondition) break  // not sure of the syntax here  break vs break; vs return ?

// more code

end

Am I way off base here?
Am I going about this properly?
Any Suggestions?

As always, thanks for any help

Bruce_Osborne · April 1, 2021, 4:38pm

Unfortunately, openHAB has no concept of ordering startup processes.

rlkoshak · April 1, 2021, 5:32pm

In OH 3 the startup process is in fact more orderly than it was in OH 2.5. There is a new concept of start levels in OH now. I believe (though I’ve seen some contra reports) that System started now corresponds with start level 40 which is in fact really early in the startup process.

I don’t have the full list handy but the list of levels I do have are:

40 - Rules loaded
50 - Rule engine started
70 - User interface started
80 - Things initialized
100 - Startup complete

Some important things to note:

This is the system start level. Reloading a rules file will not trigger the System started rules because OH is already at start level 100.
Things initialize after rules. Consequently if you have a rule trigger at start level < 80 that depends on an Action from a binding, it’s not going to work because the Thing that provides that Action hasn’t initialized yet. Because these Actions depend on the status of a Thing, it is a best practice to pull the Action immediately before using it within a rule, not when the rules file is loaded (i.e. as a global or in a System started rule). If that Thing goes offline later after the start, that global would become stale and no longer work even if the Thing comes back online.
There is no System started trigger offered in UI rules. Instead you can choose and start level above 40 to trigger the rule. I usually choose 100.

I think that restoreOnStartup gets kicked off at an earlier run level but it runs in parallel. If your DB is slow enough compared to openHAB’s startup speed it could very well be still restoring Item states when run level 40 is reached. This can be particularly pronounced when not using one of the embedded databases for restoreOnStartup like InfluxDB or MySQL.

I do not know how/if one can specify a run level trigger in a .rules file. If not an issue should be created.

Some of the errors look like orphaned timers but it’s impossible to tell without more details and logs from a specific case of the log.

In OH 2 the startup process was even more chaotic than this and people would resort to modifying the service script to rename all the .rules files to something else, wait long enough, then rename them back so OH doesn’t even try to load them until enough time has passed.

As an anecdote though I’ve experienced no loading issues when using UI based rules nor when using the other programming languages besides Rules DSL and others have reported the same, so I think this is specific to Rules DSL in .rules files only.

Sas_Bibic · April 2, 2021, 11:51am

In OH2 System started event was executed every time .rule file was updated. Is there any equivalent in OH3 ?

/Sas

mstormi · April 2, 2021, 11:58am

I don’t think so as that never has been an intentional “feature”.
And you shouldn’t need that. It’s even counterproductive as the application should not depend on it but it can hide issues with some lazy type of programming.

nyholm · April 2, 2021, 2:13pm

Is there a way to read the system level 40 - 100?

rlkoshak · April 2, 2021, 2:34pm

Not yet but there is discussion of creating a script loaded rule trigger for that case. In there mean time, you can manually run the role through MainUI or the Console. You know when the file is modified and reloaded so you will know when you need to manually run them.

In JavaScript and Python one can define a scriptLoaded function which gets called when the file is loaded.

Probably not in Rules DSL. I don’t think it’s exposed in the REST API. There’s might be a way in JavaScript and Python but someone will have to look through the source code to figure that out.

Sas_Bibic · April 2, 2021, 8:45pm

Thank You for all the answers.

/Sas

nyholm · April 2, 2021, 10:47pm

So I implemented very nearly as my initial post (#1)

var Number GreenFlag = 0

rule "Startup_Initializations"
	when
		System started
	then	
		GreenFlag = 0
	
		logInfo("Startup_Initializations", ">>>>> ENTERED RULE = Startup_Initializations *****************************************************************") 
		
		logInfo("Startup_Initializations", ">>>>> OpenHAB HS5150 IS SLEEPING 30 SECONDS TO ALLOW IT TO ORGANIZE ITSELF")
		Thread::sleep(30000)
		logInfo("Startup_Initializations", ">>>>> OpenHAB HS5150 IS NOW AWAKE **************************************************************************")
		
		HS_Events_Log.postUpdate("OH is Re-starting")
	
		BreakSilence = 0
		HS5150_Msg_Counter_Now = 0
		Start_Time = now.toInstant.toEpochMilli
		StartUp_Trigger.postUpdate(0)
		
		OHC_MsgStamp.postUpdate(-1)

		
		Date.postUpdate(new DateTimeType())
		Rule_TimeStamp4SI = Date.state.format("%tD") + " @ " + Date.state.format("%tr") 
		
		DemoLocation.postUpdate(new PointType("37.6925300,-121.7273800")) 
		
		logInfo("Startup_Initializations", ">>>>> RUNNING RULE = Startup_Initializations at " + Rule_TimeStamp4SI + " *************************************")

AND

rule "Lets_Do_Something"
when
     Time cron ............
     Item xxx changed 
then
    if (GreenFlag == 0) return;

// more code
end

and all was working beautifully UNTIL OH3 started logging non-repeatable errors after I was fiddling with other rules and restarting OH3, and even restarting the Windows PC.

I did not save the 1st error log because the rule did not even execute the 1st logInfo.
The following was logged after I commented out the 2 logInfo’s

rule "Startup_Initializations"
	when
		System started
	then	
		GreenFlag = 0
		Thread::sleep(30000)  // this is line 355
		logInfo("Startup_Initializations", ">>>>> OpenHAB HS5150 IS NOW AWAKE   // this is line 356


14:25:28.182 [ERROR] [.internal.handler.ScriptActionHandler] - Script execution of rule with UID 'HS5150-1' failed: The name 'logInfo' cannot be resolved to an item or type; line 356, column 3, length 146 in HS5150

Here’s the complete log file with line 356 failure at the end:

openhab> log:tail
14:22:28.618 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'HS5150.items'
14:22:31.825 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'mapdb.persist'
14:22:32.622 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'HS5150Lite.sitemap'
14:22:32.954 [INFO ] [del.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'HS5150Lite.sitemap', using it anyway:
Sitemap should contain either only frames or none at all
14:22:33.034 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'HS5150.sitemap'
14:22:33.730 [INFO ] [del.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'HS5150.sitemap', using it anyway:
Sitemap should contain either only frames or none at all
14:22:34.402 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'HS5150.things'
14:22:39.238 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'HS5150.rules'
14:23:34.396 [INFO ] [del.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'HS5150.rules', using it anyway:
The value of the local variable mailActions is not used
The value of the local variable mailActions is not used
The value of the local variable mailActions is not used
14:23:36.557 [INFO ] [b.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
14:23:43.853 [INFO ] [org.openhab.ui.internal.UIService    ] - Started UI on port 8080
14:23:47.330 [WARN ] [org.openhab.core.io.net.exec.ExecUtil] - Failed to execute commandLine '[arping, --help]'
14:23:52.536 [WARN ] [org.openhab.core.io.net.exec.ExecUtil] - Failed to execute commandLine '[arping, --help]'
14:24:00.387 [INFO ] [.io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = c86a53f2-1c89-4f8f-996c-521ad3c68bce, base URL = http://localhost:8080)
14:24:06.358 [INFO ] [hab.ui.habpanel.internal.HABPanelTile] - Started HABPanel at /habpanel
14:24:30.916 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:socket:WEMO01' changed from UNINITIALIZED to INITIALIZING
14:24:31.148 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'exec:command:ExecReStart' changed from UNINITIALIZED to INITIALIZING
14:24:31.332 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:socket:WEMO01' changed from INITIALIZING to ONLINE
14:24:31.692 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:socket:WEMO02' changed from UNINITIALIZED to INITIALIZING
14:24:31.956 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:socket:WEMO02' changed from INITIALIZING to ONLINE
14:24:31.876 [INFO ] [nternal.dhcp.DHCPPacketListenerServer] - DHCP request packet listener online
14:24:32.028 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'exec:command:ExecReStart' changed from INITIALIZING to ONLINE
14:24:32.177 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:socket:WEMO09' changed from UNINITIALIZED to INITIALIZING
14:24:32.249 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'exec:command:ExecShutdown' changed from UNINITIALIZED to INITIALIZING
14:24:32.257 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:socket:WEMO09' changed from INITIALIZING to ONLINE
14:24:32.473 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:socket:WEMO10' changed from UNINITIALIZED to INITIALIZING
14:24:32.665 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'exec:command:ExecShutdown' changed from INITIALIZING to ONLINE
14:24:32.873 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:socket:WEMO10' changed from INITIALIZING to ONLINE
14:24:33.090 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:lightswitch:WEMO12' changed from UNINITIALIZED to INITIALIZING
14:24:33.330 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:topic:hsbroker:WatchManThing' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
14:24:33.698 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP20' changed from UNINITIALIZED to INITIALIZING
14:24:33.810 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:lightswitch:WEMO12' changed from INITIALIZING to ONLINE
14:24:33.898 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mail:smtp:GmailHP5150' changed from UNINITIALIZED to INITIALIZING
14:24:34.229 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:lightswitch:WEMO13' changed from UNINITIALIZED to INITIALIZING
14:24:34.557 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP20' changed from INITIALIZING to ONLINE
14:24:34.701 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mail:smtp:GmailHP5150' changed from INITIALIZING to ONLINE
14:24:35.013 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:lightswitch:WEMO13' changed from INITIALIZING to ONLINE
14:24:35.493 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:lightswitch:WEMO14' changed from UNINITIALIZED to INITIALIZING
14:24:36.013 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:broker:hsbroker' changed from UNINITIALIZED to INITIALIZING
14:24:36.403 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:lightswitch:WEMO14' changed from INITIALIZING to ONLINE
14:24:36.571 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:lightswitch:WEMO15' changed from UNINITIALIZED to INITIALIZING
14:24:36.915 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:broker:hsbroker' changed from INITIALIZING to OFFLINE
14:24:37.155 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:lightswitch:WEMO15' changed from INITIALIZING to ONLINE
14:24:37.363 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP21' changed from UNINITIALIZED to INITIALIZING
14:24:37.555 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:topic:hsbroker:WatchManThing' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
14:24:37.243 [WARN ] [.core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'mqtt:broker:hsbroker' takes more than 5000ms.
14:24:37.651 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP21' changed from INITIALIZING to ONLINE
14:24:37.675 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:topic:hsbroker:WatchManThing' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)
14:24:37.755 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP22' changed from UNINITIALIZED to INITIALIZING
14:24:37.899 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP22' changed from INITIALIZING to ONLINE
14:24:38.005 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP23' changed from UNINITIALIZED to INITIALIZING
14:24:38.101 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP23' changed from INITIALIZING to ONLINE
14:24:38.181 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP24' changed from UNINITIALIZED to INITIALIZING
14:24:38.405 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP24' changed from INITIALIZING to ONLINE
14:24:38.477 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP25' changed from UNINITIALIZED to INITIALIZING
14:24:38.693 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP25' changed from INITIALIZING to ONLINE
14:24:38.813 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP26' changed from UNINITIALIZED to INITIALIZING
14:24:38.829 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP26' changed from INITIALIZING to ONLINE
14:24:38.845 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP27' changed from UNINITIALIZED to INITIALIZING
14:24:38.877 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP27' changed from INITIALIZING to ONLINE
14:24:38.933 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP28' changed from UNINITIALIZED to INITIALIZING
14:24:39.006 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP28' changed from INITIALIZING to ONLINE
14:24:39.029 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP29' changed from UNINITIALIZED to INITIALIZING
14:24:39.155 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP29' changed from INITIALIZING to ONLINE
14:24:39.196 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP30' changed from UNINITIALIZED to INITIALIZING
14:24:39.320 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP30' changed from INITIALIZING to ONLINE
14:24:39.483 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP31' changed from UNINITIALIZED to INITIALIZING
14:24:39.643 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP31' changed from INITIALIZING to ONLINE
14:24:39.795 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP32' changed from UNINITIALIZED to INITIALIZING
14:24:39.875 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP32' changed from INITIALIZING to ONLINE
14:24:40.043 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP33' changed from UNINITIALIZED to INITIALIZING
14:24:40.091 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP33' changed from INITIALIZING to ONLINE
14:24:40.131 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP34' changed from UNINITIALIZED to INITIALIZING
14:24:40.147 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP34' changed from INITIALIZING to ONLINE
14:24:40.171 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP35' changed from UNINITIALIZED to INITIALIZING
14:24:40.184 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP35' changed from INITIALIZING to ONLINE
14:24:40.196 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP51' changed from UNINITIALIZED to INITIALIZING
14:24:40.221 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP51' changed from INITIALIZING to ONLINE
14:24:40.245 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP62' changed from UNINITIALIZED to INITIALIZING
14:24:40.405 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP62' changed from INITIALIZING to ONLINE
14:24:40.301 [INFO ] [o.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '10.0.0.9' with clientid ab893704-04ce-4dd6-9ec0-7e20216aa496
14:24:40.525 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP59' changed from UNINITIALIZED to INITIALIZING
14:24:40.669 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP59' changed from INITIALIZING to ONLINE
14:24:40.725 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP60' changed from UNINITIALIZED to INITIALIZING
14:24:40.885 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP60' changed from INITIALIZING to ONLINE
14:24:40.973 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP52' changed from UNINITIALIZED to INITIALIZING
14:24:40.981 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP52' changed from INITIALIZING to ONLINE
14:24:40.989 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP63' changed from UNINITIALIZED to INITIALIZING
14:24:40.997 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP63' changed from INITIALIZING to ONLINE
14:24:41.021 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP64' changed from UNINITIALIZED to INITIALIZING
14:24:41.045 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP64' changed from INITIALIZING to ONLINE
14:24:41.053 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP65' changed from UNINITIALIZED to INITIALIZING
14:24:41.069 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP65' changed from INITIALIZING to ONLINE
14:24:41.101 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP06' changed from UNINITIALIZED to INITIALIZING
14:24:41.125 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP06' changed from INITIALIZING to ONLINE
14:24:41.141 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP08' changed from UNINITIALIZED to INITIALIZING
14:24:41.149 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP08' changed from INITIALIZING to ONLINE
14:24:41.173 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP09' changed from UNINITIALIZED to INITIALIZING
14:24:41.181 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP09' changed from INITIALIZING to ONLINE
14:24:41.221 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP98' changed from UNINITIALIZED to INITIALIZING
14:24:41.237 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP98' changed from INITIALIZING to ONLINE
14:24:41.253 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP99' changed from UNINITIALIZED to INITIALIZING
14:24:41.277 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP99' changed from INITIALIZING to ONLINE
14:24:41.317 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:broker:hsbroker' changed from OFFLINE to ONLINE
14:24:41.365 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:topic:hsbroker:WatchManThing' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
14:24:56.843 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'IP_Robert_2G' changed from ON to OFF
14:25:28.182 [ERROR] [.internal.handler.ScriptActionHandler] - Script execution of rule with UID 'HS5150-1' failed: The name 'logInfo' cannot be resolved to an item or type; line 356, column 3, length 146 in HS5150
14:25:28.342 [INFO ] [re.automation.internal.RuleEngineImpl] - Rule engine started.
14:25:34.872 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'IP_Peter_2G' changed from OFF to ON

I tried restarting again and got this somewhere later in the code somewhere after `OpenHAB HS5150 IS NOW AWAKE’:

14:36:47.021 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP09' changed from UNINITIALIZED to INITIALIZING
14:36:47.021 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP09' changed from INITIALIZING to ONLINE
14:36:47.037 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP98' changed from UNINITIALIZED to INITIALIZING
14:36:47.053 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP98' changed from INITIALIZING to ONLINE
14:36:47.053 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP99' changed from UNINITIALIZED to INITIALIZING
14:36:47.069 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP99' changed from INITIALIZING to ONLINE
14:36:47.320 [INFO ] [o.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '10.0.0.9' with clientid 04f3f69d-8ebf-45b1-ae84-9689097e61d0
14:36:47.510 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:broker:hsbroker' changed from OFFLINE to ONLINE
14:36:47.742 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:topic:hsbroker:WatchManThing' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
14:37:38.871 [INFO ] [.model.script.Startup_Initializations] - >>>>> OpenHAB HS5150 IS NOW AWAKE **************************************************************************
14:37:38.903 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'HS_Events_Log' changed from >>>>> Published OHOB_String: MS114 to OH is Re-starting
14:37:38.967 [ERROR] [.internal.handler.ScriptActionHandler] - Script execution of rule with UID 'HS5150-1' failed: An error occurred during the script execution: Cannot resolve proxy: HS5150.rules#/1 in HS5150
14:37:39.056 [INFO ] [re.automation.internal.RuleEngineImpl] - Rule engine started.

After rebooting the computer I get "GreenFlag cannot be resolved" even though GreenFlag is defined as a global Number variable var Number GreenFlag = 0. It looks like the initialization rule is time-lagging the other rules:

openhab> log:tail
15:04:49.699 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'HS5150.items'
15:04:52.600 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'mapdb.persist'
15:04:53.384 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'HS5150Lite.sitemap'
15:04:53.676 [INFO ] [del.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'HS5150Lite.sitemap', using it anyway:
Sitemap should contain either only frames or none at all
15:04:53.852 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'HS5150.sitemap'
15:04:54.492 [INFO ] [del.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'HS5150.sitemap', using it anyway:
Sitemap should contain either only frames or none at all
15:04:55.116 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'HS5150.things'
15:04:59.235 [INFO ] [b.core.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
15:04:59.515 [INFO ] [del.core.internal.ModelRepositoryImpl] - Loading model 'HS5150.rules'
15:05:50.816 [INFO ] [del.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'HS5150.rules', using it anyway:
The value of the local variable mailActions is not used
The value of the local variable mailActions is not used
The value of the local variable mailActions is not used
15:05:56.490 [INFO ] [org.openhab.ui.internal.UIService    ] - Started UI on port 8080
15:06:05.651 [WARN ] [org.openhab.core.io.net.exec.ExecUtil] - Failed to execute commandLine '[arping, --help]'
15:06:13.359 [INFO ] [.io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = c86a53f2-1c89-4f8f-996c-521ad3c68bce, base URL = http://localhost:8080)
15:06:19.823 [INFO ] [hab.ui.habpanel.internal.HABPanelTile] - Started HABPanel at /habpanel
15:06:40.940 [ERROR] [.internal.handler.ScriptActionHandler] - Script execution of rule with UID 'HS5150-1' failed: An error occurred during the script execution: Cannot resolve proxy: HS5150.rules#/1 in HS5150
15:06:41.060 [INFO ] [re.automation.internal.RuleEngineImpl] - Rule engine started.
15:06:41.327 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'exec:command:ExecReStart' changed from UNINITIALIZED to INITIALIZING
15:06:41.807 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'exec:command:ExecReStart' changed from INITIALIZING to ONLINE
15:06:41.623 [INFO ] [nternal.dhcp.DHCPPacketListenerServer] - DHCP request packet listener online
15:06:42.039 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'exec:command:ExecShutdown' changed from UNINITIALIZED to INITIALIZING
15:06:42.215 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'exec:command:ExecShutdown' changed from INITIALIZING to ONLINE
15:06:42.127 [ERROR] [.internal.handler.ScriptActionHandler] - Script execution of rule with UID 'HS5150-24' failed: The name 'GreenFlag' cannot be resolved to an item or type; line 3656, column 10, length 9 in HS5150
15:06:42.367 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mail:smtp:GmailHP5150' changed from UNINITIALIZED to INITIALIZING
15:06:42.834 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:broker:hsbroker' changed from UNINITIALIZED to INITIALIZING
15:06:43.487 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mail:smtp:GmailHP5150' changed from INITIALIZING to ONLINE
15:06:43.871 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP20' changed from UNINITIALIZED to INITIALIZING
15:06:44.135 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP20' changed from INITIALIZING to ONLINE
15:06:44.383 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:broker:hsbroker' changed from INITIALIZING to OFFLINE
15:06:44.399 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP21' changed from UNINITIALIZED to INITIALIZING
15:06:44.719 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP21' changed from INITIALIZING to ONLINE
15:06:45.143 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP22' changed from UNINITIALIZED to INITIALIZING
15:06:45.300 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP22' changed from INITIALIZING to ONLINE
15:06:45.556 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP23' changed from UNINITIALIZED to INITIALIZING
15:06:45.740 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP23' changed from INITIALIZING to ONLINE
15:06:45.900 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP24' changed from UNINITIALIZED to INITIALIZING
15:06:45.932 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP24' changed from INITIALIZING to ONLINE
15:06:46.012 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP25' changed from UNINITIALIZED to INITIALIZING
15:06:46.060 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP25' changed from INITIALIZING to ONLINE
15:06:46.116 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP26' changed from UNINITIALIZED to INITIALIZING
15:06:46.200 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP26' changed from INITIALIZING to ONLINE
15:06:46.261 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP27' changed from UNINITIALIZED to INITIALIZING
15:06:46.293 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP27' changed from INITIALIZING to ONLINE
15:06:46.357 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP28' changed from INITIALIZING to ONLINE
15:06:46.421 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP28' changed from UNINITIALIZED to INITIALIZING
15:06:46.469 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP29' changed from UNINITIALIZED to INITIALIZING
15:06:46.557 [WARN ] [.core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'mqtt:broker:hsbroker' takes more than 5000ms.
15:06:46.573 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP29' changed from INITIALIZING to ONLINE
15:06:46.650 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP30' changed from UNINITIALIZED to INITIALIZING
15:06:46.746 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP30' changed from INITIALIZING to ONLINE
15:06:46.802 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP31' changed from UNINITIALIZED to INITIALIZING
15:06:46.834 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP31' changed from INITIALIZING to ONLINE
15:06:46.970 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP32' changed from INITIALIZING to ONLINE
15:06:47.018 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP32' changed from UNINITIALIZED to INITIALIZING
15:06:47.106 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP33' changed from UNINITIALIZED to INITIALIZING
15:06:47.154 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP33' changed from INITIALIZING to ONLINE
15:06:47.215 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP34' changed from UNINITIALIZED to INITIALIZING
15:06:47.303 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP34' changed from INITIALIZING to ONLINE
15:06:47.359 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP35' changed from UNINITIALIZED to INITIALIZING
15:06:47.471 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP35' changed from INITIALIZING to ONLINE
15:06:47.551 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP51' changed from UNINITIALIZED to INITIALIZING
15:06:47.591 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP51' changed from INITIALIZING to ONLINE
15:06:47.703 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP62' changed from UNINITIALIZED to INITIALIZING
15:06:47.735 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP62' changed from INITIALIZING to ONLINE
15:06:47.807 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP59' changed from UNINITIALIZED to INITIALIZING
15:06:47.909 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP59' changed from INITIALIZING to ONLINE
15:06:48.077 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:topic:hsbroker:WatchManThing' changed from UNINITIALIZED to INITIALIZING
15:06:48.101 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP60' changed from UNINITIALIZED to INITIALIZING
15:06:48.301 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:topic:hsbroker:WatchManThing' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)
15:06:48.477 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:socket:WEMO01' changed from UNINITIALIZED to INITIALIZING
15:06:48.511 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:socket:WEMO01' changed from INITIALIZING to ONLINE
15:06:48.623 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:socket:WEMO02' changed from UNINITIALIZED to INITIALIZING
15:06:48.671 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:socket:WEMO02' changed from INITIALIZING to ONLINE
15:06:48.831 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:socket:WEMO09' changed from UNINITIALIZED to INITIALIZING
15:06:48.855 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:socket:WEMO09' changed from INITIALIZING to ONLINE
15:06:49.086 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:socket:WEMO10' changed from UNINITIALIZED to INITIALIZING
15:06:49.328 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:socket:WEMO10' changed from INITIALIZING to ONLINE
15:06:49.728 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:lightswitch:WEMO12' changed from UNINITIALIZED to INITIALIZING
15:06:50.016 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:lightswitch:WEMO12' changed from INITIALIZING to ONLINE
15:06:50.008 [INFO ] [o.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '10.0.0.9' with clientid cd6dc66c-af70-4b51-9490-4bdaa43fbc1d
15:06:50.480 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:lightswitch:WEMO13' changed from UNINITIALIZED to INITIALIZING
15:06:51.370 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:lightswitch:WEMO13' changed from INITIALIZING to ONLINE
15:06:51.402 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:lightswitch:WEMO14' changed from INITIALIZING to ONLINE
15:06:51.498 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:lightswitch:WEMO14' changed from UNINITIALIZED to INITIALIZING
15:06:51.510 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:lightswitch:WEMO15' changed from UNINITIALIZED to INITIALIZING
15:06:51.558 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'wemo:lightswitch:WEMO15' changed from INITIALIZING to ONLINE
15:06:51.566 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP60' changed from INITIALIZING to ONLINE
15:06:51.606 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP52' changed from INITIALIZING to ONLINE
15:06:51.710 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP63' changed from INITIALIZING to ONLINE
15:06:51.718 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP52' changed from UNINITIALIZED to INITIALIZING
15:06:51.734 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP63' changed from UNINITIALIZED to INITIALIZING
15:06:51.750 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP64' changed from UNINITIALIZED to INITIALIZING
15:06:51.822 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP64' changed from INITIALIZING to ONLINE
15:06:51.843 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP65' changed from UNINITIALIZED to INITIALIZING
15:06:51.897 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP65' changed from INITIALIZING to ONLINE
15:06:52.052 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP06' changed from UNINITIALIZED to INITIALIZING
15:06:52.132 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP06' changed from INITIALIZING to ONLINE
15:06:52.188 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP08' changed from UNINITIALIZED to INITIALIZING
15:06:52.222 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP08' changed from INITIALIZING to ONLINE
15:06:52.222 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP09' changed from UNINITIALIZED to INITIALIZING
15:06:52.222 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP09' changed from INITIALIZING to ONLINE
15:06:52.253 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP98' changed from UNINITIALIZED to INITIALIZING
15:06:52.253 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP98' changed from INITIALIZING to ONLINE
15:06:52.317 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP99' changed from UNINITIALIZED to INITIALIZING
15:06:52.338 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'network:pingdevice:IP99' changed from INITIALIZING to ONLINE
15:06:52.418 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:broker:hsbroker' changed from OFFLINE to ONLINE
15:06:52.474 [INFO ] [hab.event.ThingStatusInfoChangedEvent] - Thing 'mqtt:topic:hsbroker:WatchManThing' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
15:07:06.824 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'IP_Robert_2G' changed from ON to OFF
15:07:08.326 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'IP_Peter_2G' changed from ON to OFF
15:07:08.454 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'IP_Janet_5G' changed from ON to OFF
15:07:17.536 [ERROR] [.internal.handler.ScriptActionHandler] - Script execution of rule with UID 'HS5150-3' failed: The name 'GreenFlag' cannot be resolved to an item or type; line 923, column 10, length 9 in HS5150
15:07:17.560 [ERROR] [.internal.handler.ScriptActionHandler] - Script execution of rule with UID 'HS5150-24' failed: The name 'GreenFlag' cannot be resolved to an item or type; line 3656, column 10, length 9 in HS5150
15:07:17.560 [ERROR] [.internal.handler.ScriptActionHandler] - Script execution of rule with UID 'HS5150-7' failed: The name 'GreenFlag' cannot be resolved to an item or type; line 2515, column 10, length 9 in HS5150
15:07:18.048 [ERROR] [.internal.handler.ScriptActionHandler] - Script execution of rule with UID 'HS5150-7' failed: The name 'GreenFlag' cannot be resolved to an item or type; line 2515, column 10, length 9 in HS5150
15:07:17.856 [ERROR] [.internal.handler.ScriptActionHandler] - Script execution of rule with UID 'HS5150-24' failed: The name 'GreenFlag' cannot be resolved to an item or type; line 3656, column 10, length 9 in HS5150
15:07:18.200 [ERROR] [.internal.handler.ScriptActionHandler] - Script execution of rule with UID 'HS5150-7' failed: The name 'GreenFlag' cannot be resolved to an item or type; line 2515, column 10, length 9 in HS5150
15:07:54.837 [INFO ] [openhab.event.ItemStateChangedEvent  ] - Item 'IP_WatchMan' changed from ON to OFF

Do you have any ideas what in the world is happening or what I’m doing wrong?

Thanks

rossko57 · April 3, 2021, 12:33am

I don’t think you’re doing anything wrong. There are race conditions at startup, they’ll be worse for some people more than others depending on system config and host performance. Mostly, but not exclusively, these races will manifest as rules issues. Circumvention is delaying rules execution one way or another.

nyholm · April 3, 2021, 1:10am

I can visualize a way to hold off the initialize rule via use of another rule. Is there any means for me to know when the system is fully initialized? Any variable, property, etc. I can test?

rlkoshak · April 3, 2021, 3:32am

The other is you don’t know which rules will be loaded first.

When people have these sorts of problems usually the workaround ends up being Outside of OH. As I mentioned before, on Linux openHABiann even has an option to move the rules out of the way for a time on startup and move then back after a time. I don’t know if the Window services script is capable of doing the same.

Anything you get to do from oh rules themselves is going to face the previews that your lock rule doesn’t get loaded until later and rules start running when they shouldn’t.

Also, globals hey defined at load time. be The only way to delay that is to prevent the loading of the file.

The only way I can think of to know the start level involves using ui rules. You can define an item to represent the leaf level. it Then define rules in the UI to update that item with a system start level trigger. You do not want to restoreOnStartup that Item.

nyholm · April 5, 2021, 11:39pm

For the benefit of others that are fighting the OH3 startup timing / race issue here is what I found works on my 2 OH3 Windows 10 installations:

.rules
var Number GreenFlag = 0

//01 - StartUp Initializations =====================================================================================================
rule "Startup_Initializations"
	when
		System started
	then
		Thread::sleep(5000)
		Thread::sleep(5000)
		Thread::sleep(5000)
		Thread::sleep(5000)
		Thread::sleep(5000)
		Thread::sleep(5000)
		
		Thread::sleep(5000)
		Thread::sleep(5000)
		Thread::sleep(5000)
		Thread::sleep(5000)
		Thread::sleep(5000)
		Thread::sleep(5000)
		
		Thread::sleep(5000)
		Thread::sleep(5000)
		Thread::sleep(5000)
		Thread::sleep(5000)
		Thread::sleep(5000)
		Thread::sleep(5000)
		
		Thread::sleep(5000)
		Thread::sleep(5000)
		Thread::sleep(5000)
		Thread::sleep(5000)
		Thread::sleep(5000)
		Thread::sleep(5000)

		GreenFlag = 0
	
		logInfo("Startup_Initializations", ">>>>> ENTERED RULE = Startup_Initializations *****************************************************************") 

blah blah blah initialization stuff

		GreenFlag = 1

		Initialized_Time = now.toInstant.toEpochMilli 
		
		Date.postUpdate(new DateTimeType())
		Rule_TimeStamp4SI = Date.state.format("%tD") + " @ " + Date.state.format("%tr")
		
		logInfo("Startup_Initializations", ">>>>> Startup_Initializations GreenFlag set to 1 at " + Rule_TimeStamp4SI)
		
	
	
		logInfo("Startup_Initializations", ">>>>>>>>>>>>> RULE = Startup_Initializations.  FINAL CHECKING mqtt ACTIONS BEFORE PUBLISHING ***************")
		OHOB_WM_String.postUpdate(Rule_TimeStamp4SI + " >" + "\nMsgStamp:0;" + "\n" + "EOS<")
		mqttActions = getActions("mqtt","mqtt:broker:hsbroker")
		logInfo("Startup_Initializations", ">>>>>>>>>>>>> RULE = Startup_Initializations.  mqttActions = " + mqttActions)
		logInfo("Startup_Initializations", ">>>>>>>>>>>>> RULE = Startup_Initializations.  Ready to publish to topic '/WatchMan/OHOB_WM_String'")
		mqttActions.publishMQTT("/WatchMan/OHOB_WM_String", OHOB_WM_String.state.toString)
		logInfo("Startup_Initializations", ">>>>>>>>>>>>> RULE = Startup_Initializations.  mqtt FINAL CHECK WAS A SUCCESS ******************************")


end


rule "Geo_Presence" //=====================================================================================================
when
	Item OHC_Presence_Robert changed or
	Item OHC_Presence_Janet  changed or
	Item OHC_Presence_Peter  changed or
	Item OHC_Presence_Hannah changed or
	Item OHC_Presence_Guest  changed
	
then	if (GreenFlag == 0) return;

blah blah blah

end

I have read many times to avoid sleeping for long periods of time. However, I can find no other way, or anything I can test for in a loop. In fact, I have found the loop counter will fail / error on Startup.

var ii = 1
someSystemCondition = ? // like startup level = 100?
while ((ii=ii+1) < 60) && (someSystemCondition)) {
	Thread::sleep(1000)
	someSystemCondition = ?
}

I found that 12-15 Thread::sleep(5000) usually worked, so I added 100% margin and made it 24. (and I have had it still fail on 1st time launch on a new installation.)

Any parting advice or comments will be appreciated before I close this thread.

…thanks

rossko57 · April 6, 2021, 12:34am

There’s a system cache. Either because it does not hold useful stuff, or because there’s extra work populating it, the timings are less favourable on starts after e.g. upgrade where it gets cleared.

nyholm · April 12, 2021, 4:34pm

After additional restarts I have found that the method above is almost always reliable. On occasion the mail binding is not yet ready. And I have experienced 1 restart where thread could not be resolved.

Can I assume an issue has already been filed for the “Start Up Issue”? If not, how can I file one?.

Much thanks goes to all that helped me.

rlkoshak · April 12, 2021, 4:38pm

Never assume. Search the open issues on openhab-core. See How to file an Issue.

But, as was mentioned and hinted at above, a ton of work has been put into startup. I wouldn’t expect an immediate solution to be implemented, if ever.

Frankly, the fact that you didn’t have problems in OH 2.4 was a fluke. OH 2 has way more startup problems in general than OH 3. So even if you don’t get immediate satisfaction on this realize that it’s not because the devs don’t care. It’s a really hard problem.

system · May 24, 2021, 8:38am

This topic was automatically closed 41 days after the last reply. New replies are no longer allowed.