Execution of rule and return point

I’m completely lost with a simple rule and especially with the return behavior…
I read out my solar converter with SBFspot and try to devide the result string into the relevant values:

import java.util.concurrent.locks.ReentrantLock

var ReentrantLock lock  = new ReentrantLock()


rule "SBFspot"
when
	Time cron "0,30,45,15 * * * * ?"
then
	lock.lock()
	try
	{
	var String raw_output = executeCommandLine("/usr/local/bin/sbfspot.3/SBFspot -v -finq -nocsv -nosql",10000)
	var lines = raw_output.split('\n')
	
	logInfo("Exit at", "1")
	
	var V_EToday = lines.get(39).split(': ').get(1).split('kW').get(0)
	logInfo("Exit at", "2")
	var V_ETotal = lines.get(40).split(': ').get(1).split('kW').get(0)
	logInfo("Exit at", "3")
	var V_EAct = lines.get(52).split(': ').get(1).split('k').get(0)
	logInfo("Exit at", "4")

	

	PV_EAct.postUpdate(V_EAct)
	PV_ETotal.postUpdate(V_ETotal)
	PV_EToday.postUpdate(V_EToday)
		
	}
	finally{
		lock.unlock()
	}
end

Nothing special and in principal it works… but it figured out, that not all values are updated and the rule does not be executed until the last command. The log looks like:

21:02:31.511 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'pv.rules'
21:02:34.232 [ERROR] [ntime.internal.engine.ExecuteRuleJob] - Error during the execution of rule SBFspot: An error occurred during the script execution: The name '<unkown>' cannot be resolved to an item or type.
21:02:49.489 [INFO ] [lipse.smarthome.model.script.Exit at] - 1
21:02:49.501 [INFO ] [lipse.smarthome.model.script.Exit at] - 2
21:02:49.513 [INFO ] [lipse.smarthome.model.script.Exit at] - 3
21:02:49.527 [INFO ] [lipse.smarthome.model.script.Exit at] - 4
21:03:03.639 [INFO ] [lipse.smarthome.model.script.Exit at] - 1
21:03:03.657 [INFO ] [lipse.smarthome.model.script.Exit at] - 2
21:03:03.675 [INFO ] [lipse.smarthome.model.script.Exit at] - 3
21:03:03.690 [INFO ] [lipse.smarthome.model.script.Exit at] - 4
21:03:19.039 [INFO ] [lipse.smarthome.model.script.Exit at] - 1
21:03:34.287 [INFO ] [lipse.smarthome.model.script.Exit at] - 1
21:03:48.381 [INFO ] [lipse.smarthome.model.script.Exit at] - 1
21:04:03.735 [INFO ] [lipse.smarthome.model.script.Exit at] - 1
21:04:03.751 [INFO ] [lipse.smarthome.model.script.Exit at] - 2
21:04:03.764 [INFO ] [lipse.smarthome.model.script.Exit at] - 3
21:04:03.777 [INFO ] [lipse.smarthome.model.script.Exit at] - 4
21:04:19.112 [INFO ] [lipse.smarthome.model.script.Exit at] - 1
21:04:34.489 [INFO ] [lipse.smarthome.model.script.Exit at] - 1
21:04:34.503 [INFO ] [lipse.smarthome.model.script.Exit at] - 2
21:04:34.516 [INFO ] [lipse.smarthome.model.script.Exit at] - 3
21:04:34.530 [INFO ] [lipse.smarthome.model.script.Exit at] - 4

Can somebody explain that behavior? I tried before without the ReentrantLock, but the behavior likes the same…

Looking at timings, the rule is sometimes getting lost in/before the first lines.get()

Maybe the preceding executeCommandLine() doesn’t always return what you expect. I would add a report logInfo of the number of text lines as well. You might need to do something else if you don’t have 40 lines.

Why are you using a ReentrantLock for a cron triggered rule?

I strongly recommend against the use of locks unless you are absolutely certain that you have a problem caused by multiple changes being made to the same resource from multiple rules running at the same time. And even then I recommend reconsidering your architecture or approach to not need the lock.

To start, get rid of the lock.

I agree with rossko57, the most likely problem is the output is not what you think it is every time you execute that script. Either there are not 39 lines of text or there are no ‘:’ or the like and the best way to solve something like that is to actually log raw_output.

@rlkoshak: Good question - To be onest, I have no idea. I tried out if that could fix the problem… But It’s useless for that kind of rule, yes!?

I removed the lock and reworked the logging like recommended, the rule looks now:

rule "SBFspot"
when
	Time cron "0,30,45,15 * * * * ?"
then
	var String raw_output = executeCommandLine("/usr/local/bin/sbfspot.3/SBFspot -v -finq -nocsv -nosql",10000)
	var lines = raw_output.split('\n')
	
	logInfo("Exit at", "1")
	logInfo("lines:", lines.size.toString)
	logInfo("Raw_Output:", raw_output)
	
	var V_EToday = lines.get(39).split(': ').get(1).split('kW').get(0)
	logInfo("Exit at", "2")
	var V_ETotal = lines.get(40).split(': ').get(1).split('kW').get(0)
	logInfo("Exit at", "3")
	var V_EAct = lines.get(52).split(': ').get(1).split('k').get(0).split('  ').get(1)
	logInfo("Exit at", "4")

	PV_EAct.postUpdate(V_EAct)
	PV_ETotal.postUpdate(V_ETotal)
	PV_EToday.postUpdate(V_EToday)
end

The output (for better readability without the log of raw_output, here you find the complete log):

06:06:34.011 [ERROR] [ntime.internal.engine.ExecuteRuleJob] - Error during the execution of rule SBFspot: 1
06:06:35.064 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'pv.rules'
06:06:35.085 [WARN ] [el.core.internal.ModelRepositoryImpl] - Configuration model 'pv.rules' is either empty or cannot be parsed correctly!
06:06:35.730 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'pv.rules'
06:06:49.405 [INFO ] [lipse.smarthome.model.script.Exit at] - 1
06:06:49.412 [INFO ] [clipse.smarthome.model.script.lines:] - 69
06:06:49.429 [INFO ] [lipse.smarthome.model.script.Exit at] - 2
06:06:49.442 [INFO ] [lipse.smarthome.model.script.Exit at] - 3
06:06:49.458 [INFO ] [lipse.smarthome.model.script.Exit at] - 4
06:07:03.446 [INFO ] [lipse.smarthome.model.script.Exit at] - 1
06:07:03.457 [INFO ] [clipse.smarthome.model.script.lines:] - 69
06:07:03.473 [INFO ] [lipse.smarthome.model.script.Exit at] - 2
06:07:03.489 [INFO ] [lipse.smarthome.model.script.Exit at] - 3
06:07:03.507 [INFO ] [lipse.smarthome.model.script.Exit at] - 4
06:07:18.832 [INFO ] [lipse.smarthome.model.script.Exit at] - 1
06:07:18.839 [INFO ] [clipse.smarthome.model.script.lines:] - 70
06:07:18.850 [ERROR] [ntime.internal.engine.ExecuteRuleJob] - Error during the execution of rule SBFspot: 1
06:07:34.189 [INFO ] [lipse.smarthome.model.script.Exit at] - 1
06:07:34.198 [INFO ] [clipse.smarthome.model.script.lines:] - 70
06:07:34.222 [ERROR] [ntime.internal.engine.ExecuteRuleJob] - Error during the execution of rule SBFspot: 1
06:07:48.236 [INFO ] [lipse.smarthome.model.script.Exit at] - 1
06:07:48.246 [INFO ] [clipse.smarthome.model.script.lines:] - 69
06:07:48.261 [INFO ] [lipse.smarthome.model.script.Exit at] - 2
06:07:48.276 [INFO ] [lipse.smarthome.model.script.Exit at] - 3
06:07:48.297 [INFO ] [lipse.smarthome.model.script.Exit at] - 4

Seems that the root cause is the mysterious “Error 1” in the rule. Has anybody an translation for the that error codes? And what’s about the error in line 3:

“Configuration model ‘pv.rules’ is either empty or cannot be parsed correctly!”

I have no idea what’s the root cause…

Thanks for your support :slight_smile:

Are you accessing/saving your rules file over a Samba share? That could cause this error.

