Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
TheZoker opened this issue Apr 5, 2022 · 146 comments
Closed
Assignees

Comments

@TheZoker
Copy link
Contributor

TheZoker commented Apr 5, 2022

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
Copy link

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
Copy link
Contributor Author

TheZoker commented Apr 5, 2022

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

@Adminiuga
Copy link
Contributor

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

It's not.

Enable debug logging and post debug log of incoming events.

@TheZoker
Copy link
Contributor Author

TheZoker commented Apr 6, 2022

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

Log
2022-04-06 12:11:35 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 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, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x0000>, 1, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x777b>, 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=<FrameType.GLOBAL_COMMAND: 0>, 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=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, is_reply=1, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=42, command_id=<GeneralCommand.Default_Response: 11>, *is_reply=True)
2022-04-06 12:11:35 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0001] Sending reply: Default_Response(command_id=10, status=<Status.SUCCESS: 0>)
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 <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x777b>, 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, <DeconzSendDataFlags.NONE: 0>, <DeconzAddressEndpoint address_mode=2 address=0x777B endpoint=1>, 260, 1, 1, b'\x18*\x0b\n\x00', <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 0)
2022-04-06 12:11:35 DEBUG (MainThread) [zigpy_deconz.api] APS data request response: [2, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, 3]
2022-04-06 12:11:35 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 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, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.GROUP address=0x0000>, 0, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x777b>, 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=<FrameType.CLUSTER_COMMAND: 1>, 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 <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x777b>, 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: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_CONFIRM|2: 166>, 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 <DeconzAddressEndpoint address_mode=ADDRESS_MODE.NWK address=0x777b endpoint=1>, status: 0x00
2022-04-06 12:11:38 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 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, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.GROUP address=0x0000>, 0, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x777b>, 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=<FrameType.CLUSTER_COMMAND: 1>, 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 <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x777b>, 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: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 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, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.GROUP address=0x0000>, 0, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x777b>, 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=<FrameType.CLUSTER_COMMAND: 1>, 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=<StepMode.Up: 0>, 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=<StepMode.Up: 0>, 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=<StepMode.Up: 0>, step_size=43, transition_time=5)
2022-04-06 12:11:38 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x777b>, 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: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 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, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, <DeconzAddress address_mode=ADDRESS_MODE.GROUP address=0x0000>, 0, <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x777b>, 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=<FrameType.CLUSTER_COMMAND: 1>, 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=<StepMode.Down: 1>, step_size=43, transition_time=5, options_mask=<bitmap8.0: 0>, options_override=<bitmap8.0: 0>)
2022-04-06 12:11:39 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] Received command 0x02 (TSN 46): step(step_mode=<StepMode.Down: 1>, step_size=43, transition_time=5, options_mask=<bitmap8.0: 0>, options_override=<bitmap8.0: 0>)
2022-04-06 12:11:39 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] 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>)
2022-04-06 12:11:39 DEBUG (MainThread) [zigpy_deconz.api] 'aps_data_indication' response from <DeconzAddress address_mode=ADDRESS_MODE.NWK address=0x777b>, ep: 1, profile: 0x0104, cluster_id: 0x0008, data: b'012e02012b05000000'

@puddly
Copy link
Contributor

puddly commented Apr 6, 2022

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
Copy link
Contributor Author

TheZoker commented Apr 6, 2022

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

Is there any alternative for that?

@puddly
Copy link
Contributor

puddly commented Apr 6, 2022

Feel free to omit that flag.

@TheZoker
Copy link
Contributor Author

TheZoker commented Apr 6, 2022

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

