Adminiuga / zha_custom

"zha_custom" component for Home Assistant. Zigpy commands service wrapper
4 stars 5 forks source link

Request implanting Security Frames function 0x00B1 and 0x0076 #2

Closed MattWestb closed 3 years ago

MattWestb commented 3 years ago

Master @Adminiuga. First i need explaining the basis for my "request". I have large experience of communication / security systems and pretty novice in deep programing after trying BASIC in the school i was very disappointed and wos writing my code in assembler for MC6809 but was not working professional with it. Logic and analytic thinking have always being my strong side then working with technical things. And then cant finding the problem, then taking one step back and 2 to the side for seeing the problem from one other view. After reading the 13-0402-13 Base Device Behavior Specification Version 1.0 and trying applying it one the silabs AN1233: Zigbee Security and was thinking the problem was rejoining devices in the network. I have not finding any guide "how to implementing your custom EZSP coordinator" and i don't have your skills and experience of coding for NCPs. Have "reading" the UG100: EZSP Reference Guide and trying finding out how silabs have implanting the Base-Device-Behavior in the EZSP concept. After one nights sleep I was rethinking and turing the problem around and was finding that the problem is not rejoining of devices, then the devices not in the network (reseted and dont have network or trustcenter link key in its key table). Was finding 2 functions that catching my attention in the reference guide. CearKeyTable and eraseKeyTableEntry. It is not described how to using this on the host application side but its must being some logical behind them.

Back to our beloved bellows: I think bellows is working more than well as secure Zigbee 3 coordinator but i have not trying it out so much and not over longer time. I have finding that is failing some fundamental functions that is not implanted for making it working "autonome" then joining devices that was paired in one network and stored in the NCPs key table and was resetted / removed from the network. What i have see is that pairing devices then the NCP have its key table empty the NCP can adding new devices and its working well. The fundamental thing is that then removing the NCP from the network (deleting it in ZHA) its still having the "old key table" saved in the chip. Then adding it to ZHA the key table in the chip is not being reseted and ther for using the "old key table" and can't (and should NOT do!!) updating the keys then the devices is not rejoining the network (if they don't have the,same key token) the devices is doing one new joining (pairing) and the NCP suld making one new key in the key table. The logic is to erasing the key table then removing the NCP from the system. Then the NCP can adding new devices keys in the table then ZHA is adding new devices. For testing this function its needed implanting from "UG100: EZSP Reference Guide EmberZNet PRO Release 6.8.0", 10 Security Frames fuktion:

Name: clearKeyTable ID: 0x00B1
Description: This function clears the key table of the current network.
Command Parameters: None
Response Parameters:
EmberStatus status The success or failure of the operation.

If pairing its working after key table is cleared its need being integrated in ZHA. Can being in "config" menu for the NCP and / or then deleting or adding the NCP in ZHA and also possible asking "delete the old key table in the NCP ?" can being good for keeping all paired devices security credentials then needed.

The next funktion is that ZHA its not deleting the key from one device in the NCPs table then deleting the device in ZHA. Then deleted devices don't doing a "rejoining" (its dont have one network key or trustcenter link in its key table then its reseted) its doing on new pairing and therefore the old key in the NCPs table is useless and blocking the device from doing one new paring (perhaps bad for the user but its the secure way). The logick is then deleting one device in ZHA also suld deleting the key in the NCPs table. For testing this function is needed implanting from "UG100: EZSP Reference Guide EmberZNet PRO Release 6.8.0", 10 Security Frames fuktion:

Name: eraseKeyTableEntry ID: 0x0076
Description: This function erases the data in the key table entry at the specified index. 
If the index is invalid, false is returned.
Command Parameters:
uint8_t index This indicates the index of entry to erase.
Response Parameters:
EmberStatus status The success or failure of the operation.

If pairing its working after the key is erased in the NCPs table then logic needs being integrated in ZHA for doing that automatic. The normal suld being that ZHA is doing it then deleting one device in the GUI but it can also being good having it under the device property as "delete device key in NCP" thats making it possible resetting the device and repairing it without deleting it and is configuration in ZHA.

One thing that also can being god in the NCP config is "cleaning unused device keys in NCP table" for getting rid of "trash" in the key table that is not stored in ZHAs database for eliminating problems with "hidden ghost key" in the NCP.

I hope you is understanding my (un)logical thinking but i think this is the key for getting bellows working in real zigbee 3 mode without braking the security completely (as some other system have done).

Pleas integrating theses 2 functions in ZHA_CUSTOM so its being possible testing how the EZSP is handling the key table and if its working OK getting it implanted in the multiversion bellows (Bellows2 ?). If you like opening for more advance testing and possible adding installation keys you can also inplanting:

Name: addOrUpdateKeyTableEntry ID: 0x0066
Description: This function updates an existing entry in the key table or adds a new one. It first searches the table for an existing entry
that matches the passed EUI64 address. If no entry is found, it searches for the first free entry. If successful, it updates the key data and
resets the associated incoming frame counter. If it fails to find an existing entry and no free one exists, it returns a failure.
Command Parameters:
EmberEUI64 address The address of the partner device associated with the Key.
bool linkKey An indication of whether this is a Link Key (true) or Master Key (false)
EmberKeyData keyData The actual key data associated with the entry.
Response Parameters:
EmberStatus status The success or failure error code of the operation.

One thing the "UG100: EZSP Reference Guide" i have looking in is "EmberZNet PRO Release 6.8.0" so it can being its not working with older versions without adapting the commands.

PS. I have not looking on the TI chips implanting but Z2M have problem with the new texas adapters and need reflashing them for getting them working agen = can being bad keys in the table that the host and/or the NCP is not taking care of.

Have one nice weekend !!

Regard MW

Adminiuga commented 3 years ago

the problem is not in how to use eraseKeyTableEntry ID: 0x0076 but "when" to use it. zha_custom btw uses it to delete the keys, if there's a key for the device but zigpy/bellows does not have that device in database.

I think you are on the very right track and it has to do with mismatching frame counters, because one side was reset, but not the NCP. Narrowing it down to be TC link key related helps, just need to think how to handle it best way possible.

MattWestb commented 3 years ago

One thing: the frame counter is only used then doing one normal operation communication between the devices and not then doing low level joining "handshake" request from the pairing device (to its parent). Then doing one pairing (the device is being reseted its dont have any MWK or TCLI key) the TCLK and its frame counter is not in use until the device is getting one Trustcenter link key from the NCP and start using the frame counter.

The frame counter is well documented in the 13-0402-13-00zi-Base-Device-Behavior-Specification for all steps then pairing and joining devices. You need only "translating" it to how silabs have implanting the "funktion" in the EZSP.

Cleaning key table then the NCP is forming the network (for the first time). Allways erase device key then ZHA is deleting the device. = new pairing NOT rejoining = The right way. Then looking how is working and if some things need being adjusted for moving to dev branch. The "zha_custom token cleaning" is fitting very good under "NCP configuration" as one option.

Do more reading and thinking you finding the logick !!!!!

Implanting the 3 (or 1. 2 missing) functions and you can testing if the logic is working as expected or not.

Adminiuga commented 3 years ago

Cleaning key table then the NCP is forming the network (for the first time).

That could be done, but really won't solve the case for the following:

Allways erase device key then ZHA is deleting the device.

Yeah, and ZHA is not deleting the device, because user did not tell it to delete the device. This is the case I'm talking about:

  1. user joins the device the very 1st time and it works fine
  2. for some reason device falls off the network
  3. Use does reset the device and tries to re-pair it and here's the crux of the problem: a. user did not remove device from the application -> bellows does not know the device is being reset b. device tries to rejoin, but fails because of miss matching TC link keys.

This all can be avoided, if user removes the device 1st to signal bellows it should remove any existing keys. Or users could use the "install codes" but I'm surprised how few Zigbee 3.0 devices come with install codes

MattWestb commented 3 years ago

For 3:b is false (if making difference between pairing and rejoining). The device doesn't trying rejoining the network then it dont have link or network key because its have any then being deleted by the user (in the device not in the NCP). The device is trying to doing pairing. Then paring the old link key and its frame counter is obsolete and suld being deleted in the key table.

Making one "Delete link key for this device and repairing it" in the device config meu then the user can repairing the device without deleting it in ZHAs database. One logick that is looking for "device joining" and "device was leaving" and ZHA have the device in the database (or the NCP in the key table) and informing the user that is one know device have problem joining the network and need attention (deleting the old link key or the install key entered for the device in is not working).

The install code can being nice to have implanted but must being under the NCP then its not possible in device (cant being paired because the NCPs trustcenter don't have the install code). Perhaps one "key manager menu" under NCP configuration with cleaning unused keys and entering / editing install codes for devices to pairing. I think its possible extracting the type and status for the keys in the table but i'm not sure if it was in the EZSP or only written as reference in the Base-Device-Behavior-Specification.

If you implanting the" Cleaning key table" and "erase device key" then the 2 large problems is very likely away and can doing more fine tuning for the exceptions then testing the implantation. And very likely its coming more "undocumented futures" (bugs) then the paring problem is fixed that you have doing some thousand code changes but that coming later.

Do some other open system have support for install codes ???? Perhaps bellows is being the first getting it :-)))

MattWestb commented 3 years ago

Doing one automatically deleting link key and automatic pairing for case "3:b" is very dangerous and degrading the system security under tas....

The best / easiest way to not getting the "case 3" is banning all ZHA users using bellows ;-))))

Adminiuga commented 3 years ago

Try the latest updates from multiversion.

MattWestb commented 3 years ago

I was spending more than 3 days reading and thinking and in the end writing more than 320 lines and was deleting over 50 lines and you was only making 32 new lines and deleting 5 on 3 hours. THAT'S IS UNFAIR !!!!

Stopping HA and deleting zigbee.db and .storage/zha.storage. Reloading multiversion with "Custom deps deployment". Starting HA container from portainer.

First testing looks great !!! Paring 2xGU10 OK Deleting one GU10 OK Paring the deleted GU10 OK Paring one E27 OK Pairing HOMA_LEDD OK

Then looking little deeper. Repairing of deleted GU10:

[0x0000:zdo] ZDO request ZDOCmd.Mgmt_Permit_Joining_req: [60, <Bool.false: 0>]
Device 0xdb26 (14:b4:57:ff:fe:53:98:23) joined the network
[0xdb26] Requesting 'Node Descriptor'
Tries remaining: 2
[0xdb26] Extending timeout for 0x0b request
Device 0xdb26 (14:b4:57:ff:fe:53:98:23) joined the network
Skip initialization for existing device 14:b4:57:ff:fe:53:98:23
Device 0xdb26 (14:b4:57:ff:fe:53:98:23) joined the network
Skip initialization for existing device 14:b4:57:ff:fe:53:98:23
[0xdb26:zdo] ZDO request ZDOCmd.Device_annce: [0xdb26, 14:b4:57:ff:fe:53:98:23, 142]
[0xdb26] Node Descriptor: <Optional byte1=1 byte2=64 mac_capability_flags=142 manufacturer_code=4476 maximum_buffer_size=82 maximum_incoming_transfer_size=82 server_mask=11264 maximum_outgoing_transfer_size=82 descriptor_capability_field=0>
[0xdb26] Discovering endpoints
Tries remaining: 3
[0xdb26] Discovered endpoints: [1, 242]

Its going in without problems only living for using the network key (I think its one not ZB3 joining and no new TC link key is requested) and then all in.

Deleting the GU10 (0xdb26) in ZHA and not opening network for joining. Looking in ZHA debug log and its trying going back in but TC its dropping it = very good. Little strange its that ZHA is trying paring it and in the end its writing:

2020-08-23 10:22:58 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0xdb26:1:0x0005]: 'async_initialize' stage succeeded
2020-08-23 10:22:58 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xdb26](TRADFRI bulb GU10 WS 400lm): power source: Mains
2020-08-23 10:22:58 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xdb26](TRADFRI bulb GU10 WS 400lm): completed initialization

I not getting any "new" GU10 in ZHA gui = good. Restarting AH and looking in the debug log:

2020-08-23 10:47:35 DEBUG (MainThread) [zigpy.appdb] Loading application state from /config/zigbee.db
2020-08-23 10:47:35 DEBUG (MainThread) [zigpy.appdb] [0x21da:1:0x0000] Attribute id: 4 value: IKEA of Sweden
2020-08-23 10:47:35 DEBUG (MainThread) [zigpy.appdb] [0x21da:1:0x0000] Attribute id: 5 value: TRADFRI bulb GU10 WS 400lm
2020-08-23 10:47:35 DEBUG (MainThread) [zigpy.appdb] [0x21da:1:0x0300] Attribute id: 4 value: 26909
2020-08-23 10:47:35 DEBUG (MainThread) [zigpy.appdb] [0xfcdf:1:0x0000] Attribute id: 4 value: IKEA of Sweden
2020-08-23 10:47:35 DEBUG (MainThread) [zigpy.appdb] [0xfcdf:1:0x0000] Attribute id: 5 value: TRADFRI bulb E27 WW 806lm
2020-08-23 10:47:35 DEBUG (MainThread) [zigpy.appdb] [0x698e:11:0x0000] Attribute id: 4 value: ShenZhen_Homa
2020-08-23 10:47:35 DEBUG (MainThread) [zigpy.appdb] [0x698e:11:0x0000] Attribute id: 5 value: HOMA1008

The deleted GU10 (0xdb26) is not in the zigbee.db = great.

Perhaps its some logic in ZHA that is trying paring the device after it was deleted and i think the IKEA ZB3 devices don't deleting the network credentials then ZHA is deleting them and (i think) sending one lieve command so its trying rejoining the network but its cant then the TC-link key is not longer valid = right done from the TC. I saying all looks good and bellows is on track !! I should testing more pairing and deleting with other devices like homa (chinese ZB3) and xiaomi sensors. Its not so easy than my HA is in production and getting the log rel spamed with debug aktive. Testing device rejoining is not so easy but coming later than paring is tested. I think the clearKeyTable is not needed in your implantation.

Very good work done !!!!!!!!!!!!!

MattWestb commented 3 years ago

I think i have finding the first bellows 2 bug !!!!!

One real ZB3 problem found with the IKEAs new motion sensor (ZB3 one). The HA paring log:

[0x0000:zdo] ZDO request ZDOCmd.Mgmt_Permit_Joining_req: [60, <Bool.false: 0>]
Device 0x20bc (14:b4:57:ff:fe:d4:d0:31) joined the network
Device 14:b4:57:ff:fe:d4:d0:31 changed id (0x8fc4 => 0x20bc)
[0x20bc] Requesting 'Node Descriptor'
Tries remaining: 2
[0x20bc] Extending timeout for 0x4a request
Device 0x20bc (14:b4:57:ff:fe:d4:d0:31) joined the network
Skip initialization for existing device 14:b4:57:ff:fe:d4:d0:31
Device 0x20bc (14:b4:57:ff:fe:d4:d0:31) joined the network
Skip initialization for existing device 14:b4:57:ff:fe:d4:d0:31
[0x20bc:zdo] ZDO request ZDOCmd.Device_annce: [0x20bc, 14:b4:57:ff:fe:d4:d0:31, 128]
[0x20bc:zdo] ZDO request ZDOCmd.Node_Desc_req: [0x0000]
[0x20bc:zdo] Unsupported ZDO request:ZDOCmd.Node_Desc_req
Device 0x20bc (14:b4:57:ff:fe:d4:d0:31) left the network
Device 0x20bc (14:b4:57:ff:fe:d4:d0:31) joined the network
Skip initialization for existing device 14:b4:57:ff:fe:d4:d0:31

