Strange dimming behavior of ikea zigbee thing

[dniklas1 (Daniel)]

I’m using a light bulb “TRÅDFRI” from IKEA

I have recogniced a strange behavior, when dimming the light bulb: when i send one value, the thing status is update (every time) with 3 steps (eg):

2024-02-26 12:51:58.164 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'Zigbee_Kueche_Unterschrank_10w' received command 77
2024-02-26 12:51:58.272 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zigbee_Kueche_Unterschrank_10w' changed from 100 to 77
2024-02-26 12:51:58.374 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zigbee_Kueche_Unterschrank_10w' changed from 77 to 98
2024-02-26 12:51:59.373 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zigbee_Kueche_Unterschrank_10w' changed from 98 to 77

From my point of view, the “step between” is not a valid one: i want to dimm from 100 to 77. The first change event ist from 100 to 77. But the second one is from 77 to 98. And this is the wrong direction.

Any ideas whats going on here?

This was off topic in another thread:
KNX-Switch to dim of zigbee light bulb

Perhaps updating the zigbee thing could be an option. But i don’t know how to do this:
Ota: how to upgrade zigbee devices

Any ideas?
Perhaps more debug logging might helpt. Which category?

Best regards
Daniel

[rpwong (Russ)]

@dniklas1

when i send one value, the thing status is update (every time) with 3 steps (eg):

Note that it’s the item status, not the thing status. As you get more into openHAB, you’ll find that this distinction matters.

What you’re seeing is a side effect of autoupdate. You can set that to false in the item configuration by adding metadata.

Here’s a good explanation of autoupdate. It was written for OH2, but the logic is still valid.

Autoupdate - a primer

I’ve found myself having to investigate and/or explain some of the features of autoupdate over time, and thought an in-depth view would be helpful. These notes apply to openHAB version 2.5 Overview Autoupdate is primarily a “speed up” feature for openHAB Items. Mostly we can ignore it, but sometimes you may get an unwanted or unexpected effect, or you may wish to exercise more control. To fully understand autoupdate, we must understand the difference between command and state of Items. If w…

[dniklas1 (Daniel)]

Hey, sorry guys: @Udo_Hartmann mentioned that already in the other thead. I tried that, but without sucess:

The behavior does not change, there ist already the step between. Whats wrong? Is this the correct setting?

[rpwong (Russ)]

@dniklas1

mentioned that already in the other thead

I clicked that link and saw it was about your KNX, but I admittedly didn’t scroll far enough down. For what it’s worth, if it’s your thread and you’ve already talked about the issue at length, you don’t need to start a new one. Going off-topic is only an issue when someone else has started the thread.

@dniklas1

Is this the correct setting?

Yes, assuming you’ve attached it to the correct item. I don’t mean that sarcastically…it’s really easy to edit the wrong item.

Your log is showing the textbook example of autoupdate, so I don’t know why disabling wouldn’t fix it. But perhaps more importantly…does it matter? This doesn’t affect the actual operation of the device, so you only really need to fix it if it’s causing trouble for a rule. Otherwise, it’s just a split-second item update in the log.

[apella12 (Bob Eckhoff)]

Likely what is going on row 2 is the autoupdate. Row three is the light sending an unsolicited current state after getting the “SET” command. Two comments on this; 1) it takes a while for a dimmer to reach a new state and 2) this message is likely not compliant with the zigbee spec. (they aren’t supposed to send unsolicted messages in response to a “SET”, but some devices do anyway. Row four is after the device responds with a REPORT to a command poll (GET). I’m guessing on the UI page you have command poll set to 1 sec (1000ms)?

[dniklas1 (Daniel)]

@rpwong

Yes, assuming you’ve attached it to the correct item. I don’t mean that sarcastically…it’s really easy to edit the wrong item.

You’re right, that might be the problem. But it think it is correct:

@rpwong

our log is showing the textbook example of autoupdate, so I don’t know why disabling wouldn’t fix it. But perhaps more importantly…does it matter?

Not a big problem, i have to workaround this in my dimming rule, when i want to get level up to 100 or down to 0. Nevertheless it would be nice, to get rid of this.

@apella12

Likely what is going on row 2 is the autoupdate. Row three is the light sending an unsolicited current state after getting the “SET” command. Two comments on this; 1) it takes a while for a dimmer to reach a new state and 2) this message is likely not compliant with the zigbee spec. (they aren’t supposed to send unsolicted messages in response to a “SET”, but some devices do anyway. Row four is after the device responds with a REPORT to a command poll (GET). I’m guessing on the UI page you have command poll set to 1 sec (1000ms)?

2 ) can i see this in debug log if the zigbee binding, perhaps?
I don’t set al “command poll”. What is that, i don’t know what it is?

