What is ItemStatePredictedEvent?

Hi.
Since the Tellstick binding is currently broken I’ve been handling my Tellstick Items directly instead, so when the Items (which has still been linked to the Tellstick Things which has the status UNINITIALIZED because of the broken binding) change state I have a rule calling a command via executeCommandLine() to change the state of the device instead. However, after today having updated to milestone 4 this suddenly stopped working, every time I tried to change state on one of the Items I got the following in my log:

2018-09-26 20:15:00.061 [ome.event.ItemCommandEvent] - Item 'EllasFonsterlampa' received command OFF
2018-09-26 20:15:00.073 [nt.ItemStatePredictedEvent] - EllasFonsterlampa predicted to become NULL

…and the Item didn’t change state and thus the rule wasn’t called.

I simply solved this by removing the links between the uninitialized Things and my Items, but I’m trying to understand what is happening here. Is this some new fancy technology that tries to predict what state an Item will have before the status is really changed?

Guess it would be a good idea removing all those broken Things altogheter, but I’m still nourishing the hope that the Tellstick Binding will some day be fixed :slight_smile:

That is indeed a new fancy feature that you have encountered here, see https://github.com/eclipse/smarthome/pull/5011.

The “autoUpdate” is now cleverer than before - instead of pro-actively setting the item state to OFF when seeing an OFF command, it checks whether it is likely that the command is getting processed at all, which in your case isn’t the case as the Thing is uninitialized.

This rule should be triggered by the command, not by a state update (as it wants to send this itself). So if you change the trigger of the rule, everything should work as expected, even without removing the links.

1 Like

Well, that really IS fancy :smile:

Tried changing my triggers from “changed” to “received command” and indeed that made them being called. It didn’t work anyway however since I’m using triggeringItem.state in my command and it’s obviously not ON or OFF any more but NULL. So I have to unlink my Items anyway. Guess I’ll need to mention this in my broken-Tellstick-binding-workaround-howto as well.

So I suppose this is a breaking change, but only to people that use the system in a way that it’s not supposed to being used :wink:

Well, you should use receivedCommand instead, then it will also work with the links in place.

1 Like

Doh. Never used that one before. Updating my howto again :wink:

Hmm, looks like this clever autoUpdate feature outsmarts me. :grin:

I have a lot of Hue lights but somehow one of them is always reported as ON in OH. I can visually and in the official Hue App confirm that the light as actually off, so basically it works just fine outside OH (e.g. triggering it via the Hue built-in sunset/sunrise sensor state).
When trying to turn of in OH, the following two messages are logged in events.log:

[ome.event.ItemCommandEvent] - Item ‘SW_ChairLight’ received command OFF
[nt.ItemStatePredictedEvent] - SW_ChairLight predicted to become ON

And the status in OH and on the sitemap returns back to ON (nothing happens to the physical light).

The Thing definition:

Bridge hue:bridge:1 [ipAddress="...", userName="..."]
{
    // Livingroom chair standing light
    0220 bulb_chair [lightId="1"]
    ...

The Item involved:

// Livingroom chair light
Switch SW_ChairLight "Staandelamp stoel" (gLivingroom) {channel="hue:0220:1:1:brightness"}
Dimmer DM_ChairLight "Staandelamp stoel dimmer" (gLivingroom) {channel="hue:0220:1:1:brightness"}
Dimmer CT_ChairLight "Staandelamp stoel kleurtint" (gLivingroom) {channel="hue:0220:1:1:color_temperature"}

On startup of OH, the following is logged:

[.ItemChannelLinkAddedEvent] - Link 'DM_ChairLight-hue:0220:1:1:brightness' has been added.[.ItemChannelLinkAddedEvent] - Link 'SW_ChairLight-hue:0220:1:1:brightness' has been added.
[.ItemChannelLinkAddedEvent] - Link 'CT_ChairLight-hue:0220:1:1:color_temperature' has been added.
[hingStatusInfoChangedEvent] - 'hue:bridge:1' changed from UNINITIALIZED to INITIALIZING
[hingStatusInfoChangedEvent] - 'hue:0220:1:bulb_chair' changed from UNINITIALIZED to UNINITIALIZED (BRIDGE_UNINITIALIZED)
[vent.ItemStateChangedEvent] - SW_ChairLight changed from NULL to ON
[vent.ItemStateChangedEvent] - DM_ChairLight changed from NULL to 24
[vent.ItemStateChangedEvent] - CT_ChairLight changed from NULL to 82
[hingStatusInfoChangedEvent] - 'hue:bridge:1' changed from INITIALIZING to ONLINE
[hingStatusInfoChangedEvent] - 'hue:0220:1:bulb_chair' changed from UNINITIALIZED (BRIDGE_UNINITIALIZED) to INITIALIZING
[me.event.ThingUpdatedEvent] - Thing 'hue:0220:1:bulb_chair' has been updated.
[me.event.ThingUpdatedEvent] - Thing 'hue:0220:1:bulb_chair' has been updated.
[me.event.ThingUpdatedEvent] - Thing 'hue:0220:1:bulb_chair' has been updated.
[hingStatusInfoChangedEvent] - 'hue:0220:1:bulb_chair' changed from INITIALIZING to ONLINE

Doing a GET on the Hue API with:

/api/<whitelisted_user>/lights/1

shows that the light is actually OFF according to the Hue bridge:

{
	"state": {
		"on": false,
		"bri": 48,
		"ct": 451,
		"alert": "none",
		"colormode": "ct",
		"mode": "homeautomation",
		"reachable": true
	},
    ...

Neither restart of Hue Bridge device, restart of OH or clear OH cache and tmp fixed it. Currently running OH 2.4.0-SNAPSHOT Build #1389, btw.

I wonder how clever autoupdate has become. While what it is doing may surprise you, it seems like a sensible action.
Light is ON
Item commanded OFF
Autoupdate runs - sees that Item will get updated by device via binding later - leaves Item ON
binding sends command OFF to device
after a while, binding receives new OFF update from device
binding updates Item to OFF

Personally I disable with autoupdate=“false” whenever my Item is going to get a prompt update from the device with the real state anyway. I view Autoupdate as the best-guess where that is not possible.
Perhaps we need an autoupdate=“force” option as well?

I understand the logic of that. However, that means once it gets out of sync, it will never restore until an explicit update command is sent to the light. I did a ‘manual’ postUpdate and now it is off.

However, there are still issues with that light. Others do actually switch on and off and the switch status reflects that. But this one just stay OFF now. Two example events.log entries for two lights. First a correctly working light and switch item:

[ome.event.ItemCommandEvent] - Item 'SW_RtKitchenLight' received command ON
[nt.ItemStatePredictedEvent] - SW_RtKitchenLight predicted to become ON
[vent.ItemStateChangedEvent] - SW_RtKitchenLight changed from OFF to ON
[vent.ItemStateChangedEvent] - DM_RtKitchenLight changed from 0 to 57
[ome.event.ItemCommandEvent] - Item 'SW_RtKitchenLight' received command OFF
[nt.ItemStatePredictedEvent] - SW_RtKitchenLight predicted to become OFF
[vent.ItemStateChangedEvent] - SW_RtKitchenLight changed from ON to OFF

Than the erroneous light:

[ome.event.ItemCommandEvent] - Item 'SW_ChairLight' received command ON
[nt.ItemStatePredictedEvent] - SW_ChairLight predicted to become OFF
[vent.ItemStateChangedEvent] - DM_RtKitchenLight changed from 57 to 0
[ome.event.ItemCommandEvent] - Item 'SW_ChairLight' received command ON
[nt.ItemStatePredictedEvent] - SW_ChairLight predicted to become OFF

What could make these two Hue lights behave differently?

Well yes, that depends on the binding/technology involved. A polling technology would take care of it, or an on-demand tech would require the binding to conduct a ‘refresh’ as part of initializing. Autoupdate plays no part in any of that.

I don’t know about Hue. It might help others if you can show the Thing and Item definitions for the “good” lamp as well.

But looking at log

[ome.event.ItemCommandEvent] - Item 'SW_ChairLight' received command ON
[nt.ItemStatePredictedEvent] - SW_ChairLight predicted to become OFF
[vent.ItemStateChangedEvent] - DM_RtKitchenLight changed from 57 to 0
[ome.event.ItemCommandEvent] - Item 'SW_ChairLight' received command ON
[nt.ItemStatePredictedEvent] - SW_ChairLight predicted to become OFF

The Item SW_Chairlight appears to be broken. There never is a state change. I’m guessing that autoupdate knows it is broke - channel is uninitialized? - and so will not predict ON.
Maybe it should be suggesting NULL or UNDEF instead in that circumstance.

Is the unconnected Kitchen Item popping up there by coincidence, or is there a configuation issue?

Thanks @rossko57 for your support!
The log entry for the kitchen light was there in between because I tried different lights in a short time frame.
And all lights are configured the same.
Thing definition for a light that works fine (similar to the offending light):

// Kitchen right light
0220 bulb_rkitchen [lightId="14"]

Item definition for that light:

// Kitchen right light
Switch SW_RtKitchenLight "Keukenlamp rechts" (gKitchen) {channel="hue:0220:1:bulb_rkitchen:brightness"}
Dimmer DM_RtKitchenLight "Keukenlamp rechts dimmer" (gKitchen) {channel="hue:0220:1:bulb_rkitchen:brightness"}
Dimmer CT_RtKitchenLight "Keukenlamp rechts tint" (gKitchen) {channel="hue:0220:1:bulb_rkitchen:color_temperature"}

Something is broken, indeed. Not sure what. The erroneous light thing (and channel) get initialized properly as shown in the log entries in post #6 above:

'hue:0220:1:bulb_chair' changed from INITIALIZING to ONLINE

I note that chair has
channel=“hue:0220:1:1:brightness”
and kitchen has
channel=“hue:0220:1:bulb_rkitchen:brightness”
Wonder if there may be some funny effect using just a digit as a channel name?

That was a remnant from some testing I’ve done to get rid of the repeated bridge discovery and inbox delete log messages. Changing didn’t fix it. I ended up reinstalling the binding and re-importing the thing and item definitions. It’s fixed now.
Again, thanks for your support.

EDIT: And I’ve learned a thing or two about autoupdate along the way.:grin:

1 Like

Glad it’s fixed, but hate mystery glitches like that. Some caching or something behind it I expect.

I played about a bit and ended up adding autoupdate=“true”, which seemed to fix things and get things working like they used to. So I don’t know what the current logic of predicted state is, but it seems to be different to autoupdate=true/false.

i have the same problem using amazon-dash binding. some buttons are working and some not.
here ist the log:

2019-12-26 15:20:48.649 [ome.event.ItemCommandEvent] - Item 'DashDecke' received command ON
2019-12-26 15:20:48.653 [nt.ItemStatePredictedEvent] - DashDecke predicted to become NULL
2019-12-26 15:21:09.607 [ome.event.ItemCommandEvent] - Item 'DashDecke' received command ON
2019-12-26 15:21:09.613 [nt.ItemStatePredictedEvent] - DashDecke predicted to become NULL
2019-12-26 15:21:37.812 [ome.event.ItemCommandEvent] - Item 'Dashfinish' received command ON
2019-12-26 15:21:37.845 [vent.ItemStateChangedEvent] - Dashfinish changed from NULL to ON

Dashfinish is working and switching…DashDecke not. any suggestions?

If DashDecke is an Item not suited to command ON, autoupdate won’t be able to make a prediction.
Any bindings linked to DashDecke also get a say in autoupdate’s prediction. If for example the channel config is invalid, autupdate can be vetoed.

autoupdate wasn´t even enabled! enabled it over paperUI/things for dashdecke. it works now.
how can that be implemented in the .items file?

I’ve noticed this scroll by whilst watching logs in the console. Always wondered about it. I learned something today. :slight_smile:

1 Like

autoupdate is enabled by default for each and every Item. If it is not enabled, you do not get predictions.

To control in xxx.items file definitions, place in the bindings parameters e.g.
... someItem ... { channel=blah, autoupdate="false"}
to disable

Hey there =)

Is it possible to turn those log entries off in \openhab2-userdata\etc\org.ops4j.pax.logging.cfg?

So the ItemStatePredictedEvent dont show up in the log

2020-03-29 20:14:20.540 [nt.ItemStatePredictedEvent] - Deckenlampe_Ledbrightness predicted to become 0

And the ItemStateChangedEvent show up in log

2020-03-29 20:14:20.561 [vent.ItemStateChangedEvent] - Deckenlampe_Ledbrightness changed from 100 to 0

Because now these changes show up twice in the log viewer. It would be great if there was a way to only let them show once!

Thanks!