Ruler startup random behavior

Setup, Configuration and Use Scripts & Rules
1

Hello all,

I’m running openHab2 on a Raspberry Pi 3 and having random problems when openHab starts. I have reduced the rule file to the minimum so, I can focus only in the code that generates the problem. When openHab starts, either at system startup or manually, the most of time, the log file show the following errors:

2017-06-22 19:01:41.457 [WARN ] [me.internal.engine.RuleContextHelper] - Variable 'lock1' on rule file 'default.rules' cannot be initialized with value 'org.eclipse.xtext.xbase.impl.XConstructorCallImplCustom@71019e (invalidFeatureIssueCode: null, validFeature: false, explicitConstructorCall: true, anonymousClassConstructorCall: false)': An error occurred during the script execution: null**

By the way, few times, it works perfectly without any error and, of course, without any change in rule file.

I have observed that the errors refer to variables that depends of imports definition (discrete variables never cause errors). Also, not always all variables cases the problem; some times only one or two.

I’m going really crazy. I have tried to full qualify variables, change the position on the rule file, change the code, etc. without success so, any help will be appreciated.

This is the rule file:

import java.util.ArrayList
import java.util.List
import java.util.concurrent.locks.ReentrantLock
import org.eclipse.smarthome.core.library.types.DecimalType
import org.eclipse.smarthome.model.script.actions.Timer

//
// calculos presion de la caldera
var boolean msgPresCalderaSent = false

//
// variables para PIR y Alarma
var Timer pirTimeout = null

//
// variables para el control de presencia
var boolean alguienEnCasa = false
var Timer presenciaTimeout = null // tiempo de ausencia para considerar que no hay nadie en casa

//
// Variables disco mode
var Timer discoTimer
var Number flipFlop
//
// para la gestión de toldos
var Timer toldo1Timer = null
var Timer toldo2Timer = null
var Timer toldo3Timer = null
//
// calculos de energia
var Number eByHour
var Number eByDay
//
// variables generales
var String msg

//
// variables para el subsistema de riego
var boolean cancelRiego = false
var Number zonaActPrev = 0
var Timer riegoTimer = null

var List<String> nombreZonaRiego = new ArrayList<String>()
var List<String> cmdZonaRiego = new ArrayList<String>()
var List<String> topicZonaRiego = new ArrayList<String>()

//
// Variables Termostato
var List<Number> TZ1TAHistory = new ArrayList<Number>()
var Number TZ1TAaverage
var List<Number> TZ2TAHistory = new ArrayList<Number>()
var Number TZ2TAaverage
var List<Number> TZ3TAHistory = new ArrayList<Number>()
var Number TZ3TAaverage
var List<Number> TZ4TAHistory = new ArrayList<Number>()
var Number TZ4TAaverage




var int TZ1i = 4
//var TAHistory1 = newArrayList(1, 2, 3) //no funciona

var java.util.concurrent.locks.ReentrantLock lock1  = new ReentrantLock()

//***********************************************************************************************
//
rule "System startup"
when
	System started
