Core: ZHA unable to set brightness and color temperature in same call

[perosb]

Home Assistant release with the issue:
0.89.1

Last working Home Assistant release (if known):
NA

Operating environment (Hass.io/Docker/Windows/etc.):
rpi3
IKEA bulbs

Component/platform:
https://www.home-assistant.io/components/zha

(eventhough it says "custom_components" in below, it's from master 0.89.1)

Description of problem:
When trying to set both brightness and color temperature in the same call, the brightness just flickers. Color temperature changes ok.

Traceback (if applicable):

2019-03-10 11:51:27 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Sending: b'47ce219c54b4abb6589c4a24ab1593499c3851adecb86375f8c6d7d37e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Data frame: b'75cea19c54eafb187e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Sending: b'8070787e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.ezsp] Application frame 52 (sendUnicast) received
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Data frame: b'05ceb1f1ca94ded3696ab572a1556d829cfe037e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Sending: b'8160597e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.ezsp] Application frame 89 (incomingRouteRecordHandler) received
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Data frame: b'15ceb1f1ca94ded3696ab572a1556d829ce0027e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Sending: b'82503a7e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.ezsp] Application frame 89 (incomingRouteRecordHandler) received
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Data frame: b'25ceb1ed542e14ba59954b65ab5592d96385b915123162838bcd678961467e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Sending: b'83401b7e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Data frame: b'35ceb19754b4abb6589c4a24ab1593499c8e51abedad407e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Sending: b'8430fc7e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.ezsp] Application frame 63 (messageSentHandler) received
2019-03-10 11:51:27 DEBUG (MainThread) [custom_components.zha.core.channels] 0xbe9e:1:0x0008: executed command: move_to_level_with_on_off with args: (254, 5) with kwargs: {} and result: [4, <Status.SUCCESS: 0>]
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Sending: b'54cf219c54b4abb658924a24ab1593499c3950a8ecb966ace57e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Data frame: b'46cfa19c54eba0047e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Sending: b'8520dd7e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.ezsp] Application frame 52 (sendUnicast) received
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Data frame: b'56cfb1f1ca94ded3696ab572a1556d809c67667e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Sending: b'8610be7e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.ezsp] Application frame 89 (incomingRouteRecordHandler) received
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Data frame: b'66cfb1f1ca94ded3696ab572a1556d839c10367e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Sending: b'87009f7e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.ezsp] Application frame 89 (incomingRouteRecordHandler) received
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Data frame: b'76cfb1ed542e14b459954b65ab5592d86385b915123162838acd62891b957e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Sending: b'8070787e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Data frame: b'06cfb19754b4abb658924a24ab1593499c8f50abed24ac7e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Sending: b'8160597e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.ezsp] Application frame 63 (messageSentHandler) received
2019-03-10 11:51:27 DEBUG (MainThread) [custom_components.zha.core.channels] 0xbe9e:1:0x0006: executed command: on with args: () with kwargs: {} and result: [1, <Status.SUCCESS: 0>]
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Sending: b'61cc219c54b4abb658944924ab1593499c365facecb66da0ffc363635b7e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Data frame: b'17cca19c54e84b817e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Sending: b'82503a7e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.ezsp] Application frame 52 (sendUnicast) received
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Data frame: b'27ccb1f1ca94ded3696ab572a1556d809cc5ce7e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Sending: b'83401b7e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.ezsp] Application frame 89 (incomingRouteRecordHandler) received
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Data frame: b'37ccb1f1ca94ded3696ab572a1556d829cbdad7e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Sending: b'8430fc7e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.ezsp] Application frame 89 (incomingRouteRecordHandler) received
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Data frame: b'47ccb1ed542e14b25a954b65ab5592db6385b9151231628385cd6989febf7e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Sending: b'8520dd7e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Data frame: b'57ccb19754b4abb658944924ab1593499c8c5fabedfe1d7e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.uart] Sending: b'8610be7e'
2019-03-10 11:51:27 DEBUG (MainThread) [bellows.ezsp] Application frame 63 (messageSentHandler) received
2019-03-10 11:51:27 DEBUG (MainThread) [custom_components.zha.core.channels] 0xbe9e:1:0x0300: executed command: move_to_color_temp with args: (555, 5) with kwargs: {} and result: [10, <Status.SUCCESS: 0>]

