[SOLVED] Rule when System started executed more than one time

stefaanbolle · January 11, 2017, 9:39am

I have a rule which is being executed when the system is started. However I notice that the rule is executed several times. Therefor a rule depending on this (“system initialisation”) is also fired several times.
A bug? i’m using Beta 5 of OH2 ion a Raspberry Pi3

rule:

rule “System started”
when
System started
then
var Timer waitTimer = null
    logDebug("startup", "Rule System starting started")
Initializing.postUpdate(ON)
SystemStarting.postUpdate(ON)
logDebug(“startup”, "Initializing = " + Initializing.state.toString() + " & SystemStarting = " + Initializing.state.toString())
waitTimer = createTimer(now.plusMinutes(2)) [|
Initializing.postUpdate(OFF)
logDebug(“startup”, "Initializing = " + Initializing.state.toString() + " & SystemStarting = " + Initializing.state.toString())
logDebug(“startup”, “Openhab initialized, all bindings have been loaded. I am ready to sync initial Nikobus states with Vera”)
logDebug(“startup”, “Rule System starting ended”)
]
end

Log:

2017-01-11 10:03:10.536 [INFO ] [ore.internal.i18n.LocaleProviderImpl] - Locale set to en_GB
2017-01-11 10:03:12.586 [INFO ] [rihome.internal.ImperiHomeApiServlet] - Started ImperiHome integration service at /imperihome/iss
2017-01-11 10:03:20.089 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘default.items’
2017-01-11 10:03:22.384 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘logging.persist’
2017-01-11 10:03:22.482 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘mqtt.persist’
2017-01-11 10:03:22.534 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘gcal.persist’
2017-01-11 10:03:22.562 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘rrd4j.persist’
2017-01-11 10:03:22.583 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘mapdb.persist’
2017-01-11 10:03:22.606 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘exec.persist’
2017-01-11 10:03:27.420 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘sync.rules’
2017-01-11 10:03:29.517 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘automation.rules’
2017-01-11 10:03:29.713 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘tts.rules’
2017-01-11 10:03:29.757 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘startup.rules’
2017-01-11 10:03:33.727 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘default.sitemap’
2017-01-11 10:03:36.353 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model ‘default.things’
2017-01-11 10:03:42.148 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at /start
2017-01-11 10:03:42.428 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /ui
2017-01-11 10:03:45.119 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-01-11 10:03:45.638 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2017-01-11 10:03:46.012 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2017-01-11 10:03:51.458 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro job-daily-sun at midnight for thing astro:sun:local
2017-01-11 10:03:51.459 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro job-daily-moon at midnight for thing astro:moon:local
2017-01-11 10:03:51.507 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro job-positional with interval of 60 seconds for thing astro:moon:local
2017-01-11 10:03:51.508 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro job-positional with interval of 60 seconds for thing astro:sun:local
2017-01-11 10:04:21.615 [DEBUG] [lipse.smarthome.model.script.startup] - Rule System starting started
2017-01-11 10:04:21.651 [DEBUG] [lipse.smarthome.model.script.startup] - Initializing = ON & SystemStarting = ON
2017-01-11 10:04:23.603 [INFO ] [.astro.internal.job.AbstractDailyJob] - Scheduled astro event-jobs for thing astro:moon:local
2017-01-11 10:04:23.620 [INFO ] [.astro.internal.job.AbstractDailyJob] - Scheduled astro event-jobs for thing astro:sun:local
2017-01-11 10:04:26.498 [INFO ] [b.core.service.AbstractActiveService] - HTTP Refresh Service has been started
2017-01-11 10:04:27.213 [INFO ] [kobus.internal.core.NikobusInterface] - Connected to serial port ‘/dev/ttyUSB0’
2017-01-11 10:04:27.422 [INFO ] [kobus.internal.core.NikobusInterface] - Connected to Nikobus
2017-01-11 10:04:27.469 [ERROR] [platform.linux.LinuxCentralProcessor] - Couldn’t find physical processor count. Assuming 1.
2017-01-11 10:04:29.139 [INFO ] [ternal.scheduler.WeatherJobScheduler] - Starting and scheduling weatherJob-Brussel with interval of 60 minutes
2017-01-11 10:04:29.724 [INFO ] [b.core.service.AbstractActiveService] - Google Calender Event-Downloader has been started
2017-01-11 10:04:29.734 [INFO ] [penhab.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
2017-01-11 10:04:29.746 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection ‘server’
2017-01-11 10:04:31.093 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber ‘org.eclipse.smarthome.core.thing.link.ThingLinkManager@1cfa0aa’ takes more than 5000ms.
2017-01-11 10:04:35.225 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber ‘org.eclipse.smarthome.core.thing.link.ThingLinkManager@1cfa0aa’ takes more than 5000ms.
2017-01-11 10:04:40.556 [WARN ] [ore.internal.events.OSGiEventManager] - Dispatching event to subscriber ‘org.eclipse.smarthome.core.thing.link.ThingLinkManager@1cfa0aa’ takes more than 5000ms.
2017-01-11 10:05:39.656 [DEBUG] [lipse.smarthome.model.script.startup] - Rule System starting started
2017-01-11 10:05:39.744 [DEBUG] [lipse.smarthome.model.script.startup] - Initializing = ON & SystemStarting = ON
2017-01-11 10:06:24.027 [DEBUG] [lipse.smarthome.model.script.startup] - Initializing = OFF & SystemStarting = OFF
2017-01-11 10:06:24.039 [DEBUG] [lipse.smarthome.model.script.startup] - Openhab initialized, all bindings have been loaded. I am ready to sync initial Nikobus states with Vera
2017-01-11 10:06:24.043 [DEBUG] [lipse.smarthome.model.script.startup] - Rule System starting ended
2017-01-11 10:06:52.845 [DEBUG] [lipse.smarthome.model.script.startup] - Rule System starting started
2017-01-11 10:06:52.882 [DEBUG] [lipse.smarthome.model.script.startup] - Rule System initialisation started
2017-01-11 10:06:52.888 [DEBUG] [lipse.smarthome.model.script.startup] - Initializing = ON & SystemStarting = ON
2017-01-11 10:06:52.920 [DEBUG] [lipse.smarthome.model.script.startup] - Initializing = ON & SystemStarting = ON
2017-01-11 10:06:58.461 [DEBUG] [lipse.smarthome.model.script.startup] - Rule System initialisation ended
2017-01-11 10:06:58.464 [DEBUG] [lipse.smarthome.model.script.startup] - Systeem is gereed!
2017-01-11 10:07:13.469 [DEBUG] [lipse.smarthome.model.script.startup] - Initializing = ON & SystemStarting = ON
2017-01-11 10:07:13.488 [DEBUG] [lipse.smarthome.model.script.startup] - LichtenUit = OFF & LichtenAan = OFF & Sfeerlicht = OFF
2017-01-11 10:07:39.770 [DEBUG] [lipse.smarthome.model.script.startup] - Initializing = OFF & SystemStarting = OFF
2017-01-11 10:07:39.773 [DEBUG] [lipse.smarthome.model.script.startup] - Openhab initialized, all bindings have been loaded. I am ready to sync initial Nikobus states with Vera
2017-01-11 10:07:39.776 [DEBUG] [lipse.smarthome.model.script.startup] - Rule System starting ended
2017-01-11 10:07:39.782 [DEBUG] [lipse.smarthome.model.script.startup] - Rule System initialisation started
2017-01-11 10:07:39.793 [DEBUG] [lipse.smarthome.model.script.startup] - Initializing = OFF & SystemStarting = OFF
2017-01-11 10:07:44.657 [DEBUG] [lipse.smarthome.model.script.startup] - Rule System initialisation ended
2017-01-11 10:07:44.661 [DEBUG] [lipse.smarthome.model.script.startup] - Systeem is gereed!
2017-01-11 10:07:59.678 [DEBUG] [lipse.smarthome.model.script.startup] - Initializing = OFF & SystemStarting = OFF
2017-01-11 10:07:59.690 [DEBUG] [lipse.smarthome.model.script.startup] - LichtenUit = OFF & LichtenAan = OFF & Sfeerlicht = OFF
2017-01-11 10:08:52.913 [DEBUG] [lipse.smarthome.model.script.startup] - Initializing = OFF & SystemStarting = OFF
2017-01-11 10:08:52.918 [DEBUG] [lipse.smarthome.model.script.startup] - Openhab initialized, all bindings have been loaded. I am ready to sync initial Nikobus states with Vera
2017-01-11 10:08:52.922 [DEBUG] [lipse.smarthome.model.script.startup] - Rule System starting ended

stefaanbolle · January 11, 2017, 1:15pm

Appeared to be a known issue in OH2B5.
Upgraded to unstable track and in the latest version (2.0.0-SNAPSHOT Build #683) this seems to be resolved.

Frasier · January 11, 2017, 9:31pm

Hi!
I’m running 2.0.0-SNAPSHOT Build #685 and I can also confirm that the rule fires several times. Or in my case the code is running two times.

I took your code as I thought it seems healthy to wait until the startup is complete before running rules and so on.

stefaanbolle · January 12, 2017, 9:19am

The rules do run now, but I notice that they don’t care about some item states in the if call
Below rule does what it has to do, but it doesn’t care about the state of both LPhal items.
If LPhalbeneden is ON and/or LPhalboven is ON the rule still executes

rule “Turn on stair leds for 45 seconds when motion is detected”
when
Item DetectornachthalTripped changed from CLOSED to OPEN or
Item DetectorInkomTripped changed from CLOSED to OPEN
then
var ReentrantLock lock = new ReentrantLock()
var Timer waitFor = null

lock.lock()
try {
if ((DayorNightStatus.state.toString()==“0”) && (SystemStarting.state == OFF) && (LPledtrap.state != ON) && (LPhalboven.state != ON) && (LPhalbeneden.state != ON)) {
logDebug(“scene”, "LPledtrap = " + LPledtrap.state.toString() + " & LPhalboven = " + LPhalboven.state.toString() + " & LPhalbeneden = " + LPhalbeneden.state.toString())
logDebug(“scene”, “Rule Turn on stair leds for 45 seconds when motion is detected started”)
if (waitFor!=null) {
logDebug(“scene”,“Timer waitTime cancelled”)
waitFor.cancel()
}
BP_hal_trap_aan.sendCommand(ON)
logDebug(“scene”, “Turn on leds trap when motion is detected”)
waitFor = createTimer(now.plusSeconds(45)) [|
BP_hal_trap_uit.sendCommand(ON)
logDebug(“scene”, “Automatically turn off leds trap after 45 seconds”)
logDebug(“scene”, "LPledtrap = " + LPledtrap.state.toString() + " & LPhalboven = " + LPhalboven.state.toString() + " & LPhalbeneden = " + LPhalbeneden.state.toString())logDebug(“scene”, “Rule Turn on stair leds for 45 seconds when motion is detected ended”) ]
}
} finally{
lock.unlock()
}
end

Since I am on the snapshot version, feeback of Nikobus buttons is now not working anymore (it did work with beta5, but there the rules at startup have issues )

andirs · June 26, 2017, 4:26pm

Since it suits to this topic I’ll append to this one:
My only rule that triggers when the system is started also fires several times:

rule "autostart"
	when 
		System started
	then
		Thread::sleep(5000) // delay a little to let persited data load
// some stuff, nothing special
		logInfo("System","System started...")
end

The log shows the “System started” message now and then, not only ~10s after the first start, but also at other times. And why is the sleep interrupted? This lead to problems since some items then can not be resolved

2017-06-26 17:00:56.288 [ERROR] [.script.engine.ScriptExecutionThread] - Rule 'Update_String_PresenceAndi': An error occurred during the script execution: The name 'ON' cannot be resolved to an item or type.

2017-06-26 17:00:59.651 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Error during the execution of startup rule 'autostart': sleep interrupted

2017-06-26 17:01:00.281 [INFO ] [clipse.smarthome.model.script.System] - System started...

2017-06-26 17:01:11.906 [INFO ] [clipse.smarthome.model.script.System] - System started...

I am on openHAB 2.1.0 Build #967

stefaanbolle · June 26, 2017, 5:58pm

Some time ago I did a complete reinstall. The rules are fine now.
Adding and removing a lot to the config does have an impact on stability. Rules are quite sensitive to editing.
Now all runs fine.

wawa79 · September 18, 2018, 3:55pm

Same issue here.

I use a boolean variable to avoid triggering more than once:
var systemStarted = new Boolean(false)

rule "Notify OpenHAB started"
when
	System started 
then
    if(! systemStarted){
        systemStarted = true
        //here my code that should be only triggered once at startup
    }
end

It is quite worrying to realize how unstable the rule engine is.

andrelung · September 21, 2018, 5:52pm

The same happened on my installation. Not sure if it is a coincidence, but the rule triggered 7 times, while there are 7 rules in the containing .rules file.
I am running the latest stable (2.3.0-1).

smhgit · October 5, 2018, 6:52am

Also happen to me, openhabian, 2.3.0, build release.

zonegrise · December 25, 2018, 7:11pm

Happen as well with 2.4 stable

habpower · January 11, 2020, 2:15pm

I can confirm that this issue occurs still on 2.5 stable!

OMR · February 15, 2020, 9:08pm

Bug in 2.5.1 release as well. Simple work-around:

Since all items have a state value of NULL at system start:

.items file
Switch vwallswitchOnce

.rules file
rule "WallSwitch: System started"
when
    System started
then
    if (vwallswitchOnce.state == NULL) {
      postUpdate(vwallswitchOnce, ON)
      logInfo("info", "(wallswitch.rules) Loaded model ...")
    }
end