then
	logInfo("STARTUP","Start rule System startup")
	// Crea un timer para ejecutar la inicialización de variables despues que la persistencia se
	//	reestablezca
	logInfo("STARTUP","Create timer to init var and arrays")
	createTimer(now.plusSeconds(45)) [|
		logInfo("STARTUP","Initiating var and arrays")
		//
		// carga el array con los nombres de las zonas (nombre de los item del grupo RIEGO_TIEMPO)
		RIEGO_TIEMPO.members.forEach[item |
			nombreZonaRiego.add(item.name)
		]
		//
		// carga el array con el comando para activar y desactivar las zonas
		cmdZonaRiego.add("pcfgpio,65,") // Zona 1
		cmdZonaRiego.add("pcfgpio,66,") // Zona 2
		cmdZonaRiego.add("pcfgpio,67,") // Zona 3
		cmdZonaRiego.add("pcfgpio,68,") // Zona 4
		cmdZonaRiego.add("pcfgpio,69,") // Zona 5
		cmdZonaRiego.add("pcfgpio,70,") // Zona 6
		cmdZonaRiego.add("pcfgpio,71,") // Zona 7
		cmdZonaRiego.add("pcfgpio,72,") // Zona 8
		cmdZonaRiego.add("gpio,14,") 	// Zona 9
		cmdZonaRiego.add("gpio,15,") 	// Zona 10
		cmdZonaRiego.add("gpio,4,") 	// Zona 11
		cmdZonaRiego.add("pcfgpio,65,") // Zona 12
		cmdZonaRiego.add("pcfgpio,66,") // Zona 13
		cmdZonaRiego.add("pcfgpio,67,") // Zona 14
		cmdZonaRiego.add("pcfgpio,68,") // Zona 15
		cmdZonaRiego.add("pcfgpio,69,") // Zona 16
		cmdZonaRiego.add("pcfgpio,70,") // Zona 17
		cmdZonaRiego.add("pcfgpio,71,") // Zona 18
		cmdZonaRiego.add("") // Zona 19
		cmdZonaRiego.add("") // Zona 20
		//
		// carga el array con el mqtt topic para activar y desactivar las zonas
		topicZonaRiego.add("/Riego/cmd") 	// Zona 1
		topicZonaRiego.add("/Riego/cmd") 	// Zona 2
		topicZonaRiego.add("/Riego/cmd") 	// Zona 3
		topicZonaRiego.add("/Riego/cmd")		// Zona 4
		topicZonaRiego.add("/Riego/cmd")		// Zona 5
		topicZonaRiego.add("/Riego/cmd") 	// Zona 6
		topicZonaRiego.add("/Riego/cmd") 	// Zona 7
		topicZonaRiego.add("/Riego/cmd") 	// Zona 8
		topicZonaRiego.add("/Riego/cmd") 	// Zona 9
		topicZonaRiego.add("/Riego/cmd") 	// Zona 10
		topicZonaRiego.add("/Riego/cmd") 	// Zona 11
		topicZonaRiego.add("/Riego2/cmd")	// Zona 12
		topicZonaRiego.add("/Riego2/cmd") 	// Zona 13
		topicZonaRiego.add("/Riego2/cmd") 	// Zona 14
		topicZonaRiego.add("/Riego2/cmd") 	// Zona 15
		topicZonaRiego.add("/Riego2/cmd") 	// Zona 16
		topicZonaRiego.add("/Riego2/cmd") 	// Zona 17
		topicZonaRiego.add("/Riego2/cmd") 	// Zona 18
		topicZonaRiego.add("") // Zona 19
		topicZonaRiego.add("") // Zona 20
		//
		sendCommand(ZONA_ACT, 0)
		//
		// Inicializa variales por defecto al arranque
		//
		//
		if (RIEGO_HORA.state == NULL)
		{
			sendCommand(RIEGO_HORA, 0)
		}
		if (RIEGO_MINU.state == NULL)
		{
			sendCommand(RIEGO_MINU, 30)
		}
		if (RIEGO_SW.state == ON)
		{
			// si el riego automatico esta arrancado, el valor presistido (ON) se carga en el item pero
			//	no dispara la rule asociada. Esto fuerza a que se dispare.
			//logInfo("STARUP","RIEGO_SW es ON")
			sendCommand(RIEGO_SW, ON)
		}
		sendCommand(RIEGO_HORA,RIEGO_HORA.state.toString) //dispara la rule asociado a RIEGO_HORA
		sendCommand(RIEGO_MAN, OFF)
		//
		//
		logInfo("STARTUP","var and arrays initiated")
	]
	logInfo("STARTUP","End of rule System startup")
	
end

And this is the log with errors.

