OH adds commands to dimmer test rule

Hi all,
I really need some expert help on the following very simple dimmer test rule and its behavior.
The dimmer is a NEXA ZV-9101.
OH version is 2.5.1-2.
HW: RPi4B w/Z-Stick
The log results from the test show a strange and surprising OH behavior. Extra dimmer levels (commands) are added.

//Items:
Dimmer Dimmer2_KI_Ci

//Rule:
rule "test"
when
  Time cron "00 40 13 * * ?"
then
  Dimmer2_KI_Ci.sendCommand( 45)
  Thread::sleep(5000)
  logInfo("Rules", "Item status test ON " + Dimmer2_KI_Ci.state)

  Thread::sleep(10000)

  Dimmer2_KI_Ci.sendCommand(OFF)
  Thread::sleep(5000)
  logInfo("Rules", "Item status test OFF " + Dimmer2_KI_Ci.state)
end

Log:
2020-02-24 13:40:00.032 [ome.event.ItemCommandEvent] - Item 'Dimmer2_KI_Ci' received command 45
2020-02-24 13:40:00.112 [nt.ItemStatePredictedEvent] - Dimmer2_KI_Ci predicted to become 45
2020-02-24 13:40:00.125 [vent.ItemStateChangedEvent] - Dimmer2_KI_Ci changed from 0 to 45
2020-02-24 13:40:01.615 [vent.ItemStateChangedEvent] - Dimmer2_KI_Ci changed from 45 to 33         ??
2020-02-24 13:40:05.016 [INFO ] [pse.smarthome.model.script.BTN Rules] - Item status test ON 33    ??
2020-02-24 13:40:15.039 [ome.event.ItemCommandEvent] - Item 'Dimmer2_KI_Ci' received command OFF
2020-02-24 13:40:15.129 [nt.ItemStatePredictedEvent] - Dimmer2_KI_Ci predicted to become OFF
2020-02-24 13:40:15.145 [vent.ItemStateChangedEvent] - Dimmer2_KI_Ci changed from 33 to 0
2020-02-24 13:40:16.614 [vent.ItemStateChangedEvent] - Dimmer2_KI_Ci changed from 0 to 11          ??
2020-02-24 13:40:20.026 [INFO ] [pse.smarthome.model.script.BTN Rules] - Item status test OFF 11   ??

Anyone seen this before and can explain why?

I can see just two commands, and I think they both come from your rule.
Try to keep a clear distinction between commands and state updates in openHAB.

I guess your surprise is about updates to unexpected values.
These arrive about a second after the commands, and will originate from your mystery device.
I speculate they reflect a dimmer that is part way through ramping to a new value.
You’re missing a final status report from your device perhaps, when the action is finished?

Yes, you were right. I decreased the fade time from 2 to 1 sec and it looks OK (I think). Need to try the real dimmer rule first.

That’s a device thing I can’t control - right, or…?

Yes, I have been struggling with that for quite some time in relation to arithmetic in rules involving ex. postUpdate.
I’m used to real time systems, but understand that OH is an event driven, object oriented, multitasking system where statement execution finish may/will not follow the sequence of statements in a rule, which can be challenging. I find myself using wait statements such as Thread::sleep(xxxx) every now and then. Initially I thought Item.state = cccDdd would be a call to a Thing, but I guess it’s rather a call to the latest Item.state stored in memory somewhere - right?.

Could you elaborate just a little more on what your thinking was related to state updates, or point me to a place where this is discussed in more detail? Understanding is key to success!

Thanks a million for your time.

I’m guessing this is a zwave device? I’ve no idea what you features it has; what you’d like is report-status-when-action-complete.

Alternatively, I understand the openHAB binding implements poll-after-command which is adjustable delay per device.

In openHABS world of idealized Items, commands and states really represent direction of flow.

An Item command will originate in a rule or UI action, linked binding will get that and do whatever it does dependent on technology to instruct a real world device. That’s it, Item state unaltered.

Some time later, the target device will respond with its new status (we hope). The binding does its thing matching this status to the linked Item state.

Bear in mind there may be no obvious link between commanding a Dimmer to “INCREASE” and shortly getting a new status “75%”. Or perhaps it’s already 100% and no new status is forthcoming.

Viewed in this light, I hope some of openHAB makes a bit more sense. Such as why those different rule triggers.

Of course in our real systems it gets more complicated - autoupdate makes predictions based off commands, we can have Items not linked to any device, of course we can choose to freely.update any Item from rules. But that’s all extra stuff on top of the core model.

Wow. Enlightening! That was more than I payed for.
What’s challenging is also understanding the timing of all this when adding arithmetic to it.
I have been struggling with a test rule that I can run M times and get N different results , probably due to execution timing.
Anyway, Thanks a trillion for your time. Much appreciated!

Just one more quicky:
Is there a way to poll the state of the dimmer (Thing) Items?

openHAB does allow commanding REFRESH to Items. Bindings may or may not implement any actual interrogation of remote devices, depending on technology. It is rarely used, and rarely useful.

If you are trying to construct a polling mechanism you are probably on the wrong approach. It isn’t easy designing with an event driven asynchronous system, it’s made harder if you have a “traditional” procedural programming background.

For example - were you to use REFRESH, the “answer” is not immediately available. You’d have one process to kick off the REFRESH, then end. Whenever the data is updated, start a new process to do whatever.

