Erratic rule execution

mganapa · September 10, 2015, 2:56am

I have rule to turn on and off the lights based on dusk and dawn times calculated using astro binding. The astro binding items get correct values and no errors there. However, the rule works sometimes and sometimes it doesn’t. the rule is as below.

import org.joda.time.*
import org.openhab.core.library.types.*
import org.openhab.core.library.types.PercentType
import org.openhab.core.library.items.SwitchItem
import org.openhab.model.script.actions.*
import org.openhab.model.script.actions.Timer
import java.util.HashMap
import java.util.LinkedHashMap
import java.util.ArrayList
import java.util.Map
import java.util.concurrent.locks.Lock
import java.util.concurrent.locks.ReentrantLock
    
    var Lock lock = new ReentrantLock()

    /*
     * This rule turns ON front porch lights on at dusk.
     */ 
	rule "Lights ON at Dusk"
	
	when
    
    	System started or
		Time cron "0 * * * * ?" 
		        
    then
        var DateTime daystart = new DateTime((dawnStart.state as DateTimeType).calendar.timeInMillis)
        var DateTime dayend = new DateTime((duskEnd.state as DateTimeType).calendar.timeInMillis)
        val boolean isDark = now.isBefore(daystart) || now.isAfter(dayend)
	//	val boolean isDark = now.isAfter(dayend)
		
		logInfo("Date Midnight: " , (now.toDateMidnight).toString)
		logInfo( "Dusk Rule", isDark.toString)
        
        lock.lock()
 
		DuskOn.members.forEach [ pl |
        	var plStateOnOff = pl.getStateAs(pl.acceptedDataTypes.get(0))
        	logDebug( "Dusk Rule", "Item Name" + pl.name)
        	if(isDark){
        		logInfo( "Dusk Rule", "Is Dusk")
        		if (plStateOnOff == OFF) {
        			logInfo( "Dusk Rule", "Item State" + plStateOnOff.toString)
        			sendCommand(pl, ON)
        		} 
        	} else {
        		logInfo( "Dusk Rule", "Is NOT Dusk")
        		if(plStateOnOff == ON){
        			logInfo( "Dusk Rule", "Item State" + plStateOnOff.toString)
        			sendCommand(pl, OFF)
        		}
	        }
        ] 
        lock.unlock()
     
    end

When it doesn’t work the following exception can be see in the openHAB log.