Additional information:
After the call, hass ui is updated with the changed state, however now incorrect values.

Calling the commands separately works ok:

Successful brightness call:

2019-03-10 11:53:41 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast
2019-03-10 11:53:41 DEBUG (MainThread) [bellows.uart] Sending: b'72cd219c54b4abb6589c4a24ab1593499c375eadecb76375f8c6a9297e'
2019-03-10 11:53:41 DEBUG (MainThread) [bellows.uart] Data frame: b'20cda19c54e9163c7e'
2019-03-10 11:53:41 DEBUG (MainThread) [bellows.uart] Sending: b'83401b7e'
2019-03-10 11:53:41 DEBUG (MainThread) [bellows.ezsp] Application frame 52 (sendUnicast) received
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.uart] Data frame: b'30cdb1f1ca94ded3696ab572a1556d809c01457e'
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.uart] Sending: b'8430fc7e'
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.ezsp] Application frame 89 (incomingRouteRecordHandler) received
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.uart] Data frame: b'40cdb1f1ca94ded3696ab572a1556d809c5b427e'
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.uart] Sending: b'8520dd7e'
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.ezsp] Application frame 89 (incomingRouteRecordHandler) received
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.uart] Data frame: b'50cdb1ed542e14ba59954b65ab5592da6387b9151231628384cd67895cff7e'
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.uart] Sending: b'8610be7e'
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.uart] Data frame: b'60cdb19754b4abb6589c4a24ab1593499c8d5eabed638e7e'
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.uart] Sending: b'87009f7e'
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.ezsp] Application frame 63 (messageSentHandler) received
2019-03-10 11:53:42 DEBUG (MainThread) [custom_components.zha.core.channels] 0xbe9e:1:0x0008: executed command: move_to_level_with_on_off with args: (254, 5) with kwargs: {} and result: [4, <Status.SUCCESS: 0>]
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.uart] Sending: b'07d2219c54b4abb658924a24ab1593499c345da8ecb466c24f7e'
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.uart] Data frame: b'71d2a19c54ee324c7e'
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.uart] Sending: b'8070787e'
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.ezsp] Application frame 52 (sendUnicast) received
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.uart] Data frame: b'01d2b1f1ca94ded3696ab572a1556d809c69b47e'
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.uart] Sending: b'8160597e'
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.ezsp] Application frame 89 (incomingRouteRecordHandler) received
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.uart] Data frame: b'11d2b1f1ca94ded3696ab572a1556d809c77b57e'
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.uart] Sending: b'82503a7e'
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.ezsp] Application frame 89 (incomingRouteRecordHandler) received
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.uart] Data frame: b'21d2b1ed542e14b459954b65ab5592dd6387b9151231628387cd62894d267e'
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.uart] Sending: b'83401b7e'
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.uart] Data frame: b'31d2b19754b4abb658924a24ab1593499c8a5dabed65db7e'
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.uart] Sending: b'8430fc7e'
2019-03-10 11:53:42 DEBUG (MainThread) [bellows.ezsp] Application frame 63 (messageSentHandler) received
2019-03-10 11:53:42 DEBUG (MainThread) [custom_components.zha.core.channels] 0xbe9e:1:0x0006: executed command: on with args: () with kwargs: {} and result: [1, <Status.SUCCESS: 0>]

Successful color Temperature call:

2019-03-10 11:53:50 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.uart] Sending: b'14d3219c54b4abb658924a24ab1593499c355ca8ecb566ec3c7e'
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.uart] Data frame: b'42d3a19c54ef69507e'
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.uart] Sending: b'8520dd7e'
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.ezsp] Application frame 52 (sendUnicast) received
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.uart] Data frame: b'52d3b1f1ca94ded3696ab572a1556d809c96b37e'
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.uart] Sending: b'8610be7e'
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.ezsp] Application frame 89 (incomingRouteRecordHandler) received
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.uart] Data frame: b'62d3b1f1ca94ded3696ab572a1556d819c87817e'
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.uart] Sending: b'87009f7e'
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.ezsp] Application frame 89 (incomingRouteRecordHandler) received
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.uart] Data frame: b'72d3b1ed542e14b459954b65ab5592dc6387b9151231628386cd6289db007e'
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.uart] Sending: b'8070787e'
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.uart] Data frame: b'02d3b19754b4abb658924a24ab1593499c8b5cabedfca17e'
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.uart] Sending: b'8160597e'
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.ezsp] Application frame 63 (messageSentHandler) received
2019-03-10 11:53:50 DEBUG (MainThread) [custom_components.zha.core.channels] 0xbe9e:1:0x0006: executed command: on with args: () with kwargs: {} and result: [1, <Status.SUCCESS: 0>]
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.uart] Sending: b'21d0219c54b4abb658944924ab1593499c325bacecb26da0ffc36398347e'
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.uart] Data frame: b'13d0a19c54ec82d57e'
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.uart] Sending: b'82503a7e'
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.ezsp] Application frame 52 (sendUnicast) received
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.uart] Data frame: b'23d0b1f1ca94ded3696ab572a1556d809c341b7e'
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.uart] Sending: b'83401b7e'
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.ezsp] Application frame 89 (incomingRouteRecordHandler) received
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.uart] Data frame: b'33d0b1f1ca94ded3696ab572a1556d809c2a1a7e'
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.uart] Sending: b'8430fc7e'
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.ezsp] Application frame 89 (incomingRouteRecordHandler) received
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.uart] Data frame: b'43d0b1ed542e14b25a954b65ab5592df6387b9151231628381cd6989bbe97e'
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.uart] Sending: b'8520dd7e'
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.uart] Data frame: b'53d0b19754b4abb658944924ab1593499c885babed8fb17e'
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.uart] Sending: b'8610be7e'
2019-03-10 11:53:50 DEBUG (MainThread) [bellows.ezsp] Application frame 63 (messageSentHandler) received
2019-03-10 11:53:50 DEBUG (MainThread) [custom_components.zha.core.channels] 0xbe9e:1:0x0300: executed command: move_to_color_temp with args: (555, 5) with kwargs: {} and result: [10, <Status.SUCCESS: 0>]

[perosb]

I think its some kind of race condition.

When I set the transition to 0.001 it seem to work ok.

[perosb]

@dmulcahey not sure if this is rather an issue in bellows/zigpy?

[dmulcahey]

We have to look into this.

[dmulcahey]

@Adminiuga any thoughts?

[Adminiuga]

Not really. What model do you get for the light? Is it TRADFRI bulb E26 WS opal 980lm
Per trace, all calls are successful, but:

When I set the transition to 0.001 it seem to work ok.

Sounds interesting. I think in ZHA minimum duration resolution is 0.1s. Is there a specific duration value after which this fails? Also, when you say it flickers, does it

1. flickers continuously
2. just for the duration of transition -- 0.5s per trace

what was the brightness value before the light was turned off?

[perosb]

Hi,

flicker might be the wrong words, it's like it tries to change the brightness, but gets interrupted and goes back to the previous value.
I've tried it on the following with the same result.
IKEA of Sweden TRADFRI bulb E27 WS opal 980lm
IKEA of Sweden TRADFRI bulb GU10 WS 400lm

The maximum value where I can get it to work is for the GU10 transition=0.29 and for the E27 transition=0.19. Not very scientific testing tho ;)
Going from 1% to 100% brightness.

Looking at the first trace above, all commands is issued within the same second.

Edit: I've tried it with tradfri+gateway and there it works as expected.

[alex-v-g]

