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
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.
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.
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.
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.
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?
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.