Function execution is broken

Setup, Configuration and Use Scripts & Rules
1

I created a simple system to enable and disable automatic mode for several things, for example the room temperature. Therefor there are several items in a hierarchical structure:

Switch Automode "Automatik" (All, LogRRDRestore)
Switch AutomodeHeatingmode "Automatik Heizung" (All, LogRRDRestore)
Switch AutomodeHeatingmodeBad "Automatik Heizung Bad" (All, LogRRDRestore)
Switch AutomodeHeatingmodeBesprechung "Automatik Heizung Besprechung" (All, LogRRDRestore)
Switch AutomodeHeatingmodeBuero "Automatik Heizung Büro" (All, LogRRDRestore)
//...

In a rule I do:

//...
	if(checkAutomode.apply(AutomodeHeatingmodeBuero)) {
		// do something
	}
//...

The function is:

val org.eclipse.xtext.xbase.lib.Functions$Function1 checkAutomode = [
    SwitchItem item |
    
	var isInAutomode = true
	var parts = item.name.split("(?=\\p{Upper})")
	logInfo("checkAutomode", "{}: {}", item.name, parts.length)
	for(var i=0; i<parts.length; i++) {
		// generate current item name
		var currentItemName = ""
		for(var j=0; j<=i; j++){
			currentItemName += parts.get(j)
		}
	
		var currentItem = All.members.findFirst[name.equals(currentItemName)]

		logInfo("checkAutomode", "{}: {}", item.name, currentItem)
			
		if(currentItem.state != ON) {
			isInAutomode = false
		}
	}

	logInfo("checkAutomode", "{} result: {}", item.name, isInAutomode)

	isInAutomode
]

What the function should do really simple: It cuts the name on the uppercase letters and checks every item if it is false.

In some cases the function execution is broken. In my opinion it has something to do if the function is executed in parallel. This is the log:

2017-05-14 23:00:00.059 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeBesprechung: 3
2017-05-14 23:00:00.062 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeSchlafzimmer: 3
2017-05-14 23:00:00.084 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeBad: 3
2017-05-14 23:00:00.098 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeWohnzimmer: 3
2017-05-14 23:00:00.110 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeBad result: true
2017-05-14 23:00:00.112 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeSchlafzimmer: Automode (Type=SwitchItem, State=ON, Label=Automatik, Category=null, Groups=[All, LogRRDRestore])
2017-05-14 23:00:00.115 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeKueche: 3
2017-05-14 23:00:00.124 [INFO ] [marthome.model.script.temperatur Bad] - targetTemperature: 17.0
2017-05-14 23:00:00.146 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeBesprechung: Automode (Type=SwitchItem, State=ON, Label=Automatik, Category=null, Groups=[All, LogRRDRestore])
2017-05-14 23:00:00.153 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeBuero: 3
2017-05-14 23:00:00.180 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeWohnzimmer: Automode (Type=SwitchItem, State=ON, Label=Automatik, Category=null, Groups=[All, LogRRDRestore])
2017-05-14 23:00:00.196 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeKueche: Automode (Type=SwitchItem, State=ON, Label=Automatik, Category=null, Groups=[All, LogRRDRestore])
2017-05-14 23:00:00.199 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeSchlafzimmer: AutomodeHeatingmode (Type=SwitchItem, State=OFF, Label=Automatik Heizung, Category=null, Groups=[All, LogRRDRestore])
2017-05-14 23:00:00.199 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeBuero: Automode (Type=SwitchItem, State=ON, Label=Automatik, Category=null, Groups=[All, LogRRDRestore])
2017-05-14 23:00:00.213 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeBesprechung: AutomodeHeatingmode (Type=SwitchItem, State=OFF, Label=Automatik Heizung, Category=null, Groups=[All, LogRRDRestore])
2017-05-14 23:00:00.257 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeWohnzimmer: AutomodeHeatingmode (Type=SwitchItem, State=OFF, Label=Automatik Heizung, Category=null, Groups=[All, LogRRDRestore])
2017-05-14 23:00:00.288 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeSchlafzimmer result: false
2017-05-14 23:00:00.300 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeKueche: AutomodeHeatingmode (Type=SwitchItem, State=OFF, Label=Automatik Heizung, Category=null, Groups=[All, LogRRDRestore])
2017-05-14 23:00:00.303 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeBuero: AutomodeHeatingmode (Type=SwitchItem, State=OFF, Label=Automatik Heizung, Category=null, Groups=[All, LogRRDRestore])
2017-05-14 23:00:00.315 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeBesprechung: AutomodeHeatingmodeBesprechung (Type=SwitchItem, State=OFF, Label=Automatik Heizung Besprechung, Category=null, Groups=[All, LogRRDRestore])
2017-05-14 23:00:00.325 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeBesprechung result: false
2017-05-14 23:00:00.353 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeWohnzimmer: AutomodeHeatingmodeWohnzimmer (Type=SwitchItem, State=OFF, Label=Automatik Heizung Wohnzimmer, Category=null, Groups=[All, LogRRDRestore])
2017-05-14 23:00:00.369 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeWohnzimmer result: false
2017-05-14 23:00:00.379 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeBuero: AutomodeHeatingmodeBuero (Type=SwitchItem, State=OFF, Label=Automatik Heizung Büro, Category=null, Groups=[All, LogRRDRestore])
2017-05-14 23:00:00.390 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeBuero result: false
2017-05-14 23:00:00.393 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeKueche: AutomodeHeatingmodeKueche (Type=SwitchItem, State=OFF, Label=Automatik Heizung Küche, Category=null, Groups=[All, LogRRDRestore])
2017-05-14 23:00:00.407 [INFO ] [smarthome.model.script.checkAutomode] - AutomodeHeatingmodeKueche result: false

In this case the function is called several times in parallel for different rooms and for AutomodeHeatingmodeBad the execution jumps over the for loop although the logInfo the line before says the length of parts is 3.

Any suggestions?

2

I’ve had problems in the past with lambdas running in parallel. I can’t say that this is the case here but I’ve fixed the problem by using ReentrantLocks.

However, I do not understand what this code does.

You split the name on the capital letters and then immediately rebuild the name . So doesn’t item.name == currentItemName after the for loop? If so why go through the trouble? I must be missing something but to me it looks like in the end item == currentItem so you can just collapse this entire lambda down to

item.state == ON
3

If the input item is “AutomodeHeatingmodeBuero” the function checks “Automode” then “AutomodeHeatingmode” then “AutomodeHeatingmodeBuero”. If any of this items is false the function returns false. So it’s easy to to disable all heating automation by switching “AutomodeHeatingmode” to off.

Locks doesn’t seem to fix it. I tried it before but removed it here for clarity. Maybe I implemented it wrong. Full code is (obviously without the comments):

val org.eclipse.xtext.xbase.lib.Functions$Function1 checkAutomode = [
    SwitchItem item |
    
//	var java.util.concurrent.locks.ReentrantLock lock  = new java.util.concurrent.locks.ReentrantLock()
//
//    lock.lock()
	var isInAutomode = true
//    try {
	    var parts = item.name.split("(?=\\p{Upper})")
		logInfo("checkAutomode", "{}: {}", item.name, parts.length)
		for(var i=0; i<parts.length; i++) {
			// generate current item name
			var currentItemName = ""
			for(var j=0; j<=i; j++){
				currentItemName += parts.get(j)
			}
	
			var currentItem = All.members.findFirst[name.equals(currentItemName)]

			logInfo("checkAutomode", "{}: {}", item.name, currentItem)
			
			if(currentItem.state != ON) {
				isInAutomode = false
			}
		}
//	} finally{
//		lock.unlock()
//	}

	logInfo("checkAutomode", "{} result: {}", item.name, isInAutomode)

	isInAutomode
]
4

Add a try catch to the lambda and log out in the catch. There might be an exception thrown that causes the lambda and rule to fail silently. I’ve seen that before with certain exceptions. Beyond that I’ve no ideas.

5

Thanks for your help. Shouldn’t be an exception in the log if there is any and it isn’t catched? Also the rule doesn’t seem to fail as it “just” skips the for loop.

So there are two options. There is either a mistake in the function or the rule engine is broken.

Anyone else any suggestions?

6

If it is skipping the for loop the rule isn’t working.

Not all exceptions are caught and logged. In particular I’ve found exceptions thrown from lambdas often are not caught our logged.

7

Well, the rule is working except for one out of about 50 times.

		logInfo("checkAutomode", "{}: {}", item.name, parts.length)
		for(var i=0; i<parts.length; i++) {

Sometimes something happens between these two lines. If you look at the log you see parts.length is 3. But then something happens so i<parts.length is false so it jumps over the loop.

8

Or your findFirst line returns null and an exception is thrown when you try to log out currentItem on the next line. The exception kills the lambda and does not get caught so the rule fails silently.

I’ve seen this before which is why I still recommend adding try catch to the lambda.

I really recommend adding try catch to all lambdas for this same reason.

9

Or if you can guess where the problem lies, have a look for it directly

logInfo ("diag", "Looking for " + currentItemName)
var currentItem = All.members.findFirst[name.equals(currentItemName)]
if (currentItem == null) {
    logInfo ("diag", "Did not find it")
}