Exception in rules

mhaack · December 8, 2017, 3:42pm

Hello I’m getting the following exception which seem to be somehow related to a logInfo call in a timer rule.

Can I somehow, maybe be setting the correct debug logger, find out which rule / timer is the root cause of that?

2017-12-08 16:36:45.552 [ERROR] [org.quartz.core.ErrorLogger         ] - Job (DEFAULT.2017-12-08T16:36:45.539+01:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  logInfo(<XFeatureCallImplCustom>,<XStringLiteralImpl>)
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@12c96d1
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@f1f5e8
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@1ec8560
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@1f28009
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@67b094
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@1ad6bc3
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@bf7b99
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@15a1276
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@c23c9d
  org.eclipse.xtext.xbase.impl.XConstructorCallImplCustom@144492 (invalidFeatureIssueCode: null, validFeature: false, explicitConstructorCall: true, anonymousClassConstructorCall: false)
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@125d026
  logInfo(<XFeatureCallImplCustom>,<XStringLiteralImpl>)
  <null>.firstTimer = <XNullLiteralImplCustom>
} ] threw an exception.
org.quartz.SchedulerException: Job threw an unhandled exception.
	at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [115:org.eclipse.smarthome.core.scheduler:0.10.0.201712081218]
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [115:org.eclipse.smarthome.core.scheduler:0.10.0.201712081218]
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:130) ~[?:?]
	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:215) ~[?:?]
	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:141) ~[?:?]
	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:215) ~[?:?]
	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:215) ~[?:?]
	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.$Proxy203.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

opus · December 8, 2017, 3:52pm

How about posting the rule which you suspect to be causing the error?
If you can’t figure out which rule it is, use a logInfo as the first line in order to get a descriptive feedback.

rlkoshak · December 8, 2017, 7:33pm

What I will do is add a try/catch/finally to all my lambdas to print out the exception thrown in the catch clause and any other pertinent info like the states of passed in values, which lambda it is, intermediate calculations, etc depending on the context.

If you catch it in your lambda you can control what gets logged.

mhaack · December 8, 2017, 7:39pm

From the following line …

I suspect this is coming from (since this is the timer called “firstTimer” - missed that before):

if (firstTimer === null) {
        logInfo(filename, "--> 120s timer started")
        firstTimer = createTimer(now.plusSeconds(120)) [|
            logInfo(filename, "--> 120s init ...")
            // status display ground floor
            if (Switch_GF_Floor_1_Display_L1.state == NULL) Switch_GF_Floor_1_Display_L1.sendCommand("Fenster/Tür")
            if (Switch_GF_Floor_1_Display_I1.state == NULL) Switch_GF_Floor_1_Display_I1.sendCommand("CLOSED")
            if (Switch_GF_Floor_1_Display_L2.state == NULL) Switch_GF_Floor_1_Display_L2.sendCommand("Haus")
            if (Switch_GF_Floor_1_Display_I2.state == NULL) Switch_GF_Floor_1_Display_I2.sendCommand("ERROR")
            if (Switch_GF_Floor_1_Display_L3.state == NULL) Switch_GF_Floor_1_Display_L3.sendCommand("Hütte")
            if (Switch_GF_Floor_1_Display_I3.state == NULL) Switch_GF_Floor_1_Display_I3.sendCommand("ERROR")
            if (Switch_GF_Floor_1_Display_LED.state == NULL) Switch_GF_Floor_1_Display_LED.sendCommand("GREEN")
            if (Switch_GF_Floor_1_Display_BEEPER.state == NULL) Switch_GF_Floor_1_Display_BEEPER.sendCommand("OFF")

            // verbraucher
            if (DishwasherOperationState == NULL) DishwasherOperationState.postUpdate(0)

            // astro
            if (now.isAfter((Sunset_Time.state as DateTimeType).calendar.timeInMillis) ||
                now.isBefore((Sunrise_Time.state as DateTimeType).calendar.timeInMillis)
            ) {
                postUpdate(Night_State, ON)
            } else {
                postUpdate(Night_State, OFF)
            }
            logInfo(filename, "--> 120s init done")
            firstTimer = null
        ]
    }

I wonder what can be wrong with the logInfo statements?

rlkoshak · December 8, 2017, 8:28pm

Post your full lambda including the declaration.

Is firstTimer a global variable? If so you must pass it as an argument to the lambda.

rossko57 · December 8, 2017, 8:28pm

I think that points at something wrong with the X in logInfo(X,Y)

In your case

logInfo(filename, "--> 120s init ...")

What is filename, and what context was it defined in? i.e. is it still valid within the timer’s lambda code block?

mhaack · December 9, 2017, 6:13am

Here is the full rule file …

val String filename = "init.rules"

var Timer firstTimer = null
var Timer secondTimer = null

rule "OpenHAB system started - super init rule"
when
    System started
