Implements https://github.com/zigpy/zigpy/pull/848.

Unit tests for zigpy-znp pass locally.

Hello @puddly, I tried to use the new radio API and last on the same conclusion as @pipiche38, I didn't succeeded in putting the pieces together. As I understand the changes, the previous startup() function is now replaced by connect() and start_network().

connect() goes fine and I have the log: "Connected to /dev/ttyUSB0 at 115200 baud"
start_network() is not going to the end, last logs are a problem on commissioning:

2022-02-14 23:50:32,122 DEBUG   :Sending request: AppConfig.BDBStartCommissioning.Req(Mode=<BDBCommissioningMode.NwkFormation: 4>)
2022-02-14 23:50:32,128 DEBUG   :Received command: AppConfig.BDBStartCommissioning.Rsp(Status=<Status.SUCCESS: 0>)
2022-02-14 23:50:32,129 DEBUG   :Received command: AppConfig.BDBCommissioningNotification.Callback(Status=<BDBCommissioningStatus.FormationFailure: 8>, Mode=<BDBCommissioningMode.NwkSteering: 2>, RemainingModes=<BDBCommissioningMode.NONE: 0>)

Any idea what I missed? I'm still a beginner.

I don't see the possibility to form a new network through an option of start_network(), should form_network() called directly ?

As I understand the changes, the previous startup() function is now replaced by connect() and start_network().

The API hasn't really changed. startup() has moved into zigpy since all radios will provide start_network, write_network_settings, etc. so the logic will be the same for all of them: https://github.com/puddly/zigpy/blob/e7e687007c344398325990b2ed886e3c40542ccc/zigpy/application.py#L57-L73

You still use it the way you did before, you just need to install the "new radio API" branches of zigpy-znp and zigpy. In theory, nothing will change.

start_network() is not going to the end, last logs are a problem on commissioning:

FormationFailure is normal but if the function isn't exiting, that may be a bug. I will take a look at it later.

I don't see the possibility to form a new network through an option of start_network(), should form_network() called directly ?

Pass auto_form=True to startup or call form_network directly, the code merely calls write_network_settings with randomly generated settings: https://github.com/puddly/zigpy/blob/e7e687007c344398325990b2ed886e3c40542ccc/zigpy/application.py#L105-L168

As I understand the changes, the previous startup() function is now replaced by connect() and start_network().

The API hasn't really changed. startup() has moved into zigpy since all radios will provide start_network, write_network_settings, etc. so the logic will be the same for all of them: https://github.com/puddly/zigpy/blob/e7e687007c344398325990b2ed886e3c40542ccc/zigpy/application.py#L57-L73

You still use it the way you did before, you just need to install the "new radio API" branches of zigpy-znp and zigpy. In theory, nothing will change.

start_network() is not going to the end, last logs are a problem on commissioning:

FormationFailure is normal but if the function isn't exiting, that may be a bug. I will take a look at it later.

I don't see the possibility to form a new network through an option of start_network(), should form_network() called directly ?

Pass auto_form=True to startup or call form_network directly, the code merely calls write_network_settings with randomly generated settings: https://github.com/puddly/zigpy/blob/e7e687007c344398325990b2ed886e3c40542ccc/zigpy/application.py#L105-L168

It really a shame, we had a working environment and this small changes as you say, make the think not working anymore. I'm not sure this is a comminissioning issue, as the Coordinator works very well with the old radio API