2017-06-22 18:18:08.840 [INFO ] [panel.internal.HABPanelDashboardTile] - Stopped HABPanel
2017-06-22 18:18:08.849 [INFO ] [.dashboard.internal.DashboardService] - Stopped dashboard
2017-06-22 18:18:22.007 [INFO ] [egram.internal.TelegramActionService] - Bot bot1 loaded from config file
2017-06-22 18:18:23.394 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at http://192.168.1.240:8080
2017-06-22 18:18:23.397 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at https://192.168.1.240:8443
2017-06-22 18:18:33.727 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'micasa.items'
2017-06-22 18:18:34.776 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mysql.persist'
2017-06-22 18:18:55.054 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.rules'
2017-06-22 18:18:56.961 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'micasa.sitemap'
2017-06-22 18:18:57.421 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'MiCasa.things'
2017-06-22 18:18:58.902 [INFO ] [b.core.service.AbstractActiveService] - HTTP Refresh Service has been started
2017-06-22 18:18:58.956 [INFO ] [penhab.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
2017-06-22 18:18:58.959 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'mibroker'
2017-06-22 18:18:59.575 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-06-22 18:18:59.882 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2017-06-22 18:19:00.091 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2017-06-22 18:19:00.946 [INFO ] [rvice.dhcp.ReceiveDHCPRequestPackets] - DHCP request packet listener online
2017-06-22 18:19:01.454 [WARN ] [me.internal.engine.RuleContextHelper] - Variable 'nombreZonaRiego' on rule file 'default.rules' cannot be initialized with value 'org.eclipse.xtext.xbase.impl.XConstructorCallImplCustom@13b4e64 (invalidFeatureIssueCode: null, validFeature: false, explicitConstructorCall: true, anonymousClassConstructorCall: false)': An error occurred during the script execution: null
2017-06-22 18:19:01.459 [WARN ] [me.internal.engine.RuleContextHelper] - Variable 'cmdZonaRiego' on rule file 'default.rules' cannot be initialized with value 'org.eclipse.xtext.xbase.impl.XConstructorCallImplCustom@85aedf (invalidFeatureIssueCode: null, validFeature: false, explicitConstructorCall: true, anonymousClassConstructorCall: false)': An error occurred during the script execution: null
2017-06-22 18:19:01.475 [WARN ] [me.internal.engine.RuleContextHelper] - Variable 'topicZonaRiego' on rule file 'default.rules' cannot be initialized with value 'org.eclipse.xtext.xbase.impl.XConstructorCallImplCustom@92e0f2 (invalidFeatureIssueCode: null, validFeature: false, explicitConstructorCall: true, anonymousClassConstructorCall: false)': An error occurred during the script execution: null
2017-06-22 18:19:01.480 [WARN ] [me.internal.engine.RuleContextHelper] - Variable 'TZ1TAHistory' on rule file 'default.rules' cannot be initialized with value 'org.eclipse.xtext.xbase.impl.XConstructorCallImplCustom@608d67 (invalidFeatureIssueCode: null, validFeature: false, explicitConstructorCall: true, anonymousClassConstructorCall: false)': An error occurred during the script execution: null
2017-06-22 18:19:01.490 [WARN ] [me.internal.engine.RuleContextHelper] - Variable 'TZ2TAHistory' on rule file 'default.rules' cannot be initialized with value 'org.eclipse.xtext.xbase.impl.XConstructorCallImplCustom@13a3255 (invalidFeatureIssueCode: null, validFeature: false, explicitConstructorCall: true, anonymousClassConstructorCall: false)': An error occurred during the script execution: null
2017-06-22 18:19:01.538 [WARN ] [me.internal.engine.RuleContextHelper] - Variable 'TZ3TAHistory' on rule file 'default.rules' cannot be initialized with value 'org.eclipse.xtext.xbase.impl.XConstructorCallImplCustom@f0438e (invalidFeatureIssueCode: null, validFeature: false, explicitConstructorCall: true, anonymousClassConstructorCall: false)': An error occurred during the script execution: null
2017-06-22 18:19:01.559 [WARN ] [me.internal.engine.RuleContextHelper] - Variable 'TZ4TAHistory' on rule file 'default.rules' cannot be initialized with value 'org.eclipse.xtext.xbase.impl.XConstructorCallImplCustom@1cda5d1 (invalidFeatureIssueCode: null, validFeature: false, explicitConstructorCall: true, anonymousClassConstructorCall: false)': An error occurred during the script execution: null
2017-06-22 18:19:01.577 [WARN ] [me.internal.engine.RuleContextHelper] - Variable 'lock1' on rule file 'default.rules' cannot be initialized with value 'org.eclipse.xtext.xbase.impl.XConstructorCallImplCustom@10584a2 (invalidFeatureIssueCode: null, validFeature: false, explicitConstructorCall: true, anonymousClassConstructorCall: false)': An error occurred during the script execution: null
2017-06-22 18:19:01.853 [ERROR] [nding.network.service.NetworkService] - Cannot use DHCP listen: iPhonedeSandra: unknown error
2017-06-22 18:19:03.453 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2017-06-22 18:19:03.583 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel

And, for those that are think that I’m crazy, here is the most recent log file showing a correct startup:

2017-06-22 19:12:10.169 [INFO ] [basic.internal.servlet.WebAppServlet] - Stopped Basic UI
2017-06-22 19:12:20.650 [INFO ] [b.core.service.AbstractActiveService] - HTTP Refresh Service has been shut down
2017-06-22 19:12:20.687 [INFO ] [penhab.io.transport.mqtt.MqttService] - Stopping broker connection 'mibroker'
2017-06-22 19:12:20.869 [INFO ] [assic.internal.servlet.WebAppServlet] - Stopped Classic UI
2017-06-22 19:12:20.929 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Stopped HABmin servlet
2017-06-22 19:12:21.489 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Stopped Paper UI
2017-06-22 19:12:21.503 [INFO ] [panel.internal.HABPanelDashboardTile] - Stopped HABPanel
2017-06-22 19:12:21.517 [INFO ] [.dashboard.internal.DashboardService] - Stopped dashboard
2017-06-22 19:13:36.815 [INFO ] [egram.internal.TelegramActionService] - Bot bot1 loaded from config file
2017-06-22 19:13:38.206 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at http://192.168.1.240:8080
2017-06-22 19:13:38.209 [INFO ] [.dashboard.internal.DashboardService] - Started dashboard at https://192.168.1.240:8443
2017-06-22 19:13:47.795 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'micasa.items'
2017-06-22 19:13:48.819 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mysql.persist'
2017-06-22 19:14:08.334 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.rules'
2017-06-22 19:14:09.998 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'micasa.sitemap'
2017-06-22 19:14:10.489 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'MiCasa.things'
2017-06-22 19:14:11.797 [INFO ] [b.core.service.AbstractActiveService] - HTTP Refresh Service has been started
2017-06-22 19:14:11.842 [INFO ] [penhab.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
2017-06-22 19:14:11.844 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'mibroker'
2017-06-22 19:14:12.580 [INFO ] [basic.internal.servlet.WebAppServlet] - Started Basic UI at /basicui/app
2017-06-22 19:14:12.725 [INFO ] [assic.internal.servlet.WebAppServlet] - Started Classic UI at /classicui/app
2017-06-22 19:14:12.945 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2017-06-22 19:14:13.716 [INFO ] [rvice.dhcp.ReceiveDHCPRequestPackets] - DHCP request packet listener online
2017-06-22 19:14:14.139 [ERROR] [nding.network.service.NetworkService] - Cannot use DHCP listen: iPhonedeSandra: unknown error
2017-06-22 19:14:15.767 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2017-06-22 19:14:15.907 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2017-06-22 19:14:30.181 [INFO ] [lipse.smarthome.model.script.STARTUP] - Start rule System startup
2017-06-22 19:14:30.183 [INFO ] [lipse.smarthome.model.script.STARTUP] - Create timer to init var and arrays
2017-06-22 19:14:45.218 [INFO ] [lipse.smarthome.model.script.STARTUP] - End of rule System startup
2017-06-22 19:15:05.393 [INFO ] [lipse.smarthome.model.script.STARTUP] - Start rule System startup
2017-06-22 19:15:05.396 [INFO ] [lipse.smarthome.model.script.STARTUP] - Create timer to init var and arrays
2017-06-22 19:15:05.411 [INFO ] [lipse.smarthome.model.script.STARTUP] - End of rule System startup
2017-06-22 19:15:15.206 [INFO ] [lipse.smarthome.model.script.STARTUP] - Initiating var and arrays
2017-06-22 19:15:15.319 [INFO ] [lipse.smarthome.model.script.STARTUP] - var and arrays initiated

Thanks in advance for any help.
Antonio Castillo

2

First, you should not import anything from org.eclipse.smarthome nor anything from org.openhab. These are not imported for you.

Second, those are warnings, not errors. After the warnings do the Rules still work or do they fail?

If you initialize them in the System started rule do you still get the error? So set the to null above the rules and in System started call new ReentrantLock.

Try using newArrayList() instead of new ArrayList<Number>().

3

You’re a genius !!! I wasted a lot of time trying to solve it by myself instead to ask the forum… Also, I’m an old programmer (Fortran and COBOL epoch) so, my mind works in linear way not object-oriented! This added that I’m a newbie in the Java world, it is possible that I’d never find the solution. So thank very much for your help.

I have changed the rule file and put the variable initialization on System Start rule and the problem was solved.

Also, I’d like to know why this happened so, could you teach me why the definitions must be this way?

Thanks,
Antonio

4

One thing at a time.

The Rule’s Domain Specific Language (DSL) is not object oriented. It does have access to Java objects but the style of writing a rule is not object oriented. I’m not sure what to call it anymore (I used to call it closer to an actor-based language but it doesn’t really fit that either). But whatever you call it, it has more in common with the procedural type programming you are used to than object oriented programming.

While the Rules DSL allows one to access Java classes and objects, it is as unlike Java as Java is unlike Fortran. It is its own language.

I don’t know. Based on the behavior your described there was clearly some sort of timing problem which explains why you only saw the warnings sometimes. By putting the initialization of the variables in the System started rule we delayed it until this timing problem passed. This is why it worked. What the timing problem was I can’t say. There is nothing theoretically wrong with what you originally had written.

I’ll leave off by mentioning that it is pretty clear you are coming from a procedural programming background. As such I suspect you will encounter a lot of frustration because the Rules DSL sometimes seems to actively fight against that style of programming.

I don’t know enough to understand your rules (language plus the use of not terribly meaningful names to someone not familiar with your setup). But I do have some generic advice which might make your life easier in the long run.

  • The Rules DSL, as you can see, doesn’t really like for you to set up data structures. It is not equipped to handle that and actively disables features from its base language (Xtend) that let you do that (e.g. no ability to create classes, primitive arrays, etc). Look for ways to avoid the need to store data, particularly static data, in data structures (in your case the ArrayLists. There are a number of ways you can do this depending on the nature of the data including:

    • use HashMaps instead of ArrayLists keyed on the Item’s name instead of blind indices, if you must store data in vars and vals
    • use meaningful names for Items and take advantage of String parsing and manipulation to extract needed info (i.e. make static data part of the Item’s name)
    • use unbound Items to store state instead of vars and vals (additional advantage is you can use persistence)
    • use Groups and unbound Items instead of ArrayLists and HashMaps to store collections of state

  • Let the Rules DSL determine type for you. When you set the type, particularly when you set the type as a primitive, it causes the Rules DSL extra work because every time that variable gets used it must be converted to an Object behind the scenes and back to a primitive and sometimes it isn’t very good at that. So, when you declare a variable and give it an initial value that is meaningful (i.e. not null) don’t specify the type.

  • Always use MyItem.sendCommand(state) instead of sendCommand(MyItem, state) unless you are in a situation where you construct the Item name dynamically. The Item’s method is far better able to handle different data types, in particular primitive data types, that the Actions are.

  • Limit the scope of your variables as much as possible. If you only use a variable in one rule and it gets reset each time the rule is called, it should be declared and defined within that rule, not as a global.

  • If you have a cross cutting concern (e.g. alerting is a common one), centralize that code in a Rule triggered by an Item.

  • Read the Design Pattern postings. They distil what I consider the best practices for how to code in the Rules DSL. In particular, the Unbound Item, Working with Groups in Rule, Associated Items and Separation of Behaviors will help illustrate the above.

Good luck!

5

Thank you for your comments. I will follow they carefully. I’m sure that they will make may live easier…

Antonio,