OH3: Race condition on sendCommand and received update rule regarding items?

Hi - I think this is more question for the core developers of OpenHAB, but maybe somebody could help:

I recognized a strange behaviour after updating to OpenHAB v3.0.1, which worked perfectly fine with OH2.5

Scenario:

  • I have a bunch of items for my rollershutters - about 25.
  • Depending on sunshine and time, I do a sendCommand(NewRollershutterPosition) to each of these items
  • For each item I have a rule which reacts on “received update” of the item

What I now see since the update to OH3:

  • The rule doing the sendCommand(NewRollershutterPosition) is executed (means 25 sendCommands - one for each item)
  • The rules reacting on “received update” start their work, BUT: Some of the values of the items still stick to the old rollershutter position! Means the value of some of the items are not yet updated to the value NewRollershutterPosition which was sent via sendCommand to the item!

I recognized this, because I put a trace line into the rules reacting on “received update”. If I take a look to the items values via the UI, I always see, that all are updated to NewRollershutterPosition. Means, the items values are set, but sometimes a bit too late. Or in other words: The rules reacting on “received update” are already fired without having the values of the items already updated to the new value.

I think this may be a result of a race condition using multithreading in the core of OpenHAB 3?

Any hints much appreciated! :slight_smile:

It’s quite likely that timing has changed, which could expose a race that has always been there but usually worked in your favour before.

Or your devices send updates before completing their movement. We’d need more detail here.
Your events.log, taken with your rule logging, will give you a better picture of the sequence of events. (note that update-to-same events are not shown in events.log)

1 Like

Hi rossko57,

thanks for your hint, I think we come closer:

Here is a snippet of my openhab.log file. Situation: The rule doing the sendCommand(0) for all rollershutter items was executed (about 25 sendCommands done). Therefore the rules for “received update” of the items are called. There are 2 rollershutters for the “Sportzimmer”. RolladeTuerSportzimmer and RolladeFensterSportzimmer. RolladeTuerSportzimmer is fine, RolladeFensterSportzimmer shows the mentioned problem. I replaced the sensitive parts (Pw etc.). “value” contains what was sent via sendCommand(value), means the old value was 100 (rollershutter closed), the sendCommand(0) should open both rollershutters:

2021-04-23 08:20:00.979 [INFO ] [org.openhab.core.model.script.Info  ] - opus: opusRolladeTuerSportzimmer url:http://admin:Pw@192.168.4.91:8080/devices/id1/state
2021-04-23 08:20:00.979 [INFO ] [org.openhab.core.model.script.Info  ] - opus: opusRolladeTuerSportzimmer req:{ "state" : { "functions" : [ {"key" : "position", "value" : "0"}  ] } }

2021-04-23 08:20:00.980 [INFO ] [org.openhab.core.model.script.Info  ] - opus: opusRolladeFensterSportzimmer url:http://admin:Pw@192.168.4.91:8080/devices/id2/state
2021-04-23 08:20:00.980 [INFO ] [org.openhab.core.model.script.Info  ] - opus: opusRolladeFensterSportzimmer req:{ "state" : { "functions" : [ {"key" : "position", "value" : "100"}

Now lets take a look at the corresponding events.log as you suggested - again cleaned to the relevant part:

2021-04-23 08:20:00.978 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'opusRolladeTuerSportzimmer' received command 0
2021-04-23 08:20:00.978 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'opusRolladeFensterSportzimmer' received command 0
2021-04-23 08:20:00.981 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'opusRolladeTuerSportzimmer' changed from 100 to 0
2021-04-23 08:20:00.981 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'opusRolladeFensterSportzimmer' changed from 100 to 0

Interesting:

  • At timestamp 2021-04-23 08:20:00.980 the openlog-trace of the rule shows, that value 100 is the current one for opusRolladeFensterSportzimmer, but this one should be 0, as sent via sendCommand(0).
  • And it’s correct, that the rule is called, because the event.log shows 2ms before: 2021-04-23 08:20:00.978 Item ‘opusRolladeFensterSportzimmer’ received command 0
  • But: Only at 2021-04-23 08:20:00.981, means 1ms too late, the value of opusRolladeFensterSportzimmer gets really set to 0. => voila, this is the problem, I think. Suggestion: Change the order, means first set the new value of the item, then fire the event, that the “received update” rules should be called.

(It’s only a bit strange, that it worked for the RolladeTuerSportzimmer - but maybe thread scheduling causes this behaviour…)

That the devices send an update before completing their movement should not happen. Unfortunately there is no binding yet available for the OPUS system, means I manually do all this via some items and rules :wink: I know, not the best method and I should implement a binding (not only to communicate backwards, means getting updates from the devices), but it takes some time I currently don’t have and I’m not familiar with Java…but some day… :wink:

Without seeing your rules it’s not really possible to evaluate much more.

Things you need to be aware of -

Sending a command to an Item never guarantees any change of state at all, on it’s own.
This is a quite deliberate feature of openHAB, the separation of command and state is a crucial part of the design.

If a change or update should happen as a result, it always take a finite time. That’s because something somewhere has to listen out for commands, act on them, and make an update. Something like a device.

OpenHAB has a feature called autoupdate that gets involved here. This is enabled on every Item by default. It listens for commands and tries to make a prediction about the effect, and updates the Item state. It is quick so it gives a slick UI representation, but still takes a finite time.

Something that might affect you is that rule threading has changed. While in OH2 multiple “copies” of the same rule could run in parallel (bringing it’s own problems), in OH3 only one instance of a particular rule can run at once.
Say you trigger from ‘member of group’ and five members update nearly simultaneously. One rule will run and four more triggers will queue up and await their turn.

1 Like

Many thanks for your valuable comments!

If I read this former comment from you and this part of the documentation, then my understanding is:

  • sendCommand(x) sends a command and the according binding acts on this by sending it to the device
  • Here I don’t have a binding, but just a pure item. Therefore the autoupdate gets for sure involved and updates the item’s state.

But one question:
Can I expect in a rule fired by “received update” in this scenario, that the item’s state is for sure set to the value which I sent via sendCommand?
Or is the same true, which is documented in the link above for rules fired by “received command”: Means it may happen, that the rule is triggered before the item’s state is updated!

No. Nothing to stop anyone else issuing updates at any random time - another rule say.
No. Autoupdate cannot make predictions for all occasions (INCREASE command for example).

But in this case, it should deal happily with a numeric command to a Rollershutter type Item.

Absolutely every time that will happen. Cause and effect.
The Item state is likely to change sometime during or after rule execution.

1 Like

For the ones being interested:

I refactored my rules and:

  • trigger my rule now on received command
  • use the receivedCommand (and triggeringItem) in the rule instead of the state of the item
  • moved the code from multiple rules into one

All this seems to result in a more predictable execution, also with OH3 and up to now it works fine!

Thanks @rossko57 for all the insights to OpenHAB! That helped a lot! :slight_smile: