[SOLVED] Error messages during timer release

Sorry, it comes again.

I have chage the thread title to english
I used google translate so if it’s the wrong translation, pleas correct it

Please use code fences

Thanks

Please excuse my last post, it just did not work and my english is not so good.

Raspi 2
OS Catalina

For radiator thermostat control via timer
keep getting the following error messages in the log:
Error occurs only with timer release, but not with each timer release. Sometimes a switching time is skipped. Not on all days, but sometimes 2-3 times a day.

Rule "Create timer"
when
Time cron "0 0 0 * *?" or // midnight
System started or // Restart or reload rules
Member changed to WT_SchaltMinute or // switching time changed
Member of EZ_SchaltMinute changed or // switching time changed
Member of BZ_SchaltMinute changed or // switching time changed
Member of WC_SchaltMinute changed or // switching time changed // switching time changed
Item planTimer receives command // timer trigger (create next timer)
then
if (lock) return; // rule already active?
lock = true
logInfo ("timer", "create timer") // Control locks
// from here on WZ_Timer // delete old WZ_Timer, falls active
if (WZ_Timer! == null) WZ_Timer.cancel
WZ_Item = WZ_SchaltMinute.members.filter [m | (m.status as number)> now.getMinuteOfDay] .sortBy [
(State as Number) .intValue] .head as NumberItem // determine next WZ_Timer
if (WZ_Item! == null) {// still at least one timer today
logInfo ("Timer", "Create Timer WZ for {} ({})", WZ_Item.name, WZ_Item.state)
WZ_Timer = createTimer (now.withTimeAtStartOfDay.plusMinutes ((WZ_Item.state as Number) .intValue), [// Create Timer
logInfo ("timer", "timer triggered: {}", WZ_Item.name)
if (WZ_Auto.state! = ON) {// manual operation falls
logInfo ("timer", "But manual operation, abort!")
planTimer.sendCommand (OFF) // plan next BZ_Timer
Return; // and final
}
val Number wzsoll = if (WZ_Item.name.contains ("On")) 1 else 11 // Target state after WZ_Timer
logInfo ("timer", "required switching operation tool:")
WZ_ist.postUpdate (wdsoll)
if (WZ_Item.name.contains ("1") || // Should the timer be taken into account?
(WZ_Item.name.contains ("2") && WZ_SW_2.state == ON)) {
logInfo ("Timer", "Switching tool active")
if ((WZ_Thermostat.state as Number)! = wzsoll) // Current status deviating?
WZ_Thermostat.sendCommand (wzsoll)
otherwise
logInfo ("timer", "but status wz already reached")
} else {
logInfo ("Timer", "Switching inactive")
}
planTimer.sendCommand (OFF)
])
}
... 4 more Timer
end

Error:

Error:2019-11-21 20:59:00.018 [INFO ] [eclipse.smarthome.model.script.timer] - Timer WC ausgelöst: WC_Uhr2_Ein
2019-11-21 20:59:00.004 [ERROR] [org.quartz.core.JobRunShell ] - Job DEFAULT.Timer 125 2019-11-21T20:59:00.000+01:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ {
logInfo(,,)
org.eclipse.xtext.xbase.impl.XIfExpressionImpl@1418508
val wcsoll
logInfo(,)
.postUpdate()
org.eclipse.xtext.xbase.impl.XIfExpressionImpl@c9d96e
} ] threw an unhandled Exception:
java.lang.NullPointerException: null
at org.eclipse.smarthome.model.script.engine.ScriptError.(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: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.evaluateArgumentExpressions(XbaseInterpreter.java:1132) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1046) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeFeature(XbaseInterpreter.java:992) ~[?:?]
at org.eclipse.smarthome.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:151) ~[?:?]
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: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.$Proxy248.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) [182:org.openhab.core.scheduler:2.5.0.M4]
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [182:org.openhab.core.scheduler:2.5.0.M4]

Can someone help me, please, what the error messages mean?

I’m not sure that does anything in a timer’s code block; there is nowhere to return to,

I’m not sure if I found all misspelled or wrong code parts.
Spaces aren’t always allowed, for example != and ! = are different.
Upper/lower case is important, there’s a difference between Return; and return;
I’m not aware of a key word otherwise. Use else instead.

Rule "Create timer"
when
    Time cron "0 0 0 * *?" or                                                                              // midnight
    System started or                                                                                      // Restart or reload rules
    Member of WT_SchaltMinute changed or                                                                   // switching time changed
    Member of EZ_SchaltMinute changed or                                                                   // switching time changed
    Member of BZ_SchaltMinute changed or                                                                   // switching time changed
    Member of WC_SchaltMinute changed or                                                                   // switching time changed 
    Item planTimer received command                                                                        // timer trigger (create next timer)
