Timer breaks if it lasts longer than 6 minutes

I’ve been having problems with openhab timers for a while, and finally I’ve decided to debug them all. My main issue is some of the timers in my rules work, but others (apparently with a very similar code) don’t. I’ve wrote the simplest rule I could using a timer:

var Timer timerTest = null
var Number flag = 0

rule "Timer test"
when
    Time cron "0 0 0 * * ?"
then
	if(flag == 0){
		logInfo('DEBUG', 'Start timer test')
		flag = 1;
		timerTest = createTimer(now.plusMinutes(5), [|
			logInfo('DEBUG', 'End timer test')
			Fan.sendCommand(OFF)
			flag = 0;
		])
	}
end

And it works just fine as expected. But if I change it and make it run after 10 minutes instead of 5, it stops working and triggers an error which implies the “Fan” item is set to NULL. Of course, if I remove this line (“Fan.sendCommand(OFF)”), everything works again and I get the start and end events in the log as they should appear. So the problem seems to be that after several minutes, I can’t access my items anymore and timers become useless.

The problem only starts after 7 minutes, which is why some of my timers work and others crash… Has anyone experienced the same behaviour?

You don’t need the flag, check if the timer is null instead
You are not resetting the timer to null when it expire and that maybe the reason why.
Also there are only 2 timer threads available so if 2 timers expire at the same time then one one them will have to wait a bit for one of the other two to finish executing its code before starting.

var Timer timerTest = null

rule "Timer test"
when
    Time cron "0 0 0 * * ?"
then
    if(timerTest === null) {
        logInfo('DEBUG', 'Start timer test')
        timerTest = createTimer(now.plusMinutes(5), [ |
            logInfo('DEBUG', 'End timer test')
            Fan.sendCommand(OFF)
            timerTest = null
        ])
    }
end

Thanks vzorglub,

I know I don’t need the flag. I avoided using the timer status so I could simplify the timer influence as much as possible, discard it as an issue and ensure the execution of the code inside the timer.

Anyway, not setting the timer to null doesn’t explain why it works with less than 7 minutes and doesn’t work with larger amounts of time, or why it crashes only when I try to send a command to an item.

Just a tip, check out the expire binding. It’s simplified many of my timer rules, also been very stable.

Thanks, but the expire binding is only useful when an action always follows another one in the same interval of time. I have in mind a more complex use of timers, with some logic checking several conditions once the time has expired. And also I’d like to understand why it isn’t working when I think it should.

Well it shouldn’t so it may be timers interacting.
Can you post the whole rule file?

Actually, the code I posted above is the only rule in the file. Since I’m debugging, I’m trying to simplify as much as possible so there isn’t any unexpected piece of code messing things up.

Can you post the logs?

Just a caution, as you are obviously editing rule files while experimenting.

If you edit/reload a rule file, any timers it has already spawned keep running. But they are ‘orphaned’, the original context is destroyed by the rules reload. At the appointed time, the code execution block invariably fails with some kind of null error.

What is the actual error? Unfortunately errors that occur in lambdas are often opaque and hard to interpret and don’t mean what they appear to mean.

Here is the error:

2018-11-20 08:01:00.008 [INFO ] [eclipse.smarthome.model.script.DEBUG] - End timer test
2018-11-20 08:01:00.009 [ERROR] [org.quartz.core.JobRunShell ] - Job DEFAULT.2018-11-20T08:01:00.006+01:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
logInfo(,)
.sendCommand()
.flag =
.timerTest =
} ] threw an unhandled Exception:
java.lang.NullPointerException: null
at org.eclipse.smarthome.model.script.engine.ScriptError.(ScriptError.java:66) [137:org.eclipse.smarthome.model.script:0.10.0.oh230]
at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:132) [137:org.eclipse.smarthome.model.script:0.10.0.oh230]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:901) [156:org.eclipse.xtext.xbase:2.12.0.v20170519-0752]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:864) [156:org.eclipse.xtext.xbase:2.12.0.v20170519-0752]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:223) [156:org.eclipse.xtext.xbase:2.12.0.v20170519-0752]
at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:219) [137:org.eclipse.smarthome.model.script:0.10.0.oh230]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:203) [156:org.eclipse.xtext.xbase:2.12.0.v20170519-0752]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluateArgumentExpressions(XbaseInterpreter.java:1115) [156:org.eclipse.xtext.xbase:2.12.0.v20170519-0752]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1045) [156:org.eclipse.xtext.xbase:2.12.0.v20170519-0752]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeFeature(XbaseInterpreter.java:991) [156:org.eclipse.xtext.xbase:2.12.0.v20170519-0752]
at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:143) [137:org.eclipse.smarthome.model.script:0.10.0.oh230]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:763) [156:org.eclipse.xtext.xbase:2.12.0.v20170519-0752]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:219) [156:org.eclipse.xtext.xbase:2.12.0.v20170519-0752]
at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:219) [137:org.eclipse.smarthome.model.script:0.10.0.oh230]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:203) [156:org.eclipse.xtext.xbase:2.12.0.v20170519-0752]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:446) [156:org.eclipse.xtext.xbase:2.12.0.v20170519-0752]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:227) [156:org.eclipse.xtext.xbase:2.12.0.v20170519-0752]
at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:219) [137:org.eclipse.smarthome.model.script:0.10.0.oh230]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:203) [156:org.eclipse.xtext.xbase:2.12.0.v20170519-0752]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:189) [156:org.eclipse.xtext.xbase:2.12.0.v20170519-0752]
at org.eclipse.xtext.xbase.interpreter.impl.ClosureInvocationHandler.doInvoke(ClosureInvocationHandler.java:46) [156:org.eclipse.xtext.xbase:2.12.0.v20170519-0752]
at org.eclipse.xtext.xbase.interpreter.impl.AbstractClosureInvocationHandler.invoke(AbstractClosureInvocationHandler.java:29) [156:org.eclipse.xtext.xbase:2.12.0.v20170519-0752]
at com.sun.proxy.$Proxy186.apply(Unknown Source) [?:?]
at org.eclipse.smarthome.model.script.internal.actions.TimerExecutionJob.execute(TimerExecutionJob.java:49) [137:org.eclipse.smarthome.model.script:0.10.0.oh230]
at org.quartz.core.JobRunShell.run(JobRunShell.java:202) [107:org.eclipse.smarthome.core.scheduler:0.10.0.oh230]
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [107:org.eclipse.smarthome.core.scheduler:0.10.0.oh230]
2018-11-20 08:01:00.010 [ERROR] [org.quartz.core.ErrorLogger ] - Job (DEFAULT.2018-11-20T08:01:00.006+01:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
logInfo(,)
.sendCommand()
.flag =
.timerTest =
} ] threw an exception.
org.quartz.SchedulerException: Job threw an unhandled exception.
at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [107:org.eclipse.smarthome.core.scheduler:0.10.0.oh230]
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [107:org.eclipse.smarthome.core.scheduler:0.10.0.oh230]
Caused by: java.lang.NullPointerException
at org.eclipse.smarthome.model.script.engine.ScriptError.(ScriptError.java:66) ~[?:?]
at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:132) ~[?:?]
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:219) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:203) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluateArgumentExpressions(XbaseInterpreter.java:1115) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1045) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeFeature(XbaseInterpreter.java:991) ~[?:?]
at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:143) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:763) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:219) ~[?:?]
at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:219) ~[?:?]
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:219) ~[?:?]
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.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.$Proxy186.apply(Unknown Source) ~[?:?]
at org.eclipse.smarthome.model.script.internal.actions.TimerExecutionJob.execute(TimerExecutionJob.java:49) ~[?:?]
at org.quartz.core.JobRunShell.run(JobRunShell.java:202) ~[?:?]

OK, a NullPointerException has nothing to do with an Item being NULL. Unfortunately, the developers decided to overload the keyword null.

  • NULL - indicates an Item is not yet initialized
  • null - part of the language, indicates that a variable does not have a value

NullPointerExceptions (NPE) indicate that a variable is trying to be used but that variable doesn’t have a value. Now the unfortunate part is that in the Rules DSL, deep under the covers, it tries to figure out the types of all the Items you are using and trying to operate on and when it fails it throws a NPE.

Furthermore, when an error occurs inside a lambda (anything between [ | ]) it usually gets thrown as an NPE. So unfortunately all it really tells us is that some sort of error occurred.

Sometimes you can get a NPE when doing stuff with an Item that is NULL (e.g. MyItem.state as Number + 10) but you will never see a NPE when calling sendCommand or postUpdate on the Item if the Item’s state is NULL.

So looking at the lambda there really isn’t all that much that could be going on that would cause this error. The only thing that stands out is perhaps Fan doesn’t exist as an Item. Are you certain you have a Switch Item named Fan (case matters)?

Thanks a lot for your explanation. It looks like a tough mistery then, because I’m sure the item exists. In fact, this same piece of code works just editing the number of minutes passed as parameter to the “createTimer” function…

Please do bear in mind my caution about orphaned pre-existing timers after rules edits. It’s very easy to get in a loop of error-edit-error-edit and miss what’s happening.

How to produce an NPE:-
Start a timer for 10 minutes
After 5 minutes, edit and reload rules file
Optionally start a new 10 minute timer
Wait 5 minutes - error
Optionally think the error comes from the most recent edit/timer

Yes rossko57, I didn’t answer you but I’m considering that as a possible cause. Since apparently nobody is having the same problem I must be doing something wrong, I’ll keep trying.

If you are on an RPi, remember that it can that a long time to load and parse .rules files (I’ve seen times reported as high as hours). This exacerbates rossko57’s concern about the Timers hanging around.