ZHA add support for Müller Tint Remote

siccovansas commented 4 years ago

The problem

Currently I can't pair a Müller Tint Remote [official product page, Blakadder] using ZHA. Some logs were already provided in this issue. Some more information about all the functions of the remote is available in this deconz issue (more info on the remote also at the top of that issue). Is it possible for ZHA to support this remote? I'd be happy to help out and gather extra information/logs :)!

Environment

Home Assistant Core release with the issue: 0.110.5
Last working Home Assistant Core release (if known):
Operating environment (Home Assistant/Supervised/Docker/venv): Docker
Integration causing this issue: ZHA
Link to integration documentation on our website: https://www.home-assistant.io/integrations/zha/

Problem-relevant `configuration.yaml`

Traceback/Error logs

Additional information

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

zha documentation zha source _{^{(message by IssueLinks)}}

Adminiuga commented 4 years ago

you have to provide full debug logs of joining the remote (make sure it was removed 1st from ZHA) and debug logs on what is received for each button press.

siccovansas commented 4 years ago

Thanks for your reply!

I can't get the remote to pair with my CC2531. I've tried several times to remove and insert the batteries, hold the reset button of the remote (tried multiple times between 2-25 seconds), try the normal pairing process for adding bulbs (hold the group button).

I enabled debug logs and then add/search for a device using ZHA, but I can't get any debug logs consistently for the pairing proces. At the bottom of the 'Add Devices' page I once got the following logs, but most of the times I get nothing:

[0xe6dc:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=18 command_id=Command.Report_Attributes>
[0xe6dc:1:0x0008] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=uint8_t, value=254>>]]
[0xe6dc:1:0x0008] Attribute report received: current_level=254
[0xe6dc:1:0x0008]: received attribute: 0 update with value: 254
[0xe6dc:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=19 command_id=Command.Report_Attributes>
[0xe6dc:1:0x0006] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=Bool, value=Bool.false>>]]
[0xe6dc:1:0x0006] Attribute report received: on_off=0

Another time I got:

[0xe6dc:1:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=20 command_id=Command.Report_Attributes>
[0xe6dc:1:0x0300] ZCL request 0x000a: [[<Attribute attrid=3 value=<TypeValue type=uint16_t, value=24116>>, <Attribute attrid=4 value=<TypeValue type=uint16_t, value=17628>>, <Attribute attrid=7 value=<TypeValue type=uint16_t, value=228>>]]
[0xe6dc:1:0x0300] Attribute report received: current_x=24116, current_y=17628, color_temperature=228

And when I look in the debug logs I only see the 'Add Devices' search start and stop logs, with maybe 2 relevant lines in the middle (but I don't seem to get those 2 consistently everytime)?

app_1  | 2020-06-09 13:23:39 DEBUG (MainThread) [zigpy_cc.zigbee.application] broadcast (0, 54, 0, 0, 0, 0, 36, b'$<\x00', <BroadcastAddress.ALL_ROUTERS_AND_COORDINATOR: 65532>)
app_1  | 2020-06-09 13:23:39 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO mgmtPermitJoinReq tsn: 36 {'addrmode': 15, 'dstaddr': 0xfffc, 'duration': 60, 'tcsignificance': 0}
app_1  | 2020-06-09 13:23:39 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x05%6\x0f\xfc\xff<\x00&'
app_1  | 2020-06-09 13:23:39 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=54 data=b'\x00' length=1 fcs=82>
app_1  | 2020-06-09 13:23:39 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO mgmtPermitJoinReq tsn: None {'status': 0}
app_1  | 2020-06-09 13:23:39 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO mgmtPermitJoinReq tsn: None {'addrmode': 15, 'dstaddr': <BroadcastAddress.ALL_ROUTERS_AND_COORDINATOR: 65532>, 'duration': 60, 'tcsignificance': 0}
app_1  | 2020-06-09 13:23:39 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x05%6\x0f\xfc\xff<\x00&'
app_1  | 2020-06-09 13:23:39 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=203 data=b'<' length=1 fcs=179>
app_1  | 2020-06-09 13:23:39 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO permitJoinInd tsn: None {'duration': 60}
app_1  | 2020-06-09 13:23:39 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=54 data=b'\x00' length=1 fcs=82>
app_1  | 2020-06-09 13:23:39 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO mgmtPermitJoinReq tsn: None {'status': 0}
app_1  | 2020-06-09 13:23:39 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=182 data=b'\x00\x00\x00' length=3 fcs=240>
app_1  | 2020-06-09 13:23:39 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO mgmtPermitJoinRsp tsn: None {'srcaddr': 0x0000, 'status': 0}
app_1  | 2020-06-09 13:23:39 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=182 data=b'\x00\x00\x00' length=3 fcs=240>
app_1  | 2020-06-09 13:23:39 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO mgmtPermitJoinRsp tsn: None {'srcaddr': 0x0000, 'status': 0}

app_1  | 2020-06-09 13:24:39 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=203 data=b'\x00' length=1 fcs=143>
app_1  | 2020-06-09 13:24:39 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO permitJoinInd tsn: None {'duration': 0}

app_1  | 2020-06-09 13:28:30 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=129 data=b'\x00\x00\x00\x03\xdc\xe6\x01\x01\x007\x00\x84\x9e\xb5\x00\x00\x12\x08\x17\n\x03\x00!4^\x04\x00!\xdcD\x07\x00!\xe4\x00\xdc\xe6\x1d' length=38 fcs=85>
app_1  | 2020-06-09 13:28:30 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF incomingMsg tsn: None {'groupid': 0, 'clusterid': 768, 'srcaddr': 0xe6dc, 'srcendpoint': 1, 'dstendpoint': 1, 'wasbroadcast': 0, 'linkquality': 55, 'securityuse': 0, 'timestamp': 11902596, 'transseqnumber': 0, 'len': 18, 'data': b'\x08\x17\n\x03\x00!4^\x04\x00!\xdcD\x07\x00!\xe4\x00'}
app_1  | 2020-06-09 13:28:30 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message incomingMsg
app_1  | 2020-06-09 13:28:30 DEBUG (MainThread) [zigpy.zcl] [0xe6dc:1:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=23 command_id=Command.Report_Attributes>
app_1  | 2020-06-09 13:28:30 DEBUG (MainThread) [zigpy.zcl] [0xe6dc:1:0x0300] ZCL request 0x000a: [[<Attribute attrid=3 value=<TypeValue type=uint16_t, value=24116>>, <Attribute attrid=4 value=<TypeValue type=uint16_t, value=17628>>, <Attribute attrid=7 value=<TypeValue type=uint16_t, value=228>>]]
app_1  | 2020-06-09 13:28:30 DEBUG (MainThread) [zigpy.zcl] [0xe6dc:1:0x0300] Attribute report received: current_x=24116, current_y=17628, color_temperature=228
app_1  | 2020-06-09 13:28:30 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xe6dc, 260, 768, 1, 1, 23, b'\x18\x17\x0b\n\x00', False, False)
app_1  | 2020-06-09 13:28:30 DEBUG (MainThread) [zigpy_cc.api] --> SREQ AF dataRequest tsn: 23 {'dstaddr': 59100, 'destendpoint': 1, 'srcendpoint': 1, 'clusterid': 768, 'transid': 38, 'options': 0, 'radius': 30, 'len': 5, 'data': b'\x18\x17\x0b\n\x00'}
app_1  | 2020-06-09 13:28:30 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x0f$\x01\xdc\xe6\x01\x01\x00\x03&\x00\x1e\x05\x18\x17\x0b\n\x00 '
app_1  | 2020-06-09 13:28:30 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.AF command_id=1 data=b'\x00' length=1 fcs=100>
app_1  | 2020-06-09 13:28:30 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP AF dataRequest tsn: None {'status': 0}
app_1  | 2020-06-09 13:28:30 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=128 data=b'\x00\x01&' length=3 fcs=224>
app_1  | 2020-06-09 13:28:30 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF dataConfirm tsn: None {'status': 0, 'endpoint': 1, 'transid': 38}
app_1  | 2020-06-09 13:28:30 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: dataConfirm

Am I doing anything wrong? Can I get other/more debug logs?

Adminiuga commented 4 years ago

in the logs when you see something like [0xe6dc:1:0x0008] the 1st part 0xe6dc is the NWK address of the device sending/receiving data. 1 is the endpoint id, and last part 0x0008 is the cluster_id. You can see the NWK address of your devices from zha config panel, but judging by the attribute reports, that's most likely one of your color bulbs.

Now, the zigpy-cc radio type for ZHA integration is relatively new and some quirks are expected. I'd suggest opening an issue in zigpy-cc repo as I currently don't see the logs indicating a successful or any join of this remote. You also could try https://github.com/zha-ng/zigpy-znp It is an alternative implementation for CC2531 (TI based radios) and being actively developed, but currently not in the upstream, so requires a custom component (read the readme for znp) to inject new radio type into ZHA

siccovansas commented 4 years ago

Ok, turned out I couldn't pair the remote because my CC2531's firmware wasn't up to date. I didn't manage to flash using an Arduino, but I did get the new flash using USB with zigpy-znp to work after multiple tries (sometimes it hangs). I now use the latest firmware (Z-Stack 3.0.x CC2531_20190425) and I can pair the remote. I can now provide you the debug logs of the pairing and of each button press (see the attached image of the manual to see how each button is called and see the color image for the color layout of the 'Colour control' fake wheel (it's actually just 4 buttons beneath the wheel)).

tint_remote csm_404011_a01_000_M_d2d317d1fb_a4b255390b

Pair debug log:

app_1        | 2020-06-12 18:17:16 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=180 data=b'\xe9B\x00' length=3 fcs=89>
app_1        | 2020-06-12 18:17:16 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO mgmtLeaveRsp tsn: None {'srcaddr': 0x42e9, 'status': 0}
app_1        | 2020-06-12 18:17:16 WARNING (MainThread) [zigpy_cc.zigbee.application] Unhandled message: CommandType.AREQ Subsystem.ZDO mgmtLeaveRsp
app_1        | 2020-06-12 18:17:17 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=201 data=b'\xe9B\xf9\x02\xfe\x01\x00\x8d\x15\x00\x00\x00\x00' length=13 fcs=182>
app_1        | 2020-06-12 18:17:17 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO leaveInd tsn: None {'srcaddr': 0x42e9, 'extaddr': 00:15:8d:00:01:fe:02:f9, 'request': 0, 'removechildren': 0, 'rejoin': 0}
app_1        | 2020-06-12 18:17:17 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: leaveInd
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=196 data=b'\x88\x85\x00' length=3 fcs=143>
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO srcRtgInd tsn: None {'dstaddr': 0x8588, 'relaycount': 0, 'relaylist': []}
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: srcRtgInd
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=196 data=b'\x88\x85\x00' length=3 fcs=143>
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO srcRtgInd tsn: None {'dstaddr': 0x8588, 'relaycount': 0, 'relaylist': []}
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: srcRtgInd
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=202 data=b'c&\xf9\x02\xfe\x01\x00\x8d\x15\x00\x88\x85' length=12 fcs=87>
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO tcDeviceInd tsn: None {'nwkaddr': 0x2663, 'extaddr': 00:15:8d:00:01:fe:02:f9, 'parentaddr': 0x8588}
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: tcDeviceInd
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=202 data=b'c&\xf9\x02\xfe\x01\x00\x8d\x15\x00\x88\x85' length=12 fcs=87>
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO tcDeviceInd tsn: None {'nwkaddr': 0x2663, 'extaddr': 00:15:8d:00:01:fe:02:f9, 'parentaddr': 0x8588}
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: tcDeviceInd
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=193 data=b'c&c&\xf9\x02\xfe\x01\x00\x8d\x15\x00\x80' length=13 fcs=149>
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO endDeviceAnnceInd tsn: 0 {'srcaddr': 0x2663, 'nwkaddr': 0x2663, 'ieeeaddr': 00:15:8d:00:01:fe:02:f9, 'capabilities': 128}
app_1        | 2020-06-12 18:17:22 INFO (MainThread) [zigpy_cc.zigbee.application] New device joined: 0x2663, 00:15:8d:00:01:fe:02:f9
app_1        | 2020-06-12 18:17:22 INFO (MainThread) [zigpy.application] Device 0x2663 (00:15:8d:00:01:fe:02:f9) joined the network
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 0 endDeviceAnnceInd
app_1        | 2020-06-12 18:17:22 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message endDeviceAnnceInd
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy.zdo] [0x2663:zdo] ZDO request ZDOCmd.Device_annce: [0x2663, 00:15:8d:00:01:fe:02:f9, 128]
app_1        | 2020-06-12 18:17:22 INFO (MainThread) [zigpy.device] [0x2663] Requesting 'Node Descriptor'
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy.util] Tries remaining: 2
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy.device] [0x2663] Extending timeout for 0xe6 request
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0x2663, 0, <ZDOCmd.Node_Desc_req: 2>, 0, 0, 230, b'\xe6c&', True, False)
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy_cc.api] waiting for 230 nodeDescReq
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO nodeDescReq tsn: 230 {'dstaddr': 0x2663, 'nwkaddrofinterest': 0x2663}
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x04%\x02c&c&#'
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=2 data=b'\x00' length=1 fcs=102>
app_1        | 2020-06-12 18:17:22 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO nodeDescReq tsn: None {'status': 0}
app_1        | 2020-06-12 18:17:23 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=196 data=b'c&\x01\x88\x85' length=5 fcs=205>
app_1        | 2020-06-12 18:17:23 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO srcRtgInd tsn: None {'dstaddr': 0x2663, 'relaycount': 1, 'relaylist': [34184]}
app_1        | 2020-06-12 18:17:23 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: srcRtgInd
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=196 data=b'c&\x01\x88\x85' length=5 fcs=205>
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO srcRtgInd tsn: None {'dstaddr': 0x2663, 'relaycount': 1, 'relaylist': [34184]}
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: srcRtgInd
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=130 data=b'c&\x00c&\x02@\x80\x1b\x12\x7fd\x00\x00,d\x00\x00' length=18 fcs=77>
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO nodeDescRsp tsn: 230 {'srcaddr': 0x2663, 'status': 0, 'nwkaddr': 0x2663, 'logicaltype_cmplxdescavai_userdescavai': 2, 'apsflags_freqband': 64, 'maccapflags': 128, 'manufacturercode': 4635, 'maxbuffersize': 127, 'maxintransfersize': 100, 'servermask': 11264, 'maxouttransfersize': 100, 'descriptorcap': 0}
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 230 nodeDescRsp
app_1        | 2020-06-12 18:17:24 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message nodeDescRsp
app_1        | 2020-06-12 18:17:24 INFO (MainThread) [zigpy.device] [0x2663] Node Descriptor: <Optional byte1=2 byte2=64 mac_capability_flags=128 manufacturer_code=4635 maximum_buffer_size=127 maximum_incoming_transfer_size=100 server_mask=11264 maximum_outgoing_transfer_size=100 descriptor_capability_field=0>
app_1        | 2020-06-12 18:17:24 INFO (MainThread) [zigpy.device] [0x2663] Discovering endpoints
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy.device] [0x2663] Extending timeout for 0xe8 request
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0x2663, 0, <ZDOCmd.Active_EP_req: 5>, 0, 0, 232, b'\xe8c&', True, False)
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.api] waiting for 232 activeEpReq
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO activeEpReq tsn: 232 {'dstaddr': 0x2663, 'nwkaddrofinterest': 0x2663}
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x04%\x05c&c&$'
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=5 data=b'\x00' length=1 fcs=97>
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO activeEpReq tsn: None {'status': 0}
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=196 data=b'c&\x01\x88\x85' length=5 fcs=205>
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO srcRtgInd tsn: None {'dstaddr': 0x2663, 'relaycount': 1, 'relaylist': [34184]}
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: srcRtgInd
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=133 data=b'c&\x00c&\x01\x01' length=7 fcs=199>
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO activeEpRsp tsn: 232 {'srcaddr': 0x2663, 'status': 0, 'nwkaddr': 0x2663, 'activeepcount': 1, 'activeeplist': [1]}
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 232 activeEpRsp
app_1        | 2020-06-12 18:17:24 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message activeEpRsp
app_1        | 2020-06-12 18:17:24 INFO (MainThread) [zigpy.device] [0x2663] Discovered endpoints: [1]
app_1        | 2020-06-12 18:17:24 INFO (MainThread) [zigpy.endpoint] [0x2663:1] Discovering endpoint information
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy.device] [0x2663] Extending timeout for 0xea request
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0x2663, 0, <ZDOCmd.Simple_Desc_req: 4>, 0, 0, 234, b'\xeac&\x01', True, False)
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.api] waiting for 234 simpleDescReq
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO simpleDescReq tsn: 234 {'dstaddr': 0x2663, 'nwkaddrofinterest': 0x2663, 'endpoint': 1}
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x05%\x04c&c&\x01%'
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=4 data=b'\x00' length=1 fcs=96>
app_1        | 2020-06-12 18:17:24 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO simpleDescReq tsn: None {'status': 0}
app_1        | 2020-06-12 18:17:25 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=196 data=b'c&\x01\x88\x85' length=5 fcs=205>
app_1        | 2020-06-12 18:17:25 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO srcRtgInd tsn: None {'dstaddr': 0x2663, 'relaycount': 1, 'relaylist': [34184]}
app_1        | 2020-06-12 18:17:25 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: srcRtgInd
app_1        | 2020-06-12 18:17:25 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=132 data=b'c&\x00c&\x1e\x01\x04\x01\x00\x08\x01\x03\x00\x00\x03\x00\x00\x10\x08\x04\x00\x03\x00\x06\x00\x08\x00\x00\x03\x00\x10\x19\x00\x00\x00' length=36 fcs=237>
app_1        | 2020-06-12 18:17:25 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO simpleDescRsp tsn: 234 {'srcaddr': 0x2663, 'status': 0, 'nwkaddr': 0x2663, 'len': 30, 'endpoint': 1, 'profileid': 260, 'deviceid': 2048, 'deviceversion': 1, 'numinclusters': 3, 'inclusterlist': [0, 3, 4096], 'numoutclusters': 8, 'outclusterlist': [4, 3, 6, 8, 768, 4096, 25, 0]}
app_1        | 2020-06-12 18:17:25 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 234 simpleDescRsp
app_1        | 2020-06-12 18:17:25 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message simpleDescRsp
app_1        | 2020-06-12 18:17:25 INFO (MainThread) [zigpy.endpoint] [0x2663:1] Discovered endpoint information: <Optional endpoint=1 profile=260 device_type=2048 device_version=1 input_clusters=[0, 3, 4096] output_clusters=[4, 3, 6, 8, 768, 4096, 25, 0]>
app_1        | 2020-06-12 18:17:25 DEBUG (MainThread) [zigpy.device] [0x2663] Extending timeout for 0xec request
app_1        | 2020-06-12 18:17:25 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0x2663, 260, 0, 1, 1, 236, b'\x00\xec\x00\x04\x00\x05\x00', True, False)
app_1        | 2020-06-12 18:17:25 DEBUG (MainThread) [zigpy_cc.api] --> SREQ AF dataRequest tsn: 236 {'dstaddr': 9827, 'destendpoint': 1, 'srcendpoint': 1, 'clusterid': 0, 'transid': 237, 'options': 0, 'radius': 30, 'len': 7, 'data': b'\x00\xec\x00\x04\x00\x05\x00'}
app_1        | 2020-06-12 18:17:25 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x11$\x01c&\x01\x01\x00\x00\xed\x00\x1e\x07\x00\xec\x00\x04\x00\x05\x00h'
app_1        | 2020-06-12 18:17:25 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.AF command_id=1 data=b'\x00' length=1 fcs=100>
app_1        | 2020-06-12 18:17:25 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP AF dataRequest tsn: None {'status': 0}
app_1        | 2020-06-12 18:17:25 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=128 data=b'\x00\x01\xed' length=3 fcs=43>
app_1        | 2020-06-12 18:17:25 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF dataConfirm tsn: None {'status': 0, 'endpoint': 1, 'transid': 237}
app_1        | 2020-06-12 18:17:25 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: dataConfirm
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=196 data=b'c&\x01\x88\x85' length=5 fcs=205>
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO srcRtgInd tsn: None {'dstaddr': 0x2663, 'relaycount': 1, 'relaylist': [34184]}
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: srcRtgInd
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=129 data=b'\x00\x00\x00\x00c&\x01\x01\x00\x1f\x00\xc9\xac%\x00\x00#\x18\xec\x01\x04\x00\x00B\x03MLI\x05\x00\x00B\x13ZBT-Remote-ALL-RGBW\x88\x85\x1c' length=55 fcs=114>
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF incomingMsg tsn: None {'groupid': 0, 'clusterid': 0, 'srcaddr': 0x2663, 'srcendpoint': 1, 'dstendpoint': 1, 'wasbroadcast': 0, 'linkquality': 31, 'securityuse': 0, 'timestamp': 2469065, 'transseqnumber': 0, 'len': 35, 'data': b'\x18\xec\x01\x04\x00\x00B\x03MLI\x05\x00\x00B\x13ZBT-Remote-ALL-RGBW'}
app_1        | 2020-06-12 18:17:26 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message incomingMsg
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=236 command_id=Command.Read_Attributes_rsp>
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.endpoint] [0x2663:1] Manufacturer: MLI
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.endpoint] [0x2663:1] Model: ZBT-Remote-ALL-RGBW
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Checking quirks for MLI ZBT-Remote-ALL-RGBW (00:15:8d:00:01:fe:02:f9)
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'bellows.zigbee.application.EZSPCoordinator'>
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because device_type mismatch on at least one endpoint
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.gledopto.soposhgu10.SoposhGU10'>
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {11, 13} {1}
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.lutron.lzl4bwhl01remote.LutronLZL4BWHL01Remote2'>
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because profile_id mismatch on at least one endpoint
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.netvox.z308e3ed.Z308E3ED'>
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because device_type mismatch on at least one endpoint
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.osram.a19twhite.A19TunableWhite'>
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {3} {1}
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.philips.rom001.PhilipsROM001'>
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because device_type mismatch on at least one endpoint
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.philips.rwl020.PhilipsRWL020'>
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1, 2} {1}
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.philips.rwl021.PhilipsRWL021'>
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1, 2} {1}
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.smartthings.multi.SmartthingsMultiPurposeSensor'>
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because device_type mismatch on at least one endpoint
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.smartthings.tag_v4.SmartThingsTagV4'>
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because device_type mismatch on at least one endpoint
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.xbee.xbee3_io.XBee3Sensor'>
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {232, 230} {1}
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.xbee.xbee_io.XBeeSensor'>
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {232, 230} {1}
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.xiaomi.mija.smoke.MijiaHoneywellSmokeDetectorSensor'>
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because device_type mismatch on at least one endpoint
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [homeassistant.components.zha.core.gateway] device - 0x2663:00:15:8d:00:01:fe:02:f9 entering async_device_initialized - is_new_join: True
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [homeassistant.components.zha.core.gateway] device - 0x2663:00:15:8d:00:01:fe:02:f9 has joined the ZHA zigbee network
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x2663](ZBT-Remote-ALL-RGBW): started configuration
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:ZDO](ZBT-Remote-ALL-RGBW): 'async_configure' stage succeeded
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.device] [0x2663] Extending timeout for 0xee request
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0x2663, 0, <ZDOCmd.Bind_req: 33>, 0, 0, 238, b'\xee\xf9\x02\xfe\x01\x00\x8d\x15\x00\x01\x00\x00\x03l\x7f\xd4\x1c\x00K\x12\x00\x01', True, False)
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy_cc.api] waiting for 238 bindReq
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO bindReq tsn: 238 {'dstaddr': 0x2663, 'srcaddr': 00:15:8d:00:01:fe:02:f9, 'srcendpoint': 1, 'clusterid': 0, 'dstaddrmode': 3, 'dstaddress': 00:12:4b:00:1c:d4:7f:6c, 'dstendpoint': 1}
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x17%!c&\xf9\x02\xfe\x01\x00\x8d\x15\x00\x01\x00\x00\x03l\x7f\xd4\x1c\x00K\x12\x00\x01K'
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.device] [0x2663] Extending timeout for 0xf0 request
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0x2663, 0, <ZDOCmd.Bind_req: 33>, 0, 0, 240, b'\xf0\xf9\x02\xfe\x01\x00\x8d\x15\x00\x01\x00\x10\x03l\x7f\xd4\x1c\x00K\x12\x00\x01', True, False)
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy_cc.api] waiting for 240 bindReq
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO bindReq tsn: 240 {'dstaddr': 0x2663, 'srcaddr': 00:15:8d:00:01:fe:02:f9, 'srcendpoint': 1, 'clusterid': 4096, 'dstaddrmode': 3, 'dstaddress': 00:12:4b:00:1c:d4:7f:6c, 'dstendpoint': 1}
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x17%!c&\xf9\x02\xfe\x01\x00\x8d\x15\x00\x01\x00\x10\x03l\x7f\xd4\x1c\x00K\x12\x00\x01['
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy.device] [0x2663] Extending timeout for 0xf2 request
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0x2663, 0, <ZDOCmd.Bind_req: 33>, 0, 0, 242, b'\xf2\xf9\x02\xfe\x01\x00\x8d\x15\x00\x01\x08\x00\x03l\x7f\xd4\x1c\x00K\x12\x00\x01', True, False)
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy_cc.api] waiting for 242 bindReq
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO bindReq tsn: 242 {'dstaddr': 0x2663, 'srcaddr': 00:15:8d:00:01:fe:02:f9, 'srcendpoint': 1, 'clusterid': 8, 'dstaddrmode': 3, 'dstaddress': 00:12:4b:00:1c:d4:7f:6c, 'dstendpoint': 1}
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x17%!c&\xf9\x02\xfe\x01\x00\x8d\x15\x00\x01\x08\x00\x03l\x7f\xd4\x1c\x00K\x12\x00\x01C'
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=33 data=b'\x00' length=1 fcs=69>
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO bindReq tsn: None {'status': 0}
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=33 data=b'\x00' length=1 fcs=69>
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO bindReq tsn: None {'status': 0}
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=33 data=b'\x00' length=1 fcs=69>
app_1        | 2020-06-12 18:17:26 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO bindReq tsn: None {'status': 0}
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=196 data=b'c&\x01\x88\x85' length=5 fcs=205>
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO srcRtgInd tsn: None {'dstaddr': 0x2663, 'relaycount': 1, 'relaylist': [34184]}
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: srcRtgInd
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=196 data=b'c&\x01\x88\x85' length=5 fcs=205>
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO srcRtgInd tsn: None {'dstaddr': 0x2663, 'relaycount': 1, 'relaylist': [34184]}
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: srcRtgInd
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=196 data=b'c&\x01\x88\x85' length=5 fcs=205>
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO srcRtgInd tsn: None {'dstaddr': 0x2663, 'relaycount': 1, 'relaylist': [34184]}
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: srcRtgInd
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=196 data=b'c&\x01\x88\x85' length=5 fcs=205>
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO srcRtgInd tsn: None {'dstaddr': 0x2663, 'relaycount': 1, 'relaylist': [34184]}
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: srcRtgInd
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=161 data=b'c&\x00' length=3 fcs=162>
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO bindRsp tsn: 238 {'srcaddr': 0x2663, 'status': 0}
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 238 bindRsp
app_1        | 2020-06-12 18:17:27 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message bindRsp
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0000]: bound 'basic' cluster: Status.SUCCESS
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0000]: finished channel configuration
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy.device] [0x2663] Extending timeout for 0xf4 request
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0x2663, 260, 0, 1, 1, 244, b'\x00\xf4\x00\x07\x00', True, False)
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.api] --> SREQ AF dataRequest tsn: 244 {'dstaddr': 9827, 'destendpoint': 1, 'srcendpoint': 1, 'clusterid': 0, 'transid': 245, 'options': 0, 'radius': 30, 'len': 5, 'data': b'\x00\xf4\x00\x07\x00'}
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x0f$\x01c&\x01\x01\x00\x00\xf5\x00\x1e\x05\x00\xf4\x00\x07\x00r'
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.AF command_id=1 data=b'\x00' length=1 fcs=100>
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP AF dataRequest tsn: None {'status': 0}
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=128 data=b'\x00\x01\xf5' length=3 fcs=51>
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF dataConfirm tsn: None {'status': 0, 'endpoint': 1, 'transid': 245}
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: dataConfirm
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=161 data=b'c&\x00' length=3 fcs=162>
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO bindRsp tsn: 240 {'srcaddr': 0x2663, 'status': 0}
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 240 bindRsp
app_1        | 2020-06-12 18:17:27 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message bindRsp
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x1000]: bound 'lightlink' cluster: Status.SUCCESS
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x1000]: finished channel configuration
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy.device] [0x2663] Extending timeout for 0xf6 request
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0x2663, 0, <ZDOCmd.Bind_req: 33>, 0, 0, 246, b'\xf6\xf9\x02\xfe\x01\x00\x8d\x15\x00\x01\x06\x00\x03l\x7f\xd4\x1c\x00K\x12\x00\x01', True, False)
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.api] waiting for 246 bindReq
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO bindReq tsn: 246 {'dstaddr': 0x2663, 'srcaddr': 00:15:8d:00:01:fe:02:f9, 'srcendpoint': 1, 'clusterid': 6, 'dstaddrmode': 3, 'dstaddress': 00:12:4b:00:1c:d4:7f:6c, 'dstendpoint': 1}
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x17%!c&\xf9\x02\xfe\x01\x00\x8d\x15\x00\x01\x06\x00\x03l\x7f\xd4\x1c\x00K\x12\x00\x01M'
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=33 data=b'\x00' length=1 fcs=69>
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO bindReq tsn: None {'status': 0}
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=196 data=b'c&\x01\x88\x85' length=5 fcs=205>
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO srcRtgInd tsn: None {'dstaddr': 0x2663, 'relaycount': 1, 'relaylist': [34184]}
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: srcRtgInd
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=196 data=b'c&\x01\x88\x85' length=5 fcs=205>
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO srcRtgInd tsn: None {'dstaddr': 0x2663, 'relaycount': 1, 'relaylist': [34184]}
app_1        | 2020-06-12 18:17:27 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: srcRtgInd
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=161 data=b'c&\x00' length=3 fcs=162>
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO bindRsp tsn: 242 {'srcaddr': 0x2663, 'status': 0}
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 242 bindRsp
app_1        | 2020-06-12 18:17:28 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message bindRsp
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0008]: bound 'level' cluster: Status.SUCCESS
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0008]: finished channel configuration
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy.device] [0x2663] Extending timeout for 0xf8 request
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0x2663, 0, <ZDOCmd.Bind_req: 33>, 0, 0, 248, b'\xf8\xf9\x02\xfe\x01\x00\x8d\x15\x00\x01\x19\x00\x03l\x7f\xd4\x1c\x00K\x12\x00\x01', True, False)
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.api] waiting for 248 bindReq
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO bindReq tsn: 248 {'dstaddr': 0x2663, 'srcaddr': 00:15:8d:00:01:fe:02:f9, 'srcendpoint': 1, 'clusterid': 25, 'dstaddrmode': 3, 'dstaddress': 00:12:4b:00:1c:d4:7f:6c, 'dstendpoint': 1}
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x17%!c&\xf9\x02\xfe\x01\x00\x8d\x15\x00\x01\x19\x00\x03l\x7f\xd4\x1c\x00K\x12\x00\x01R'
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=33 data=b'\x00' length=1 fcs=69>
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO bindReq tsn: None {'status': 0}
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=196 data=b'c&\x01\x88\x85' length=5 fcs=205>
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO srcRtgInd tsn: None {'dstaddr': 0x2663, 'relaycount': 1, 'relaylist': [34184]}
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: srcRtgInd
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=129 data=b'\x00\x00\x00\x00c&\x01\x01\x00\x1c\x00\x9b\xc0%\x00\x00\x08\x18\xf4\x01\x07\x00\x000\x03\x88\x85\x1c' length=28 fcs=62>
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF incomingMsg tsn: None {'groupid': 0, 'clusterid': 0, 'srcaddr': 0x2663, 'srcendpoint': 1, 'dstendpoint': 1, 'wasbroadcast': 0, 'linkquality': 28, 'securityuse': 0, 'timestamp': 2474139, 'transseqnumber': 0, 'len': 8, 'data': b'\x18\xf4\x01\x07\x00\x000\x03'}
app_1        | 2020-06-12 18:17:28 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message incomingMsg
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=244 command_id=Command.Read_Attributes_rsp>
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0000]: initializing channel: from_cache: False
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy.device] [0x2663] Extending timeout for 0xfa request
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0x2663, 0, <ZDOCmd.Bind_req: 33>, 0, 0, 250, b'\xfa\xf9\x02\xfe\x01\x00\x8d\x15\x00\x01\x00\x03\x03l\x7f\xd4\x1c\x00K\x12\x00\x01', True, False)
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.api] waiting for 250 bindReq
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO bindReq tsn: 250 {'dstaddr': 0x2663, 'srcaddr': 00:15:8d:00:01:fe:02:f9, 'srcendpoint': 1, 'clusterid': 768, 'dstaddrmode': 3, 'dstaddress': 00:12:4b:00:1c:d4:7f:6c, 'dstendpoint': 1}
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x17%!c&\xf9\x02\xfe\x01\x00\x8d\x15\x00\x01\x00\x03\x03l\x7f\xd4\x1c\x00K\x12\x00\x01H'
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=33 data=b'\x00' length=1 fcs=69>
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO bindReq tsn: None {'status': 0}
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=196 data=b'c&\x01\x88\x85' length=5 fcs=205>
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO srcRtgInd tsn: None {'dstaddr': 0x2663, 'relaycount': 1, 'relaylist': [34184]}
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: srcRtgInd
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=196 data=b'c&\x01\x88\x85' length=5 fcs=205>
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO srcRtgInd tsn: None {'dstaddr': 0x2663, 'relaycount': 1, 'relaylist': [34184]}
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: srcRtgInd
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=161 data=b'c&\x00' length=3 fcs=162>
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO bindRsp tsn: 246 {'srcaddr': 0x2663, 'status': 0}
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 246 bindRsp
app_1        | 2020-06-12 18:17:28 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message bindRsp
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0006]: bound 'on_off' cluster: Status.SUCCESS
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0006]: finished channel configuration
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=196 data=b'c&\x01\x88\x85' length=5 fcs=205>
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO srcRtgInd tsn: None {'dstaddr': 0x2663, 'relaycount': 1, 'relaylist': [34184]}
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: srcRtgInd
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=196 data=b'c&\x01\x88\x85' length=5 fcs=205>
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO srcRtgInd tsn: None {'dstaddr': 0x2663, 'relaycount': 1, 'relaylist': [34184]}
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: srcRtgInd
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=161 data=b'c&\x00' length=3 fcs=162>
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO bindRsp tsn: 248 {'srcaddr': 0x2663, 'status': 0}
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 248 bindRsp
app_1        | 2020-06-12 18:17:28 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message bindRsp
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0019]: bound 'ota' cluster: Status.SUCCESS
app_1        | 2020-06-12 18:17:28 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0019]: finished channel configuration
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=196 data=b'c&\x01\x88\x85' length=5 fcs=205>
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO srcRtgInd tsn: None {'dstaddr': 0x2663, 'relaycount': 1, 'relaylist': [34184]}
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: srcRtgInd
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=196 data=b'c&\x01\x88\x85' length=5 fcs=205>
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO srcRtgInd tsn: None {'dstaddr': 0x2663, 'relaycount': 1, 'relaylist': [34184]}
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: srcRtgInd
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=161 data=b'c&\x00' length=3 fcs=162>
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO bindRsp tsn: 250 {'srcaddr': 0x2663, 'status': 0}
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 250 bindRsp
app_1        | 2020-06-12 18:17:29 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message bindRsp
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0300]: bound 'light_color' cluster: Status.SUCCESS
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0300]: finished channel configuration
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0000]: 'async_configure' stage succeeded
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x1000]: 'async_configure' stage succeeded
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0008]: 'async_configure' stage succeeded
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0006]: 'async_configure' stage succeeded
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0019]: 'async_configure' stage succeeded
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0300]: 'async_configure' stage succeeded
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x2663](ZBT-Remote-ALL-RGBW): completed configuration
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x2663](ZBT-Remote-ALL-RGBW): stored in registry: ZhaDeviceEntry(name='MLI ZBT-Remote-ALL-RGBW', ieee='00:15:8d:00:01:fe:02:f9', last_seen=1591978649.2014177)
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy.device] [0x2663] Extending timeout for 0xfc request
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0x2663, 260, 3, 1, 1, 252, b'\x01\xfc@\x02\x00', True, False)
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.api] --> SREQ AF dataRequest tsn: 252 {'dstaddr': 9827, 'destendpoint': 1, 'srcendpoint': 1, 'clusterid': 3, 'transid': 253, 'options': 0, 'radius': 30, 'len': 5, 'data': b'\x01\xfc@\x02\x00'}
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x0f$\x01c&\x01\x01\x03\x00\xfd\x00\x1e\x05\x01\xfc@\x02\x005'
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.AF command_id=1 data=b'\x00' length=1 fcs=100>
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP AF dataRequest tsn: None {'status': 0}
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=128 data=b'\x00\x01\xfd' length=3 fcs=59>
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF dataConfirm tsn: None {'status': 0, 'endpoint': 1, 'transid': 253}
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: dataConfirm
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=196 data=b'c&\x01\x88\x85' length=5 fcs=205>
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO srcRtgInd tsn: None {'dstaddr': 0x2663, 'relaycount': 1, 'relaylist': [34184]}
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: srcRtgInd
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=129 data=b'\x00\x00\x03\x00c&\x01\x01\x00\x1c\x00d\xd1%\x00\x00\x05\x18\xfc\x0b@\x00\x88\x85\x1c' length=25 fcs=173>
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF incomingMsg tsn: None {'groupid': 0, 'clusterid': 3, 'srcaddr': 0x2663, 'srcendpoint': 1, 'dstendpoint': 1, 'wasbroadcast': 0, 'linkquality': 28, 'securityuse': 0, 'timestamp': 2478436, 'transseqnumber': 0, 'len': 5, 'data': b'\x18\xfc\x0b@\x00'}
app_1        | 2020-06-12 18:17:29 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message incomingMsg
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0003] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=252 command_id=Command.Default_Response>
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0003]: executed 'trigger_effect' command with args: '(2, 0)' kwargs: '{}' result: [64, <Status.SUCCESS: 0>]
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x2663](ZBT-Remote-ALL-RGBW): started initialization
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:ZDO](ZBT-Remote-ALL-RGBW): 'async_initialize' stage succeeded
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy.device] [0x2663] Extending timeout for 0xfe request
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0x2663, 260, 0, 1, 1, 254, b'\x00\xfe\x00\x07\x00', True, False)
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.api] --> SREQ AF dataRequest tsn: 254 {'dstaddr': 9827, 'destendpoint': 1, 'srcendpoint': 1, 'clusterid': 0, 'transid': 255, 'options': 0, 'radius': 30, 'len': 5, 'data': b'\x00\xfe\x00\x07\x00'}
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x0f$\x01c&\x01\x01\x00\x00\xff\x00\x1e\x05\x00\xfe\x00\x07\x00r'
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x1000]: initializing channel: from_cache: False
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0008]: initializing channel: from_cache: False
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0006]: initializing channel: from_cache: False
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0019]: initializing channel: from_cache: False
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0300]: initializing channel: from_cache: False
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.AF command_id=1 data=b'\x00' length=1 fcs=100>
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP AF dataRequest tsn: None {'status': 0}
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=128 data=b'\x00\x01\xff' length=3 fcs=57>
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF dataConfirm tsn: None {'status': 0, 'endpoint': 1, 'transid': 255}
app_1        | 2020-06-12 18:17:29 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: dataConfirm
app_1        | 2020-06-12 18:17:30 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=196 data=b'c&\x01\x88\x85' length=5 fcs=205>
app_1        | 2020-06-12 18:17:30 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO srcRtgInd tsn: None {'dstaddr': 0x2663, 'relaycount': 1, 'relaylist': [34184]}
app_1        | 2020-06-12 18:17:30 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: srcRtgInd
app_1        | 2020-06-12 18:17:30 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=129 data=b'\x00\x00\x00\x00c&\x01\x01\x00\x1a\x00\x80\xdd%\x00\x00\x08\x18\xfe\x01\x07\x00\x000\x03\x88\x85\x1c' length=28 fcs=52>
app_1        | 2020-06-12 18:17:30 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF incomingMsg tsn: None {'groupid': 0, 'clusterid': 0, 'srcaddr': 0x2663, 'srcendpoint': 1, 'dstendpoint': 1, 'wasbroadcast': 0, 'linkquality': 26, 'securityuse': 0, 'timestamp': 2481536, 'transseqnumber': 0, 'len': 8, 'data': b'\x18\xfe\x01\x07\x00\x000\x03'}
app_1        | 2020-06-12 18:17:30 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message incomingMsg
app_1        | 2020-06-12 18:17:30 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=254 command_id=Command.Read_Attributes_rsp>
app_1        | 2020-06-12 18:17:30 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0000]: initializing channel: from_cache: False
app_1        | 2020-06-12 18:17:30 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0000]: 'async_initialize' stage succeeded
app_1        | 2020-06-12 18:17:30 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x1000]: 'async_initialize' stage succeeded
app_1        | 2020-06-12 18:17:30 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0008]: 'async_initialize' stage succeeded
app_1        | 2020-06-12 18:17:30 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0006]: 'async_initialize' stage succeeded
app_1        | 2020-06-12 18:17:30 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0019]: 'async_initialize' stage succeeded
app_1        | 2020-06-12 18:17:30 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x2663:1:0x0300]: 'async_initialize' stage succeeded
app_1        | 2020-06-12 18:17:30 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x2663](ZBT-Remote-ALL-RGBW): power source: Battery or Unknown
app_1        | 2020-06-12 18:17:30 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x2663](ZBT-Remote-ALL-RGBW): completed initialization

Standby button (it can be used to turn the lamp on and off):

app_1        | 2020-06-12 18:20:58 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=129 data=b'\x04@\x06\x00c&\x01\x01\x00\x1f\x00\x9e\xc4/\x00\x00\x03\x11\x14\x00\x88\x85\x1c' length=23 fcs=168>
app_1        | 2020-06-12 18:20:58 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF incomingMsg tsn: None {'groupid': 16388, 'clusterid': 6, 'srcaddr': 0x2663, 'srcendpoint': 1, 'dstendpoint': 1, 'wasbroadcast': 0, 'linkquality': 31, 'securityuse': 0, 'timestamp': 3130526, 'transseqnumber': 0, 'len': 3, 'data': b'\x11\x14\x00'}
app_1        | 2020-06-12 18:20:58 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message incomingMsg
app_1        | 2020-06-12 18:20:58 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=CLUSTER_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=20 command_id=0>
app_1        | 2020-06-12 18:20:58 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0006] ZCL request 0x0000: []
app_1        | 2020-06-12 18:20:58 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0006] No handler for cluster command 0
app_1        | 2020-06-12 18:20:58 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event zha_event[L]: device_ieee=00:15:8d:00:01:fe:02:f9, unique_id=00:15:8d:00:01:fe:02:f9:1:0x0006, endpoint_id=1, cluster_id=6, command=off, args=[]>

White control: warmer

app_1        | 2020-06-12 18:23:19 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=129 data=b'\x04@\x00\x03c&\x01\x01\x00\x1c\x00\xf1y6\x00\x00\t\x11\x16\nr\x01\n\x00\x00\x00\x88\x85\x1c' length=29 fcs=20>
app_1        | 2020-06-12 18:23:19 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF incomingMsg tsn: None {'groupid': 16388, 'clusterid': 768, 'srcaddr': 0x2663, 'srcendpoint': 1, 'dstendpoint': 1, 'wasbroadcast': 0, 'linkquality': 28, 'securityuse': 0, 'timestamp': 3570161, 'transseqnumber': 0, 'len': 9, 'data': b'\x11\x16\nr\x01\n\x00\x00\x00'}
app_1        | 2020-06-12 18:23:19 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message incomingMsg
app_1        | 2020-06-12 18:23:19 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=CLUSTER_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=22 command_id=10>
app_1        | 2020-06-12 18:23:19 WARNING (MainThread) [zigpy.zcl] [0x2663:1:0x0300] Data remains after deserializing ZCL frame
app_1        | 2020-06-12 18:23:19 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0300] ZCL request 0x000a: [370, 10]
app_1        | 2020-06-12 18:23:19 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0300] No handler for cluster command 10
app_1        | 2020-06-12 18:23:19 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event zha_event[L]: device_ieee=00:15:8d:00:01:fe:02:f9, unique_id=00:15:8d:0
![tint_remote](https://user-images.githubusercontent.com/696839/84524512-6379dc00-acda-11ea-8de0-d8f969e72eb9.jpeg)
0:01:fe:02:f9:1:0x0300, endpoint_id=1, cluster_id=768, command=move_to_color_temp, args=[370, 10]>

White control: cooler

app_1        | 2020-06-12 18:32:55 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=129 data=b'\x04@\x00\x03c&\x01\x01\x00\x15\x00\xdc\xf1Q\x00\x00\t\x11\x18\n\xc8\x00\n\x00\x00\x00\x88\x85\x1c' length=29 fcs=106>
app_1        | 2020-06-12 18:32:55 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF incomingMsg tsn: None {'groupid': 16388, 'clusterid': 768, 'srcaddr': 0x2663, 'srcendpoint': 1, 'dstendpoint': 1, 'wasbroadcast': 0, 'linkquality': 21, 'securityuse': 0, 'timestamp': 5370332, 'transseqnumber': 0, 'len': 9, 'data': b'\x11\x18\n\xc8\x00\n\x00\x00\x00'}
app_1        | 2020-06-12 18:32:55 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message incomingMsg
app_1        | 2020-06-12 18:32:55 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=CLUSTER_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=24 command_id=10>
app_1        | 2020-06-12 18:32:55 WARNING (MainThread) [zigpy.zcl] [0x2663:1:0x0300] Data remains after deserializing ZCL frame
app_1        | 2020-06-12 18:32:55 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0300] ZCL request 0x000a: [200, 10]
app_1        | 2020-06-12 18:32:55 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0300] No handler for cluster command 10
app_1        | 2020-06-12 18:32:55 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event zha_event[L]: device_ieee=00:15:8d:00:01:fe:02:f9, unique_id=00:15:8d:00:01:fe:02:f9:1:0x0300, endpoint_id=1, cluster_id=768, command=move_to_color_temp, args=[200, 10]>

Brightness control: dimmer

app_1        | 2020-06-12 18:33:19 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=129 data=b'\x04@\x08\x00c&\x01\x01\x00\x17\x00U\x1bS\x00\x00\t\x11\x19\x02\x01+\n\x00\x00\x08\x88\x85\x1c' length=29 fcs=225>
app_1        | 2020-06-12 18:33:19 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF incomingMsg tsn: None {'groupid': 16388, 'clusterid': 8, 'srcaddr': 0x2663, 'srcendpoint': 1, 'dstendpoint': 1, 'wasbroadcast': 0, 'linkquality': 23, 'securityuse': 0, 'timestamp': 5446485, 'transseqnumber': 0, 'len': 9, 'data': b'\x11\x19\x02\x01+\n\x00\x00\x08'}
app_1        | 2020-06-12 18:33:19 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message incomingMsg
app_1        | 2020-06-12 18:33:19 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=CLUSTER_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=25 command_id=2>
app_1        | 2020-06-12 18:33:19 WARNING (MainThread) [zigpy.zcl] [0x2663:1:0x0008] Data remains after deserializing ZCL frame
app_1        | 2020-06-12 18:33:19 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0008] ZCL request 0x0002: [1, 43, 10]
app_1        | 2020-06-12 18:33:19 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0008] No handler for cluster command 2
app_1        | 2020-06-12 18:33:19 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event zha_event[L]: device_ieee=00:15:8d:00:01:fe:02:f9, unique_id=00:15:8d:00:01:fe:02:f9:1:0x0008, endpoint_id=1, cluster_id=8, command=step, args=[1, 43, 10]>

Brightness control: brighter

app_1        | 2020-06-12 18:33:48 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=129 data=b'\x04@\x08\x00c&\x01\x01\x00\x12\x00\xb5\x81T\x00\x00\t\x11\x1a\x02\x00+\n\x00\x00\x00\x88\x85\x1c' length=29 fcs=147>
app_1        | 2020-06-12 18:33:48 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF incomingMsg tsn: None {'groupid': 16388, 'clusterid': 8, 'srcaddr': 0x2663, 'srcendpoint': 1, 'dstendpoint': 1, 'wasbroadcast': 0, 'linkquality': 18, 'securityuse': 0, 'timestamp': 5538229, 'transseqnumber': 0, 'len': 9, 'data': b'\x11\x1a\x02\x00+\n\x00\x00\x00'}
app_1        | 2020-06-12 18:33:48 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message incomingMsg
app_1        | 2020-06-12 18:33:48 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=CLUSTER_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=26 command_id=2>
app_1        | 2020-06-12 18:33:48 WARNING (MainThread) [zigpy.zcl] [0x2663:1:0x0008] Data remains after deserializing ZCL frame
app_1        | 2020-06-12 18:33:48 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0008] ZCL request 0x0002: [0, 43, 10]
app_1        | 2020-06-12 18:33:48 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0008] No handler for cluster command 2
app_1        | 2020-06-12 18:33:48 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event zha_event[L]: device_ieee=00:15:8d:00:01:fe:02:f9, unique_id=00:15:8d:00:01:fe:02:f9:1:0x0008, endpoint_id=1, cluster_id=8, command=step, args=[0, 43, 10]>

"Working light" scene button:

app_1        | 2020-06-12 18:34:14 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=129 data=b'\x04@\x00\x00c&\x01\x01\x00\x17\x00i\xbcU\x00\x00\t\x14\x1b\x12\x1b\x02\x05@ \x03\x88\x85\x1c' length=29 fcs=52>
app_1        | 2020-06-12 18:34:14 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF incomingMsg tsn: None {'groupid': 16388, 'clusterid': 0, 'srcaddr': 0x2663, 'srcendpoint': 1, 'dstendpoint': 1, 'wasbroadcast': 0, 'linkquality': 23, 'securityuse': 0, 'timestamp': 5618793, 'transseqnumber': 0, 'len': 9, 'data': b'\x14\x1b\x12\x1b\x02\x05@ \x03'}
app_1        | 2020-06-12 18:34:14 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message incomingMsg
app_1        | 2020-06-12 18:34:14 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=True is_reply=False disable_default_response=True> manufacturer=4635 tsn=27 command_id=Command.Write_Attributes>
app_1        | 2020-06-12 18:34:14 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0000] ZCL request 0x0002: [[<Attribute attrid=16389 value=<TypeValue type=uint8_t, value=3>>]]

"Sunset" scene button:

app_1        | 2020-06-12 18:34:45 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=129 data=b'\x04@\x00\x00c&\x01\x01\x00\x17\x00c1W\x00\x00\t\x14\x1b\x12\x1c\x02\x05@ \x01\x88\x85\x1c' length=29 fcs=180>
app_1        | 2020-06-12 18:34:45 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF incomingMsg tsn: None {'groupid': 16388, 'clusterid': 0, 'srcaddr': 0x2663, 'srcendpoint': 1, 'dstendpoint': 1, 'wasbroadcast': 0, 'linkquality': 23, 'securityuse': 0, 'timestamp': 5714275, 'transseqnumber': 0, 'len': 9, 'data': b'\x14\x1b\x12\x1c\x02\x05@ \x01'}
app_1        | 2020-06-12 18:34:45 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message incomingMsg
app_1        | 2020-06-12 18:34:45 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=True is_reply=False disable_default_response=True> manufacturer=4635 tsn=28 command_id=Command.Write_Attributes>
app_1        | 2020-06-12 18:34:45 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0000] ZCL request 0x0002: [[<Attribute attrid=16389 value=<TypeValue type=uint8_t, value=1>>]]

"Party" scene button:

app_1        | 2020-06-12 18:35:05 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=129 data=b'\x04@\x00\x00c&\x01\x01\x00\x17\x00\xdc+X\x00\x00\t\x14\x1b\x12\x1d\x02\x05@ \x02\x88\x85\x1c' length=29 fcs=28>
app_1        | 2020-06-12 18:35:05 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF incomingMsg tsn: None {'groupid': 16388, 'clusterid': 0, 'srcaddr': 0x2663, 'srcendpoint': 1, 'dstendpoint': 1, 'wasbroadcast': 0, 'linkquality': 23, 'securityuse': 0, 'timestamp': 5778396, 'transseqnumber': 0, 'len': 9, 'data': b'\x14\x1b\x12\x1d\x02\x05@ \x02'}
app_1        | 2020-06-12 18:35:05 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message incomingMsg
app_1        | 2020-06-12 18:35:05 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=True is_reply=False disable_default_response=True> manufacturer=4635 tsn=29 command_id=Command.Write_Attributes>
app_1        | 2020-06-12 18:35:05 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0000] ZCL request 0x0002: [[<Attribute attrid=16389 value=<TypeValue type=uint8_t, value=2>>]]

"Night lights" scene button:

app_1        | 2020-06-12 18:35:22 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=129 data=b'\x04@\x00\x00c&\x01\x01\x00\x17\x00j\xf6X\x00\x00\t\x14\x1b\x12\x1e\x02\x05@ \x06\x88\x85\x1c' length=29 fcs=112>
app_1        | 2020-06-12 18:35:22 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF incomingMsg tsn: None {'groupid': 16388, 'clusterid': 0, 'srcaddr': 0x2663, 'srcendpoint': 1, 'dstendpoint': 1, 'wasbroadcast': 0, 'linkquality': 23, 'securityuse': 0, 'timestamp': 5830250, 'transseqnumber': 0, 'len': 9, 'data': b'\x14\x1b\x12\x1e\x02\x05@ \x06'}
app_1        | 2020-06-12 18:35:22 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message incomingMsg
app_1        | 2020-06-12 18:35:22 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=True is_reply=False disable_default_response=True> manufacturer=4635 tsn=30 command_id=Command.Write_Attributes>
app_1        | 2020-06-12 18:35:22 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0000] ZCL request 0x0002: [[<Attribute attrid=16389 value=<TypeValue type=uint8_t, value=6>>]]

"Campfire" scene button:

app_1        | 2020-06-12 18:35:39 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=129 data=b'\x04@\x00\x00c&\x01\x01\x00\x17\x00+\xcaY\x00\x00\t\x14\x1b\x12\x1f\x02\x05@ \x04\x88\x85\x1c' length=29 fcs=15>
app_1        | 2020-06-12 18:35:39 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF incomingMsg tsn: None {'groupid': 16388, 'clusterid': 0, 'srcaddr': 0x2663, 'srcendpoint': 1, 'dstendpoint': 1, 'wasbroadcast': 0, 'linkquality': 23, 'securityuse': 0, 'timestamp': 5884459, 'transseqnumber': 0, 'len': 9, 'data': b'\x14\x1b\x12\x1f\x02\x05@ \x04'}
app_1        | 2020-06-12 18:35:39 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message incomingMsg
app_1        | 2020-06-12 18:35:39 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=True is_reply=False disable_default_response=True> manufacturer=4635 tsn=31 command_id=Command.Write_Attributes>
app_1        | 2020-06-12 18:35:39 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0000] ZCL request 0x0002: [[<Attribute attrid=16389 value=<TypeValue type=uint8_t, value=4>>]]

"Romantic" scene button:

app_1        | 2020-06-12 18:36:13 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=129 data=b'\x04@\x00\x00c&\x01\x01\x00\x17\x00Xd[\x00\x00\t\x14\x1b\x12 \x02\x05@ \x05\x88\x85\x1c' length=29 fcs=238>
app_1        | 2020-06-12 18:36:13 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF incomingMsg tsn: None {'groupid': 16388, 'clusterid': 0, 'srcaddr': 0x2663, 'srcendpoint': 1, 'dstendpoint': 1, 'wasbroadcast': 0, 'linkquality': 23, 'securityuse': 0, 'timestamp': 5989464, 'transseqnumber': 0, 'len': 9, 'data': b'\x14\x1b\x12 \x02\x05@ \x05'}
app_1        | 2020-06-12 18:36:13 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message incomingMsg
app_1        | 2020-06-12 18:36:13 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=True is_reply=False disable_default_response=True> manufacturer=4635 tsn=32 command_id=Command.Write_Attributes>
app_1        | 2020-06-12 18:36:13 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0000] ZCL request 0x0002: [[<Attribute attrid=16389 value=<TypeValue type=uint8_t, value=5>>]]

