Startup error for all cron based rules

All, I again spent some time to dig into this and I think I solved it.
The issue seemed to be a concurrency issue that caused rules to be scheduled at startup and at the same time reloaded (because new items or rule actions appeared) and thus rescheduled again.
I have implemented multiple improvements that all address this issue at the same time: https://github.com/eclipse/smarthome/pull/2480

I hope that this can be merged soon and it then should become available in the openHAB distro this weekend. Watch out for news on https://community.openhab.org/c/openhab-2/news-important-changes, where I will post once it has made it in the distro.

5 Likes

Many thanks for the assistance, looking forward to the update. Also there is something in the rules engine making updating of some variables erratic but I have not looked this up in the threads, might already be taken care of. It is anyhow an item for another thread (I think). Same here, works beautifully on 1.8.3 but erratic on 2.0b4.

Ok, I pushed the changed from ESH to openHAB 2 today and as there isn’t that much worth to mention besides the CRON issue, I refrain from doing any annoucement on https://community.openhab.org/c/openhab-2/news-important-changes, but only inform you guys here: All my fixes are now available in the latest distro #595 and a brief test didn’t show me any issues with it.

Now it is your turn: Please go and test and report back your results! Thanks :slight_smile:

Kia Ora Kai

Many thanks, that seems to have fixed the cron rule errors.

Kia kaha Wayne

The startup error has been removed, but for some reason the rules appear to run multiple times e.g. rule

   Time cron "0 * * * * ?"

runs once a minute but each minute runs the code more than once (often 3 times) very quickly. I have a tag inside the code which is increment each time run and this increments by up to 3 each minute.

If you edit the rule, then it resets it and runs correctly. If I restart openhab or reboot raspberry pi, then it runs multiple times each minute.

Hm, I cannot reproduce this behavior… Could you do a

log:set DEBUG org.eclipse.smarthome.model.rule

on your console, then do a restart and provide me the logs of that start? This should help analysing what is happening exactly.

Hi Kai

I have attached the log file and with some comments added.

Regards

Wayne

Incidentally Kai in NZ Maori = food e.g moana = the sea. Kai moana = seafoodopenhab.log.pdf (85.3 KB)

Sorry for the delay, I am just downloading #596 (presumably all changes are also included here) and will install it and report tomorrow.

I installed the #597 this morning and can confirm that the cron errors previously showing up in the logs are gone. The new installation has been running just a short while now so will monitor the logs and revert if anything similar comes up.

Hi all,

so far as I understood I have to simply download the last snapshot, replace all (?) folder of my already installed version to solve this problem? I’ve installed the beta4 Version with apt-get repo.

Thanks a lot! :slight_smile:

EDIT:
Ah, I think I should use that procedure then

FTR, This is now tracked at https://github.com/eclipse/smarthome/issues/2545 - so far without any reproducible scenario. @WayneStronach, maybe you can provide (a simple, minimal) one on the issue?

I also get this error multiple times in my log at startup, but also occasional hours after OpenHab was started. I hope you find a solution for this.

You replied to a thread that is old and that is referring to an Issue believed to be solved and closed. Could you post the error you see and the code of the relating rule? Additionally please state the OH version you are using.

I’ve just got the error again multiple times after the start. (Using OH 2.2 release on OpenHabian) Here is the error:

2017-12-27 20:51:22.270 [ERROR] [model.script.actions.ScriptExecution] - Failed to schedule code for execution.
org.quartz.ObjectAlreadyExistsException: Unable to store Job : 'DEFAULT.2017-12-27T20:52:22.264+01:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  <XFeatureCallImplCustom>.postUpdate(<XFeatureCallImplCustom>)
} ]', because one already exists with this identification.
	at org.quartz.simpl.RAMJobStore.storeJob(RAMJobStore.java:279) ~[?:?]
	at org.quartz.simpl.RAMJobStore.storeJobAndTrigger(RAMJobStore.java:251) ~[?:?]
	at org.quartz.core.QuartzScheduler.scheduleJob(QuartzScheduler.java:886) ~[?:?]
	at org.quartz.impl.StdScheduler.scheduleJob(StdScheduler.java:249) ~[?:?]
	at org.eclipse.smarthome.model.script.actions.ScriptExecution.makeTimer(ScriptExecution.java:133) ~[?:?]
	at org.eclipse.smarthome.model.script.actions.ScriptExecution.createTimer(ScriptExecution.java:92) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1085) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1060) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1046) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeFeature(XbaseInterpreter.java:991) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:141) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:901) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:864) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:223) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:215) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:203) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:446) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:227) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:215) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:203) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:189) ~[?:?]
	at org.eclipse.smarthome.model.script.runtime.internal.engine.ScriptImpl.execute(ScriptImpl.java:82) ~[?:?]
	at org.eclipse.smarthome.model.rule.runtime.internal.engine.RuleEngineImpl.lambda$2(RuleEngineImpl.java:343) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]