Feb 15 08:56:31 rasp domoticz[25092]: Traceback (most recent call last):
Feb 15 08:56:31 rasp domoticz[25092]:   File "/usr/lib/python3.9/threading.py", line 973, in _bootstrap_inner
Feb 15 08:56:31 rasp domoticz[25092]:     self.run()
Feb 15 08:56:31 rasp domoticz[25092]:   File "/usr/lib/python3.9/threading.py", line 910, in run
Feb 15 08:56:31 rasp domoticz[25092]:     self._target(*self._args, **self._kwargs)
Feb 15 08:56:31 rasp domoticz[25092]:   File "/var/lib/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 73, in zigpy_thread
Feb 15 08:56:31 rasp domoticz[25092]:     asyncio.run(
Feb 15 08:56:31 rasp domoticz[25092]:   File "/usr/lib/python3.9/asyncio/runners.py", line 44, in run
Feb 15 08:56:31 rasp domoticz[25092]:     return loop.run_until_complete(main)
Feb 15 08:56:31 rasp domoticz[25092]:   File "/usr/lib/python3.9/asyncio/base_events.py", line 642, in run_until_complete
Feb 15 08:56:31 rasp domoticz[25092]:     return future.result()
Feb 15 08:56:31 rasp domoticz[25092]:   File "/var/lib/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 108, in radio_start
Feb 15 08:56:31 rasp domoticz[25092]:     await self.app.startup(
Feb 15 08:56:31 rasp domoticz[25092]:   File "/var/lib/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/AppZnp.py", line 59, in startup
Feb 15 08:56:31 rasp domoticz[25092]:     await super().startup(auto_form=auto_form)
Feb 15 08:56:31 rasp domoticz[25092]:   File "/var/lib/domoticz/plugins/Domoticz-Zigbee/zigpy/application.py", line 70, in startup
Feb 15 08:56:31 rasp domoticz[25092]:     await self.start_network()
Feb 15 08:56:31 rasp domoticz[25092]:   File "/var/lib/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/zigbee/application.py", line 183, in start_network
Feb 15 08:56:31 rasp domoticz[25092]:     await self._znp.start_network()
Feb 15 08:56:31 rasp domoticz[25092]:   File "/var/lib/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/api.py", line 255, in start_network
Feb 15 08:56:31 rasp domoticz[25092]:     raise RuntimeError(
Feb 15 08:56:31 rasp domoticz[25092]: RuntimeError: Network formation failed: AppConfig.BDBCommissioningNotification.Callback(Status=<BDBCommissioningStatus.FormationFailure: 8>, Mode=<BDBCommissioningMode.NwkSteering: 2>, RemainingModes=<BDBCommissioningMode.NONE: 0>)

@puddly you should guess that if everything was working like before, we won't be there :)

The startup from zigpy is not calling connect() so we have to call it first ?

No, that's a regression. I will re-add it to zigpy's startup.

I had to add a try/except on the call of await self._znp.start_network() in application.py or the function was not ending properly. I always have this exception at startup.

No, that's a regression. I will re-add it to zigpy's startup.

@puddly, can you tell us, how is the standard framework, because I'm struggling that we are facing this issue and you not, no may be we are doing it correctly. Better than we use the same approach to avoid future issues

Asked in https://github.com/zigpy/zigpy-zigate/pull/117 if using puddly's new radio API repo branches for zigpy, zigpy-znp, zigpy-cli, and zigpy-zigate(?):

https://github.com/puddly/zigpy/tree/puddly/new-radio-settings-api

https://github.com/puddly/zigpy-znp/tree/puddly/new-radio-settings-api

https://github.com/puddly/zigpy-cli/tree/puddly/zigpy-radio-api

https://github.com/puddly/zigpy-zigate/tree/puddly/new-radio-api

They are all updated so need to install those modified versions of zigpy and zigpy-znp from those branches to test new radio API:

# May need to uninstall zigpy, zigpy-znp, zigpy-cli, and zigpy-zigate first
pip install \
    git+https://github.com/puddly/zigpy.git@puddly/new-radio-settings-api \
    git+https://github.com/puddly/zigpy-znp.git@puddly/new-radio-settings-api \
    git+https://github.com/puddly/zigpy-cli.git@puddly/zigpy-radio-api \
    git+https://github.com/puddly/zigpy-zigate.git@puddly/new-radio-api

As mentioned may need to first uninstall all of them before installing the modified versions of them from puddly's repo branches.

Hello Hedda, Installation steps are well understood and it's not the problem we encountered. With the new radio libraries, the plugin didn't initialized and failed to run. Two problems identified:

connect() was not called anymore
an exception is not managed during the start network procedure and raised each time

Our concern is why only us met the problem? How the modification are tested and in which condition, that'll help.

@puddly, we are trying to test your PRs by taking your repository for zigpy and zigpy-znp on the new-radio-api branche, but somehow the results are cahotic, which means sometime it works some other time it doesn't

@deufo has identified that the start_network () fails time to time by just adding a try/except on line 183 - encapsulate the start_network()

2022-02-19 13:01:28,574 DEBUG :start_network exception: Network formation failed: AppConfig.BDBCommissioningNotification.Callback(Status=<BDBCommissioningStatus.FormationFailure: 8>, Mode=<BDBCommissioningMode.NwkSteering: 2>, RemainingModes=<BDBCommissioningMode.NONE: 0>)

So for now, we cannot even think to test zigpy-zigate. can you help us on this ?

basically here is the change which makes our plugin working

diff --git a/zigpy_znp/zigbee/application.py b/zigpy_znp/zigbee/application.py
index 2d6f578..fee47c0 100644
--- a/zigpy_znp/zigbee/application.py
+++ b/zigpy_znp/zigbee/application.py
@@ -180,7 +180,11 @@ class ControllerApplication(zigpy.application.ControllerApplication):
         if self.state.node_info == zigpy.state.NodeInfo():
             await self.load_network_info()

-        await self._znp.start_network()
+        asyncio.sleep(1)
+        try:
+            await self._znp.start_network()
+        except:
+            LOGGER.debug("start_network exception: %s" %e)

         self._version_rsp = await self._znp.request(c.SYS.Version.Req())

I will take a look at this later next week.

Having this after a new network request:

Traceback (most recent call last):
File "/usr/lib/python3.7/threading.py", line 917, in _bootstrap_inner
self.run()
File "/usr/lib/python3.7/threading.py", line 865, in run
self._target(*self._args, **self._kwargs)
File "/opt/domoticz/userdata/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 83, in zigpy_thread
loop.run_until_complete(task)
File "/usr/lib/python3.7/asyncio/base_events.py", line 584, in run_until_complete
return future.result()
File "/opt/domoticz/userdata/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 172, in radio_start
permit_to_join_timer = self.permit_to_join_timer)
File "/opt/domoticz/userdata/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/AppZnp.py", line 63, in startup
await self.load_network_info( load_devices=True )
File "/opt/domoticz/userdata/plugins/Domoticz-Zigbee/zigpy_znp/zigbee/application.py", line 148, in load_network_info
await self._znp.load_network_info(load_devices=load_devices)
File "/opt/domoticz/userdata/plugins/Domoticz-Zigbee/zigpy_znp/api.py", line 120, in load_network_info
ieee = await self.nvram.osal_read(OsalNvIds.EXTADDR, item_type=t.EUI64)
File "/opt/domoticz/userdata/plugins/Domoticz-Zigbee/zigpy_znp/nvram.py", line 171, in osal_read
raise KeyError(f"NV item does not exist: {nv_id!r}")
KeyError: 'NV item does not exist: <OsalNvIds.EXTADDR: 1>'

with the most recent update, the network startup doesn't work

domoticz@pi4:~/domoticz/plugins/Domoticz-Zigbee $ python3 -m zigpy_znp.tools.energy_scan /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0

2022-03-31 09:07:18.739 pi4 main INFO Starting up zigpy-znp

Traceback (most recent call last): File "/home/domoticz/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/api.py", line 275, in start_network await started_as_coordinator asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last): File "/home/domoticz/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/api.py", line 275, in start_network await started_as_coordinator File "/usr/local/lib/python3.9/dist-packages/async_timeout/init.py", line 129, in aexit self._do_exit(exc_type) File "/usr/local/lib/python3.9/dist-packages/async_timeout/init.py", line 212, in _do_exit raise asyncio.TimeoutError asyncio.exceptions.TimeoutError

The above exception was the direct cause of the following exception:

Traceback (most recent call last): File "/usr/lib/python3.9/runpy.py", line 197, in _run_module_as_main return _run_code(code, main_globals, None, File "/usr/lib/python3.9/runpy.py", line 87, in _run_code exec(code, run_globals) File "/home/domoticz/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/tools/energy_scan.py", line 96, in asyncio.run(main(sys.argv[1:])) # pragma: no cover File "/usr/lib/python3.9/asyncio/runners.py", line 44, in run return loop.run_until_complete(main) File "/usr/lib/python3.9/asyncio/base_events.py", line 642, in run_until_complete return future.result() File "/home/domoticz/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/tools/energy_scan.py", line 92, in main await perform_energy_scan(args.serial, num_scans=args.num_scans) File "/home/domoticz/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/tools/energy_scan.py", line 25, in perform_energy_scan await app.start_network(read_only=True) File "/home/domoticz/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/zigbee/application.py", line 183, in start_network await self._znp.start_network() File "/home/domoticz/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/api.py", line 277, in start_network raise RuntimeError( RuntimeError: Network formation refused, RF environment is likely too noisy. Temporarily unscrew the antenna or shield the coordinator with metal until a network is formed.

That isn't a problem that can be fixed with ZNP. All it means is that the radio effectively crashed during network formation, which is caused by its formation scan failing. Move it to another location or use a USB extension cable.

That isn't a problem that can be fixed with ZNP. All it means is that the radio effectively crashed during network formation, which is caused by its formation scan failing. Move it to another location or use a USB extension cable.

ok, but I run the same command just before update zigpy_znp and it works like a charm. So why should a code change in zigpy would make this issue visible ?

Can you check again? If it still happens, run both commands with -v and attach the log files for both. I can't reproduce the issue with my zzh.

This is happening with a zzh, and basically we are not able to start.

domoticz@pi4:~/domoticz/plugins/Domoticz-Zigbee $ python3 -m zigpy_znp.tools.energy_scan -v /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0
2022-03-31 17:33:33.879 pi4 __main__ INFO Starting up zigpy-znp
2022-03-31 17:33:33.882 pi4 zigpy_znp.uart DEBUG Connecting to /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 at 115200 baud
2022-03-31 17:33:33.887 pi4 zigpy_znp.uart DEBUG Opened /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 serial port
2022-03-31 17:33:33.888 pi4 zigpy_znp.uart DEBUG Connected to /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 at 115200 baud
2022-03-31 17:33:33.888 pi4 zigpy_znp.api DEBUG Toggling RTS/DTR pins to skip bootloader or reset chip
2022-03-31 17:33:33.889 pi4 zigpy_znp.uart DEBUG Setting serial pin states: DTR=False, RTS=False
2022-03-31 17:33:34.040 pi4 zigpy_znp.uart DEBUG Setting serial pin states: DTR=False, RTS=True
2022-03-31 17:33:34.193 pi4 zigpy_znp.uart DEBUG Setting serial pin states: DTR=False, RTS=False
2022-03-31 17:33:34.346 pi4 zigpy_znp.api DEBUG Sending request: SYS.Ping.Req()
2022-03-31 17:33:34.352 pi4 zigpy_znp.api DEBUG Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2022-03-31 17:33:34.353 pi4 zigpy_znp.api DEBUG Radio is alive: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2022-03-31 17:33:34.353 pi4 zigpy_znp.nvram DEBUG Detecting struct alignment
2022-03-31 17:33:34.354 pi4 zigpy_znp.api DEBUG Sending request: UTIL.AssocFindDevice.Req(Index=0)
2022-03-31 17:33:34.362 pi4 zigpy_znp.api DEBUG Received command: UTIL.AssocFindDevice.Rsp(Device=b'\xFE\xFF\x00\x20\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-03-31 17:33:34.362 pi4 zigpy_znp.nvram DEBUG Detected struct alignment: True
2022-03-31 17:33:34.363 pi4 zigpy_znp.api DEBUG Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.TCLK_TABLE: 4>, SubId=0)
2022-03-31 17:33:34.370 pi4 zigpy_znp.api DEBUG Received command: SYS.NVLength.Rsp(Length=20)
2022-03-31 17:33:34.371 pi4 zigpy_znp.api DEBUG Sending request: SYS.NVRead.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.TCLK_TABLE: 4>, SubId=0, Offset=0, Length=20)
2022-03-31 17:33:34.380 pi4 zigpy_znp.api DEBUG Received command: SYS.NVRead.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xFF\x00\x00\x00')
2022-03-31 17:33:34.380 pi4 zigpy_znp.nvram DEBUG Read NVRAM[NvSysIds.ZSTACK][ExNvIds.TCLK_TABLE][0x0000] = b'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xFF\x00\x00\x00'
2022-03-31 17:33:34.381 pi4 zigpy_znp.api DEBUG Detected Z-Stack 3.3
2022-03-31 17:33:34.381 pi4 zigpy_znp.api DEBUG Connected to /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 at 115200 baud
2022-03-31 17:33:34.386 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NIB: 33>)
2022-03-31 17:33:34.391 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVLength.Rsp(ItemLen=116)
2022-03-31 17:33:34.392 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NIB: 33>, Offset=0)
2022-03-31 17:33:34.408 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x72\x05\x02\x33\x0F\x33\x00\x1E\x00\x00\x00\x01\x05\x01\x8F\x00\x07\x00\x02\x0D\x1E\x00\x00\x00\x11\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x81\xDC\x08\x00\x00\x00\x02\x00\x0F\x0F\x04\x00\x01\x00\x00\x00\x01\x00\x00\x00\x00\x0C\x92\x0E\xBC\xA1\x71\x7B\xF9\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x0F\x05\x00\x01\x64\x0A\x01\x00\x00\x00\x00\x00\x00\x00')
2022-03-31 17:33:34.412 pi4 zigpy_znp.nvram DEBUG Read NVRAM["LEGACY"][0x0021] = NIB(SequenceNum=114, PassiveAckTimeout=5, MaxBroadcastRetries=2, MaxChildren=51, MaxDepth=15, MaxRouters=51, dummyNeighborTable=0, BroadcastDeliveryTime=30, ReportConstantCost=0, RouteDiscRetries=0, dummyRoutingTable=0, SecureAllFrames=1, SecurityLevel=5, SymLink=1, CapabilityFlags=143, TransactionPersistenceTime=7, nwkProtocolVersion=2, RouteDiscoveryTime=13, RouteExpiryTime=30, nwkDevAddress=0x0000, nwkLogicalChannel=17, nwkCoordAddress=0x0000, nwkCoordExtAddress=00:00:00:00:00:00:00:00, nwkPanId=56449, nwkState=<NwkState.NWK_ROUTER: 8>, channelList=<Channels.CHANNEL_17: 131072>, beaconOrder=15, superFrameOrder=15, scanDuration=4, battLifeExt=0, allocatedRouterAddresses=1, allocatedEndDeviceAddresses=1, nodeDepth=0, extendedPANID=f9:7b:71:a1:bc:0e:92:0c, nwkKeyLoaded=<Bool.true: 1>, spare1=NwkKeyDesc(KeySeqNum=0, Key=00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00), spare2=NwkKeyDesc(KeySeqNum=0, Key=00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00), spare3=0, spare4=0, nwkLinkStatusPeriod=15, nwkRouterAgeLimit=5, nwkUseMultiCast=<Bool.false: 0>, nwkIsConcentrator=<Bool.true: 1>, nwkConcentratorDiscoveryTime=100, nwkConcentratorRadius=10, nwkAllFresh=1, nwkManagerAddr=0x0000, nwkTotalTransmissions=0, nwkUpdateId=0)
2022-03-31 17:33:34.412 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.BDBNODEISONANETWORK: 85>)
2022-03-31 17:33:34.423 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2022-03-31 17:33:34.423 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.BDBNODEISONANETWORK: 85>, Offset=0)
2022-03-31 17:33:34.439 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x01')
2022-03-31 17:33:34.440 pi4 zigpy_znp.nvram DEBUG Read NVRAM["LEGACY"][0x0055] = 1
2022-03-31 17:33:34.440 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.EXTADDR: 1>)
2022-03-31 17:33:34.446 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVLength.Rsp(ItemLen=8)
2022-03-31 17:33:34.447 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.EXTADDR: 1>, Offset=0)
2022-03-31 17:33:34.455 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x93\xAB\x8D\x23\x00\x4B\x12\x00')
2022-03-31 17:33:34.456 pi4 zigpy_znp.nvram DEBUG Read NVRAM["LEGACY"][0x0001] = 00:12:4b:00:23:8d:ab:93
2022-03-31 17:33:34.456 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.LOGICAL_TYPE: 135>)
2022-03-31 17:33:34.467 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2022-03-31 17:33:34.467 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.LOGICAL_TYPE: 135>, Offset=0)
2022-03-31 17:33:34.483 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00')
2022-03-31 17:33:34.483 pi4 zigpy_znp.nvram DEBUG Read NVRAM["LEGACY"][0x0087] = <DeviceLogicalType.Coordinator: 0>
2022-03-31 17:33:34.484 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NWK_ACTIVE_KEY_INFO: 58>)
2022-03-31 17:33:34.494 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVLength.Rsp(ItemLen=17)
2022-03-31 17:33:34.495 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NWK_ACTIVE_KEY_INFO: 58>, Offset=0)
2022-03-31 17:33:34.512 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00\x75\x4D\x47\x5D\x99\x5A\x61\xE4\x5B\x2F\x0E\xEE\xB7\x29\xA2\xF1')
2022-03-31 17:33:34.513 pi4 zigpy_znp.nvram DEBUG Read NVRAM["LEGACY"][0x003a] = NwkKeyDesc(KeySeqNum=0, Key=75:4d:47:5d:99:5a:61:e4:5b:2f:0e:ee:b7:29:a2:f1)
2022-03-31 17:33:34.513 pi4 zigpy_znp.api DEBUG Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.NWK_SEC_MATERIAL_TABLE: 7>, SubId=0)
2022-03-31 17:33:34.519 pi4 zigpy_znp.api DEBUG Received command: SYS.NVLength.Rsp(Length=12)
2022-03-31 17:33:34.520 pi4 zigpy_znp.api DEBUG Sending request: SYS.NVRead.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.NWK_SEC_MATERIAL_TABLE: 7>, SubId=0, Offset=0, Length=12)
2022-03-31 17:33:34.526 pi4 zigpy_znp.api DEBUG Received command: SYS.NVRead.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\xB4\x0C\x00\x00\x0C\x92\x0E\xBC\xA1\x71\x7B\xF9')
2022-03-31 17:33:34.527 pi4 zigpy_znp.nvram DEBUG Read NVRAM[NvSysIds.ZSTACK][ExNvIds.NWK_SEC_MATERIAL_TABLE][0x0000] = NwkSecMaterialDesc(FrameCounter=3252, ExtendedPanID=f9:7b:71:a1:bc:0e:92:0c)
2022-03-31 17:33:34.528 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.TCLK_SEED: 257>)
2022-03-31 17:33:34.538 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVLength.Rsp(ItemLen=16)
2022-03-31 17:33:34.539 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.TCLK_SEED: 257>, Offset=0)
2022-03-31 17:33:34.556 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x50\x84\xB5\x02\xDD\x71\x5C\x51\x00\x62\x2C\x44\xBD\x55\x0F\x38')
2022-03-31 17:33:34.557 pi4 zigpy_znp.nvram DEBUG Read NVRAM["LEGACY"][0x0101] = 50:84:b5:02:dd:71:5c:51:00:62:2c:44:bd:55:0f:38
2022-03-31 17:33:34.558 pi4 zigpy_znp.api DEBUG Sending request: AppConfig.BDBStartCommissioning.Req(Mode=<BDBCommissioningMode.NwkFormation: 4>)
2022-03-31 17:33:34.564 pi4 zigpy_znp.api DEBUG Received command: AppConfig.BDBStartCommissioning.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:33:34.565 pi4 zigpy_znp.api DEBUG Received command: AppConfig.BDBCommissioningNotification.Callback(Status=<BDBCommissioningStatus.FormationFailure: 8>, Mode=<BDBCommissioningMode.NwkSteering: 2>, RemainingModes=<BDBCommissioningMode.NONE: 0>)
Traceback (most recent call last):
  File "/home/domoticz/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/api.py", line 275, in start_network
    await started_as_coordinator
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/domoticz/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/api.py", line 275, in start_network
    await started_as_coordinator
  File "/usr/local/lib/python3.9/dist-packages/async_timeout/__init__.py", line 129, in __aexit__
    self._do_exit(exc_type)
  File "/usr/local/lib/python3.9/dist-packages/async_timeout/__init__.py", line 212, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/lib/python3.9/runpy.py", line 197, in _run_module_as_main
    return _run_code(code, main_globals, None,
  File "/usr/lib/python3.9/runpy.py", line 87, in _run_code
    exec(code, run_globals)
  File "/home/domoticz/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/tools/energy_scan.py", line 96, in <module>
    asyncio.run(main(sys.argv[1:]))  # pragma: no cover
  File "/usr/lib/python3.9/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/usr/lib/python3.9/asyncio/base_events.py", line 642, in run_until_complete
    return future.result()
  File "/home/domoticz/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/tools/energy_scan.py", line 92, in main
    await perform_energy_scan(args.serial, num_scans=args.num_scans)
  File "/home/domoticz/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/tools/energy_scan.py", line 25, in perform_energy_scan
    await app.start_network(read_only=True)
  File "/home/domoticz/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/zigbee/application.py", line 183, in start_network
    await self._znp.start_network()
  File "/home/domoticz/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/api.py", line 277, in start_network
    raise RuntimeError(
RuntimeError: Network formation refused, RF environment is likely too noisy. Temporarily unscrew the antenna or shield the coordinator with metal until a network is formed.

here is with the legacy api

python3 -m zigpy_znp.tools.energy_scan -v /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0
2022-03-31 17:44:49.339 pi4 __main__ INFO Starting up zigpy-znp
2022-03-31 17:44:49.341 pi4 zigpy_znp.uart DEBUG Connecting to /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 at 115200 baud
2022-03-31 17:44:49.347 pi4 zigpy_znp.uart DEBUG Opened /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 serial port
2022-03-31 17:44:49.348 pi4 zigpy_znp.uart DEBUG Connected to /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 at 115200 baud
2022-03-31 17:44:49.348 pi4 zigpy_znp.api DEBUG Toggling RTS/DTR pins to skip bootloader or reset chip
2022-03-31 17:44:49.349 pi4 zigpy_znp.uart DEBUG Setting serial pin states: DTR=False, RTS=False
2022-03-31 17:44:49.502 pi4 zigpy_znp.uart DEBUG Setting serial pin states: DTR=False, RTS=True
2022-03-31 17:44:49.655 pi4 zigpy_znp.uart DEBUG Setting serial pin states: DTR=False, RTS=False
2022-03-31 17:44:49.809 pi4 zigpy_znp.api DEBUG Sending request: SYS.Ping.Req()
2022-03-31 17:44:49.814 pi4 zigpy_znp.api DEBUG Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2022-03-31 17:44:49.815 pi4 zigpy_znp.api DEBUG Radio is alive: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2022-03-31 17:44:49.815 pi4 zigpy_znp.nvram DEBUG Detecting struct alignment
2022-03-31 17:44:49.816 pi4 zigpy_znp.api DEBUG Sending request: UTIL.AssocFindDevice.Req(Index=0)
2022-03-31 17:44:49.824 pi4 zigpy_znp.api DEBUG Received command: UTIL.AssocFindDevice.Rsp(Device=b'\xFE\xFF\x00\x20\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF\xFF')
2022-03-31 17:44:49.825 pi4 zigpy_znp.nvram DEBUG Detected struct alignment: True
2022-03-31 17:44:49.825 pi4 zigpy_znp.api DEBUG Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.TCLK_TABLE: 4>, SubId=0)
2022-03-31 17:44:49.832 pi4 zigpy_znp.api DEBUG Received command: SYS.NVLength.Rsp(Length=20)
2022-03-31 17:44:49.833 pi4 zigpy_znp.api DEBUG Sending request: SYS.NVRead.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.TCLK_TABLE: 4>, SubId=0, Offset=0, Length=20)
2022-03-31 17:44:49.841 pi4 zigpy_znp.api DEBUG Received command: SYS.NVRead.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xFF\x00\x00\x00')
2022-03-31 17:44:49.842 pi4 zigpy_znp.nvram DEBUG Read NVRAM[NvSysIds.ZSTACK][ExNvIds.TCLK_TABLE][0x0000] = b'\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\xFF\x00\x00\x00'
2022-03-31 17:44:49.842 pi4 zigpy_znp.api DEBUG Detected Z-Stack 3.3
2022-03-31 17:44:49.843 pi4 zigpy_znp.api DEBUG Connected to /dev/serial/by-id/usb-1a86_USB_Serial-if00-port0 at 115200 baud
2022-03-31 17:44:49.843 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.HAS_CONFIGURED_ZSTACK3: 96>)
2022-03-31 17:44:49.854 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2022-03-31 17:44:49.854 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.HAS_CONFIGURED_ZSTACK3: 96>, Offset=0)
2022-03-31 17:44:49.870 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x55')
2022-03-31 17:44:49.870 pi4 zigpy_znp.nvram DEBUG Read NVRAM["LEGACY"][0x0060] = 85
2022-03-31 17:44:49.871 pi4 zigpy_znp.api DEBUG Sending request: SYS.ResetReq.Req(Type=<ResetType.Soft: 1>)
2022-03-31 17:44:49.871 pi4 zigpy_znp.api DEBUG Request has no response, not waiting for one.
2022-03-31 17:44:51.938 pi4 zigpy_znp.api DEBUG Received command: SYS.ResetInd.Callback(Reason=<ResetReason.PowerUp: 0>, TransportRev=2, ProductId=1, MajorRel=2, MinorRel=7, MaintRel=1)
2022-03-31 17:44:51.940 pi4 zigpy_znp.zigbee.application INFO ZNP is already configured, not forming a new network
2022-03-31 17:44:51.941 pi4 zigpy_znp.api DEBUG Sending request: AppConfig.BDBStartCommissioning.Req(Mode=<BDBCommissioningMode.NwkFormation: 4>)
2022-03-31 17:44:54.336 pi4 zigpy_znp.api DEBUG Received command: AppConfig.BDBStartCommissioning.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.337 pi4 zigpy_znp.api DEBUG Received command: ZDO.StateChangeInd.Callback(State=<DeviceState.StartedAsCoordinator: 9>)
2022-03-31 17:44:54.339 pi4 zigpy_znp.api DEBUG Received command: AppConfig.BDBCommissioningNotification.Callback(Status=<BDBCommissioningStatus.NetworkRestored: 13>, Mode=<BDBCommissioningMode.NONE: 0>, RemainingModes=<BDBCommissioningMode.NwkFormation: 4>)
2022-03-31 17:44:54.543 pi4 zigpy_znp.api DEBUG Received command: AppConfig.BDBCommissioningNotification.Callback(Status=<BDBCommissioningStatus.FormationFailure: 8>, Mode=<BDBCommissioningMode.NwkSteering: 2>, RemainingModes=<BDBCommissioningMode.NONE: 0>)
2022-03-31 17:44:54.545 pi4 zigpy_znp.api DEBUG Sending request: SYS.Version.Req()
2022-03-31 17:44:54.553 pi4 zigpy_znp.api DEBUG Received command: SYS.Version.Rsp(TransportRev=2, ProductId=1, MajorRel=2, MinorRel=7, MaintRel=1, CodeRevision=20211207, BootloaderBuildType=<BootloaderBuildType.NON_BOOTLOADER_BUILD: 0>, BootloaderRevision=None)
2022-03-31 17:44:54.555 pi4 zigpy_znp.api DEBUG Sending request: UTIL.LEDControl.Req(LED=255, Mode=<LEDMode.OFF: 0>)
2022-03-31 17:44:54.561 pi4 zigpy_znp.api DEBUG Received command: UTIL.LEDControl.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.563 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NIB: 33>)
2022-03-31 17:44:54.570 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVLength.Rsp(ItemLen=116)
2022-03-31 17:44:54.571 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NIB: 33>, Offset=0)
2022-03-31 17:44:54.590 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x78\x05\x02\x33\x0F\x33\x00\x1E\x00\x00\x00\x01\x05\x01\x8F\x00\x07\x00\x02\x0D\x1E\x00\x00\x00\x11\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x81\xDC\x08\x00\x00\x00\x02\x00\x0F\x0F\x04\x00\x01\x00\x00\x00\x01\x00\x00\x00\x00\x0C\x92\x0E\xBC\xA1\x71\x7B\xF9\x01\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x0F\x05\x00\x01\x64\x0A\x01\x00\x00\x00\x00\x00\x00\x00')
2022-03-31 17:44:54.597 pi4 zigpy_znp.nvram DEBUG Read NVRAM["LEGACY"][0x0021] = NIB(SequenceNum=120, PassiveAckTimeout=5, MaxBroadcastRetries=2, MaxChildren=51, MaxDepth=15, MaxRouters=51, dummyNeighborTable=0, BroadcastDeliveryTime=30, ReportConstantCost=0, RouteDiscRetries=0, dummyRoutingTable=0, SecureAllFrames=1, SecurityLevel=5, SymLink=1, CapabilityFlags=143, TransactionPersistenceTime=7, nwkProtocolVersion=2, RouteDiscoveryTime=13, RouteExpiryTime=30, nwkDevAddress=0x0000, nwkLogicalChannel=17, nwkCoordAddress=0x0000, nwkCoordExtAddress=00:00:00:00:00:00:00:00, nwkPanId=56449, nwkState=<NwkState.NWK_ROUTER: 8>, channelList=<Channels.CHANNEL_17: 131072>, beaconOrder=15, superFrameOrder=15, scanDuration=4, battLifeExt=0, allocatedRouterAddresses=1, allocatedEndDeviceAddresses=1, nodeDepth=0, extendedPANID=f9:7b:71:a1:bc:0e:92:0c, nwkKeyLoaded=<Bool.true: 1>, spare1=NwkKeyDesc(KeySeqNum=0, Key=00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00), spare2=NwkKeyDesc(KeySeqNum=0, Key=00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00), spare3=0, spare4=0, nwkLinkStatusPeriod=15, nwkRouterAgeLimit=5, nwkUseMultiCast=<Bool.false: 0>, nwkIsConcentrator=<Bool.true: 1>, nwkConcentratorDiscoveryTime=100, nwkConcentratorRadius=10, nwkAllFresh=1, nwkManagerAddr=0x0000, nwkTotalTransmissions=0, nwkUpdateId=0)
2022-03-31 17:44:54.599 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.BDBNODEISONANETWORK: 85>)
2022-03-31 17:44:54.607 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2022-03-31 17:44:54.609 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.BDBNODEISONANETWORK: 85>, Offset=0)
2022-03-31 17:44:54.620 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x01')
2022-03-31 17:44:54.621 pi4 zigpy_znp.nvram DEBUG Read NVRAM["LEGACY"][0x0055] = 1
2022-03-31 17:44:54.622 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.NWK_ACTIVE_KEY_INFO: 58>)
2022-03-31 17:44:54.630 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVLength.Rsp(ItemLen=17)
2022-03-31 17:44:54.632 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.NWK_ACTIVE_KEY_INFO: 58>, Offset=0)
2022-03-31 17:44:54.644 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00\x75\x4D\x47\x5D\x99\x5A\x61\xE4\x5B\x2F\x0E\xEE\xB7\x29\xA2\xF1')
2022-03-31 17:44:54.646 pi4 zigpy_znp.nvram DEBUG Read NVRAM["LEGACY"][0x003a] = NwkKeyDesc(KeySeqNum=0, Key=75:4d:47:5d:99:5a:61:e4:5b:2f:0e:ee:b7:29:a2:f1)
2022-03-31 17:44:54.647 pi4 zigpy_znp.api DEBUG Sending request: SYS.NVLength.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.NWK_SEC_MATERIAL_TABLE: 7>, SubId=0)
2022-03-31 17:44:54.654 pi4 zigpy_znp.api DEBUG Received command: SYS.NVLength.Rsp(Length=12)
2022-03-31 17:44:54.655 pi4 zigpy_znp.api DEBUG Sending request: SYS.NVRead.Req(SysId=<NvSysIds.ZSTACK: 1>, ItemId=<ExNvIds.NWK_SEC_MATERIAL_TABLE: 7>, SubId=0, Offset=0, Length=12)
2022-03-31 17:44:54.663 pi4 zigpy_znp.api DEBUG Received command: SYS.NVRead.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x5A\x1B\x00\x00\x0C\x92\x0E\xBC\xA1\x71\x7B\xF9')
2022-03-31 17:44:54.664 pi4 zigpy_znp.nvram DEBUG Read NVRAM[NvSysIds.ZSTACK][ExNvIds.NWK_SEC_MATERIAL_TABLE][0x0000] = NwkSecMaterialDesc(FrameCounter=7002, ExtendedPanID=f9:7b:71:a1:bc:0e:92:0c)
2022-03-31 17:44:54.665 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.TCLK_SEED: 257>)
2022-03-31 17:44:54.673 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVLength.Rsp(ItemLen=16)
2022-03-31 17:44:54.674 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.TCLK_SEED: 257>, Offset=0)
2022-03-31 17:44:54.686 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x50\x84\xB5\x02\xDD\x71\x5C\x51\x00\x62\x2C\x44\xBD\x55\x0F\x38')
2022-03-31 17:44:54.687 pi4 zigpy_znp.nvram DEBUG Read NVRAM["LEGACY"][0x0101] = 50:84:b5:02:dd:71:5c:51:00:62:2c:44:bd:55:0f:38
2022-03-31 17:44:54.688 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.EXTADDR: 1>)
2022-03-31 17:44:54.698 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVLength.Rsp(ItemLen=8)
2022-03-31 17:44:54.699 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.EXTADDR: 1>, Offset=0)
2022-03-31 17:44:54.716 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x93\xAB\x8D\x23\x00\x4B\x12\x00')
2022-03-31 17:44:54.717 pi4 zigpy_znp.nvram DEBUG Read NVRAM["LEGACY"][0x0001] = 00:12:4b:00:23:8d:ab:93
2022-03-31 17:44:54.717 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.LOGICAL_TYPE: 135>)
2022-03-31 17:44:54.725 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2022-03-31 17:44:54.726 pi4 zigpy_znp.api DEBUG Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.LOGICAL_TYPE: 135>, Offset=0)
2022-03-31 17:44:54.737 pi4 zigpy_znp.api DEBUG Received command: SYS.OSALNVReadExt.Rsp(Status=<Status.SUCCESS: 0>, Value=b'\x00')
2022-03-31 17:44:54.738 pi4 zigpy_znp.nvram DEBUG Read NVRAM["LEGACY"][0x0087] = <DeviceLogicalType.Coordinator: 0>
2022-03-31 17:44:54.739 pi4 zigpy_znp.api DEBUG Sending request: AF.Register.Req(Endpoint=1, ProfileId=260, DeviceId=1024, DeviceVersion=0, LatencyReq=<LatencyReq.NoLatencyReqs: 0>, InputClusters=[0, 25], OutputClusters=[1280, 1282])
2022-03-31 17:44:54.746 pi4 zigpy_znp.api DEBUG Received command: AF.Register.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.747 pi4 zigpy_znp.api DEBUG Sending request: AF.Register.Req(Endpoint=2, ProfileId=49246, DeviceId=2080, DeviceVersion=0, LatencyReq=<LatencyReq.NoLatencyReqs: 0>, InputClusters=[0], OutputClusters=[])
2022-03-31 17:44:54.753 pi4 zigpy_znp.api DEBUG Received command: AF.Register.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.754 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=19)
2022-03-31 17:44:54.760 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.761 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=31)
2022-03-31 17:44:54.767 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.768 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32768)
2022-03-31 17:44:54.773 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.774 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32769)
2022-03-31 17:44:54.780 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.781 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32770)
2022-03-31 17:44:54.787 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.788 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32771)
2022-03-31 17:44:54.793 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.794 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32772)
2022-03-31 17:44:54.800 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.801 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32773)
2022-03-31 17:44:54.807 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.808 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32774)
2022-03-31 17:44:54.813 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.814 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32784)
2022-03-31 17:44:54.820 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.821 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32785)
2022-03-31 17:44:54.827 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.828 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32786)
2022-03-31 17:44:54.833 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.834 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32788)
2022-03-31 17:44:54.840 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.841 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32789)
2022-03-31 17:44:54.846 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.848 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32790)
2022-03-31 17:44:54.853 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.854 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32791)
2022-03-31 17:44:54.860 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.861 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32792)
2022-03-31 17:44:54.866 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.867 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32793)
2022-03-31 17:44:54.873 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.874 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32794)
2022-03-31 17:44:54.879 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.880 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32795)
2022-03-31 17:44:54.886 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.887 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32796)
2022-03-31 17:44:54.892 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.893 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32797)
2022-03-31 17:44:54.899 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.900 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32798)
2022-03-31 17:44:54.905 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.906 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32799)
2022-03-31 17:44:54.912 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.913 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32800)
2022-03-31 17:44:54.918 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.919 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32801)
2022-03-31 17:44:54.925 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.926 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32802)
2022-03-31 17:44:54.931 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.932 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32817)
2022-03-31 17:44:54.937 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.938 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32818)
2022-03-31 17:44:54.944 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.945 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32819)
2022-03-31 17:44:54.950 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.951 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32820)
2022-03-31 17:44:54.957 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.958 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32822)
2022-03-31 17:44:54.963 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.964 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MsgCallbackRegister.Req(ClusterId=32824)
2022-03-31 17:44:54.970 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCallbackRegister.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.971 pi4 zigpy.device DEBUG [0x0000] Scheduling initialization
2022-03-31 17:44:54.971 pi4 zigpy.util DEBUG Tries remaining: 3
2022-03-31 17:44:54.972 pi4 zigpy.device INFO [0x0000] Requesting 'Node Descriptor'
2022-03-31 17:44:54.972 pi4 zigpy.util DEBUG Tries remaining: 2
2022-03-31 17:44:54.973 pi4 zigpy.device DEBUG [0x0000] Extending timeout for 0x01 request
2022-03-31 17:44:54.974 pi4 zigpy.application DEBUG Received frame on uninitialized device <ZNPCoordinator model='CC1352/CC2652, Z-Stack 3.30+ (build 20211207)' manuf='Texas Instruments' nwk=0x0000 ieee=00:12:4b:00:23:8d:ab:93 is_initialized=False> from ep 0 to ep 0, cluster ZDOCmd.Node_Desc_req: b'\x01\x00\x00'
2022-03-31 17:44:54.975 pi4 zigpy.zdo DEBUG [0x0000:zdo] ZDO request ZDOCmd.Node_Desc_req: [0x0000]
2022-03-31 17:44:54.975 pi4 zigpy.zdo DEBUG [0x0000:zdo] No handler for ZDO request:ZDOCmd.Node_Desc_req([0x0000])
2022-03-31 17:44:54.976 pi4 zigpy_znp.api DEBUG Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x0000), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=2, TSN=1, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x01\x00\x00')
2022-03-31 17:44:54.985 pi4 zigpy_znp.api DEBUG Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:54.991 pi4 zigpy_znp.api DEBUG Received command: ZDO.NodeDescRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>, NWK=0x0000, NodeDescriptor=NullableNodeDescriptor(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=4151, maximum_buffer_size=80, maximum_incoming_transfer_size=160, server_mask=11265, maximum_outgoing_transfer_size=160, 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-03-31 17:44:54.992 pi4 zigpy_znp.api DEBUG Command was not handled
2022-03-31 17:44:54.994 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCbIncoming.Callback(Src=0x0000, IsBroadcast=<Bool.false: 0>, ClusterId=32770, SecurityUse=0, TSN=1, MacDst=0x0000, Data=b'\x00\x00\x00\x00\x40\x8F\x37\x10\x50\xA0\x00\x01\x2C\xA0\x00\x00')
2022-03-31 17:44:54.996 pi4 zigpy.application DEBUG Received frame on uninitialized device <ZNPCoordinator model='CC1352/CC2652, Z-Stack 3.30+ (build 20211207)' manuf='Texas Instruments' nwk=0x0000 ieee=00:12:4b:00:23:8d:ab:93 is_initialized=False> from ep 0 to ep 0, cluster 32770: b'\x01\x00\x00\x00\x00@\x8f7\x10P\xa0\x00\x01,\xa0\x00\x00'
2022-03-31 17:44:54.998 pi4 zigpy.device 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=4151, maximum_buffer_size=80, maximum_incoming_transfer_size=160, server_mask=11265, maximum_outgoing_transfer_size=160, 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-03-31 17:44:54.999 pi4 zigpy.device INFO [0x0000] Discovering endpoints
2022-03-31 17:44:54.999 pi4 zigpy.util DEBUG Tries remaining: 3
2022-03-31 17:44:55.000 pi4 zigpy.application DEBUG Received frame on uninitialized device <ZNPCoordinator model='CC1352/CC2652, Z-Stack 3.30+ (build 20211207)' manuf='Texas Instruments' nwk=0x0000 ieee=00:12:4b:00:23:8d:ab:93 is_initialized=False> from ep 0 to ep 0, cluster ZDOCmd.Active_EP_req: b'\x02\x00\x00'
2022-03-31 17:44:55.001 pi4 zigpy.zdo DEBUG [0x0000:zdo] ZDO request ZDOCmd.Active_EP_req: [0x0000]
2022-03-31 17:44:55.001 pi4 zigpy.zdo DEBUG [0x0000:zdo] No handler for ZDO request:ZDOCmd.Active_EP_req([0x0000])
2022-03-31 17:44:55.002 pi4 zigpy_znp.api DEBUG Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x0000), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=5, TSN=2, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x02\x00\x00')
2022-03-31 17:44:55.011 pi4 zigpy_znp.api DEBUG Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:55.013 pi4 zigpy_znp.api DEBUG Received command: ZDO.ActiveEpRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>, NWK=0x0000, ActiveEndpoints=[2, 1])
2022-03-31 17:44:55.013 pi4 zigpy_znp.api DEBUG Command was not handled
2022-03-31 17:44:55.015 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCbIncoming.Callback(Src=0x0000, IsBroadcast=<Bool.false: 0>, ClusterId=32773, SecurityUse=0, TSN=2, MacDst=0x0000, Data=b'\x00\x00\x00\x02\x02\x01')
2022-03-31 17:44:55.016 pi4 zigpy.application DEBUG Received frame on uninitialized device <ZNPCoordinator model='CC1352/CC2652, Z-Stack 3.30+ (build 20211207)' manuf='Texas Instruments' nwk=0x0000 ieee=00:12:4b:00:23:8d:ab:93 is_initialized=False> from ep 0 to ep 0, cluster 32773: b'\x02\x00\x00\x00\x02\x02\x01'
2022-03-31 17:44:55.017 pi4 zigpy.device INFO [0x0000] Discovered endpoints: [2, 1]
2022-03-31 17:44:55.017 pi4 zigpy.device INFO [0x0000] Initializing endpoints [<Endpoint id=2 in=[] out=[] status=<Status.NEW: 0>>, <Endpoint id=1 in=[] out=[] status=<Status.NEW: 0>>]
2022-03-31 17:44:55.018 pi4 zigpy.endpoint INFO [0x0000:2] Discovering endpoint information
2022-03-31 17:44:55.018 pi4 zigpy.util DEBUG Tries remaining: 3
2022-03-31 17:44:55.019 pi4 zigpy.application DEBUG Received frame on uninitialized device <ZNPCoordinator model='CC1352/CC2652, Z-Stack 3.30+ (build 20211207)' manuf='Texas Instruments' nwk=0x0000 ieee=00:12:4b:00:23:8d:ab:93 is_initialized=False> from ep 0 to ep 0, cluster ZDOCmd.Simple_Desc_req: b'\x03\x00\x00\x02'
2022-03-31 17:44:55.019 pi4 zigpy.zdo DEBUG [0x0000:zdo] ZDO request ZDOCmd.Simple_Desc_req: [0x0000, 2]
2022-03-31 17:44:55.020 pi4 zigpy.zdo DEBUG [0x0000:zdo] No handler for ZDO request:ZDOCmd.Simple_Desc_req([0x0000, 2])
2022-03-31 17:44:55.021 pi4 zigpy_znp.api DEBUG Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x0000), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=4, TSN=3, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x03\x00\x00\x02')
2022-03-31 17:44:55.030 pi4 zigpy_znp.api DEBUG Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:55.032 pi4 zigpy_znp.api DEBUG Received command: ZDO.SimpleDescRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>, NWK=0x0000, SimpleDescriptor=SizePrefixedSimpleDescriptor(endpoint=2, profile=49246, device_type=2080, device_version=0, input_clusters=[0], output_clusters=[]))
2022-03-31 17:44:55.033 pi4 zigpy_znp.api DEBUG Command was not handled
2022-03-31 17:44:55.034 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCbIncoming.Callback(Src=0x0000, IsBroadcast=<Bool.false: 0>, ClusterId=32772, SecurityUse=0, TSN=3, MacDst=0x0000, Data=b'\x00\x00\x00\x0A\x02\x5E\xC0\x20\x08\x00\x01\x00\x00\x00')
2022-03-31 17:44:55.036 pi4 zigpy.application DEBUG Received frame on uninitialized device <ZNPCoordinator model='CC1352/CC2652, Z-Stack 3.30+ (build 20211207)' manuf='Texas Instruments' nwk=0x0000 ieee=00:12:4b:00:23:8d:ab:93 is_initialized=False> from ep 0 to ep 0, cluster 32772: b'\x03\x00\x00\x00\n\x02^\xc0 \x08\x00\x01\x00\x00\x00'
2022-03-31 17:44:55.038 pi4 zigpy.endpoint INFO [0x0000:2] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=2, profile=49246, device_type=2080, device_version=0, input_clusters=[0], output_clusters=[])
2022-03-31 17:44:55.038 pi4 zigpy.endpoint INFO [0x0000:1] Discovering endpoint information
2022-03-31 17:44:55.038 pi4 zigpy.util DEBUG Tries remaining: 3
2022-03-31 17:44:55.039 pi4 zigpy.application DEBUG Received frame on uninitialized device <ZNPCoordinator model='CC1352/CC2652, Z-Stack 3.30+ (build 20211207)' manuf='Texas Instruments' nwk=0x0000 ieee=00:12:4b:00:23:8d:ab:93 is_initialized=False> from ep 0 to ep 0, cluster ZDOCmd.Simple_Desc_req: b'\x04\x00\x00\x01'
2022-03-31 17:44:55.040 pi4 zigpy.zdo DEBUG [0x0000:zdo] ZDO request ZDOCmd.Simple_Desc_req: [0x0000, 1]
2022-03-31 17:44:55.041 pi4 zigpy.zdo DEBUG [0x0000:zdo] No handler for ZDO request:ZDOCmd.Simple_Desc_req([0x0000, 1])
2022-03-31 17:44:55.041 pi4 zigpy_znp.api DEBUG Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x0000), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=4, TSN=4, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x04\x00\x00\x01')
2022-03-31 17:44:55.051 pi4 zigpy_znp.api DEBUG Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:55.055 pi4 zigpy_znp.api DEBUG Received command: ZDO.SimpleDescRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>, NWK=0x0000, SimpleDescriptor=SizePrefixedSimpleDescriptor(endpoint=1, profile=260, device_type=1024, device_version=0, input_clusters=[0, 25], output_clusters=[1280, 1282]))
2022-03-31 17:44:55.055 pi4 zigpy_znp.api DEBUG Command was not handled
2022-03-31 17:44:55.056 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCbIncoming.Callback(Src=0x0000, IsBroadcast=<Bool.false: 0>, ClusterId=32772, SecurityUse=0, TSN=4, MacDst=0x0000, Data=b'\x00\x00\x00\x10\x01\x04\x01\x00\x04\x00\x02\x00\x00\x19\x00\x02\x00\x05\x02\x05')
2022-03-31 17:44:55.058 pi4 zigpy.application DEBUG Received frame on uninitialized device <ZNPCoordinator model='CC1352/CC2652, Z-Stack 3.30+ (build 20211207)' manuf='Texas Instruments' nwk=0x0000 ieee=00:12:4b:00:23:8d:ab:93 is_initialized=False> from ep 0 to ep 0, cluster 32772: b'\x04\x00\x00\x00\x10\x01\x04\x01\x00\x04\x00\x02\x00\x00\x19\x00\x02\x00\x05\x02\x05'
2022-03-31 17:44:55.059 pi4 zigpy.endpoint INFO [0x0000:1] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=1, profile=260, device_type=1024, device_version=0, input_clusters=[0, 25], output_clusters=[1280, 1282])
2022-03-31 17:44:55.060 pi4 zigpy.device INFO [0x0000] Already have model and manufacturer info
2022-03-31 17:44:55.060 pi4 zigpy.device INFO [0x0000] Discovered basic device information for <ZNPCoordinator model='CC1352/CC2652, Z-Stack 3.30+ (build 20211207)' manuf='Texas Instruments' nwk=0x0000 ieee=00:12:4b:00:23:8d:ab:93 is_initialized=True>
2022-03-31 17:44:55.061 pi4 zigpy.application DEBUG Device is initialized <ZNPCoordinator model='CC1352/CC2652, Z-Stack 3.30+ (build 20211207)' manuf='Texas Instruments' nwk=0x0000 ieee=00:12:4b:00:23:8d:ab:93 is_initialized=True>
2022-03-31 17:44:55.062 pi4 zigpy.quirks.registry DEBUG Checking quirks for Texas Instruments CC1352/CC2652, Z-Stack 3.30+ (build 20211207) (00:12:4b:00:23:8d:ab:93)
2022-03-31 17:44:55.062 pi4 zigpy_znp.zigbee.application INFO Network settings
2022-03-31 17:44:55.063 pi4 zigpy_znp.zigbee.application INFO   Model: CC1352/CC2652, Z-Stack 3.30+ (build 20211207)
2022-03-31 17:44:55.063 pi4 zigpy_znp.zigbee.application INFO   Z-Stack version: 3.3
2022-03-31 17:44:55.063 pi4 zigpy_znp.zigbee.application INFO   Z-Stack build id: 20211207
2022-03-31 17:44:55.063 pi4 zigpy_znp.zigbee.application INFO   Max concurrent requests: 16
2022-03-31 17:44:55.064 pi4 zigpy_znp.zigbee.application INFO   Channel: 17
2022-03-31 17:44:55.064 pi4 zigpy_znp.zigbee.application INFO   PAN ID: 0xDC81
2022-03-31 17:44:55.064 pi4 zigpy_znp.zigbee.application INFO   Extended PAN ID: f9:7b:71:a1:bc:0e:92:0c
2022-03-31 17:44:55.065 pi4 zigpy_znp.zigbee.application INFO   Device IEEE: 00:12:4b:00:23:8d:ab:93
2022-03-31 17:44:55.065 pi4 zigpy_znp.zigbee.application INFO   Device NWK: 0x0000
2022-03-31 17:44:55.065 pi4 zigpy_znp.zigbee.application DEBUG   Network key: 75:4d:47:5d:99:5a:61:e4:5b:2f:0e:ee:b7:29:a2:f1
2022-03-31 17:44:55.065 pi4 zigpy_znp.zigbee.application INFO Permitting joins for 0 seconds
2022-03-31 17:44:55.066 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.NWK: 2>, Dst=0x0000, Duration=0, TCSignificance=1)
2022-03-31 17:44:55.067 pi4 zigpy_znp.zigbee.application DEBUG Starting watchdog loop
2022-03-31 17:44:55.075 pi4 zigpy_znp.api DEBUG Received command: ZDO.MgmtPermitJoinReq.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:55.076 pi4 zigpy_znp.api DEBUG Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:55.077 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCbIncoming.Callback(Src=0x0000, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=0, MacDst=0x0000, Data=b'\x00')
2022-03-31 17:44:55.078 pi4 zigpy_znp.api DEBUG Sending request: ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.Broadcast: 15>, Dst=0xFFFC, Duration=0, TCSignificance=0)
2022-03-31 17:44:55.080 pi4 zigpy.zdo DEBUG [0x0000:zdo] ZDO request ZDOCmd.Mgmt_Permit_Joining_rsp: [<Status.SUCCESS: 0>]
2022-03-31 17:44:55.080 pi4 zigpy.zdo DEBUG [0x0000:zdo] No handler for ZDO request:ZDOCmd.Mgmt_Permit_Joining_rsp([<Status.SUCCESS: 0>])
2022-03-31 17:44:55.088 pi4 zigpy_znp.api DEBUG Received command: ZDO.MgmtPermitJoinReq.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:55.089 pi4 zigpy_znp.api DEBUG Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:55.089 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCbIncoming.Callback(Src=0x0000, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=1, MacDst=0x0000, Data=b'\x00')
2022-03-31 17:44:55.090 pi4 zigpy_znp.api DEBUG Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.Broadcast: 15>, address=0xFFFC), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=54, TSN=5, Options=<TransmitOptions.NONE: 0>, Radius=0, Data=b'\x05\x00\x00')
2022-03-31 17:44:55.092 pi4 zigpy.zdo DEBUG [0x0000:zdo] ZDO request ZDOCmd.Mgmt_Permit_Joining_rsp: [<Status.SUCCESS: 0>]
2022-03-31 17:44:55.092 pi4 zigpy.zdo DEBUG [0x0000:zdo] No handler for ZDO request:ZDOCmd.Mgmt_Permit_Joining_rsp([<Status.SUCCESS: 0>])
2022-03-31 17:44:55.098 pi4 zigpy_znp.api DEBUG Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:55.099 pi4 __main__ INFO Running scan...
2022-03-31 17:44:55.100 pi4 zigpy.zdo DEBUG [0x0000:zdo] ZDO request ZDOCmd.Mgmt_NWK_Update_req: [NwkUpdate(ScanChannels=<Channels.ALL_CHANNELS: 134215680>, ScanDuration=2, ScanCount=1)]
2022-03-31 17:44:55.101 pi4 zigpy_znp.api DEBUG Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x0000), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=56, TSN=6, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x06\x00\xF8\xFF\x07\x02\x01')
2022-03-31 17:44:55.110 pi4 zigpy_znp.api DEBUG Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-03-31 17:44:56.537 pi4 zigpy_znp.api DEBUG Received command: ZDO.MgmtNWKUpdateNotify.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>, ScannedChannels=<Channels.ALL_CHANNELS: 134215680>, TotalTransmissions=0, TransmissionFailures=0, EnergyValues=[69, 40, 54, 3, 109, 0, 3, 0, 0, 29, 134, 160, 153, 123, 91, 94])
2022-03-31 17:44:56.538 pi4 zigpy_znp.api DEBUG Command was not handled
2022-03-31 17:44:56.539 pi4 zigpy_znp.api DEBUG Received command: ZDO.MsgCbIncoming.Callback(Src=0x0000, IsBroadcast=<Bool.false: 0>, ClusterId=32824, SecurityUse=0, TSN=6, MacDst=0x0000, Data=b'\x00\x00\xF8\xFF\x07\x00\x00\x00\x00\x10\x45\x28\x36\x03\x6D\x00\x03\x00\x00\x1D\x86\xA0\x99\x7B\x5B\x5E')
Channel energy (mean of 1 / 5):
------------------------------------------------
 + Lower energy is better
 + Active Zigbee networks on a channel may still cause congestion
 + TX on 26 in North America may be with lower power due to regulations
 + Zigbee channels 15, 20, 25 fall between WiFi channels 1, 6, 11
 + Some Zigbee devices only join networks on channels 15, 20, and 25