Confirming this issue with latest ZHA ... tried few versions - right now I'm on 0.90 beta 3. All sliders on UI became unreliable with both ikea bulbs and philips hue. Sliders for on/off and brightness do not follow the real state and "jumping" back and forth.
Automation scripts working OK for now. I'm using elelabs gpio PCB.

[Adminiuga]

I'm getting those jumps too. Per logs it looks like after I move the brightness slider in UI and send the command, UI is updated immediately with the new value, however the bulb(s) are quick enough to send one or two intermediate "level" attribute reports, which makes the slider jump back and forth. Had this problem for a while.
Not sure about a work around. We could smooth it a bit, by delaying brightness changes via attribute reporting, but if the duration of brightness transition is long enough, these intermediate attribute updates still would get through. Although, when using UI you probably don't specify the duration anyway...

[dmulcahey]

I’m gonna try something. I don’t think this happened before the last PR that touched this class but I’m not positive. I’m going to try reverting it locally to see if there is still an issue. Another thing we can possibly do is use a guard to ignore updates that come in while we’re manipulating state via commands.

[perosb]

@dmulcahey I think think has been there for a while.

I tried my zha stick long time ago this issue was the reason I switched back to trådfri+gateway.

I just switched back to zha like 0.85 or 0.86..

[jkabradley]

I am experiencing what I think is the same issue with a plain white Sengled bulb (E11-G13) on the HUSBZB-1, v0.90.1; I believe this is not uniquely related to colour bulbs, but all Zigbee devices thru ZHA. I touch a desired brightness in the UI, then it flips back to its previous setting. E.g. if I have the light at 100%, then click 50%, the slider pops back to 100%.

I tested the States page as well as Lovelace. Hopefully this will help with the diagnostics.

[valkenburgh]

Also experiencing this. Started with either the v0.89 or 0.90 update. I have several zigbee bulbs and devices (Hue, Cree, Hubbell) connected through HUSBZB-1 and all of them are now exhibiting this bad behavior when dimming using the UI.

[ghost]

I am experiencing a similar thing. When trying to change brightness on ZHA connected Hue globes (all types) the brightness control flickers then jumps back to the old setting.
Occasionally it will jump to a random point between old setting and where I want it to be set.
Repeatable on all Hue globes I have just trying to use the UI to set brightness.
Started happening in 0.90.0. Worked fine in 0.89.x
I have the Elelabs USB ZigBee controller.

This only happens for ZHA connected devices. The Hue globes still on the Hue bridge and ZWave connected devices work normally

[dmulcahey]

Try the current beta. The UI is still a bit jumpy but it’s all functional now.

[perosb]

@dmulcahey there is no change in behavior in the latest beta ;(

[dmulcahey]

Remove and rejoin the device.

[perosb]

Sorry, not much of a difference.
The brightness "effect" is a bit different, longer, than on .90. Like it's changing to my value, but then back again.

Nice "Add device" UI ;)

[valkenburgh]

The latest beta is a modest improvement for me. It's inconsistent. Before the beta if I repeatedly pressed the slider to a lower/higher brightness eventually the light would respond part way. Repeat and I could get the lights where I wanted them. After the beta I do the same and it works more rapidly but still not in one click. Also, and this is the real reason I wanted to give more feedback, Google Assistant integration through Nabu Casa is completely broken for dimming. Can still have Google turn lights on and off but asking for any specific brightness always fails.

[dmulcahey]

Can we get a debug log for that interaction? @valkenburgh can you set logging to debug and ask google to set a brightness and then put the logs on pastebin or hastebin or something similar and give us the link?

[valkenburgh]

Here I asked Google to change the brightness of a zigbee light controller made by Hubbell (nicknamed Plants) from 100% to 81%. Hopefully I got all the useful bits of the log. The light did not change brightness at all.

