Timer error messages

[danst (Daniel)]

Hi,

I get the following error messages every now and then in my logs. There does not seem to be any indication in the message on where I should look (beside the timers). Any idea on where to start debugging?

Thanks,

Daniel

2020-04-30 07:12:37.532 [ERROR] [org.quartz.core.JobRunShell         ] - Job DEFAULT.Timer 25 2020-04-30T07:12:37.514+02:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  logInfo(<XStringLiteralImpl>,<XStringLiteralImpl>)
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@5c94f743 (conditionalExpression: false)
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  <XFeatureCallImplCustom>.sendCommand(<XFeatureCallImplCustom>)
  <XFeatureCallImplCustom>.sendCommand(<XFeatureCallImplCustom>)
  <XFeatureCallImplCustom>.sendCommand(<XFeatureCallImplCustom>)
} ] threw an unhandled Exception: 
java.lang.IllegalStateException: Could not invoke method: org.eclipse.smarthome.model.script.actions.BusEvent.sendCommand(org.eclipse.smarthome.core.items.Item,java.lang.Number) on instance: null
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1192) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1150) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1136) ~[?:?]
	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:861) ~[?:?]
	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._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.$Proxy592.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:?]
Caused by: java.lang.IllegalArgumentException: java.lang.ClassCastException@f4599cc
	at sun.reflect.GeneratedMethodAccessor159.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_232]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_232]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1175) ~[?:?]
	... 19 more
2020-04-30 07:12:37.540 [ERROR] [org.quartz.core.ErrorLogger         ] - Job (DEFAULT.Timer 25 2020-04-30T07:12:37.514+02:00: Proxy for org.eclipse.xtext.xbase.lib.Procedures$Procedure0: [ | {
  logInfo(<XStringLiteralImpl>,<XStringLiteralImpl>)
  org.eclipse.xtext.xbase.impl.XIfExpressionImpl@5c94f743 (conditionalExpression: false)
  logInfo(<XStringLiteralImpl>,<XBinaryOperationImplCustom>)
  <XFeatureCallImplCustom>.sendCommand(<XFeatureCallImplCustom>)
  <XFeatureCallImplCustom>.sendCommand(<XFeatureCallImplCustom>)
  <XFeatureCallImplCustom>.sendCommand(<XFeatureCallImplCustom>)
} ] threw an exception.
org.quartz.SchedulerException: Job threw an unhandled exception.
	at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [bundleFile:?]
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573) [bundleFile:?]
Caused by: java.lang.IllegalStateException: Could not invoke method: org.eclipse.smarthome.model.script.actions.BusEvent.sendCommand(org.eclipse.smarthome.core.items.Item,java.lang.Number) on instance: null
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1192) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1150) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1136) ~[?:?]
	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:861) ~[?:?]
	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._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.$Proxy592.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) ~[?:?]
	... 1 more
Caused by: java.lang.IllegalArgumentException: java.lang.ClassCastException@f4599cc
	at sun.reflect.GeneratedMethodAccessor159.invoke(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_232]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_232]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1175) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:1150) ~[?:?]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._invokeFeature(XbaseInterpreter.java:1136) ~[?:?]
	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:861) ~[?:?]
	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._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.$Proxy592.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) ~[?:?]
	... 1 more

[lfs_alp5 (Alpoy)]

I would guess some cron rule is doing a “sendCommand” on an invalid item or the value sent to the item is of an invalid type

[rossko57]

@danst

where I should look (beside the timers)

Good start.
It does show you a “skeleton” of the timer code, so you.d look for one that begins with -

logInfo(xx,xx)
if ( ) {
 xxx
}
logInfo(xx,xx)
xx.sendCommand(xx)
xx.sendCommand(xx)
xx.sendCommand(xx)
xx

which should be fairly distinctive.
It’s probably blown up on that third sendCommand, trying to make a command from something that isn’t available.

Before diving in too deep, if you have long-running timers and if you have been editing rules files - beware orphan timers.

[SOLVED] Unhandled Exception w/o active rules

That looks like the sort of report you get from orphaned Timers - typically, a long running timer was spawned by a rule, and the rule file was later edited on other business. When the rule file reloads, the context for the waiting timer is destroyed - but the quartz scheduled timer job is not. Maybe hours later, the now “orphaned” timer code executes and usually fails with a NullPointerException because some variable it references no longer exists.