------------------------------------------------
 - 11    27.06%  ###########################
 - 12    15.69%  ###############
 - 13    21.18%  #####################
 - 14     1.18%  #
 - 15    42.75%  ##########################################
 - 16     0.00%
 - 17     1.18%  #
 - 18     0.00%
 - 19     0.00%
 - 20    11.37%  ###########
 - 21    52.55%  ####################################################
 - 22    62.75%  ##############################################################
 - 23    60.00%  ############################################################
 - 24    48.24%  ################################################
 - 25    35.69%  ###################################
 - 26*   36.86%  ####################################

2022-03-31 17:44:56.550 pi4 zigpy.zdo DEBUG [0x0000:zdo] ZDO request ZDOCmd.Mgmt_NWK_Update_req: [NwkUpdate(ScanChannels=<Channels.ALL_CHANNELS: 134215680>, ScanDuration=2, ScanCount=1)]
2022-03-31 17:44:56.552 pi4 zigpy_znp.api DEBUG Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x0000), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=56, TSN=7, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x07\x00\xF8\xFF\x07\x02\x01')

The only difference that I can find is that the old API is sending a Reset before it forms a network. Try this latest change and see if it fixes the problem for you, I still cannot replicate the problem on my end.

The only difference that I can find is that the old API is sending a Reset before it forms a network. Try this latest change and see if it fixes the problem for you, I still cannot replicate the problem on my end.

will monitor during the day, but it does fix my issue

@puddly, looks like there is an issue in the latest commit

async def _write_stack_settings(self, *, reset_if_changed: bool) -> bool:

while

await self._write_stack_settings()

I updated the _write_stack_settings(self) -> bool: in my environment and then it works perfectly

Oops. I've added a MyPy pre-commit hook to ensure this doesn't happen again.

Looks something new happen

Apr 01 18:16:50 pi4 domoticz[17365]: zigpy-zzh: Call to function 'onStart' failed, exception details:
Apr 01 18:16:50 pi4 domoticz[17365]: zigpy-zzh: Traceback (most recent call last):
Apr 01 18:16:50 pi4 domoticz[17365]: zigpy-zzh:   File "/home/domoticz/domoticz/plugins/Domoticz-Zigbee/plugin.py", line 1577, in onStart
Apr 01 18:16:50 pi4 domoticz[17365]: zigpy-zzh:     _plugin.onStart()
Apr 01 18:16:50 pi4 domoticz[17365]: zigpy-zzh:   File "/home/domoticz/domoticz/plugins/Domoticz-Zigbee/plugin.py", line 599, in onStart
Apr 01 18:16:50 pi4 domoticz[17365]: zigpy-zzh:     from Classes.ZigpyTransport.Transport import ZigpyTransport
Apr 01 18:16:50 pi4 domoticz[17365]: zigpy-zzh:   File "/home/domoticz/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/Transport.py", line 17, in <module>
Apr 01 18:16:50 pi4 domoticz[17365]: zigpy-zzh:     from Classes.ZigpyTransport.zigpyThread import (start_zigpy_thread,
Apr 01 18:16:50 pi4 domoticz[17365]: zigpy-zzh:   File "/home/domoticz/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 32, in <module>
Apr 01 18:16:50 pi4 domoticz[17365]: zigpy-zzh:     from Classes.ZigpyTransport.AppZnp import App_znp
Apr 01 18:16:50 pi4 domoticz[17365]: zigpy-zzh:   File "/home/domoticz/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/AppZnp.py", line 28, in <module>
Apr 01 18:16:50 pi4 domoticz[17365]: zigpy-zzh:     import zigpy_znp.zigbee.application
Apr 01 18:16:50 pi4 domoticz[17365]: zigpy-zzh:   File "/home/domoticz/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/zigbee/application.py", line 30, in <module>
Apr 01 18:16:50 pi4 domoticz[17365]: zigpy-zzh:     from zigpy_znp.api import ZNP
Apr 01 18:16:50 pi4 domoticz[17365]: zigpy-zzh:   File "/home/domoticz/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/api.py", line 52, in <module>
Apr 01 18:16:50 pi4 domoticz[17365]: zigpy-zzh:     class ZNP:
Apr 01 18:16:50 pi4 domoticz[17365]: zigpy-zzh:   File "/home/domoticz/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/api.py", line 888, in ZNP
Apr 01 18:16:50 pi4 domoticz[17365]: zigpy-zzh:     self, responses, *, context: bool = Literal[True]
Apr 01 18:16:50 pi4 domoticz[17365]: zigpy-zzh: NameError: name 'Literal' is not defined

Puddly, While testing zigpy (new radio-API and the znp/new-radio-api from your repository), I still get Timeout when requesting a permit to join to a particular router

2022-06-16 14:50:25,748 INFO    : [       MainThread] Requesting router: 96be to enable Permit to join
2022-06-16 14:50:25,749 DEBUG   : [       MainThread] zdp_permit_joining_request 96be f0 00
2022-06-16 14:50:25,750 DEBUG   : [       MainThread] zdp_raw_permit_joining_request 96be f0 00
2022-06-16 14:50:25,761 INFO    :Permitting joins for 240 seconds
2022-06-16 14:50:25,763 DEBUG   :[0x96be] Extending timeout for 0x10 request
2022-06-16 14:50:25,764 DEBUG   : [       ZigpyCom_8] got a command PERMIT-TO-JOIN
2022-06-16 14:50:25,766 DEBUG   :Sending request: ZDO.ExtRouteChk.Req(Dst=0x96BE, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2022-06-16 14:50:25,767 DEBUG   : [       ZigpyCom_8] PERMIT-TO-JOIN: 1253443264226639 duration: 240
2022-06-16 14:50:25,771 DEBUG   : [       ZigpyCom_8] PERMIT-TO-JOIN: duration: 240 target: 00:04:74:00:00:82:a5:4f
2022-06-16 14:50:25,771 DEBUG   : [       ZigpyCom_8] AppZnp - get_device ieee:00:04:74:00:00:82:a5:4f nwk:None
2022-06-16 14:50:25,772 DEBUG   : [       ZigpyCom_8] AppZnp - get_device found device: <Device model=None manuf=None nwk=0x96BE ieee=00:04:74:00:00:82:a5:4f is_initialized=False>
2022-06-16 14:50:25,773 DEBUG   : [       ZigpyCom_8] AppZnp - get_device ieee:None nwk:0x96BE
2022-06-16 14:50:25,774 DEBUG   : [       ZigpyCom_8] AppZnp - get_device found device: <Device model=None manuf=None nwk=0x96BE ieee=00:04:74:00:00:82:a5:4f is_initialized=False>
2022-06-16 14:50:25,775 DEBUG   :Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2022-06-16 14:50:25,779 DEBUG   :Sending request: ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.NWK: 2>, Dst=0x96BE, Duration=240, TCSignificance=0)
2022-06-16 14:50:25,792 DEBUG   :Received command: ZDO.MgmtPermitJoinReq.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-16 14:50:25,837 DEBUG   :Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x96BE, Status=<Status.SUCCESS: 0>)
2022-06-16 14:50:25,839 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0x96BE, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=3, MacDst=0x0000, Data=b'\x00')
2022-06-16 14:50:25,841 DEBUG   :Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x96BE), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=54, TSN=16, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x10\xF0\x00')
2022-06-16 14:50:25,845 DEBUG   : [       ZigpyCom_8] AppZnp - get_device ieee:None nwk:0x96BE
2022-06-16 14:50:25,848 DEBUG   : [       ZigpyCom_8] AppZnp - get_device found device: <Device model=None manuf=None nwk=0x96BE ieee=00:04:74:00:00:82:a5:4f is_initialized=False>
2022-06-16 14:50:25,850 DEBUG   : [       ZigpyCom_8] handle_message 0x8036: 0x96BE Profile: 0000 Cluster: 8036 srcEp: 00 dstEp: 00 message: 0300
2022-06-16 14:50:25,851 INFO    : [ ZigpyForwarder_8] Accepting new Hardware: Enable (On)
2022-06-16 14:50:25,858 DEBUG   :Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-16 14:50:25,903 DEBUG   :Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x96BE, Status=<Status.SUCCESS: 0>)
2022-06-16 14:50:25,904 DEBUG   :Command was not handled
2022-06-16 14:50:25,905 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0x96BE, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=16, MacDst=0x0000, Data=b'\x00')
2022-06-16 14:50:25,908 DEBUG   : [       ZigpyCom_8] AppZnp - get_device ieee:None nwk:0x96BE
2022-06-16 14:50:25,909 DEBUG   : [       ZigpyCom_8] AppZnp - get_device found device: <Device model=None manuf=None nwk=0x96BE ieee=00:04:74:00:00:82:a5:4f is_initialized=False>
2022-06-16 14:50:25,910 DEBUG   : [       ZigpyCom_8] handle_message 0x8036: 0x96BE Profile: 0000 Cluster: 8036 srcEp: 00 dstEp: 00 message: 1000
2022-06-16 14:50:33,431 DEBUG   :Sending request: SYS.Ping.Req()
2022-06-16 14:50:33,437 DEBUG   :Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2022-06-16 14:50:53,894 ERROR   : [       ZigpyCom_8] asyncio.TimeoutError / : request() Not able to execute the zigpy command: PERMIT-TO-JOIN data: {'Duration' : 240,'targetRouter' : 1253443264226639,}