The device is starting paring and is in the network and having NWK and the initial TC link key and sending one [0x20bc:zdo] ZDO request ZDOCmd.Device_annce: [0x20bc, 14:b4:57:ff:fe:d4:d0:31, 128] = ZB3 standard. Next is sending one [0x20bc:zdo] ZDO request ZDOCmd.Node_Desc_req: [0x0000] for checking if the TC is ZB3(>R21). The TC is sending [0x20bc:zdo] Unsupported ZDO request:ZDOCmd.Node_Desc_req That is false (if the NCP is ZBB3 and if not its true and ZB3 devices cant joining the network for to low security by ZB3 standard and leaving the network) !!! Because of that its cant getting one new TC-link key and the initial TC-link key is expired and leaving the network = by ZB3 standard and the paring is failing for 110%.

From the UG100: EZSP Reference Guide EZSP_VALUE_ENABLE_R21_BEHAVIOR 0x29 Setting this byte enables R21 behavior on the NCP must being un set. And the "EZSP" funktion is described under "Name: updateTcLinkKey ID: 0x006C Description: Requests a new link key from the Trust Center. This function starts by sending a Node Descriptor request to the Trust Center to verify its R21+ stack version compliance. A Request Key message will then be sent, followed by a Verify Key Confirm message. Command Parameters: uint8_t maxAttempts The maximum number of attempts a node should make when sending the Node Descriptor, Request Key, and Verify Key Confirm messages. The number of attempts resets for each message type sent (e.g., if maxAttempts is 3, up to 3 Node Descriptors are sent, up to 3 Request Keys, and up to 3 Verify Key Confirm messages are sent). Response Parameters: EmberStatus status The success or failure of sending the request. If the Node Descriptor is successfully transmitted, ezspZigbeeKeyEstablishmentHandler(...) will be called at a later time with a fina The workflow is good described in the "AN1233: Zigbee Security" under "3.3.3 Requesting a New Link Key after Joining". I think also Application Link Keys (APS) must being enabled in TC for it suld working then the [0x20bc:zdo] ZDO request ZDOCmd.Node_Desc_req: [0x0000] can going thru routers and need "private" encryption channel to TC using APS.

Interesting things is happening :-))))

Adminiuga commented 3 years ago

The TC is sending [0x20bc:zdo] Unsupported ZDO request:ZDOCmd.Node_Desc_req

That is not the device checking TC level. That's zigpy query ing the device. You need to enable bellows.zigbee.application: debug and bellows.ezsp: debug to see what's happening

MattWestb commented 3 years ago

I have:

logger:
  default: info
  logs:
    homeassistant.core: debug
    homeassistant.components.zha: debug
    bellows.zigbee.application: debug
    bellows.ezsp: debug
    zigpy: debug
    bellows.zigbee.application: debug
    bellows.ezsp: debug
#    zigpy_cc: debug
#    zigpy_deconz.zigbee.application: debug
#    zigpy_deconz.api: debug
#    zigpy_xbee.zigbee.application: debug
#    zigpy_xbee.api: debug
#    zigpy_zigate: debug
#    zhaquirks: debug

Can i taking more away so not spamming the log so much ? Or do you have more that can being good putting in for bellows ?

MattWestb commented 3 years ago

New tyre with better debug setting:

2020-08-23 15:02:07 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] ZDO request ZDOCmd.Mgmt_Permit_Joining_req: [60, <Bool.false: 0>]
2020-08-23 15:02:08 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'75f9b1a96b2a134ea6944a13aa5592499c4e27d3b9ce6787f47e'
2020-08-23 15:02:08 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2020-08-23 15:02:08 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'06fcff0000360000000000000078540000'
2020-08-23 15:02:08 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_BROADCAST: 6>, 65532, EmberApsFrame(profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_NONE: 0>, groupId=0, sequence=120), 84, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:02:08 DEBUG (MainThread) [bellows.ezsp.protocol] Send command permitJoining: (60,)
2020-08-23 15:02:08 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'50fe21a9762a29876c7e'
2020-08-23 15:02:08 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'06fea1a9762a1519d17e'
2020-08-23 15:02:08 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2020-08-23 15:02:08 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 34 (permitJoining) received: b'00'
2020-08-23 15:02:15 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2020-08-23 15:02:15 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'61ff21a9512a94567e'
2020-08-23 15:02:15 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'17ffa1a9512a81137e'
2020-08-23 15:02:15 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2020-08-23 15:02:15 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''
2020-08-23 15:02:21 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'27ffb1a9772a14b3669c7bf57eab6d1e285a23cfbc7e'
2020-08-23 15:02:21 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2020-08-23 15:02:21 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 35 (childJoinHandler) received: b'01013f0831d0d4feff57b41404'
2020-08-23 15:02:21 DEBUG (MainThread) [bellows.zigbee.application] Received childJoinHandler frame with [1, <Bool.true: 1>, 0x083f, 14:b4:57:ff:fe:d4:d0:31, <EmberNodeType.SLEEPY_END_DEVICE: 4>]
2020-08-23 15:02:21 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'37ffb1a9702a2aba68449edb5502265d9d4e27abfe9e7e'
2020-08-23 15:02:21 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2020-08-23 15:02:21 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 36 (trustCenterJoinHandler) received: b'3f0831d0d4feff57b41401000000'
2020-08-23 15:02:21 DEBUG (MainThread) [bellows.zigbee.application] Received trustCenterJoinHandler frame with [0x083f, 14:b4:57:ff:fe:d4:d0:31, <EmberDeviceUpdate.STANDARD_SECURITY_UNSECURED_JOIN: 1>, <EmberJoinDecision.USE_PRECONFIGURED_KEY: 0>, 0x0000]
2020-08-23 15:02:21 INFO (MainThread) [zigpy.application] Device 0x083f (14:b4:57:ff:fe:d4:d0:31) joined the network
2020-08-23 15:02:21 DEBUG (MainThread) [zigpy.application] Device 14:b4:57:ff:fe:d4:d0:31 changed id (0xa8a8 => 0x083f)
2020-08-23 15:02:21 DEBUG (MainThread) [bellows.ezsp.protocol] Send command findKeyTableEntry: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:02:21 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'74fc21a9212a24628d6ab5721e4193a02c7e'
2020-08-23 15:02:21 INFO (MainThread) [zigpy.device] [0x083f] Requesting 'Node Descriptor'
2020-08-23 15:02:21 DEBUG (MainThread) [zigpy.util] Tries remaining: 2
2020-08-23 15:02:21 DEBUG (MainThread) [zigpy.device] [0x083f] Extending timeout for 0x55 request
2020-08-23 15:02:21 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:d4:d0:31/0x083f
2020-08-23 15:02:21 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:02:21 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'40fca1a9212aea2bf67e'
2020-08-23 15:02:21 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2020-08-23 15:02:21 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'05fd21a92a2a24628d6ab5721e419356527e'
2020-08-23 15:02:21 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 117 (findKeyTableEntry) received: b'ff'
2020-08-23 15:02:21 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'51fda1a92a2af6c27e'
2020-08-23 15:02:21 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2020-08-23 15:02:21 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2020-08-23 15:02:21 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x083f, EmberApsFrame(profileId=0, clusterId=2, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=85), 86, b'U?\x08')
2020-08-23 15:02:21 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'168221a9602a158d51944a27aa5592099d4e27febbcd32b4f5fa707e'
2020-08-23 15:02:22 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6282a1a9602a15c9729c7e'
2020-08-23 15:02:22 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2020-08-23 15:02:22 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'007b'
2020-08-23 15:02:23 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7282b1a9772a14b3669c7bf57eab6d1e285a23a5d37e'
2020-08-23 15:02:23 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2020-08-23 15:02:23 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 35 (childJoinHandler) received: b'01013f0831d0d4feff57b41404'
2020-08-23 15:02:23 DEBUG (MainThread) [bellows.zigbee.application] Received childJoinHandler frame with [1, <Bool.true: 1>, 0x083f, 14:b4:57:ff:fe:d4:d0:31, <EmberNodeType.SLEEPY_END_DEVICE: 4>]
2020-08-23 15:02:23 INFO (MainThread) [homeassistant.components.esphome] Can't connect to ESPHome API for 192.168.2.122: Error connecting to ('192.168.2.122', 6053): [Errno 113] Connect call failed ('192.168.2.122', 6053)
2020-08-23 15:02:23 INFO (MainThread) [homeassistant.components.esphome] Trying to reconnect to 192.168.2.122 in 60 seconds
2020-08-23 15:02:23 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0282b1a9702a2aba68449edb5502265d9d4e27ab37b97e'
2020-08-23 15:02:23 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2020-08-23 15:02:23 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 36 (trustCenterJoinHandler) received: b'3f0831d0d4feff57b41401000000'
2020-08-23 15:02:23 DEBUG (MainThread) [bellows.zigbee.application] Received trustCenterJoinHandler frame with [0x083f, 14:b4:57:ff:fe:d4:d0:31, <EmberDeviceUpdate.STANDARD_SECURITY_UNSECURED_JOIN: 1>, <EmberJoinDecision.USE_PRECONFIGURED_KEY: 0>, 0x0000]
2020-08-23 15:02:23 INFO (MainThread) [zigpy.application] Device 0x083f (14:b4:57:ff:fe:d4:d0:31) joined the network
2020-08-23 15:02:23 DEBUG (MainThread) [zigpy.application] Skip initialization for existing device 14:b4:57:ff:fe:d4:d0:31
2020-08-23 15:02:23 DEBUG (MainThread) [bellows.ezsp.protocol] Send command findKeyTableEntry: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:02:23 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'218321a9212a24628d6ab5721e41937d3a0b7e'
2020-08-23 15:02:23 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'1383a1a9212aea997c7e'
2020-08-23 15:02:23 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2020-08-23 15:02:23 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 117 (findKeyTableEntry) received: b'ff'
2020-08-23 15:02:23 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'2383b5a9362a24628d6ab5721e41102c7e'
2020-08-23 15:02:23 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2020-08-23 15:02:23 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 98 (incomingSenderEui64Handler) received: b'31d0d4feff57b414'
2020-08-23 15:02:23 DEBUG (MainThread) [bellows.zigbee.application] Received incomingSenderEui64Handler frame with [14:b4:57:ff:fe:d4:d0:31]
2020-08-23 15:02:23 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'3383b1a9112a11b259874a25aa5596499c0dd85ad2c69874f1475c81cdaeeb59149a6a7b0ffd16957e'
2020-08-23 15:02:23 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2020-08-23 15:02:23 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'040000130000000004000043fff13f08ffff0c813f0831d0d4feff57b4148002'
2020-08-23 15:02:23 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_BROADCAST: 4>, EmberApsFrame(profileId=0, clusterId=19, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_SOURCE_EUI64: 1024>, groupId=0, sequence=67), 255, -15, 0x083f, 255, 255, b'\x81?\x081\xd0\xd4\xfe\xffW\xb4\x14\x80']
2020-08-23 15:02:23 INFO (MainThread) [bellows.zigbee.application] ZDO Device announce: 0x083f, 14:b4:57:ff:fe:d4:d0:31
2020-08-23 15:02:23 INFO (MainThread) [zigpy.application] Device 0x083f (14:b4:57:ff:fe:d4:d0:31) joined the network
2020-08-23 15:02:23 DEBUG (MainThread) [zigpy.application] Skip initialization for existing device 14:b4:57:ff:fe:d4:d0:31
2020-08-23 15:02:23 DEBUG (MainThread) [zigpy.zdo] [0x083f:zdo] ZDO request ZDOCmd.Device_annce: [0x083f, 14:b4:57:ff:fe:d4:d0:31, 128]
2020-08-23 15:02:24 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4383b1a96b2a134fa6944a36aa559249984e27e8edce67a7cc7e'
2020-08-23 15:02:24 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2020-08-23 15:02:24 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'06fdff0000130000000004000043000000'
2020-08-23 15:02:24 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_BROADCAST: 6>, 65533, EmberApsFrame(profileId=0, clusterId=19, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_SOURCE_EUI64: 1024>, groupId=0, sequence=67), 0, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:02:24 DEBUG (MainThread) [bellows.zigbee.application] Unexpected message send notification tag: 0
2020-08-23 15:02:25 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2020-08-23 15:02:25 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'358021a9512a9a1c7e'
2020-08-23 15:02:25 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5480a1a9512a5d9c7e'
2020-08-23 15:02:25 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2020-08-23 15:02:25 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''
2020-08-23 15:02:26 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6480b1a9112a15b259964a25aa1593499c0ad85ad2c69874fec76389fe85357e'
2020-08-23 15:02:26 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2020-08-23 15:02:26 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'000000020000004001000044fff13f08ffff0301000002'
2020-08-23 15:02:26 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=2, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=68), 255, -15, 0x083f, 255, 255, b'\x01\x00\x00']
2020-08-23 15:02:26 DEBUG (MainThread) [zigpy.zdo] [0x083f:zdo] ZDO request ZDOCmd.Node_Desc_req: [0x0000]
2020-08-23 15:02:26 DEBUG (MainThread) [zigpy.zdo] [0x083f:zdo] Unsupported ZDO request:ZDOCmd.Node_Desc_req
2020-08-23 15:02:26 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7480b1a9cf2a24628d6ab5721e419421e97e'
2020-08-23 15:02:26 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2020-08-23 15:02:26 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 155 (zigbeeKeyEstablishmentHandler) received: b'31d0d4feff57b41406'
2020-08-23 15:02:26 DEBUG (MainThread) [bellows.zigbee.application] Received zigbeeKeyEstablishmentHandler frame with [14:b4:57:ff:fe:d4:d0:31, <EmberKeyStatus.TC_RESPONDED_TO_KEY_REQUEST: 6>]
2020-08-23 15:02:30 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0480b5a9772a14b2669c7bf57eab6d1e285a2360fe7e'
2020-08-23 15:02:30 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2020-08-23 15:02:30 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 35 (childJoinHandler) received: b'01003f0831d0d4feff57b41404'
2020-08-23 15:02:30 DEBUG (MainThread) [bellows.zigbee.application] Received childJoinHandler frame with [1, <Bool.false: 0>, 0x083f, 14:b4:57:ff:fe:d4:d0:31, <EmberNodeType.SLEEPY_END_DEVICE: 4>]
2020-08-23 15:02:30 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'1480b1a9702a2aba68449edb5502265d9e4dd85492dc7e'
2020-08-23 15:02:30 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2020-08-23 15:02:30 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 36 (trustCenterJoinHandler) received: b'3f0831d0d4feff57b4140203ffff'
2020-08-23 15:02:30 DEBUG (MainThread) [bellows.zigbee.application] Received trustCenterJoinHandler frame with [0x083f, 14:b4:57:ff:fe:d4:d0:31, <EmberDeviceUpdate.DEVICE_LEFT: 2>, <EmberJoinDecision.NO_ACTION: 3>, 0xffff]
2020-08-23 15:02:30 INFO (MainThread) [zigpy.application] Device 0x083f (14:b4:57:ff:fe:d4:d0:31) left the network
2020-08-23 15:02:35 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2020-08-23 15:02:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'428121a9512abd907e'
2020-08-23 15:02:35 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'2581a1a9512af7f17e'
2020-08-23 15:02:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2020-08-23 15:02:35 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''
2020-08-23 15:02:45 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2020-08-23 15:02:45 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'538621a9512a85607e'
2020-08-23 15:02:45 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'3686a1a9512a44417e'
2020-08-23 15:02:45 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2020-08-23 15:02:45 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''
2020-08-23 15:02:55 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2020-08-23 15:02:55 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'648721a9512ac8fc7e'
2020-08-23 15:02:55 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4787a1a9512aee2c7e'
2020-08-23 15:02:55 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2020-08-23 15:02:55 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''
2020-08-23 15:03:02 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5787b1a9772a14b3669c7bf57eab6d1e285a2353ff7e'
2020-08-23 15:03:02 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2020-08-23 15:03:02 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 35 (childJoinHandler) received: b'01013f0831d0d4feff57b41404'
2020-08-23 15:03:02 DEBUG (MainThread) [bellows.zigbee.application] Received childJoinHandler frame with [1, <Bool.true: 1>, 0x083f, 14:b4:57:ff:fe:d4:d0:31, <EmberNodeType.SLEEPY_END_DEVICE: 4>]
2020-08-23 15:03:03 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6787b1a9702a2aba68449edb5502265d9d4e27ab290d7e'
2020-08-23 15:03:03 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2020-08-23 15:03:03 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 36 (trustCenterJoinHandler) received: b'3f0831d0d4feff57b41401000000'
2020-08-23 15:03:03 DEBUG (MainThread) [bellows.zigbee.application] Received trustCenterJoinHandler frame with [0x083f, 14:b4:57:ff:fe:d4:d0:31, <EmberDeviceUpdate.STANDARD_SECURITY_UNSECURED_JOIN: 1>, <EmberJoinDecision.USE_PRECONFIGURED_KEY: 0>, 0x0000]
2020-08-23 15:03:03 INFO (MainThread) [zigpy.application] Device 0x083f (14:b4:57:ff:fe:d4:d0:31) joined the network
2020-08-23 15:03:03 DEBUG (MainThread) [zigpy.application] Skip initialization for existing device 14:b4:57:ff:fe:d4:d0:31
2020-08-23 15:03:03 DEBUG (MainThread) [bellows.ezsp.protocol] Send command findKeyTableEntry: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:03:03 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'778421a9212a24628d6ab5721e4193d8e57e'
2020-08-23 15:03:03 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7084a1a9212aea3aa57e'
2020-08-23 15:03:03 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2020-08-23 15:03:03 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 117 (findKeyTableEntry) received: b'ff'
2020-08-23 15:03:05 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2020-08-23 15:03:05 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'008521a9512ad5c67e'
2020-08-23 15:03:06 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0185a1a9512a4d5e7e'
2020-08-23 15:03:06 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2020-08-23 15:03:06 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''
2020-08-23 15:03:16 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2020-08-23 15:03:16 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'7d318a21a9512aef1b7e'
2020-08-23 15:03:16 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'128aa1a9512afcc37e'
2020-08-23 15:03:16 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2020-08-23 15:03:16 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''