022-04-06 19:18:55 DEBUG (MainThread) [zigpy_deconz.api] Device state changed response: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 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, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, , 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=<FrameType.CLUSTER_COMMAND: 1>, 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: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 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, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, , 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=<FrameType.CLUSTER_COMMAND: 1>, 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=<StepMode.Up: 0>, 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=<StepMode.Up: 0>, 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=<StepMode.Up: 0>, 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: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 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, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, , 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=<FrameType.CLUSTER_COMMAND: 1>, 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: [<DeviceState.128|APSDE_DATA_REQUEST_SLOTS_AVAILABLE|APSDE_DATA_INDICATION|2: 170>, 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, <DeviceState.APSDE_DATA_REQUEST_SLOTS_AVAILABLE|2: 34>, , 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=<FrameType.CLUSTER_COMMAND: 1>, 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=<StepMode.Down: 1>, step_size=43, transition_time=5, options_mask=<bitmap8.0: 0>, options_override=<bitmap8.0: 0>)
2022-04-06 19:18:57 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] Received command 0x02 (TSN 68): step(step_mode=<StepMode.Down: 1>, step_size=43, transition_time=5, options_mask=<bitmap8.0: 0>, options_override=<bitmap8.0: 0>)
2022-04-06 19:18:57 DEBUG (MainThread) [zigpy.zcl] [0x777B:1:0x0008] 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>)
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'

</details>

@puddly
Copy link
Contributor

puddly commented Apr 6, 2022

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
Copy link
Contributor Author

TheZoker commented Apr 6, 2022

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
Copy link
Contributor

puddly commented Apr 6, 2022

@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
Copy link
Contributor

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

@MattWestb
Copy link
Contributor

MattWestb commented Apr 6, 2022

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
Copy link

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

@deejbee
Copy link

deejbee commented Apr 7, 2022

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
Copy link

hastime commented Apr 7, 2022

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
Copy link

deejbee commented Apr 7, 2022

@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
Copy link
Contributor

puddly commented Apr 7, 2022

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
Copy link
Contributor

puddly commented Apr 7, 2022

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
Copy link

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
Copy link

RealKoenisch commented Apr 7, 2022

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
Copy link
Contributor

@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
Copy link

lucasfr commented Apr 7, 2022

I had a similar issue with an IKEA STYRBAR.

@aetha
Copy link

aetha commented Apr 7, 2022

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
Copy link
Contributor

@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 zigpy/zha-device-handlers#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.

@stalakerob
Copy link

I have 2 remotes. Both behave the same.

@stalakerob
Copy link

0x61d3 is an osram plug that is not plugged in.

@dmulcahey
Copy link
Contributor

Attach the device diagnostic data for both please. You can get this from the device page in HA

@MattWestb
Copy link
Contributor

You remote is one with old firmware IkeaTradfriRemote1 = very good then we have not testing the last fix for it.

The errors you was getting is that your OSRAM plug is not responding on the command sent to it.
Try is you can sending on/off from device card and if not working repower the OSRAM plug.

@stalakerob
Copy link

In fact one is IkeaTradfriRemote1 and the other IkeaTradfriRemote

@MattWestb
Copy link
Contributor

@dmulcahey thanks for hint !!!

Shall we changing from ARGS to PARMS in all light controller or updating the ARGS that is "new" (i have all IKEA made local and have testing the current firmware ones) ?

@MattWestb
Copy link
Contributor

MattWestb commented Apr 16, 2022

Robert your error is coming not from the remotes its coming from the 0x61d3 is an osram plug that your automation is trying sending on and off commands to.

@stalakerob
Copy link

Here's the diagnostic for one of those