then
    logInfo(filename, "--> direct init ...")
    // status notification
    if (StateNotify.state == NULL) postUpdate(StateNotify, OFF)

    // room status messages
    if (RoomContactStatus.state == NULL) postUpdate(RoomContactStatus,"Alles geschlossen")
    if (RoomMotionStatus.state == NULL) postUpdate(RoomMotionStatus,0)
    logInfo(filename, "--> direct init done")

    if (firstTimer === null) {
        logInfo(filename, "--> 120s timer started")
        firstTimer = createTimer(now.plusSeconds(120)) [|
            logInfo(filename, "--> 120s init ...")
            // status display ground floor
            if (Switch_GF_Floor_1_Display_L1.state == NULL) Switch_GF_Floor_1_Display_L1.sendCommand("Fenster/Tür")
            if (Switch_GF_Floor_1_Display_I1.state == NULL) Switch_GF_Floor_1_Display_I1.sendCommand("CLOSED")
            if (Switch_GF_Floor_1_Display_L2.state == NULL) Switch_GF_Floor_1_Display_L2.sendCommand("Haus")
            if (Switch_GF_Floor_1_Display_I2.state == NULL) Switch_GF_Floor_1_Display_I2.sendCommand("ERROR")
            if (Switch_GF_Floor_1_Display_L3.state == NULL) Switch_GF_Floor_1_Display_L3.sendCommand("Hütte")
            if (Switch_GF_Floor_1_Display_I3.state == NULL) Switch_GF_Floor_1_Display_I3.sendCommand("ERROR")
            if (Switch_GF_Floor_1_Display_LED.state == NULL) Switch_GF_Floor_1_Display_LED.sendCommand("GREEN")
            if (Switch_GF_Floor_1_Display_BEEPER.state == NULL) Switch_GF_Floor_1_Display_BEEPER.sendCommand("OFF")

            // astro
            if (now.isAfter((Sunset_Time.state as DateTimeType).calendar.timeInMillis) ||
                now.isBefore((Sunrise_Time.state as DateTimeType).calendar.timeInMillis)
            ) {
                postUpdate(Night_State, ON)
            } else {
                postUpdate(Night_State, OFF)
            }
            logInfo(filename, "--> 120s init done")
            firstTimer = null
        ]
    }

    if (secondTimer === null) {
        logInfo(filename, "--> 240s timer started")
        secondTimer = createTimer(now.plusSeconds(240)) [|
            logInfo(filename, "--> 240s init ...")
            // status display ground floor
            Switch_GF_Floor_1_Display_SUBMIT.sendCommand(ON)

            // automatic programs for lights & outdoor
            if (Program_Pond.state == NULL) Program_Pond.postUpdate(1)
            if (Program_Teracce.state == NULL) Program_Teracce.postUpdate(3)
            if (Program_XMAS_Indoor.state == NULL) Program_XMAS_Indoor.postUpdate(0)
            if (Program_XMAS_Outdoor.state == NULL) Program_XMAS_Outdoor.postUpdate(0)

            // rollershutter 
            Rollershutter_StatusUpdate_Action.sendCommand(ON)

            logInfo(filename, "--> 240s init done")
            secondTimer = null
        ]
    }
end

mhaack · December 9, 2017, 6:18am

I think it can’t be related to filename, which is defined as a global constant, see ^^^^

[UPDATE] @rlkoshak, @rossko57 I did some more tests, I think it is some wired state or race condition with the timers during OH startup. The error is only reproducible under the following two conditions:

occurs during OH start up
occurs if I save the rule file twice while OH is running > save, wait some seconds until the timers are created, save again, new timers are created

While OH is running I can touch the file which triggers the rule to reload. If I only save the file once and wait until the timers have triggered (120s and 240s) everything is fine, no error.

So I guess if I save the file while the timers are running (but have not triggered) they get not destroyed correctly. Not sure why this happens during startup.

rossko57 · December 9, 2017, 11:26am

Yes, that is a normal event in OH (though it is sneaky and causes most of us puzzling moments!)
Reloading a rule file destroys the context for already running Timers but not the Timers, which then throw peculiar errors when they execute later.

As to failure during system startup, that will need more study. Most likely something is not (yet) initialized at first run (astro items?). Be particularly suspicious of any Items involved which are not persisted.

mhaack · December 9, 2017, 8:25pm

Thx @rossko57 for clarification, at least I know I can ignore it when I update rule files. For startup I will have a look next time.

DavidR · December 11, 2017, 12:52pm

I think the three ‘=’ signs are wrong.
Not sure if it’s your problem though.

mhaack · December 11, 2017, 1:28pm

@DavidR I think the === is not the problem, I have them in other rules as well, also see here Operator replaced with ===?

DavidR · December 11, 2017, 2:13pm

Yes you are right. I didn’t bother checking the docs because surely no language could be that quirky . Xtend continues to surprise me.

mhilbush · December 11, 2017, 2:27pm

Yeah, I see this all the time at OH startup on my “System started” rules that have timers. Since the rules eventually run successfully, I haven’t spent the time to solve it.

I had not thought to pass the timer variable as a parameter into the lamdba as @rlkoshak had suggested above. Maybe I’ll give that a go and see if it resolves the problem. For that to work, parameters passed to a lambda must be by reference. Is that true, @rlkoshak?

rlkoshak · December 11, 2017, 6:44pm

This is something relatively new that has popped up that I really don’t like because it really requires a deep understanding of the difference between .equals (i.e. ==) and identity equals (i.e. ===).

I have no good rule of thumb to provide. The best I can offer is if one of the arguments is null use === and use == otherwise. The problem is null doesn’t have a .equals so == won’t work.

I’m not certain. I do know if you pass a Map to a lambda and put into that Map the Map will preserve that change. I’ve never tried to reassign a passed in variable to a new object though which is what one would do with a Timer. I’m thinking that won’t work though.