search

zigpy / bellows

A Python 3 project to implement EZSP for EmberZNet devices
GNU General Public License v3.0
184 stars 87 forks source link

Not able to start zigpy/bellows since the latest update of master #468

Closed pipiche38 closed 2 years ago

pipiche38 commented 2 years ago

I have apply the latest zigpy and bellows version (from master) and not able to start. if I fall back to the previous version it works liek a charm

2022-07-18 14:16:51,717 INFO    :[0x0000] Already have endpoints: {0: <zigpy.zdo.ZDO object at 0xa97bae68>, 1: <EZSPEndpoint id=1 in=[] out=[] status=<Status.NEW: 0>>}
2022-07-18 14:16:51,723 INFO    :[0x0000] Initializing endpoints [<EZSPEndpoint id=1 in=[] out=[] status=<Status.NEW: 0>>]
2022-07-18 14:16:51,734 INFO    :[0x0000:1] Discovering endpoint information
2022-07-18 14:16:51,736 DEBUG   :Tries remaining: 3
2022-07-18 14:16:51,745 DEBUG   :Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0000, EmberApsFrame(profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=3), 4, b'\x03\x00\x00\x01')
2022-07-18 14:16:51,761 DEBUG   :Sending: b'267b21a9602a15b259944a21aa5592099d4e27a8e9ca648bfdc7d3d57e'
2022-07-18 14:16:51,774 DEBUG   :Data frame: b'637ba1a9602a1549a0937e'
2022-07-18 14:16:51,776 DEBUG   :Sending: b'87009f7e'
2022-07-18 14:16:51,780 DEBUG   :Application frame 52 (sendUnicast) received: b'00fb'
2022-07-18 14:16:51,781 DEBUG   :Data frame: b'737bb1a9112a15b259904a25aa1593499cb5d8abedce9874f9c56389fd67907e'
2022-07-18 14:16:51,786 DEBUG   :Sending: b'8070787e'
2022-07-18 14:16:51,789 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'0000000400000040010000fbff000000ffff0403000001'
2022-07-18 14:16:51,791 DEBUG   :Data frame: b'037bb1a9112a15b25990ca25aa1593499cb2d8abedce9874e2c56389fc643ea3eacdda6f8affc7ddd5d869954622ace8773b85ea7587439d34797e'
2022-07-18 14:16:51,801 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=251), 255, 0, 0x0000, 255, 255, b'\x03\x00\x00\x01']
2022-07-18 14:16:51,802 DEBUG   :Sending: b'8160597e'
2022-07-18 14:16:51,808 DEBUG   :Received frame on uninitialized device <EZSPCoordinator model='EZSP' manuf='Silicon Labs' nwk=0x0000 ieee=cc:cc:cc:ff:fe:a5:f3:07 is_initialized=False> from ep 0 to ep 0, cluster 4: b'\x03\x00\x00\x01'
2022-07-18 14:16:51,815 DEBUG   :Data frame: b'137bb1a96b2a15b259944a21aa5592099d4e2750e9ce67e0747e'
2022-07-18 14:16:51,819 DEBUG   :Sending: b'82503a7e'
2022-07-18 14:16:51,816 DEBUG   :[0x0000:zdo] ZDO request ZDOCmd.Simple_Desc_req: [0x0000, 1]
2022-07-18 14:16:51,824 DEBUG   :[0x0000:zdo] No handler for ZDO request:ZDOCmd.Simple_Desc_req([0x0000, 1])
2022-07-18 14:16:51,834 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'0000000480000040010000fcff000000ffff1f030000001a01040100040005000006000a0019000105040100200000050205'
2022-07-18 14:16:51,842 DEBUG   :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=252), 255, 0, 0x0000, 255, 255, b'\x03\x00\x00\x00\x1a\x01\x04\x01\x00\x04\x00\x05\x00\x00\x06\x00\n\x00\x19\x00\x01\x05\x04\x01\x00 \x00\x00\x05\x02\x05']
2022-07-18 14:16:51,852 DEBUG   :Received frame on uninitialized device <EZSPCoordinator model='EZSP' manuf='Silicon Labs' nwk=0x0000 ieee=cc:cc:cc:ff:fe:a5:f3:07 is_initialized=False> from ep 0 to ep 0, cluster 32772: b'\x03\x00\x00\x00\x1a\x01\x04\x01\x00\x04\x00\x05\x00\x00\x06\x00\n\x00\x19\x00\x01\x05\x04\x01\x00 \x00\x00\x05\x02\x05'
2022-07-18 14:16:51,865 DEBUG   :Application frame 63 (messageSentHandler) received: b'00000000000400000040010000fb040000'
2022-07-18 14:16:51,876 DEBUG   :Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0, EmberApsFrame(profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=251), 4, <EmberStatus.SUCCESS: 0>, b'']
2022-07-18 14:16:51,886 INFO    :[0x0000:1] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=1, profile=260, device_type=1024, device_version=0, input_clusters=[0, 6, 10, 25, 1281], output_clusters=[1, 32, 1280, 1282])
2022-07-18 14:16:51,893 INFO    :[0x0000] Already have model and manufacturer info
2022-07-18 14:16:51,899 INFO    :[0x0000] Discovered basic device information for <EZSPCoordinator model='EZSP' manuf='Silicon Labs' nwk=0x0000 ieee=cc:cc:cc:ff:fe:a5:f3:07 is_initialized=True>
2022-07-18 14:16:51,901 DEBUG   :Device is initialized <EZSPCoordinator model='EZSP' manuf='Silicon Labs' nwk=0x0000 ieee=cc:cc:cc:ff:fe:a5:f3:07 is_initialized=True>
2022-07-18 14:16:51,904 DEBUG   :Checking quirks for Silicon Labs EZSP (cc:cc:cc:ff:fe:a5:f3:07)
2022-07-18 14:16:51,906 ERROR   :Couldn't start application
2022-07-18 14:16:51,907 DEBUG   :Cancelling watchdog
2022-07-18 14:16:51,909 DEBUG   :Cancelling watchdog
2022-07-18 14:16:51,911 DEBUG   :Closed serial connection
pipiche38 commented 2 years ago

I did some debuging, and it looks like it crashes on the new added code

        if db_device is not None:
                ezsp_device.endpoints[1].member_of.update(db_device.endpoints[1].member_of)
puddly commented 2 years ago

What is the traceback?

pipiche38 commented 2 years ago 
2022-07-19 09:59:50,123 INFO    : [ ZigpyForwarder_7] ZigpyTransport: thread_processing_and_sending Thread start.
2022-07-19 09:59:50,126 INFO    : [       MainThread] Start Web Server connection
2022-07-19 09:59:50,129 INFO    : [       MainThread] Web backend for Web User Interface started on port: 9440
2022-07-19 09:59:50,132 INFO    : [       MainThread] Domoticz Widgets usage is at 13.7 %
2022-07-19 09:59:51,727 INFO    : [       ZigpyCom_7] Started radio ezsp port: /dev/serial/by-id/usb-1a86_USB2.0-Serial-if00-port0
2022-07-19 09:59:51,736 DEBUG   :Using selector: EpollSelector
2022-07-19 09:59:53,486 DEBUG   :Network info: NetworkInfo(extended_pan_id=3a:da:a7:1b:a8:eb:93:b7, pan_id=0xA943, nwk_update_id=0, nwk_manager_id=0x0000, channel=15, channel_mask=<Channels.ALL_CHANNELS: 134215680>, security_level=5, network_key=Key(key=7d:91:be:91:11:64:1c:74:b0:a3:5c:bf:8b:8e:5e:d3, tx_counter=2830337, rx_counter=0, seq=0, partner_ieee=ff:ff:ff:ff:ff:ff:ff:ff), tc_link_key=Key(key=5a:69:67:42:65:65:41:6c:6c:69:61:6e:63:65:30:39, tx_counter=65536, rx_counter=0, seq=0, partner_ieee=cc:cc:cc:ff:fe:a5:f3:07), key_table=[], children=[], nwk_addresses={}, stack_specific={'ezsp': {'hashed_tclk': 'a23bc18d7292917f2db9135ba9f56414'}}, metadata={'ezsp': {'manufacturer': 'Elelabs', 'board': 'ELR023', 'version': '6.10.3.0 build 297', 'stack_version': 8}}, source='bellows@0.31.1')
2022-07-19 09:59:53,489 DEBUG   :Node info: NodeInfo(nwk=0x0000, ieee=cc:cc:cc:ff:fe:a5:f3:07, logical_type=<LogicalType.Coordinator: 0>)
2022-07-19 09:59:53,954 ERROR   :Traceback (most recent call last):
  File "/var/lib/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/AppBellows.py", line 110, in _startup
    await self.start_network()
  File "/var/lib/domoticz/plugins/Domoticz-Zigbee/bellows/zigbee/application.py", line 208, in start_network
    ezsp_device.endpoints[1].member_of.update(db_device.endpoints[1].member_of)