I set frequency: 300 in the dimmer channel of my thing.

[dniklas1 (Daniel)]

ok, now i set logging catetory org.openhab.binding.zigbee to debug.
This is the output, when i set dimm level to 77:

2024-03-08 08:10:53.945 [INFO ] [script.ui.testDimmwertKuecheStatisch] - Küche Unterschrank per Rule auf 77 setzen.
2024-03-08 08:10:53.968 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 3C2EF5FFFEEE71BB: Command for channel zigbee:device:d541f83264:3c2ef5fffeee71bb:3C2EF5FFFEEE71BB_1_dimmer --> 77 [PercentType]
2024-03-08 08:10:53.971 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 3C2EF5FFFEEE71BB: Channel zigbee:device:d541f83264:3c2ef5fffeee71bb:3C2EF5FFFEEE71BB_1_dimmer waiting for response to 77
2024-03-08 08:10:53.950 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'Zigbee_Kueche_Unterschrank_10w' received command 77
2024-03-08 08:10:54.052 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 3C2EF5FFFEEE71BB: Channel zigbee:device:d541f83264:3c2ef5fffeee71bb:3C2EF5FFFEEE71BB_1_dimmer received SUCCESS in response to 77
2024-03-08 08:10:54.054 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 3C2EF5FFFEEE71BB: Channel zigbee:device:d541f83264:3c2ef5fffeee71bb:3C2EF5FFFEEE71BB_1_dimmer updated to 77
2024-03-08 08:10:54.055 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 3C2EF5FFFEEE71BB: Updating ZigBee channel state zigbee:device:d541f83264:3c2ef5fffeee71bb:3C2EF5FFFEEE71BB_1_dimmer to 77
2024-03-08 08:10:54.093 [DEBUG] [nternal.converter.ZigBeeConverterIas] - 0015BC0031020273: ZigBee command report ZoneStatusChangeNotificationCommand [IAS Zone: 18B1/35 -> 0000/1, cluster=0500, TID=C1, zoneStatus=48, extendedStatus=0, zoneId=0, delay=65535]
2024-03-08 08:10:54.093 [DEBUG] [nternal.converter.ZigBeeConverterIas] - 0015BC0031020273: ZigBee command report ZoneStatusChangeNotificationCommand [IAS Zone: 18B1/35 -> 0000/1, cluster=0500, TID=C1, zoneStatus=48, extendedStatus=0, zoneId=0, delay=65535]
2024-03-08 08:10:54.093 [DEBUG] [nternal.converter.ZigBeeConverterIas] - 0015BC0031020273: ZigBee command report ZoneStatusChangeNotificationCommand [IAS Zone: 18B1/35 -> 0000/1, cluster=0500, TID=C1, zoneStatus=48, extendedStatus=0, zoneId=0, delay=65535]
2024-03-08 08:10:54.095 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 0015BC0031020273: Channel zigbee:device:d541f83264:0015bc0031020273:0015BC0031020273_35_tamper updated to OFF
2024-03-08 08:10:54.096 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0015BC0031020273: Updating ZigBee channel state zigbee:device:d541f83264:0015bc0031020273:0015BC0031020273_35_tamper to OFF
2024-03-08 08:10:54.157 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - 3C2EF5FFFEEE71BB: ZigBee attribute reports ZclAttribute [cluster=Level Control, id=0, name=Current Level, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=138, lastReportTime=Fri Mar 08 08:10:54 CET 2024, implemented=true]
2024-03-08 08:10:54.159 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 3C2EF5FFFEEE71BB: Channel zigbee:device:d541f83264:3c2ef5fffeee71bb:3C2EF5FFFEEE71BB_1_dimmer updated to 54
2024-03-08 08:10:54.160 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 3C2EF5FFFEEE71BB: Updating ZigBee channel state zigbee:device:d541f83264:3c2ef5fffeee71bb:3C2EF5FFFEEE71BB_1_dimmer to 54
2024-03-08 08:10:54.059 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zigbee_Kueche_Unterschrank_10w' changed from 52 to 77
2024-03-08 08:10:54.166 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zigbee_Kueche_Unterschrank_10w' changed from 77 to 54
2024-03-08 08:10:55.158 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - 3C2EF5FFFEEE71BB: ZigBee attribute reports ZclAttribute [cluster=Level Control, id=0, name=Current Level, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=196, lastReportTime=Fri Mar 08 08:10:55 CET 2024, implemented=true]
2024-03-08 08:10:55.160 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 3C2EF5FFFEEE71BB: Channel zigbee:device:d541f83264:3c2ef5fffeee71bb:3C2EF5FFFEEE71BB_1_dimmer updated to 77
2024-03-08 08:10:55.161 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 3C2EF5FFFEEE71BB: Updating ZigBee channel state zigbee:device:d541f83264:3c2ef5fffeee71bb:3C2EF5FFFEEE71BB_1_dimmer to 77
2024-03-08 08:10:55.167 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Zigbee_Kueche_Unterschrank_10w' changed from 54 to 77
2024-03-08 08:10:58.804 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'amazonechocontrol:smartHomeDevice:amazonAccount:1909d1f9-3898-40de-8977-789ac37f34c8' changed from UNKNOWN: State not found to ONLINE
2024-03-08 08:11:03.444 [DEBUG] [nternal.converter.ZigBeeConverterIas] - 0015BC0031020305: ZigBee command report ZoneStatusChangeNotificationCommand [IAS Zone: CEEA/35 -> 0000/1, cluster=0500, TID=11, zoneStatus=48, extendedStatus=0, zoneId=0, delay=65535]
2024-03-08 08:11:03.444 [DEBUG] [nternal.converter.ZigBeeConverterIas] - 0015BC0031020305: ZigBee command report ZoneStatusChangeNotificationCommand [IAS Zone: CEEA/35 -> 0000/1, cluster=0500, TID=11, zoneStatus=48, extendedStatus=0, zoneId=0, delay=65535]
2024-03-08 08:11:03.444 [DEBUG] [nternal.converter.ZigBeeConverterIas] - 0015BC0031020305: ZigBee command report ZoneStatusChangeNotificationCommand [IAS Zone: CEEA/35 -> 0000/1, cluster=0500, TID=11, zoneStatus=48, extendedStatus=0, zoneId=0, delay=65535]
2024-03-08 08:11:03.446 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 0015BC0031020305: Channel zigbee:device:d541f83264:0015bc0031020305:0015BC0031020305_35_tamper updated to OFF
2024-03-08 08:11:03.448 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0015BC0031020305: Updating ZigBee channel state zigbee:device:d541f83264:0015bc0031020305:0015BC0031020305_35_tamper to OFF
2024-03-08 08:11:09.251 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'amazonechocontrol:smartHomeDevice:amazonAccount:1909d1f9-3898-40de-8977-789ac37f34c8' changed from ONLINE to UNKNOWN: State not found
2024-03-08 08:11:18.082 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 60B647FFFE3F4937: Not polling zigbee:device:d541f83264:60b647fffe3f4937:60B647FFFE3F4937_1_dimmer - channel is not linked
2024-03-08 08:11:20.303 [DEBUG] [nternal.converter.ZigBeeConverterIas] - 0015BC003102057B: ZigBee command report ZoneStatusChangeNotificationCommand [IAS Zone: 679E/35 -> 0000/1, cluster=0500, TID=B8, zoneStatus=48, extendedStatus=0, zoneId=0, delay=65535]
2024-03-08 08:11:20.303 [DEBUG] [nternal.converter.ZigBeeConverterIas] - 0015BC003102057B: ZigBee command report ZoneStatusChangeNotificationCommand [IAS Zone: 679E/35 -> 0000/1, cluster=0500, TID=B8, zoneStatus=48, extendedStatus=0, zoneId=0, delay=65535]
2024-03-08 08:11:20.303 [DEBUG] [nternal.converter.ZigBeeConverterIas] - 0015BC003102057B: ZigBee command report ZoneStatusChangeNotificationCommand [IAS Zone: 679E/35 -> 0000/1, cluster=0500, TID=B8, zoneStatus=48, extendedStatus=0, zoneId=0, delay=65535]
2024-03-08 08:11:20.305 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 0015BC003102057B: Channel zigbee:device:d541f83264:0015bc003102057b:0015BC003102057B_35_tamper updated to OFF
2024-03-08 08:11:20.306 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0015BC003102057B: Updating ZigBee channel state zigbee:device:d541f83264:0015bc003102057b:0015BC003102057B_35_tamper to OFF```

[apella12 (Bob Eckhoff)]

TBH I’m not familiar with zigbee, but what I described is how Zwave works and they are products of the same company (Silabs) and the OH bindings are written by the same developer, so I figured they operate similarly.
With that caution;

@dniklas1

I don’t set al “command poll”. What is that, i don’t know what it is?

From the other linked topic I see this; I’m thinking that is the zigbee equivalent of Command Poll. The reason for the polling delay is that dimmers take a while to reach their commanded state.

    configuration:
      zigbee_reporting_polling: 900

I ran your log snippet through the Zigbee debug viewer and there is a clear update at one second.

I’d still maintain that the intermediate reading a spurious (and too early) report from the device.

[dniklas1 (Daniel)]

ok, so “autoupdate=false” cannot help. Strictly speeking this is a bug of the zigbee device?

A solution might be to update the zigbee devices. I tried this without success so far:

Ota: how to upgrade zigbee devices

There’s a little bit of info on the zigbee otaupgrade here: Purpose of Zigbee otaupgrade commandline

[rpwong (Russ)]

@dniklas1

ok, so “autoupdate=false” cannot help.

Yep, if you’ve definitely got it on the right item, @apella12’s theory is more likely.

I don’t know anything about OTA updates with the Zigbee binding, so I can’t help you there. I use Zigbee2mqtt instead of the binding.

[chris (Chris Jackson)]

This is perfectly normal, and it’s the way that Zigbee works. It’s not a bug, and it’s not a spurious reading…

When you command a device to go from (say) 0% to 100%, it will do so over a specified time period. By default this is 1 second. Devices are configured to send reports when they change - this is required when the state of a device changes because someone manually updates it. So, when the device changes from 0 to 100%, the device will likely send a report at some point during this change.

In theory, it would be possible to change the rate at which reports are sent. This defaults (I think) to every second if there is a change. However, changing this will have other side effects - ie when other changes are made, there will be a delay in reporting…

Like everything in life, it’s a trade, but basically. what you are seeing if the inevitable delay from commanding the device, to. the device actually implementing the change.

[dniklas1 (Daniel)]

@chris

When you command a device to go from (say) 0% to 100%, it will do so over a specified time period. By default this is 1 second. Devices are configured to send reports when they change - this is required when the state of a device changes because someone manually updates it. So, when the device changes from 0 to 100%, the device will likely send a report at some point during this change.

No problem with that. I was surprised, because the device reported stepts in the wrong direction:

i estimated: 0 → 100
0 → 16
41 → 65
80 → 97

but not: 0 → 100
0 → 41
16 → 51
98 → 100
or something like that.