I have a similar rule that parses data, but I use grep for it. This approach should work even if the data format is inconsistent. Hopefully this doesn’t muddy things up worse for you!

rule "SBFspot"
when
	Time cron "0/15 * * * * ?"
then
	val String raw_output = executeCommandLine("/usr/local/bin/sbfspot.3/SBFspot -v -finq -nocsv -nosql",10000)
	//logInfo("SBFspot", "raw_output=[{}]", raw_output)
	val String V_EToday = executeCommandLine("/bin/sh@@-c@@grep \"EToday\" <<< \"" + raw_output + "\" | grep -oP '(\\d+\\.\\d+)(?!.*(?1))'",1000)
    logInfo("SBFspot", "V_EToday=[{}]", V_EToday)
    val String V_ETotal = executeCommandLine("/bin/sh@@-c@@grep \"ETotal\" <<< \"" + raw_output + "\" | grep -oP '(\\d+\\.\\d+)(?!.*(?1))'",1000)
    logInfo("SBFspot", "V_ETotal=[{}]", V_ETotal)
    val String V_EAct = executeCommandLine("/bin/sh@@-c@@grep \"Total Pac\" <<< \"" + raw_output + "\" | grep -oP '(\\d+\\.\\d+)(?!.*(?1))'",1000)
    logInfo("SBFspot", "V_EAct=[{}]", V_EAct)
    
	PV_EAct.postUpdate(V_EAct)
	PV_ETotal.postUpdate(V_ETotal)
	PV_EToday.postUpdate(V_EToday)
end

@5iver
Yes, I use Samba to access the openhab config stuff on my RP. I tried to create a new rule file directly and this doesn’t lead to the error log message - so I will ignore that message in the future.

Secondly I tried out your grep stuff - not easy for me as grep-Newby :wink:
Your rule lead to the following error:

21:10:04.100 [INFO ] [lipse.smarthome.model.script.SBFspot] - V_EToday=[/bin/sh: 1: Syntax error: redirection unexpected]
21:10:04.166 [INFO ] [lipse.smarthome.model.script.SBFspot] - V_ETotal=[/bin/sh: 1: Syntax error: redirection unexpected]
21:10:04.229 [INFO ] [lipse.smarthome.model.script.SBFspot] - V_EAct=[/bin/sh: 1: Syntax error: redirection unexpected]

Perhaps it’s easier for you to understand and debut - any idea what’s the problem?

Thanks!

It looks like your shell does not support the redirection operator (<<<). How does this work for you?

rule "SBFspot"
when
	Time cron "0/15 * * * * ?"
then
	val String raw_output = executeCommandLine("/usr/local/bin/sbfspot.3/SBFspot -v -finq -nocsv -nosql",10000)
	//logInfo("Raw_Output:", raw_output)
    val String V_EToday = executeCommandLine("/bin/sh@@-c@@echo \"" + raw_output + "\" | grep \"EToday\" | grep -oP '(\\d+\\.\\d+)(?!.*(?1))'",10000)
    logInfo("SBFspot", "V_EToday=[{}]", V_EToday)
    val String V_ETotal = executeCommandLine("/bin/sh@@-c@@echo \"" + raw_output + "\" | grep \"ETotal\" | grep -oP '(\\d+\\.\\d+)(?!.*(?1))'",10000)
    logInfo("SBFspot", "V_ETotal=[{}]", V_ETotal)
    val String V_EAct = executeCommandLine("/bin/sh@@-c@@echo \"" + raw_output + "\" | grep \"Total Pac\" | grep -oP '(\\d+\\.\\d+)(?!.*(?1))'",10000)
    logInfo("SBFspot", "V_EAct=[{}]", V_EAct)
    
	PV_EAct.postUpdate(V_EAct)
	PV_ETotal.postUpdate(V_ETotal)
	PV_EToday.postUpdate(V_EToday)
end

Early bird debugging :slight_smile:
Your right, the <<< operator was the problem. Your last proposal without seems to work fine. I let it run during the day and report you later.

Thanks so far!

Good Morning,

just a quick one: did you find out, what’s the reason for this ominous error “1”?
I have the same occasionally and don’t have a clue.