{
  "home_assistant": {
    "installation_type": "Home Assistant Container",
    "version": "2022.4.4",
    "dev": false,
    "hassio": false,
    "virtualenv": false,
    "python_version": "3.9.9",
    "docker": true,
    "arch": "armv7l",
    "timezone": "Europe/Berlin",
    "os_name": "Linux",
    "os_version": "5.4.51-v7l+",
    "run_as_root": true
  },
  "custom_components": {
    "deepstack_object": {
      "version": "4.3.0",
      "requirements": [
        "pillow",
        "deepstack-python==0.8"
      ]
    },
    "hacs": {
      "version": "1.24.5",
      "requirements": [
        "aiogithubapi>=21.11.0"
      ]
    },
    "alexa_media": {
      "version": "3.11.1",
      "requirements": [
        "alexapy==1.25.3",
        "packaging>=20.3",
        "wrapt>=1.12.1"
      ]
    },
    "blitzortung": {
      "version": "1.0.1",
      "requirements": [
        "paho-mqtt>=1.5.0"
      ]
    },
    "rpi_gpio": {
      "version": "2022.4.0",
      "requirements": [
        "RPi.GPIO==0.7.1a4"
      ]
    },
    "cover_rf_time_based": {
      "version": "1.0.8",
      "requirements": [
        "xknx==0.9.4"
      ]
    },
    "midea_dehumidifier": {
      "version": "1.0.3",
      "requirements": [
        "midea-inventor-lib==1.0.4"
      ]
    }
  },
  "integration_manifest": {
    "domain": "zha",
    "name": "Zigbee Home Automation",
    "config_flow": true,
    "documentation": "https://www.home-assistant.io/integrations/zha",
    "requirements": [
      "bellows==0.29.0",
      "pyserial==3.5",
      "pyserial-asyncio==0.6",
      "zha-quirks==0.0.72",
      "zigpy-deconz==0.14.0",
      "zigpy==0.44.2",
      "zigpy-xbee==0.14.0",
      "zigpy-zigate==0.8.0",
      "zigpy-znp==0.7.0"
    ],
    "usb": [
      {
        "vid": "10C4",
        "pid": "EA60",
        "description": "*2652*",
        "known_devices": [
          "slae.sh cc2652rb stick"
        ]
      },
      {
        "vid": "10C4",
        "pid": "EA60",
        "description": "*sonoff*plus*",
        "known_devices": [
          "sonoff zigbee dongle plus"
        ]
      },
      {
        "vid": "10C4",
        "pid": "EA60",
        "description": "*tubeszb*",
        "known_devices": [
          "TubesZB Coordinator"
        ]
      },
      {
        "vid": "1A86",
        "pid": "7523",
        "description": "*tubeszb*",
        "known_devices": [
          "TubesZB Coordinator"
        ]
      },
      {
        "vid": "1A86",
        "pid": "7523",
        "description": "*zigstar*",
        "known_devices": [
          "ZigStar Coordinators"
        ]
      },
      {
        "vid": "1CF1",
        "pid": "0030",
        "description": "*conbee*",
        "known_devices": [
          "Conbee II"
        ]
      },
      {
        "vid": "10C4",
        "pid": "8A2A",
        "description": "*zigbee*",
        "known_devices": [
          "Nortek HUSBZB-1"
        ]
      },
      {
        "vid": "10C4",
        "pid": "8B34",
        "description": "*bv 2010/10*",
        "known_devices": [
          "Bitron Video AV2010/10"
        ]
      }
    ],
    "codeowners": [
      "@dmulcahey",
      "@adminiuga"
    ],
    "zeroconf": [
      {
        "type": "_esphomelib._tcp.local.",
        "name": "tube*"
      }
    ],
    "after_dependencies": [
      "usb",
      "zeroconf"
    ],
    "iot_class": "local_polling",
    "loggers": [
      "aiosqlite",
      "bellows",
      "crccheck",
      "pure_pcapy3",
      "zhaquirks",
      "zigpy",
      "zigpy_deconz",
      "zigpy_xbee",
      "zigpy_zigate",
      "zigpy_znp"
    ],
    "is_built_in": true
  },
  "data": {
    "ieee": "**REDACTED**",
    "nwk": 50765,
    "manufacturer": "IKEA of Sweden",
    "model": "TRADFRI remote control",
    "name": "IKEA of Sweden TRADFRI remote control",
    "quirk_applied": true,
    "quirk_class": "fivebtnremotezha.IkeaTradfriRemote1",
    "manufacturer_code": 4476,
    "power_source": "Battery or Unknown",
    "lqi": 255,
    "rssi": -64,
    "last_seen": "2022-04-16T13:15:39",
    "available": true,
    "device_type": "EndDevice",
    "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"
          ]
        }
      }
    },
    "entities": [
      {
        "entity_id": "button.ikea_of_sweden_tradfri_remote_control_64ebf8fe_identify",
        "name": "IKEA of Sweden TRADFRI remote control"
      },
      {
        "entity_id": "sensor.ikea_of_sweden_tradfri_remote_control_2_power",
        "name": "IKEA of Sweden TRADFRI remote control"
      }
    ],
    "neighbors": [],
    "endpoint_names": [
      {
        "name": "NON_COLOR_CONTROLLER"
      }
    ],
    "user_given_name": "IKEA of Sweden TRADFRI remote control 2",
    "device_reg_id": "f9bf62a9f8e974b0ca3d9a7017d25ab4",
    "area_id": "609266ad474747f4a8709baa308f5bc9"
  }
}

