Scheduled job failed and stopped

  • Platform information:
    • Hardware: Raspi 3b+
    • OS: Openhabian
    • Java Runtime Environment: 11
    • openHAB version: 3 stable

Hello, since a few days (maybe since i migrated to OH3, maybe since i use timers in rules) i got an error. “Scheduled job failed and stopped” Out of the error message i cannot find the reason for this. Does anyone also has these errors?

Thanks.

I too am getting inconsistent errors of this nature in my timers. I’m using DSL rules and all items were created/defined via UI. I can run a timer immediately with this same code and all is well. Some mornings it will kick off just fine while others give me this message. I have been working in the system with getting things set up each day so is the reloading of the other rule files possibly causing issues? All my lambda is set to do within the timer is an if statement checking that state of two variables and if they are both ON then sending a command to another item. Any input is appreciated - I’ve added another log entry text at the forefront of my lambda to see if it shows up. I’m running OH 3.1.0.M1 within docker.

2021-02-10 07:15:00.000 [WARN ] [ore.internal.scheduler.SchedulerImpl] - Scheduled job failed and stopped
java.lang.reflect.UndeclaredThrowableException: null
at com.sun.proxy.$Proxy1113.apply(Unknown Source) ~[?:?]
at org.openhab.core.model.script.actions.ScriptExecution.lambda$0(ScriptExecution.java:82) ~[?:?]
at org.openhab.core.internal.scheduler.SchedulerImpl.lambda$12(SchedulerImpl.java:166) ~[bundleFile:?]
at org.openhab.core.internal.scheduler.SchedulerImpl.lambda$1(SchedulerImpl.java:76) [bundleFile:?]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: org.openhab.core.model.script.engine.ScriptExecutionException: The name ‘’ cannot be resolved to an item or type; line 0, column 0
at org.openhab.core.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:141) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:992) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:955) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:236) ~[?:?]
at org.openhab.core.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:216) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:858) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:232) ~[?:?]
at org.openhab.core.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:216) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluateArgumentExpressions(XbaseInterpreter.java:1206) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1136) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeFeature(XbaseInterpreter.java:1082) ~[?:?]
at org.openhab.core.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:151) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:992) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:238) ~[?:?]
at org.openhab.core.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:216) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluateArgumentExpressions(XbaseInterpreter.java:1206) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1136) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeFeature(XbaseInterpreter.java:1082) ~[?:?]
at org.openhab.core.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:151) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:992) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:238) ~[?:?]
at org.openhab.core.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:216) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:470) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:256) ~[?:?]
at org.openhab.core.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:216) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:459) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:240) ~[?:?]
at org.openhab.core.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:216) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:202) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.ClosureInvocationHandler.doInvoke(ClosureInvocationHandler.java:47) ~[?:?]
at org.eclipse.xtext.xbase.interpreter.impl.AbstractClosureInvocationHandler.invoke(AbstractClosureInvocationHandler.java:30) ~[?:?]
… 10 more

Mayyyybe.
Do you think this is a long-running timer?
It is possible to create an “orphan” timer in DSL.
Start a timer.
Edit/reload it’s parent rule file before the scheduled run.
The timer will still try to execute at its appointed time,but it’s originating environment has been destroyed. Invariably, it will fail with a null error due to referencing something that no longer exists.

Hey Rossko - that is certainly possible as I have made file edits and had timers destroyed that way - my only thought is that shouldn’t the newly created timer still execute though? or is it perhaps an issue with the variable name? I know I really need to get these rules converted over to use the new ui rule engine but I’ve just not gotten there yet - focused on the impacts of creating all items in the UI and updating rules to use these new names as well as the other new specifics that have been popping up.

What newly created timer? They’re all fully independent. If an orphan dies, it should not affect subsequent scheduled timers. If a timer fails that was created after your last edit of that file, you’ve got a code problem.

If you are using OH3 you are using the new rules engine, it has an interface for DSL rules now, it is the only one.

Right I know the ones that were created stay out there when the file is edited/ reloaded. I guess my point was that I can imagine seeing these messages for the ‘orphan’ timers but I had recreated the timer after the final file reload so I would expect that one to work. (I’ve added some extra logging text into it to see if it helps in tracking things down)

