(OH2) Timer error in log, Rule seems to work

[narf27 (Peter)]

Hello!
i have found various irrigation rules on this forum and on other sites and wrote (tried to adapt various examples) the following rule:

var Timer BW_Auto_Timer = null
var Timer BW_Z1_Timer  = null
var Timer BW_Z2_StartTimer  = null
var Timer BW_Z2_StopTimer  = null

/* Bewässerung */

rule "Bewässerung Neu"
when
	Item TestBewaesserung received command ON
then

	// Tag aktiviert?
	if (gWTWasser.members.filter(w | w.name=="WT_"+now.getDayOfWeek.toString && w.state==ON).size==0) {
		logInfo("Garten","keine Bewässerung, Wochentag deaktiviert")
		return
	}
	
	// Niederschlag?
	var Number Niederschlag = (Niederschlag_WSK.state as DecimalType) + (Niederschlag_WSK_24h.state as DecimalType)
	if (Niederschlag > 4) {
		logInfo("Garten","keine Bewässerung, Summe Niederschlag = " + Niederschlag)
		return
	}
	
	var DateTime startTime
	var DateTime endTime

	val LZ1 = (BW_Auto_LZ1.state as DecimalType).intValue
	val LZ2 = (BW_Auto_LZ2.state as DecimalType).intValue
	
	if (LZ1 > 0) {
		endTime = now.plusMinutes(LZ1)
		// var String tmpZ1 = endTime.state.format("%1$td.%1$tm %1$tH:%1$tM") this does not work...
		BW_Z1.sendCommand(ON)
		BW_Z1_state.postUpdate(ON)
		logInfo("Garten","Zone 1 wird bis " + endTime + " bewässert")
		
		BW_Z1_Timer = createTimer(endTime) [|
		BW_Z1.sendCommand(OFF)
		BW_Z1_state.postUpdate(OFF)
		BW_Z1_LastRun.postUpdate(new DateTimeType())
		logInfo("Garten","Bewässerung Zone 1 abgeschlossen")
		]
		
		startTime = endTime.plusMinutes(1)
		logInfo("Garten", startTime + " = Start Zone 2")
	}
	
		if (LZ2 > 0) {
		endTime = startTime.plusMinutes(LZ2)
		BW_Z2_StartTimer = createTimer(startTime) [|
		BW_Z2.sendCommand(ON)
		BW_Z2_state.postUpdate(ON)
		logInfo("Garten","Zone 2 wird bis " + endTime + " bewässert")
		]

		BW_Z2_StopTimer = createTimer(endTime) [|
		BW_Z2.sendCommand(OFF)
		BW_Z2_state.postUpdate(OFF)
		BW_Z2_LastRun.postUpdate(new DateTimeType())
		logInfo("Garten","Bewässerung Zone 2 abgeschlossen")
		TestBewaesserung.postUpdate(OFF)
		]
	}

end

rule "Bewässerung Abbrechen" // abort Timers
	when 
		Item TestBewaesserung received command OFF
	then
		// Beregnung abbrechen, wenn sie gestartet wurde 
     	if (BW_Z1_Timer !== null) {
       		    BW_Z1_Timer.cancel
        	    BW_Z1_Timer = null
        	    logInfo("Garten", "Zone 1 Bewässerung deaktiviert")
    	}
    	
    	if  (BW_Z2_StartTimer !== null) {
       		    BW_Z2_StartTimer.cancel
        	    BW_Z2_StartTimer = null
        	    logInfo("Garten", "Zone 2 Bewässerung deaktiviert")
    	}
    	
     	if  (BW_Z2_StopTimer !== null) {
       		    BW_Z2_StopTimer.cancel
        	    BW_Z2_StopTimer = null
            	}

        if 	(BW_Z1.state == ON) {
				BW_Z1.sendCommand(OFF)
		}

		if 	(BW_Z2.state == ON) {
				BW_Z2.sendCommand(OFF)
		}
        
end

