OH 2.5.0~S1622-1 (Build #1622) - NPE with timers

Setup, Configuration and Use Runtime
, ,
1

I have the impression that when reloading rules, sometimes the rule context is not yet initialized when using timers, as in:

2019-06-24 11:50:23.554 [ERROR] [org.quartz.core.JobRunShell         ] - Job DEFAULT.2019-06-24T11:50:23.543+02:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  <XMemberFeatureCallImplCustom>.forEach(<XClosureImplCustom>)
  <null>.timer_startup = <XNullLiteralImplCustom>
} ] threw an unhandled Exception: 
java.lang.NullPointerException: null
        at org.eclipse.smarthome.model.script.engine.ScriptError.<init>(ScriptError.java:66) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:140) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:902) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:865) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:224) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:768) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:220) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:768) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:220) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:447) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:228) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:190) ~[?:?]
        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.$Proxy334.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) [185:org.openhab.core.scheduler:2.5.0.201906240304]
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [185:org.openhab.core.scheduler:2.5.0.201906240304]
2019-06-24 11:50:23.696 [ERROR] [org.quartz.core.ErrorLogger         ] - Job (DEFAULT.2019-06-24T11:50:23.543+02:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  <XMemberFeatureCallImplCustom>.forEach(<XClosureImplCustom>)
  <null>.timer_startup = <XNullLiteralImplCustom>
} ] threw an exception.
org.quartz.SchedulerException: Job threw an unhandled exception.
        at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [185:org.openhab.core.scheduler:2.5.0.201906240304]
        at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [185:org.openhab.core.scheduler:2.5.0.201906240304]
Caused by: java.lang.NullPointerException
        at org.eclipse.smarthome.model.script.engine.ScriptError.<init>(ScriptError.java:66) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:140) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:902) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:865) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:224) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:768) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:220) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:768) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:220) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:447) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:228) ~[?:?]
        at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:204) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:190) ~[?:?]
        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.$Proxy334.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) ~[?:?]
        ... 1 more

The rule reads as follows:

rule "System startup - shutters"
when
	System started
then
	val String ruleTitle = "Roller Shutters: OpenHAB STARTUP"
	logInfo(ruleTitle, "Initializing timers")
	val int STARTUP_DELAY_SECONDS = 5 // 30
    STARTED_UP = false;

    if (timer_startup === null) {
        // Wait 30 seconds before resetting all timers
        timer_startup = createTimer(now.plusSeconds(STARTUP_DELAY_SECONDS), [ |
            gShutter.allMembers.forEach[ s |
                if (timers.get(s.name) !== null) {
                    timers.put(s.name, null)
                }
            ]
            STARTED_UP = true;
			logInfo(ruleTitle, "Rules and timers have been initialized")
            timer_startup = null;
        ])
    } else {
		logWarn(ruleTitle, "Double startup trigger? rescheduling the stattup timer")
        timer_startup.reschedule(now.plusSeconds(STARTUP_DELAY_SECONDS))
    }
end
2

It’s not just a feeling. On some machines, some times, Rules will start to execute before everything else in OH is read. This can lead to unexpected errors or weird errors like a complaint that “ON” is an unknown symbol.

But, in this case I suspect what is happening is another known behavior. When you reload a .rules file, any Timers you may have had scheduled don’t go away. They are still scheduled by orphaned from their original context since the context is gone. As a result the Timer errors out when it finally does expire. It’s a benign and predictable error.

3

I see.

You just confirmed 2 behaviours I frequently encountered with rules DSL.

4

I should note that the first behavior can also occur with JSR223 Rules.