Re the web UI vs the .rules files - I was under the impression that in long term the DSL rules interface in the files was planned to be phased out? I presume some things we can do via the UI should be a bit smoother in cases like this? I need to look more into what all that can do.

Who knows what will happen in OH4

Hi, I am getting the same errors on OH3, in average 1-2 times per day. is there any way to find out which rule is doing this? other than editing all rules and adding loginfo in them…

Two different errors are described above, so there’s not much we can say about “same error”.

the one from the subject of the topic :slight_smile:

2021-08-23 16:04:57.098 [WARN ] [ore.internal.scheduler.SchedulerImpl] - Scheduled job failed and stopped
java.lang.IllegalArgumentException: The argument 'command' must not be null.
        at org.openhab.core.events.AbstractEventFactory.checkNotNull(AbstractEventFactory.java:115) ~[?:?]
        at org.openhab.core.items.events.ItemEventFactory.assertValidArguments(ItemEventFactory.java:403) ~[?:?]
        at org.openhab.core.items.events.ItemEventFactory.createCommandEvent(ItemEventFactory.java:223) ~[?:?]
        at org.openhab.core.items.events.ItemEventFactory.createCommandEvent(ItemEventFactory.java:239) ~[?:?]
        at org.openhab.core.model.script.actions.BusEvent.sendCommand(BusEvent.java:113) ~[?:?]
        at jdk.internal.reflect.GeneratedMethodAccessor262.invoke(Unknown Source) ~[?:?]
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1192) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1167) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1153) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeFeature(XbaseInterpreter.java:1098) ~[?:?]
        at org.openhab.core.model.script.interpreter.ScriptInterpreter.invokeFeature(ScriptInterpreter.java:151) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:878) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:243) ~[?:?]
        at org.openhab.core.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:227) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._doEvaluate(XbaseInterpreter.java:475) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.doEvaluate(XbaseInterpreter.java:251) ~[?:?]
        at org.openhab.core.model.script.interpreter.ScriptInterpreter.doEvaluate(ScriptInterpreter.java:226) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:227) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:213) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.ClosureInvocationHandler.doInvoke(ClosureInvocationHandler.java:47) ~[?:?]
        at org.eclipse.xtext.xbase.interpreter.impl.AbstractClosureInvocationHandler.invoke(AbstractClosureInvocationHandler.java:30) ~[?:?]
        at com.sun.proxy.$Proxy214.apply(Unknown Source) ~[?:?]
        at org.openhab.core.model.script.actions.ScriptExecution.lambda$0(ScriptExecution.java:82) ~[?:?]
        at org.openhab.core.internal.scheduler.SchedulerImpl.lambda$12(SchedulerImpl.java:184) ~[?:?]
        at org.openhab.core.internal.scheduler.SchedulerImpl.lambda$1(SchedulerImpl.java:87) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:829) [?:?]

I don’t think that comes from a rule at all.

Looks a big clue. Something trying to generate an Item command on a schedule …

Are you using ‘expire’ feature on any Items? Check they are allproperly configured.

hm…i dont use expire feature on any item…
if its not a rule from where it’s coming?

I suspect Android alarm clock rule, as i see this error 4 times at 7:20 at the time of the alarm…but then again, why would it get triggered at other random times…I’ll disable the rule for a few days and monitor it…