both rules seem to work, but after several minutes i get a ton of these errors:

2021-03-26 13:36:57.070 [ERROR] [org.quartz.core.JobRunShell         ] - Job DEFAULT.Timer 27 2021-03-26T13:36:57.068+01:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {	
  sendCommand(<XFeatureCallImplCustom>,<XFeatureCallImplCustom>)	
} ] threw an unhandled Exception: 	
java.lang.NullPointerException: null	
	at org.eclipse.smarthome.model.script.engine.ScriptError.<init>(ScriptError.java:65) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:140) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:991) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:954) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:235) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:215) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluateArgumentExpressions(XbaseInterpreter.java:1205) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1135) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeFeature(XbaseInterpreter.java:1081) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:151) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:991) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:954) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:235) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:215) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:458) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:239) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:215) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:201) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.ClosureInvocationHandler.doInvoke(ClosureInvocationHandler.java:46) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.AbstractClosureInvocationHandler.invoke(AbstractClosureInvocationHandler.java:29) ~[?:?]
	at com.sun.proxy.$Proxy534.apply(Unknown Source) ~[?:?]
	at org.eclipse.smarthome.model.script.internal.actions.TimerExecutionJob.execute(TimerExecutionJob.java:48) ~[?:?]
	at org.quartz.core.JobRunShell.run(JobRunShell.java:202) [bundleFile:?]
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [bundleFile:?]
2021-03-26 13:36:57.101 [ERROR] [org.quartz.core.ErrorLogger         ] - Job (DEFAULT.Timer 27 2021-03-26T13:36:57.068+01:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {	
  sendCommand(<XFeatureCallImplCustom>,<XFeatureCallImplCustom>)	
} ] threw an exception.	
org.quartz.SchedulerException: Job threw an unhandled exception.	
	at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [bundleFile:?]
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [bundleFile:?]
Caused by: java.lang.NullPointerException	
	at org.eclipse.smarthome.model.script.engine.ScriptError.<init>(ScriptError.java:65) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:140) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:991) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:954) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:235) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:215) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluateArgumentExpressions(XbaseInterpreter.java:1205) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1135) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeFeature(XbaseInterpreter.java:1081) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:151) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:991) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:954) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:235) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:215) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:458) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:239) ~[?:?]
	at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:215) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:201) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.ClosureInvocationHandler.doInvoke(ClosureInvocationHandler.java:46) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.AbstractClosureInvocationHandler.invoke(AbstractClosureInvocationHandler.java:29) ~[?:?]
	at com.sun.proxy.$Proxy534.apply(Unknown Source) ~[?:?]
	at org.eclipse.smarthome.model.script.internal.actions.TimerExecutionJob.execute(TimerExecutionJob.java:48) ~[?:?]
	at org.quartz.core.JobRunShell.run(JobRunShell.java:202) ~[?:?]
	... 1 more

i don’t understand what started “Job DEFAULT.Timer 27” and i don’t understand at all what this error means.

i’ve been looking for related threads on this problem but i still don’t have the slightest idea whats happening.

any help would be appreciated!

[rossko57]

@narf27

i don’t understand what started “Job DEFAULT.Timer 27”

You did, or rather your rule did. When you use createTimer() you are scheduling an independent job for the future.

@narf27

i don’t understand at all what this error means.

Because timers are fully independent of the rule that spawned them, the error messaging is always a bit vague.
You do get a sort of skeleton of the timer code processed so far - so in the error you show us, it’s fallen down trying to do something to do with sendCommand.
That doesn’t help us a great deal here, as all your timer code blocks begin with a sendCommand.

The actual error - something was unexpectedly null - is fairly universal for a timer error, once you get over basic syntax errors.

I’m going to make a guess that these are fairly long-running timers, and that you have been editing your new rules while setting them up and testing.
You need to bear the “orphaned timer” effect in mind as the most likely culprit here -

[SOLVED] Unhandled Exception w/o active rules