Looks like it works fine:

2022-06-16 14:50:25,779 DEBUG   :Sending request: ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.NWK: 2>, Dst=0x96BE, Duration=240, TCSignificance=0)
2022-06-16 14:50:25,792 DEBUG   :Received command: ZDO.MgmtPermitJoinReq.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-16 14:50:25,837 DEBUG   :Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x96BE, Status=<Status.SUCCESS: 0>)

I also can't replicate the problem with ZHA. How are you permitting joins through a specific router?

yes, it does work, however there is a TimeOut which is rise and it looks like until the timout is issue commands are just queuing

So we don't get return from the self.app.permit(time_s=duration, node=target) call

I believe the Timeout is triggered by the zigpy lib; asyncio.TimeoutError /

can it be related to

2022-06-16 14:50:25,903 DEBUG   :Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x96BE, Status=<Status.SUCCESS: 0>)
2022-06-16 14:50:25,904 DEBUG   :Command was not handled

Don't know much your code, but is this test not the issue, as in that case, I do see that we setup a Callback_rsp as node != self.ieee and time_s != 0

if time_s == 0 or self._zstack_build_id < 20210708 or node == self.ieee:

I've added some extra logging to ZHA and everything is working as intended:

# Before call to `permit(node=...)`
2022-06-16 13:51:29 INFO (MainThread) [homeassistant.components.zha.api] Permitting joins through cc:cc:cc:ff:fe:e6:8e:ca for 60s...