The 'Colour control' consists of 4 areas that you can press (let's call them West(light blue), East(red), North(purple) and South(green)). When you press one of them your current color is moved towards that color. Again a better description can be found in this comment and some later comments.

West(light blue)

app_1        | 2020-06-12 18:42:51 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=129 data=b'\x04@\x00\x03c&\x01\x01\x00\x1a\x00\xe5Zn\x00\x00\x0b\x11"\x07\x0fM\x0e&\x00\x00\x00\x00\x88\x85\x1c' length=31 fcs=87>
app_1        | 2020-06-12 18:42:51 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF incomingMsg tsn: None {'groupid': 16388, 'clusterid': 768, 'srcaddr': 0x2663, 'srcendpoint': 1, 'dstendpoint': 1, 'wasbroadcast': 0, 'linkquality': 26, 'securityuse': 0, 'timestamp': 7232229, 'transseqnumber': 0, 'len': 11, 'data': b'\x11"\x07\x0fM\x0e&\x00\x00\x00\x00'}
app_1        | 2020-06-12 18:42:51 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message incomingMsg
app_1        | 2020-06-12 18:42:51 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=CLUSTER_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=34 command_id=7>
app_1        | 2020-06-12 18:42:51 WARNING (MainThread) [zigpy.zcl] [0x2663:1:0x0300] Data remains after deserializing ZCL frame
app_1        | 2020-06-12 18:42:51 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0300] ZCL request 0x0007: [19727, 9742, 0]
app_1        | 2020-06-12 18:42:51 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0300] No handler for cluster command 7
app_1        | 2020-06-12 18:42:51 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event zha_event[L]: device_ieee=00:15:8d:00:01:fe:02:f9, unique_id=00:15:8d:00:01:fe:02:f9:1:0x0300, endpoint_id=1, cluster_id=768, command=move_to_color, args=[19727, 9742, 0]>

East(red)

app_1        | 2020-06-12 18:43:34 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=129 data=b'\x04@\x00\x03c&\x01\x01\x00\x17\x00\x95qp\x00\x00\x0b\x11#\x07\x8cV\xa7)\x00\x00\x00\x00\x88\x85\x1c' length=31 fcs=32>
app_1        | 2020-06-12 18:43:34 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF incomingMsg tsn: None {'groupid': 16388, 'clusterid': 768, 'srcaddr': 0x2663, 'srcendpoint': 1, 'dstendpoint': 1, 'wasbroadcast': 0, 'linkquality': 23, 'securityuse': 0, 'timestamp': 7369109, 'transseqnumber': 0, 'len': 11, 'data': b'\x11#\x07\x8cV\xa7)\x00\x00\x00\x00'}
app_1        | 2020-06-12 18:43:34 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message incomingMsg
app_1        | 2020-06-12 18:43:34 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=CLUSTER_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=35 command_id=7>
app_1        | 2020-06-12 18:43:34 WARNING (MainThread) [zigpy.zcl] [0x2663:1:0x0300] Data remains after deserializing ZCL frame
app_1        | 2020-06-12 18:43:34 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0300] ZCL request 0x0007: [22156, 10663, 0]
app_1        | 2020-06-12 18:43:34 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0300] No handler for cluster command 7
app_1        | 2020-06-12 18:43:34 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event zha_event[L]: device_ieee=00:15:8d:00:01:fe:02:f9, unique_id=00:15:8d:00:01:fe:02:f9:1:0x0300, endpoint_id=1, cluster_id=768, command=move_to_color, args=[22156, 10663, 0]>

North(purple)

app_1        | 2020-06-12 18:43:47 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=129 data=b'\x04@\x00\x03c&\x01\x01\x00\x1a\x00\x92\x06q\x00\x00\x0b\x11$\x07\x0fM\x0e&\x00\x00\x00\x00\x88\x85\x1c' length=31 fcs=101>
app_1        | 2020-06-12 18:43:47 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF incomingMsg tsn: None {'groupid': 16388, 'clusterid': 768, 'srcaddr': 0x2663, 'srcendpoint': 1, 'dstendpoint': 1, 'wasbroadcast': 0, 'linkquality': 26, 'securityuse': 0, 'timestamp': 7407250, 'transseqnumber': 0, 'len': 11, 'data': b'\x11$\x07\x0fM\x0e&\x00\x00\x00\x00'}
app_1        | 2020-06-12 18:43:47 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message incomingMsg
app_1        | 2020-06-12 18:43:47 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=CLUSTER_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=36 command_id=7>
app_1        | 2020-06-12 18:43:47 WARNING (MainThread) [zigpy.zcl] [0x2663:1:0x0300] Data remains after deserializing ZCL frame
app_1        | 2020-06-12 18:43:47 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0300] ZCL request 0x0007: [19727, 9742, 0]
app_1        | 2020-06-12 18:43:47 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0300] No handler for cluster command 7
app_1        | 2020-06-12 18:43:47 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event zha_event[L]: device_ieee=00:15:8d:00:01:fe:02:f9, unique_id=00:15:8d:00:01:fe:02:f9:1:0x0300, endpoint_id=1, cluster_id=768, command=move_to_color, args=[19727, 9742, 0]>

South(green)

app_1        | 2020-06-12 18:44:02 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=129 data=b'\x04@\x00\x03c&\x01\x01\x00\x1a\x00\x96\xc9q\x00\x00\x0b\x11%\x07\x8cV\xa7)\x00\x00\x00\x00\x88\x85\x1c' length=31 fcs=145>
app_1        | 2020-06-12 18:44:02 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF incomingMsg tsn: None {'groupid': 16388, 'clusterid': 768, 'srcaddr': 0x2663, 'srcendpoint': 1, 'dstendpoint': 1, 'wasbroadcast': 0, 'linkquality': 26, 'securityuse': 0, 'timestamp': 7457174, 'transseqnumber': 0, 'len': 11, 'data': b'\x11%\x07\x8cV\xa7)\x00\x00\x00\x00'}
app_1        | 2020-06-12 18:44:02 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message incomingMsg
app_1        | 2020-06-12 18:44:02 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=CLUSTER_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=37 command_id=7>
app_1        | 2020-06-12 18:44:02 WARNING (MainThread) [zigpy.zcl] [0x2663:1:0x0300] Data remains after deserializing ZCL frame
app_1        | 2020-06-12 18:44:03 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0300] ZCL request 0x0007: [22156, 10663, 0]
app_1        | 2020-06-12 18:44:03 DEBUG (MainThread) [zigpy.zcl] [0x2663:1:0x0300] No handler for cluster command 7
app_1        | 2020-06-12 18:44:03 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event zha_event[L]: device_ieee=00:15:8d:00:01:fe:02:f9, unique_id=00:15:8d:00:01:fe:02:f9:1:0x0300, endpoint_id=1, cluster_id=768, command=move_to_color, args=[22156, 10663, 0]>

Group button, doesn't show any activity in the debug log.

I think that is all :). Is there any more I can help with?

Adminiuga commented 4 years ago

For the quirks:

Node Descriptor: <Optional byte1=2 byte2=64 mac_capability_flags=128 manufacturer_code=4635 maximum_buffer_size=127 maximum_incoming_transfer_size=100 server_mask=11264 maximum_outgoing_transfer_size=100 descriptor_capability_field=0>
Discovered endpoints: [1]
Discovered endpoint information: <Optional endpoint=1 profile=260 device_type=2048 device_version=1 input_clusters=[0, 3, 4096] output_clusters=[4, 3, 6, 8, 768, 4096, 25, 0]>
Manufacturer: MLI
Model: ZBT-Remote-ALL-RGBW

Adminiuga commented 4 years ago

Out of the box, for things other than the "scene" button you could use zha_event for automations. Would need a quirk for the "scenes" button and need to figure out how to translate the attribute write request into something more digestable.

stale[bot] commented 4 years ago

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

home-assistant / core