[SOLVED] Timer error message (another one :-) ): Could not invoke method: [….] on instance: null

wawa79 · September 25, 2018, 5:23pm

Hello,

I had following script error when running a Timer created in a rule that handles gate opening:

2018-09-25 16:42:35.808 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Commande mCR_portail': An error occurred during the script execution: Could not invoke method: org.eclipse.smarthome.model.script.actions.ScriptExecution.createTimer(org.joda.time.base.AbstractInstant,org.eclipse.xtext.xbase.lib.Procedures$Procedure0) on instance: null

Other topics mention same issue when parameter is wrong type. This is not my case (see code below) and the rule worked properly for several weeks (triggered at least 4 times / day).

Any idea of what could cause the null error? Is it possible that global constants get reset due to other errors with the scripting engine (they were several errors ? I moved them inside the rule block to ensure they get set everytime the rule is triggered but I would like to understand the root cause of the error.

import org.joda.time.DateTime

var Timer portail_task = null

val int portail_opensecs = 26 
val int portail_closesecs = 25
val int portail_pietonsecs = 6 

rule "Commande mCR_portail"
when
	Item DW_mCR_portail received command
then
	var new_mode = null
    val DateTime now_date =  new DateTime()


	var DateTime portail_move_start = now_date
	var DateTime portail_move_end = now_date.plusMillis(portail_opensecs * 1000 + 500)

    portail_task?.cancel()
    portail_task = null

	switch(DW_mCR_portail.state.toString + ">" + new_mode){
		case '0>30':{//CLOSED > PIETON
			AC_mCR_portail.sendCommand(ON)
			portail_move_start = now_date
			portail_move_end = now_date.plusMillis(portail_pietonsecs * 1000 + 500) 
			DW_mCR_portail.postUpdate(10)//OPENING
			portail_task = createTimer(portail_move_end) [|
				AC_mCR_portail.sendCommand(ON)
				DW_mCR_portail.postUpdate(30) //PIETON
				]
		}
	}

The rule uses a timer to determine the state of the gate because it does not have position sensors. For example, when “OPEN” command is received, the state is set immediately to “OPENING” and a Timer is created to change the state to “OPEN” when opening of the gate it completed after portail_pietonsecs seconds. (I removed all other case {} block to make code lighter).

rlkoshak · September 25, 2018, 6:50pm

Does this error occur every time the Rule runs or only when OH first starts or the .rules file first loads?

Except for the code being pretty awkward I see nothing obviously wrong with the Timer. I see other problems.

For example, new_mode gets set to null as the first thing in the Rule and never gets set to anything else. So I see no way for the switch case to ever evaluate.

This use of the switch statement is awkward and not at all a typical use of switch. An if statement would make more sense.

You don’t need to create a new DateTime object to get access to now. Just use now.

var portail_move_start = now
var portail_move_end = portail_move_start.plusMillis(portail_opensecs * 1000  + 500)

Don’t use primitives unless you absolutely have to.

val portail_opensecs = 26
val portail_closesecs = 25
val portail_pietonsecs = 6

Do not import DateTime. It is already imported.

wawa79 · September 25, 2018, 7:32pm

The error only happened once this morning. OpenHAB was up since 2 days and it had run already normally last 2 days before raising the error this morning.

Sorry for new_mode: it is in a piece of code I removed for readability: below is the full code.

rule "Commande mCR_portail"
when
	Item DW_mCR_portail received command
then
	var new_mode = null
    val DateTime now_date =  new DateTime()

	val int portail_opensecs = 26 
	val int portail_closesecs = 25
	val int portail_pietonsecs = 6 

	var DateTime portail_move_start = now_date
	var DateTime portail_move_end = now_date.plusMillis(portail_opensecs * 1000 + 500)

    portail_task?.cancel()
    portail_task = null

	if(receivedCommand==50){//TOGGLE
		if(newArrayList('0', '90').contains(DW_mCR_portail.state.toString)){//CLOSED OR CLOSING
			new_mode = '100' //OPEN
		}
		else if(newArrayList('100', '30', '10').contains(DW_mCR_portail.state.toString)){//OPEN, PIETON OR OPENING
			new_mode = '0' //CLOSED
		}
	}
	else{
		new_mode = receivedCommand.toString
	}

	switch(DW_mCR_portail.state.toString + ">" + new_mode){
		case '0>30':{//CLOSED > PIETON
			AC_mCR_portail.sendCommand(ON)
			portail_move_start = now_date
			portail_move_end = now_date.plusMillis(portail_pietonsecs * 1000 + 500) 
			DW_mCR_portail.postUpdate(10)//OPENING
			portail_task = createTimer(portail_move_end) [|
				AC_mCR_portail.sendCommand(ON)
				DW_mCR_portail.postUpdate(30) //PIETON
				]
		}
		case '0>100':{//CLOSED > OPEN
			AC_mCR_portail.sendCommand(ON)
			portail_move_start = now_date
			portail_move_end = now_date.plusMillis(portail_opensecs * 1000 + 500) 
			DW_mCR_portail.postUpdate(10)//OPENING
			portail_task = createTimer(portail_move_end) [|
				DW_mCR_portail.postUpdate(100) //OPEN
				]
		}
		case '100>0':{//OPEN > CLOSED
			AC_mCR_portail.sendCommand(ON)
			portail_move_start = now_date
			portail_move_end = now_date.plusMillis(portail_closesecs * 1000 + 500) 
			DW_mCR_portail.postUpdate(90)//CLOSING
			portail_task = createTimer(portail_move_end) [|
				DW_mCR_portail.postUpdate(0) //CLOSED
				]
		}
		case '30>0':{//PIETON > CLOSED
			AC_mCR_portail.sendCommand(ON)
			portail_move_start = now_date
			portail_move_end = now_date.plusMillis(portail_pietonsecs * 1000 + 500) 
			DW_mCR_portail.postUpdate(90)//CLOSING
			portail_task = createTimer(portail_move_end) [|
				DW_mCR_portail.postUpdate(0) //CLOSED
				]
		}
		case '10>0':{//OPENING > CLOSED
			AC_mCR_portail.sendCommand(ON)
			createTimer(1) [|
				AC_mCR_portail.sendCommand(ON)
			]
			val elapsed_secs = Seconds.secondsBetween(portail_move_start, now_date).getSeconds()
			portail_move_end = now_date.plusSeconds(elapsed_secs)
			portail_move_start = now_date 
			DW_mCR_portail.postUpdate(90)//CLOSING
			portail_task = createTimer(portail_move_end) [|
				DW_mCR_portail.postUpdate(0) //CLOSED
				]
		}
		case '90>100':{//CLOSING >OPEN
			AC_mCR_portail.sendCommand(ON)
			createTimer(1) [|
				AC_mCR_portail.sendCommand(ON)
			]
			val elapsed_secs = Seconds.secondsBetween(portail_move_start, now_date).getSeconds()
			portail_move_end = now_date.plusSeconds(elapsed_secs)
			portail_move_start = now_date 
			DW_mCR_portail.postUpdate(10)//OPENING
			portail_task = createTimer(portail_move_end) [|
				DW_mCR_portail.postUpdate(100) //OPEN
				]
		}
	}
end

rlkoshak · September 25, 2018, 10:02pm

For what it does this Rule seems excessively long and complicated. About all I can recommend is to make sure that all the Items you are using in the Rule have a non-NULL state and add logging statements to track the results of calculations as you go.

wawa79 · September 26, 2018, 7:07am

What do you mean by complicated?
Do you refer to the repetition of statements in all case blocks that could be factored or is there anything else that would improve robustness of the code to avoid unexpected errors?
Would it make sense to add a lock() to the rule?

I will add debug statements to monitor execution as you suggest to catch why the CreateTimer fails time to time.

wawa79 · September 26, 2018, 11:47am

I found the cause of the Timer error:

createTimer(1) [|
				AC_mCR_portail.sendCommand(ON)
			]

instead of now+plusSeconds(1)…

Conclusion: next time I will post the entire rule and not an excerpt so you can blame me for being so stupid

The error did not happen until now because this case{} block runs when an open/close command is sent and the door is already moving to the opposite state (eg OPEN received while the door is closing). I need to send the command twice, once to stop the door and once to start movement in the opposite direction with a delay of 1 sec using CreateTimer().

The error happens when the door command button is clicked twice on the UI. I will avoid this by hidding the buttons in the sitemap once clicked.

rlkoshak · September 26, 2018, 4:34pm

It is long for what it does. It creates variables that don’t need to be created (e.g. now_date). The constants for the amount of time to schedule the timers should be global, should be vals, and should not be ints. The conditions for the switch statement are not intuitive. What’s with the array lists?

I’m sure it all makes perfect sense to you, and that is what is most important, but for someone coming at it with no prior knowledge it’s really hard to figure out how it works and what it all means.

Not so much, though that can easily be handled by applying Design Pattern: How to Structure a Rule.

The complicated part is what the heck does DW_mCR_portail get set to? What about DW_mCR_portail? What does “CLOSED > PIETON” mean?

Please avoid locks unless absolutely necessary. They result in brittle code and run the risk of running out of Rules runtime threads.

Not stupid. We all make mistakes like this. I do believe though that VSCode would have identified this as an error since the problem is one of type.

Though having the full Rule often will give us the context necessary to help solve the problem.

So, I mentioned a number of problems I had with understanding your code. First let me emphasize that these are not problems with the code itself. But they are barriors to understanding the Rule for other developers who, like me, have not spent hours working on it.

Some recommendations I have that will make the code a little more self explanatory.

Use now instead of creating new DateTime objects
Always use val for constants. The standard naming convention is to use all caps for constants.
Use Strings instead of numbers for what gets saved to DW_mCR_portail and new_mode. if(DW_mCR_portail.state == "OPEN") is much more clear to the person than if(DW_mCR_portail.state == 100)
Avoid repeating code. Not only is it easier to read, it is more maintainable in the long run.

So the Rule could look something like:

val PORTAIL_OPENTIME = 26 * 1000 + 500
val PORTAIL_CLOSETIME = 25 * 1000 + 500
val PORTAIL_PIETONTIME = 6 * 1000 + 500

var Timer portail_task = null
var moveEnd = now

rule "Commande mCR_portail"
when
    Item DW_mCR_portail received command
then

    // 1. Decide if we need to run
    // Always run

    // 2. Calculate what needs to be done

    // calculate the new mode 
    var new_mode = ""
    switch(receivedCommand.toString) {
        case "CLOSED",
        case "CLOSING": new_mode = "OPEN"
        case "OPEN",
        case "PIETON",
        case "OPENING": new_mode = "CLOSED"
        default: new_mode = receivedCommand.toString
    }

    // Calculate the move end and new gate state
    val transition = receivedCommand.toString + " to " + new_mode // Never use the state of an Item inside a Rule where the Item receiving a command is the trigger of the Rule
    var currState = ""
    var portail_move_time = 0

    switch (transition) {
        case "CLOSED to PIETON": {
            portail_move_time = PORTAIL_PIETONTIME
            currState = "OPENING"
        }
        case "CLOSED to OPEN": {
            portail_move_time = PORTAIL_OPENTIME
            currState = "OPENING"
        }
        case "OPEN to CLOSED": {
            portail_move_time = PORTAIL_CLOSETIME
            currState = "CLOSING"
        }
        case "PIETON to CLOSED": {
            portail_move_time = PORTAIL_PIETONTIME
            currState = "CLOSING"
        }
        case "OPENING to CLOSED": {
            portail_move_time = moveEnd
            currState = "CLOSED"
        }
        case "CLOSING to OPEN": {
            portail_move_time = moveEnd
            currState = "OPENING"
        }
    }

    // 3. Do it
    // If we are OPENING or CLOSING stop the portail and start it again
    if(receivedCommand.toString.endsWith("ING")) {
        AC_mCR_portail.sendCommand(ON)
        createTimer(now.plusSeconds(1), [ | AC_mCR_portail.sendCommand(ON) ])
    }

    // Set the timer
    portail_task?.cancel
    portail_task = createTimer(now.plusMillis(portail_move_time, [ | 
            if(new_mode == "PIETON") AC_mCR_portail.sendCommand(ON)
            DW_mCR_portail.postUpdate(new_mode)
            portail_task = null
         ])
    moveEnd = portail_move_time
end

I’ve no idea if all of the above is correct but it should do the same thing as your original Rule. I can’t speak to whether there were not bugs in the original Rule. It is unclear whether the triggering Item will received the ING commands.

wawa79 · September 26, 2018, 8:40pm

Ok, changed. Anyway now_date variable is important as it allows calculating elapsed time when transition from OPENING>CLOSE and CLOSING>OPEN

Ok. Just realized recently that constant were declared with val keyword…

This is the heritage of my old Python script. I will update all items types to String when I have some time left.

Indeed transitions is between current state (before the rule is executed) and command received: DW_CR_portail is a virtual item with autoupdate=false.
PIETON refers to the state where the gate is open partly for pedestrian (and not OPEN for a car)

Thank you for your time.

rlkoshak · September 26, 2018, 8:46pm

Not the way you were using it. It was a Rule local value which means as soon as the Rule exited the value gets destroyed. You need to store that value in a global. And once you are storing that value as a global, why not just store the datetime when the timer will go off as a global instead of recalculating the end time based on elapsed time?

wawa79 · September 27, 2018, 7:28am

Indeed, the variables and time constants were global until I started troubleshooting the CreateTimer()… I copied/pasted the constants into the rule but also the timer variables by mistake.
Calculating the elapsed time is needed to determine delay of timer for OPENING>CLOSE and CLOSING>OPEN (cases when the command execution is interrupted)
Example for OPENING>CLOSE
When sending command CLOSE while the gate is opening (gate’s state is OPENING), existing timer that would have set its state to OPEN is cancelled and a new timer is set to change the state to CLOSED. Duration for this timer is the elapsed time of the opening movement until the CLOSE command was received (assuming speed of opening is the same as speed of closing).

This is why I record the start time.