[SOLVED] Rule 'UG Waschmaschine fertig': An error occurred during the script execution: null

I searched the Forum and find this issue, but there had been allways different Script-Errors and I didn’t found a solution.

Its a rule for the washing machine. It works fine, but sometimes it throws an error in the Log:

openhab.log:

2019-02-18 12:52:10.612 [INFO ] [model.script.5_Fenster_Heizung.rules] - EG-Twins: Fenster geschlossen, Temperatur 5 °C wieder hergestellt
2019-02-18 12:52:25.180 [INFO ] [veClimateControlScheduleCommandClass] - NODE 25 reported: Override type: NO_OVERRIDE, ScheduleState: [UNUSED]
2019-02-18 12:52:53.186 [INFO ] [veClimateControlScheduleCommandClass] - NODE 15 reported: Override type: NO_OVERRIDE, ScheduleState: [UNUSED]
2019-02-18 12:52:56.831 [INFO ] [.model.script.UG_Waschmaschine.rules] - Sende: 2.085639404990511
2019-02-18 12:52:56.836 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'UG Waschmaschine fertig': An error occurred during the script execution: null
2019-02-18 12:53:41.857 [INFO ] [veClimateControlScheduleCommandClass] - NODE 26 reported: Override type: NO_OVERRIDE, ScheduleState: [UNUSED]
2019-02-18 12:53:56.828 [INFO ] [.model.script.UG_Waschmaschine.rules] - Sende: 2.099385238252456
2019-02-18 12:54:28.732 [INFO ] [veClimateControlScheduleCommandClass] - NODE 5 reported: Override type: NO_OVERRIDE, ScheduleState: [UNUSED]
2019-02-18 12:54:49.731 [INFO ] [veClimateControlScheduleCommandClass] - NODE 14 reported: Override type: NO_OVERRIDE, ScheduleState: [UNUSED]
2019-02-18 12:54:56.858 [INFO ] [.model.script.UG_Waschmaschine.rules] - Sende: 2.105264519848996
2019-02-18 12:55:03.959 [INFO ] [veClimateControlScheduleCommandClass] - NODE 27 reported: Override type: NO_OVERRIDE, ScheduleState: [UNUSED]

event-log time of error:

2019-02-18 12:52:56.831 [vent.ItemStateChangedEvent] - UG_Waschmaschine_Plug_Watt changed from 2.251 to 2.116
2019-02-18 12:52:56.832 [ome.event.ItemCommandEvent] - Item 'UG_Waschmaschine_Plug_Watt_5Min' received command 2.085639701687717
2019-02-18 12:52:56.834 [ome.event.ItemCommandEvent] - Item 'UG_Waschmaschine_Plug_Watt_10Min' received command 2.039410909602702
2019-02-18 12:52:56.835 [vent.ItemStateChangedEvent] - UG_Waschmaschine_Plug_Watt_5Min changed from 2.047702734365788 to 2.085639998382924
2019-02-18 12:52:56.837 [vent.ItemStateChangedEvent] - UG_Waschmaschine_Plug_Watt_5Min changed from 2.085639998382924 to 2.085639701687717
2019-02-18 12:52:56.837 [vent.ItemStateChangedEvent] - UG_Waschmaschine_Plug_Watt_10Min changed from 2.032033465381962 to 2.039411134619455
2019-02-18 12:52:56.837 [vent.ItemStateChangedEvent] - UG_Waschmaschine_Plug_Watt_10Min changed from 2.039411134619455 to 2.039410909602702

The Rule caused the error:

rule "UG Waschmaschine fertig"
when
    Item UG_Waschmaschine_Plug_Watt_10Min changed
then
    val Number currentSecond = now.getSecondOfMinute + 1
    val MessageList = newArrayList('BLA1', 'BLA2', 'BLA3')
    val Number maxMessages = 3.0
    if (UG_Waschmaschine_Plug_Watt_10Min.state < 7.0 && UG_WaschmaschineAn.state == ON) {
	logInfo("UG_Waschmaschine.rules", "Fertig: " + UG_Waschmaschine_Plug_Watt_10Min.state)
	UG_WaschmaschineAn.sendCommand(OFF)
        UG_WaschmaschineAn.postUpdate(OFF)
	sendTelegram("Jens","Waschmaschine fertig")
	var int chosenMessage = (Math::floor((currentSecond.floatValue+30/maxMessages.floatValue) * maxMessages.floatValue / 60.0 )).intValue
//	var String Nachricht = MessageList.get(chosenMessage)
	sendTelegram("Jens", "Sekunde: "+currentSecond+"\n--- Max: "+maxMessages+"\n---Gewählt: "+chosenMessage+"\n---Text: "+"Nachricht")
    }
end

Curious that the Rule is triggered twice to recalculate 5Min-Usage and 10-Min-Usage (if looking in Log, one command received, two Updates):

rule "UG Waschmaschine Durchschnittsverbrauch"
when
    Item UG_Waschmaschine_Plug_Watt received update
then
    logInfo("UG_Waschmaschine.rules", "Sende: " + UG_Waschmaschine_Plug_Watt.averageSince(now.minusMinutes(5)).toString)
    UG_Waschmaschine_Plug_Watt_5Min.sendCommand(UG_Waschmaschine_Plug_Watt.averageSince(now.minusMinutes(5)))
    UG_Waschmaschine_Plug_Watt_5Min.postUpdate(UG_Waschmaschine_Plug_Watt.averageSince(now.minusMinutes(5)))
    UG_Waschmaschine_Plug_Watt_10Min.sendCommand(UG_Waschmaschine_Plug_Watt.averageSince(now.minusMinutes(10)))
    UG_Waschmaschine_Plug_Watt_10Min.postUpdate(UG_Waschmaschine_Plug_Watt.averageSince(now.minusMinutes(10)))
end

The Rule itself works, but I want to get rid of this errors.

Somebody has got an idea?

Let’s do that part.
Rule is triggered on state change

rule "UG Waschmaschine fertig"
when
   Item UG_Waschmaschine_Plug_Watt_10Min changed

Item state gets changed twice here

when
   Item UG_Waschmaschine_Plug_Watt received update
then
   logInfo("UG_Waschmaschine.rules", "Sende: " + UG_Waschmaschine_Plug_Watt.averageSince(now.minusMinutes(5)).toString)
   UG_Waschmaschine_Plug_Watt_5Min.sendCommand(UG_Waschmaschine_Plug_Watt.averageSince(now.minusMinutes(5)))
   UG_Waschmaschine_Plug_Watt_5Min.postUpdate(UG_Waschmaschine_Plug_Watt.averageSince(now.minusMinutes(5)))

First you send a command, using a calculated value.
Then you post an update, using a new calculated value, and because time has moved on a little the calculated value will be different by a few decimals.
A short time later, autoupdate will apply an update to the Item based on the command.
So, two updates, two rule triggers.

I’m not at all sure why you use both sendCommand and postUpdate.

The rule triggers are so close together in time you will probably have two copies of the rule running at the same time. Might have something to with your ‘nulls’, so I’d fix the double command/update first and see what’s left.

O.K., I did in all rules. Had found somewhere had to do both. Now corrected everywhere and I ll look again for the Logs.

Thanks!

Until now, no further errors in log. Seems had been the solution :wink:

Not sure why. There’s nothing wrong in principle with multiple rule starts. It usually goes wrong if they alter some shared resource, but I can’t spot anything like that.