2015-09-09 20:00:00.026 [ERROR] [.o.m.r.i.engine.ExecuteRuleJob] - Error during the execution of rule Lights ON at Dusk
java.lang.IllegalStateException: Could not invoke method: org.openhab.model.script.actions.BusEvent.sendCommand(java.lang.String,java.lang.String) on instance: null
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:738) ~[na:na]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._featureCallOperation(XbaseInterpreter.java:713) ~[na:na]
	at sun.reflect.GeneratedMethodAccessor172.invoke(Unknown Source) ~[na:na]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:1.8.0_51]
	at java.lang.reflect.Method.invoke(Unknown Source) ~[na:1.8.0_51]
	at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) ~[na:na]
	at org.openhab.model.script.interpreter.ScriptInterpreter.internalFeatureCallDispatch(ScriptInterpreter.java:69) ~[na:na]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateAbstractFeatureCall(XbaseInterpreter.java:658) ~[na:na]
	at sun.reflect.GeneratedMethodAccessor180.invoke(Unknown Source) ~[na:na]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:1.8.0_51]
	at java.lang.reflect.Method.invoke(Unknown Source) ~[na:1.8.0_51]
	at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) ~[na:na]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) ~[na:na]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateBlockExpression(XbaseInterpreter.java:321) ~[na:na]
	at sun.reflect.GeneratedMethodAccessor189.invoke(Unknown Source) ~[na:na]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:1.8.0_51]
	at java.lang.reflect.Method.invoke(Unknown Source) ~[na:1.8.0_51]
	at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) ~[na:na]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) ~[na:na]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateIfExpression(XbaseInterpreter.java:329) ~[na:na]
	at sun.reflect.GeneratedMethodAccessor191.invoke(Unknown Source) ~[na:na]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:1.8.0_51]
	at java.lang.reflect.Method.invoke(Unknown Source) ~[na:1.8.0_51]
	at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) ~[na:na]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) ~[na:na]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateBlockExpression(XbaseInterpreter.java:321) ~[na:na]
	at sun.reflect.GeneratedMethodAccessor189.invoke(Unknown Source) ~[na:na]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:1.8.0_51]
	at java.lang.reflect.Method.invoke(Unknown Source) ~[na:1.8.0_51]
	at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) ~[na:na]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) ~[na:na]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateIfExpression(XbaseInterpreter.java:329) ~[na:na]
	at sun.reflect.GeneratedMethodAccessor191.invoke(Unknown Source) ~[na:na]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:1.8.0_51]
	at java.lang.reflect.Method.invoke(Unknown Source) ~[na:1.8.0_51]
	at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) ~[na:na]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) ~[na:na]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateBlockExpression(XbaseInterpreter.java:321) ~[na:na]
	at sun.reflect.GeneratedMethodAccessor189.invoke(Unknown Source) ~[na:na]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:1.8.0_51]
	at java.lang.reflect.Method.invoke(Unknown Source) ~[na:1.8.0_51]
	at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) ~[na:na]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) ~[na:na]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:204) ~[na:na]
	at org.eclipse.xtext.xbase.interpreter.impl.ClosureInvocationHandler.doInvoke(ClosureInvocationHandler.java:46) ~[na:na]
	at org.eclipse.xtext.xbase.interpreter.impl.AbstractClosureInvocationHandler.invoke(AbstractClosureInvocationHandler.java:28) ~[na:na]
	at com.sun.proxy.$Proxy84.apply(Unknown Source) ~[na:na]
	at org.eclipse.xtext.xbase.lib.IterableExtensions.forEach(IterableExtensions.java:395) ~[na:na]
	at sun.reflect.GeneratedMethodAccessor201.invoke(Unknown Source) ~[na:na]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:1.8.0_51]
	at java.lang.reflect.Method.invoke(Unknown Source) ~[na:1.8.0_51]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:729) ~[na:na]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._featureCallOperation(XbaseInterpreter.java:713) ~[na:na]
	at sun.reflect.GeneratedMethodAccessor172.invoke(Unknown Source) ~[na:na]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:1.8.0_51]
	at java.lang.reflect.Method.invoke(Unknown Source) ~[na:1.8.0_51]
	at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) ~[na:na]
	at org.openhab.model.script.interpreter.ScriptInterpreter.internalFeatureCallDispatch(ScriptInterpreter.java:69) ~[na:na]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateMemberFeatureCall(XbaseInterpreter.java:549) ~[na:na]
	at sun.reflect.GeneratedMethodAccessor179.invoke(Unknown Source) ~[na:na]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:1.8.0_51]
	at java.lang.reflect.Method.invoke(Unknown Source) ~[na:1.8.0_51]
	at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) ~[na:na]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) ~[na:na]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter._evaluateBlockExpression(XbaseInterpreter.java:321) ~[na:na]
	at sun.reflect.GeneratedMethodAccessor189.invoke(Unknown Source) ~[na:na]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:1.8.0_51]
	at java.lang.reflect.Method.invoke(Unknown Source) ~[na:1.8.0_51]
	at org.eclipse.xtext.util.PolymorphicDispatcher.invoke(PolymorphicDispatcher.java:291) ~[na:na]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.internalEvaluate(XbaseInterpreter.java:218) ~[na:na]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.evaluate(XbaseInterpreter.java:204) ~[na:na]
	at org.openhab.model.script.internal.engine.ScriptImpl.execute(ScriptImpl.java:59) ~[na:na]
	at org.openhab.model.rule.internal.engine.ExecuteRuleJob.execute(ExecuteRuleJob.java:55) ~[na:na]
	at org.quartz.core.JobRunShell.run(JobRunShell.java:213) [quartz-all-2.1.7.jar:na]
	at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:557) [quartz-all-2.1.7.jar:na]
Caused by: java.lang.IllegalArgumentException: argument type mismatch
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_51]
	at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source) ~[na:1.8.0_51]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[na:1.8.0_51]
	at java.lang.reflect.Method.invoke(Unknown Source) ~[na:1.8.0_51]
	at org.eclipse.xtext.xbase.interpreter.impl.XbaseInterpreter.invokeOperation(XbaseInterpreter.java:729) ~[na:na]
	... 74 common frames omitted

Environment: OpenHAB 1.7.1 JAVA 1.8.0_51 WIndows 10 Aeon USB ZStick Gen 5

Any help is appreciated.

watou · September 10, 2015, 6:50am

I don’t know why this would match the (String,String) method signature (rule engine bug?), but would it work if you replaced the sendCommand(item, state) with item.sendCommand(state), like

pl.sendCommand(ON)

Also, is there any reason you don’t test pl.state instead of having a plStateOnOff variable?

Lastly, could you instead trigger on switch items changed by the astro binding instead of running this rule every minute and on system startup?

mganapa · October 14, 2015, 7:28pm

@watou Thanks for your response. I tried your suggestion item.sendCommand(state) and it didn’t help. Most of my code is copied over from an example someone posted. There is no good reason as to why I have this particular syntax as opposed to another, atleast till this point.

The issue is something like this: OpenHAB instance is started - If rule works after dusk (isDark becomes true) it works consistently and never fails. If I restart openHAB there is a good chance that the rule might not work anymore. I have to keep restarting OpenHAB until the rule works again.

There is no pattern to finding how to restart OpenHAB in such a way that the rule works.

watou · October 14, 2015, 11:20pm

Your issue sounds similar to this post and issues 2646, 2692, and 3166. I don’t have more to add, but you might inquire in those places to see if anyone has found workarounds or more insight into causes.