That looks like the sort of report you get from orphaned Timers - typically, a long running timer was spawned by a rule, and the rule file was later edited on other business. When the rule file reloads, the context for the waiting timer is destroyed - but the quartz scheduled timer job is not. Maybe hours later, the now “orphaned” timer code executes and usually fails with a NullPointerException because some variable it references no longer exists.

But you should also consider
BW_Z2_StartTimer = createTimer(startTime) [| ...
the timer does NOT “live” in the variable BW_Z2_StartTimer, it’s fully independent remember.
The variable just holds a pointer or handle for the timer proper. So you could come along later and rewrite that variable with something else, that will not affect the previously linked timer which will still run at the appointed time.
One way to do that is to run the rule containing
BW_Z2_StartTimer = createTimer(startTime) [| ...
again, making a new timer linked to the handle variable, but not stopping the previous one.
Your rule is able to do that, so be careful.

The way to avoid that is to write the rule so that it examines the handle variable first, to find out if there is an existing timer. It can then decide to reschedule or cancel it.
This way to work is the whole point of setting the handle variable to null after you really have executed or cancelled the timer.

[narf27 (Peter)]

@rossko57

You did, or rather your rule did. When you use createTimer() you are scheduling an independent job for the future.

Yes , sure…
but i don’t understand what piece of my code started the timer with number 27 (errors have different numbers). it’s probably not possible to check what number a timer i appointed to, is it?

@rossko57

I’m going to make a guess that these are fairly long-running timers, and that you have been editing your new rules while setting them up and testing.

good guess

@rossko57

You need to bear the “orphaned timer” effect in mind as the most likely culprit here -

ok, i didn’t have any more erros since my opening post, i’ll try again with the first rule from my code…

@rossko57

This way to work is the whole point of setting the handle variable to null after you really have executed or cancelled the timer.

isn’t the variable set to null after when the timer “expires”? within my first rule i don’t set the timers to null, only in the second rule (abort) the variables are canceled and set to null…
so…
should i set the variable to null also in the first rule?

f.e. last line in thsi piece of code:

		BW_Z1_Timer = createTimer(endTime) [|
		BW_Z1.sendCommand(OFF)
		BW_Z1_state.postUpdate(OFF)
		BW_Z1_LastRun.postUpdate(new DateTimeType())
		logInfo("Garten","Bewässerung Zone 1 abgeschlossen")
		BW_Z1_Timer = null

?

[rossko57]

@narf27

it’s probably not possible to check what number a timer i appointed to, is it?

That’s right,it’s all internal business. The only reference that you can have to this independent timer is the handle,if you keep it.

@narf27

should i set the variable to null also in the first rule?

Think it through.
Remember, it’s just a handle to get hold of the timer, when you want to cancel or reschedule it.
When there isn’t a timer, you don’t need the handle. But it’s your variable, nothing will happen to it if you don’t make it happen.

If we just happened to make sure set it to null when we don’t need it - the timer has finished, or we’ve cancelled it - then we have a very simple test to see if a timer is already running. Is the handle null? Then no existing timer, do whatever (make a new one maybe?), else do something else (cancel or reschedule the old timer?).

But managing the handle must be done in our rules.

[narf27 (Peter)]

@rossko57

Think it through.

i’m trying, i’m trying…

@rossko57

When there isn’t a timer, you don’t need the handle.

timer expired = there isn’t a timer?

@rossko57

Then no existing timer, do whatever (make a new one maybe?), else do something else (cancel or reschedule the old timer?).

ok, i’ll try to add this to my rule…

[rossko57]

You should find this kind of detail in the other rule examples you looked at.

The idea is to make your rule disaster proof - while you might not expect two ON commands to come along in succession and run the timer-making rule, there’s nothing to stop that happening.
Unless you take steps, that would make a new set of additional timers each run.

[narf27 (Peter)]

I have added *timer_handle = null for my various Timers and the error didn’t pop up anymore.
I’m aware this isn’t disaster proof but i think it’s good enough for me.
thanks for all the explanations!