KeyError: 1
pipiche38 commented 2 years ago

In order to avoid a potential issue in our _startup() which is just a copy of the zigpy one withoout the permit(0) here is without


2022-07-19 10:18:15,574 INFO    : [       ZigpyCom_7] Started radio ezsp port: /dev/serial/by-id/usb-1a86_USB2.0-Serial-if00-port0
2022-07-19 10:18:15,582 DEBUG   :Using selector: EpollSelector
2022-07-19 10:18:17,833 ERROR   :Couldn't start application
2022-07-19 10:18:17,856 ERROR   :Traceback (most recent call last):
  File "/var/lib/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/AppBellows.py", line 65, in startup
    await super().startup( auto_form=True )
  File "/var/lib/domoticz/plugins/Domoticz-Zigbee/zigpy/application.py", line 80, in startup
    await self.start_network()
  File "/var/lib/domoticz/plugins/Domoticz-Zigbee/bellows/zigbee/application.py", line 208, in start_network
    ezsp_device.endpoints[1].member_of.update(db_device.endpoints[1].member_of)
KeyError: 1
pipiche38 commented 2 years ago

@puddly is that the stack trace you were looking for ? Should I do more tests ?

puddly commented 2 years ago

This likely is caused by you not using the zigpy database, since the error says that your coordinator entry in the database has no endpoints.

pipiche38 commented 2 years ago

I don't understand your comment. The only thing that we do is that the zigpy database is not persistent (we do not define a filename to store it), but we didn't overwrite anything here. Do you mean that we must have the zigpy database persistent ?

If I understood correctly the logic

we do call super().startup() -> self.connect() -> register_endpoint() -> super().register_endpoints()

So EndPoint should be registered, no ? In the log here after which give you the all debug info of startup, there is the endpoint_registration happening.