2022-06-16 13:51:29 INFO (MainThread) [zigpy_znp.zigbee.application] Permitting joins for 60 seconds
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy.application] Sending 'mgmt_permit_joining_req' to cc:cc:cc:ff:fe:e6:8e:ca
2022-06-16 13:51:29 INFO (MainThread) [zigpy.zdo] Sending ZDOCmd.Mgmt_Permit_Joining_req (60, 0)
2022-06-16 13:51:29 INFO (MainThread) [zigpy.device] Sending profile, cluster, src_ep, dst_ep, sequence, data = (0, <ZDOCmd.Mgmt_Permit_Joining_req: 0x0036>, 0, 0, 12, b'\x0c<\x00') with seq=<zigpy.util.Request object at 0x10eaf5660>
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.ExtRouteChk.Req(Dst=0x1B94, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy_znp.api] Sending request: ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.NWK: 2>, Dst=0x1B94, Duration=60, TCSignificance=0)
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtPermitJoinReq.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x1B94, Status=<Status.SUCCESS: 0>)
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0x1B94, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=3, MacDst=0x0000, Data=b'\x00')
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x1B94), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=54, TSN=12, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x0C\x3C\x00')
2022-06-16 13:51:29 INFO (MainThread) [zigpy.device] Received hdr args {'_command_id': <ZDOCmd.Mgmt_Permit_Joining_rsp: 0x8036>, '_tsn': 3} [<Status.SUCCESS: 0>] pending {12: <zigpy.util.Request object at 0x10eaf5660>}
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy.zdo] [0x1b94:zdo] ZDO request ZDOCmd.Mgmt_Permit_Joining_rsp: [<Status.SUCCESS: 0>]
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy.zdo] [0x1b94:zdo] No handler for ZDO request:ZDOCmd.Mgmt_Permit_Joining_rsp([<Status.SUCCESS: 0>])
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x1B94, Status=<Status.SUCCESS: 0>)
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy_znp.api] Command was not handled
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.MsgCbIncoming.Callback(Src=0x1B94, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=12, MacDst=0x0000, Data=b'\x00')
2022-06-16 13:51:29 INFO (MainThread) [zigpy.device] Received hdr args {'_command_id': <ZDOCmd.Mgmt_Permit_Joining_rsp: 0x8036>, '_tsn': 12} [<Status.SUCCESS: 0>] pending {12: <zigpy.util.Request object at 0x10eaf5660>}
2022-06-16 13:51:29 INFO (MainThread) [zigpy.device] Resolving request 12 with [<Status.SUCCESS: 0>]
2022-06-16 13:51:29 DEBUG (MainThread) [zigpy.application] Sent 'mgmt_permit_joining_req' to cc:cc:cc:ff:fe:e6:8e:ca: [<Status.SUCCESS: 0>]

