I have a rule that controls the lights in my room depending on motion, daylight and time of day. Sometimes the rule does not work as expected and light is not toggled. I can see from the logs that this is because sometimes the items behave the opposite of what they should with log entries like:
2021-01-26 14:54:09.344 [ome.event.ItemCommandEvent] - Item 'I_FL_Kommodenlicht_Toggle' received command OFF
2021-01-26 14:54:09.370 [nt.ItemStatePredictedEvent] - I_FL_Kommodenlicht_Toggle predicted to become ON
The rule has turned it off (like it can also be correctly seen in the first line) but for some reason it says “predicted to become ON” and it also stays on in this example.
The prediction comes from the autoupdate feature, probably in collusion with whatever binding is involved here.
Details, see
I think the area of interest is likely to be
“Linked Item with broken channel or an OFFLINE Thing, or binding veto”
which I think is about the only circumstance where a prediction overrides a command. The binding has said “nah, can’t do that, somethings offline”
So your real problem is -
Sometimes the command cannot be implemented - connectivity, busy with something else?
There are/were a few zigbee things that applied a veto in the binding, which would look like this, but that’s permanent not occasionally.
Looking at timestamps, 26mS seems a long time between command and prediction. Is this a heavily loaded system? Is it perhaps busy doing some kind of error recovery?
What is the state of the switch item BEFORE the rule sends the command to ON? I suspect OFF. Such can happen if the item is not in sync with the real thing ( caused by missing this information).
The binding being used here in the Hue binding. Indeed, the light loses connection frequently (for unknown reason) which can be seen in the logs with entries like this:
2021-01-26 15:24:55.180 [hingStatusInfoChangedEvent] - 'hue:XXX changed from ONLINE to OFFLINE: Hue bridge reports light as not reachable.
and then again
2021-01-26 15:29:28.853 [hingStatusInfoChangedEvent] - ‘hue:XXX’ changed from OFFLINE: Hue bridge reports light as not reachable. to ONLINE .
However, I have already checked that in these problems occur at times when the thing is online at least according to this logging.
In the example above, the light is ON and should be turned off. The status of the switch item is also ON.
That’s far too much of a coincidence. The online/offline reporting is only going to happen after something’s gone wrong, and there may be timeouts involved too.
PS: I do not thing that this is a heavily loaded system but do not know for sure. We are talking about a rasperry pi here. Output of the top command is
top - 15:32:55 up 4 days, 16:27, 1 user, load average: 0.12, 0.18, 0.25
Tasks: 109 total, 1 running, 64 sleeping, 0 stopped, 0 zombie
%Cpu(s): 2.2 us, 0.5 sy, 0.0 ni, 97.2 id, 0.0 wa, 0.0 hi, 0.1 si, 0.0 st
KiB Mem : 999036 total, 55452 free, 575988 used, 367596 buff/cache
KiB Swap: 102396 total, 83880 free, 18516 used. 480460 avail Mem
Okay,it was just a thought. If you look at other Items you’ll probably find a command-to-prediction delay of just a few mS. This one might take longer because an error is involved.
