[JSR223][Jython]What is the correct way to avoid a race condition getting an item value inside a /received update/ triggered rule?

[leif (Leif Claesson)]

Thank you for replying, rossko57!

@rossko57

The race I think you are looking at with your UI switch is I think with the UI.

I was going to dismiss the theory outright because I first saw the problem on a “received update” rule on an item that was updated by postUpdate in a rule triggered by astro, not the GUI.

But, I figured you might be right, so I decided to test it thoroughly, and the test results shows that it is not in the gui.

Here’s the test setup:

Items:

Switch RaceGuiSwitch 	"Race Condition Gui Item" 	<lightbulb> (Bench)
Switch RaceItemSwitch    "Race Condition Item"

racecondition.py

from core.rules import rule
from core.triggers import when

from core.log import logging, LOG_PREFIX
log = logging.getLogger(LOG_PREFIX + ".racetest")

def logprint(text):
	log.debug(text)

@rule("RaceGuiSwitch", description="", tags=["utility"])
@when("Item RaceGuiSwitch changed from OFF to ON")
def RaceGuiSwitch(event):
	events.postUpdate(ir.getItem("RaceItemSwitch"),ON)

@rule("RaceGuiSwitch", description="", tags=["utility"])
@when("Item RaceGuiSwitch changed from ON to OFF")
def RaceGuiSwitch(event):
	events.postUpdate(ir.getItem("RaceItemSwitch"),OFF)


@rule("RaceItemSwitch", description="", tags=["utility"])
@when("Item RaceItemSwitch received update")
def RaceItemSwitch(event):
	logprint("ir.getItem().getState(): " + str(ir.getItem("RaceItemSwitch").getState()) + "    event.itemState:" + str(event.itemState))

Here’s the console output:

2019-06-14 20:06:13.706 [DEBUG] [jsr223.jython.racetest              ] - ir.getItem().getState(): OFF    event.itemState:OFF
2019-06-14 20:06:14.990 [DEBUG] [jsr223.jython.racetest              ] - ir.getItem().getState(): OFF    event.itemState:ON
2019-06-14 20:06:15.685 [DEBUG] [jsr223.jython.racetest              ] - ir.getItem().getState(): OFF    event.itemState:OFF
2019-06-14 20:06:16.500 [DEBUG] [jsr223.jython.racetest              ] - ir.getItem().getState(): ON    event.itemState:ON
2019-06-14 20:06:16.992 [DEBUG] [jsr223.jython.racetest              ] - ir.getItem().getState(): OFF    event.itemState:OFF
2019-06-14 20:06:17.446 [DEBUG] [jsr223.jython.racetest              ] - ir.getItem().getState(): OFF    event.itemState:ON
2019-06-14 20:06:17.743 [DEBUG] [jsr223.jython.racetest              ] - ir.getItem().getState(): OFF    event.itemState:OFF

The discrepancy between getItem().getState() and event.itemState could not have come from the GUI because the RaceItemSwitch is decoupled from RaceGuiSwitch by two rules: “changed from ON to OFF” and “changed from OFF to ON”.

I also implemented the test rule in Rules DSL, as follows:

rule "test race condition"
when
	Item RaceItemSwitch received update
then
	logInfo("rules DSL","item state: " + RaceItemSwitch.state)
	
end

pi@openhab:~ $ tail -f /var/log/openhab2/openhab.log | grep jython
2019-06-14 20:18:50.457 [DEBUG] [jsr223.jython.racetest              ] - ir.getItem().getState(): ON    event.itemState:ON
2019-06-14 20:18:50.658 [DEBUG] [jsr223.jython.racetest              ] - ir.getItem().getState(): OFF    event.itemState:OFF
2019-06-14 20:18:50.891 [DEBUG] [jsr223.jython.racetest              ] - ir.getItem().getState(): OFF    event.itemState:ON
2019-06-14 20:18:51.071 [DEBUG] [jsr223.jython.racetest              ] - ir.getItem().getState(): OFF    event.itemState:OFF
2019-06-14 20:18:51.263 [DEBUG] [jsr223.jython.racetest              ] - ir.getItem().getState(): ON    event.itemState:ON
^C
pi@openhab:~ $ tail -f /var/log/openhab2/openhab.log | grep DSL
2019-06-14 20:18:50.471 [INFO ] [pse.smarthome.model.script.rules DSL] - item state: ON
2019-06-14 20:18:50.670 [INFO ] [pse.smarthome.model.script.rules DSL] - item state: OFF
2019-06-14 20:18:50.916 [INFO ] [pse.smarthome.model.script.rules DSL] - item state: ON
2019-06-14 20:18:51.085 [INFO ] [pse.smarthome.model.script.rules DSL] - item state: OFF
2019-06-14 20:18:51.273 [INFO ] [pse.smarthome.model.script.rules DSL] - item state: ON
^C

Note how it does NOT show any problem! I spammed the GUI button for several minutes, could not trip it up. So this problem looks to be inherent to JSR223, or perhaps the next gen rule engine, or perhaps Jython. That makes more sense – a bug of this magnitude couldn’t remain if it affected the majority of users and uses.

Now, the reason I’m not using Rules DSL is that as I read through the documentation, I came across some (to my eyes as a programmer) ugly workarounds around the lack of being able to define functions, and then in this document i came across this:

@rlkoshak

That’s Just a Bunch of Hacks

That is a subjective opinion. These are tried and true ways to write short, concise, and non-duplicative code in Rules DSL. If you can’t or won’t apply these techniques to your code perhaps the Rules DSL isn’t for you. Luckily there are many many alternatives.

Upon reading this, and seeing as I was dumping my $600+ Fibaro Home Center 2 and switching to Openhab mostly because of annoying scripting limitations that make anything beyond the simplest of systems a maintenance nightmare, I realized that Rules DSL would indeed NOT be for me, and that perhaps it was time to learn a new language. And that is how after 20 years of C++ experience, I started learning Python!

So anyway. Could anyone else help confirm this race condition in JSR223/Python rule handling?