There’s no detail to offer any advice about your rules. One often seen pitfall however is doing things at the wrong time. If you want X to happen when a dimmer changes, then that is the way to trigger your process, when the dimmer changes. Do not trigger on the dimmer being commanded, because that is not the same thing (and importantly is not at the same time).

i’m struggling a bit with timing. It feels completely unpredictable, but i’ll find ways around it i hope.
Thanks again for your patience.
Have a good one!

It is. You never know when stuff is going to happen with real world devices, zwave, WiFi, etc. are inderminate. It’s why openHAB is the way it is.

Share a problematic rule.

Probably not under the right Topic, but OK.
Here is one, a charging simulator calculating accumulated charge by simple arithmetic.
I’m using item.postUpdate() to simulate Item states. Same problem occurs though using a meter_energy item on a metered switch.
Reason is that Items maintain their content during .rules file updates while var Number goes to null. Hence it is possible for Items to accumulate energy consumption over time even if the .rules file is updated.
I have added more wait statements to see if that stabilizes the behavior without much success.

Take a look and have fun.
Comments are very much appreciated.

//Items:
Number Energy    // Energy Meter Item
Number StartE    // Start Energy
Number Charge    // Accumulated Charge

rule "Charging Simulator"
when
  Time cron "00 02 15 * * ?"                                           // Set time as required to run Test
then
  Energy.postUpdate(1.0)                                               // Set Item to an Energy
  Energy.postUpdate(10.0)                                              // Add an Energy
  StartE.postUpdate(Energy.state as Number)                            // Save as Start Energy
  Energy.postUpdate(60.0)                                              // Add an Energy
//  Thread::sleep(1000)                                                  // Wait
  Charge.postUpdate(Energy.state as Number - StartE.state as Number)   //Calculate Accum. Charge
  Thread::sleep(1000)                                                  // Wait for subtraction
  logInfo("Charging Rule", "Accumulated Charge = " + Charge.state)
end

Log results Shall be:

.... Energy changed from xx.0 to 1.0
.... Energy changed from 1.0 to 10.0
.... StartE changed from 1.0 to 10.0
.... Energy changed from 10.0 to 60.0
.... Charge changed from xx.0 to 50.0
logInfo - Accumulated Charge = 50.0

where xx.0 is previous state (null first time)

Results from one run:

.... Energy changed from 60.0 to 1.0
.... Energy changed from 1.0 to 10.0
.... Energy changed from 10.0 to 60.0
.... Charge changed from 59.0 to 0.0
logInfo - Accumulated Charge = 0.0

Results from another run with uncommented wait:

.... Energy changed from 60.0 to 1.0
.... Energy changed from 1.0 to 10.0
.... Energy changed from 10.0 to 60.0
.... Charge changed from 0.0 to 59.0
logInfo - Accumulated Charge = 59.0

I don’t understand the purpose of that.
X = 1
X = 10 … what was the 1 for? Just playing I suppose.

Now, in openHAB terms it’s much more complicated … postUpdate does what it says. It posts an update to the Item. That gets put on openHABs event bus, for anyone interested. There might be bindings or rule triggers listening for updates, the Item might be displayed to a UI listening for updates. And openHAB core which actually actions the post and finally updates the Item object.

In short -
Energy.postUpdate(1.0) takes a couple of milliseconds to get around to updating the Item state.
The rule does not stop and wait for that to happen, why should it. It’ll carry on executing the next lines of the rule.
It’s asynchronous.

You’ll note that because these things are happening asynchronously in a multi-threaded system, there is a tiny chance that the 10 update gets actioned before the 1, because they are issued so close together. openHAB event bus is usually pretty good at FIFO ordering, but I do not think there are any guarantees.

So, taking that into account, this is doomed to failure.
As the second line is being executed, you can have no idea whether the previous update has been actioned or not yet. (It usually has not.)
Here be unpredictable behaviour.

Wahh, what can we do?
On the face of it those two lines of code are dumb, but I understand this is just an exploratory rule.
In a real rule doing that, you would not attempt to “read back” the Item state … you already know what exactly what you just posted to it and would just use the “10”.

But … you do not have to structure a real rule that way at all. You need to be clear about your objective. Looking at your line
StartE.postUpdate(Energy.state as Number)
I can interpret that as meaning you want to update Item StartE when Item Energy changes (if it doesn’t change, there’s no point most likely?)
I’d make a new rule for that. Do not be frightened of having many small rules. Understand the different rule triggers available - update, changed, etc.

rule "Charging updated"
when
  Item Energy changed
then
  StartE.postUpdate(Energy.state as Number) 
  // whatever else you might do e.g. calculations

Don’t be frightened to use variables in your rules, much more convenient than using Item states for everything. Because they are updated immediately, for one thing!

Let’s rewrite that with a variable and so get rid of the delay.

var myTemp = (Energy.state as Number) - (StartE.state as Number) //Calculate Accum. Charge
Charge.postUpdate(myTemp) //update the Item
logInfo("Charging Rule", "Accumulated Charge = " + myTemp.toString)

I’m guessing you’re trying to simulate a periodic charger report, and add that to a running total.
That’s at least two separate tasks for separate rules.
One time based rule issuing simulated charger status to an Item.
Another rule listening for Item change and then doing the sums.

Wow. That was a lot of good comments.
Thanks. Very much appreciated!!