then
    if(lock) return;                                                                                       // rule already active?
    lock = true
    logInfo("timer", "create timer")                                                                       // Control locks
    // from here on WZ_Timer
    if(WZ_Timer !== null) WZ_Timer.cancel                                                                  // delete old WZ_Timer, falls active
    WZ_Item = WZ_SchaltMinute.members.filter[m | 
        (m.status as Number) > now.getMinuteOfDay].sortBy[(State as Number).intValue].head as NumberItem   // determine next WZ_Timer
    if(WZ_Item !== null) {                                                                                 // still at least one timer today
        logInfo("Timer", "Create Timer WZ for {} ({})", WZ_Item.name, WZ_Item.state)
        WZ_Timer = createTimer(now.withTimeAtStartOfDay.plusMinutes((WZ_Item.state as Number).intValue), [ // Create Timer
            logInfo("timer", "timer triggered: {}", WZ_Item.name)
            if(WZ_Auto.state != ON) {                                                                      // manual operation falls
                logInfo("timer", "But manual operation, abort!")
                planTimer.sendCommand(OFF)                                                                 // plan next BZ_Timer
                return;                                                                                    // and final
            }
            val Number wzsoll = if(WZ_Item.name.contains("On")) 1 else 11                                  // Target state after WZ_Timer
            logInfo("timer", "required switching operation tool:")
            WZ_ist.postUpdate(wdsoll)
            if(WZ_Item.name.contains("1") ||                                                               // Should the timer be taken into account?
            (WZ_Item.name.contains("2") && WZ_SW_2.state == ON)) {
                logInfo("Timer", "Switching tool active")
                if((WZ_Thermostat.state as Number) != wzsoll) WZ_Thermostat.sendCommand(wzsoll)            // Current status deviating?
                else logInfo("timer", "but status wz already reached")
            } else logInfo("Timer", "Switching inactive")
            planTimer.sendCommand(OFF)
        ])
    }
    // ... 4 more Timer
end

Don’t know if it’s important or right, but I’d never seen a trigger(third one) like

Member changed to WT_SchaltMinute

Or this trigger too:

Item planTimer receives command

It should be received

yeah peter that looks screwy
maybe was supposed to be

Member WT_SchaltMinute changed

like the rest of them but my German not so good so struggling here

Yepp. Always missing some typos :wink: I’m pretty sure there are some more in it…

1 Like

…or

Member of WT_SchaltMinute changed

:wink::wink:

1 Like

Hi,
please excuse me and thank you for your advice.
I wanted to do it very well and have the code run again because of the German descriptions of the translator and this nonsense came out of it.
There was such nonsense as “! =”, “otherwise” or “Member changed to”.
It should be a lesson to me!
This was my code:

rule "Timer anlegen"
when
    Time cron " 0 0 0 * * ?"  or                                                                                 // Mitternacht
    System started or                                                                                           // Neustart oder Rules neu geladen
    Member of WZ_SchaltMinute changed or                                                                        // Schaltzeit geändert
    Member of EZ_SchaltMinute changed or                                                                        // Schaltzeit geändert
    Member of BZ_SchaltMinute changed or                                                                        // Schaltzeit geändert
    Member of WC_SchaltMinute changed or                                                                        // Schaltzeit geändert                                                                     // Schaltzeit geändert
    Item planTimer received command                                                                             // Timertrigger (nächsten Timer anlegen)
then
    if(lock) return;                                                                                            // Rule bereits aktiv?
    lock = true
    logInfo("timer","Timer anlegen")                                                                                          // Rule sperren
                                            // ab hier WZ_Timer                                               // alten WZ_Timer löschen, falls aktiv
    if(WZ_Timer !== null) WZ_Timer.cancel
    WZ_Item = WZ_SchaltMinute.members.filter[m|(m.state as Number) > now.getMinuteOfDay].sortBy[
        (state as Number).intValue].head as NumberItem                                                          // Nächsten WZ_Timer ermitteln
    if(WZ_Item !== null) {                                                                                      // noch mindestens ein Timer heute
        logInfo("timer","Timer WZ anlegen für {} ({})",WZ_Item.name,WZ_Item.state)
        WZ_Timer = createTimer(now.withTimeAtStartOfDay.plusMinutes((WZ_Item.state as Number).intValue),[       // Timer anlegen
            logInfo("timer","Timer ausgelöst: {}",WZ_Item.name)
            if(WZ_Auto.state != ON) {                                                                           // falls manueller Betrieb
                logInfo("timer","Aber manueller Betrieb, Abbruch!")
                planTimer.sendCommand(OFF)                                                                      // nächsten BZ_Timer planen
                return;                                                                                         // und Schluss
            }
            val Number wzsoll = if(WZ_Item.name.contains("Ein")) 1 else 11                                       // Sollzustand nach WZ_Timer
            logInfo("timer","geforderter Schaltvorgang WZ : ")    
            WZ_ist.postUpdate(wzsoll)
            if (WZ_Item.name.contains("1") ||                                                                 // Soll der Timer berücksichtigt werden?
            (WZ_Item.name.contains("2") && WZ_SW_2.state == ON)) {
                logInfo("timer","Schaltvorgang WZ aktiv")
                if((WZ_Thermostat.state as Number) != wzsoll)                                                  // Aktueller Status abweichend?
                    WZ_Thermostat.sendCommand(wzsoll)
                else 
                    logInfo("timer","aber Zustand WZ bereits erreicht")
            } else {
                logInfo("timer","Schaltvorgang inaktiv")
            }
            planTimer.sendCommand(OFF)                                                                                     
        ])
    }
......

Unfortunately I can not find the mistakes. I have 4 almost same timers for 4 thermostats.
There are daily errors in the log, but not with every triggering and with some timers more frequently. The error block is then about 60 times in the log. The Rule in question is in the last post. The error block is always the same, only with val wzsoll, val ezsoll, val bzsoll or val wcsoll.

  logInfo(<XStringLiteralImpl>,<XStringLiteralImpl>,<XMemberFeatureCallImplCustom>)
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@1c32eec (conditionalExpression: false)
  val wzsoll
  logInfo(<XStringLiteralImpl>,<XStringLiteralImpl>,<XFeatureCallImplCustom>)
  <XFeatureCallImplCustom>.postUpdate(<XFeatureCallImplCustom>)
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@3d6719 (conditionalExpression: false)
  <XFeatureCallImplCustom>.sendCommand(<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._doEvaluate(XbaseInterpreter.java:857) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:231) ~[?:?]
	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:1221) ~[?:?]
	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.$Proxy599.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:?]

I think the problem comes from there:

            val Number wzsoll = if(WZ_Item.name.contains("Ein")) 1 else 11                                       // Sollzustand nach WZ_Timer

When the timer executes what if WZ_Item ?

So create a string global variable:
var String WZItemName
In the top of the rule:

...
    if(WZ_Timer !== null) WZ_Timer.cancel
    WZ_Item = WZ_SchaltMinute.members.filter[m|(m.state as Number) > now.getMinuteOfDay].sortBy[
        (state as Number).intValue].head as NumberItem                                                          // Nächsten WZ_Timer ermitteln
    if(WZ_Item !== null) {                                                                                      // noch mindestens ein Timer heute
        WZItemName = WZItem.name.toString
...

And in the timer:

...
        WZ_Timer = createTimer(now.withTimeAtStartOfDay.plusMinutes((WZ_Item.state as Number).intValue),[       // Timer anlegen
            logInfo("timer","Timer ausgelöst: {}",WZ_Item.name)
            if(WZ_Auto.state != ON) {                                                                           // falls manueller Betrieb
                logInfo("timer","Aber manueller Betrieb, Abbruch!")
                planTimer.sendCommand(OFF)                                                                      // nächsten BZ_Timer planen
                return;                                                                                         // und Schluss
            }
            val Number wzsoll = if(WZItemName.contains("Ein")) 1 else 11                                       // Sollzustand nach WZ_Timer
            logInfo("timer","geforderter Schaltvorgang WZ : ")    
            WZ_ist.postUpdate(wzsoll)
            if (WZItemName.contains("1") ||                                                                 // Soll der Timer berücksichtigt werden?
            (WZItemName.contains("2") && WZ_SW_2.state == ON)) {
                logInfo("timer","Schaltvorgang WZ aktiv")
                if((WZ_Thermostat.state as Number) != wzsoll)                                                  // Aktueller Status abweichend?
                    WZ_Thermostat.sendCommand(wzsoll)
                else 
                    logInfo("timer","aber Zustand WZ bereits erreicht")
            } else {
                logInfo("timer","Schaltvorgang inaktiv")
            }
            planTimer.sendCommand(OFF)                                                                                     
        ])

...

If any of the Items in your Group have non-numeric states at timer run time, this line will error.

I would open it out into step-by-step code that allows you to test for numeric before using it in an expression. (and add logging to see the states)

I am currently testing the changes suggested by vincent, but I will not see that until tomorrow. I’ve used a global variable before, but it’s worth a try.

The suggestion of Rossko57 does not seem to me relevant, because the error appears only after the release and the time in the log is correct:
(DEFAULT.Timer 68 2019-12-03T23: 30: 00.000 + 01: 00:

Quite so! I managed to misread the group filter as part of the timer code. That’s a trap for another day :wink:

Are these long running timers? A reminder that if you edit a rules file that has already started timers, the timers continue to run but usually fail at their due time with a null error, because their context has been destroyed.

That could be the solution. I did not realize that the timers continue to run when the rules change.
I delete the timers at midnight and when triggered, but since I am making many changes to the rule because of the issues, it may be that timers remain open. That would also explain why often 60 error messages are in the log. Is it possible to log the open timers?

Nope. Once you reload a rules file, any timers it may have started before are completely orphaned and inaccessible.

To diagnose if this what is happening requires you to understand what your own system is up to, there are no short cuts.

To avoid the issue - or in this case demonstrate whether or not you still get errors - reboot openHAB after your last rules edit of the day.

I have now changed one of the 4 timers and will start openHAB again. Then tomorrow I should see where the problem lies.

That was the solution.

For months I search the error in my code. It did not matter if it was global or local variables or items used as memory for the timers.

The errors came from orphaned timers while saving the rule.
Thanks to rossko57, I now know that the timers are retained with .
It’s not so nice to do a restart of OH after each rule change, as many battery devices take hours to wake up, but the bugs are gone.