pi@knx:/etc/openhab/items $ cat  /var/log/openhab/openhab* | grep "Scheduled job failed and stopped"
2021-08-15 15:51:10.417 [WARN ] [ore.internal.scheduler.SchedulerImpl] - Scheduled job failed and stopped
2021-08-16 07:20:00.011 [WARN ] [ore.internal.scheduler.SchedulerImpl] - Scheduled job failed and stopped
2021-08-16 07:20:00.021 [WARN ] [ore.internal.scheduler.SchedulerImpl] - Scheduled job failed and stopped
2021-08-16 15:34:02.337 [WARN ] [ore.internal.scheduler.SchedulerImpl] - Scheduled job failed and stopped
2021-08-16 23:13:07.382 [WARN ] [ore.internal.scheduler.SchedulerImpl] - Scheduled job failed and stopped
2021-08-17 08:31:10.206 [WARN ] [ore.internal.scheduler.SchedulerImpl] - Scheduled job failed and stopped
2021-08-17 15:29:00.394 [WARN ] [ore.internal.scheduler.SchedulerImpl] - Scheduled job failed and stopped
2021-08-18 07:20:00.001 [WARN ] [ore.internal.scheduler.SchedulerImpl] - Scheduled job failed and stopped
2021-08-18 15:34:52.754 [WARN ] [ore.internal.scheduler.SchedulerImpl] - Scheduled job failed and stopped
2021-08-18 16:41:00.156 [WARN ] [ore.internal.scheduler.SchedulerImpl] - Scheduled job failed and stopped
2021-08-18 21:21:26.866 [WARN ] [ore.internal.scheduler.SchedulerImpl] - Scheduled job failed and stopped
2021-08-18 23:51:37.615 [WARN ] [ore.internal.scheduler.SchedulerImpl] - Scheduled job failed and stopped
2021-08-19 15:32:47.036 [WARN ] [ore.internal.scheduler.SchedulerImpl] - Scheduled job failed and stopped
2021-08-20 01:10:48.099 [WARN ] [ore.internal.scheduler.SchedulerImpl] - Scheduled job failed and stopped
2021-08-22 07:19:55.003 [WARN ] [ore.internal.scheduler.SchedulerImpl] - Scheduled job failed and stopped
2021-08-22 15:30:44.775 [WARN ] [ore.internal.scheduler.SchedulerImpl] - Scheduled job failed and stopped
2021-08-23 16:04:57.098 [WARN ] [ore.internal.scheduler.SchedulerImpl] - Scheduled job failed and stopped

I found which rule is doing it (sometimes) but can’t figure out why…

var Timer timerKodi = null

rule "KODI Screen Saver"
when 
    Item myKodi_screensaver received update
then
if(myKodi_screensaver.state == ON && Television.state == ON)
{if(timerKodi === null)
{logInfo("kodi.rules", "LGTV_ON - timer started")
timerKodi = createTimer(now.plusMinutes(6)) [
 Television.sendCommand(if(myKodi_screensaver.state == ON && Television.state == ON) OFF)
 logInfo("kodi.rules", "LGTV_OFF - TV has powered off")
 timerKodi.cancel
 timerKodi = null]}}
else if(myKodi_screensaver.state == OFF && timerKodi !== null)
{logInfo("kodi.rules", "LGTV_ON - timer canceled")
timerKodi.cancel
timerKodi = null}
end

this rules sometimes fails with that error - to be exact, second part of the rule after else. but only sometimes, and sometimes it works normally as I can see it in the log.

We already found the error related to sending a command, so this looks promising for culprit.

When the Timer executes it will send a command. We know the trouble is about what command is sent.
What command will we send? It’s determined by
if(myKodi_screensaver.state == ON && Television.state == ON) OFF
If conditions = true, send OFF. Looks okay.

if conditions = false, umm… null. You can’t send a null command, which is what the message tells you.

Did you mean to put the sendCommand() inside the if(), maybe? Or maybe have a else clause?

indeed i did…

rule "KODI Screen Saver"
when 
    Item myKodi_screensaver received update
then
if(myKodi_screensaver.state == ON && Television.state == ON && timerKodi === null)
{logInfo("kodi.rules", "LGTV_ON - timer started")
timerKodi = createTimer(now.plusMinutes(6))
[if(myKodi_screensaver.state == ON && Television.state == ON)
 {Television.sendCommand(OFF)
 logInfo("kodi.rules", "LGTV_OFF - TV has powered off")}
 timerKodi.cancel
 timerKodi = null]}
else if(myKodi_screensaver.state == OFF && timerKodi !== null)
{logInfo("kodi.rules", "LGTV_ON - timer canceled")
timerKodi.cancel
timerKodi = null}
end

will this work better?
do i even need the last part after else? or anyway the timer will get cancelled right? only then I won’t see in the log when the rule was fired and when it got cancelled…

thanks