# After call to `permit(node=...)`
2022-06-16 13:51:29 INFO (MainThread) [homeassistant.components.zha.api] Successfully permitted joins through cc:cc:cc:ff:fe:e6:8e:ca for 60s

What exact coordinator and firmware are you using?

Yes the Permit to join work and I'm able to pair devices, however the permit call is not returning until it's timeout which them create some side effect in our environment.

The problem occured with new-radio-API or not only on ZNP (not on bellows, not on deconz) with Sonoff and zzh and zzhp

Firmware is 20220219

however the permit call is not returning until it's timeout which them create some side effect in our environment.

This is what I'm unable to replicate. I'm also using a ZZH with the same firmware.

however the permit call is not returning until it's timeout which them create some side effect in our environment.

This is what I'm unable to replicate. I'm also using a ZZH with the same firmware.

I'm glad for you, but how should I debug it ? all is in the zigpy layers as it never returns from the call and that is the zigpy async timeout which is triggered!

Here is the stack trace when the Timeout is issued

Traceback (most recent call last):
  File "/var/lib/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 344, in _permit_to_joint
    await self.app.permit(time_s=duration, node=target_router )
  File "/var/lib/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/zigbee/application.py", line 532, in permit
    await super().permit(time_s=time_s, node=node)
  File "/var/lib/domoticz/plugins/Domoticz-Zigbee/zigpy/application.py", line 427, in permit
    r = await dev.zdo.permit(time_s)
  File "/var/lib/domoticz/plugins/Domoticz-Zigbee/zigpy/device.py", line 327, in request
    return await asyncio.wait_for(req.result, timeout)
  File "/usr/lib/python3.9/asyncio/tasks.py", line 492, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