Router statistics, ESPHome devices deCONZ and Tradfri GW is cutted out.

MattWestb commented 3 years ago

Then i don't knowing what i'm doing i did trying changing this key from 4 to 8 and restarting HA. (pi@PI3BPlus:/usr/share/hassio/homeassistant/deps/lib/python3.8/site-packages/bellows/ezsp/v8 $)

    #
    # The size of the Key Table used for storing individual link keys (if the device
    # is a Trust Center) or Application Link Keys (if the device is a normal node)
    vol.Optional(EzspConfigId.CONFIG_KEY_TABLE_SIZE.name, default=8): vol.All(
        int, vol.Range(min=0)
    ),  

And then trying paring the new motion sensor:

2020-08-23 15:43:58 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] ZDO request ZDOCmd.Mgmt_Permit_Joining_req: [60, <Bool.false: 0>]
2020-08-23 15:43:59 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6410b1a96b2a134ea6944a13aa5592499c4e2751d6ce67639a7e'
2020-08-23 15:43:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2020-08-23 15:43:59 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'06fcff00003600000000000000fa3b0000'
2020-08-23 15:43:59 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_BROADCAST: 6>, 65532, EmberApsFrame(profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_NONE: 0>, groupId=0, sequence=250), 59, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:43:59 DEBUG (MainThread) [bellows.ezsp.protocol] Send command permitJoining: (60,)
2020-08-23 15:43:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'477d3121a9762a29e7687e'
2020-08-23 15:43:59 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7511a1a9762a150b097e'
2020-08-23 15:43:59 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2020-08-23 15:43:59 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 34 (permitJoining) received: b'00'
2020-08-23 15:44:02 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0511b1a90d2aca4ef900cadb5502265d63a427526b7e'
2020-08-23 15:44:02 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2020-08-23 15:44:02 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 89 (incomingRouteRecordHandler) received: b'dffca09480feff57b414ffea00'
2020-08-23 15:44:02 DEBUG (MainThread) [bellows.zigbee.application] Received incomingRouteRecordHandler frame with [0xfcdf, 14:b4:57:ff:fe:80:94:a0, 255, -22, []]
2020-08-23 15:44:02 DEBUG (MainThread) [bellows.zigbee.application] Processing route record request: (0xfcdf, 14:b4:57:ff:fe:80:94:a0, 255, -22, [])
2020-08-23 15:44:02 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'1511b1a9112a15b658924a24ab5593499c60d84132329874face4c83fc7e2fa7e909817e'
2020-08-23 15:44:02 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2020-08-23 15:44:02 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'00040106000101000100002effeadffcffff07082f0a0000100002'
2020-08-23 15:44:02 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=46), 255, -22, 0xfcdf, 255, 255, b'\x08/\n\x00\x00\x10\x00']
2020-08-23 15:44:02 DEBUG (MainThread) [zigpy.zcl] [0xfcdf:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=False> manufacturer=None tsn=47 command_id=Command.Report_Attributes>
2020-08-23 15:44:02 DEBUG (MainThread) [zigpy.zcl] [0xfcdf:1:0x0006] ZCL request 0x000a: [[<Attribute attrid=0 value=<TypeValue type=Bool, value=Bool.false>>]]
2020-08-23 15:44:02 DEBUG (MainThread) [zigpy.zcl] [0xfcdf:1:0x0006] Attribute report received: on_off=0
2020-08-23 15:44:02 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0xfcdf, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=47), 60, b'\x18/\x0b\n\x00')
2020-08-23 15:44:02 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'521621a9602a156da5904b23aa5493099d4e2784d1cb7fa4f6cc63a7337e'
2020-08-23 15:44:03 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'2616a1a9602a154947ed7e'
2020-08-23 15:44:03 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2020-08-23 15:44:03 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'00fb'
2020-08-23 15:44:03 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'3616b1a90d2aca4ef900cadb5502265d63a42780597e'
2020-08-23 15:44:03 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2020-08-23 15:44:03 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 89 (incomingRouteRecordHandler) received: b'dffca09480feff57b414ffea00'
2020-08-23 15:44:03 DEBUG (MainThread) [bellows.zigbee.application] Received incomingRouteRecordHandler frame with [0xfcdf, 14:b4:57:ff:fe:80:94:a0, 255, -22, []]
2020-08-23 15:44:03 DEBUG (MainThread) [bellows.zigbee.application] Processing route record request: (0xfcdf, 14:b4:57:ff:fe:80:94:a0, 255, -22, [])
2020-08-23 15:44:03 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4616b1a96b2a156da5904b23aa5493099d4e2750d1ce6742647e'
2020-08-23 15:44:03 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2020-08-23 15:44:03 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'00dffc04010600010140010000fb3c0000'
2020-08-23 15:44:03 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 64735, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=251), 60, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:05 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2020-08-23 15:44:05 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'651721a9512aabd67e'
2020-08-23 15:44:05 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5717a1a9512ad2227e'
2020-08-23 15:44:05 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2020-08-23 15:44:05 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''
2020-08-23 15:44:15 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6717b1a9772a15b328937bf57eab6d1e285a2312857e'
2020-08-23 15:44:15 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2020-08-23 15:44:15 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 35 (childJoinHandler) received: b'0001710731d0d4feff57b41404'
2020-08-23 15:44:15 DEBUG (MainThread) [bellows.zigbee.application] Received childJoinHandler frame with [0, <Bool.true: 1>, 0x0771, 14:b4:57:ff:fe:d4:d0:31, <EmberNodeType.SLEEPY_END_DEVICE: 4>]
2020-08-23 15:44:15 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2020-08-23 15:44:15 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'771421a9512ad4c07e'
2020-08-23 15:44:15 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7717b1a9702a64b568449edb5502265d9d4e27abea2b7e'
2020-08-23 15:44:15 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2020-08-23 15:44:15 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 36 (trustCenterJoinHandler) received: b'710731d0d4feff57b41401000000'
2020-08-23 15:44:15 DEBUG (MainThread) [bellows.zigbee.application] Received trustCenterJoinHandler frame with [0x0771, 14:b4:57:ff:fe:d4:d0:31, <EmberDeviceUpdate.STANDARD_SECURITY_UNSECURED_JOIN: 1>, <EmberJoinDecision.USE_PRECONFIGURED_KEY: 0>, 0x0000]
2020-08-23 15:44:15 INFO (MainThread) [zigpy.application] Device 0x0771 (14:b4:57:ff:fe:d4:d0:31) joined the network
2020-08-23 15:44:15 DEBUG (MainThread) [bellows.ezsp.protocol] Send command findKeyTableEntry: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:15 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0014a1a9512a84257e'
2020-08-23 15:44:15 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2020-08-23 15:44:15 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''
2020-08-23 15:44:15 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'011521a9212a24628d6ab5721e41931df17e'
2020-08-23 15:44:15 INFO (MainThread) [zigpy.device] [0x0771] Requesting 'Node Descriptor'
2020-08-23 15:44:15 DEBUG (MainThread) [zigpy.util] Tries remaining: 2
2020-08-23 15:44:15 DEBUG (MainThread) [zigpy.device] [0x0771] Extending timeout for 0x3d request
2020-08-23 15:44:15 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:d4:d0:31/0x0771
2020-08-23 15:44:15 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:15 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'1115a1a9212aeabada7e'
2020-08-23 15:44:15 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2020-08-23 15:44:15 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 117 (findKeyTableEntry) received: b'ff'
2020-08-23 15:44:15 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'127d3a21a92a2a24628d6ab5721e4193f1477e'
2020-08-23 15:44:15 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'221aa1a92a2a21667e'
2020-08-23 15:44:15 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2020-08-23 15:44:15 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2020-08-23 15:44:15 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0771, EmberApsFrame(profileId=0, clusterId=2, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=61), 62, b'=q\x07')
2020-08-23 15:44:15 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'231b21a9602a15c35e944a27aa5592099d4e2796d3cd5afafa332d7e'
2020-08-23 15:44:16 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'331ba1a9602a154c88487e'
2020-08-23 15:44:16 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2020-08-23 15:44:16 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'00fe'
2020-08-23 15:44:17 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'431bb1a9772a15b328937bf57eab6d1e285a233be87e'
2020-08-23 15:44:17 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2020-08-23 15:44:17 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 35 (childJoinHandler) received: b'0001710731d0d4feff57b41404'
2020-08-23 15:44:17 DEBUG (MainThread) [bellows.zigbee.application] Received childJoinHandler frame with [0, <Bool.true: 1>, 0x0771, 14:b4:57:ff:fe:d4:d0:31, <EmberNodeType.SLEEPY_END_DEVICE: 4>]
2020-08-23 15:44:17 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'531bb1a9702a64b568449edb5502265d9d4e27ab32607e'
2020-08-23 15:44:17 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2020-08-23 15:44:17 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 36 (trustCenterJoinHandler) received: b'710731d0d4feff57b41401000000'
2020-08-23 15:44:17 DEBUG (MainThread) [bellows.zigbee.application] Received trustCenterJoinHandler frame with [0x0771, 14:b4:57:ff:fe:d4:d0:31, <EmberDeviceUpdate.STANDARD_SECURITY_UNSECURED_JOIN: 1>, <EmberJoinDecision.USE_PRECONFIGURED_KEY: 0>, 0x0000]
2020-08-23 15:44:17 INFO (MainThread) [zigpy.application] Device 0x0771 (14:b4:57:ff:fe:d4:d0:31) joined the network
2020-08-23 15:44:17 DEBUG (MainThread) [zigpy.application] Skip initialization for existing device 14:b4:57:ff:fe:d4:d0:31
2020-08-23 15:44:17 DEBUG (MainThread) [bellows.ezsp.protocol] Send command findKeyTableEntry: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:17 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'367d3821a9212a24628d6ab5721e4193db577e'
2020-08-23 15:44:17 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6418a1a9212aea095f7e'
2020-08-23 15:44:17 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2020-08-23 15:44:17 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 117 (findKeyTableEntry) received: b'ff'
2020-08-23 15:44:17 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7418b5a9362a24628d6ab5721e41ea897e'
2020-08-23 15:44:17 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2020-08-23 15:44:17 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 98 (incomingSenderEui64Handler) received: b'31d0d4feff57b414'
2020-08-23 15:44:17 DEBUG (MainThread) [bellows.zigbee.application] Received incomingSenderEui64Handler frame with [14:b4:57:ff:fe:d4:d0:31]
2020-08-23 15:44:17 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0418b1a9112a11b259874a25aa5596499c94d8459cc99874f147128ecdaeeb59149a6a7b0ffd71667e'
2020-08-23 15:44:17 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2020-08-23 15:44:17 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0400001300000000040000daffee7107ffff0c81710731d0d4feff57b4148002'
2020-08-23 15:44:17 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_BROADCAST: 4>, EmberApsFrame(profileId=0, clusterId=19, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_SOURCE_EUI64: 1024>, groupId=0, sequence=218), 255, -18, 0x0771, 255, 255, b'\x81q\x071\xd0\xd4\xfe\xffW\xb4\x14\x80']
2020-08-23 15:44:17 INFO (MainThread) [bellows.zigbee.application] ZDO Device announce: 0x0771, 14:b4:57:ff:fe:d4:d0:31
2020-08-23 15:44:17 INFO (MainThread) [zigpy.application] Device 0x0771 (14:b4:57:ff:fe:d4:d0:31) joined the network
2020-08-23 15:44:17 DEBUG (MainThread) [zigpy.application] Skip initialization for existing device 14:b4:57:ff:fe:d4:d0:31
2020-08-23 15:44:17 DEBUG (MainThread) [zigpy.zdo] [0x0771:zdo] ZDO request ZDOCmd.Device_annce: [0x0771, 14:b4:57:ff:fe:d4:d0:31, 128]
2020-08-23 15:44:18 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'1418b1a96b2a134fa6944a36aa559249984e2771edce67a7827e'
2020-08-23 15:44:18 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2020-08-23 15:44:18 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'06fdff00001300000000040000da000000'
2020-08-23 15:44:18 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_BROADCAST: 6>, 65533, EmberApsFrame(profileId=0, clusterId=19, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_SOURCE_EUI64: 1024>, groupId=0, sequence=218), 0, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:18 DEBUG (MainThread) [bellows.zigbee.application] Unexpected message send notification tag: 0
2020-08-23 15:44:21 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'2418b1a9112a15b259964a25aa1593499c95d8459cc99874fec76389fed7c37e'
2020-08-23 15:44:21 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2020-08-23 15:44:21 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0000000200000040010000dbffee7107ffff0301000002'
2020-08-23 15:44:21 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=2, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=219), 255, -18, 0x0771, 255, 255, b'\x01\x00\x00']
2020-08-23 15:44:21 DEBUG (MainThread) [zigpy.zdo] [0x0771:zdo] ZDO request ZDOCmd.Node_Desc_req: [0x0000]
2020-08-23 15:44:21 DEBUG (MainThread) [zigpy.zdo] [0x0771:zdo] Unsupported ZDO request:ZDOCmd.Node_Desc_req
2020-08-23 15:44:21 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'3418b1a9cf2a24628d6ab5721e419471027e'
2020-08-23 15:44:21 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2020-08-23 15:44:21 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 155 (zigbeeKeyEstablishmentHandler) received: b'31d0d4feff57b41406'
2020-08-23 15:44:21 DEBUG (MainThread) [bellows.zigbee.application] Received zigbeeKeyEstablishmentHandler frame with [14:b4:57:ff:fe:d4:d0:31, <EmberKeyStatus.TC_RESPONDED_TO_KEY_REQUEST: 6>]
2020-08-23 15:44:25 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2020-08-23 15:44:25 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'441921a9512a14d67e'
2020-08-23 15:44:25 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4519a1a9512a8c4e7e'
2020-08-23 15:44:25 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2020-08-23 15:44:25 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''
2020-08-23 15:44:26 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5519b1a9112a15b25996ca25aa1593499c90d8459cc99874ecfb63f8fb7c7f2797dc8c3d8fffeb89d5d26b0c6a7e'
2020-08-23 15:44:26 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2020-08-23 15:44:26 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0000000280000040010000deffee7107ffff113d0071070240807c11525200002c52000002'
2020-08-23 15:44:26 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6519b1a96b2a15c35e944a27aa5592099d4e2755d3ce67d7f07e'
2020-08-23 15:44:26 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2020-08-23 15:44:26 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=32770, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=222), 255, -18, 0x0771, 255, 255, b'=\x00q\x07\x02@\x80|\x11RR\x00\x00,R\x00\x00']
2020-08-23 15:44:26 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'00710700000200000040010000fe3e0000'
2020-08-23 15:44:26 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 1905, EmberApsFrame(profileId=0, clusterId=2, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=254), 62, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:26 INFO (MainThread) [zigpy.device] [0x0771] Node Descriptor: <Optional byte1=2 byte2=64 mac_capability_flags=128 manufacturer_code=4476 maximum_buffer_size=82 maximum_incoming_transfer_size=82 server_mask=11264 maximum_outgoing_transfer_size=82 descriptor_capability_field=0>
2020-08-23 15:44:26 INFO (MainThread) [zigpy.device] [0x0771] Discovering endpoints
2020-08-23 15:44:26 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2020-08-23 15:44:26 DEBUG (MainThread) [zigpy.device] [0x0771] Extending timeout for 0x3f request
2020-08-23 15:44:26 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:d4:d0:31/0x0771
2020-08-23 15:44:26 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:26 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'571e21a92a2a24628d6ab5721e41937d33a57e'
2020-08-23 15:44:26 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'761ea1a92a2ade557e'
2020-08-23 15:44:26 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2020-08-23 15:44:26 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2020-08-23 15:44:26 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0771, EmberApsFrame(profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=63), 64, b'?q\x07')
2020-08-23 15:44:26 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'601f21a9602a15c35e944a20aa5592099d4e2794adcd58fafa09e57e'
2020-08-23 15:44:26 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'071fa1a9602a15b64e6a7e'
2020-08-23 15:44:26 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2020-08-23 15:44:26 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0004'
2020-08-23 15:44:27 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'171fb1a9112a15b25991ca25aa1593499c91d8459cc99874fbf963f8fb7f3ea59ae97e'
2020-08-23 15:44:27 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2020-08-23 15:44:27 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0000000580000040010000dfffee7107ffff063f007107010102'
2020-08-23 15:44:27 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'271fb1a96b2a15c35e944a20aa5592099d4e27afadce679c6b7e'
2020-08-23 15:44:27 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2020-08-23 15:44:27 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=32773, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=223), 255, -18, 0x0771, 255, 255, b'?\x00q\x07\x01\x01']
2020-08-23 15:44:27 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'0071070000050000004001000004400000'
2020-08-23 15:44:27 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 1905, EmberApsFrame(profileId=0, clusterId=5, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=4), 64, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:27 INFO (MainThread) [zigpy.device] [0x0771] Discovered endpoints: [1]
2020-08-23 15:44:27 INFO (MainThread) [zigpy.endpoint] [0x0771:1] Discovering endpoint information
2020-08-23 15:44:27 DEBUG (MainThread) [zigpy.util] Tries remaining: 3
2020-08-23 15:44:27 DEBUG (MainThread) [zigpy.device] [0x0771] Extending timeout for 0x41 request
2020-08-23 15:44:27 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:d4:d0:31/0x0771
2020-08-23 15:44:27 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:27 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'731c21a92a2a24628d6ab5721e4193e3c17e'
2020-08-23 15:44:27 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'301ca1a92a2a7d277e'
2020-08-23 15:44:27 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2020-08-23 15:44:27 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2020-08-23 15:44:27 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0771, EmberApsFrame(profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=65), 66, b'Aq\x07\x01')
2020-08-23 15:44:27 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'041d21a9602a15c35e944a21aa5592099d4e27eaafca26fafac7907f7e'
2020-08-23 15:44:27 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'401cb1a9112a11b259a24a25aa5592499caed8459cc99874fec4d788fe97fd7e'
2020-08-23 15:44:27 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2020-08-23 15:44:27 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0400003600000000000000e0ffee7107ffff0302b40102'
2020-08-23 15:44:27 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_BROADCAST: 4>, EmberApsFrame(profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_NONE: 0>, groupId=0, sequence=224), 255, -18, 0x0771, 255, 255, b'\x02\xb4\x01']
2020-08-23 15:44:27 DEBUG (MainThread) [zigpy.zdo] [0x0771:zdo] ZDO request ZDOCmd.Mgmt_Permit_Joining_req: [180, <Bool.true: 1>]
2020-08-23 15:44:27 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'501cb1a9112a11b658974a24555593499cafd8459cc99874fec76388feffa57e'
2020-08-23 15:44:27 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2020-08-23 15:44:27 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'040401030001ff00010000e1ffee7107ffff0301000102'
2020-08-23 15:44:27 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'611da1a9602a15b733db7e'
2020-08-23 15:44:27 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2020-08-23 15:44:27 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_BROADCAST: 4>, EmberApsFrame(profileId=260, clusterId=3, sourceEndpoint=1, destinationEndpoint=255, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=225), 255, -18, 0x0771, 255, 255, b'\x01\x00\x01']
2020-08-23 15:44:27 DEBUG (MainThread) [zigpy.device] Ignoring message (b'010001') on cluster 3: unknown endpoint or cluster id: 'No cluster ID 0x0003 on (14:b4:57:ff:fe:d4:d0:31, 1)'
2020-08-23 15:44:27 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0005'
2020-08-23 15:44:28 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'711db1a96b2a134ea6944a13aa5592499c4e274bedce6760887e'
2020-08-23 15:44:28 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2020-08-23 15:44:28 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'06fcff00003600000000000000e0000000'
2020-08-23 15:44:28 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_BROADCAST: 6>, 65532, EmberApsFrame(profileId=0, clusterId=54, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_NONE: 0>, groupId=0, sequence=224), 0, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:28 DEBUG (MainThread) [bellows.zigbee.application] Unexpected message send notification tag: 0
2020-08-23 15:44:28 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'011db1a96b2a134da6904b26aa546d499d4e274aedce67dbbd7e'
2020-08-23 15:44:28 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2020-08-23 15:44:28 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'06ffff0401030001ff00010000e1000000'
2020-08-23 15:44:28 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_BROADCAST: 6>, 65535, EmberApsFrame(profileId=260, clusterId=3, sourceEndpoint=1, destinationEndpoint=255, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=225), 0, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:28 DEBUG (MainThread) [bellows.zigbee.application] Unexpected message send notification tag: 0
2020-08-23 15:44:28 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'111db1a9112a15b25990ca25aa1593499cacd8459cc99874da8763f8fb5c3ea3ea9dd66e88ffc7dad5d169854603a9ec664759ec768245984a261bb1f970380c0cff8a7e'
2020-08-23 15:44:28 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2020-08-23 15:44:28 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0000000480000040010000e2ffee7107ffff274100710722010401500801070000010003000900200000107cfc0603000400060008001900001002'
2020-08-23 15:44:28 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'211db1a96b2a15c35e944a21aa5592099d4e27aeafce6712617e'
2020-08-23 15:44:28 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2020-08-23 15:44:28 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=32772, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=226), 255, -18, 0x0771, 255, 255, b'A\x00q\x07"\x01\x04\x01P\x08\x01\x07\x00\x00\x01\x00\x03\x00\t\x00 \x00\x00\x10|\xfc\x06\x03\x00\x04\x00\x06\x00\x08\x00\x19\x00\x00\x10']
2020-08-23 15:44:28 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'0071070000040000004001000005420000'
2020-08-23 15:44:28 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 1905, EmberApsFrame(profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=5), 66, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:28 INFO (MainThread) [zigpy.endpoint] [0x0771:1] Discovered endpoint information: <Optional endpoint=1 profile=260 device_type=2128 device_version=1 input_clusters=[0, 1, 3, 9, 32, 4096, 64636] output_clusters=[3, 4, 6, 8, 25, 4096]>
2020-08-23 15:44:28 DEBUG (MainThread) [zigpy.device] [0x0771] Extending timeout for 0x43 request
2020-08-23 15:44:28 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:d4:d0:31/0x0771
2020-08-23 15:44:28 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:28 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'7d332221a92a2a24628d6ab5721e4193efe87e'
2020-08-23 15:44:28 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'3222a1a92a2a35217e'
2020-08-23 15:44:28 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2020-08-23 15:44:28 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2020-08-23 15:44:28 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0771, EmberApsFrame(profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=67), 68, b'\x00C\x00\x04\x00\x05\x00')
2020-08-23 15:44:28 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'242321a9602a15c35e904b25aa5493099d4e27e8a9c967c8fdc2638cfcc1c87e'
2020-08-23 15:44:28 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4323a1a9602a15b49c737e'
2020-08-23 15:44:28 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2020-08-23 15:44:28 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0006'
2020-08-23 15:44:29 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5323b1a9112a15b658944a24ab1593499cadd8459cc99874cdde2088f87e3fe5e584952acedfa8bdf5811ee92246c7e9763be7ff21d000dc0a745a918d1f4c7561699b96af0bf92ae84f35977e'
2020-08-23 15:44:29 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2020-08-23 15:44:29 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0004010000010140010000e3ffee7107ffff30184301040000420e494b4541206f662053776564656e050000421554524144465249206d6f74696f6e2073656e736f7202'
2020-08-23 15:44:29 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6323b1a96b2a15c35e904b25aa5493099d4e27ada9ce67f41e7e'
2020-08-23 15:44:29 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2020-08-23 15:44:29 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=227), 255, -18, 0x0771, 255, 255, b'\x18C\x01\x04\x00\x00B\x0eIKEA of Sweden\x05\x00\x00B\x15TRADFRI motion sensor']
2020-08-23 15:44:29 DEBUG (MainThread) [zigpy.zcl] [0x0771: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=67 command_id=Command.Read_Attributes_rsp>
2020-08-23 15:44:29 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'0071070401000001014001000006440000'
2020-08-23 15:44:29 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 1905, EmberApsFrame(profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=6), 68, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:29 DEBUG (MainThread) [zigpy.endpoint] [0x0771:1] Manufacturer: IKEA of Sweden
2020-08-23 15:44:29 DEBUG (MainThread) [zigpy.endpoint] [0x0771:1] Model: TRADFRI motion sensor
2020-08-23 15:44:29 DEBUG (MainThread) [zigpy.quirks.registry] Checking quirks for IKEA of Sweden TRADFRI motion sensor (14:b4:57:ff:fe:d4:d0:31)
2020-08-23 15:44:29 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.ikea.motion.IkeaTradfriMotion'>
2020-08-23 15:44:29 DEBUG (MainThread) [zigpy.quirks.registry] Fail because profile_id mismatch on at least one endpoint
2020-08-23 15:44:29 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.ikea.motionzha.IkeaTradfriMotion'>
2020-08-23 15:44:29 DEBUG (MainThread) [zigpy.quirks.registry] Fail because input cluster mismatch on at least one endpoint
2020-08-23 15:44:29 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.ikea.motionzha.IkeaTradfriMotionE1745'>
2020-08-23 15:44:29 DEBUG (MainThread) [zigpy.quirks.registry] Found custom device replacement for 14:b4:57:ff:fe:d4:d0:31: <class 'zhaquirks.ikea.motionzha.IkeaTradfriMotionE1745'>
2020-08-23 15:44:29 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event device_registry_updated[L]: action=create, device_id=0b2d3e0612cb4c55888eaf23733bfb88>
2020-08-23 15:44:29 DEBUG (MainThread) [homeassistant.components.zha.core.gateway] device - 0x0771:14:b4:57:ff:fe:d4:d0:31 entering async_device_initialized - is_new_join: True
2020-08-23 15:44:29 DEBUG (MainThread) [homeassistant.components.zha.core.gateway] device - 0x0771:14:b4:57:ff:fe:d4:d0:31 has joined the ZHA zigbee network
2020-08-23 15:44:29 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0771](TRADFRI motion sensor): started configuration
2020-08-23 15:44:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:ZDO](TRADFRI motion sensor): 'async_configure' stage succeeded
2020-08-23 15:44:29 DEBUG (MainThread) [zigpy.device] [0x0771] Extending timeout for 0x45 request
2020-08-23 15:44:29 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:d4:d0:31/0x0771
2020-08-23 15:44:29 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:29 DEBUG (MainThread) [zigpy.device] [0x0771] Extending timeout for 0x47 request
2020-08-23 15:44:29 DEBUG (MainThread) [zigpy.device] [0x0771] Extending timeout for 0x49 request
2020-08-23 15:44:29 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'372021a92a2a24628d6ab5721e41931f8c7e'
2020-08-23 15:44:29 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7420a1a92a2a96537e'
2020-08-23 15:44:29 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2020-08-23 15:44:29 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2020-08-23 15:44:29 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0771, EmberApsFrame(profileId=260, clusterId=4096, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=69), 70, b'\x01EA\x00')
2020-08-23 15:44:29 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'402121a9602a15c35e904b25ba5493099d4e27eeabca66cebcc65c857e'
2020-08-23 15:44:29 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0521a1a9602a15b59aaa7e'
2020-08-23 15:44:29 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2020-08-23 15:44:29 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0007'
2020-08-23 15:44:29 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:d4:d0:31/0x0771
2020-08-23 15:44:29 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:29 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'512621a92a2a24628d6ab5721e4193759d7e'
2020-08-23 15:44:30 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'1626a1a92a2a8f8e7e'
2020-08-23 15:44:30 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2020-08-23 15:44:30 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2020-08-23 15:44:30 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0771, EmberApsFrame(profileId=260, clusterId=32, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=71), 72, b'\x00G\x02\x00\x00#\x903\x00\x00')
2020-08-23 15:44:30 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'622721a9602a15c35e904b05aa5493099d4e27eca5c467ccffc663aa6c4d3fa7198f7e'
2020-08-23 15:44:30 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'2727a1a9602a15ba3eae7e'
2020-08-23 15:44:30 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2020-08-23 15:44:30 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0008'
2020-08-23 15:44:30 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:d4:d0:31/0x0771
2020-08-23 15:44:30 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:30 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'732421a92a2a24628d6ab5721e419353927e'
2020-08-23 15:44:30 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'3727b1a9112a15b658945a24ab1593499caad8459cc99874fbdf26c8fd7e3fa57f0e7e'
2020-08-23 15:44:30 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2020-08-23 15:44:30 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0004010010010140010000e4ffee7107ffff0619454101000002'
2020-08-23 15:44:30 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4727b1a96b2a15c35e904b25ba5493099d4e27acabce67fa577e'
2020-08-23 15:44:30 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2020-08-23 15:44:30 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=4096, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=228), 255, -18, 0x0771, 255, 255, b'\x19EA\x01\x00\x00']
2020-08-23 15:44:30 DEBUG (MainThread) [zigpy.zcl] [0x0771:1:0x1000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=CLUSTER_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=69 command_id=65>
2020-08-23 15:44:30 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5727b1a9112a15b658b44a24ab1593499cabd8459cc99874f9de248dfc7c23907e'
2020-08-23 15:44:30 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2020-08-23 15:44:30 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'0071070401001001014001000007460000'
2020-08-23 15:44:30 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 1905, EmberApsFrame(profileId=260, clusterId=4096, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=7), 70, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:30 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6727b1a96b2a15c35e904b05aa5493099d4e27a3a5ce676ec97e'
2020-08-23 15:44:30 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2020-08-23 15:44:30 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7024a1a92a2a19f47e'
2020-08-23 15:44:30 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2020-08-23 15:44:30 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0004012000010140010000e5ffee7107ffff041847040002'
2020-08-23 15:44:30 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=32, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=229), 255, -18, 0x0771, 255, 255, b'\x18G\x04\x00']
2020-08-23 15:44:30 DEBUG (MainThread) [zigpy.zcl] [0x0771:1:0x0020] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=71 command_id=Command.Write_Attributes_rsp>
2020-08-23 15:44:30 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'0071070401200001014001000008480000'
2020-08-23 15:44:30 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 1905, EmberApsFrame(profileId=260, clusterId=32, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=8), 72, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:30 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2020-08-23 15:44:30 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0771, EmberApsFrame(profileId=0, clusterId=33, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=73), 74, b'I1\xd0\xd4\xfe\xffW\xb4\x14\x01\x00\x00\x03\x19\xb3\xb9\xfe\xff\xcc\xcc\xcc\x01')
2020-08-23 15:44:30 WARNING (MainThread) [zhaquirks.ikea] unable to locate required group info - falling back to group 0x0000.
2020-08-23 15:44:30 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x1000]: bound 'lightlink' cluster: None
2020-08-23 15:44:30 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x1000]: finished channel configuration
2020-08-23 15:44:30 DEBUG (MainThread) [zigpy.device] [0x0771] Extending timeout for 0x4b request
2020-08-23 15:44:30 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'002521a9602a15c35e944a04aa5592099d4e27e2a7d82eba2d129d76abca2ba6ebcddd763c463924191ea58db7bb7e'
2020-08-23 15:44:30 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0020]: 3300.0s check-in interval set: [[<WriteAttributesStatusRecord status=Status.SUCCESS>]]
2020-08-23 15:44:30 DEBUG (MainThread) [zigpy.device] [0x0771] Extending timeout for 0x4d request
2020-08-23 15:44:30 INFO (MainThread) [homeassistant.components.esphome] Can't connect to ESPHome API for 192.168.2.122: Error connecting to ('192.168.2.122', 6053): [Errno 113] Connect call failed ('192.168.2.122', 6053)
2020-08-23 15:44:30 INFO (MainThread) [homeassistant.components.esphome] Trying to reconnect to 192.168.2.122 in 60 seconds
2020-08-23 15:44:30 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0125a1a9602a15bbb5cf7e'
2020-08-23 15:44:30 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2020-08-23 15:44:30 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0009'
2020-08-23 15:44:30 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:d4:d0:31/0x0771
2020-08-23 15:44:30 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:30 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'7d312a21a92a2a24628d6ab5721e4193495a7e'
2020-08-23 15:44:30 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'122aa1a92a2a02047e'
2020-08-23 15:44:30 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2020-08-23 15:44:30 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2020-08-23 15:44:30 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0771, EmberApsFrame(profileId=0, clusterId=33, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=75), 76, b'K1\xd0\xd4\xfe\xffW\xb4\x14\x01\x01\x00\x03\x19\xb3\xb9\xfe\xff\xcc\xcc\xcc\x01')
2020-08-23 15:44:30 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'222b21a9602a15c35e944a04aa5592099d4e27e0a1d82cba2d129d76abca2ba6eacddd763c463924191ea58dae627e'
2020-08-23 15:44:31 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'232ba1a9602a15b843ea7e'
2020-08-23 15:44:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2020-08-23 15:44:31 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'000a'
2020-08-23 15:44:31 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:d4:d0:31/0x0771
2020-08-23 15:44:31 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'332821a92a2a24628d6ab5721e41936f557e'
2020-08-23 15:44:31 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'332bb1a9112a15b259b5ca25aa1593499ca8d8459cc99874ff8f638bf7ec7e'
2020-08-23 15:44:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2020-08-23 15:44:31 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4428a1a92a2abbf27e'
2020-08-23 15:44:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2020-08-23 15:44:31 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0000002180000040010000e6ffee7107ffff02490002'
2020-08-23 15:44:31 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=32801, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=230), 255, -18, 0x0771, 255, 255, b'I\x00']
2020-08-23 15:44:31 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5428b1a96b2a15c35e944a04aa5592099d4e27a2a7ce67f9c57e'
2020-08-23 15:44:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2020-08-23 15:44:31 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2020-08-23 15:44:31 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0771, EmberApsFrame(profileId=0, clusterId=33, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=77), 78, b'M1\xd0\xd4\xfe\xffW\xb4\x14\x01 \x00\x03\x19\xb3\xb9\xfe\xff\xcc\xcc\xcc\x01')
2020-08-23 15:44:31 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6428b1a9112a15b259b5ca25aa1593499ca9d8459cc99874ff8d638b5ca87e'
2020-08-23 15:44:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2020-08-23 15:44:31 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'00710700002100000040010000094a0000'
2020-08-23 15:44:31 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7428b1a96b2a15c35e944a04aa5592099d4e27a1a1ce67b0557e'
2020-08-23 15:44:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2020-08-23 15:44:31 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 1905, EmberApsFrame(profileId=0, clusterId=33, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=9), 74, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:31 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0000002180000040010000e7ffee7107ffff024b0002'
2020-08-23 15:44:31 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=32801, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=231), 255, -18, 0x0771, 255, 255, b'K\x00']
2020-08-23 15:44:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'402921a9602a15c35e944a04aa5592099d4e27e6a3d82aba2d129d76abca2ba6cbcddd763c463924191ea58d838d7e'
2020-08-23 15:44:31 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'007107000021000000400100000a4c0000'
2020-08-23 15:44:31 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 1905, EmberApsFrame(profileId=0, clusterId=33, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=10), 76, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:31 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0000]: bound 'basic' cluster: Status.SUCCESS
2020-08-23 15:44:31 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0000]: finished channel configuration
2020-08-23 15:44:31 DEBUG (MainThread) [zigpy.device] [0x0771] Extending timeout for 0x4f request
2020-08-23 15:44:31 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0001]: bound 'power' cluster: Status.SUCCESS
2020-08-23 15:44:31 DEBUG (MainThread) [zigpy.device] [0x0771] Extending timeout for 0x51 request
2020-08-23 15:44:31 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0529a1a9602a15b9c88b7e'
2020-08-23 15:44:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2020-08-23 15:44:31 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'000b'
2020-08-23 15:44:31 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:d4:d0:31/0x0771
2020-08-23 15:44:31 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'512e21a92a2a24628d6ab5721e41939ef67e'
2020-08-23 15:44:31 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'162ea1a92a2a8da37e'
2020-08-23 15:44:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2020-08-23 15:44:31 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2020-08-23 15:44:31 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0771, EmberApsFrame(profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=79), 80, b'\x00O\x00\x07\x00')
2020-08-23 15:44:31 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'622f21a9602a15c35e904b25aa5493099d4e27e4bdcb67c4fdc16373827e'
2020-08-23 15:44:32 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'272fa1a9602a15beed877e'
2020-08-23 15:44:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2020-08-23 15:44:32 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'000c'
2020-08-23 15:44:32 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:d4:d0:31/0x0771
2020-08-23 15:44:32 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'732c21a92a2a24628d6ab5721e4193b8f97e'
2020-08-23 15:44:32 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'372fb1a9112a15b259b5ca25aa1593499ca6d8459cc99874ff8b638bbf9e7e'
2020-08-23 15:44:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2020-08-23 15:44:32 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0000002180000040010000e8ffee7107ffff024d0002'
2020-08-23 15:44:32 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'472fb1a96b2a15c35e944a04aa5592099d4e27a0a3ce67462f7e'
2020-08-23 15:44:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2020-08-23 15:44:32 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=32801, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=232), 255, -18, 0x0771, 255, 255, b'M\x00']
2020-08-23 15:44:32 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'007107000021000000400100000b4e0000'
2020-08-23 15:44:32 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 1905, EmberApsFrame(profileId=0, clusterId=33, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=11), 78, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:32 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0020]: bound 'poll_control' cluster: Status.SUCCESS
2020-08-23 15:44:32 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0020]: finished channel configuration
2020-08-23 15:44:32 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'572fb1a9112a15b658944a24ab1593499ca7d8459cc99874f5de2c88fb7e3f97e8cfb1087e'
2020-08-23 15:44:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2020-08-23 15:44:32 DEBUG (MainThread) [zigpy.device] [0x0771] Extending timeout for 0x53 request
2020-08-23 15:44:32 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'672fb1a96b2a15c35e904b25aa5493099d4e27a7bdce677ef97e'
2020-08-23 15:44:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2020-08-23 15:44:32 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'702ca1a92a2a1bd97e'
2020-08-23 15:44:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2020-08-23 15:44:32 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0004010000010140010000e9ffee7107ffff08184f01070000300302'
2020-08-23 15:44:32 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=233), 255, -18, 0x0771, 255, 255, b'\x18O\x01\x07\x00\x000\x03']
2020-08-23 15:44:32 DEBUG (MainThread) [zigpy.zcl] [0x0771: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=79 command_id=Command.Read_Attributes_rsp>
2020-08-23 15:44:32 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'007107040100000101400100000c500000'
2020-08-23 15:44:32 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 1905, EmberApsFrame(profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=12), 80, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:32 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2020-08-23 15:44:32 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0771, EmberApsFrame(profileId=260, clusterId=1, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=81), 82, b'\x00Q\x06\x00 \x00 \x10\x0e0*\x01')
2020-08-23 15:44:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'002d21a9602a15c35e904b24aa5493099d4e27fabfc267dafbc64389dc6e3197c1cc656e7e'
2020-08-23 15:44:32 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0000]: initializing channel: from_cache: False
2020-08-23 15:44:32 DEBUG (MainThread) [zigpy.device] [0x0771] Extending timeout for 0x55 request
2020-08-23 15:44:32 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'012da1a9602a15bf66e67e'
2020-08-23 15:44:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2020-08-23 15:44:32 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'000d'
2020-08-23 15:44:32 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:d4:d0:31/0x0771
2020-08-23 15:44:32 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'7d313221a92a2a24628d6ab5721e419364c67e'
2020-08-23 15:44:32 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'1232a1a92a2a04737e'
2020-08-23 15:44:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2020-08-23 15:44:32 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2020-08-23 15:44:32 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0771, EmberApsFrame(profileId=0, clusterId=33, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=83), 84, b'S1\xd0\xd4\xfe\xffW\xb4\x14\x01\x06\x00\x03\x19\xb3\xb9\xfe\xff\xcc\xcc\xcc\x01')
2020-08-23 15:44:32 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'223321a9602a15c35e944a04aa5592099d4e27f8b9d834ba2d129d76abca2ba6edcddd763c463924191ea58d17d57e'
2020-08-23 15:44:33 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'2333a1a9602a15bca7b87e'
2020-08-23 15:44:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2020-08-23 15:44:33 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'000e'
2020-08-23 15:44:33 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:d4:d0:31/0x0771
2020-08-23 15:44:33 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'333021a92a2a24628d6ab5721e419342c97e'
2020-08-23 15:44:33 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'3430a1a92a2af8197e'
2020-08-23 15:44:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2020-08-23 15:44:33 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2020-08-23 15:44:33 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0771, EmberApsFrame(profileId=0, clusterId=33, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=85), 86, b'U1\xd0\xd4\xfe\xffW\xb4\x14\x01\x08\x00\x03\x19\xb3\xb9\xfe\xff\xcc\xcc\xcc\x01')
2020-08-23 15:44:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'443121a9602a15c35e944a04aa5592099d4e27febbd832ba2d129d76abca2ba6e3cddd763c463924191ea58d48e87e'
2020-08-23 15:44:33 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4531a1a9602a15bdda097e'
2020-08-23 15:44:33 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2020-08-23 15:44:33 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'000f'
2020-08-23 15:44:34 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5531b1a9112a15b658954a24ab1593499ca4d8459cc99874f9ce328efc7cb41c7e'
2020-08-23 15:44:34 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2020-08-23 15:44:34 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6531b1a96b2a15c35e904b24aa5493099d4e27a6bfce67305a7e'
2020-08-23 15:44:34 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2020-08-23 15:44:34 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0004010100010140010000eaffee7107ffff040851070002'
2020-08-23 15:44:34 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=1, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=234), 255, -18, 0x0771, 255, 255, b'\x08Q\x07\x00']
2020-08-23 15:44:34 DEBUG (MainThread) [zigpy.zcl] [0x0771:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=81 command_id=Command.Configure_Reporting_rsp>
2020-08-23 15:44:34 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7531b1a9112a15b259b5ca25aa1593499ca5d8459cc99874ff95638bf0227e'
2020-08-23 15:44:34 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2020-08-23 15:44:34 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'007107040101000101400100000d520000'
2020-08-23 15:44:34 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0531b1a96b2a15c35e944a04aa5592099d4e27a5b9ce67ea127e'
2020-08-23 15:44:34 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2020-08-23 15:44:34 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 1905, EmberApsFrame(profileId=260, clusterId=1, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=13), 82, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:34 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0000002180000040010000ebffee7107ffff02530002'
2020-08-23 15:44:34 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=32801, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=235), 255, -18, 0x0771, 255, 255, b'S\x00']
2020-08-23 15:44:34 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'1531b1a9112a15b259b5ca25aa1593499ca2d8459cc99874ff93638b0d127e'
2020-08-23 15:44:34 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2020-08-23 15:44:34 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'2531b1a96b2a15c35e944a04aa5592099d4e27a4bbce67922a7e'
2020-08-23 15:44:34 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2020-08-23 15:44:34 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'007107000021000000400100000e540000'
2020-08-23 15:44:34 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 1905, EmberApsFrame(profileId=0, clusterId=33, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=14), 84, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:34 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0000002180000040010000ecffee7107ffff02550002'
2020-08-23 15:44:34 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=32801, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=236), 255, -18, 0x0771, 255, 255, b'U\x00']
2020-08-23 15:44:34 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'007107000021000000400100000f560000'
2020-08-23 15:44:34 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 1905, EmberApsFrame(profileId=0, clusterId=33, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=15), 86, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:34 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0001]: reporting 'battery_voltage' attr on 'power' cluster: 3600/10800/1: Result: '[[<ConfigureReportingResponseRecord status=Status.SUCCESS>]]'
2020-08-23 15:44:34 DEBUG (MainThread) [zigpy.device] [0x0771] Extending timeout for 0x57 request
2020-08-23 15:44:34 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:d4:d0:31/0x0771
2020-08-23 15:44:34 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:34 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0006]: bound 'on_off' cluster: Status.SUCCESS
2020-08-23 15:44:34 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0006]: finished channel configuration
2020-08-23 15:44:34 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'533621a92a2a24628d6ab5721e4193feb37e'
2020-08-23 15:44:34 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0008]: bound 'level' cluster: Status.SUCCESS
2020-08-23 15:44:34 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0008]: finished channel configuration
2020-08-23 15:44:34 DEBUG (MainThread) [zigpy.device] [0x0771] Extending timeout for 0x59 request
2020-08-23 15:44:34 DEBUG (MainThread) [zigpy.device] [0x0771] Extending timeout for 0x5b request
2020-08-23 15:44:34 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'3636a1a92a2abedc7e'
2020-08-23 15:44:34 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2020-08-23 15:44:34 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2020-08-23 15:44:34 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0771, EmberApsFrame(profileId=260, clusterId=1, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=87), 88, b'\x00W\x06\x00!\x00 \x10\x0e0*\x01')
2020-08-23 15:44:34 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'643721a9602a15c35e904b24aa5493099d4e27fcb5c267dcfbc64289dc6e3197c1ccca5f7e'
2020-08-23 15:44:34 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4737a1a9602a15a217547e'
2020-08-23 15:44:34 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2020-08-23 15:44:34 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0010'
2020-08-23 15:44:34 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:d4:d0:31/0x0771
2020-08-23 15:44:34 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:34 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'753421a92a2a24628d6ab5721e4193430e7e'
2020-08-23 15:44:35 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5034a1a92a2a28a67e'
2020-08-23 15:44:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2020-08-23 15:44:35 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2020-08-23 15:44:35 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0771, EmberApsFrame(profileId=0, clusterId=33, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=89), 90, b'Y1\xd0\xd4\xfe\xffW\xb4\x14\x01\x06\x00\x03\x19\xb3\xb9\xfe\xff\xcc\xcc\xcc\x01')
2020-08-23 15:44:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'063521a9602a15c35e944a04aa5592099d4e27f2b7d83eba2d129d76abca2ba6edcddd763c463924191ea58d127b7e'
2020-08-23 15:44:35 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6135a1a9602a15a39c357e'
2020-08-23 15:44:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2020-08-23 15:44:35 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0011'
2020-08-23 15:44:35 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:d4:d0:31/0x0771
2020-08-23 15:44:35 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'173a21a92a2a24628d6ab5721e419359c67e'
2020-08-23 15:44:35 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2020-08-23 15:44:35 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'723aa1a92a2a59467e'
2020-08-23 15:44:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2020-08-23 15:44:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'203b21a9512a01587e'
2020-08-23 15:44:35 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2020-08-23 15:44:35 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0771, EmberApsFrame(profileId=0, clusterId=33, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=91), 92, b'[1\xd0\xd4\xfe\xffW\xb4\x14\x01\x19\x00\x03\x19\xb3\xb9\xfe\xff\xcc\xcc\xcc\x01')
2020-08-23 15:44:35 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'033ba1a9512a27887e'
2020-08-23 15:44:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2020-08-23 15:44:35 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'313821a9602a15c35e944a04aa5592099d4e27f0b1d83cba2d129d76abca2ba6f2cddd763c463924191ea58de5c37e'
2020-08-23 15:44:35 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''
2020-08-23 15:44:36 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'1438a1a9602a15a0beee7e'
2020-08-23 15:44:36 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2020-08-23 15:44:36 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0012'
2020-08-23 15:44:37 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'2438b1a9112a15b658954a24ab1593499ca3d8459cc99874f9ce348efc7c92107e'
2020-08-23 15:44:37 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2020-08-23 15:44:37 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'3438b1a96b2a15c35e904b24aa5493099d4e27bbb5ce6772647e'
2020-08-23 15:44:37 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2020-08-23 15:44:37 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0004010100010140010000edffee7107ffff040857070002'
2020-08-23 15:44:37 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=1, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=237), 255, -18, 0x0771, 255, 255, b'\x08W\x07\x00']
2020-08-23 15:44:37 DEBUG (MainThread) [zigpy.zcl] [0x0771:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=87 command_id=Command.Configure_Reporting_rsp>
2020-08-23 15:44:37 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'0071070401010001014001000010580000'
2020-08-23 15:44:37 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4438b1a9112a15b259b5ca25aa1593499ca0d8459cc99874ff9f638b9f297e'
2020-08-23 15:44:37 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2020-08-23 15:44:37 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 1905, EmberApsFrame(profileId=260, clusterId=1, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=16), 88, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:37 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5438b1a96b2a15c35e944a04aa5592099d4e27bab7ce6799847e'
2020-08-23 15:44:37 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2020-08-23 15:44:37 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0000002180000040010000eeffee7107ffff02590002'
2020-08-23 15:44:37 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=32801, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=238), 255, -18, 0x0771, 255, 255, b'Y\x00']
2020-08-23 15:44:37 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'00710700002100000040010000115a0000'
2020-08-23 15:44:37 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 1905, EmberApsFrame(profileId=0, clusterId=33, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=17), 90, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:37 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0001]: reporting 'battery_percentage_remaining' attr on 'power' cluster: 3600/10800/1: Result: '[[<ConfigureReportingResponseRecord status=Status.SUCCESS>]]'
2020-08-23 15:44:37 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0001]: finished channel configuration
2020-08-23 15:44:37 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6438b1a9112a15b259b5ca25aa1593499ca1d8459cc99874ff9d638bfb047e'
2020-08-23 15:44:37 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2020-08-23 15:44:37 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7438b1a96b2a15c35e944a04aa5592099d4e27b9b1ce67d0147e'
2020-08-23 15:44:37 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2020-08-23 15:44:37 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0000002180000040010000efffee7107ffff025b0002'
2020-08-23 15:44:37 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=32801, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=239), 255, -18, 0x0771, 255, 255, b'[\x00']
2020-08-23 15:44:37 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'00710700002100000040010000125c0000'
2020-08-23 15:44:37 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 1905, EmberApsFrame(profileId=0, clusterId=33, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=18), 92, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:37 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0006]: bound 'on_off' cluster: Status.SUCCESS
2020-08-23 15:44:37 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0006]: finished channel configuration
2020-08-23 15:44:37 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0019]: bound 'ota' cluster: Status.SUCCESS
2020-08-23 15:44:37 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0019]: finished channel configuration
2020-08-23 15:44:37 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x1000]: 'async_configure' stage succeeded
2020-08-23 15:44:37 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0020]: 'async_configure' stage succeeded
2020-08-23 15:44:37 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0000]: 'async_configure' stage succeeded
2020-08-23 15:44:37 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0001]: 'async_configure' stage succeeded
2020-08-23 15:44:37 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0006]: 'async_configure' stage succeeded
2020-08-23 15:44:37 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0008]: 'async_configure' stage succeeded
2020-08-23 15:44:37 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0006]: 'async_configure' stage succeeded
2020-08-23 15:44:37 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0019]: 'async_configure' stage succeeded
2020-08-23 15:44:37 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0771](TRADFRI motion sensor): completed configuration
2020-08-23 15:44:37 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0771](TRADFRI motion sensor): stored in registry: ZhaDeviceEntry(name='IKEA of Sweden TRADFRI motion sensor', ieee='14:b4:57:ff:fe:d4:d0:31', last_seen=1598190277.6375015)
2020-08-23 15:44:37 DEBUG (MainThread) [zigpy.device] [0x0771] Extending timeout for 0x5d request
2020-08-23 15:44:37 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:d4:d0:31/0x0771
2020-08-23 15:44:37 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:37 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'403921a92a2a24628d6ab5721e4193c8717e'
2020-08-23 15:44:37 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0539a1a92a2a3a497e'
2020-08-23 15:44:37 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2020-08-23 15:44:37 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2020-08-23 15:44:37 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0771, EmberApsFrame(profileId=260, clusterId=3, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=93), 94, b'\x01]@\x02\x00')
2020-08-23 15:44:37 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'513e21a9602a15c35e904b26aa5493099d4e27f6b3cb66d6bdc4639bc17e'
2020-08-23 15:44:38 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'163ea1a9602a15a1804c7e'
2020-08-23 15:44:38 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2020-08-23 15:44:38 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0013'
2020-08-23 15:44:39 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'263eb1a9112a15b658974a24ab1593499cbed8459cc99874f8ce3e82bcff3dfc477e'
2020-08-23 15:44:39 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2020-08-23 15:44:39 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'363eb1a96b2a15c35e904b26aa5493099d4e27b8b3ce67eb157e'
2020-08-23 15:44:39 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2020-08-23 15:44:39 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0004010300010140010000f0ffee7107ffff05085d0b408102'
2020-08-23 15:44:39 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=3, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=240), 255, -18, 0x0771, 255, 255, b'\x08]\x0b@\x81']
2020-08-23 15:44:39 DEBUG (MainThread) [zigpy.zcl] [0x0771:1:0x0003] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=False> manufacturer=None tsn=93 command_id=Command.Default_Response>
2020-08-23 15:44:39 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'00710704010300010140010000135e0000'
2020-08-23 15:44:39 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 1905, EmberApsFrame(profileId=260, clusterId=3, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=19), 94, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:39 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0003]: executed 'trigger_effect' command with args: '(2, 0)' kwargs: '{}' result: [64, <Status.UNSUP_CLUSTER_COMMAND: 129>]
2020-08-23 15:44:39 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0771](TRADFRI motion sensor): started initialization
2020-08-23 15:44:39 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:ZDO](TRADFRI motion sensor): 'async_initialize' stage succeeded
2020-08-23 15:44:39 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x1000]: initializing channel: from_cache: False
2020-08-23 15:44:39 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0020]: initializing channel: from_cache: False
2020-08-23 15:44:39 DEBUG (MainThread) [zigpy.device] [0x0771] Extending timeout for 0x5f request
2020-08-23 15:44:39 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:d4:d0:31/0x0771
2020-08-23 15:44:39 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:39 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'643f21a92a2a24628d6ab5721e4193c5b07e'
2020-08-23 15:44:39 DEBUG (MainThread) [zigpy.device] [0x0771] Extending timeout for 0x61 request
2020-08-23 15:44:39 DEBUG (MainThread) [zigpy.device] [0x0771] Extending timeout for 0x63 request
2020-08-23 15:44:40 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'473fa1a92a2a169c7e'
2020-08-23 15:44:40 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2020-08-23 15:44:40 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2020-08-23 15:44:40 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0771, EmberApsFrame(profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=95), 96, b'\x00_\x00\x07\x00')
2020-08-23 15:44:40 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'753c21a9602a15c35e904b25aa5493099d4e27f48dcb67d4fdc163a3b77e'
2020-08-23 15:44:40 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'503ca1a9602a15a6e6537e'
2020-08-23 15:44:40 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2020-08-23 15:44:40 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0014'
2020-08-23 15:44:40 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:d4:d0:31/0x0771
2020-08-23 15:44:40 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:40 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'063d21a92a2a24628d6ab5721e4193c9b67e'
2020-08-23 15:44:40 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'613da1a92a2aeaf67e'
2020-08-23 15:44:40 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2020-08-23 15:44:40 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2020-08-23 15:44:40 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0771, EmberApsFrame(profileId=260, clusterId=1, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=97), 98, b'\x00a\x001\x00!\x00 \x003\x00')
2020-08-23 15:44:40 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'17c221a9602a15c35e904b24aa5493099d4e27ca8fc567eafdf763a8fc5e3f94eb42567e'
2020-08-23 15:44:40 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'713db1a9112a15b658944a24ab1593499cbfd8459cc99874f5de3c88fb7e3f97e8cf9cb37e'
2020-08-23 15:44:40 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2020-08-23 15:44:40 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0004010000010140010000f1ffee7107ffff08185f01070000300302'
2020-08-23 15:44:40 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'013db1a96b2a15c35e904b25aa5493099d4e27bf8dce67ace17e'
2020-08-23 15:44:40 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2020-08-23 15:44:40 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=241), 255, -18, 0x0771, 255, 255, b'\x18_\x01\x07\x00\x000\x03']
2020-08-23 15:44:40 DEBUG (MainThread) [zigpy.zcl] [0x0771: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=95 command_id=Command.Read_Attributes_rsp>
2020-08-23 15:44:40 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'0071070401000001014001000014600000'
2020-08-23 15:44:40 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 1905, EmberApsFrame(profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=20), 96, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0000]: initializing channel: from_cache: False
2020-08-23 15:44:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0008]: initializing channel: from_cache: False
2020-08-23 15:44:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0006]: initializing channel: from_cache: False
2020-08-23 15:44:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0019]: initializing channel: from_cache: False
2020-08-23 15:44:40 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'12c2a1a9602a15a792147e'
2020-08-23 15:44:40 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2020-08-23 15:44:40 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0015'
2020-08-23 15:44:40 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:d4:d0:31/0x0771
2020-08-23 15:44:40 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:40 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'22c321a92a2a24628d6ab5721e419308e57e'
2020-08-23 15:44:41 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'23c3a1a92a2afb587e'
2020-08-23 15:44:41 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2020-08-23 15:44:41 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2020-08-23 15:44:41 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0771, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=99), 100, b'\x00c\x00\x00\x00')
2020-08-23 15:44:41 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'33c021a9602a15c35e904b23aa5493099d4e27c889cb67e8fdc663f5e37e'
2020-08-23 15:44:41 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'34c0a1a9602a15a439377e'
2020-08-23 15:44:41 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2020-08-23 15:44:41 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0016'
2020-08-23 15:44:41 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'44c0b1a9112a15b658954a24ab1593499cbcd8459cc99874eede0288cd7eb986ebcdfe0bafffc7fbd5e1690a4487fb7e'
2020-08-23 15:44:41 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2020-08-23 15:44:41 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0004010100010140010000f2ffee7107ffff131861013100862100002064200000200033008602'
2020-08-23 15:44:41 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'54c0b1a96b2a15c35e904b24aa5493099d4e27be8fce678bf67e'
2020-08-23 15:44:41 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2020-08-23 15:44:41 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=1, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=242), 255, -18, 0x0771, 255, 255, b'\x18a\x011\x00\x86!\x00\x00 d \x00\x00 \x003\x00\x86']
2020-08-23 15:44:41 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'64c0b1a9112a15b658924a24ab1593499cbdd8459cc99874fbde0088fc7eb9a58f327e'
2020-08-23 15:44:41 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2020-08-23 15:44:41 DEBUG (MainThread) [zigpy.zcl] [0x0771:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=97 command_id=Command.Read_Attributes_rsp>
2020-08-23 15:44:41 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'74c0b1a96b2a15c35e904b23aa5493099d4e27bd89ce67ca2d7e'
2020-08-23 15:44:41 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2020-08-23 15:44:41 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'0071070401010001014001000015620000'
2020-08-23 15:44:41 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 1905, EmberApsFrame(profileId=260, clusterId=1, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=21), 98, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:41 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0004010600010140010000f3ffee7107ffff0618630100008602'
2020-08-23 15:44:41 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=243), 255, -18, 0x0771, 255, 255, b'\x18c\x01\x00\x00\x86']
2020-08-23 15:44:41 DEBUG (MainThread) [zigpy.zcl] [0x0771:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=99 command_id=Command.Read_Attributes_rsp>
2020-08-23 15:44:41 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'0071070401060001014001000016640000'
2020-08-23 15:44:41 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 1905, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=22), 100, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:41 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0001]: initializing channel: from_cache: False
2020-08-23 15:44:41 DEBUG (MainThread) [zigpy.device] [0x0771] Extending timeout for 0x65 request
2020-08-23 15:44:41 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:d4:d0:31/0x0771
2020-08-23 15:44:41 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:41 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'40c121a92a2a24628d6ab5721e419304e37e'
2020-08-23 15:44:41 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0006]: initializing channel: from_cache: False
2020-08-23 15:44:41 DEBUG (MainThread) [zigpy.device] [0x0771] Extending timeout for 0x67 request
2020-08-23 15:44:41 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'05c1a1a92a2a07327e'
2020-08-23 15:44:41 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2020-08-23 15:44:41 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2020-08-23 15:44:41 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0771, EmberApsFrame(profileId=260, clusterId=1, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=101), 102, b'\x00e\x00 \x00!\x00')
2020-08-23 15:44:41 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'51c621a9602a15c35e904b24aa5493099d4e27ce8bc967eefde663a8fce0cc7e'
2020-08-23 15:44:42 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'16c6a1a9602a15a57cfd7e'
2020-08-23 15:44:42 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2020-08-23 15:44:42 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0017'
2020-08-23 15:44:42 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 14:b4:57:ff:fe:d4:d0:31/0x0771
2020-08-23 15:44:42 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setExtendedTimeout: (14:b4:57:ff:fe:d4:d0:31, True)
2020-08-23 15:44:42 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'62c721a92a2a24628d6ab5721e4193df497e'
2020-08-23 15:44:42 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'27c7a1a92a2a74ff7e'
2020-08-23 15:44:42 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2020-08-23 15:44:42 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 126 (setExtendedTimeout) received: b''
2020-08-23 15:44:42 DEBUG (MainThread) [bellows.ezsp.protocol] Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0771, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=103), 104, b'\x00g\x00\x00\x00')
2020-08-23 15:44:42 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'73c421a9602a15c35e904b23aa5493099d4e27cc85cb67ecfdc663faf77e'
2020-08-23 15:44:42 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'30c4a1a9602a15aa16527e'
2020-08-23 15:44:42 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2020-08-23 15:44:42 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 52 (sendUnicast) received: b'0018'
2020-08-23 15:44:43 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'40c4b1a9112a15b658954a24ab1593499cbad8459cc99874f0de0688dc7e3f87ebecde6faf9bc58c7a7e'
2020-08-23 15:44:43 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2020-08-23 15:44:43 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0004010100010140010000f4ffee7107ffff0d1865012000002000210000206402'
2020-08-23 15:44:43 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=1, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=244), 255, -18, 0x0771, 255, 255, b'\x18e\x01 \x00\x00 \x00!\x00\x00 d']
2020-08-23 15:44:43 DEBUG (MainThread) [zigpy.zcl] [0x0771:1:0x0001] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=101 command_id=Command.Read_Attributes_rsp>
2020-08-23 15:44:43 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'50c4b1a96b2a15c35e904b24aa5493099d4e27bc8bce6799127e'
2020-08-23 15:44:43 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2020-08-23 15:44:43 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'60c4b1a9112a15b658924a24ab1593499cbbd8459cc99874fbde0488fc7eb9a532277e'
2020-08-23 15:44:43 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2020-08-23 15:44:43 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'0071070401010001014001000017660000'
2020-08-23 15:44:43 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 1905, EmberApsFrame(profileId=260, clusterId=1, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=23), 102, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:43 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0004010600010140010000f5ffee7107ffff0618670100008602'
2020-08-23 15:44:43 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=245), 255, -18, 0x0771, 255, 255, b'\x18g\x01\x00\x00\x86']
2020-08-23 15:44:43 DEBUG (MainThread) [zigpy.zcl] [0x0771:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=103 command_id=Command.Read_Attributes_rsp>
2020-08-23 15:44:43 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'70c4b1a96b2a15c35e904b23aa5493099d4e27b385ce673e5a7e'
2020-08-23 15:44:43 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2020-08-23 15:44:43 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'0071070401060001014001000018680000'
2020-08-23 15:44:43 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 1905, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=24), 104, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:43 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x1000]: 'async_initialize' stage succeeded
2020-08-23 15:44:43 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0020]: 'async_initialize' stage succeeded
2020-08-23 15:44:43 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0000]: 'async_initialize' stage succeeded
2020-08-23 15:44:43 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0001]: 'async_initialize' stage succeeded
2020-08-23 15:44:43 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0006]: 'async_initialize' stage succeeded
2020-08-23 15:44:43 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0008]: 'async_initialize' stage succeeded
2020-08-23 15:44:43 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0006]: 'async_initialize' stage succeeded
2020-08-23 15:44:43 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0019]: 'async_initialize' stage succeeded
2020-08-23 15:44:43 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0771](TRADFRI motion sensor): power source: Battery or Unknown
2020-08-23 15:44:43 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0771](TRADFRI motion sensor): completed initialization
2020-08-23 15:44:43 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event device_registry_updated[L]: action=update, device_id=0b2d3e0612cb4c55888eaf23733bfb88>
2020-08-23 15:44:43 INFO (MainThread) [homeassistant.helpers.entity_registry] Registered new binary_sensor.zha entity: binary_sensor.ikea_of_sweden_tradfri_motion_sensor_31d0d4fe_on_off
2020-08-23 15:44:43 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event entity_registry_updated[L]: action=create, entity_id=binary_sensor.ikea_of_sweden_tradfri_motion_sensor_31d0d4fe_on_off>
2020-08-23 15:44:43 INFO (MainThread) [homeassistant.helpers.entity_registry] Registered new sensor.zha entity: sensor.ikea_of_sweden_tradfri_motion_sensor_31d0d4fe_power
2020-08-23 15:44:43 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event entity_registry_updated[L]: action=create, entity_id=sensor.ikea_of_sweden_tradfri_motion_sensor_31d0d4fe_power>
2020-08-23 15:44:43 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.ikea_of_sweden_tradfri_motion_sensor_31d0d4fe_on_off, old_state=None, new_state=<state binary_sensor.ikea_of_sweden_tradfri_motion_sensor_31d0d4fe_on_off=on; friendly_name=IKEA of Sweden TRADFRI motion sensor 31d0d4fe on_off, device_class=opening @ 2020-08-23T15:44:43.865362+02:00>>
2020-08-23 15:44:43 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.ikea_of_sweden_tradfri_motion_sensor_31d0d4fe_power, old_state=None, new_state=<state sensor.ikea_of_sweden_tradfri_motion_sensor_31d0d4fe_power=unavailable; unit_of_measurement=%, friendly_name=IKEA of Sweden TRADFRI motion sensor 31d0d4fe power, device_class=battery @ 2020-08-23T15:44:43.868166+02:00>>
2020-08-23 15:44:45 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2020-08-23 15:44:45 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'00c521a9512ac4ae7e'
2020-08-23 15:44:46 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'01c5a1a9512a5c367e'
2020-08-23 15:44:46 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2020-08-23 15:44:46 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''
2020-08-23 15:44:47 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event device_registry_updated[L]: action=update, device_id=0b2d3e0612cb4c55888eaf23733bfb88>
2020-08-23 15:44:48 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'11c5b1a9112a17b658924a24555593499cb8d8459cc99874f5c767cbfc7638a7ebcfbc947e'
2020-08-23 15:44:48 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2020-08-23 15:44:48 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'020401060001ff00010000f6ffee7107ffff08010442000807000002'
2020-08-23 15:44:48 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_MULTICAST: 2>, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=255, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=246), 255, -18, 0x0771, 255, 255, b'\x01\x04B\x00\x08\x07\x00\x00']
2020-08-23 15:44:48 DEBUG (MainThread) [zigpy.zcl] [0x0771:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=CLUSTER_COMMAND manufacturer_specific=False is_reply=False disable_default_response=False> manufacturer=None tsn=4 command_id=66>
2020-08-23 15:44:48 DEBUG (MainThread) [zigpy.zcl] [0x0771:1:0x0006] ZCL request 0x0042: [0, 1800, 0]
2020-08-23 15:44:48 DEBUG (MainThread) [zigpy.zcl] [0x0771:1:0x0006] No handler for cluster command 66
2020-08-23 15:44:48 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event zha_event[L]: device_ieee=14:b4:57:ff:fe:d4:d0:31, unique_id=14:b4:57:ff:fe:d4:d0:31:1:0x0006, endpoint_id=1, cluster_id=6, command=on_with_timed_off, args=[0, 1800, 0]>
2020-08-23 15:44:48 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x0771:1:0x0006]: received 'on_with_timed_off' command with [0, 1800, 0] args on cluster_id '6' tsn '4'
2020-08-23 15:44:49 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'21c5b1a96b2a164fa6904b23aa546d499d4e275dedce6760537e'
2020-08-23 15:44:49 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2020-08-23 15:44:49 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'03fdff0401060001ff00010000f6000000'
2020-08-23 15:44:49 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_MULTICAST: 3>, 65533, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=255, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=246), 0, <EmberStatus.SUCCESS: 0>, b'']
2020-08-23 15:44:49 DEBUG (MainThread) [bellows.zigbee.application] Unexpected message send notification tag: 0
2020-08-23 15:44:56 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2020-08-23 15:44:56 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'7d33ca21a9512a75337e'
2020-08-23 15:44:56 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'32caa1a9512ad8a37e'
2020-08-23 15:44:56 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2020-08-23 15:44:56 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''
2020-08-23 15:45:06 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2020-08-23 15:45:06 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'24cb21a9512a38af7e'
2020-08-23 15:45:06 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'43cba1a9512a72ce7e'
2020-08-23 15:45:06 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2020-08-23 15:45:06 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''
2020-08-23 15:45:16 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2020-08-23 15:45:16 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'35c821a9512a89597e'
2020-08-23 15:45:16 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'54c8a1a9512a4ed97e'
2020-08-23 15:45:16 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2020-08-23 15:45:16 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''
2020-08-23 15:45:26 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2020-08-23 15:45:26 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'46c921a9512aa8747e'
2020-08-23 15:45:26 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'65c9a1a9512a8ea47e'
2020-08-23 15:45:26 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2020-08-23 15:45:26 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''
2020-08-23 15:45:36 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2020-08-23 15:45:36 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'57ce21a9512a90847e'
2020-08-23 15:45:36 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'76cea1a9512a3d147e'
2020-08-23 15:45:36 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2020-08-23 15:45:36 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''
2020-08-23 15:45:46 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2020-08-23 15:45:46 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'60cf21a9512add7d387e'
2020-08-23 15:45:46 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'07cfa1a9512a97797e'
2020-08-23 15:45:46 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2020-08-23 15:45:46 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''
2020-08-23 15:45:54 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event device_registry_updated[L]: action=update, device_id=0b2d3e0612cb4c55888eaf23733bfb88>
2020-08-23 15:45:54 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event entity_registry_updated[L]: action=update, entity_id=binary_sensor.ikea_motion_sensor_new_on_off, changes=['name', 'entity_id'], old_entity_id=binary_sensor.ikea_of_sweden_tradfri_motion_sensor_31d0d4fe_on_off>
2020-08-23 15:45:54 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event entity_registry_updated[L]: action=update, entity_id=sensor.ikea_motion_sensor_new_power, changes=['name', 'entity_id'], old_entity_id=sensor.ikea_of_sweden_tradfri_motion_sensor_31d0d4fe_power>
2020-08-23 15:45:54 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.ikea_of_sweden_tradfri_motion_sensor_31d0d4fe_on_off, old_state=<state binary_sensor.ikea_of_sweden_tradfri_motion_sensor_31d0d4fe_on_off=on; friendly_name=IKEA of Sweden TRADFRI motion sensor 31d0d4fe on_off, device_class=opening @ 2020-08-23T15:44:43.865362+02:00>, new_state=None>
2020-08-23 15:45:54 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.ikea_of_sweden_tradfri_motion_sensor_31d0d4fe_power, old_state=<state sensor.ikea_of_sweden_tradfri_motion_sensor_31d0d4fe_power=unavailable; unit_of_measurement=%, friendly_name=IKEA of Sweden TRADFRI motion sensor 31d0d4fe power, device_class=battery @ 2020-08-23T15:44:43.868166+02:00>, new_state=None>
2020-08-23 15:45:54 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.ikea_motion_sensor_new_on_off, old_state=None, new_state=<state binary_sensor.ikea_motion_sensor_new_on_off=off; friendly_name=IKEA motion sensor New on_off, device_class=opening @ 2020-08-23T15:45:54.588971+02:00>>
2020-08-23 15:45:54 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.ikea_motion_sensor_new_power, old_state=None, new_state=<state sensor.ikea_motion_sensor_new_power=unavailable; unit_of_measurement=%, friendly_name=IKEA motion sensor New power, device_class=battery @ 2020-08-23T15:45:54.591749+02:00>>
2020-08-23 15:45:56 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2020-08-23 15:45:56 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'71cc21a9512a6cee7e'
2020-08-23 15:45:56 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'10cca1a9512aab6e7e'
2020-08-23 15:45:56 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2020-08-23 15:46:06 DEBUG (MainThread) [bellows.ezsp.protocol] Send command nop: ()
2020-08-23 15:46:06 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 5 (nop) received: b''