I suppose this means there is a problem with a cron job in the default.rules file. (I got muliple rule files)

In the default.rules file I have 11 rules, but they are all item based. So there is not a single cron based rule in this file. Any idea what could cause this error?

I’m not sure about the “Default” . My guess this word does not relate to your Default.rules file.
Do you have any cron-triggered rules. If yes,please post the code and/or check the logs if one of them has been loaded twice (without deleting it).

I’m not exactly sure how I should check if the cron-triggered rules are loaded twice. Could you please explain this? Here is the code of all my cron triggered rules:

rule "Daily Doorbird motion events"
	when
	    Time cron "0 0 0 * * ?"
	then
		var int counter = (NUM_Entrance_DoorBird_MotionEventCounterDaily.state as DecimalType).intValue
		//logError("Daily Doorbird motion events", counter.toString())
		NUM_Entrance_DoorBird_MotionEventsDaily.postUpdate(counter)
		NUM_Entrance_DoorBird_MotionEventCounterDaily.postUpdate(0)
	end
	
rule "Hourly Doorbird motion events"
	when
	    Time cron "0 0 * * * ?"
	then
		var int counter = (NUM_Entrance_DoorBird_MotionEventCounterHourly.state as DecimalType).intValue
		//logError("Hourly Doorbird motion events", counter.toString())
		NUM_Entrance_DoorBird_MotionEventsHourly.postUpdate(counter)
		NUM_Entrance_DoorBird_MotionEventCounterHourly.postUpdate(0)
	end
	
rule "Fire indicator check"
	when
		Time cron "0 0 17 * * ?"
	then
		var DateTime checkDateTime = now.minusDays(1)
		
		var sb = new StringBuilder
		var String strDateTimeFormat = "yyyy-MM-dd'T'HH:mm:ssz"

		var DateTime lastPacketReceived = getZwaveLastPacketReceived.apply("zwave:device:4c0da5c0:node28")
		DT_ZWAVE_FireIND_1_LastUpdate.postUpdate(lastPacketReceived.toString(strDateTimeFormat))
		//var String checkResult = checkStateIsBefore.apply(DT_ZWAVE_FireIND_1_LastUpdate, lastPacketReceived, checkDateTime) as String
		if (lastPacketReceived.isBefore(checkDateTime)) {
  			sb.append(String::format("PC Zimmer David: %s\n", lastPacketReceived.toString(strDateTimeFormat)))
		}

		lastPacketReceived = getZwaveLastPacketReceived.apply("zwave:device:4c0da5c0:node12")
		DT_ZWAVE_FireIND_2_LastUpdate.postUpdate(lastPacketReceived.toString(strDateTimeFormat))
		//checkResult = checkStateIsBefore.apply(DT_ZWAVE_FireIND_2_LastUpdate, lastPacketReceived, checkDateTime) as String
		if (lastPacketReceived.isBefore(checkDateTime)) {
  			sb.append(String::format("Keller: %s\n", lastPacketReceived.toString(strDateTimeFormat)))
		}
		
		lastPacketReceived = getZwaveLastPacketReceived.apply("zwave:device:4c0da5c0:node44")
		DT_ZWAVE_FireIND_4_LastUpdate.postUpdate(lastPacketReceived.toString(strDateTimeFormat))
		//checkResult = checkStateIsBefore.apply(DT_ZWAVE_FireIND_4_LastUpdate, lastPacketReceived, checkDateTime) as String
		if (lastPacketReceived.isBefore(checkDateTime)) {
  			sb.append(String::format("1. Stock: %s\n", lastPacketReceived.toString(strDateTimeFormat)))
		}
		
		lastPacketReceived = getZwaveLastPacketReceived.apply("zwave:device:4c0da5c0:node43")
		DT_ZWAVE_FireIND_3_LastUpdate.postUpdate(lastPacketReceived.toString(strDateTimeFormat))
		//checkResult = checkStateIsBefore.apply(DT_ZWAVE_FireIND_3_LastUpdate, lastPacketReceived, checkDateTime) as String
		if (lastPacketReceived.isBefore(checkDateTime)) {
  			sb.append(String::format("2. Stock: %s\n", lastPacketReceived.toString(strDateTimeFormat)))
		}
		
		if (sb.length > 0) {
			var String message = String::format("Rauchmelder Haus 75 sind offline:\n\n%s", sb.toString())
			sendMail("test@test.com", "Rauchmelder Haus 75 offline", message)
		}