Well, there’s no point cancelling a timer inside its own code. Too late, it’s already running.
Apart from that I don’t know what you want to happen if the rule proper is triggered while a timer is running.

Well, this is what I picked up in some examples, i was thinking you should reset the timer in the end…so you are saying I can remove that, he will be reset to null automatically after 6 minutes anyway right?
When I think about it, yes I do need else clause, as I want timer to be reset everytime screensaver is found ON, i dont want it to keep counting 6 minutes…
My goal here is simple, I want TV to be shutoff if kodi screensaver is running for 6 minutes, and I want it to abort shutdown and not switchoff if someone started using kodi meanwhile (screensaver OFF)

There are two different things to consider here.

createTimer( blah ...)

This creates a Timer due to execute in the future, completely independent of the rule that spawned it.

Note that because it is completely independent of any rule, rules cannot affect it either. Except if we do it this way …

fred = createTimer( blah ...)

Variable fred here is a handle, a pointer, a reference, a communications channel to the independent Timer. Through fred we can pass instructions, like fred.cancel to abandon the timing.

The Timer is still independent. We can destroy the handle
fred = null
and this makes no difference to the Timer, which carries on.

Likewise, when the time comes and the Timer executes, it doesn’t do anything to the handle either. fred remains a valid handle, pointing to a Timer that has already run.
Sometimes that has uses, we can use the handle to ask if the Timer has done its thing yet.
if (fred.hasTerminated)

So that’s how these two parts, handle and Timer, interact.
How can we make use of that in practice?

A very common technique is to use the handle as a “flag” to show this Timer is running, so that rules can find out and do different things. (We will invariably make fred a global variable so that it survives between runs of rules)

if (fred === null) {
    // no timer yet, so make one
   fred = createTimer( blah ...
} else {
   // Timer already running, do something else
}

But - there is a problem here. Even when the Timer has executed, it doesn’t affect fred. This only works once.
So it is up to us to set the handle to null after use. This why you often see the equivalent of
fred = null
at the end of a Timer code block, this “lowers the flag” so any rule can easily find out if there is an active Timer.

if (fred === null) {
    // no timer yet, so make one
   fred = createTimer( blah ...) [
           // timer actions
          fred = null
       ]
} else {
   // Timer already running, do something else
}

We could use fred.hasTerminated instead but it gets fiddly, remembering fred will be null before the very first time we use it anyway, and null.hasTerminated will cause a rule-stopping error

So now our rule can start a Timer if needed, and find out if already running … then do something else.
Exactly what the something else might be is your choice, it depends what you want to do.

Perhaps this is a window-open alarm, so your rule runs on window-changed. If it changes to closed and the alarm delay is already running, you want to stop it.

if (fred === null) {
    // no timer yet, so make one
   fred = createTimer( blah ...) [
           // ring window alarm bell
          fred = null
       ]
} else {
   // Timer already running, but window now closed
   fred.cancel
   // Timer killed ... but not the handle yet, remember
   fred = null
   // now we are back to starting point
}

Or perhaps this is a motion triggered light. If your rule re-triggers while the Timer is already running, you want to extend the delay, not cancel it.

if (fred === null) {
    // no timer yet, so make one
   fred = createTimer( blah ...) [
           // turn light off
          fred = null
       ]
} else {
   // Timer already running, but another motion trigger
   fred.reschedule( blah )
   // Timer changed to a new future time
   // this time we leave fred alone, it is still valid
}

An alternative approach to ‘reschedule’ that will you will often see is simply to always cancel the Timer and then make a completely new one.

  // kill any old Timer
fred?.cancel
  // special ? here does some magic to suppress error if fred is null
  // no need to set it null, we are just about to overwrite it
fred = createTimer( blah ...) [
           // turn light off
          fred = null
           // although if we do not check fred elsewhere
           // we need not do this
       ]

If you copy-paste from complex examples. you will get into trouble if you do not understand them.

4 Likes

thanks for clarifications!

Thank you for this!

I had xxx.cancel within and at the end of the timer and it was causing so many errors with OH3.x. Now I’m just using the xxx = null line only within and at the end of the actual timer.

Best, Jay