2019-04-02 21:44:31 DEBUG (MainThread) [hass_nabucasa.iot] Received message:
{'handler': 'google_actions',
 'msgid': '57fbee0d-6b91-4a30-8d9d-1aeb47fd20a7',
 'payload': {'inputs': [{'context': {'locale_language': 'en'},
                         'intent': 'action.devices.EXECUTE',
                         'payload': {'commands': [{'devices': [{'id': 'light.hubbell_93057436_light_control_module_00111e96_22'}],
                                                   'execution': [{'command': 'action.devices.commands.BrightnessAbsolute',
                                                                  'params': {'brightness': 81}}]}]}}],
             'requestId': '6683614391099448347'}}

2019-04-02 21:44:31 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event google_assistant_command[L]: request_id=6683614391099448347, entity_id=light.hubbell_93057436_light_control_module_00111e96_22, execution=command=action.devices.commands.BrightnessAbsolute, params=brightness=81>
2019-04-02 21:44:31 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=light, service=turn_on, service_data=entity_id=light.hubbell_93057436_light_control_module_00111e96_22, brightness_pct=81>
2019-04-02 21:44:31 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast
2019-04-02 21:44:31 DEBUG (MainThread) [bellows.uart] Sending: b'55c7219c54e1c6b6589c4a33bc1593499c026badec826345f8c661f47e'
2019-04-02 21:44:31 DEBUG (MainThread) [bellows.uart] Data frame: b'56c7a19c546e79807e'
2019-04-02 21:44:31 DEBUG (MainThread) [bellows.uart] Sending: b'8610be7e'
2019-04-02 21:44:31 DEBUG (MainThread) [bellows.ezsp] Application frame 52 (sendUnicast) received
2019-04-02 21:44:31 DEBUG (MainThread) [bellows.uart] Data frame: b'66c7b1ed542e14ba59825c65ab5592b363f8ec7812316293b1cd6789aa297e'
2019-04-02 21:44:31 DEBUG (MainThread) [bellows.uart] Sending: b'87009f7e'
2019-04-02 21:44:31 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received
2019-04-02 21:44:31 DEBUG (MainThread) [bellows.uart] Data frame: b'76c7b19754e1c6b6589c4a33bc1593499c0a6babed0d517e'
2019-04-02 21:44:31 DEBUG (MainThread) [bellows.uart] Sending: b'8070787e'
2019-04-02 21:44:31 DEBUG (MainThread) [bellows.ezsp] Application frame 63 (messageSentHandler) received
2019-04-02 21:44:31 DEBUG (MainThread) [homeassistant.components.zha.core.channels] 0xd3cb:22:0x0008: executed command: move_to_level_with_on_off with args: (206, 5) with kwargs: {} and result: [4, <Status.SUCCESS: 0>]
2019-04-02 21:44:31 DEBUG (MainThread) [bellows.ezsp] Send command sendUnicast
2019-04-02 21:44:31 DEBUG (MainThread) [bellows.uart] Sending: b'60c4219c54e1c6b658924a33bc1593499c036aa8ec836643387e'
2019-04-02 21:44:31 DEBUG (MainThread) [bellows.uart] Data frame: b'07c4a19c546fb2477e'
2019-04-02 21:44:31 DEBUG (MainThread) [bellows.uart] Sending: b'8160597e'
2019-04-02 21:44:31 DEBUG (MainThread) [bellows.ezsp] Application frame 52 (sendUnicast) received
2019-04-02 21:44:31 DEBUG (MainThread) [bellows.uart] Data frame: b'17c4b1ed542e14ba59825c65ab5592b263f8ec7812316093fdcc6389dcc9b27f7e'
2019-04-02 21:44:31 DEBUG (MainThread) [bellows.uart] Sending: b'82503a7e'
2019-04-02 21:44:31 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received
2019-04-02 21:44:31 DEBUG (MainThread) [zigpy.zcl] [0xd3cb:22:0x0008] ZCL request 0x000a: [[<Attribute attrid=0 value=<zigpy.zcl.foundation.TypeValue object at 0x6d37c370>>]]
2019-04-02 21:44:31 DEBUG (MainThread) [zigpy.zcl] [0xd3cb:22:0x0008] Attribute report received: 0=183
2019-04-02 21:44:32 DEBUG (MainThread) [homeassistant.components.zha.core.channels.general] 0xd3cb:22:0x0008: received attribute: 0 update with value: 183
2019-04-02 21:44:32 DEBUG (MainThread) [bellows.uart] Data frame: b'27c4b1ed542e14b459825c65ab5592b563f8ec7812316293b0cd628910147e'
2019-04-02 21:44:32 DEBUG (MainThread) [bellows.uart] Sending: b'83401b7e'
2019-04-02 21:44:32 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received
2019-04-02 21:44:32 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.hubbell_93057436_light_control_module_00111e96_22, old_state=<state light.hubbell_93057436_light_control_module_00111e96_22=on; brightness=180, friendly_name=Plants, supported_features=33 @ 2019-04-02T21:38:44.119763+00:00>, new_state=<state light.hubbell_93057436_light_control_module_00111e96_22=on; brightness=183, friendly_name=Plants, supported_features=33 @ 2019-04-02T21:38:44.119763+00:00>>
2019-04-02 21:44:32 DEBUG (MainThread) [bellows.uart] Data frame: b'37c4b19754e1c6b658924a33bc1593499c0b6aabedcc167e'
2019-04-02 21:44:32 DEBUG (MainThread) [bellows.uart] Sending: b'8430fc7e'
2019-04-02 21:44:32 DEBUG (MainThread) [bellows.ezsp] Application frame 63 (messageSentHandler) received
2019-04-02 21:44:32 DEBUG (MainThread) [bellows.uart] Data frame: b'2fc4b1ed542e14b459825c65ab5592b563f8ec7812316293b0cd628924957e'
2019-04-02 21:44:32 DEBUG (MainThread) [bellows.uart] Sending: b'83401b7e'
2019-04-02 21:44:32 DEBUG (MainThread) [bellows.ezsp] Application frame 69 (incomingMessageHandler) received
2019-04-02 21:44:32 DEBUG (MainThread) [bellows.zigbee.application] [0xd3cb:22:0x0006]: Invalid state on future - probably duplicate response: invalid state
2019-04-02 21:44:32 DEBUG (MainThread) [bellows.uart] Data frame: b'3fc4b19754e1c6b658924a33bc1593499c0b6aabed03607e'
2019-04-02 21:44:32 DEBUG (MainThread) [bellows.uart] Sending: b'8430fc7e'
2019-04-02 21:44:32 DEBUG (MainThread) [bellows.ezsp] Application frame 63 (messageSentHandler) received
2019-04-02 21:44:32 DEBUG (MainThread) [bellows.zigbee.application] [0xd3cb:22:0x0006]: Invalid state on future - probably duplicate response: invalid state
2019-04-02 21:44:32 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection.1863849552] Sending {'id': 2, 'type': 'event', 'event': <Event state_changed[L]: entity_id=light.hubbell_93057436_light_control_module_00111e96_22, old_state=<state light.hubbell_93057436_light_control_module_00111e96_22=on; brightness=180, friendly_name=Plants, supported_features=33 @ 2019-04-02T21:38:44.119763+00:00>, new_state=<state light.hubbell_93057436_light_control_module_00111e96_22=on; brightness=183, friendly_name=Plants, supported_features=33 @ 2019-04-02T21:38:44.119763+00:00>>}
2019-04-02 21:44:32 DEBUG (MainThread) [homeassistant.components.zha.core.channels] 0xd3cb:22:0x0006: executed command: on with args: () with kwargs: {} and result: [1, <Status.SUCCESS: 0>]
2019-04-02 21:44:32 DEBUG (MainThread) [hass_nabucasa.iot] Publishing message:
{'msgid': '57fbee0d-6b91-4a30-8d9d-1aeb47fd20a7',
 'payload': {'payload': {'agentUserId': '197a7729-7a78-4650-9e97-404d039794d3',
                         'commands': [{'ids': ['light.hubbell_93057436_light_control_module_00111e96_22'],
                                       'states': {'brightness': 71,
                                                  'on': True,
                                                  'online': True},
                                       'status': 'SUCCESS'}]},
             'requestId': '6683614391099448347'}}