And it was paring !!!!!

The reading of its group is failing like in the old one and E1743 (On/Off dimmer switch) but that is not ZB3 related (I think = not knowing).

MattWestb commented 3 years ago

The TC is sending [0x20bc:zdo] Unsupported ZDO request:ZDOCmd.Node_Desc_req

That is not the device checking TC level. That's zigpy query ing the device. You need to enable bellows.zigbee.application: debug and bellows.ezsp: debug to see what's happening

Im very sorry but i think you have wrong in this question. Then the coordinator is requesting one device nod description its looks like this

[0x20bc] Requesting 'Node Descriptor'

And its not one broadcast its one unicast to the device. Then open the network for joining the NCP is sending

[0x0000:zdo] ZDO request ZDOCmd.Mgmt_Permit_Joining_req: [60, <Bool.false: 0>] 

That is one ZDO command (broadcast) from the coordinator (0x0000) to allowing devices to joining.

By standard one ZB3 device that have getting the network key encrypted with the "preconfigured well known TC link key" is starting with broadcasting one device announcement so it perrent and the TC is knowing its back online.

[0x20bc:zdo] ZDO request ZDOCmd.Device_annce: [0x20bc, 14:b4:57:ff:fe:d4:d0:31, 128]

Then its unicasting one request for the TCs node descripting so it can compering if the ZCL is 2 or higher (= R22/ZB3). Still with the preconfigured well known TC link key.