@dmulcahey
Copy link
Contributor

@dmulcahey thanks for hint !!!

Shall we changing from ARGS to PARMS in all light controller or updating the ARGS that is "new" (i have all IKEA made local and have testing the current firmware ones) ?

Params should be used from now on

@MattWestb
Copy link
Contributor

Then i getting the IkeaTradfriRemote1 (old ZHA firmware) working i can doing one PR for all IKEA controllers that have testing the current version and only the ZLL is untested and can being wrong.

Do you have one 5 button for testing with older firmware ?

@stalakerob
Copy link

Anything more I can help with?

@MattWestb
Copy link
Contributor

Rober can you posting one log then doing one long pressing of the toggle button ?

Is you automatons working OK or is it some that is not working ?

@stalakerob
Copy link

The up/down buttons are not working. The other buttons work.
Which one is the toggle button (on/off ?)

@MattWestb
Copy link
Contributor

Toggle is the on/off button.
The short pressing the up and then down and after that long press up and down and post the log :-))

@stalakerob
Copy link

home-assistant   | 2022-04-16 13:58:02 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] Received ZCL frame: b'\x01\x11\x06\x00+\x05\x00'
home-assistant   | 2022-04-16 13:58:02 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=0, is_reply=0, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=17, command_id=6, *is_reply=False)
home-assistant   | 2022-04-16 13:58:02 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] Decoded ZCL frame: LevelControl:step_with_on_off(step_mode=<StepMode.Up: 0>, step_size=43, transition_time=5)
home-assistant   | 2022-04-16 13:58:02 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] Received command 0x06 (TSN 17): step_with_on_off(step_mode=<StepMode.Up: 0>, step_size=43, transition_time=5)
home-assistant   | 2022-04-16 13:58:02 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] No explicit handler for cluster command 0x06: step_with_on_off(step_mode=<StepMode.Up: 0>, step_size=43, transition_time=5)
home-assistant   | 2022-04-16 13:58:03 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] Received ZCL frame: b'\x01\x12\x02\x01+\x05\x00\x00\x00'
home-assistant   | 2022-04-16 13:58:03 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=0, is_reply=0, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=18, command_id=2, *is_reply=False)
home-assistant   | 2022-04-16 13:58:03 DEBUG (MainThread) [zigpy.zcl] [0xC64D: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>)
home-assistant   | 2022-04-16 13:58:03 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] Received command 0x02 (TSN 18): step(step_mode=<StepMode.Down: 1>, step_size=43, transition_time=5, options_mask=<bitmap8.0: 0>, options_override=<bitmap8.0: 0>)
home-assistant   | 2022-04-16 13:58:03 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] 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>)
home-assistant   | 2022-04-16 13:58:05 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] Received ZCL frame: b'\x01\x13\x05\x00T'
home-assistant   | 2022-04-16 13:58:05 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=0, is_reply=0, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=19, command_id=5, *is_reply=False)
home-assistant   | 2022-04-16 13:58:05 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] Decoded ZCL frame: LevelControl:move_with_on_off(move_mode=<MoveMode.Up: 0>, rate=84)
home-assistant   | 2022-04-16 13:58:05 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] Received command 0x05 (TSN 19): move_with_on_off(move_mode=<MoveMode.Up: 0>, rate=84)
home-assistant   | 2022-04-16 13:58:05 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] No explicit handler for cluster command 0x05: move_with_on_off(move_mode=<MoveMode.Up: 0>, rate=84)
home-assistant   | 2022-04-16 13:58:08 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] Received ZCL frame: b'\x01\x14\x07'
home-assistant   | 2022-04-16 13:58:08 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=0, is_reply=0, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=20, command_id=7, *is_reply=False)
home-assistant   | 2022-04-16 13:58:08 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] Decoded ZCL frame: LevelControl:stop_with_on_off()
home-assistant   | 2022-04-16 13:58:08 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] Received command 0x07 (TSN 20): stop_with_on_off()
home-assistant   | 2022-04-16 13:58:08 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] No explicit handler for cluster command 0x07: stop_with_on_off()
home-assistant   | 2022-04-16 13:58:10 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] Received ZCL frame: b'\x01\x15\x01\x01T\x00\x00'
home-assistant   | 2022-04-16 13:58:10 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=0, is_reply=0, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=21, command_id=1, *is_reply=False)
home-assistant   | 2022-04-16 13:58:10 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] Decoded ZCL frame: LevelControl:move(move_mode=<MoveMode.Down: 1>, rate=84, options_mask=<bitmap8.0: 0>, options_override=<bitmap8.0: 0>)
home-assistant   | 2022-04-16 13:58:10 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] Received command 0x01 (TSN 21): move(move_mode=<MoveMode.Down: 1>, rate=84, options_mask=<bitmap8.0: 0>, options_override=<bitmap8.0: 0>)
home-assistant   | 2022-04-16 13:58:10 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] No explicit handler for cluster command 0x01: move(move_mode=<MoveMode.Down: 1>, rate=84, options_mask=<bitmap8.0: 0>, options_override=<bitmap8.0: 0>)
home-assistant   | 2022-04-16 13:58:13 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] Received ZCL frame: b'\x01\x16\x03\x00\x00'
home-assistant   | 2022-04-16 13:58:13 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl(frame_type=<FrameType.CLUSTER_COMMAND: 1>, is_manufacturer_specific=0, is_reply=0, disable_default_response=0, reserved=0, *is_cluster=True, *is_general=False), tsn=22, command_id=3, *is_reply=False)
home-assistant   | 2022-04-16 13:58:13 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] Decoded ZCL frame: LevelControl:stop(options_mask=<bitmap8.0: 0>, options_override=<bitmap8.0: 0>)
home-assistant   | 2022-04-16 13:58:13 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] Received command 0x03 (TSN 22): stop(options_mask=<bitmap8.0: 0>, options_override=<bitmap8.0: 0>)
home-assistant   | 2022-04-16 13:58:13 DEBUG (MainThread) [zigpy.zcl] [0xC64D:1:0x0008] No explicit handler for cluster command 0x03: stop(options_mask=<bitmap8.0: 0>, options_override=<bitmap8.0: 0>)