Here is global permit to join which do not trigger timeout

2022-06-17 10:01:36,367 INFO    : [       MainThread] Request Accepting new Hardware for 240 seconds
2022-06-17 10:01:36,398 INFO    :Permitting joins for 240 seconds
2022-06-17 10:01:36,401 DEBUG   :Sending request: ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.Broadcast: 15>, Dst=0xFFFC, Duration=240, TCSignificance=0)
2022-06-17 10:01:36,402 INFO    : [       ZigpyCom_8] PERMIT-TO-JOIN: {'cmd': 'PERMIT-TO-JOIN', 'datas': {'Duration': 240, 'targetRouter': 'FFFC'}, 'NwkId': None, 'TimeStamp': 1655456496.3652534, 'ACKIsDisable': False, 'Sqn': None}
2022-06-17 10:01:36,405 INFO    : [       ZigpyCom_8] PERMIT-TO-JOIN: duration: 240 for Radio: znp for node: None
2022-06-17 10:01:36,413 DEBUG   :Received command: ZDO.MgmtPermitJoinReq.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-17 10:01:36,415 DEBUG   :Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0x0000, Status=<Status.SUCCESS: 0>)
2022-06-17 10:01:36,416 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0x0000, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=10, MacDst=0x0000, Data=b'\x00')
2022-06-17 10:01:36,418 DEBUG   :Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.Broadcast: 15>, address=0xFFFC), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=54, TSN=167, Options=<TransmitOptions.NONE: 0>, Radius=0, Data=b'\xA7\xF0\x00')
2022-06-17 10:01:36,423 DEBUG   :[0x0000:zdo] ZDO request ZDOCmd.Mgmt_Permit_Joining_rsp: [<Status.SUCCESS: 0>]
2022-06-17 10:01:36,425 DEBUG   :[0x0000:zdo] No handler for ZDO request:ZDOCmd.Mgmt_Permit_Joining_rsp([<Status.SUCCESS: 0>])
2022-06-17 10:01:36,431 DEBUG   :Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-17 10:01:36,433 INFO    : [       ZigpyCom_8] returning from the self.app.permit(time_s=240, node=None )

Now is the Permit to join to a specific router

2022-06-17 10:00:24,004 INFO    :Permitting joins for 240 seconds
2022-06-17 10:00:24,005 INFO    : [       ZigpyCom_8] PERMIT-TO-JOIN: {'cmd': 'PERMIT-TO-JOIN', 'datas': {'Duration': 240, 'targetRouter': 1253443264774027}, 'NwkId': None, 'TimeStamp': 1655456423.933107, 'ACKIsDisable': False, 'Sqn': None}
2022-06-17 10:00:24,006 DEBUG   :[0xbfbe] Extending timeout for 0xa6 request
2022-06-17 10:00:24,007 INFO    : [       ZigpyCom_8] PERMIT-TO-JOIN: duration: 240 for Radio: znp for node: 00:04:74:00:00:8a:ff:8b
2022-06-17 10:00:24,009 DEBUG   :Sending request: ZDO.ExtRouteChk.Req(Dst=0xBFBE, RtStatus=<RouteStatus.ACTIVE: 1>, Options=<RouteOptions.NO_ROUTE_CACHE|MTO_ROUTE: 3>)
2022-06-17 10:00:24,017 DEBUG   :Received command: ZDO.ExtRouteChk.Rsp(Status=<RoutingStatus.SUCCESS: 0>)
2022-06-17 10:00:24,019 DEBUG   :Sending request: ZDO.MgmtPermitJoinReq.Req(AddrMode=<AddrMode.NWK: 2>, Dst=0xBFBE, Duration=240, TCSignificance=0)
2022-06-17 10:00:24,038 DEBUG   :Received command: ZDO.MgmtPermitJoinReq.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-17 10:00:24,084 DEBUG   :Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0xBFBE, Status=<Status.SUCCESS: 0>)
2022-06-17 10:00:24,086 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0xBFBE, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=9, MacDst=0x0000, Data=b'\x00')
2022-06-17 10:00:24,087 DEBUG   :Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0xBFBE), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=54, TSN=166, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\xA6\xF0\x00')
2022-06-17 10:00:24,094 INFO    : [ ZigpyForwarder_8] Accepting new Hardware: Enable (On)
2022-06-17 10:00:24,109 DEBUG   :Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-17 10:00:24,165 DEBUG   :Received command: ZDO.MgmtPermitJoinRsp.Callback(Src=0xBFBE, Status=<Status.SUCCESS: 0>)
2022-06-17 10:00:24,166 DEBUG   :Command was not handled
2022-06-17 10:00:24,167 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0xBFBE, IsBroadcast=<Bool.false: 0>, ClusterId=32822, SecurityUse=0, TSN=166, MacDst=0x0000, Data=b'\x00')
2022-06-17 10:00:43,562 DEBUG   :Sending request: SYS.Ping.Req()
2022-06-17 10:00:43,569 DEBUG   :Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2022-06-17 10:00:52,133 ERROR   : [       ZigpyCom_8] asyncio.TimeoutError / : request() Not able to execute the zigpy command: PERMIT-TO-JOIN data: {'Duration' : 240,'targetRouter' : 1253443264774027,}

Last I see a strange behaviour while sniffing the trafic as I see 2 Permit to join sent !!

Codecov Report

Merging #97 (9dce57e) into dev (19df5c0) will increase coverage by 0.00%. The diff coverage is 98.25%.

@@           Coverage Diff           @@
##              dev      #97   +/-   ##
=======================================
  Coverage   98.59%   98.60%           
=======================================
  Files          44       43    -1     
  Lines        3916     3863   -53     
=======================================
- Hits         3861     3809   -52     
+ Misses         55       54    -1

Impacted Files	Coverage Δ
zigpy_znp/api.py	`97.15% <96.38%> (+0.34%)`	:arrow_up:
zigpy_znp/const.py	`100.00% <100.00%> (ø)`
zigpy_znp/tools/energy_scan.py	`100.00% <100.00%> (ø)`
zigpy_znp/tools/network_backup.py	`97.82% <100.00%> (-0.10%)`	:arrow_down:
zigpy_znp/tools/network_restore.py	`100.00% <100.00%> (ø)`
zigpy_znp/types/commands.py	`100.00% <100.00%> (ø)`
zigpy_znp/types/named.py	`100.00% <100.00%> (ø)`
zigpy_znp/zigbee/application.py	`95.27% <100.00%> (-0.60%)`	:arrow_down:
zigpy_znp/zigbee/device.py	`100.00% <100.00%> (ø)`
zigpy_znp/znp/security.py	`95.18% <100.00%> (ø)`
... and 2 more

Continue to review full report at Codecov.

Legend - Click here to learn more Δ = absolute <relative> (impact), ø = not affected, ? = missing data Powered by Codecov. Last update 19df5c0...9dce57e. Read the comment docs.

zigpy / zigpy-znp

Implement new zigpy radio API #97

Codecov Report