[valkenburgh]

I've been staying up to date with the betas. So far no improvement. Also, a timer automation with a slow fade in and fade out no longer works.

[dmulcahey]

@valkenburgh what is odd here is that the command sent to the level control cluster reports success:

2019-04-02 21:44:31 DEBUG (MainThread) [homeassistant.components.zha.core.channels] 0xd3cb:22:0x0008: executed command: move_to_level_with_on_off with args: (206, 5) with kwargs: {} and result: [4, <Status.SUCCESS: 0>]

yet, it then reports in post command:

2019-04-02 21:44:31 DEBUG (MainThread) [zigpy.zcl] [0xd3cb:22:0x0008] Attribute report received: 0=183
2019-04-02 21:44:32 DEBUG (MainThread) [homeassistant.components.zha.core.channels.general] 0xd3cb:22:0x0008: received attribute: 0 update with value: 183

with a different value...

@Adminiuga any ideas?

[Adminiuga]

Yes, I've seen this with a few lights, after sending the move_to_level_with_on_off command, it would report an intermediate level right away (since light moves to the new level within 0.5s and it is not momentary) and the once it settles it would send a report attribute with correct value.

[valkenburgh]

It's this Thomas research products led driver that suffers the most from that behavior. https://www.ledsmagazine.com/ugc/2016/07/29/thomas-research-products-releases-zigbeecertified-wireless-driver-control-module.html