@stalakerob
Copy link

BTW I'm using this blueprint to control the remote:

blueprint:
  name: ZHA - IKEA five button remote
  description: 'Control anything using IKEA five button remote

    '
  domain: automation
  input:
    remote:
      name: Remote
      description: IKEA remote to use
      selector:
        device:
          integration: zha
          manufacturer: IKEA of Sweden
          model: TRADFRI remote control
    button_on_off:
      name: On off button press
      description: Action to run on press of on off button
      default: []
      selector:
        action: {}
    button_brightness_up_short:
      name: Brightness up button - short press
      description: Action to run on short brightness up press
      default: []
      selector:
        action: {}
    button_brightness_up_long:
      name: Brightness up button - long press
      description: Action to run on long brightness up press
      default: []
      selector:
        action: {}
    button_brightness_down_short:
      name: Brightness down button - short press
      description: Action to run on short brightness down press
      default: []
      selector:
        action: {}
    button_brightness_down_long:
      name: Brightness down button - long press
      description: Action to run on long brightness down press
      default: []
      selector:
        action: {}
    button_left_short:
      name: Left button - short press
      description: Action to run on short left button press
      default: []
      selector:
        action: {}
    button_left_long:
      name: Left button - long press
      description: Action to run on long left button press
      default: []
      selector:
        action: {}
    button_right_short:
      name: Right button - short press
      description: Action to run on short right button press
      default: []
      selector:
        action: {}
    button_right_long:
      name: Right button - long press
      description: Action to run on long right button press
      default: []
      selector:
        action: {}
  source_url: https://community.home-assistant.io/t/zha-ikea-five-button-remote/255120/14
