home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
73.78k stars 30.88k forks source link

ZHA ikea tradfri button up/down buttons service calls are not recognized anymore #69375

Closed TheZoker closed 2 years ago

TheZoker commented 2 years ago

The problem

The up and down button services are not recognized on the ikea tradfri button with ZHA anymore: image

When I track the zha_event I see that there are events received when I press the button. But when I use the up or down service in an automation, it is not triggered.

Here you can see two triggers for the same device, on is using the service description and one is using the event trigger. Only the event trigger is "triggered" while the other is not. image

This worked until the recent beta, so I assume something related to those services changed here.

What is interesting here is, that the main button in the middle works without any issue, but the left/right arrow buttons don't work as well.

What version of Home Assistant Core has the issue?

core-2022.4.0b0

What was the last working version of Home Assistant Core?

core-2022.3.8

What type of installation are you running?

Home Assistant OS

Integration causing the issue

zha

Link to integration documentation on our website

https://www.home-assistant.io/integrations/zha

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

No response

probot-home-assistant[bot] commented 2 years ago

Hey there @dmulcahey, @adminiuga, mind taking a look at this issue as it has been labeled with an integration (zha) you are listed as a code owner for? Thanks! (message by CodeOwnersMention)


zha documentation zha source (message by IssueLinks)

TheZoker commented 2 years ago

This seems to be maybe related: https://github.com/zigpy/zigpy/issues/912

Adminiuga commented 2 years ago

This seems to be maybe related: zigpy/zigpy#912

It's not.

Enable debug logging and post debug log of incoming events.

TheZoker commented 2 years ago

I'm not sure what exactly belongs to the events, but here is the zigbee log:

Log ```log 2022-04-06 12:11:35 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [, 0] 2022-04-06 12:11:35 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1) 2022-04-06 12:11:35 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [30, , , 1, , 1, 260, 1, b'\x08*\n \x00 \x1e', 0, 175, 255, 93, 213, 104, 0, -63] 2022-04-06 12:11:35 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0001] Received ZCL frame: b'\x08*\n \x00 \x1e' 2022-04-06 12:11:35 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0001] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=0, is_reply=1, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True), tsn=42, command_id=10, *is_reply=True) 2022-04-06 12:11:35 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0001] Decoded ZCL frame: PowerConfiguration1CRCluster:Report_Attributes(attribute_reports=[Attribute(attrid=0x0020, value=TypeValue(type=uint8_t, value=30))]) 2022-04-06 12:11:35 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0001] Received command 0x0A (TSN 42): Report_Attributes(attribute_reports=[Attribute(attrid=0x0020, value=TypeValue(type=uint8_t, value=30))]) 2022-04-06 12:11:35 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0001] Attribute report received: battery_voltage=30 2022-04-06 12:11:35 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0001] Sending reply header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=False, is_reply=1, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=42, command_id=, *is_reply=True) 2022-04-06 12:11:35 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0001] Sending reply: Default_Response(command_id=10, status=) 2022-04-06 12:11:35 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending Zigbee request with tsn 42 under 3 request id, data: b'182a0b0a00' 2022-04-06 12:11:35 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from , ep: 1, profile: 0x0104, cluster_id: 0x0001, data: b'082a0a2000201e' 2022-04-06 12:11:35 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_request (20, 3, , , 260, 1, 1, b'\x18*\x0b\n\x00', , 0) 2022-04-06 12:11:35 DEBUG (MainThread) [zigpy_deconz.api] APS data request response: [2, , 3] 2022-04-06 12:11:35 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [, 0] 2022-04-06 12:11:35 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1) 2022-04-06 12:11:35 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [32, , , 0, , 1, 260, 5, b'\x05|\x11+\x07\x01\x01\r\x00', 0, 175, 255, 93, 213, 104, 0, -64] 2022-04-06 12:11:35 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] Received ZCL frame: b'\x05|\x11+\x07\x01\x01\r\x00' 2022-04-06 12:11:35 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=True, is_reply=0, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), manufacturer=4476, tsn=43, command_id=7, *is_reply=False) 2022-04-06 12:11:35 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] Decoded ZCL frame: ScenesCluster:press(param1=257, param2=13, param3=0) 2022-04-06 12:11:35 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] Received command 0x07 (TSN 43): press(param1=257, param2=13, param3=0) 2022-04-06 12:11:35 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] No explicit handler for cluster command 0x07: press(param1=257, param2=13, param3=0) 2022-04-06 12:11:35 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from , ep: 1, profile: 0x0104, cluster_id: 0x0005, data: b'057c112b0701010d00' 2022-04-06 12:11:36 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [, 0] 2022-04-06 12:11:36 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_confirm (0,) 2022-04-06 12:11:36 DEBUG (MainThread) [zigpy_deconz.api] APS data confirm response for request with id 3: 00 2022-04-06 12:11:36 DEBUG (MainThread) [zigpy_deconz.api] Request id: 0x03 'aps_data_confirm' for , status: 0x00 2022-04-06 12:11:38 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [, 0] 2022-04-06 12:11:38 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1) 2022-04-06 12:11:38 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [32, , , 0, , 1, 260, 5, b'\x05|\x11,\x07\x00\x01\r\x00', 0, 175, 252, 97, 213, 104, 0, -64] 2022-04-06 12:11:38 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] Received ZCL frame: b'\x05|\x11,\x07\x00\x01\r\x00' 2022-04-06 12:11:38 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=True, is_reply=0, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), manufacturer=4476, tsn=44, command_id=7, *is_reply=False) 2022-04-06 12:11:38 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] Decoded ZCL frame: ScenesCluster:press(param1=256, param2=13, param3=0) 2022-04-06 12:11:38 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] Received command 0x07 (TSN 44): press(param1=256, param2=13, param3=0) 2022-04-06 12:11:38 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] No explicit handler for cluster command 0x07: press(param1=256, param2=13, param3=0) 2022-04-06 12:11:38 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from , ep: 1, profile: 0x0104, cluster_id: 0x0005, data: b'057c112c0700010d00' 2022-04-06 12:11:38 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [, 0] 2022-04-06 12:11:38 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1) 2022-04-06 12:11:38 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [30, , , 0, , 1, 260, 8, b'\x01-\x06\x00+\x05\x00', 0, 175, 255, 88, 213, 104, 0, -66] 2022-04-06 12:11:38 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] Received ZCL frame: b'\x01-\x06\x00+\x05\x00' 2022-04-06 12:11:38 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=0, is_reply=0, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=45, command_id=6, *is_reply=False) 2022-04-06 12:11:38 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] Decoded ZCL frame: LevelControl:step_with_on_off(step_mode=, step_size=43, transition_time=5) 2022-04-06 12:11:38 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] Received command 0x06 (TSN 45): step_with_on_off(step_mode=, step_size=43, transition_time=5) 2022-04-06 12:11:38 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] No explicit handler for cluster command 0x06: step_with_on_off(step_mode=, step_size=43, transition_time=5) 2022-04-06 12:11:38 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from , ep: 1, profile: 0x0104, cluster_id: 0x0008, data: b'012d06002b0500' 2022-04-06 12:11:39 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [, 0] 2022-04-06 12:11:39 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1) 2022-04-06 12:11:39 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [32, , , 0, , 1, 260, 8, b'\x01.\x02\x01+\x05\x00\x00\x00', 0, 175, 255, 100, 213, 104, 0, -65] 2022-04-06 12:11:39 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] Received ZCL frame: b'\x01.\x02\x01+\x05\x00\x00\x00' 2022-04-06 12:11:39 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=0, is_reply=0, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=46, command_id=2, *is_reply=False) 2022-04-06 12:11:39 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] Decoded ZCL frame: LevelControl:step(step_mode=, step_size=43, transition_time=5, options_mask=, options_override=) 2022-04-06 12:11:39 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] Received command 0x02 (TSN 46): step(step_mode=, step_size=43, transition_time=5, options_mask=, options_override=) 2022-04-06 12:11:39 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] No explicit handler for cluster command 0x02: step(step_mode=, step_size=43, transition_time=5, options_mask=, options_override=) 2022-04-06 12:11:39 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from , ep: 1, profile: 0x0104, cluster_id: 0x0008, data: b'012e02012b05000000' ```
puddly commented 2 years ago

You can filter by Decoded ZCL frame: to see only the stuff the device sends back to the coordinator:

# Battery voltage report
2022-04-06 12:11:35 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0001] Decoded ZCL frame: PowerConfiguration1CRCluster:Report_Attributes(attribute_reports=[Attribute(attrid=0x0020, value=TypeValue(type=uint8_t, value=30))])

2022-04-06 12:11:35 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] Decoded ZCL frame: ScenesCluster:press(param1=257, param2=13, param3=0)

2022-04-06 12:11:38 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] Decoded ZCL frame: ScenesCluster:press(param1=256, param2=13, param3=0)
2022-04-06 12:11:38 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] Decoded ZCL frame: LevelControl:step_with_on_off(step_mode=<StepMode.Up: 0>, step_size=43, transition_time=5)

2022-04-06 12:11:39 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] Decoded ZCL frame: LevelControl:step(step_mode=<StepMode.Down: 1>, step_size=43, transition_time=5, options_mask=<bitmap8.0: 0>, options_override=<bitmap8.0: 0>)

I can't really tell what button was being pressed here so if you can tail -f /config/home-assistant.log | grep --line-buffered -F 'Decoded ZCL frame:' and annotate the condensed log (in addition to posting the full one!), that would be very helpful.

TheZoker commented 2 years ago

Hmm the ssh terminal does not seem to know the line-buffered option: image

Is there any alternative for that?

puddly commented 2 years ago

Feel free to omit that flag.

TheZoker commented 2 years ago

Here is the filterd log:

2022-04-06 19:18:55 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] Decoded ZCL frame: ScenesCluster:press(param1=257, param2=13, param3=0)
2022-04-06 19:18:56 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] Decoded ZCL frame: LevelControl:step_with_on_off(step_mode=<StepMode.Up: 0>, step_size=43, transition_time=5)
2022-04-06 19:18:57 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] Decoded ZCL frame: ScenesCluster:press(param1=256, param2=13, param3=0)
2022-04-06 19:18:57 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] Decoded ZCL frame: LevelControl:step(step_mode=<StepMode.Down: 1>, step_size=43, transition_time=5, options_mask=<bitmap8.0: 0>, options_override=<bitmap8.0: 0>)

Button order: left, up, right, down

And here the full log:

Log ```log ``` 022-04-06 19:18:55 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [, 0] 2022-04-06 19:18:55 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1) 2022-04-06 19:18:55 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [32, , , 0, , 1, 260, 5, b'\x05|\x11A\x07\x01\x01\r\x00', 0, 175, 255, 231, 225, 104, 0, -50] 2022-04-06 19:18:55 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] Received ZCL frame: b'\x05|\x11A\x07\x01\x01\r\x00' 2022-04-06 19:18:55 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=True, is_reply=0, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), manufacturer=4476, tsn=65, command_id=7, *is_reply=False) 2022-04-06 19:18:55 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] Decoded ZCL frame: ScenesCluster:press(param1=257, param2=13, param3=0) 2022-04-06 19:18:55 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] Received command 0x07 (TSN 65): press(param1=257, param2=13, param3=0) 2022-04-06 19:18:55 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] No explicit handler for cluster command 0x07: press(param1=257, param2=13, param3=0) 2022-04-06 19:18:55 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from , ep: 1, profile: 0x0104, cluster_id: 0x0005, data: b'057c11410701010d00' 2022-04-06 19:18:56 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [, 0] 2022-04-06 19:18:56 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1) 2022-04-06 19:18:56 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [30, , , 0, , 1, 260, 8, b'\x01B\x06\x00+\x05\x00', 0, 175, 255, 233, 225, 104, 0, -63] 2022-04-06 19:18:56 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] Received ZCL frame: b'\x01B\x06\x00+\x05\x00' 2022-04-06 19:18:56 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=0, is_reply=0, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=66, command_id=6, *is_reply=False) 2022-04-06 19:18:56 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] Decoded ZCL frame: LevelControl:step_with_on_off(step_mode=, step_size=43, transition_time=5) 2022-04-06 19:18:56 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] Received command 0x06 (TSN 66): step_with_on_off(step_mode=, step_size=43, transition_time=5) 2022-04-06 19:18:56 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] No explicit handler for cluster command 0x06: step_with_on_off(step_mode=, step_size=43, transition_time=5) 2022-04-06 19:18:56 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from , ep: 1, profile: 0x0104, cluster_id: 0x0008, data: b'014206002b0500' 2022-04-06 19:18:57 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [, 0] 2022-04-06 19:18:57 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1) 2022-04-06 19:18:57 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [32, , , 0, , 1, 260, 5, b'\x05|\x11C\x07\x00\x01\r\x00', 0, 175, 255, 235, 225, 104, 0, -49] 2022-04-06 19:18:57 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] Received ZCL frame: b'\x05|\x11C\x07\x00\x01\r\x00' 2022-04-06 19:18:57 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=True, is_reply=0, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), manufacturer=4476, tsn=67, command_id=7, *is_reply=False) 2022-04-06 19:18:57 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] Decoded ZCL frame: ScenesCluster:press(param1=256, param2=13, param3=0) 2022-04-06 19:18:57 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] Received command 0x07 (TSN 67): press(param1=256, param2=13, param3=0) 2022-04-06 19:18:57 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0005] No explicit handler for cluster command 0x07: press(param1=256, param2=13, param3=0) 2022-04-06 19:18:57 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from , ep: 1, profile: 0x0104, cluster_id: 0x0005, data: b'057c11430700010d00' 2022-04-06 19:18:57 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [, 0] 2022-04-06 19:18:57 DEBUG (MainThread) [zigpy_deconz.api] Command Command.aps_data_indication (1, 1) 2022-04-06 19:18:57 DEBUG (MainThread) [zigpy_deconz.api] APS data indication response: [32, , , 0, , 1, 260, 8, b'\x01D\x02\x01+\x05\x00\x00\x00', 0, 175, 255, 237, 225, 104, 0, -48] 2022-04-06 19:18:57 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] Received ZCL frame: b'\x01D\x02\x01+\x05\x00\x00\x00' 2022-04-06 19:18:57 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=, is_manufacturer_specific=0, is_reply=0, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=68, command_id=2, *is_reply=False) 2022-04-06 19:18:57 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] Decoded ZCL frame: LevelControl:step(step_mode=, step_size=43, transition_time=5, options_mask=, options_override=) 2022-04-06 19:18:57 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] Received command 0x02 (TSN 68): step(step_mode=, step_size=43, transition_time=5, options_mask=, options_override=) 2022-04-06 19:18:57 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] No explicit handler for cluster command 0x02: step(step_mode=, step_size=43, transition_time=5, options_mask=, options_override=) 2022-04-06 19:18:57 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from , ep: 1, profile: 0x0104, cluster_id: 0x0008, data: b'014402012b05000000' ```
puddly commented 2 years ago

So each button press results in a message received by the coordinator? That looks fine to me.

Can you post the Zigbee device signature?

TheZoker commented 2 years ago

Device signature:

{
  "node_descriptor": "NodeDescriptor(logical_type=<LogicalType.EndDevice: 2>, complex_descriptor_available=0, user_descriptor_available=0, reserved=0, aps_flags=0, frequency_band=<FrequencyBand.Freq2400MHz: 8>, mac_capability_flags=<MACCapabilityFlags.AllocateAddress: 128>, manufacturer_code=4476, maximum_buffer_size=82, maximum_incoming_transfer_size=82, server_mask=11264, maximum_outgoing_transfer_size=82, descriptor_capability_field=<DescriptorCapability.NONE: 0>, *allocate_address=True, *is_alternate_pan_coordinator=False, *is_coordinator=False, *is_end_device=True, *is_full_function_device=False, *is_mains_powered=False, *is_receiver_on_when_idle=False, *is_router=False, *is_security_capable=False)",
  "endpoints": {
    "1": {
      "profile_id": 260,
      "device_type": "0x0820",
      "in_clusters": [
        "0x0000",
        "0x0001",
        "0x0003",
        "0x0020",
        "0x1000",
        "0xfc7c"
      ],
      "out_clusters": [
        "0x0003",
        "0x0004",
        "0x0005",
        "0x0006",
        "0x0008",
        "0x0019",
        "0x1000"
      ]
    }
  },
  "manufacturer": "IKEA of Sweden",
  "model": "TRADFRI remote control",
  "class": "zhaquirks.ikea.fivebtnremotezha.IkeaTradfriRemote1"
}

I can also see the event in the HA dev page, but the service call does not work. When I track for events in the automation it works (see initial post description)

puddly commented 2 years ago

@MattWestb you're totally right, the new, optional options_mask and options_override fields of the step command are causing the existing automation trigger to not match. This likely affects every device using automation triggers that also sends these new ZCLR7/8 command fields.

@dmulcahey Any ideas for how we can preserve the existing behavior but not rely on the exact values of those fields? Is it possible to do "prefix" matching with the ARGS field of device_automation_triggers? Or do we just tack , 0, 0] to the IKEA ARGS?

MattWestb commented 2 years ago

Sorry Puddly i was posing in the wrong closed issue :-(( Great that you is "on the hunt" and doing the findings !!!

MattWestb commented 2 years ago

I think other no IKEA remotes can having the same problem like HUE dimmer switch(es) and the tuya TS004F dimmer switch and knob that is using the dame Zigbee commands in DA. But i have not time updating all my 5 (Z)HA systems for testing and adding the HUE dimmer that is in the black Zigbee box for bad devices but i doing tomorrow.

engeles20 commented 2 years ago

So what's the word? I reverted the newest ha update after this broke

deejbee commented 2 years ago

I have a lot of automations based on various zigbee wall switches all of which now don't work.

Possibly related is this error in the automation trace: Error: Error rendering data template: UndefinedError: 'dict object' has no attribute 'event'

The automation has a template that contains this:

    set selection = options.index(states('input_select.scroll_scenes')) -%} {%
    if trigger.event.data.args[0] == 257 -%}

I read about trigger variables being introduced in 2022.4 so I'm wondering if that is clearing trigger.event object or maybe its a red herring?. I don't have the knowledge about the options_mask & options_override.

A sample captured event doesn't seem to have any additional args that would cause it not to match by the looks of it:

    "data": {
        "device_ieee": "0c:43:14:ff:fe:4c:bc:7b",
        "unique_id": "0c:43:14:ff:fe:4c:bc:7b:1:0x0005",
        "device_id": "12f62b05e32759b2d36648e190044570",
        "endpoint_id": 1,
        "cluster_id": 5,
        "command": "press",
        "args": [
            257,
            13,
            0
        ]
    },

This is my trigger YAML:

event_type: zha_event
event_data:
  device_ieee: 0c:43:14:ff:fe:4c:bc:7b
  unique_id: 0c:43:14:ff:fe:4c:bc:7b:1:0x0005
  device_id: 12f62b05e32759b2d36648e190044570
  command: press
  endpoint_id: 1
  cluster_id: 5
  args:
    - 257
    - 13
    - 0

It doesn't fire/match now unless I remove the args completely which isn't feasible.

hastime commented 2 years ago

I have this same issue with a ts004f switch that is sending 'step' messages on two of the buttons which now don't trigger automations the other two buttons work, this broke after the 2022.4 update. Any suggestions on how to resolve this would be appreciated!

Thanks,

deejbee commented 2 years ago

@hastime I have the 5 button ikea tradfi remote as well as the single button one. On the single button one I noticed the command have changed to one of stop_with_on_off (long press), move_with_on_off (before long press triggered) and on (tap press).

On the 5 button remote it can see the brightness up/down buttons command has changed to step_with_on_off, move_with_on_off and stop_with_on_off.

It looks like _with_on_off has been added to a lot of the commands for some reason.

puddly commented 2 years ago

stop_with_on_off is indeed a bug, it should just be called stop. The other _with_on_off commands have always been there.

puddly commented 2 years ago

Hmm, or maybe not. The ZCL R8 spec ambiguously lists two stop commands (0x03 and 0x07):

image image

But the lighting spec matches what is now in the new version of zigpy:

image

So it looks like the IKEA devices were indeed sending a stop_with_on_off command, the command name was just "wrong" in zigpy up until this release and will need to be fixed in quirks.

megarch2021 commented 2 years ago

I use this blueprint "EPMatt/ikea_e1524_e1810"

I have updated my blueprints to reflect the following commands

  button_up_short:
  - step_with_on_off_StepMode.Up_43_5
  button_up_long:
  - move_with_on_off_MoveMode.Up_83
  - move_with_on_off_MoveMode.Up_84

  button_down_short:
  - step_StepMode.Down_43_5_bitmap8.0_bitmap8.0
  button_down_long:
  - move_MoveMode.Down_83_bitmap8.0_bitmap8.0
  - move_MoveMode.Down_84_bitmap8.0_bitmap8.0

My wild guess is that the "_bitmap8.0_bitmap8.0" is an error I will update them later if homeassistant core gets updated to fix this.

RealKoenisch commented 2 years ago

I can confirm the fault in handling "args" in the zha trigger. In case you use args for a specific indentifaction the event will never fire since the update 2022.04. In my case it is a sunricher zigbee remote control ZG2868A.

platform: event event_type: zha_event event_data: device_id: 018fdcfd30642b44eaa8df4dfc672ebf command: step_color_temp endpoint_id: 1 args:

  • 1
  • 37
  • 0
  • 155
  • 450

The result of

{{trigger.event.data.args }} == step_color_temp(step_mode=<StepMode.Up: 1>, step_size=37, transition_time=0, color_temp_min_mireds=155, color_temp_max_mireds=450, options_mask=<bitmap8.0: 0>, options_override=<bitmap8.0: 0>)

{{trigger.event.data.args[0] }} == StepMode.Up {{trigger.event.data.args.step_mode }} == StepMode.Up

{{trigger.event.data.args[1] }} == 37 {{trigger.event.data.args.step_size }} == 37

{{trigger.event.data.args[2] }} == 0

{{trigger.event.data.args[3] }} == 155

{{trigger.event.data.args[4] }} == 450

with this changed behaviour the args can't be used in the event trigger.


The same strange issue appears in reading args. The event: { "event_type": "zha_event", "data": { "device_ieee": "00:0d:6f:00:10:6a:7c:67", "unique_id": "00:0d:6f:00:10:6a:7c:67:1:0x0005", "device_id": "018fdcfd30642b44eaa8df4dfc672ebf", "endpoint_id": 1, "cluster_id": 5, "command": "recall", "args": [ 0, 1, null ] },

The result of

{{ trigger.event.data.args }} == recall(group_id=0x0000, scene_id=1, transition_time=None)

The result of

{{ trigger.event.data.args[1] }} == 1

dmulcahey commented 2 years ago

@MattWestb you're totally right, the new, optional options_mask and options_override fields of the step command are causing the existing automation trigger to not match. This likely affects every device using automation triggers that also sends these new ZCLR7/8 command fields.

@dmulcahey Any ideas for how we can preserve the existing behavior but not rely on the exact values of those fields? Is it possible to do "prefix" matching with the ARGS field of device_automation_triggers? Or do we just tack , 0, 0] to the IKEA ARGS?

ugh... I think it is time to change how these work. I am not sure about your question off the top of my head. I need to reacquaint myself w/ the code to see what can be done.

lucasfr commented 2 years ago

I had a similar issue with an IKEA STYRBAR.

aetha commented 2 years ago

Can confirm I’m having the same issue with my Tradfri 5-button remote. Also with my Ikea Symfonisk rotary remotes too; click to play/pause works, but rotation triggers actions such as move_MoveMode.Down_195_bitmap8.0_bitmap8.0.

MattWestb commented 2 years ago

@hastime with this update you is also having "scene" / events mode of your TS004F and you is getting 12 "scenes" you can using for automatons. You need deleting the device and waiting on minute and adding it new and the system shall enabling the new mode and you can switching between dimmer / events mode by pressing the uper and lower right buttons for 6 sec and the lower left is blinking.

More info in the PR https://github.com/zigpy/zha-device-handlers/pull/1437.

The problem i Dimmer mode we must waiting and see what the devs is desiding how to fixing it perhaps we must redoing many quirks for getting it working.

dumpfheimer commented 2 years ago

I believe this might be an issue I had earlier this year: https://github.com/dumpfheimer/core/commit/486d3d841d59640a065b4620630ea077562cd0ce

Adding these lines made it work for me again. If someone wants to try it, I made a branch: https://github.com/dumpfheimer/core/tree/dumpfheimer/zha-device-automation-trigger-fix

If somebody can confirm it working I would create a PR unless a zigpy dev has a better way of doing it

puddly commented 2 years ago

Good timing, @dmulcahey and I just came to the same conclusion. I have a slightly different approach: https://github.com/zigpy/zha-device-handlers/pull/1464#issuecomment-1092025714=

Is the int call you added necessary?

This will unfortunately break the EPMatt/ikea_e1524_e1810 blueprint because of the way it constructs names using string concatenation. Not much that can be done about that, some command parameters were given more specific enum types in zigpy and this will have to be handled by the above blueprint.

dumpfheimer commented 2 years ago

Honestly, I'm not sure. I want to believe there was a reason for it, though.

I will try without it in a minute

MattWestb commented 2 years ago

@puddly If its "only" braking blueprints its not so bad (its not supported by HA devs its community) if we is getting the device automatons working so user can getting there automatons working agen but best if we is getting all working without braking the long lasted ZCLR7/8 update.

dumpfheimer commented 2 years ago

@puddly seems like the int() call is NOT necessary. Looks like it works like this:


    @callback
    def zha_send_event(self, event_data: dict[str, str | int]) -> None:
        """Relay events to hass."""
        if "args" in event_data:
            try:
                compatibility_args = []

                fields = event_data["args"].assigned_fields()
                for field, value in fields:
                    if not field.optional:
#                        try:
#                            compatibility_args.append(int(value))
#                        except ValueError:
#                            compatibility_args.append(value)
                         compatibility_args.append(value)
                event_data["args"] = compatibility_args
            except Error:
                pass
        self.zha_device.hass.bus.async_fire(
            "zha_event",
            {   
                const.ATTR_DEVICE_IEEE: str(self.zha_device.ieee),
                const.ATTR_UNIQUE_ID: self.unique_id,
                ATTR_DEVICE_ID: self.zha_device.device_id,
                **event_data,
            },
        )
puddly commented 2 years ago

The second half of this fix (due to stop being split into stop and stop_with_on_off) is here, if you want to test it out as well: https://github.com/zigpy/zha-device-handlers/pull/1465

dumpfheimer commented 2 years ago

Not quite sure what the issue with stopis. I reduced my fix to a single line: (edit: two single lines ;-)) https://github.com/dumpfheimer/core/commit/b00d1b02c02f7746e282205196edb3acca8566d6

puddly commented 2 years ago

Hmm. Is the field.optional check necessary? It seems like it would strip off assigned fields that are not actually None but just defined as optional in the spec.

dumpfheimer commented 2 years ago

Let me try. Might be that the not None check is enough.

dumpfheimer commented 2 years ago

With this: event_data["args"] = [value for field, value in event_data["args"].assigned_fields() if field is not None]

The "up" button works, but "down" does not. Could this be the stop issue you mentioned?

MattWestb commented 2 years ago

I think yes is looking in https://github.com/zigpy/zha-device-handlers/pull/1465/files.

MattWestb commented 2 years ago

4 button / Styrbar looks working OK with the second last posted fix (have not testing the last) but need the "puddly patch" 2.

dumpfheimer commented 2 years ago

I tried HA 2022.4.1 and looks like most automations are back to normal. Thanks for fixing it so quickly! @puddly @dmulcahey

Only on my IKEA Tradfri 5-button-remotes "down" still seems broken. Not sure if this should be fixed yet.

dumpfheimer commented 2 years ago

So it seems like the options_mask and options_override arguments were not matched previously but now should be. example log entry: ...No explicit handler for cluster command 0x02: step(step_mode=<StepMode.Down: 1>, step_size=43, transition_time=5, options_mask=<bitmap8.0: 0>, options_override=<bitmap8.0: 0>) This fixes my issue: https://github.com/dumpfheimer/zha-device-handlers/commit/5599a83367da5e56026fff89c512991f0fa4c7d3

Not sure if the ikea 5 btn remote V3 is the only device where this happens - there might be many. Was previous to 2022.04 0 treated the same as None ? That might explain why the 0 values where not needed. Or are the options_mask and options_override arguments new?

In my opinion there are 2 ways to approach this:

  1. The fix I made + possible fixes for other quirks that might not be working either
  2. Somehow change zigpy to consider the frame matchable to the quirk's trigger

Maybe @puddly or @dmulcahey can tell if this new behavior is intended and desirable?

If so, and there are multiple quirks that need a fix, possibly it would be best to have a transition period where zigpy will match the trigger but issue a warning to help find the broken quirks?

puddly commented 2 years ago

Or are the options_mask and options_override arguments new?

Sort of. In the ZCL R7 spec, these new fields are listed as optional and some IKEA devices were indeed sending them. zigpy wasn't previously parsing this extra data and was instead generating a warning about unknown trailing data. Now these fields are being parsed and seem to be breaking device triggers (this also may depend on the device firmware version?).

There are a few solutions to this problem:

  1. Identify and fix all affected device quirks, if possible. This would be the ideal solution but I don't own every device with every firmware version. There may not be many to fix, though.
  2. Somehow do prefix matching in the device trigger event, so [1, 2, 3] will match [1, 2, 3, 0, 0]. Is this possible?
  3. Match against the new "params" dictionary instead and only look at the non-optional fields: {"step_mode": StepMode.Down, "step_size": 43, "transition_time": 5}. This seems promising and may even be a quirks-only change.
dumpfheimer commented 2 years ago

What if the quirks try to match with the optional parameters and if no match is found the optional parameters are removed and it tries to match a second time without the optional parameters?

OlwinFroon commented 2 years ago

Nice! 2022.4.1 fixed most of the long hold/release issues I had with my Tradfri shortcut buttons and on/off buttons.

The Tradfri on/off buttons' have been partially fixed: the ON part works perfectly, long holding/releasing the OFF part does not. Seems similar to the 5-Button "down" issue mentioned above.

Here's the OFF long hold event:

{
    "event_type": "zha_event",    
    "data": {    
        "device_ieee": "04:cd:15:ff:fe:38:bd:dd",        
        "unique_id": "04:cd:15:ff:fe:38:bd:dd:1:0x0008",        
        "device_id": "ac12d534e3899c2edfbbefcdc18ff533",        
        "endpoint_id": 1,        
        "cluster_id": 8,        
        "command": "move",        
        "args": [        
            1,            
            83,            
            0,            
            0            
        ],        
        "params": {        
            "move_mode": 1,            
            "rate": 83,            
            "options_mask": 0,            
            "options_override": 0            
        }        
    },    
    "origin": "LOCAL",
    "time_fired": "2022-04-08T08:26:36.618993+00:00",
    "context": {    
        "id": "532865fcf8592824231d75164e1db144",        
        "parent_id": null,        
        "user_id": null        
    }    
}

which used to trigger "dimmer down pressed continuously".

Any chance to fix this?

TheZoker commented 2 years ago

Same for me, every button now works except for the down button

frayberen commented 2 years ago

Same problem with a long press to turn off, it still doesn't work on the Ikea Tradfri push button with two buttons. Any solution?

pbvdven commented 2 years ago

i updated to 2022.4.1 from 2022.3.8 after i tried 2022.4.0 and found out nothing ZHA related is working like it should. now on 2022.4.1 things are a little bit better but sill having lot of problems with my IKEA stuff like 5 button remote only reacts to middle button. IKEA light bulbs wont go on at all or wont go off some react some dont. my 2 button ikea remote wont react to anything. im using mostly blueprints for my IKEA remotes do i need to change anything to get it working again. or should it just work with 2022.4.1

dumpfheimer commented 2 years ago

Are there any major drawbacks in using only the non-optional parameters for now? Just to buy some time. I can not anticipate the impact on other devices (maybe this could affect ZCLv7 devices?)

This does seem to affect a considerable amount of people.

H4rl3k1n commented 2 years ago

confirmed, dimmer down button is still not working, with 4.1 rest of the buttons are working again.

TomW1605 commented 2 years ago

hi just found this issue (after 3 days of replacing batteries and restarting) and thought i would mention that, while with 4.1 the down button does not work on the 5 button controller as others have said, holding the down buttons does work, as do all the other buttons for both press and hold. haven't seen this said yet so thought it might help

pbvdven commented 2 years ago

oke its mostly the blueprint that dont work anymore. i have setup new automation but the following buttons wont trigger. on the 5 button remote: "Dim up" button continuously pressed "Dim down" button continuously pressed "Dim down" button pressed

IKEA of Sweden TRADFRI on/off switch wont trigger at all but i read here that some people where it works.

dumpfheimer commented 2 years ago

If you have some time on your hands I would be glad if you could test this fix (upon 2022.04.1): https://github.com/dumpfheimer/core/commit/ef7c7cd0efb09f08f220326dd3de7082944bb155

And test not only the devices that have not been working since 2022.04 but as many as possible