Race condition: Rule activation vs. state value?

[stevenc88 (Steven Christensen)]

I am using OH 2.5, and have created a Dimmer item which is exposed to Google Assistant.

I have a rule which triggers when the new “bulb” receives a command. Within the rule I expect the state value of the Dimmer item to be 100 (= ON) when the rule is invoked due to an ON command. But when I use GA to command the bulb ON, I find at the beginning of the rule, the state value is still 0 (=OFF). But at the end of the rule, the state value is correct.

Here is some of the code in my rule:

rule "barlights command"
when
    Item barlights received command
then
    logInfo("barlights_cmd", "Got barlights command = %s".format(barlights))

    // Misc operations unrelated to the barlight item (mostly sending MQTT messages to other devices)

    logInfo("barlights_cmd", "End barlights command = %s".format(barlights))
end

This results many times (but not every time):

2021-02-08 22:28:49.351 [INFO ] [smarthome.model.script.barlights_cmd] - Got barlights command = barlights (Type=DimmerItem, State=0, Label=Bar Lights, Category=null)
2021-02-08 22:28:49.394 [INFO ] [smarthome.model.script.barlights_cmd] - End barlights command = barlights (Type=DimmerItem, State=100, Label=Bar Lights, Category=null)

So at the beginning of my rule execution, state isn’t correct; but by the end of the script it is correct.

I also have another rule for the same item which is for: Item barlights received command ON

When I print out state for that rule, it also has the same issue - incorrect at the beginning, but OK a short time later.

Is this expected behavoir?

[rossko57]

@stevenc88

Is this expected behavoir?

Yes.

ReentrantLock - correct use or not?

That’s right. When a command arrives on the OH event bus, it triggers any rules looking for ‘received command’. It triggers any bindings that might pass the command to external devices. It also triggers the autoupdate feature that generates an update of the Item’s state (unless inhibited). The race is on … what happens first is indeterminate, but autoupdate effect is always a finite time later. So, a rule triggered by received command that examines the Item.state may get state from befo…

[denominator (James Bowler)]

Yes this is normal. Its a pain but it is normal.

I suggest using implicit variable

Try

logInfo("barlights_cmd", "Got barlights command = %s".format(receivedCommand))

Rules