[0x20bc:zdo] ZDO request ZDOCmd.Node_Desc_req: [0x0000]

The TC is don't like the request of some reason (running in R21 mode ?) an login it like this

[0x20bc:zdo] Unsupported ZDO request:ZDOCmd.Node_Desc_req

Therefore is the node falling back and working in backward compatibility mode (not ZB3). I'm very sure that the NCP is running in R21 mode (Zigbee PRO 201x) and not in R22 / ZB3. I have not seen and not looking for ZB3 specific things in the log (i think client and parent manamengs commands) that is specific for ZB3.

Picture from silabs "an1233-zigbee-security". Bell2A

Adminiuga commented 3 years ago

The TC is sending [0x20bc:zdo] Unsupported ZDO request:ZDOCmd.Node_Desc_req

That is not the device checking TC level. That's zigpy query ing the device. You need to enable bellows.zigbee.application: debug and bellows.ezsp: debug to see what's happening

Yes, you are correct. That particular line is the result of the joining ZB3.0 device checking if coordinator is a ZB3 device too. The NCP is configured to pass through all ZDO requests and the log line is a response from zigpy itself, but I assume the NCP responded to this node descriptor request. See if you can sniff the traffic to confirm.

MattWestb commented 3 years ago

And you is also right then in the log after the ZDO request the device confirming it have getting one new TC-link key:

2020-08-23 15:44:21 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 155 (zigbeeKeyEstablishmentHandler) received: b'31d0d4feff57b41406'
2020-08-23 15:44:21 DEBUG (MainThread) [bellows.zigbee.application] Received zigbeeKeyEstablishmentHandler frame with [14:b4:57:ff:fe:d4:d0:31, 

If the TC not have sending the response and if it woas ZCL <22 the device dont have asking for on new TC-link key. The response "zigbeeKeyEstablishmentHandler" is by the device encrypted with the new link key and the NCP can decrypting it = OK

Name: requestLinkKey ID: 0x0014
Response Parameters:
EmberStatus status The success or failure of sending the request. This is not the final result of the attempt.
ezspZigbeeKeyEstablishmentHandler(...) will return that.

So bellows is running ZB3 :-))))

Then its the strange thing with only paring 4 ZB3 devices then the default was 4 and the 5 ZB3 device cant getting one new TC key.

vol.Optional(EzspConfigId.CONFIG_KEY_TABLE_SIZE.name, default=8): vol.All(
        int, vol.Range(min=0)
    ),  

Perhaps the default is not fine tuned and need being higher ?

MattWestb commented 3 years ago

I think you need taking one deeper looks at this setting.

vol.Optional(EzspConfigId.CONFIG_KEY_TABLE_SIZE.name, default=8): vol.All(
        int, vol.Range(min=0)
    ),  

