Problem
When I add Hue motion sensor (SML001) thru ZHA integration, pairing process ends, but none of the sensor function work.
Illuminance, temperature, power is "unknown" state, occupancy is always "clear".
I noticed something strange during pairing operation. When I start adding new devices, after few minutes searching stops, logs stops, but when I only hit "search again", then process is continuing, new entry logs came's up.
Reset and reconfig doesn't help. Tried at HA 111.0, 111.4 and 112.0 version.
Adminiuga sugested this could be a zigpy-cc problem.
https://github.com/home-assistant/core/issues/36162
Environment
![86395172-1ae18d00-bca0-11ea-9c84-d3b2e5721700](https://user-images.githubusercontent.com/67756947/86518502-7ba0cf00-be32-11ea-91bc-6e339cdcb027.png)
Zigbee module : CC2531 USB
ZHA log
Device 0xcf1a (00:17:88:01:06:f7:e9:9d) joined the network
[0xcf1a:zdo] ZDO request ZDOCmd.Device_annce: [0xcf1a, 00:17:88:01:06:f7:e9:9d, 128]
[0xcf1a] Requesting 'Node Descriptor'
Tries remaining: 2
[0xcf1a] Extending timeout for 0x03 request
[0xcf1a] Node Descriptor:
[0xcf1a] Discovering endpoints
Tries remaining: 3
[0xcf1a] Extending timeout for 0x05 request
[0xcf1a] Discovered endpoints: [2, 1]
[0xcf1a:2] Discovering endpoint information
Tries remaining: 3
[0xcf1a] Extending timeout for 0x07 request
[0xcf1a:2] Discovered endpoint information: <Optional endpoint=2 profile=260 device_type=263 device_version=0 input_clusters=[0, 1, 3, 1030, 1024, 1026] output_clusters=[25]>
[0xcf1a] Extending timeout for 0x09 request
[0xcf1a] Extending timeout for 0x0b request
[0xcf1a] Extending timeout for 0x0d request
[0xcf1a:2] Manufacturer: None
[0xcf1a:2] Model: None
[0xcf1a:1] Discovering endpoint information
Tries remaining: 3
[0xcf1a] Extending timeout for 0x0f request
[0xcf1a:1] Discovered endpoint information: <Optional endpoint=1 profile=49246 device_type=2128 device_version=2 input_clusters=[0] output_clusters=[0, 3, 4, 6, 8, 768, 5]>
[0xcf1a] Extending timeout for 0x11 request
[0xcf1a:1:0x0000] ZCL deserialize: <ZCLHeader frame_control= manufacturer=None tsn=17 command_id=Command.Read_Attributes_rsp>
[0xcf1a:1] Manufacturer: Philips
[0xcf1a:1] Model: SML001
Checking quirks for Philips SML001 (00:17:88:01:06:f7:e9:9d)
Considering <class 'bellows.zigbee.application.EZSPCoordinator'>
Fail because endpoint list mismatch: {1} {1, 2}
Considering <class 'zhaquirks.gledopto.soposhgu10.SoposhGU10'>
Fail because endpoint list mismatch: {11, 13} {1, 2}
Considering <class 'zhaquirks.lutron.lzl4bwhl01remote.LutronLZL4BWHL01Remote2'>
Fail because endpoint list mismatch: {1} {1, 2}
Considering <class 'zhaquirks.netvox.z308e3ed.Z308E3ED'>
Fail because endpoint list mismatch: {1} {1, 2}
Considering <class 'zhaquirks.osram.a19twhite.A19TunableWhite'>
Fail because endpoint list mismatch: {3} {1, 2}
Considering <class 'zhaquirks.philips.rom001.PhilipsROM001'>
Fail because endpoint list mismatch: {1} {1, 2}
Considering <class 'zhaquirks.philips.rwl020.PhilipsRWL020'>
Fail because device_type mismatch on at least one endpoint
Considering <class 'zhaquirks.philips.rwl021.PhilipsRWL021'>
Fail because device_type mismatch on at least one endpoint
Considering <class 'zhaquirks.smartthings.multi.SmartthingsMultiPurposeSensor'>
Fail because endpoint list mismatch: {1} {1, 2}
Considering <class 'zhaquirks.smartthings.tag_v4.SmartThingsTagV4'>
Fail because endpoint list mismatch: {1} {1, 2}
Considering <class 'zhaquirks.xbee.xbee3_io.XBee3Sensor'>
Fail because endpoint list mismatch: {232, 230} {1, 2}
Considering <class 'zhaquirks.xbee.xbee_io.XBeeSensor'>
Fail because endpoint list mismatch: {232, 230} {1, 2}
Considering <class 'zhaquirks.xiaomi.mija.smoke.MijiaHoneywellSmokeDetectorSensor'>
Fail because endpoint list mismatch: {1} {1, 2}
device - 0xcf1a:00:17:88:01:06:f7:e9:9d entering async_device_initialized - is_new_join: True
device - 0xcf1a:00:17:88:01:06:f7:e9:9d has joined the ZHA zigbee network
0xcf1a: started configuration
0xcf1a:ZDO: 'async_configure' stage succeeded
[0xcf1a] Extending timeout for 0x13 request
[0xcf1a] Extending timeout for 0x15 request
[0xcf1a] Extending timeout for 0x17 request
[0xcf1a:1:0x0000]: bound 'basic' cluster: Status.SUCCESS
[0xcf1a:1:0x0000]: finished channel configuration
[0xcf1a] Extending timeout for 0x19 request
[0xcf1a:1:0x0006]: bound 'on_off' cluster: Status.SUCCESS
[0xcf1a:1:0x0006]: finished channel configuration
[0xcf1a] Extending timeout for 0x1b request
[0xcf1a:1:0x0008]: bound 'level' cluster: Status.SUCCESS
[0xcf1a:1:0x0008]: finished channel configuration
[0xcf1a] Extending timeout for 0x1d request
[0xcf1a:1:0x0000] ZCL deserialize: <ZCLHeader frame_control= manufacturer=None tsn=25 command_id=Command.Read_Attributes_rsp>
[0xcf1a:1:0x0000]: initializing channel: from_cache: False
[0xcf1a] Extending timeout for 0x1f request
[0xcf1a:1:0x0006]: bound 'on_off' cluster: Status.SUCCESS
[0xcf1a:1:0x0006]: finished channel configuration
[0xcf1a] Extending timeout for 0x21 request
[0xcf1a:1:0x0005]: bound 'scenes' cluster: Status.SUCCESS
[0xcf1a:1:0x0005]: finished channel configuration
[0xcf1a] Extending timeout for 0x23 request
[0xcf1a:1:0x0300]: bound 'light_color' cluster: Status.SUCCESS
[0xcf1a:1:0x0300]: finished channel configuration
[0xcf1a] Extending timeout for 0x25 request
[0xcf1a:1:0x0000]: 'async_configure' stage succeeded
[0xcf1a:1:0x0006]: 'async_configure' stage succeeded
[0xcf1a:1:0x0008]: 'async_configure' stage succeeded
[0xcf1a:1:0x0006]: 'async_configure' stage succeeded
[0xcf1a:1:0x0005]: 'async_configure' stage succeeded
[0xcf1a:1:0x0300]: 'async_configure' stage succeeded
[0xcf1a:2:0x0001]: bound 'power' cluster: Status.SUCCESS
[0xcf1a] Extending timeout for 0x27 request
[0xcf1a:2:0x0402]: bound 'temperature' cluster: Status.SUCCESS
[0xcf1a] Extending timeout for 0x29 request
[0xcf1a:2:0x0400]: bound 'illuminance' cluster: Status.SUCCESS
[0xcf1a] Extending timeout for 0x2b request
[0xcf1a:1:0x0006] ZCL deserialize: <ZCLHeader frame_control= manufacturer=None tsn=0 command_id=66>
[0xcf1a:1:0x0006] ZCL request 0x0042: [0, 3000, 0]
[0xcf1a:1:0x0006] No handler for cluster command 66
[0xcf1a:1:0x0006]: received 'on_with_timed_off' command with [0, 3000, 0] args on cluster_id '6' tsn '0'
SEARCHING NEW DEVICE STOPS HERE
BUT WHEN I CLICK ON "SEARCH AGAIN" BUTTON... IT CONTINUES...
[0xcf1a:2:0x0001]: failed to get attributes '['battery_size', 'battery_percentage_remaining', 'battery_voltage', 'battery_quantity']' on 'power' cluster:
[0xcf1a:2:0x0001]: initializing channel: from_cache: False
[0xcf1a] Extending timeout for 0x49 request
[0xcf1a:2:0x0402]: failed to get attributes '['measured_value']' on 'temperature' cluster:
[0xcf1a:2:0x0406]: initializing channel: from_cache: False
[0xcf1a] Extending timeout for 0x4b request
[0xcf1a:2:0x0400]: failed to get attributes '['measured_value']' on 'illuminance' cluster:
[0xcf1a] Extending timeout for 0x4d request
[0xcf1a:2:0x0001]: failed to get attributes '['battery_voltage', 'battery_percentage_remaining']' on 'power' cluster:
[0xcf1a:2:0x0019]: initializing channel: from_cache: False
[0xcf1a:2:0x0406]: failed to get attributes '['occupancy']' on 'occupancy' cluster:
[0xcf1a:2:0x0000]: initializing channel: from_cache: False
[0xcf1a:2:0x0001]: 'async_initialize' stage succeeded
[0xcf1a:2:0x0402]: 'async_initialize' stage succeeded
[0xcf1a:2:0x0400]: 'async_initialize' stage succeeded
[0xcf1a:2:0x0406]: 'async_initialize' stage succeeded
[0xcf1a:2:0x0000]: 'async_initialize' stage succeeded
[0xcf1a:2:0x0019]: 'async_initialize' stage succeeded
0xcf1a: power source: Battery or Unknown
0xcf1a: completed initialization
HASS log
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.zigbee.application] broadcast (0, 54, 0, 0, 0, 0, 1, b'\x01<\x00', <BroadcastAddress.ALL_ROUTERS_AND_COORDINATOR: 65532>)
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO mgmtPermitJoinReq tsn: 1 {'addrmode': 15, 'dstaddr': 0xfffc, 'duration': 60, 'tcsignificance': 0}
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x05%6\x0f\xfc\xff<\x00&'
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=54 data=b'\x00' length=1 fcs=82>
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO mgmtPermitJoinReq tsn: None {'status': 0}
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO mgmtPermitJoinReq tsn: None {'addrmode': 15, 'dstaddr': <BroadcastAddress.ALL_ROUTERS_AND_COORDINATOR: 65532>, 'duration': 60, 'tcsignificance': 0}
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x05%6\x0f\xfc\xff<\x00&'
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=203 data=b'<' length=1 fcs=179>
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO permitJoinInd tsn: None {'duration': 60}
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.api] --> SREQ UTIL ledControl tsn: None {'ledid': 3, 'mode': <LedMode.On: 1>}
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.uart] Send: b"\xfe\x02'\n\x03\x01-"
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=54 data=b'\x00' length=1 fcs=82>
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO mgmtPermitJoinReq tsn: None {'status': 0}
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.UTIL command_id=10 data=b'\x00' length=1 fcs=108>
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP UTIL ledControl tsn: None {'status': 0}
2020-07-03 20:39:28 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>
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO mgmtPermitJoinRsp tsn: None {'srcaddr': 0x0000, 'status': 0}
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.api] --> SREQ UTIL ledControl tsn: None {'ledid': 3, 'mode': <LedMode.On: 1>}
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.uart] Send: b"\xfe\x02'\n\x03\x01-"
2020-07-03 20:39:28 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>
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO mgmtPermitJoinRsp tsn: None {'srcaddr': 0x0000, 'status': 0}
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.api] --> SREQ UTIL ledControl tsn: None {'ledid': 3, 'mode': <LedMode.On: 1>}
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.uart] Send: b"\xfe\x02'\n\x03\x01-"
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.UTIL command_id=10 data=b'\x00' length=1 fcs=108>
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP UTIL ledControl tsn: None {'status': 0}
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.UTIL command_id=10 data=b'\x00' length=1 fcs=108>
2020-07-03 20:39:28 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP UTIL ledControl tsn: None {'status': 0}
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=202 data=b'\x1a\xcf\x9d\xe9\xf7\x06\x01\x88\x17\x00\x00\x00' length=12 fcs=77>
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO tcDeviceInd tsn: None {'nwkaddr': 0xcf1a, 'extaddr': 00:17:88:01:06:f7:e9:9d, 'parentaddr': 0x0000}
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: tcDeviceInd
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=193 data=b'\x1a\xcf\x1a\xcf\x9d\xe9\xf7\x06\x01\x88\x17\x00\x80' length=13 fcs=18>
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO endDeviceAnnceInd tsn: 0 {'srcaddr': 0xcf1a, 'nwkaddr': 0xcf1a, 'ieeeaddr': 00:17:88:01:06:f7:e9:9d, 'capabilities': 128}
2020-07-03 20:39:32 INFO (MainThread) [zigpy_cc.zigbee.application] New device joined: 0xcf1a, 00:17:88:01:06:f7:e9:9d
2020-07-03 20:39:32 INFO (MainThread) [zigpy.application] Device 0xcf1a (00:17:88:01:06:f7:e9:9d) joined the network
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 0 endDeviceAnnceInd
2020-07-03 20:39:32 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message endDeviceAnnceInd
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy.zdo] [0xcf1a:zdo] ZDO request ZDOCmd.Device_annce: [0xcf1a, 00:17:88:01:06:f7:e9:9d, 128]
2020-07-03 20:39:32 INFO (MainThread) [zigpy.device] [0xcf1a] Requesting 'Node Descriptor'
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy.util] Tries remaining: 2
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x03 request
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 0, <ZDOCmd.Node_Desc_req: 2>, 0, 0, 3, b'\x03\x1a\xcf', True, False)
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy_cc.api] waiting for 3 nodeDescReq
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO nodeDescReq tsn: 3 {'dstaddr': 0xcf1a, 'nwkaddrofinterest': 0xcf1a}
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x04%\x02\x1a\xcf\x1a\xcf#'
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=2 data=b'\x00' length=1 fcs=102>
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO nodeDescReq tsn: None {'status': 0}
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=130 data=b'\x1a\xcf\x00\x1a\xcf\x02@\x80\x0b\x10Y?\x00\x00\x00?\x00\x00' length=18 fcs=85>
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO nodeDescRsp tsn: 3 {'srcaddr': 0xcf1a, 'status': 0, 'nwkaddr': 0xcf1a, 'logicaltype_cmplxdescavai_userdescavai': 2, 'apsflags_freqband': 64, 'maccapflags': 128, 'manufacturercode': 4107, 'maxbuffersize': 89, 'maxintransfersize': 63, 'servermask': 0, 'maxouttransfersize': 63, 'descriptorcap': 0}
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 3 nodeDescRsp
2020-07-03 20:39:32 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message nodeDescRsp
2020-07-03 20:39:32 INFO (MainThread) [zigpy.device] [0xcf1a] Node Descriptor:
2020-07-03 20:39:32 INFO (MainThread) [zigpy.device] [0xcf1a] Discovering endpoints
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x05 request
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 0, <ZDOCmd.Active_EP_req: 5>, 0, 0, 5, b'\x05\x1a\xcf', True, False)
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy_cc.api] waiting for 5 activeEpReq
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO activeEpReq tsn: 5 {'dstaddr': 0xcf1a, 'nwkaddrofinterest': 0xcf1a}
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x04%\x05\x1a\xcf\x1a\xcf$'
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=5 data=b'\x00' length=1 fcs=97>
2020-07-03 20:39:32 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO activeEpReq tsn: None {'status': 0}
2020-07-03 20:39:33 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=133 data=b'\x1a\xcf\x00\x1a\xcf\x02\x02\x01' length=8 fcs=201>
2020-07-03 20:39:33 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO activeEpRsp tsn: 5 {'srcaddr': 0xcf1a, 'status': 0, 'nwkaddr': 0xcf1a, 'activeepcount': 2, 'activeeplist': [2, 1]}
2020-07-03 20:39:33 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 5 activeEpRsp
2020-07-03 20:39:33 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message activeEpRsp
2020-07-03 20:39:33 INFO (MainThread) [zigpy.device] [0xcf1a] Discovered endpoints: [2, 1]
2020-07-03 20:39:33 INFO (MainThread) [zigpy.endpoint] [0xcf1a:2] Discovering endpoint information
2020-07-03 20:39:33 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2020-07-03 20:39:33 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x07 request
2020-07-03 20:39:33 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 0, <ZDOCmd.Simple_Desc_req: 4>, 0, 0, 7, b'\x07\x1a\xcf\x02', True, False)
2020-07-03 20:39:33 DEBUG (MainThread) [zigpy_cc.api] waiting for 7 simpleDescReq
2020-07-03 20:39:33 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO simpleDescReq tsn: 7 {'dstaddr': 0xcf1a, 'nwkaddrofinterest': 0xcf1a, 'endpoint': 2}
2020-07-03 20:39:33 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x05%\x04\x1a\xcf\x1a\xcf\x02&'
2020-07-03 20:39:33 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=4 data=b'\x00' length=1 fcs=96>
2020-07-03 20:39:33 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO simpleDescReq tsn: None {'status': 0}
2020-07-03 20:39:33 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=132 data=b'\x1a\xcf\x00\x1a\xcf\x16\x02\x04\x01\x07\x01\x00\x06\x00\x00\x01\x00\x03\x00\x06\x04\x00\x04\x02\x04\x01\x19\x00' length=28 fcs=214>
2020-07-03 20:39:33 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO simpleDescRsp tsn: 7 {'srcaddr': 0xcf1a, 'status': 0, 'nwkaddr': 0xcf1a, 'len': 22, 'endpoint': 2, 'profileid': 260, 'deviceid': 263, 'deviceversion': 0, 'numinclusters': 6, 'inclusterlist': [0, 1, 3, 1030, 1024, 1026], 'numoutclusters': 1, 'outclusterlist': [25]}
2020-07-03 20:39:33 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 7 simpleDescRsp
2020-07-03 20:39:33 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message simpleDescRsp
2020-07-03 20:39:33 INFO (MainThread) [zigpy.endpoint] [0xcf1a:2] Discovered endpoint information: <Optional endpoint=2 profile=260 device_type=263 device_version=0 input_clusters=[0, 1, 3, 1030, 1024, 1026] output_clusters=[25]>
2020-07-03 20:39:33 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x09 request
2020-07-03 20:39:33 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 260, 0, 2, 2, 9, b'\x00\t\x00\x04\x00\x05\x00', True, False)
2020-07-03 20:39:33 DEBUG (MainThread) [zigpy_cc.api] --> SREQ AF dataRequest tsn: 9 {'dstaddr': 53018, 'destendpoint': 2, 'srcendpoint': 2, 'clusterid': 0, 'transid': 10, 'options': 0, 'radius': 30, 'len': 7, 'data': b'\x00\t\x00\x04\x00\x05\x00'}
2020-07-03 20:39:33 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x11$\x01\x1a\xcf\x02\x02\x00\x00\n\x00\x1e\x07\x00\t\x00\x04\x00\x05\x00\xfa'
2020-07-03 20:39:33 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.AF command_id=1 data=b'\x00' length=1 fcs=100>
2020-07-03 20:39:33 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP AF dataRequest tsn: None {'status': 0}
2020-07-03 20:39:34 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=128 data=b'\x00\x02\n' length=3 fcs=207>
2020-07-03 20:39:34 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF dataConfirm tsn: None {'status': 0, 'endpoint': 2, 'transid': 10}
2020-07-03 20:39:34 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: dataConfirm
2020-07-03 20:40:02 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x0b request
2020-07-03 20:40:02 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 260, 0, 2, 2, 11, b'\x00\x0b\x00\x04\x00', True, False)
2020-07-03 20:40:02 DEBUG (MainThread) [zigpy_cc.api] --> SREQ AF dataRequest tsn: 11 {'dstaddr': 53018, 'destendpoint': 2, 'srcendpoint': 2, 'clusterid': 0, 'transid': 12, 'options': 0, 'radius': 30, 'len': 5, 'data': b'\x00\x0b\x00\x04\x00'}
2020-07-03 20:40:02 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x0f$\x01\x1a\xcf\x02\x02\x00\x00\x0c\x00\x1e\x05\x00\x0b\x00\x04\x00\xe7'
2020-07-03 20:40:02 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.AF command_id=1 data=b'\x00' length=1 fcs=100>
2020-07-03 20:40:02 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP AF dataRequest tsn: None {'status': 0}
2020-07-03 20:40:02 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=128 data=b'\x00\x02\x0c' length=3 fcs=201>
2020-07-03 20:40:02 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF dataConfirm tsn: None {'status': 0, 'endpoint': 2, 'transid': 12}
2020-07-03 20:40:02 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: dataConfirm
2020-07-03 20:40:28 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=203 data=b'\x00' length=1 fcs=143>
2020-07-03 20:40:28 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO permitJoinInd tsn: None {'duration': 0}
2020-07-03 20:40:28 DEBUG (MainThread) [zigpy_cc.api] --> SREQ UTIL ledControl tsn: None {'ledid': 3, 'mode': <LedMode.Off: 0>}
2020-07-03 20:40:28 DEBUG (MainThread) [zigpy_cc.uart] Send: b"\xfe\x02'\n\x03\x00,"
2020-07-03 20:40:28 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.UTIL command_id=10 data=b'\x00' length=1 fcs=108>
2020-07-03 20:40:28 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP UTIL ledControl tsn: None {'status': 0}
2020-07-03 20:40:30 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x0d request
2020-07-03 20:40:30 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 260, 0, 2, 2, 13, b'\x00\r\x00\x05\x00', True, False)
2020-07-03 20:40:30 DEBUG (MainThread) [zigpy_cc.api] --> SREQ AF dataRequest tsn: 13 {'dstaddr': 53018, 'destendpoint': 2, 'srcendpoint': 2, 'clusterid': 0, 'transid': 14, 'options': 0, 'radius': 30, 'len': 5, 'data': b'\x00\r\x00\x05\x00'}
2020-07-03 20:40:30 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x0f$\x01\x1a\xcf\x02\x02\x00\x00\x0e\x00\x1e\x05\x00\r\x00\x05\x00\xe2'
2020-07-03 20:40: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>
2020-07-03 20:40:30 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP AF dataRequest tsn: None {'status': 0}
2020-07-03 20:40:30 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=128 data=b'\x00\x02\x0e' length=3 fcs=203>
2020-07-03 20:40:30 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF dataConfirm tsn: None {'status': 0, 'endpoint': 2, 'transid': 14}
2020-07-03 20:40:30 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: dataConfirm
2020-07-03 20:40:58 DEBUG (MainThread) [zigpy.endpoint] [0xcf1a:2] Manufacturer: None
2020-07-03 20:40:58 DEBUG (MainThread) [zigpy.endpoint] [0xcf1a:2] Model: None
2020-07-03 20:40:58 INFO (MainThread) [zigpy.endpoint] [0xcf1a:1] Discovering endpoint information
2020-07-03 20:40:58 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2020-07-03 20:40:58 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x0f request
2020-07-03 20:40:58 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 0, <ZDOCmd.Simple_Desc_req: 4>, 0, 0, 15, b'\x0f\x1a\xcf\x01', True, False)
2020-07-03 20:40:58 DEBUG (MainThread) [zigpy_cc.api] waiting for 15 simpleDescReq
2020-07-03 20:40:58 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO simpleDescReq tsn: 15 {'dstaddr': 0xcf1a, 'nwkaddrofinterest': 0xcf1a, 'endpoint': 1}
2020-07-03 20:40:58 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x05%\x04\x1a\xcf\x1a\xcf\x01%'
2020-07-03 20:40:58 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=4 data=b'\x00' length=1 fcs=96>
2020-07-03 20:40:58 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO simpleDescReq tsn: None {'status': 0}
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=132 data=b'\x1a\xcf\x00\x1a\xcf\x18\x01^\xc0P\x08\x02\x01\x00\x00\x07\x00\x00\x03\x00\x04\x00\x06\x00\x08\x00\x00\x03\x05\x00' length=30 fcs=11>
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO simpleDescRsp tsn: 15 {'srcaddr': 0xcf1a, 'status': 0, 'nwkaddr': 0xcf1a, 'len': 24, 'endpoint': 1, 'profileid': 49246, 'deviceid': 2128, 'deviceversion': 2, 'numinclusters': 1, 'inclusterlist': [0], 'numoutclusters': 7, 'outclusterlist': [0, 3, 4, 6, 8, 768, 5]}
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 15 simpleDescRsp
2020-07-03 20:40:59 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message simpleDescRsp
2020-07-03 20:40:59 INFO (MainThread) [zigpy.endpoint] [0xcf1a:1] Discovered endpoint information: <Optional endpoint=1 profile=49246 device_type=2128 device_version=2 input_clusters=[0] output_clusters=[0, 3, 4, 6, 8, 768, 5]>
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x11 request
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 260, 0, 1, 1, 17, b'\x00\x11\x00\x04\x00\x05\x00', True, False)
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.api] --> SREQ AF dataRequest tsn: 17 {'dstaddr': 53018, 'destendpoint': 1, 'srcendpoint': 1, 'clusterid': 0, 'transid': 18, 'options': 0, 'radius': 30, 'len': 7, 'data': b'\x00\x11\x00\x04\x00\x05\x00'}
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x11$\x01\x1a\xcf\x01\x01\x00\x00\x12\x00\x1e\x07\x00\x11\x00\x04\x00\x05\x00\xfa'
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.AF command_id=1 data=b'\x00' length=1 fcs=100>
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP AF dataRequest tsn: None {'status': 0}
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=128 data=b'\x00\x01\x12' length=3 fcs=212>
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF dataConfirm tsn: None {'status': 0, 'endpoint': 1, 'transid': 18}
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: dataConfirm
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=129 data=b'\x00\x00\x00\x00\x1a\xcf\x01\x01\x00Y\x00G\xa7Q\x00\x00\x1a\x18\x11\x01\x04\x00\x00B\x07Philips\x05\x00\x00B\x06SML001\x1a\xcf\x1d' length=46 fcs=56>
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF incomingMsg tsn: None {'groupid': 0, 'clusterid': 0, 'srcaddr': 0xcf1a, 'srcendpoint': 1, 'dstendpoint': 1, 'wasbroadcast': 0, 'linkquality': 89, 'securityuse': 0, 'timestamp': 5351239, 'transseqnumber': 0, 'len': 26, 'data': b'\x18\x11\x01\x04\x00\x00B\x07Philips\x05\x00\x00B\x06SML001'}
2020-07-03 20:40:59 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message incomingMsg
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.zcl] [0xcf1a:1:0x0000] ZCL deserialize: <ZCLHeader frame_control= manufacturer=None tsn=17 command_id=Command.Read_Attributes_rsp>
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.endpoint] [0xcf1a:1] Manufacturer: Philips
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.endpoint] [0xcf1a:1] Model: SML001
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Checking quirks for Philips SML001 (00:17:88:01:06:f7:e9:9d)
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'bellows.zigbee.application.EZSPCoordinator'>
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 2}
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.gledopto.soposhgu10.SoposhGU10'>
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {11, 13} {1, 2}
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.lutron.lzl4bwhl01remote.LutronLZL4BWHL01Remote2'>
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 2}
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.netvox.z308e3ed.Z308E3ED'>
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 2}
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.osram.a19twhite.A19TunableWhite'>
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {3} {1, 2}
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.philips.rom001.PhilipsROM001'>
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 2}
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.philips.rwl020.PhilipsRWL020'>
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Fail because device_type mismatch on at least one endpoint
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.philips.rwl021.PhilipsRWL021'>
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Fail because device_type mismatch on at least one endpoint
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.smartthings.multi.SmartthingsMultiPurposeSensor'>
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 2}
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.smartthings.tag_v4.SmartThingsTagV4'>
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 2}
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.xbee.xbee3_io.XBee3Sensor'>
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {232, 230} {1, 2}
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.xbee.xbee_io.XBeeSensor'>
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {232, 230} {1, 2}
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.xiaomi.mija.smoke.MijiaHoneywellSmokeDetectorSensor'>
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 2}
2020-07-03 20:40:59 DEBUG (MainThread) [homeassistant.components.zha.core.gateway] device - 0xcf1a:00:17:88:01:06:f7:e9:9d entering async_device_initialized - is_new_join: True
2020-07-03 20:40:59 DEBUG (MainThread) [homeassistant.components.zha.core.gateway] device - 0xcf1a:00:17:88:01:06:f7:e9:9d has joined the ZHA zigbee network
2020-07-03 20:40:59 DEBUG (MainThread) [homeassistant.components.zha.core.device] 0xcf1a: started configuration
2020-07-03 20:40:59 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] 0xcf1a:ZDO: 'async_configure' stage succeeded
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x13 request
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 0, <ZDOCmd.Bind_req: 33>, 0, 0, 19, b'\x13\x9d\xe9\xf7\x06\x01\x88\x17\x00\x01\x00\x00\x03\x1d\xd0\xdb\x14\x00K\x12\x00\x01', True, False)
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.api] waiting for 19 bindReq
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO bindReq tsn: 19 {'dstaddr': 0xcf1a, 'srcaddr': 00:17:88:01:06:f7:e9:9d, 'srcendpoint': 1, 'clusterid': 0, 'dstaddrmode': 3, 'dstaddress': 00:12:4b:00:14:db:d0:1d, 'dstendpoint': 1}
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x17%!\x1a\xcf\x9d\xe9\xf7\x06\x01\x88\x17\x00\x01\x00\x00\x03\x1d\xd0\xdb\x14\x00K\x12\x00\x01\x85'
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x15 request
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 0, <ZDOCmd.Bind_req: 33>, 0, 0, 21, b'\x15\x9d\xe9\xf7\x06\x01\x88\x17\x00\x01\x06\x00\x03\x1d\xd0\xdb\x14\x00K\x12\x00\x01', True, False)
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.api] waiting for 21 bindReq
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO bindReq tsn: 21 {'dstaddr': 0xcf1a, 'srcaddr': 00:17:88:01:06:f7:e9:9d, 'srcendpoint': 1, 'clusterid': 6, 'dstaddrmode': 3, 'dstaddress': 00:12:4b:00:14:db:d0:1d, 'dstendpoint': 1}
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x17%!\x1a\xcf\x9d\xe9\xf7\x06\x01\x88\x17\x00\x01\x06\x00\x03\x1d\xd0\xdb\x14\x00K\x12\x00\x01\x83'
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x17 request
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 0, <ZDOCmd.Bind_req: 33>, 0, 0, 23, b'\x17\x9d\xe9\xf7\x06\x01\x88\x17\x00\x01\x08\x00\x03\x1d\xd0\xdb\x14\x00K\x12\x00\x01', True, False)
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.api] waiting for 23 bindReq
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO bindReq tsn: 23 {'dstaddr': 0xcf1a, 'srcaddr': 00:17:88:01:06:f7:e9:9d, 'srcendpoint': 1, 'clusterid': 8, 'dstaddrmode': 3, 'dstaddress': 00:12:4b:00:14:db:d0:1d, 'dstendpoint': 1}
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x17%!\x1a\xcf\x9d\xe9\xf7\x06\x01\x88\x17\x00\x01\x08\x00\x03\x1d\xd0\xdb\x14\x00K\x12\x00\x01\x8d'
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=33 data=b'\x00' length=1 fcs=69>
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO bindReq tsn: None {'status': 0}
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=33 data=b'\x00' length=1 fcs=69>
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO bindReq tsn: None {'status': 0}
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=33 data=b'\x00' length=1 fcs=69>
2020-07-03 20:40:59 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO bindReq tsn: None {'status': 0}
2020-07-03 20:41:00 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=161 data=b'\x1a\xcf\x00' length=3 fcs=50>
2020-07-03 20:41:00 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO bindRsp tsn: 19 {'srcaddr': 0xcf1a, 'status': 0}
2020-07-03 20:41:00 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 19 bindRsp
2020-07-03 20:41:00 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message bindRsp
2020-07-03 20:41:00 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:1:0x0000]: bound 'basic' cluster: Status.SUCCESS
2020-07-03 20:41:00 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:1:0x0000]: finished channel configuration
2020-07-03 20:41:00 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x19 request
2020-07-03 20:41:00 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 260, 0, 1, 1, 25, b'\x00\x19\x00\x07\x00', True, False)
2020-07-03 20:41:00 DEBUG (MainThread) [zigpy_cc.api] --> SREQ AF dataRequest tsn: 25 {'dstaddr': 53018, 'destendpoint': 1, 'srcendpoint': 1, 'clusterid': 0, 'transid': 26, 'options': 0, 'radius': 30, 'len': 5, 'data': b'\x00\x19\x00\x07\x00'}
2020-07-03 20:41:00 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x0f$\x01\x1a\xcf\x01\x01\x00\x00\x1a\x00\x1e\x05\x00\x19\x00\x07\x00\xe0'
2020-07-03 20:41:00 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.AF command_id=1 data=b'\x00' length=1 fcs=100>
2020-07-03 20:41:00 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP AF dataRequest tsn: None {'status': 0}
2020-07-03 20:41:00 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=161 data=b'\x1a\xcf\x00' length=3 fcs=50>
2020-07-03 20:41:00 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO bindRsp tsn: 21 {'srcaddr': 0xcf1a, 'status': 0}
2020-07-03 20:41:00 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 21 bindRsp
2020-07-03 20:41:00 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message bindRsp
2020-07-03 20:41:00 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:1:0x0006]: bound 'on_off' cluster: Status.SUCCESS
2020-07-03 20:41:00 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:1:0x0006]: finished channel configuration
2020-07-03 20:41:00 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x1b request
2020-07-03 20:41:00 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 0, <ZDOCmd.Bind_req: 33>, 0, 0, 27, b'\x1b\x9d\xe9\xf7\x06\x01\x88\x17\x00\x01\x06\x00\x03\x1d\xd0\xdb\x14\x00K\x12\x00\x01', True, False)
2020-07-03 20:41:00 DEBUG (MainThread) [zigpy_cc.api] waiting for 27 bindReq
2020-07-03 20:41:00 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO bindReq tsn: 27 {'dstaddr': 0xcf1a, 'srcaddr': 00:17:88:01:06:f7:e9:9d, 'srcendpoint': 1, 'clusterid': 6, 'dstaddrmode': 3, 'dstaddress': 00:12:4b:00:14:db:d0:1d, 'dstendpoint': 1}
2020-07-03 20:41:00 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x17%!\x1a\xcf\x9d\xe9\xf7\x06\x01\x88\x17\x00\x01\x06\x00\x03\x1d\xd0\xdb\x14\x00K\x12\x00\x01\x83'
2020-07-03 20:41:00 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=33 data=b'\x00' length=1 fcs=69>
2020-07-03 20:41:00 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO bindReq tsn: None {'status': 0}
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=161 data=b'\x1a\xcf\x00' length=3 fcs=50>
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO bindRsp tsn: 23 {'srcaddr': 0xcf1a, 'status': 0}
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 23 bindRsp
2020-07-03 20:41:01 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message bindRsp
2020-07-03 20:41:01 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:1:0x0008]: bound 'level' cluster: Status.SUCCESS
2020-07-03 20:41:01 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:1:0x0008]: finished channel configuration
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x1d request
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 0, <ZDOCmd.Bind_req: 33>, 0, 0, 29, b'\x1d\x9d\xe9\xf7\x06\x01\x88\x17\x00\x01\x05\x00\x03\x1d\xd0\xdb\x14\x00K\x12\x00\x01', True, False)
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.api] waiting for 29 bindReq
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO bindReq tsn: 29 {'dstaddr': 0xcf1a, 'srcaddr': 00:17:88:01:06:f7:e9:9d, 'srcendpoint': 1, 'clusterid': 5, 'dstaddrmode': 3, 'dstaddress': 00:12:4b:00:14:db:d0:1d, 'dstendpoint': 1}
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x17%!\x1a\xcf\x9d\xe9\xf7\x06\x01\x88\x17\x00\x01\x05\x00\x03\x1d\xd0\xdb\x14\x00K\x12\x00\x01\x80'
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=33 data=b'\x00' length=1 fcs=69>
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO bindReq tsn: None {'status': 0}
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=128 data=b'\x00\x01\x1a' length=3 fcs=220>
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF dataConfirm tsn: None {'status': 0, 'endpoint': 1, 'transid': 26}
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: dataConfirm
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=129 data=b'\x00\x00\x00\x00\x1a\xcf\x01\x01\x00Y\x00N\xc0Q\x00\x00\x08\x18\x19\x01\x07\x00\x000\x03\x1a\xcf\x1d' length=28 fcs=126>
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF incomingMsg tsn: None {'groupid': 0, 'clusterid': 0, 'srcaddr': 0xcf1a, 'srcendpoint': 1, 'dstendpoint': 1, 'wasbroadcast': 0, 'linkquality': 89, 'securityuse': 0, 'timestamp': 5357646, 'transseqnumber': 0, 'len': 8, 'data': b'\x18\x19\x01\x07\x00\x000\x03'}
2020-07-03 20:41:01 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message incomingMsg
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy.zcl] [0xcf1a:1:0x0000] ZCL deserialize: <ZCLHeader frame_control= manufacturer=None tsn=25 command_id=Command.Read_Attributes_rsp>
2020-07-03 20:41:01 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:1:0x0000]: initializing channel: from_cache: False
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x1f request
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 0, <ZDOCmd.Bind_req: 33>, 0, 0, 31, b'\x1f\x9d\xe9\xf7\x06\x01\x88\x17\x00\x01\x00\x03\x03\x1d\xd0\xdb\x14\x00K\x12\x00\x01', True, False)
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.api] waiting for 31 bindReq
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO bindReq tsn: 31 {'dstaddr': 0xcf1a, 'srcaddr': 00:17:88:01:06:f7:e9:9d, 'srcendpoint': 1, 'clusterid': 768, 'dstaddrmode': 3, 'dstaddress': 00:12:4b:00:14:db:d0:1d, 'dstendpoint': 1}
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x17%!\x1a\xcf\x9d\xe9\xf7\x06\x01\x88\x17\x00\x01\x00\x03\x03\x1d\xd0\xdb\x14\x00K\x12\x00\x01\x86'
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=161 data=b'\x1a\xcf\x00' length=3 fcs=50>
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO bindRsp tsn: 27 {'srcaddr': 0xcf1a, 'status': 0}
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 27 bindRsp
2020-07-03 20:41:01 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message bindRsp
2020-07-03 20:41:01 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:1:0x0006]: bound 'on_off' cluster: Status.SUCCESS
2020-07-03 20:41:01 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:1:0x0006]: finished channel configuration
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=33 data=b'\x00' length=1 fcs=69>
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO bindReq tsn: None {'status': 0}
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x21 request
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 0, <ZDOCmd.Bind_req: 33>, 0, 0, 33, b'!\x9d\xe9\xf7\x06\x01\x88\x17\x00\x02\x01\x00\x03\x1d\xd0\xdb\x14\x00K\x12\x00\x01', True, False)
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.api] waiting for 33 bindReq
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO bindReq tsn: 33 {'dstaddr': 0xcf1a, 'srcaddr': 00:17:88:01:06:f7:e9:9d, 'srcendpoint': 2, 'clusterid': 1, 'dstaddrmode': 3, 'dstaddress': 00:12:4b:00:14:db:d0:1d, 'dstendpoint': 1}
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x17%!\x1a\xcf\x9d\xe9\xf7\x06\x01\x88\x17\x00\x02\x01\x00\x03\x1d\xd0\xdb\x14\x00K\x12\x00\x01\x87'
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=33 data=b'\x00' length=1 fcs=69>
2020-07-03 20:41:01 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO bindReq tsn: None {'status': 0}
2020-07-03 20:41:02 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=161 data=b'\x1a\xcf\x00' length=3 fcs=50>
2020-07-03 20:41:02 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO bindRsp tsn: 29 {'srcaddr': 0xcf1a, 'status': 0}
2020-07-03 20:41:02 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 29 bindRsp
2020-07-03 20:41:02 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message bindRsp
2020-07-03 20:41:02 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:1:0x0005]: bound 'scenes' cluster: Status.SUCCESS
2020-07-03 20:41:02 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:1:0x0005]: finished channel configuration
2020-07-03 20:41:02 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x23 request
2020-07-03 20:41:02 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 0, <ZDOCmd.Bind_req: 33>, 0, 0, 35, b'#\x9d\xe9\xf7\x06\x01\x88\x17\x00\x02\x02\x04\x03\x1d\xd0\xdb\x14\x00K\x12\x00\x01', True, False)
2020-07-03 20:41:02 DEBUG (MainThread) [zigpy_cc.api] waiting for 35 bindReq
2020-07-03 20:41:02 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO bindReq tsn: 35 {'dstaddr': 0xcf1a, 'srcaddr': 00:17:88:01:06:f7:e9:9d, 'srcendpoint': 2, 'clusterid': 1026, 'dstaddrmode': 3, 'dstaddress': 00:12:4b:00:14:db:d0:1d, 'dstendpoint': 1}
2020-07-03 20:41:02 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x17%!\x1a\xcf\x9d\xe9\xf7\x06\x01\x88\x17\x00\x02\x02\x04\x03\x1d\xd0\xdb\x14\x00K\x12\x00\x01\x80'
2020-07-03 20:41:02 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=33 data=b'\x00' length=1 fcs=69>
2020-07-03 20:41:02 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO bindReq tsn: None {'status': 0}
2020-07-03 20:41:02 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=161 data=b'\x1a\xcf\x00' length=3 fcs=50>
2020-07-03 20:41:02 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO bindRsp tsn: 31 {'srcaddr': 0xcf1a, 'status': 0}
2020-07-03 20:41:02 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 31 bindRsp
2020-07-03 20:41:02 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message bindRsp
2020-07-03 20:41:02 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:1:0x0300]: bound 'light_color' cluster: Status.SUCCESS
2020-07-03 20:41:02 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:1:0x0300]: finished channel configuration
2020-07-03 20:41:02 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x25 request
2020-07-03 20:41:02 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 0, <ZDOCmd.Bind_req: 33>, 0, 0, 37, b'%\x9d\xe9\xf7\x06\x01\x88\x17\x00\x02\x00\x04\x03\x1d\xd0\xdb\x14\x00K\x12\x00\x01', True, False)
2020-07-03 20:41:02 DEBUG (MainThread) [zigpy_cc.api] waiting for 37 bindReq
2020-07-03 20:41:02 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO bindReq tsn: 37 {'dstaddr': 0xcf1a, 'srcaddr': 00:17:88:01:06:f7:e9:9d, 'srcendpoint': 2, 'clusterid': 1024, 'dstaddrmode': 3, 'dstaddress': 00:12:4b:00:14:db:d0:1d, 'dstendpoint': 1}
2020-07-03 20:41:02 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x17%!\x1a\xcf\x9d\xe9\xf7\x06\x01\x88\x17\x00\x02\x00\x04\x03\x1d\xd0\xdb\x14\x00K\x12\x00\x01\x82'
2020-07-03 20:41:02 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:1:0x0000]: 'async_configure' stage succeeded
2020-07-03 20:41:02 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:1:0x0006]: 'async_configure' stage succeeded
2020-07-03 20:41:02 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:1:0x0008]: 'async_configure' stage succeeded
2020-07-03 20:41:02 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:1:0x0006]: 'async_configure' stage succeeded
2020-07-03 20:41:02 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:1:0x0005]: 'async_configure' stage succeeded
2020-07-03 20:41:02 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:1:0x0300]: 'async_configure' stage succeeded
2020-07-03 20:41:02 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=33 data=b'\x00' length=1 fcs=69>
2020-07-03 20:41:02 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO bindReq tsn: None {'status': 0}
2020-07-03 20:41:03 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=161 data=b'\x1a\xcf\x00' length=3 fcs=50>
2020-07-03 20:41:03 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO bindRsp tsn: 33 {'srcaddr': 0xcf1a, 'status': 0}
2020-07-03 20:41:03 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 33 bindRsp
2020-07-03 20:41:03 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message bindRsp
2020-07-03 20:41:03 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:2:0x0001]: bound 'power' cluster: Status.SUCCESS
2020-07-03 20:41:03 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x27 request
2020-07-03 20:41:03 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 260, 1, 2, 2, 39, b"\x00'\x06\x00 \x00 \x10\x0e0*\x01", True, False)
2020-07-03 20:41:03 DEBUG (MainThread) [zigpy_cc.api] --> SREQ AF dataRequest tsn: 39 {'dstaddr': 53018, 'destendpoint': 2, 'srcendpoint': 2, 'clusterid': 1, 'transid': 40, 'options': 0, 'radius': 30, 'len': 12, 'data': b"\x00'\x06\x00 \x00 \x10\x0e0*\x01"}
2020-07-03 20:41:03 DEBUG (MainThread) [zigpy_cc.uart] Send: b"\xfe\x16$\x01\x1a\xcf\x02\x02\x01\x00(\x00\x1e\x0c\x00'\x06\x00 \x00 \x10\x0e0*\x01\xf9"
2020-07-03 20:41:03 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.AF command_id=1 data=b'\x00' length=1 fcs=100>
2020-07-03 20:41:03 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP AF dataRequest tsn: None {'status': 0}
2020-07-03 20:41:03 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=161 data=b'\x1a\xcf\x00' length=3 fcs=50>
2020-07-03 20:41:03 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO bindRsp tsn: 35 {'srcaddr': 0xcf1a, 'status': 0}
2020-07-03 20:41:03 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 35 bindRsp
2020-07-03 20:41:03 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message bindRsp
2020-07-03 20:41:03 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:2:0x0402]: bound 'temperature' cluster: Status.SUCCESS
2020-07-03 20:41:03 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x29 request
2020-07-03 20:41:03 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 260, 1026, 2, 2, 41, b'\x00)\x06\x00\x00\x00)\x1e\x00\x84\x032\x00', True, False)
2020-07-03 20:41:03 DEBUG (MainThread) [zigpy_cc.api] --> SREQ AF dataRequest tsn: 41 {'dstaddr': 53018, 'destendpoint': 2, 'srcendpoint': 2, 'clusterid': 1026, 'transid': 42, 'options': 0, 'radius': 30, 'len': 13, 'data': b'\x00)\x06\x00\x00\x00)\x1e\x00\x84\x032\x00'}
2020-07-03 20:41:03 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x17$\x01\x1a\xcf\x02\x02\x02\x04*\x00\x1e\r\x00)\x06\x00\x00\x00)\x1e\x00\x84\x032\x00u'
2020-07-03 20:41:03 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.AF command_id=1 data=b'\x00' length=1 fcs=100>
2020-07-03 20:41:03 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP AF dataRequest tsn: None {'status': 0}
2020-07-03 20:41:04 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=161 data=b'\x1a\xcf\x00' length=3 fcs=50>
2020-07-03 20:41:04 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO bindRsp tsn: 37 {'srcaddr': 0xcf1a, 'status': 0}
2020-07-03 20:41:04 DEBUG (MainThread) [zigpy_cc.zigbee.application] REPLY for 37 bindRsp
2020-07-03 20:41:04 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message bindRsp
2020-07-03 20:41:04 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:2:0x0400]: bound 'illuminance' cluster: Status.SUCCESS
2020-07-03 20:41:04 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x2b request
2020-07-03 20:41:04 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 260, 1024, 2, 2, 43, b'\x00+\x06\x00\x00\x00!\x1e\x00\x84\x03\x01\x00', True, False)
2020-07-03 20:41:04 DEBUG (MainThread) [zigpy_cc.api] --> SREQ AF dataRequest tsn: 43 {'dstaddr': 53018, 'destendpoint': 2, 'srcendpoint': 2, 'clusterid': 1024, 'transid': 44, 'options': 0, 'radius': 30, 'len': 13, 'data': b'\x00+\x06\x00\x00\x00!\x1e\x00\x84\x03\x01\x00'}
2020-07-03 20:41:04 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x17$\x01\x1a\xcf\x02\x02\x00\x04,\x00\x1e\r\x00+\x06\x00\x00\x00!\x1e\x00\x84\x03\x01\x00H'
2020-07-03 20:41:04 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.AF command_id=1 data=b'\x00' length=1 fcs=100>
2020-07-03 20:41:04 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP AF dataRequest tsn: None {'status': 0}
2020-07-03 20:41:04 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=128 data=b'\x00\x02(' length=3 fcs=237>
2020-07-03 20:41:04 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF dataConfirm tsn: None {'status': 0, 'endpoint': 2, 'transid': 40}
2020-07-03 20:41:04 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: dataConfirm
2020-07-03 20:41:04 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=128 data=b'\x00\x02*' length=3 fcs=239>
2020-07-03 20:41:04 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF dataConfirm tsn: None {'status': 0, 'endpoint': 2, 'transid': 42}
2020-07-03 20:41:04 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: dataConfirm
2020-07-03 20:41:04 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=128 data=b'\x00\x02,' length=3 fcs=233>
2020-07-03 20:41:04 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF dataConfirm tsn: None {'status': 0, 'endpoint': 2, 'transid': 44}
2020-07-03 20:41:04 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: dataConfirm
2020-07-03 20:41:07 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=129 data=b'\x00\x00\x06\x00\x1a\xcf\x01\x01\x00Y\x00E\tR\x00\x00\x08\x01\x00B\x00\xb8\x0b\x00\x00\x1a\xcf\x1d' length=28 fcs=125>
2020-07-03 20:41:07 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF incomingMsg tsn: None {'groupid': 0, 'clusterid': 6, 'srcaddr': 0xcf1a, 'srcendpoint': 1, 'dstendpoint': 1, 'wasbroadcast': 0, 'linkquality': 89, 'securityuse': 0, 'timestamp': 5376325, 'transseqnumber': 0, 'len': 8, 'data': b'\x01\x00B\x00\xb8\x0b\x00\x00'}
2020-07-03 20:41:07 INFO (MainThread) [zigpy_cc.zigbee.application] handle_message incomingMsg
2020-07-03 20:41:07 DEBUG (MainThread) [zigpy.zcl] [0xcf1a:1:0x0006] ZCL deserialize: <ZCLHeader frame_control= manufacturer=None tsn=0 command_id=66>
2020-07-03 20:41:07 DEBUG (MainThread) [zigpy.zcl] [0xcf1a:1:0x0006] ZCL request 0x0042: [0, 3000, 0]
2020-07-03 20:41:07 DEBUG (MainThread) [zigpy.zcl] [0xcf1a:1:0x0006] No handler for cluster command 66
2020-07-03 20:41:07 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:1:0x0006]: received 'on_with_timed_off' command with [0, 3000, 0] args on cluster_id '6' tsn '0'
2020-07-03 20:42:56 DEBUG (MainThread) [zigpy_cc.zigbee.application] broadcast (0, 54, 0, 0, 0, 0, 71, b'G<\x00', <BroadcastAddress.ALL_ROUTERS_AND_COORDINATOR: 65532>)
2020-07-03 20:42:56 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO mgmtPermitJoinReq tsn: 71 {'addrmode': 15, 'dstaddr': 0xfffc, 'duration': 60, 'tcsignificance': 0}
2020-07-03 20:42:56 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x05%6\x0f\xfc\xff<\x00&'
2020-07-03 20:42:56 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=54 data=b'\x00' length=1 fcs=82>
2020-07-03 20:42:56 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO mgmtPermitJoinReq tsn: None {'status': 0}
2020-07-03 20:42:56 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO mgmtPermitJoinReq tsn: None {'addrmode': 15, 'dstaddr': <BroadcastAddress.ALL_ROUTERS_AND_COORDINATOR: 65532>, 'duration': 60, 'tcsignificance': 0}
2020-07-03 20:42:56 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x05%6\x0f\xfc\xff<\x00&'
2020-07-03 20:42:56 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=203 data=b'<' length=1 fcs=179>
2020-07-03 20:42:56 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO permitJoinInd tsn: None {'duration': 60}
2020-07-03 20:42:56 DEBUG (MainThread) [zigpy_cc.api] --> SREQ UTIL ledControl tsn: None {'ledid': 3, 'mode': <LedMode.On: 1>}
2020-07-03 20:42:56 DEBUG (MainThread) [zigpy_cc.uart] Send: b"\xfe\x02'\n\x03\x01-"
2020-07-03 20:42:57 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=54 data=b'\x00' length=1 fcs=82>
2020-07-03 20:42:57 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO mgmtPermitJoinReq tsn: None {'status': 0}
2020-07-03 20:42:57 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.UTIL command_id=10 data=b'\x00' length=1 fcs=108>
2020-07-03 20:42:57 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP UTIL ledControl tsn: None {'status': 0}
2020-07-03 20:42:57 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>
2020-07-03 20:42:57 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO mgmtPermitJoinRsp tsn: None {'srcaddr': 0x0000, 'status': 0}
2020-07-03 20:42:57 DEBUG (MainThread) [zigpy_cc.api] --> SREQ UTIL ledControl tsn: None {'ledid': 3, 'mode': <LedMode.On: 1>}
2020-07-03 20:42:57 DEBUG (MainThread) [zigpy_cc.uart] Send: b"\xfe\x02'\n\x03\x01-"
2020-07-03 20:42:57 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>
2020-07-03 20:42:57 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO mgmtPermitJoinRsp tsn: None {'srcaddr': 0x0000, 'status': 0}
2020-07-03 20:42:57 DEBUG (MainThread) [zigpy_cc.api] --> SREQ UTIL ledControl tsn: None {'ledid': 3, 'mode': <LedMode.On: 1>}
2020-07-03 20:42:57 DEBUG (MainThread) [zigpy_cc.uart] Send: b"\xfe\x02'\n\x03\x01-"
2020-07-03 20:42:57 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.UTIL command_id=10 data=b'\x00' length=1 fcs=108>
2020-07-03 20:42:57 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP UTIL ledControl tsn: None {'status': 0}
2020-07-03 20:42:57 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.UTIL command_id=10 data=b'\x00' length=1 fcs=108>
2020-07-03 20:42:57 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP UTIL ledControl tsn: None {'status': 0}
2020-07-03 20:42:58 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:2:0x0001]: failed to get attributes '['battery_size', 'battery_percentage_remaining', 'battery_voltage', 'battery_quantity']' on 'power' cluster:
2020-07-03 20:42:58 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:2:0x0001]: initializing channel: from_cache: False
2020-07-03 20:42:58 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x49 request
2020-07-03 20:42:58 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 260, 1, 2, 2, 73, b'\x00I\x00 \x00!\x00', True, False)
2020-07-03 20:42:58 DEBUG (MainThread) [zigpy_cc.api] --> SREQ AF dataRequest tsn: 73 {'dstaddr': 53018, 'destendpoint': 2, 'srcendpoint': 2, 'clusterid': 1, 'transid': 74, 'options': 0, 'radius': 30, 'len': 7, 'data': b'\x00I\x00 \x00!\x00'}
2020-07-03 20:42:58 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x11$\x01\x1a\xcf\x02\x02\x01\x00J\x00\x1e\x07\x00I\x00 \x00!\x00\xfb'
2020-07-03 20:42:58 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.AF command_id=1 data=b'\x00' length=1 fcs=100>
2020-07-03 20:42:58 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP AF dataRequest tsn: None {'status': 0}
2020-07-03 20:42:58 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=128 data=b'\x00\x02J' length=3 fcs=143>
2020-07-03 20:42:58 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF dataConfirm tsn: None {'status': 0, 'endpoint': 2, 'transid': 74}
2020-07-03 20:42:58 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: dataConfirm
2020-07-03 20:42:59 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:2:0x0402]: failed to get attributes '['measured_value']' on 'temperature' cluster:
2020-07-03 20:42:59 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:2:0x0406]: initializing channel: from_cache: False
2020-07-03 20:42:59 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x4b request
2020-07-03 20:42:59 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 260, 1030, 2, 2, 75, b'\x00K\x00\x00\x00', True, False)
2020-07-03 20:42:59 DEBUG (MainThread) [zigpy_cc.api] --> SREQ AF dataRequest tsn: 75 {'dstaddr': 53018, 'destendpoint': 2, 'srcendpoint': 2, 'clusterid': 1030, 'transid': 76, 'options': 0, 'radius': 30, 'len': 5, 'data': b'\x00K\x00\x00\x00'}
2020-07-03 20:42:59 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x0f$\x01\x1a\xcf\x02\x02\x06\x04L\x00\x1e\x05\x00K\x00\x00\x00\xe1'
2020-07-03 20:42:59 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.AF command_id=1 data=b'\x00' length=1 fcs=100>
2020-07-03 20:42:59 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP AF dataRequest tsn: None {'status': 0}
2020-07-03 20:42:59 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=128 data=b'\x00\x02L' length=3 fcs=137>
2020-07-03 20:42:59 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF dataConfirm tsn: None {'status': 0, 'endpoint': 2, 'transid': 76}
2020-07-03 20:42:59 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: dataConfirm
2020-07-03 20:42:59 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:2:0x0400]: failed to get attributes '['measured_value']' on 'illuminance' cluster:
2020-07-03 20:42:59 DEBUG (MainThread) [zigpy.device] [0xcf1a] Extending timeout for 0x4d request
2020-07-03 20:42:59 DEBUG (MainThread) [zigpy_cc.zigbee.application] request (0xcf1a, 260, 0, 2, 2, 77, b'\x00M\x00\x07\x00', True, False)
2020-07-03 20:42:59 DEBUG (MainThread) [zigpy_cc.api] --> SREQ AF dataRequest tsn: 77 {'dstaddr': 53018, 'destendpoint': 2, 'srcendpoint': 2, 'clusterid': 0, 'transid': 78, 'options': 0, 'radius': 30, 'len': 5, 'data': b'\x00M\x00\x07\x00'}
2020-07-03 20:42:59 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x0f$\x01\x1a\xcf\x02\x02\x00\x00N\x00\x1e\x05\x00M\x00\x07\x00\xe0'
2020-07-03 20:42:59 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.AF command_id=1 data=b'\x00' length=1 fcs=100>
2020-07-03 20:42:59 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP AF dataRequest tsn: None {'status': 0}
2020-07-03 20:42:59 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.AF command_id=128 data=b'\x00\x02N' length=3 fcs=139>
2020-07-03 20:42:59 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ AF dataConfirm tsn: None {'status': 0, 'endpoint': 2, 'transid': 78}
2020-07-03 20:42:59 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: dataConfirm
2020-07-03 20:43:26 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:2:0x0001]: failed to get attributes '['battery_voltage', 'battery_percentage_remaining']' on 'power' cluster:
2020-07-03 20:43:26 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:2:0x0019]: initializing channel: from_cache: False
2020-07-03 20:43:27 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:2:0x0406]: failed to get attributes '['occupancy']' on 'occupancy' cluster:
2020-07-03 20:43:27 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:2:0x0000]: initializing channel: from_cache: False
2020-07-03 20:43:27 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:2:0x0001]: 'async_initialize' stage succeeded
2020-07-03 20:43:27 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:2:0x0402]: 'async_initialize' stage succeeded
2020-07-03 20:43:27 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:2:0x0400]: 'async_initialize' stage succeeded
2020-07-03 20:43:27 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:2:0x0406]: 'async_initialize' stage succeeded
2020-07-03 20:43:27 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:2:0x0000]: 'async_initialize' stage succeeded
2020-07-03 20:43:27 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xcf1a:2:0x0019]: 'async_initialize' stage succeeded
2020-07-03 20:43:27 DEBUG (MainThread) [homeassistant.components.zha.core.device] 0xcf1a: power source: Battery or Unknown
2020-07-03 20:43:27 DEBUG (MainThread) [homeassistant.components.zha.core.device] 0xcf1a: completed initialization
2020-07-03 20:43:57 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=203 data=b'\x00' length=1 fcs=143>
2020-07-03 20:43:57 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO permitJoinInd tsn: None {'duration': 0}
2020-07-03 20:43:57 DEBUG (MainThread) [zigpy_cc.api] --> SREQ UTIL ledControl tsn: None {'ledid': 3, 'mode': <LedMode.Off: 0>}
2020-07-03 20:43:57 DEBUG (MainThread) [zigpy_cc.uart] Send: b"\xfe\x02'\n\x03\x00,"
2020-07-03 20:43:57 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.UTIL command_id=10 data=b'\x00' length=1 fcs=108>
2020-07-03 20:43:57 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP UTIL ledControl tsn: None {'status': 0}