2022-07-21 15:22:56,935 DEBUG   :SQLite version for <module 'sqlite3' from '/usr/lib/python3.9/sqlite3/__init__.py'>: 3.34.1
2022-07-21 15:22:58,442 DEBUG   :Using selector: EpollSelector
2022-07-21 15:22:59,807 DEBUG   :Using selector: EpollSelector
2022-07-21 15:22:59,828 DEBUG   :Resetting EZSP
2022-07-21 15:22:59,834 DEBUG   :Resetting ASH
2022-07-21 15:22:59,836 DEBUG   :Sending: b'1ac038bc7e'
2022-07-21 15:23:00,915 DEBUG   :RSTACK Version: 2 Reason: RESET_SOFTWARE frame: b'c1020b0a527e'
2022-07-21 15:23:00,920 DEBUG   :Send command version: (4,)
2022-07-21 15:23:00,924 DEBUG   :Sending: b'004221a850ed2c7e'
2022-07-21 15:23:00,934 DEBUG   :Data frame: b'0142a1a85c2825d8e12b7e'
2022-07-21 15:23:00,936 DEBUG   :Sending: b'8160597e'
2022-07-21 15:23:00,939 DEBUG   :Application frame 0 (version) received: b'0802306a'
2022-07-21 15:23:00,942 DEBUG   :Switching to EZSP protocol version 8
2022-07-21 15:23:00,945 DEBUG   :Send command version: (8,)
2022-07-21 15:23:00,949 DEBUG   :Sending: b'7d314221a9542a1d8cdf7e'
2022-07-21 15:23:00,960 DEBUG   :Data frame: b'1242a1a9542a1db069fe46f07e'
2022-07-21 15:23:00,961 DEBUG   :Sending: b'82503a7e'
2022-07-21 15:23:00,965 DEBUG   :Application frame 0 (version) received: b'0802306a'
2022-07-21 15:23:00,967 DEBUG   :EZSP Stack Type: 2, Stack Version: 6a30, Protocol version: 8
2022-07-21 15:23:00,968 DEBUG   :Send command getValue: (<EzspValueId.VALUE_FREE_BUFFERS: 3>,)
2022-07-21 15:23:00,971 DEBUG   :Sending: b'224321a9fe2a1683467e'
2022-07-21 15:23:00,980 DEBUG   :Data frame: b'2343a1a9fe2a15b3a191d67e'
2022-07-21 15:23:00,982 DEBUG   :Sending: b'83401b7e'
2022-07-21 15:23:00,984 DEBUG   :Application frame 170 (getValue) received: b'0001f8'
2022-07-21 15:23:00,988 DEBUG   :Send command getConfigurationValue: (<EzspConfigId.CONFIG_PACKET_BUFFER_COUNT: 1>,)
2022-07-21 15:23:00,992 DEBUG   :Sending: b'334021a9062a14a80d7e'
2022-07-21 15:23:01,001 DEBUG   :Data frame: b'3440a1a9062a15485927a17e'
2022-07-21 15:23:01,003 DEBUG   :Sending: b'8430fc7e'
2022-07-21 15:23:01,006 DEBUG   :Application frame 82 (getConfigurationValue) received: b'00fa00'
2022-07-21 15:23:01,009 DEBUG   :Free/configured buffers before any configurations: 248/250
2022-07-21 15:23:01,011 DEBUG   :Send command setConfigurationValue: (<EzspConfigId.CONFIG_STACK_PROFILE: 12>, 2)
2022-07-21 15:23:01,015 DEBUG   :Sending: b'444121a9072a19b05925087e'
2022-07-21 15:23:01,024 DEBUG   :Data frame: b'4541a1a9072a15cd287e'
2022-07-21 15:23:01,025 DEBUG   :Sending: b'8520dd7e'
2022-07-21 15:23:01,028 DEBUG   :Application frame 83 (setConfigurationValue) received: b'00'
2022-07-21 15:23:01,031 DEBUG   :Send command setConfigurationValue: (<EzspConfigId.CONFIG_TC_REJOINS_USING_WELL_KNOWN_KEY_TIMEOUT_S: 56>, 90)
2022-07-21 15:23:01,035 DEBUG   :Sending: b'554621a9072a2de859c4be7e'
2022-07-21 15:23:01,044 DEBUG   :Data frame: b'5646a1a9072a15ea907e'
2022-07-21 15:23:01,046 DEBUG   :Sending: b'8610be7e'
2022-07-21 15:23:01,049 DEBUG   :Application frame 83 (setConfigurationValue) received: b'00'
2022-07-21 15:23:01,052 DEBUG   :Send command setConfigurationValue: (<EzspConfigId.CONFIG_SUPPORTED_NETWORKS: 45>, 1)
2022-07-21 15:23:01,056 DEBUG   :Sending: b'664721a9072a38b35920fd7e'
2022-07-21 15:23:01,068 DEBUG   :Data frame: b'6747a1a9072a154edc7e'
2022-07-21 15:23:01,069 DEBUG   :Sending: b'87009f7e'
2022-07-21 15:23:01,073 DEBUG   :Application frame 83 (setConfigurationValue) received: b'00'
2022-07-21 15:23:01,077 DEBUG   :Send command setConfigurationValue: (<EzspConfigId.CONFIG_ADDRESS_TABLE_SIZE: 5>, 16)
2022-07-21 15:23:01,080 DEBUG   :Sending: b'774421a9072a10a2594f707e'
2022-07-21 15:23:01,094 DEBUG   :Data frame: b'7044a1a9072a15ae037e'
2022-07-21 15:23:01,095 DEBUG   :Sending: b'8070787e'
2022-07-21 15:23:01,098 DEBUG   :Application frame 83 (setConfigurationValue) received: b'00'
2022-07-21 15:23:01,101 DEBUG   :Send command setConfigurationValue: (<EzspConfigId.CONFIG_SECURITY_LEVEL: 13>, 5)
2022-07-21 15:23:01,106 DEBUG   :Sending: b'004521a9072a7d38b75947f47e'
2022-07-21 15:23:01,117 DEBUG   :Data frame: b'0145a1a9072a15d7a37e'
2022-07-21 15:23:01,119 DEBUG   :Sending: b'8160597e'
2022-07-21 15:23:01,122 DEBUG   :Application frame 83 (setConfigurationValue) received: b'00'
2022-07-21 15:23:01,126 DEBUG   :Send command setConfigurationValue: (<EzspConfigId.CONFIG_PAN_ID_CONFLICT_REPORT_THRESHOLD: 34>, 2)
2022-07-21 15:23:01,130 DEBUG   :Sending: b'7d314a21a9072a37b059158b7e'
2022-07-21 15:23:01,139 DEBUG   :Data frame: b'124aa1a9072a15fd597e'
2022-07-21 15:23:01,140 DEBUG   :Sending: b'82503a7e'
2022-07-21 15:23:01,143 DEBUG   :Application frame 83 (setConfigurationValue) received: b'00'
2022-07-21 15:23:01,146 DEBUG   :Send command setConfigurationValue: (<EzspConfigId.CONFIG_END_DEVICE_POLL_TIMEOUT: 19>, 8)
2022-07-21 15:23:01,150 DEBUG   :Sending: b'224b21a9072a06ba5996407e'
2022-07-21 15:23:01,161 DEBUG   :Data frame: b'234ba1a9072a1559157e'
2022-07-21 15:23:01,163 DEBUG   :Sending: b'83401b7e'
2022-07-21 15:23:01,168 DEBUG   :Application frame 83 (setConfigurationValue) received: b'00'
2022-07-21 15:23:01,171 DEBUG   :Send command setConfigurationValue: (<EzspConfigId.CONFIG_APPLICATION_ZDO_FLAGS: 42>, <EmberZdoConfigurationFlags.APP_HANDLES_UNSUPPORTED_ZDO_REQUESTS|APP_RECEIVES_SUPPORTED_ZDO_REQUESTS: 3>)
2022-07-21 15:23:01,175 DEBUG   :Sending: b'334821a9072a3fb15961267e'
2022-07-21 15:23:01,184 DEBUG   :Data frame: b'3448a1a9072a15b9ca7e'
2022-07-21 15:23:01,185 DEBUG   :Sending: b'8430fc7e'
2022-07-21 15:23:01,188 DEBUG   :Application frame 83 (setConfigurationValue) received: b'00'
2022-07-21 15:23:01,192 DEBUG   :Send command setConfigurationValue: (<EzspConfigId.CONFIG_MULTICAST_TABLE_SIZE: 6>, 16)
2022-07-21 15:23:01,197 DEBUG   :Sending: b'444921a9072a7d33a25999027e'
2022-07-21 15:23:01,210 DEBUG   :Data frame: b'4549a1a9072a15c06a7e'
2022-07-21 15:23:01,211 DEBUG   :Sending: b'8520dd7e'
2022-07-21 15:23:01,214 DEBUG   :Application frame 83 (setConfigurationValue) received: b'00'
2022-07-21 15:23:01,218 DEBUG   :Send command setConfigurationValue: (<EzspConfigId.CONFIG_SOURCE_ROUTE_TABLE_SIZE: 26>, 16)
2022-07-21 15:23:01,223 DEBUG   :Sending: b'554e21a9072a0fa259d0c57e'
2022-07-21 15:23:01,235 DEBUG   :Data frame: b'564ea1a9072a15e7d27e'
2022-07-21 15:23:01,237 DEBUG   :Sending: b'8610be7e'
2022-07-21 15:23:01,239 DEBUG   :Application frame 83 (setConfigurationValue) received: b'00'
2022-07-21 15:23:01,243 DEBUG   :Send command setConfigurationValue: (<EzspConfigId.CONFIG_INDIRECT_TRANSMISSION_TIMEOUT: 18>, 7680)
2022-07-21 15:23:01,246 DEBUG   :Sending: b'664f21a9072a07b247177d5d7e'
2022-07-21 15:23:01,255 DEBUG   :Data frame: b'674fa1a9072a15439e7e'
2022-07-21 15:23:01,257 DEBUG   :Sending: b'87009f7e'
2022-07-21 15:23:01,259 DEBUG   :Application frame 83 (setConfigurationValue) received: b'00'
2022-07-21 15:23:01,265 DEBUG   :Send command setConfigurationValue: (<EzspConfigId.CONFIG_TRUST_CENTER_ADDRESS_CACHE_SIZE: 25>, 2)
2022-07-21 15:23:01,269 DEBUG   :Sending: b'774c21a9072a0cb05902b97e'
2022-07-21 15:23:01,281 DEBUG   :Data frame: b'704ca1a9072a15a3417e'
2022-07-21 15:23:01,283 DEBUG   :Sending: b'8070787e'
2022-07-21 15:23:01,286 DEBUG   :Application frame 83 (setConfigurationValue) received: b'00'
2022-07-21 15:23:01,289 DEBUG   :Send command getValue: (<EzspValueId.VALUE_FREE_BUFFERS: 3>,)
2022-07-21 15:23:01,293 DEBUG   :Sending: b'004d21a9fe2a160df07e'
2022-07-21 15:23:01,302 DEBUG   :Data frame: b'014da1a9fe2a15b3a16e5c7e'
2022-07-21 15:23:01,304 DEBUG   :Sending: b'8160597e'
2022-07-21 15:23:01,307 DEBUG   :Application frame 170 (getValue) received: b'0001f8'
2022-07-21 15:23:01,309 DEBUG   :Send command getConfigurationValue: (<EzspConfigId.CONFIG_PACKET_BUFFER_COUNT: 1>,)
2022-07-21 15:23:01,313 DEBUG   :Sending: b'7d315221a9062a1437dc7e'
2022-07-21 15:23:01,322 DEBUG   :Data frame: b'1252a1a9062a15485968c77e'
2022-07-21 15:23:01,323 DEBUG   :Sending: b'82503a7e'
2022-07-21 15:23:01,327 DEBUG   :Application frame 82 (getConfigurationValue) received: b'00fa00'
2022-07-21 15:23:01,330 DEBUG   :Free/configured buffers before all memory allocation: 248/250
2022-07-21 15:23:01,331 DEBUG   :Send command setConfigurationValue: (<EzspConfigId.CONFIG_PACKET_BUFFER_COUNT: 1>, 255)
2022-07-21 15:23:01,335 DEBUG   :Sending: b'225321a9072a144d59127b7e'
2022-07-21 15:23:01,347 DEBUG   :Data frame: b'2353a1a9072a154ed37e'
2022-07-21 15:23:01,349 DEBUG   :Sending: b'83401b7e'
2022-07-21 15:23:01,352 DEBUG   :Application frame 83 (setConfigurationValue) received: b'00'
2022-07-21 15:23:01,355 DEBUG   :Send command getValue: (<EzspValueId.VALUE_FREE_BUFFERS: 3>,)
2022-07-21 15:23:01,358 DEBUG   :Sending: b'335021a9fe2a16d8387e'
2022-07-21 15:23:01,368 DEBUG   :Data frame: b'3450a1a9fe2a15b3a2b6217e'
2022-07-21 15:23:01,369 DEBUG   :Sending: b'8430fc7e'
2022-07-21 15:23:01,372 DEBUG   :Application frame 170 (getValue) received: b'0001fb'
2022-07-21 15:23:01,375 DEBUG   :Send command getConfigurationValue: (<EzspConfigId.CONFIG_PACKET_BUFFER_COUNT: 1>,)
2022-07-21 15:23:01,379 DEBUG   :Sending: b'445121a9062a146a0c7e'
2022-07-21 15:23:01,389 DEBUG   :Data frame: b'4551a1a9062a154f5984a97e'
2022-07-21 15:23:01,390 DEBUG   :Sending: b'8520dd7e'
2022-07-21 15:23:01,393 DEBUG   :Application frame 82 (getConfigurationValue) received: b'00fd00'
2022-07-21 15:23:01,397 DEBUG   :Free/configured buffers after all memory allocation: 251/253
2022-07-21 15:23:01,399 DEBUG   :Send command setConcentrator: (True, <EmberConcentratorType.HIGH_RAM_CONCENTRATOR: 65529>, 10, 90, 4, 3, 0)
2022-07-21 15:23:01,403 DEBUG   :Sending: b'555621a9442a144ba69e4a7faa519149502a7e'
2022-07-21 15:23:01,413 DEBUG   :Data frame: b'5656a1a9442a15b4e97e'
2022-07-21 15:23:01,415 DEBUG   :Sending: b'8610be7e'
2022-07-21 15:23:01,418 DEBUG   :Application frame 16 (setConcentrator) received: b'00'
2022-07-21 15:23:01,420 DEBUG   :Set concentrator type: [<EmberStatus.SUCCESS: 0>]
2022-07-21 15:23:01,422 DEBUG   :Send command setSourceRouteDiscoveryMode: (1,)
2022-07-21 15:23:01,426 DEBUG   :Sending: b'665721a90e2a1440597e'
2022-07-21 15:23:01,435 DEBUG   :Data frame: b'6757a1a90e2a3db2599418f27e'
2022-07-21 15:23:01,436 DEBUG   :Sending: b'87009f7e'
2022-07-21 15:23:01,439 DEBUG   :Application frame 90 (setSourceRouteDiscoveryMode) received: b'28000000'
2022-07-21 15:23:01,442 DEBUG   :Send command getConfigurationValue: (<EzspConfigId.CONFIG_APS_UNICAST_MESSAGE_COUNT: 3>,)
2022-07-21 15:23:01,446 DEBUG   :Sending: b'775421a9062a1688407e'
2022-07-21 15:23:01,456 DEBUG   :Data frame: b'7054a1a9062a15b859c58f7e'
2022-07-21 15:23:01,457 DEBUG   :Sending: b'8070787e'
2022-07-21 15:23:01,460 DEBUG   :Application frame 82 (getConfigurationValue) received: b'000a00'
2022-07-21 15:23:01,463 DEBUG   :APS_UNICAST_MESSAGE_COUNT is set to 10
2022-07-21 15:23:01,468 DEBUG   :Send command addEndpoint: (1, 260, <DeviceType.IAS_CONTROL: 1024>, 0, 5, 4, [0, 6, 10, 25, 1281], [1, 32, 1280, 1282])
2022-07-21 15:23:01,472 DEBUG   :Sending: b'005521a9562a14b658944e25af5192499a4e2dabf4ce668efcc64389fc7b3da283277e'
2022-07-21 15:23:01,486 DEBUG   :Data frame: b'0155a1a9562a15a4d97e'
2022-07-21 15:23:01,488 DEBUG   :Sending: b'8160597e'
2022-07-21 15:23:01,491 DEBUG   :Application frame 2 (addEndpoint) received: b'00'
2022-07-21 15:23:01,493 DEBUG   :Ezsp adding endpoint: [<EzspStatus.SUCCESS: 0>]
2022-07-21 15:23:01,496 DEBUG   :Send command addEndpoint: (2, 49246, <DeviceType.CONTROLLER: 2080>, 0, 1, 0, [0], [])
2022-07-21 15:23:01,500 DEBUG   :Sending: b'7d315a21a9562a17ec99b44225ab5592496ae87e'
2022-07-21 15:23:01,511 DEBUG   :Data frame: b'125aa1a9562a158e237e'
2022-07-21 15:23:01,512 DEBUG   :Sending: b'82503a7e'
2022-07-21 15:23:01,516 DEBUG   :Application frame 2 (addEndpoint) received: b'00'
2022-07-21 15:23:01,520 DEBUG   :Ezsp adding endpoint: [<EzspStatus.SUCCESS: 0>]
2022-07-21 15:23:01,522 DEBUG   :getting MFG_STRING token
2022-07-21 15:23:01,523 DEBUG   :Send command getMfgToken: (<EzspMfgTokenId.MFG_STRING: 1>,)
2022-07-21 15:23:01,528 DEBUG   :Sending: b'225b21a95f2a143e6e7e'
2022-07-21 15:23:01,539 DEBUG   :Data frame: b'235ba1a95f2a05f735f12644c8266db663b1d85412319810547e'
2022-07-21 15:23:01,541 DEBUG   :Sending: b'83401b7e'
2022-07-21 15:23:01,544 DEBUG   :Application frame 11 (getMfgToken) received: b'10456c656c616273ffffffffffffffffff'
2022-07-21 15:23:01,547 DEBUG   :getting MFG_BOARD_NAME token
2022-07-21 15:23:01,548 DEBUG   :Send command getMfgToken: (<EzspMfgTokenId.MFG_BOARD_NAME: 2>,)
2022-07-21 15:23:01,552 DEBUG   :Sending: b'335821a95f2a174ff77e'
2022-07-21 15:23:01,564 DEBUG   :Data frame: b'3458a1a95f2a05f715c67a1799aa6db663b1d8541231986c877e'
2022-07-21 15:23:01,566 DEBUG   :Sending: b'8430fc7e'
2022-07-21 15:23:01,569 DEBUG   :Application frame 11 (getMfgToken) received: b'10454c52303233ffffffffffffffffffff'
2022-07-21 15:23:01,571 DEBUG   :Send command getValue: (<EzspValueId.VALUE_VERSION_INFO: 17>,)
2022-07-21 15:23:01,575 DEBUG   :Sending: b'445921a9fe2a043f8c7e'
2022-07-21 15:23:01,585 DEBUG   :Data frame: b'4559a1a9fe2a15b570954c2fa9553823d57e'
2022-07-21 15:23:01,587 DEBUG   :Sending: b'8520dd7e'
2022-07-21 15:23:01,590 DEBUG   :Application frame 170 (getValue) received: b'00072901060a0300aa'
2022-07-21 15:23:01,594 INFO    :EZSP Radio manufacturer: Elelabs
2022-07-21 15:23:01,595 INFO    :EZSP Radio board name: ELR023
2022-07-21 15:23:01,596 INFO    :EmberZNet version: 6.10.3.0 build 297
2022-07-21 15:23:01,597 DEBUG   :Send command networkState: ()
2022-07-21 15:23:01,601 DEBUG   :Sending: b'555e21a94c2a48617e'
2022-07-21 15:23:01,612 DEBUG   :Data frame: b'565ea1a94c2a15100a7e'
2022-07-21 15:23:01,614 DEBUG   :Sending: b'8610be7e'
2022-07-21 15:23:01,617 DEBUG   :Application frame 24 (networkState) received: b'00'
2022-07-21 15:23:01,620 DEBUG   :Send command networkInit: ()
2022-07-21 15:23:01,624 DEBUG   :Sending: b'665f21a9432a7d33627e'
2022-07-21 15:23:01,637 DEBUG   :Data frame: b'675fa5a9432a1511717e'
2022-07-21 15:23:01,638 DEBUG   :Sending: b'87009f7e'
2022-07-21 15:23:01,640 DEBUG   :Data frame: b'775fb1a94d2a8533ee7e'
2022-07-21 15:23:01,641 DEBUG   :Application frame 23 (networkInit) received: b'00'
2022-07-21 15:23:01,643 DEBUG   :Sending: b'8070787e'
2022-07-21 15:23:01,646 DEBUG   :Send command getNetworkParameters: ()
2022-07-21 15:23:01,652 DEBUG   :Application frame 25 (stackStatusHandler) received: b'90'
2022-07-21 15:23:01,654 DEBUG   :Sending: b'705c21a97c2a7f7d5e7e'
2022-07-21 15:23:01,669 DEBUG   :Data frame: b'005ca1a97c2a15b3e8cb5c42c1f47aea8c262fa4edce678bfd3e9c8e650c7e'
2022-07-21 15:23:01,670 DEBUG   :Sending: b'8160597e'
2022-07-21 15:23:01,673 DEBUG   :Application frame 40 (getNetworkParameters) received: b'0001b15f16676ba1e8a31068080f0000000000f8ff07'
2022-07-21 15:23:01,682 DEBUG   :Send command getNodeId: ()
2022-07-21 15:23:01,686 DEBUG   :Sending: b'015d21a9732ac52d7e'
2022-07-21 15:23:01,697 DEBUG   :Data frame: b'115da1a9732a15b28ee57e'
2022-07-21 15:23:01,703 DEBUG   :Sending: b'82503a7e'
2022-07-21 15:23:01,719 DEBUG   :Application frame 39 (getNodeId) received: b'0000'
2022-07-21 15:23:01,723 DEBUG   :Send command getEui64: ()
2022-07-21 15:23:01,726 DEBUG   :Sending: b'126221a9722a4b6f7e'
2022-07-21 15:23:01,737 DEBUG   :Data frame: b'2262a1a9722a1241fc6ab5e966993a8f7e'
2022-07-21 15:23:01,739 DEBUG   :Sending: b'83401b7e'
2022-07-21 15:23:01,742 DEBUG   :Application frame 38 (getEui64) received: b'07f3a5feffcccccc'
2022-07-21 15:23:01,745 DEBUG   :Send command getConfigurationValue: (<EzspConfigId.CONFIG_SECURITY_LEVEL: 13>,)
2022-07-21 15:23:01,749 DEBUG   :Sending: b'236321a9062a7d38a5127e'
2022-07-21 15:23:01,761 DEBUG   :Data frame: b'3363a1a9062a15b75926e87e'
2022-07-21 15:23:01,762 DEBUG   :Sending: b'8430fc7e'
2022-07-21 15:23:01,765 DEBUG   :Application frame 82 (getConfigurationValue) received: b'000500'
2022-07-21 15:23:01,768 DEBUG   :Send command getKey: (<EmberKeyType.CURRENT_NETWORK_KEY: 3>,)
2022-07-21 15:23:01,772 DEBUG   :Sending: b'346021a93e2a16c8077e'
2022-07-21 15:23:01,785 DEBUG   :Data frame: b'4460a1a93e2a15b159979103bb2f0ee99f0c26c10c016514946c62d9fa7e3fa7ebcdde6f8fffc7dbd5d269acc07e'
2022-07-21 15:23:01,787 DEBUG   :Sending: b'8520dd7e'
2022-07-21 15:23:01,790 DEBUG   :Application frame 106 (getKey) received: b'00030003db26117a9ca00342016ae1cf029f69aa0150060000000000000000000000000000'
2022-07-21 15:23:01,800 DEBUG   :Send command getKey: (<EmberKeyType.TRUST_CENTER_LINK_KEY: 1>,)
2022-07-21 15:23:01,809 DEBUG   :Sending: b'456121a93e2a1491e57e'
2022-07-21 15:23:01,824 DEBUG   :Data frame: b'5561a1a93e2a15a85995f1af997cb6370622b3882232621a01a163f9fd7e3fa7ebcdde687c5a3924191ea5e4a67e'
2022-07-21 15:23:01,825 DEBUG   :Sending: b'8610be7e'
2022-07-21 15:23:01,829 DEBUG   :Application frame 106 (getKey) received: b'001a0001bb8a3329247e9a6c9423cffc0591fc6700700100000000000007f3a5feffcccccc'
2022-07-21 15:23:01,840 DEBUG   :Send command getCurrentSecurityState: ()
2022-07-21 15:23:01,843 DEBUG   :Sending: b'566621a93d2ab32a7e'
2022-07-21 15:23:01,854 DEBUG   :Data frame: b'6666a1a93d2a15465993b98054aa5e855026c17e'
2022-07-21 15:23:01,855 DEBUG   :Sending: b'87009f7e'
2022-07-21 15:23:01,858 DEBUG   :Application frame 105 (getCurrentSecurityState) received: b'00f40007f3a5feffcccccc'
2022-07-21 15:23:01,867 DEBUG   :getting MFG_STRING token
2022-07-21 15:23:01,869 DEBUG   :Send command getMfgToken: (<EzspMfgTokenId.MFG_STRING: 1>,)
2022-07-21 15:23:01,874 DEBUG   :Sending: b'676721a95f2a14be4a7e'
2022-07-21 15:23:01,886 DEBUG   :Data frame: b'7767a1a95f2a05f735f12644c8266db663b1d8541231984bfe7e'
2022-07-21 15:23:01,888 DEBUG   :Sending: b'8070787e'
2022-07-21 15:23:01,891 DEBUG   :Application frame 11 (getMfgToken) received: b'10456c656c616273ffffffffffffffffff'
2022-07-21 15:23:01,895 DEBUG   :getting MFG_BOARD_NAME token
2022-07-21 15:23:01,898 DEBUG   :Send command getMfgToken: (<EzspMfgTokenId.MFG_BOARD_NAME: 2>,)
2022-07-21 15:23:01,902 DEBUG   :Sending: b'706421a95f2a176ef67e'
2022-07-21 15:23:01,914 DEBUG   :Data frame: b'0064a1a95f2a05f715c67a1799aa6db663b1d85412319896197e'
2022-07-21 15:23:01,916 DEBUG   :Sending: b'8160597e'
2022-07-21 15:23:01,919 DEBUG   :Application frame 11 (getMfgToken) received: b'10454c52303233ffffffffffffffffffff'
2022-07-21 15:23:01,923 DEBUG   :Send command getValue: (<EzspValueId.VALUE_VERSION_INFO: 17>,)
2022-07-21 15:23:01,927 DEBUG   :Sending: b'016521a9fe2a04bfa87e'
2022-07-21 15:23:01,938 DEBUG   :Data frame: b'1165a1a9fe2a15b570954c2fa9553891127e'
2022-07-21 15:23:01,940 DEBUG   :Sending: b'82503a7e'
2022-07-21 15:23:01,942 DEBUG   :Application frame 170 (getValue) received: b'00072901060a0300aa'
2022-07-21 15:23:01,947 DEBUG   :Network info: NetworkInfo(extended_pan_id=a3:e8:a1:6b:67:16:5f:b1, pan_id=0x6810, nwk_update_id=0, nwk_manager_id=0x0000, channel=15, channel_mask=<Channels.ALL_CHANNELS: 134215680>, security_level=5, network_key=Key(key=db:26:11:7a:9c:a0:03:42:01:6a:e1:cf:02:9f:69:aa, tx_counter=413697, rx_counter=0, seq=0, partner_ieee=ff:ff:ff:ff:ff:ff:ff:ff), tc_link_key=Key(key=5a:69:67:42:65:65:41:6c:6c:69:61:6e:63:65:30:39, tx_counter=94208, rx_counter=0, seq=0, partner_ieee=cc:cc:cc:ff:fe:a5:f3:07), key_table=[], children=[], nwk_addresses={}, stack_specific={'ezsp': {'hashed_tclk': 'bb8a3329247e9a6c9423cffc0591fc67'}}, metadata={'ezsp': {'manufacturer': 'Elelabs', 'board': 'ELR023', 'version': '6.10.3.0 build 297', 'stack_version': 8}}, source='bellows@0.31.1')
2022-07-21 15:23:01,950 DEBUG   :Node info: NodeInfo(nwk=0x0000, ieee=cc:cc:cc:ff:fe:a5:f3:07, logical_type=<LogicalType.Coordinator: 0>)
2022-07-21 15:23:01,952 DEBUG   :Send command networkState: ()
2022-07-21 15:23:01,955 DEBUG   :Sending: b'126a21a94c2a6fd87e'
2022-07-21 15:23:01,964 DEBUG   :Data frame: b'226aa1a94c2a175cc27e'
2022-07-21 15:23:01,965 DEBUG   :Sending: b'83401b7e'
2022-07-21 15:23:01,968 DEBUG   :Application frame 24 (networkState) received: b'02'
2022-07-21 15:23:01,971 DEBUG   :Send command setPolicy: (<EzspPolicyId.TRUST_CENTER_POLICY: 0>, <EzspDecisionBitmask.IGNORE_UNSECURED_REJOINS|ALLOW_JOINS: 9>)
2022-07-21 15:23:01,976 DEBUG   :Sending: b'236b21a9012a15bb59e28c7e'
2022-07-21 15:23:01,985 DEBUG   :Data frame: b'336ba1a9012a15e9c67e'
2022-07-21 15:23:01,986 DEBUG   :Sending: b'8430fc7e'
2022-07-21 15:23:01,990 DEBUG   :Application frame 85 (setPolicy) received: b'00'
2022-07-21 15:23:01,992 DEBUG   :Send command setPolicy: (<EzspPolicyId.APP_KEY_REQUEST_POLICY: 6>, <EzspDecisionId.DENY_APP_KEY_REQUESTS: 96>)
2022-07-21 15:23:01,996 DEBUG   :Sending: b'346821a9012a7d33d259cbbe7e'
2022-07-21 15:23:02,005 DEBUG   :Data frame: b'4468a1a9012a15ba037e'
2022-07-21 15:23:02,007 DEBUG   :Sending: b'8520dd7e'
2022-07-21 15:23:02,011 DEBUG   :Application frame 85 (setPolicy) received: b'00'
2022-07-21 15:23:02,013 DEBUG   :Send command setPolicy: (<EzspPolicyId.TC_KEY_REQUEST_POLICY: 5>, <EzspDecisionId.ALLOW_TC_KEY_REQUESTS: 81>)
2022-07-21 15:23:02,017 DEBUG   :Sending: b'456921a9012a10e359a3617e'
2022-07-21 15:23:02,027 DEBUG   :Data frame: b'5569a1a9012a1570b97e'
2022-07-21 15:23:02,029 DEBUG   :Sending: b'8610be7e'
2022-07-21 15:23:02,032 DEBUG   :Application frame 85 (setPolicy) received: b'00'
2022-07-21 15:23:02,035 DEBUG   :Send command networkState: ()
2022-07-21 15:23:02,039 DEBUG   :Sending: b'566e21a94c2a8a6f7e'
2022-07-21 15:23:02,047 DEBUG   :Data frame: b'666ea1a94c2a1746497e'
2022-07-21 15:23:02,048 DEBUG   :Sending: b'87009f7e'
2022-07-21 15:23:02,052 DEBUG   :Application frame 24 (networkState) received: b'02'
2022-07-21 15:23:02,055 DEBUG   :Send command getNetworkParameters: ()
2022-07-21 15:23:02,058 DEBUG   :Sending: b'676f21a97c2a4f877e'
2022-07-21 15:23:02,070 DEBUG   :Data frame: b'776fa1a97c2a15b3e8cb5c42c1f47aea8c262fa4edce678bfd3e9c8e60a67e'
2022-07-21 15:23:02,072 DEBUG   :Sending: b'8070787e'
2022-07-21 15:23:02,075 DEBUG   :Application frame 40 (getNetworkParameters) received: b'0001b15f16676ba1e8a31068080f0000000000f8ff07'
2022-07-21 15:23:02,084 DEBUG   :Send command getNodeId: ()
2022-07-21 15:23:02,088 DEBUG   :Sending: b'706c21a9732a63ae7e'
2022-07-21 15:23:02,097 DEBUG   :Data frame: b'006ca1a9732a15b2156e7e'
2022-07-21 15:23:02,099 DEBUG   :Sending: b'8160597e'
2022-07-21 15:23:02,102 DEBUG   :Application frame 39 (getNodeId) received: b'0000'
2022-07-21 15:23:02,105 DEBUG   :Send command getEui64: ()
2022-07-21 15:23:02,109 DEBUG   :Sending: b'016d21a9722afaf27e'
2022-07-21 15:23:02,118 DEBUG   :Data frame: b'116da1a9722a1241fc6ab5e966992d467e'
2022-07-21 15:23:02,120 DEBUG   :Sending: b'82503a7e'
2022-07-21 15:23:02,122 DEBUG   :Application frame 38 (getEui64) received: b'07f3a5feffcccccc'
2022-07-21 15:23:02,126 DEBUG   :Send command getConfigurationValue: (<EzspConfigId.CONFIG_SECURITY_LEVEL: 13>,)
2022-07-21 15:23:02,130 DEBUG   :Sending: b'127221a9062a7d381bda7e'
2022-07-21 15:23:02,140 DEBUG   :Data frame: b'2272a1a9062a15b759e4527e'
2022-07-21 15:23:02,142 DEBUG   :Sending: b'83401b7e'
2022-07-21 15:23:02,145 DEBUG   :Application frame 82 (getConfigurationValue) received: b'000500'
2022-07-21 15:23:02,148 DEBUG   :Send command getKey: (<EmberKeyType.CURRENT_NETWORK_KEY: 3>,)
2022-07-21 15:23:02,152 DEBUG   :Sending: b'237321a93e2a16325c7e'
2022-07-21 15:23:02,165 DEBUG   :Data frame: b'3373a1a93e2a15b159979103bb2f0ee99f0c26c10c016514946c62d9fa7e3fa7ebcdde6f8fffc7dbd5d26907cf7e'
2022-07-21 15:23:02,167 DEBUG   :Sending: b'8430fc7e'
2022-07-21 15:23:02,170 DEBUG   :Application frame 106 (getKey) received: b'00030003db26117a9ca00342016ae1cf029f69aa0150060000000000000000000000000000'
2022-07-21 15:23:02,179 DEBUG   :Send command getKey: (<EmberKeyType.TRUST_CENTER_LINK_KEY: 1>,)
2022-07-21 15:23:02,183 DEBUG   :Sending: b'347021a93e2a14f2c17e'
2022-07-21 15:23:02,197 DEBUG   :Data frame: b'4470a1a93e2a15a85995f1af997cb6370622b3882232621a01a163f9fd7e3fa7ebcdde687c5a3924191ea52c257e'
2022-07-21 15:23:02,198 DEBUG   :Sending: b'8520dd7e'
2022-07-21 15:23:02,202 DEBUG   :Application frame 106 (getKey) received: b'001a0001bb8a3329247e9a6c9423cffc0591fc6700700100000000000007f3a5feffcccccc'
2022-07-21 15:23:02,211 DEBUG   :Send command getCurrentSecurityState: ()
2022-07-21 15:23:02,215 DEBUG   :Sending: b'457121a93d2a04c07e'
2022-07-21 15:23:02,225 DEBUG   :Data frame: b'5571a1a93d2a15465993b98054aa5e85507e717e'
2022-07-21 15:23:02,227 DEBUG   :Sending: b'8610be7e'
2022-07-21 15:23:02,230 DEBUG   :Application frame 105 (getCurrentSecurityState) received: b'00f40007f3a5feffcccccc'
2022-07-21 15:23:02,237 DEBUG   :getting MFG_STRING token
2022-07-21 15:23:02,238 DEBUG   :Send command getMfgToken: (<EzspMfgTokenId.MFG_STRING: 1>,)
2022-07-21 15:23:02,242 DEBUG   :Sending: b'567621a95f2a1400827e'
2022-07-21 15:23:02,254 DEBUG   :Data frame: b'6676a1a95f2a05f735f12644c8266db663b1d854123198ce1d7e'
2022-07-21 15:23:02,256 DEBUG   :Sending: b'87009f7e'
2022-07-21 15:23:02,259 DEBUG   :Application frame 11 (getMfgToken) received: b'10456c656c616273ffffffffffffffffff'
2022-07-21 15:23:02,262 DEBUG   :getting MFG_BOARD_NAME token
2022-07-21 15:23:02,263 DEBUG   :Send command getMfgToken: (<EzspMfgTokenId.MFG_BOARD_NAME: 2>,)
2022-07-21 15:23:02,267 DEBUG   :Sending: b'677721a95f2a1794ad7e'
2022-07-21 15:23:02,277 DEBUG   :Data frame: b'7777a1a95f2a05f715c67a1799aa6db663b1d85412319827657e'
2022-07-21 15:23:02,279 DEBUG   :Sending: b'8070787e'
2022-07-21 15:23:02,282 DEBUG   :Application frame 11 (getMfgToken) received: b'10454c52303233ffffffffffffffffffff'
2022-07-21 15:23:02,286 DEBUG   :Send command getValue: (<EzspValueId.VALUE_VERSION_INFO: 17>,)
2022-07-21 15:23:02,290 DEBUG   :Sending: b'707421a9fe2a04dc8c7e'
2022-07-21 15:23:02,300 DEBUG   :Data frame: b'0074a1a9fe2a15b570954c2fa95538ccf27e'
2022-07-21 15:23:02,302 DEBUG   :Sending: b'8160597e'
2022-07-21 15:23:02,305 DEBUG   :Application frame 170 (getValue) received: b'00072901060a0300aa'
2022-07-21 15:23:02,314 DEBUG   :[0x0000] Scheduling initialization
2022-07-21 15:23:02,319 DEBUG   :Starting EZSP watchdog
2022-07-21 15:23:02,322 DEBUG   :Tries remaining: 3
2022-07-21 15:23:02,324 INFO    :[0x0000] Requesting 'Node Descriptor'
2022-07-21 15:23:02,326 DEBUG   :Tries remaining: 2
2022-07-21 15:23:02,328 DEBUG   :[0x0000] Extending timeout for 0x01 request
2022-07-21 15:23:02,335 DEBUG   :Extending timeout for cc:cc:cc:ff:fe:a5:f3:07/0x0000
2022-07-21 15:23:02,337 DEBUG   :Send command setExtendedTimeout: (cc:cc:cc:ff:fe:a5:f3:07, True)
2022-07-21 15:23:02,342 DEBUG   :Sending: b'017521a92a2a1241fc6ab5e966999365c57e'
2022-07-21 15:23:02,352 DEBUG   :Data frame: b'1175a1a92a2abc2f7e'
2022-07-21 15:23:02,354 DEBUG   :Sending: b'82503a7e'
2022-07-21 15:23:02,356 DEBUG   :Application frame 126 (setExtendedTimeout) received: b''
2022-07-21 15:23:02,361 DEBUG   :Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0000, EmberApsFrame(profileId=0, clusterId=2, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=1), 2, b'\x01\x00\x00')
2022-07-21 15:23:02,377 DEBUG   :Sending: b'127a21a9602a15b259944a27aa5592099d4e27aaefcd668bfddadc7e'
2022-07-21 15:23:02,389 DEBUG   :Data frame: b'227aa1a9602a1592d3e77e'
2022-07-21 15:23:02,390 DEBUG   :Sending: b'83401b7e'
2022-07-21 15:23:02,393 DEBUG   :Application frame 52 (sendUnicast) received: b'0020'
2022-07-21 15:23:02,394 DEBUG   :Data frame: b'327ab1a9112a15b259964a25aa1593499c6ed8abedce9874fec7638978d57e'
2022-07-21 15:23:02,400 DEBUG   :Sending: b'8430fc7e'
2022-07-21 15:23:02,404 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'000000020000004001000020ff000000ffff03010000'
2022-07-21 15:23:02,406 DEBUG   :Data frame: b'427ab1a9112a15b25996ca25aa1593499c6fd8abedce9874ecc76389fc7e7f2826668cef8fbeeb5bd5d24c4b7e'
2022-07-21 15:23:02,412 DEBUG   :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=32), 255, 0, 0x0000, 255, 255, b'\x01\x00\x00']
2022-07-21 15:23:02,413 DEBUG   :Sending: b'8520dd7e'
2022-07-21 15:23:02,419 DEBUG   :Received frame on uninitialized device <EZSPCoordinator model='EZSP' manuf='Silicon Labs' nwk=0x0000 ieee=cc:cc:cc:ff:fe:a5:f3:07 is_initialized=False> from ep 0 to ep 0, cluster 2: b'\x01\x00\x00'
2022-07-21 15:23:02,425 DEBUG   :Data frame: b'527ab1a96b2a15b259944a27aa5592099d4e278befce6726fd7e'
2022-07-21 15:23:02,426 DEBUG   :[0x0000:zdo] ZDO request ZDOCmd.Node_Desc_req: [0x0000]
2022-07-21 15:23:02,428 DEBUG   :Sending: b'8610be7e'
2022-07-21 15:23:02,431 DEBUG   :[0x0000:zdo] No handler for ZDO request:ZDOCmd.Node_Desc_req([0x0000])
2022-07-21 15:23:02,451 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'000000028000004001000021ff000000ffff110100000000408fcdab528000412c800000'
2022-07-21 15:23:02,460 DEBUG   :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=33), 255, 0, 0x0000, 255, 255, b'\x01\x00\x00\x00\x00@\x8f\xcd\xabR\x80\x00A,\x80\x00\x00']
2022-07-21 15:23:02,467 DEBUG   :Received frame on uninitialized device <EZSPCoordinator model='EZSP' manuf='Silicon Labs' nwk=0x0000 ieee=cc:cc:cc:ff:fe:a5:f3:07 is_initialized=False> from ep 0 to ep 0, cluster 32770: b'\x01\x00\x00\x00\x00@\x8f\xcd\xabR\x80\x00A,\x80\x00\x00'
2022-07-21 15:23:02,479 DEBUG   :Application frame 63 (messageSentHandler) received: b'0000000000020000004001000020020000'
2022-07-21 15:23:02,498 DEBUG   :Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0, EmberApsFrame(profileId=0, clusterId=2, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=32), 2, <EmberStatus.SUCCESS: 0>, b'']
2022-07-21 15:23:02,505 INFO    :[0x0000] Got Node Descriptor: NodeDescriptor(logical_type=<LogicalType.Coordinator: 0>, complex_descriptor_available=0, user_descriptor_available=0, reserved=0, aps_flags=0, frequency_band=<FrequencyBand.Freq2400MHz: 8>, mac_capability_flags=<MACCapabilityFlags.AllocateAddress|RxOnWhenIdle|MainsPowered|FullFunctionDevice|AlternatePanCoordinator: 143>, manufacturer_code=43981, maximum_buffer_size=82, maximum_incoming_transfer_size=128, server_mask=11329, maximum_outgoing_transfer_size=128, descriptor_capability_field=<DescriptorCapability.NONE: 0>, *allocate_address=True, *is_alternate_pan_coordinator=True, *is_coordinator=True, *is_end_device=False, *is_full_function_device=True, *is_mains_powered=True, *is_receiver_on_when_idle=True, *is_router=False, *is_security_capable=False)
2022-07-21 15:23:02,509 INFO    :[0x0000] Already have endpoints: {0: <zigpy.zdo.ZDO object at 0xaa6ebbe0>, 1: <EZSPEndpoint id=1 in=[] out=[] status=<Status.NEW: 0>>}
2022-07-21 15:23:02,511 INFO    :[0x0000] Initializing endpoints [<EZSPEndpoint id=1 in=[] out=[] status=<Status.NEW: 0>>]
2022-07-21 15:23:02,512 INFO    :[0x0000:1] Discovering endpoint information
2022-07-21 15:23:02,514 DEBUG   :Tries remaining: 3
2022-07-21 15:23:02,519 DEBUG   :Send command sendUnicast: (<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0x0000, EmberApsFrame(profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=3), 4, b'\x03\x00\x00\x01')
2022-07-21 15:23:02,531 DEBUG   :Sending: b'267b21a9602a15b259944a21aa5592099d4e27a8e9ca648bfdc7d3d57e'
2022-07-21 15:23:02,544 DEBUG   :Data frame: b'637ba1a9602a1590fac77e'
2022-07-21 15:23:02,545 DEBUG   :Sending: b'87009f7e'
2022-07-21 15:23:02,548 DEBUG   :Application frame 52 (sendUnicast) received: b'0022'
2022-07-21 15:23:02,550 DEBUG   :Data frame: b'737bb1a9112a15b259904a25aa1593499c6cd8abedce9874f9c56389fd3ffc7e'
2022-07-21 15:23:02,554 DEBUG   :Sending: b'8070787e'
2022-07-21 15:23:02,557 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'000000040000004001000022ff000000ffff0403000001'
2022-07-21 15:23:02,564 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=34), 255, 0, 0x0000, 255, 255, b'\x03\x00\x00\x01']
2022-07-21 15:23:02,568 DEBUG   :Data frame: b'037bb1a9112a15b25990ca25aa1593499c6dd8abedce9874e2c56389fc643ea3eacdda6f8affc7ddd5d869954622ace8773b85ea7587439de6477e'
2022-07-21 15:23:02,571 DEBUG   :Received frame on uninitialized device <EZSPCoordinator model='EZSP' manuf='Silicon Labs' nwk=0x0000 ieee=cc:cc:cc:ff:fe:a5:f3:07 is_initialized=False> from ep 0 to ep 0, cluster 4: b'\x03\x00\x00\x01'
2022-07-21 15:23:02,573 DEBUG   :Sending: b'8160597e'
2022-07-21 15:23:02,576 DEBUG   :[0x0000:zdo] ZDO request ZDOCmd.Simple_Desc_req: [0x0000, 1]
2022-07-21 15:23:02,581 DEBUG   :Data frame: b'137bb1a96b2a15b259944a21aa5592099d4e2789e9ce67bb007e'
2022-07-21 15:23:02,582 DEBUG   :[0x0000:zdo] No handler for ZDO request:ZDOCmd.Simple_Desc_req([0x0000, 1])
2022-07-21 15:23:02,583 DEBUG   :Sending: b'82503a7e'
2022-07-21 15:23:02,592 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'000000048000004001000023ff000000ffff1f030000001a01040100040005000006000a0019000105040100200000050205'
2022-07-21 15:23:02,604 DEBUG   :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=35), 255, 0, 0x0000, 255, 255, b'\x03\x00\x00\x00\x1a\x01\x04\x01\x00\x04\x00\x05\x00\x00\x06\x00\n\x00\x19\x00\x01\x05\x04\x01\x00 \x00\x00\x05\x02\x05']
2022-07-21 15:23:02,609 DEBUG   :Received frame on uninitialized device <EZSPCoordinator model='EZSP' manuf='Silicon Labs' nwk=0x0000 ieee=cc:cc:cc:ff:fe:a5:f3:07 is_initialized=False> from ep 0 to ep 0, cluster 32772: b'\x03\x00\x00\x00\x1a\x01\x04\x01\x00\x04\x00\x05\x00\x00\x06\x00\n\x00\x19\x00\x01\x05\x04\x01\x00 \x00\x00\x05\x02\x05'
2022-07-21 15:23:02,617 DEBUG   :Application frame 63 (messageSentHandler) received: b'0000000000040000004001000022040000'
2022-07-21 15:23:02,630 DEBUG   :Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0, EmberApsFrame(profileId=0, clusterId=4, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=34), 4, <EmberStatus.SUCCESS: 0>, b'']
2022-07-21 15:23:02,636 INFO    :[0x0000:1] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=1, profile=260, device_type=1024, device_version=0, input_clusters=[0, 6, 10, 25, 1281], output_clusters=[1, 32, 1280, 1282])
2022-07-21 15:23:02,639 INFO    :[0x0000] Already have model and manufacturer info
2022-07-21 15:23:02,641 INFO    :[0x0000] Discovered basic device information for <EZSPCoordinator model='EZSP' manuf='Silicon Labs' nwk=0x0000 ieee=cc:cc:cc:ff:fe:a5:f3:07 is_initialized=True>
2022-07-21 15:23:02,642 DEBUG   :Device is initialized <EZSPCoordinator model='EZSP' manuf='Silicon Labs' nwk=0x0000 ieee=cc:cc:cc:ff:fe:a5:f3:07 is_initialized=True>
2022-07-21 15:23:02,645 DEBUG   :Checking quirks for Silicon Labs EZSP (cc:cc:cc:ff:fe:a5:f3:07)
2022-07-21 15:23:02,647 ERROR   :=================Couldn't start network 1
2022-07-21 15:23:02,656 DEBUG   :getting MFG_STRING token
2022-07-21 15:23:02,658 ERROR   : [       ZigpyCom_7] Issue in request , dumping stack: Traceback (most recent call last):
  File "/var/lib/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/AppBellows.py", line 110, in _startup
    await self.start_network()
  File "/var/lib/domoticz/plugins/Domoticz-Zigbee/bellows/zigbee/application.py", line 208, in start_network
    ezsp_device.endpoints[1].member_of.update(db_device.endpoints[1].member_of)
KeyError: 1