Back in v0.88 and earlier it worked perfectly. Now it reports these intermediate levels and doesn't dim to where I specified. I can bring it up ordown by repeatedly calling a dim command (each time it meets me half way). My other zigbee lights are now working properly again thanks to recent updates (hue and Cree) but this led driver is not. I'd replace it but it's architectural and in the plenum of the ceiling (also I don't know of many alternative 0-10v connected dimming drivers). Any thoughts on things I could do to fix it in software?

[Adminiuga]

Within 30s after the driver finished level change it should report the correct level. If this is not happening, then it is the problem with the driver. Could it be the UI is not updating with this "final" report?
Do you have the debug log including at least one minute after the service call?

[lwis]

I did some testing on this issue (using IKEA bulbs and a ConBee II stick);

Phoscon deConz native scenes - are able to transition with temp, brightness, and transition time set.
HASS ZHA component - Unable to reliably in any configuration.
HASS deConz component - Unable to reliably in any configuration.

Is there any way to set the deConz app to debug to view the ZigBee commands?

[wlatic]

I've been doing groups and scenes and then hiding them in the interface to get the call working, its not ideal but works.

Would be great if Home Assistant could get this figured out!

[ghost]

My latest experience is positive.
I am using Hassio with HA 0.94.2 and ZHA seems to be working a lot better.
I did a fresh install in my Dev environment, but I only have Philips Hue globes to test with there. Everything is working as expected and stable, at least for now.
Hopefully it will remain stable.

My DEV environment is using Home Assistant via HASSIO on a Raspberry Pi 3B+ with a Digi XSTICK2 (XBEE) USB Stick for ZHA and AEOTEK Z-Stick 5 for Z-Wave.
Not sure if there is a difference for this using different sticks, but it seems fine with Xbee.

[wlatic]

Austwhite this is specific to IKEA bulbs as per the first report.

[ghost]

@wlatic:
I have heard the IKEA TradFri bulbs have some quirks unique to them.
I have been meaning to pick up a couple to play with :)

[comatose-tortoise]

I have the same problem (I think). I have a number of different scenes set up in the GUI, when I use them, the Tradfri bulbs turn on/off as they should and change their color temperature correctly, but brightness does not change to the correct level. The GUI reports the brightness set in the scene and not the brightness the bulbs actually have. If I click the "Activate" button for the scene in the GUI multiple times quickly, the lights sometimes change their brightness a couple of percent in the correct direction, but not always. If use the brightness slider for an individual bulb in the GUI (that indicates the wrong brightness) and set brightness to something different, it immediately changes brightness to whatever I set.