mode: restart
max_exceeded: silent
trigger:
- platform: event
  event_type: zha_event
  event_data:
    device_id: !input 'remote'
action:
- variables:
    command: '{{ trigger.event.data.command }}'
    cluster_id: '{{ trigger.event.data.cluster_id }}'
    endpoint_id: '{{ trigger.event.data.endpoint_id }}'
    args: '{{ trigger.event.data.args }}'
- choose:
  - conditions:
    - '{{ command == ''toggle'' }}'
    - '{{ cluster_id == 6 }}'
    - '{{ endpoint_id == 1 }}'
    sequence: !input 'button_on_off'
  - conditions:
    - '{{ command == ''step_with_on_off'' }}'
    - '{{ cluster_id == 8 }}'
    - '{{ endpoint_id == 1 }}'
    - '{{ args == [0, 43, 5] }}'
    sequence: !input 'button_brightness_up_short'
  - conditions:
    - '{{ command == ''move_with_on_off'' }}'
    - '{{ cluster_id == 8 }}'
    - '{{ endpoint_id == 1 }}'
    - '{{ args == [0, 83] }}'
    sequence: !input 'button_brightness_up_long'
  - conditions:
    - '{{ command == ''step'' }}'
    - '{{ cluster_id == 8 }}'
    - '{{ endpoint_id == 1 }}'
    - '{{ args == [1, 43, 5] }}'
    sequence: !input 'button_brightness_down_short'
  - conditions:
    - '{{ command == ''move'' }}'
    - '{{ cluster_id == 8 }}'
    - '{{ endpoint_id == 1 }}'
    - '{{ args == [1, 83] }}'
    sequence: !input 'button_brightness_down_long'
  - conditions:
    - '{{ command == ''press'' }}'
    - '{{ cluster_id == 5 }}'
    - '{{ endpoint_id == 1 }}'
    - '{{ args == [257, 13, 0] }}'
    sequence: !input 'button_left_short'
  - conditions:
    - '{{ command == ''hold'' }}'
    - '{{ cluster_id == 5 }}'
    - '{{ endpoint_id == 1 }}'
    - '{{ args == [3329, 0] }}'
    sequence: !input 'button_left_long'
  - conditions:
    - '{{ command == ''press'' }}'
    - '{{ cluster_id == 5 }}'
    - '{{ endpoint_id == 1 }}'
    - '{{ args == [256, 13, 0] }}'
    sequence: !input 'button_right_short'
  - conditions:
    - '{{ command == ''hold'' }}'
    - '{{ cluster_id == 5 }}'
    - '{{ endpoint_id == 1 }}'
    - '{{ args == [3328, 0] }}'
    sequence: !input 'button_right_long'

@MattWestb
Copy link
Contributor

Your remote is sending commands OK but its having one not so common firmware that is using different parameters for long press (have only seen one very old issue with that).
Its 2 ways to going. If you dont using the remote for steering light with Zigbee groups its the best updating the firmware to current IKEA production and you is loosing the group binding but you is getting many bug fixed in the device (that shall being the best then you is using is for automatons and not controlling light with it). The second is changing your blur print using 84 instead of 83 (2 places) and all shall working OK.

@dmulcahey is one very unusual firmware version and one PR is not merged for it (shall not being instead updating the device firmware) zigpy/zha-device-handlers#318.

@stalakerob
Copy link

stalakerob commented Apr 16, 2022

I don't have a Ikea Gateway so I cannot update.

The second is changing your blur print using 84 instead of 83 (2 places) and all shall working OK.

Sorry, but where can I change this?

@MattWestb
Copy link
Contributor

You is running ZHA so you can only configuring IKEA OTA and its shall working https://github.com/zigpy/zigpy/wiki/OTA-Device-Firmware-Updates

@stalakerob
Copy link