end

rule "Target temperature"
	when
		Item SW_Bedroom_Sleep changed or
	    Item SW_Presence_David_Phone_Home changed or
	    Item SW_Presence_David_Phone_Work changed or
	    Item SW_Living_Manual_Temperature changed or
	    Item NUM_Living_Manual_Temperature changed or
	    Time cron "0 0 18 ? * MON-FRI"
	then
		var Number temp = 19
		var Number hour = now.getHourOfDay()
		
		//logError("Target temperature", "Rule triggered hour: " + hour.toString())
		
		if (SW_Living_Manual_Temperature.state == ON) {
			temp = NUM_Living_Manual_Temperature.state as DecimalType
		} else if (SW_Bedroom_Sleep.state == ON) {
			temp = 19.75
		} else if(SW_Presence_David_Phone_Home.state == ON) {
	        temp = 20.5
	   	} else if(SW_Presence_David_Phone_Work.state == ON && hour >= 18) {
	   		temp = 20.5
	    }
	    
	    if (NUM_Living_Target_Temperature.state == NULL) {
	        NUM_Living_Target_Temperature.postUpdate(19)
	    }
	    
	    var Number currentTemp = NUM_Living_Target_Temperature.state as DecimalType
	    
	    if (currentTemp != temp) {
	    	NUM_Living_Target_Temperature.postUpdate(temp)
	    	//logError("Target temperature", "Target temperature set to: " + temp.toString)
	    }
end

rule "Heat alert"
	when
		Time cron "0 0,30 * * * ?"
	then
		if (NUM_OneWire_Living_Temperature.state instanceof DecimalType) {
			var Number currentTemp = NUM_OneWire_Living_Temperature.state as DecimalType

			if (NUM_Living_Target_Temperature.state instanceof DecimalType) {
				var Number targetTemp = NUM_Living_Target_Temperature.state as DecimalType
				
				if(currentTemp <= 17 && SW_ZWAVE_Living_Heating.state == ON) {
					var String message = String::format("Die Heitzung scheint nicht mehr zu funktionieren. Es sind %.3f °C. Zieltemperatur ist %.3f °C.", currentTemp.floatValue, targetTemp.floatValue)
					sendMail("test@test.com", "!!!HEITZUNGSALARM HAUS 75!!!", message)
				} else if (currentTemp >= 22 && SW_ZWAVE_Living_Heating.state == ON) {
					var String message = String::format("Die Heitzung läuft zu lange. Es sind %.3f °C. Zieltemperatur ist %.3f °C.", currentTemp.floatValue, targetTemp.floatValue)
					sendMail("test@test.comh", "!!!HEITZUNGSALARM HAUS 75!!!", message)
				}
			} else {
				var String message = String::format("Achtung die Zieltemperatur ist nicht initialisiert. Es sind %.3f °C.", currentTemp.floatValue)
				sendMail("test@test.com", "!!!HEITZUNGSALARM HAUS 75!!!", message)
			}
		}
end