[Torrenator]

Seems like I have the same issue as described here. My lighting setup consists of Ikea lights both rgb and color temperature bulbs. They are connected through deconz using the raspberry pi shield.

My observation after reading this thread and testing it myself after having trouble with a scene, is that as soon as I set the transition to 0 the bulb changes brightness and color at the same time. Just tested this a few times but it seems reliable. But as @lwis said, in the phoscon app the scenes do work as expected.

Edit: running latest 0.96.2 version of HA

[comatose-tortoise]

I solved it with using scripts that wait two seconds between setting brightness and color. But would be great if it that workaround wasn't needed.

[elmurato]

I have the exact same issue with deCONZ and IKEA bulbs (RPi3 on HASS.IO with ConBee II, HA 0.96.5).

If the payload of the light.turn_on service has both (brightness and color_temp) inside, the color_temp changes, but the brightness does not. It flickers briefly as if it was trying to set the requested brightness but then goes back to current brightness.

If the payload has only one of them it works without any issues. Very weird.

Are there dependencies which are the same for ZHA and deCONZ? Maybe it's a problem in a common dependency... If I can help please let me know what I should do.

@frenck As you also have deCONZ with ConBee II and IKEA lights: Do you also face the same issue? Thanks in advance.

EDIT: As @Torrenator reported setting in addition the transition to 0 works as a workaround.

[abmantis]

I also saw this issue with zigbee2mqtt, so its probably a bug in the bulb's firmware... Could we workaround it in the quirks library? Maybe by delaying the one of the operations by the transition time?

[stale[bot]]

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates.
Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍
This issue now has been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.

[chris-nite]

Unfortunately also in the current Home Assistant-Version the Ikea Tradfri Lights cannot be transitioned with light and color levels at the same time. With Deconz Scenes itself it seems to work just fine, but not in Home Assistant.
Anyone else got these problems?

[comatose-tortoise]

I still have this problem using ZHA and Conbee 2. Interesting that it works with Deconz, should be possible to do do in HA too, then?

[Adminiuga]

in which PR it was fixed in deCONZ?

[miguelcaravantes]

smoothly color and brightness transitions works for me in deconz integration but doesn't work with zha

[wlcx]

I seem to have this issue too - I have tradfri lights and a tradfri hub. HA core 0.118.0

I have 3 scenes - off, night, and day. Off is off, night is warm color temp, day is cool. If I go between scenes, e.g. day -> off -> night, the "night" color temp is not applied, and it's only by going from night -> day -> night that the color temp changes.

[MattWestb]

@Adminiuga deCONZ have putting down the reporting for IKEA lights because if they is having more groups then can stalling the mesh then reporting then the light is doing transition from one leight level / colour https://github.com/dresden-elektronik/deconz-rest-plugin/pull/3614#issue-517376635.

Keep in mind IKEA is always using one group (with one or more controller) and the lights can only being in one group. Then adding one light i more groups its making its reporting all status changes to all of those groups and making its heavy for the mesh.

It can being good doing the same for IKEA and other devices that is reporting their status (ala Zigbee 3 standard) for avoiding flooding the mesh.

IKEA lights (perhaps Silabs stack ?) is also famous not liking getting more commands then executing one (like doing on transaction then power on) and doing intense reporting is making it worths (typical masculine task switcher).

[Adminiuga]

I did not notice flooding with Ikea, maybe because we already had max interval set to 15 min.

@dmulcahey Deconz changed reporting for IKEA for on/off from min interval from 0s to 1s and for level reports from 1s to 5s. ZHA currently uses reporting of 0s -- immediate for on/off and 1s for level transitions. I don't think I see to many reports with that config, but can attest: having level min reporting set to 0s does bring network to a crawl during transitions

[MattWestb]

It can being problem if sending on with transition and then setting colour then the light is sending multiple status changes then doing the transition and blocking the setting color command.

[Adminiuga]

Even if doing transition, that's 1 message per sec.