This doesn't seem to work. When I try using the manual update service I'm getting errors. How do I use the other option changing blur print?


home-assistant   | 2022-04-16 16:00:40 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [2786281624] Error handling message: Unknown error (unknown_error)
home-assistant   | Traceback (most recent call last):
home-assistant   |   File "/usr/local/lib/python3.9/site-packages/zigpy/types/struct.py", line 39, in _convert_type
home-assistant   |     return self.type(value)
home-assistant   |   File "/usr/local/lib/python3.9/site-packages/zigpy/types/basic.py", line 254, in __call__
home-assistant   |     value = int(value)
home-assistant   | ValueError: invalid literal for int() with base 10: '0 100'
home-assistant   |
home-assistant   | The above exception was the direct cause of the following exception:
home-assistant   |
home-assistant   | Traceback (most recent call last):
home-assistant   |   File "/usr/src/homeassistant/homeassistant/components/websocket_api/decorators.py", line 27, in _handle_async_response
home-assistant   |     await func(hass, connection, msg)
home-assistant   |   File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 630, in handle_execute_script
home-assistant   |     await script_obj.async_run(msg.get("variables"), context=context)
home-assistant   |   File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 1275, in async_run
home-assistant   |     await asyncio.shield(run.async_run())
home-assistant   |   File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 359, in async_run
home-assistant   |     await self._async_step(log_exceptions=False)
home-assistant   |   File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 379, in _async_step
home-assistant   |     await getattr(self, handler)()
home-assistant   |   File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 582, in _async_call_service_step
home-assistant   |     await service_task
home-assistant   |   File "/usr/src/homeassistant/homeassistant/core.py", line 1634, in async_call
home-assistant   |     task.result()
home-assistant   |   File "/usr/src/homeassistant/homeassistant/core.py", line 1671, in _execute_service
home-assistant   |     await cast(Callable[[ServiceCall], Awaitable[None]], handler.job.target)(
home-assistant   |   File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 747, in admin_handler
home-assistant   |     await result
home-assistant   |   File "/usr/src/homeassistant/homeassistant/components/zha/api.py", line 1149, in issue_zigbee_cluster_command
home-assistant   |     response = await zha_device.issue_cluster_command(
home-assistant   |   File "/usr/src/homeassistant/homeassistant/components/zha/core/device.py", line 647, in issue_cluster_command
home-assistant   |     response = await cluster.client_command(command, *args)
home-assistant   |   File "/usr/local/lib/python3.9/site-packages/zigpy/zcl/__init__.py", line 309, in reply
home-assistant   |     request = schema(*args, **kwargs)  # type:ignore[operator]
home-assistant   |   File "/usr/local/lib/python3.9/site-packages/zigpy/types/struct.py", line 115, in __new__
home-assistant   |     setattr(instance, name, field._convert_type(value))
home-assistant   |   File "/usr/local/lib/python3.9/site-packages/zigpy/types/struct.py", line 41, in _convert_type
home-assistant   |     raise ValueError(
home-assistant   | ValueError: Failed to convert payload_type='0 100' from type <class 'str'> to <enum 'ImageNotifyPayloadType'>

@MattWestb
Copy link
Contributor

Ops i have not testing HA 2033.4.X but i think its one braking thing implanted zigpy/zigpy#961 that shall being fixed but i think its not getting the the last HA 2022.4.4.
You can waiting some days and testing and also look in the release notes of HA for see if somthing is updated.
Also the Zigpy release notes can telling if its in the next HA https://github.com/zigpy/zigpy/releases.

@stalakerob
Copy link

After some further testing I figured out that the ZHA events are actually coming through, also for up and down buttons. I created an automation that successfully acts on the event. The issue must be in the blueprint then.

@Hedda
Copy link
Contributor

Hedda commented Apr 19, 2022

@EPMatt
Copy link
Contributor

EPMatt commented Apr 22, 2022

Hi @Hedda,

thank you so much for reaching out here. Sure! I can see a fix was proposed for this issue on this PR on the Awesome HA Blueprints repo. I'll take some time to review it later today.

Thank you for your patience!

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging a pull request may close this issue.