I’ve been experiencing an odd bug, and have narrowed it down to sendCommand being slightly asynchronous.
It can be demonstrated with the following:
items file:
String sillytest "This is a test"
Rule:
logInfo("TEST", "Currently {}",sillytest.state)
sillytest.sendCommand("I am now set")
logInfo("TEST", "Step 1: {}",sillytest.state)
Thread::sleep(500)
logInfo("TEST", "Step 2: {}",sillytest.state)
The logs should (I would think) show the same output at step 1 and step 2 - but they don’t:
20|2018-06-27 22:07:45.520 [INFO ] [.eclipse.smarthome.model.script.TEST] - Currently NULL |
20|2018-06-27 22:07:45.520 [INFO ] [.eclipse.smarthome.model.script.TEST] - Step 1: NULL |
20|2018-06-27 22:07:46.021 [INFO ] [.eclipse.smarthome.model.script.TEST] - Step 2: I am now set
So the item hasn’t updated in time for the next line of the rule. Only after a delay have things caught up:
This example repeats every time for me - do others see the same effect? Or something weird about my system - a fairly vanilla ubuntu 16.04 build running the OH 2.3 release version?
This is perfectly normal
Is you look at the log when a command is sent to an item would will see for example:
2018-06-27 22:32:57.682 [ome.event.ItemCommandEvent] - Item 'Presence_Vincent' received command ON
2018-06-27 22:32:57.690 [vent.ItemStateChangedEvent] - Presence_Vincent changed from OFF to ON
The item receives a command and the state updates 8ms later
When your rule execute the logInfo line below the sendCommand line execute very quickly after. Before the item has changed state.
The openHAB eventbus is doing it’s job. It is doing a bit slower than the rules are executing.
This is normal behaviour and needs to be taken into account when writing rules.
For example:
rule "dummy"
when
Item dummy received command ON
then
logInfo("DUMMY", dummy.state.toString)
end
Will not necessarily print out the state as ON because the rule execute immediately as soon as the ON command is received but as the item state is not yet updated, you cannot rely on the state of the item in the rule.
Note also that sendCommand may never update an Items .state at all, e.g. when autoupdate=“false”, and/or an update may occur some later via a binding to external data.
This is by design.
Recent related posting
It’s one of those areas you have to get your head around when writing non-trivial rules, so always worth bringing it up.