From the "UG100: EZSP Reference Guide " is the default 4 (that i was changing to 8) in your config not one default value its the RAM cost / units configured.

Configuration Value | Min. | Max. | Units | RAM Cost | Description 
EZSP_CONFIG_KEY_TABLE_SIZE | 0 | - | entries | 4 | The size of the Key Table used for storing individual link keys (if the device is a Trust Center) or Application Link Keys (if the device is a normal node). 

This is the parameters that making ZB3 not supporting 64K (if i remember right is the maximum address range in Zigbee) devices in the mech as in the previous versions was doing. I think its not possible (or not easy) making it dynamic in the TC and making one problem on witch hardware its running on (how much onboard RAM the device having). Perhaps one default for 32K devices its good and possible changing in config file for 64K and 96K RAM devices. Perhaps its possible pulling the HW configurations parameters from the EZSP stack and using them.

Look read and thinking it true how its working and you finding one good solution.

Edit: Was reading that in EZSP 6.8.0.2 in chapter "2.1 Plugin Changes" is it possible extending the reporting key table if having enough flash for larger NVM3. I don't knowing if its have with this problem or not but you can looking and see what is changed in the new version . Perhaps the NVM3 size is also one part of how large the KEY_TABLE_SIZE suld being.

MattWestb commented 3 years ago