rule "Lights cellar"
	when
	    Time cron "0 0,15,30,45 * * * ?"
	then
		var Number LuminanceAverage = NUM_ZWAVE_Cellar_Luminance.averageSince(now.minusMinutes(15), "rrd4j") as Number
		var State MotionMaximum = SW_ZWAVE_Cellar_Motion.maximumSince(now.minusMinutes(15), "rrd4j").state
		
		//logError("Lights.cellar", String::format("Helligkeit %s, Bewegungssensor %s", LuminanceAverage, MotionMaximum))
		
		if (MotionMaximum == OFF && LuminanceAverage > 25) {
			var String message = String::format("Licht im Keller läuft noch (Helligkeit %.3f, Bewegungssensor %s)", LuminanceAverage.floatValue, MotionMaximum)
			sendMail("test@test.com", "!!!Keller Licht!!!", message)
		}
	end

rule "UPS Pico"
	when
		Time cron "0 * * * * ?" or
		Item SW_System_Pico_Active received update
	then
		if (SW_System_Pico_Active.state == ON)
		{
			var String strOutput = executeCommandLine("/usr/bin/python /etc/openhab2/scripts/pico.py", 5000)
			var strSplit = strOutput.split("\\|")
			
			//logError("UPS Pico output", strOutput)
			
			if (strSplit.size == 3) {
				var Number numTemp = new DecimalType(strSplit.get(0))
				//if (NUM_System_Pico_Temp.state != numTemp)
				NUM_System_Pico_Temp.postUpdate(numTemp)
				
				var Number numBattery = new DecimalType(strSplit.get(1))
				//if (NUM_System_Pico_Battery.state != numBattery)
				NUM_System_Pico_Battery.postUpdate(numBattery)
				
				var String strPower = strSplit.get(2)
				//if (ST_System_Pico_Power.state != strPower)
				ST_System_Pico_Power.postUpdate(strPower)
			}
		}
end

rule "Z-Wave CAN hourly"
	when
		Time cron "0 0 * * * ?"
	then
		if (NUM_ZWAVE_Info_CAN.state != NULL)
        {
        	var Number numCan = NUM_ZWAVE_Info_CAN.state as Number
            var Number numCanLast = 0

            if (NUM_ZWAVE_Info_CAN_Last.state != NULL)
            {
 	           numCanLast = NUM_ZWAVE_Info_CAN_Last.state as Number
            }

            NUM_ZWAVE_Info_CAN_Hourly.postUpdate(numCan - numCanLast)
            NUM_ZWAVE_Info_CAN_Last.postUpdate(numCan)
		}
end

rule "Memory check"
	when
		Time cron "0 0 17 * * ?"
	then
		if (NUM_System_Memory_Available_Percent.state != NULL)
        {
        	var Number numMemoryAvailable = NUM_System_Memory_Available_Percent.state as Number

            if (numMemoryAvailable <= 15)
            {
 	           sendMail("test@test.com", "Memoryauslastung Openhabian01", String::format("Memory frei: %s%%", numMemoryAvailable))
            }
		}
end

rule "Battery alert"
	when
		Time cron "0 0 16 * * ?"
	then
		val sb = new StringBuilder
		
		G_All.allMembers.filter(d | d.state instanceof Number && d.name.endsWith("_Battery")).forEach[ batteryItem |
        	val Number numBattery = batteryItem.state as Number
        	if (numBattery < 15)
        	{
        		sb.append(String::format("Item: %s Batteriestand: %s\n", batteryItem.name, numBattery))
        	}
        ]
        
        //logError("Battery alert", sb.length.toString())
        
        if (sb.length > 0) {
			var String message = String::format("Folgende Batterien sind bald leer:\n\n%s", sb.toString())
			sendMail("test@test.com", "Alarm Batteriestand", message)
		}
end

In the logs (either openhab or events.log, not sure on that) you will see an entry for every rules file that is loaded. Probably also for each cron trigger. In the cases that were observed earlier, the files were reported twice to be loaded during startup.

I’ve checked the openhab.log, but every rules file seams to be loaded only once.

Hi opus, I’ve now completeley reinstalled my Openhabian installation, but I still get this error. Any ideas what could cause this?

What are the actual error?
Do all rules have different names?