Back to the original request:

clearKeyTable

I have looking how you is deleting obsolete TC-keys (that is not the same that i understanding it for 110%) and its looks working well but we have not testing it so muth. I only seeing one scenario that can making obelite keys not being deleted in the key table. As long the device is coming back in the system they being deleted and then re added (updated). If the device is not coming back (broken or moved to one other site) the obsolete TC-key is not being deleted for infinite time. Also if the NCP is moving from one site there it was populated with ZB3 devices and forming one new network at the new site with new ZB3 devices all the old TC-keys is left in the key table. I think one "housekeeping" routine is needed for deleting the obsolete keys that is not in the ZHAs db (as your zha_custom can do by user command) and perhaps clearing the key tabe then forming the network new.

Its not urgent but in the long run its necessary getting the obsolete TC-keys deleted in the keytable and the table size is costing RAM that is better used for other things then its possible.

Read and think and you finding how to do the coding well.

MattWestb commented 3 years ago

Was finding some old but interesting info from building slabs NCP in AN1010: Building a Customized NCP Application Its old and using the EmberZNet PRO 5.4.1.

The interesting is:

2.3 Customizations
Plugins

• In the Stack Libraries section, Security Link Keys Library plugin, change the Link Key 
Table Size parameter to the desired maximum number of unique APS link keys used by the NCP. 
Note that if you are configuring your NCP to act as a Trust Center with Zigbee 3.0 Security 
(as set in the Security Type area on the Zigbee Stack tab), it is not necessary to have a 
unique key table entry for every device. Instead, a single security key known as a Master Key 
is used to compute unique keys via an AES-HMAC hash function for each device. 
However, supporting install-code-based keys requires a link key table with as many entries as 
the number ofinstall-code-based keys you wish to support simultaneously for joining devices 
with install code support.

I think that is the EMBER_TRUST_CENTER_USES_HASHED_LINK_KEY function that you was asking about before. Was also finding one description from silab Hashed Link Keys and yes you need reform the network after setting the opinion.

And its sound logic that giving all clients TC-link keys that is build from hach of the master key and only having the master key in the trust center and not unique keys saved for all devices. If its working then is the key table don't needed being large then it not storing TC-link keys only Application Link Keys (and perhaps install codes i think) that TC is making for devices that need it for cryptating private communication to other device.

More is described in AN1233: Zigbee Security searching for "APS security".

I think in the end that you is having right as normal !!!

Adminiuga commented 3 years ago

I think that too, but need to confirm. And it probably won't help those with already formed networks, as this is a param set during network formation. Although would be interesting to test if backup/restore can change that 🤔

MattWestb commented 3 years ago

From ug100-ezsp-reference-guide.pdf: EMBER_TRUST_CENTER_USES_HASHED_LINK_KEY 0x0084 This denotes that the preconfiguredKey is not the actual Link Key but a Secret Key known only to the Trust Center. It is hashed with the IEEE Address of the destination device in order to create the actual Link Key used in encryption. This is bit is only used by the Trust Center. The joining device need not set this.

MattWestb commented 3 years ago

Thanks for the "Add 'ezsp_clear_keys' command to clear Key Table." :-)))

Adminiuga commented 3 years ago

I think correct answer to the problem is to use the hashed TC link key and changing policy to send the current TC link key.

MattWestb commented 3 years ago

Can you telling how to use the command of the function "clear_keys" in HA (zha_cunstum) ? I trying the updated functions in tasmota and the old keys from bellowes is making all one mess and need doing one flash erase for it to working.

If implanting the hashed TC key is easy changing the policy then testing (what i have seen in the code). Say then you need help for testing and i trying helping as much i can !!

Adminiuga commented 3 years ago

to clear the keys just call zha_custom.execute with command: ezsp_clear_keys

MattWestb commented 3 years ago

Thanks very much I testing later and reporting back if its not working.

MattWestb commented 3 years ago

Thanks very much !!!

Only for information:

2020-08-27 16:43:30 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event call_service[L]: domain=zha_custom, service=execute, service_data=command=ezsp_clear_keys>
2020-08-27 16:43:30 INFO (MainThread) [custom_components.zha_custom] Running custom service: <ServiceCall zha_custom.execute (c:acf01da2e87311eaa83cb5d5219f604e): command=ezsp_clear_keys>
2020-08-27 16:43:30 INFO (MainThread) [custom_components.zha_custom.ezsp] Clear key table
2020-08-27 16:43:30 DEBUG (MainThread) [bellows.ezsp.protocol] Send command clearKeyTable: ()
2020-08-27 16:43:31 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 177 (clearKeyTable) received: b'00'
2020-08-27 16:43:31 INFO (MainThread) [custom_components.zha_custom.ezsp] Cleared key table: EmberStatus.SUCCESS

If having paired "real" ZB3 devices in ZHA and not clearing the key table in the NCP then its not possible pairing the devices in tasmot zigbee gateway. If not reflashing the NCP after erasing the internal flash or using some of you "magic" commands ;-))))

Stephan is informed but hi don't like to understanding the problematic so its not our problems now.

MattWestb commented 3 years ago

Is trying out the last commit cd0fa9d I have observed that all my ZB3 bulbs but not ZB3 end devices was pared in "HA12" mode. Was deleting the bulbs and repairing and they was going in as ZB3.

Sent 'mgmt_permit_joining_req' to 14:b4:57:ff:fe:3e:e2:77: [<Status.SUCCESS: 0>]
Device 0x5961 (14:b4:57:ff:fe:53:98:23) joined the network
Device 0x5961 (14:b4:57:ff:fe:53:98:23) joined the network
Skip initialization for existing device 14:b4:57:ff:fe:53:98:23
[0x5961] Requesting 'Node Descriptor'
Tries remaining: 2
[0x5961] Extending timeout for 0xb9 request
Device 0x5961 (14:b4:57:ff:fe:53:98:23) joined the network
Skip initialization for existing device 14:b4:57:ff:fe:53:98:23
Device 0x5961 (14:b4:57:ff:fe:53:98:23) joined the network
Skip initialization for existing device 14:b4:57:ff:fe:53:98:23
[0x5961] Cancelling old group rescan
Device 0x5961 (14:b4:57:ff:fe:53:98:23) joined the network
Skip initialization for existing device 14:b4:57:ff:fe:53:98:23
[0x5961:zdo] ZDO request ZDOCmd.Device_annce: [0x5961, 14:b4:57:ff:fe:53:98:23, 142]
[0x5961:zdo] ZDO request ZDOCmd.Node_Desc_req: [0x0000]
[0x5961:zdo] Unsupported ZDO request:ZDOCmd.Node_Desc_req
[0x5961:zdo] ZDO request ZDOCmd.Mgmt_Permit_Joining_req: [180, <Bool.true: 1>]

The " ZDO request ZDOCmd.Device_annce:" all ZB3 devices is doig. The device request "ZDO request ZDOCmd.Node_Desc_req:", NCP response "Unsupported ZDOrequest:ZDOCmd.Node_Desc_req" and the device sending " ZDO request ZDOCmd.Mgmt_Permit_Joining_req: " ar the new link key handshaking in ZB3.

If only the first occur then its one HA21 joining, if all 4 then its one real ZB3 joining.

I doing more tests and looking if its was some temporary glitch or one bad behaviour.

MattWestb commented 3 years ago

The second try: Was trying "hard" deleting devices in HA that was before in deCONZ and was showing up as "deCONZ, ZHA (HA is saving zigbee devices with uid as device mac and its the same if moving between integrations and is very annoying) Ended with deleting the core.device_registry then having deleting little to much and must reconfiguring all devices ;-((

This time all devices was resetted and the ZB3 bulbs was pairing in HA12 mode but the HOMA was going in as ZB3. Deleting the device and repairing then and the ZB3 is pairing as ZB3 and HOMA as HA12.

Of the 5 end devices is only one having battery status OK. Opening the paring window and resetting the device (= repairing without deleting) and after success they having getting battery status.

I like the "personality" of bellows !!! Little more work and you have all important things in place :-))

MattWestb commented 3 years ago

Have changing branch to dev with this parameters in HA.

pypi:
  - 'git+https://github.com/zigpy/bellows@dev#bellows==0.20.0.dev0'
apk: []

Then updating Home Assistant to 0.114.4. from 0.114.0. Deleting and resetting all devices. Deleting ZHA. Restarting HA.

Installing ZHA with EZSP. Paring lights: GU10WS1 = HA 1.2 GU10WS2 = ZB3 E27WW = HA 1.2 HOMA = HA.12. Deleting GU10WS1. Trying paring it again not possible. After 5 tries i restarting HA. Then paring as ZB3 is OK. Deleting E27WW and paring Ok as ZB3.

Paring end devices: E7143 = ZB3 and default groupe (0x000) allocated in HA. Motion old = LL and grupe allocated in HA. Motion new = ZB3. Xiaomi Aqara Magnet2 HA. Xiaomi Aqara Weather HA. (have warning in HA log that failing getting groupe and falling back to 0x000 but i don't knowing which device it triggering that but likely motion sensor new and its sending its commands to groupe 0x0000). All end device have battery and status updated.

Restarting HA and all devices is there with battery status updated and looks OK Adding 2 ZB3 lights to the motion sensor old (with "sniffed") groupe and its working OK = triggered motion = 60 sec light. Adding 1 ZB3 light and HOMA to the default (0) groupe. Motion triggered = 180 sce light = OK. E1743 On/Off, dimmer up/down = OK Group changing from HA is working OK All ZB3 lights is updating there status in HA OK HOMA is normally not updating its status in HA, only then the command is being sended from HA (I think its bad / no standard attribute reporting from the device). Xiaomi Aquara magnet and weather looks working as expected.

Only concern is that verified ZB3 device like being paired ad HA then first paring them but not easy understand way perhaps is it one timing thing.

+10,266 −1,279 lines lines is done to dev and very sure more is coming :-)))

As normal Code Master !!!!

MattWestb commented 3 years ago

Timing problems then then pairing devices in ZHA. The default time then opening the network for pairing is set to 60 seconds in zigpy / bellows and ZHA. The paring process is running in the background if not finished in the time frame if the device have getting network key and TC-link key. If one device is not replying fast enough on requests or if ZHA is taking to long time fo doing is things or too much time outs its happens oft that the 60 seconds is running out. Also the last added "Set joining with well known key timeout to 90s" is making it little more complicated. I think its better changing the standard time for opening the network to 90 (or 120) seconds and also adjusting ZHA paring time out to the same. The problem is that ZHA is doing the same for all redios and need being patched or all radios in zigpy should have the the longer pairing time. I think its making the zigbee life easier for the users if adjusting this parameters.

Adminiuga commented 3 years ago

you can call zha.permit service with duration: 180 to increase joining time. Although i don't think you really need to re-pair all the devices, unless you want to.

MattWestb commented 3 years ago

I have seeing the service in HA but not trying it out. I was liking to see if the IKEAS was pairing in ZB3 mode and if it was possible getting then all in secure mode. I think its can being firmware related if they they doing one real ZB3 pairing or not. The HOMA was one time asking for updated TC-link key and was using it 2 ;-))

MattWestb commented 3 years ago

In and output on flexible security levels in bellows.

Bellows looks being very flexible and can being adopting for both high and low security systems then tuning it right. Then reading and trying understanding how Silabs have cooking EZSP for (co)working with deferens versions of Zigbee protocols I have observing that the EZSP have many very good options for high network security and networks steering for eliminating interference then its possible. If having one network with only ZB3 devices its can being very good disabling futures that making the network less secure from sniffing and stealing the network key so can easy keeping the network in high secure level. Forcing change of Trustcanter link key then joining is one good and easy method but only working in true zigbee 3 devices. If not having and bad behaviour ZB3 device and no Xiaomis it can be good disable Trust Center Rejoin after have pairing all device and keeping it safe and hope not getting problems with loosing devices. For keeping the door open and making its flexible setting some parameters in ZHAs config wold open many doors and making its easy for user management the security in the network. Can being like “ZB3 secure”, ZB3 relaxed”. “LL/HA compatible” or more technical the real “EZSP parameters” in HAs config file. Also making it possible changing the security policy and parameters true HA service on the fly can being good but need being possible doing settings that is more permanent and not being resettled then opening and closing the network for joining and restarting the system (HA config). Implanting install code is large ting but can being good to do in the future. Wat I see is only Philips HUE that is using it with Bluetooth for getting the code in to the NCP. Initial channel scan, PAN-ID and E-PAN-ID scan for finding free IDs and avoiding ID conflicts then forming the network its good. Channels scan on the fly for detecting jammed channels and moving the network if detecting one better channel. Rolling the network key on demand or thru maximum age its good 2. But I’m 110% sure its not Xiaomi compatible !! Secure EZSP is also one good thing for ver2 (1 is not interesting for new projects) can attracting developers that like making one high-end system with good security from zigbee end device to end application. But not so much use in DIY HA systems.

Some things can be easy implanted and perhaps going in Bellows 20.0 GA and other perhaps for 25 or 35 or not at all. R23 is coming and the hardware demand for key storages is large wat hi have understanding so i think install code and “private unique link key” is one large part of the bucket in it. Very likely the Ikea module is not getting the R23 as most first gen EFR32s and older chips then its having not enough flash for the key storage. I’m not the Code Master only doing some brain storming and perhaps you are finding something useful.

My intension is then Bellows 20 is stable for production i moving all Xiaomi and Philips HUE devices to ZHA with EZSP and deCONZ is RIP (Not stabile enough for critical lights and braking bugs that is not being fixed from the company). The IKEA GW is very stable and staying longer. Then Bellows is real proven stable the big is moving all lights (perhaps only ZB3) using one EFR32 for keeping the core stabile and secure and so autonomy as possible. And one Tasmota with CC-2531 or EFR32 module for no ZB3 devices and Xiaomi sensors. The door is open for Z2M is they is jumping on the gecko track or getting RaspBee / CornBee stabile then my old RaspBee 1gen is getting one second life.

Adminiuga commented 3 years ago

Bellows supported joining with install codes for a while now, but currently not exposed through a zha service. Once new version is published, should be fairly easy to add it to zha. See this article https://www.silabs.com/community/wireless/zigbee-and-thread/knowledge-base.entry.html/2018/12/31/zigbee_3_0_preventio-EIW3 I've tried my best following those recommendation and currently bellows for ezsp v8 behaves very similarly to silabs network-creator plug in. In the long run, we could add a switch for not allowing ha12 devices. We'll see.

MattWestb commented 3 years ago

Interesting KB and well describing the scenarios with ZB3 and legacy / bad behaviour devices. The important things is have the doors open and not making braking things for the future. You have the rest of the Zigpy family to taking care of and must getting all together and some don't have the capacity implanting all good things or is braking other than stretching them to much. The large challenge is to getting so much good out of the hardware without breaking the hole change and getting HA to playing well with it. I letting you little working silence and doing more hardware work (modding smoke detectors with Aqaras door window contact as zigbee transmitter) and waiting for your progress with our beloved. If need help with testing give my one signal and I trying helping as much i can ! And I closing this issue then i have getting the "0x00B1" and the "0x0076" was already implanted (but not reviled).