Devices Offline / Trouble Shooting Guide

[MrYutz]

All,

I have been trying to move my ~100 devices to Home Assistant from Hubitat for several months without success. I started with Insteon, moved to Smartthings, then Hubitat, then Hubitat + HA. Now I'd like to get it all on one platform.

The problem is, I am getting device unavailable on random devices in my network. I am an RF engineer and have been trying to figure out what the deal is. All devices are within 20m of a router. The coordinator is within 10m or 10 routers. Most links show very high quality in HA, but in XCTU it is a different picture.

I have tried both conbee II and NORTEK HUSBZB-1 with the latest 115k Firmware. I have a XSTICK2 joined to the network for troubleshooting.

I think that one or more of my Router devices are black-holing traffic. I am getting weird symptoms like the following:

• Device joins network in < 10 seconds. Works for 24 hours perfectly, then goes unavailable.
• Device status in HA dashboard is accurate, and shows on/off events live. If you send a command however, it never gets to endpoint. So HA is receiving status updates, but can't send commands.
• Router Device will show power consumption correctly, but not respond to events.
• Device that worked for 4 weeks goes unavailable. When repaired it works great for another 4 weeks.
• HA reports 255 LQ, XCTU disagrees

90% of my devices are JASCO / GE in wall dimmers and switches. I also have a pile of smart plugs from different manufactures that I can use for additional coverage or Christmas lights depending on the time of year.

I am not sure this is the right place to post this but because bellows does Source Routing, I thought this community might be the place to get involved.

So my first question is: Where would I jump in to docs for creating a route mapping python script? Is there a FAQ on source routing? I am reasonably familiar with Digi's ZigBee docs, but I haven't written anything beyond simple P2P communications.

I'd like to build some doc and tools to help the community better understand their network and allow me to consolidate on one box.

[Adminiuga]

If you receive on/off events from the device, that means the device is on the network and has the current network key. You are not saying what device is it, so it's hard to guess, but usually battery operated devices i.e. end devices, go in sleep and don't reply to request.
In certain cases, an end devices could switch the parent, with the old parent still thinking it has that end device and it may cause one way communication too. The remediation is to send a specially crafted zdo leave message to the old parent.

Zha/zigpy keeps the neighbor table of each router, you could use that information to construct the topology. Or use the built in visualization or install the 3rd party zig-zag component.

Keep debug logging running, and monitor for trustCenterHandler message. That would tell you when a device leaves the network or joins it.
I.e. if the device decided to leave the network for some reason, it won't be accessible.

Alternatively, setup the packet sniffer and troubleshoot individual device: are they getting the packet? Do they acknowledge it? Etc

[Adminiuga]

Ps: troubleshooting why xiaomis leave the network is a lost cause. They need compatibile routers

[MattWestb]

In no software engineer but more radio / telecom engineer but if look on the line (that i can see) you dont have some general bad radio connections.

I can being RF interference that is blocking your mesh but not so likely. If that happens is unicast not working but very likely mullti/broadcast (group commands) i working OK.

But i think you is having on or more devices that is bad behaving in your mesh and making the problems.

One "classical problem" is OSRAM plugs that is having very bad RF and buggy firmware that is not forwarding all packages so end devices is leaving then is not getting acks from the coordinator.

Not the easy way but the best is sniffing traffic with on external sniffer devices so can see all passages also the IEEE 802.15.4 acks between devices in the chain that you cant see in the Zigbee level.

Building on routing map sound great so can see where the traffic is broken or at least around where the problem is shoeing up.

If you is having one extra EM35X or EFR32 device you can using it as one good zigbee sniffier with normal NCP firmware on it.

To finding good docs that describing source routing is not so easy but om very sure you can finding but i dont have see any.
Normal good source is NXP, TI, Nordic and Silabs but can being hard finding them.
Also Zigbee dock but is not public released.

Its also one nasty firmware bug in older Silabs router devices like IKEA and many more that is crashing the firmware and cant routing traffic and is triggered of parent announcement (fixed in EZSP 6.7.7.0 stack) and the router must being re powered for start working (and that is triggering the device broadcasting parent announcement).

[MrYutz]

Most devices are Jasco family in wall.

I see the bad links in Digi's XCTU, but not really in ZigZag. There are some for sure... but .... they all worked great on Hubitat as the controller.

My idea is that I could test all routes by traversing each router. 95% of my devices are wired. I only have 6 battery powered motion on the network. Everything else is a router, or a mains powered end point.

There has to be a good testing methodology to walk the routes and see which devices say they are good, vs the devices that actually are.

I gave up on all xiaomis 30 minutes after pairing them. Ugh.....

I have been looking at the neighbor table from zha. How is it constructed? Smartthings sent a one to many routing packet every sixty seconds. I feel like there is a liar in the network. Maybe a sociopath. It thinks it's telling the truth....but it isn't. If I can find it and kill it, or replace it I'll fix the black hole and then that will fix the routes.

I'll totally get an extra EM35X or EFR32. What do you use for sniffing with those? Different that XCTU?

I have been running XCTU for 6 hours. 6 edge devices. Everything else is a router.

[Adminiuga]

you could enable source routing for EZSP with the following in your configuration.yaml, this would tell EZSP to send many-to-one routing request, it did solve a problem for me with a problematic "corner" of my network.

zha:
  zigpy_config:
    source_routing: True
    ezsp_config:
      CONFIG_SOURCE_ROUTE_TABLE_SIZE: 32

There has to be a good testing methodology to walk the routes and see which devices say they are good, vs the devices that actually are.

ZHA sends Mgmt_LQI_Req to each router to retrieve the neighbours of that router, however some device may report wrong information. Other than that, I'm not aware of any other reliable method to retrieve it, without a low level access to the NWK layer.

For sniffing, you could use CC2531 with ZBoss sniffer firmware, but it requires a flasher. Otherwise, any Silabs (EZSP) based USB device would work, like Elelabs, if you don't have a SWD flasher. If you have one, then there're more options, like EBYTE E180-Z120B module, or some other MG21 based USB dongles from aliexpress

Sonoff Zigbee Bridge flashed with EZSP firmware could be used to, but it runs over WiFi and may not work reliably.

[MattWestb]

Was looking for FCC docks but most is not under the name Jasco but under the Chinese manufacture but its looks like they is using CEL modules with EM357 chips = good.
But it can they is having the famous bug in the zigbee stack that IKEA and other is being hitted of then running large networks (that is nod documented then it was i implanted or if its being in the stack from beginning).

One good instruction for sniffing is: https://www.zigbee2mqtt.io/how_tos/how_to_sniff_zigbee_traffic.html.
If having on TI CC-2531 (I dont recommended it) you need flashing it with sniffing firmware and need the TI flasher or some other flasher that can do the flashing of the TI chip.

If going EM35X / EFR32 you only need have one EZSP coordinator firmware running on the hardware and can sniffing with the program in the link above.

Elelabs USB dongle is working out of the box and can being updated if you need without problem.
Also EM35X USB dongle is working but can needing updating the firmware but its easy done with without hardware tools.

If you is having SWD flasher (original J-Link) you can flashing every EFR32 device also the new IKEA N2 (E2000 / E2001) remote that is having one very good EFR32MG21 module and have all the pads for SWD flashing on the PCB only needing on USB-TTL for com after flashing one EZSP firmware.

[pipiche38]

@MrYutz did you succeed in making your network stable ?
We are also struggling in a large setup (more than 60 devices, with a lot of metering, which means a lot of zigbee trafic)
About 1.38 incoming message/seconde (average).
We are getting a lot of failure in sending command to devices .
We are also getting the Elelabs Shield / bellows crashing and where ONLY a Power cycle is needed to get the system back

    result, msg = await self.app.request( destination, Profile, Cluster, sEp, dEp, sequence, payload, expect_reply, use_ieee )
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/bellows/zigbee/application.py", line 727, in request
    raise ControllerError("ApplicationController is not running")

So any feedback/ experience sharing would be great

[Adminiuga]

[core-ssh config]$ tail -1000 home-assistant.log | grep ezsp_counters
2022-07-24 16:17:06 DEBUG (MainThread) [bellows.zigbee.application] ezsp_counters: [MAC_RX_BROADCAST = 1474839, MAC_TX_BROADCAST = 127058, MAC_RX_UNICAST = 586015, MAC_TX_UNICAST_SUCCESS = 332931, MAC_TX_UNICAST_RETRY = 68541, MAC_TX_UNICAST_FAILED = 15526, APS_DATA_RX_BROADCAST = 18417, APS_DATA_TX_BROADCAST = 18344, APS_DATA_RX_UNICAST = 254991, APS_DATA_TX_UNICAST_SUCCESS = 224496, APS_DATA_TX_UNICAST_RETRY = 0, APS_DATA_TX_UNICAST_FAILED = 10757, ROUTE_DISCOVERY_INITIATED = 13275, NEIGHBOR_ADDED = 17254, NEIGHBOR_REMOVED = 17228, NEIGHBOR_STALE = 18912, JOIN_INDICATION = 0, CHILD_REMOVED = 0, ASH_OVERFLOW_ERROR = 0, ASH_FRAMING_ERROR = 0, ASH_OVERRUN_ERROR = 0, NWK_FRAME_COUNTER_FAILURE = 7, APS_FRAME_COUNTER_FAILURE = 0, UTILITY = 0, APS_LINK_KEY_NOT_AUTHORIZED = 0, NWK_DECRYPTION_FAILURE = 132695, APS_DECRYPTION_FAILURE = 2606, ALLOCATE_PACKET_BUFFER_FAILURE = 0, RELAYED_UNICAST = 0, PHY_TO_MAC_QUEUE_LIMIT_REACHED = 0, PACKET_VALIDATE_LIBRARY_DROPPED_COUNT = 0, TYPE_NWK_RETRY_OVERFLOW = 0, PHY_CCA_FAIL_COUNT = 19776, BROADCAST_TABLE_FULL = 39, PTA_LO_PRI_REQUESTED = 0, PTA_HI_PRI_REQUESTED = 0, PTA_LO_PRI_DENIED = 0, PTA_HI_PRI_DENIED = 0, PTA_LO_PRI_TX_ABORTED = 0, PTA_HI_PRI_TX_ABORTED = 0, ADDRESS_CONFLICT_SENT = 0, EZSP_FREE_BUFFERS = 245]
2022-07-24 16:17:16 DEBUG (MainThread) [bellows.zigbee.application] ezsp_counters: [MAC_RX_BROADCAST = 1475127, MAC_TX_BROADCAST = 127070, MAC_RX_UNICAST = 586097, MAC_TX_UNICAST_SUCCESS = 332976, MAC_TX_UNICAST_RETRY = 68551, MAC_TX_UNICAST_FAILED = 15527, APS_DATA_RX_BROADCAST = 18417, APS_DATA_TX_BROADCAST = 18345, APS_DATA_RX_UNICAST = 255015, APS_DATA_TX_UNICAST_SUCCESS = 224519, APS_DATA_TX_UNICAST_RETRY = 0, APS_DATA_TX_UNICAST_FAILED = 10758, ROUTE_DISCOVERY_INITIATED = 13275, NEIGHBOR_ADDED = 17255, NEIGHBOR_REMOVED = 17229, NEIGHBOR_STALE = 18912, JOIN_INDICATION = 0, CHILD_REMOVED = 0, ASH_OVERFLOW_ERROR = 0, ASH_FRAMING_ERROR = 0, ASH_OVERRUN_ERROR = 0, NWK_FRAME_COUNTER_FAILURE = 7, APS_FRAME_COUNTER_FAILURE = 0, UTILITY = 0, APS_LINK_KEY_NOT_AUTHORIZED = 0, NWK_DECRYPTION_FAILURE = 132716, APS_DECRYPTION_FAILURE = 2606, ALLOCATE_PACKET_BUFFER_FAILURE = 0, RELAYED_UNICAST = 0, PHY_TO_MAC_QUEUE_LIMIT_REACHED = 0, PACKET_VALIDATE_LIBRARY_DROPPED_COUNT = 0, TYPE_NWK_RETRY_OVERFLOW = 0, PHY_CCA_FAIL_COUNT = 19777, BROADCAST_TABLE_FULL = 39, PTA_LO_PRI_REQUESTED = 0, PTA_HI_PRI_REQUESTED = 0, PTA_LO_PRI_DENIED = 0, PTA_HI_PRI_DENIED = 0, PTA_LO_PRI_TX_ABORTED = 0, PTA_HI_PRI_TX_ABORTED = 0, ADDRESS_CONFLICT_SENT = 0, EZSP_FREE_BUFFERS = 252]

In 10s there were 24 RX Unicast, and 23 TX successful unicasts and 1 failed TX unicasts. About 120 devices, at least 3/8 are mains powered.

We are also getting the Elelabs Shield / bellows crashing and where ONLY a Power cycle is needed to get the system

That should not happen. I mean: even if bellows may looses connection to the stick, bellows restart should re-establish the connection. On the other hand, i'm not fond of Pi Shields, too much interference close to the radio and cannot really separate it. Try turning off Wifi and Bluetooth on RPI.

[Adminiuga]

and pay attention to PHY_CCA_FAIL_COUNT counter, that would indicate interference. It is quite possible that single failed Unicast TX was caused my CCA failure.

[pipiche38]

I'll re-enabled debug information to capture those mettrics. But here is what I found on past logs

PluginZigbee_04.log.2022-07-23:2022-07-23 13:21:54,633 DEBUG   :ezsp_counters: [MAC_RX_BROADCAST = 1697, MAC_TX_BROADCAST = 231, MAC_RX_UNICAST = 499, MAC_TX_UNICAST_SUCCESS = 237, MAC_TX_UNICAST_RETRY = 58, MAC_TX_UNICAST_FAILED = 28, APS_DATA_RX_BROADCAST = 27, APS_DATA_TX_BROADCAST = 27, APS_DATA_RX_UNICAST = 224, APS_DATA_TX_UNICAST_SUCCESS = 29, APS_DATA_TX_UNICAST_RETRY = 29, APS_DATA_TX_UNICAST_FAILED = 11, ROUTE_DISCOVERY_INITIATED = 36, NEIGHBOR_ADDED = 35, NEIGHBOR_REMOVED = 19, NEIGHBOR_STALE = 9, JOIN_INDICATION = 0, CHILD_REMOVED = 0, ASH_OVERFLOW_ERROR = 0, ASH_FRAMING_ERROR = 0, ASH_OVERRUN_ERROR = 0, NWK_FRAME_COUNTER_FAILURE = 0, APS_FRAME_COUNTER_FAILURE = 0, UTILITY = 0, APS_LINK_KEY_NOT_AUTHORIZED = 0, NWK_DECRYPTION_FAILURE = 380, APS_DECRYPTION_FAILURE = 2, ALLOCATE_PACKET_BUFFER_FAILURE = 0, RELAYED_UNICAST = 1, PHY_TO_MAC_QUEUE_LIMIT_REACHED = 0, PACKET_VALIDATE_LIBRARY_DROPPED_COUNT = 0, TYPE_NWK_RETRY_OVERFLOW = 0, PHY_CCA_FAIL_COUNT = 37, BROADCAST_TABLE_FULL = 0, PTA_LO_PRI_REQUESTED = 0, PTA_HI_PRI_REQUESTED = 0, PTA_LO_PRI_DENIED = 0, PTA_HI_PRI_DENIED = 0, PTA_LO_PRI_TX_ABORTED = 0, PTA_HI_PRI_TX_ABORTED = 0, ADDRESS_CONFLICT_SENT = 0, EZSP_FREE_BUFFERS = 247]
PluginZigbee_04.log.2022-07-23:2022-07-23 13:22:04,672 DEBUG   :ezsp_counters: [MAC_RX_BROADCAST = 1757, MAC_TX_BROADCAST = 236, MAC_RX_UNICAST = 519, MAC_TX_UNICAST_SUCCESS = 239, MAC_TX_UNICAST_RETRY = 58, MAC_TX_UNICAST_FAILED = 28, APS_DATA_RX_BROADCAST = 27, APS_DATA_TX_BROADCAST = 27, APS_DATA_RX_UNICAST = 235, APS_DATA_TX_UNICAST_SUCCESS = 29, APS_DATA_TX_UNICAST_RETRY = 29, APS_DATA_TX_UNICAST_FAILED = 11, ROUTE_DISCOVERY_INITIATED = 37, NEIGHBOR_ADDED = 36, NEIGHBOR_REMOVED = 20, NEIGHBOR_STALE = 10, JOIN_INDICATION = 0, CHILD_REMOVED = 0, ASH_OVERFLOW_ERROR = 0, ASH_FRAMING_ERROR = 0, ASH_OVERRUN_ERROR = 0, NWK_FRAME_COUNTER_FAILURE = 0, APS_FRAME_COUNTER_FAILURE = 0, UTILITY = 0, APS_LINK_KEY_NOT_AUTHORIZED = 0, NWK_DECRYPTION_FAILURE = 396, APS_DECRYPTION_FAILURE = 2, ALLOCATE_PACKET_BUFFER_FAILURE = 0, RELAYED_UNICAST = 1, PHY_TO_MAC_QUEUE_LIMIT_REACHED = 0, PACKET_VALIDATE_LIBRARY_DROPPED_COUNT = 0, TYPE_NWK_RETRY_OVERFLOW = 0, PHY_CCA_FAIL_COUNT = 37, BROADCAST_TABLE_FULL = 0, PTA_LO_PRI_REQUESTED = 0, PTA_HI_PRI_REQUESTED = 0, PTA_LO_PRI_DENIED = 0, PTA_HI_PRI_DENIED = 0, PTA_LO_PRI_TX_ABORTED = 0, PTA_HI_PRI_TX_ABORTED = 0, ADDRESS_CONFLICT_SENT = 0, EZSP_FREE_BUFFERS = 247]

[Adminiuga]

Keep in mind, the counters are reset about every 1800s (

bellows/bellows/zigbee/application.py

Line 930 in 7dc68b0

read_counter = (

) , but the total counters should be available to application via the state object state.counters['ezsp_counters']
check the counters values just before it resets, cause 10s could be too short.

[pipiche38]

Is there a way to get some documentations on all those counters ?

For instance , PHY_CCA_FAIL_COUNT what should be a reasonable value ? In your example I see PHY_CCA_FAIL_COUNT = 19777 so I wouldn't be to worry about a large number , should I compare it to the Number of Tx sent ?

[pipiche38]

here after is an exemple of crash. Should I do to fix "ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT" ?
And then it looks like everything is stuck, no more logs until we restart

2022-07-25 11:00:51,947 DEBUG   :Free buffers status EzspStatus.SUCCESS, value: 249
2022-07-25 11:00:51,948 DEBUG   :ezsp_counters: [MAC_RX_BROADCAST = 3934, MAC_TX_BROADCAST = 376, MAC_RX_UNICAST = 4365, MAC_TX_UNICAST_SUCCESS = 1867, MAC_TX_UNICAST_RETRY = 347, MAC_TX_UNICAST_FAILED = 130, APS_DATA_RX_BROADCAST = 25, APS_DATA_TX_BROADCAST = 19, APS_DATA_RX_UNICAST = 2568, APS_DATA_TX_UNICAST_SUCCESS = 235, APS_DATA_TX_UNICAST_RETRY = 79, APS_DATA_TX_UNICAST_FAILED = 34, ROUTE_DISCOVERY_INITIATED = 45, NEIGHBOR_ADDED = 199, NEIGHBOR_REMOVED = 183, NEIGHBOR_STALE = 129, JOIN_INDICATION = 0, CHILD_REMOVED = 0, ASH_OVERFLOW_ERROR = 0, ASH_FRAMING_ERROR = 0, ASH_OVERRUN_ERROR = 0, NWK_FRAME_COUNTER_FAILURE = 1, APS_FRAME_COUNTER_FAILURE = 0, UTILITY = 0, APS_LINK_KEY_NOT_AUTHORIZED = 0, NWK_DECRYPTION_FAILURE = 487, APS_DECRYPTION_FAILURE = 0, ALLOCATE_PACKET_BUFFER_FAILURE = 0, RELAYED_UNICAST = 0, PHY_TO_MAC_QUEUE_LIMIT_REACHED = 0, PACKET_VALIDATE_LIBRARY_DROPPED_COUNT = 0, TYPE_NWK_RETRY_OVERFLOW = 0, PHY_CCA_FAIL_COUNT = 129, BROADCAST_TABLE_FULL = 0, PTA_LO_PRI_REQUESTED = 0, PTA_HI_PRI_REQUESTED = 0, PTA_LO_PRI_DENIED = 0, PTA_HI_PRI_DENIED = 0, PTA_LO_PRI_TX_ABORTED = 0, PTA_HI_PRI_TX_ABORTED = 0, ADDRESS_CONFLICT_SENT = 0, EZSP_FREE_BUFFERS = 249]
2022-07-25 11:00:52,465 DEBUG   :Data frame: b'16a6b1a9112a15b658924a24ab5592499c3f5713a3ba9874face6e83fc7e2fa7e3eafb7e'
2022-07-25 11:00:52,466 DEBUG   :Sending: b'82503a7e'
2022-07-25 11:00:52,468 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'00040106000101000000007170b84e74ffff07080d0a0000100008'
2022-07-25 11:00:52,470 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=6, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_NONE: 0>, groupId=0, sequence=113), 112, -72, 0x744e, 255, 255, b'\x08\r\n\x00\x00\x10\x00']
2022-07-25 11:00:53,445 DEBUG   :Data frame: b'26a6b1a9112a15b658954824ab1593499c2cd858c97a9874fade2383b97e0fa2efaf297e'
2022-07-25 11:00:53,446 DEBUG   :Sending: b'83401b7e'
2022-07-25 11:00:53,448 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'000401010201014001000062fff324b4ffff0718400a4500300504'
2022-07-25 11:00:53,452 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=98), 255, -13, 0xb424, 255, 255, b'\x18@\nE\x000\x05']
2022-07-25 11:00:53,463 DEBUG   :Data frame: b'36a6b1a9112a15b658954824ab1593499c2dd858c97a9874f4da5f98bd743f5afbccdaa73a7e'
2022-07-25 11:00:53,464 DEBUG   :Sending: b'8430fc7e'
2022-07-25 11:00:53,466 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'000401010201014001000063fff324b4ffff091c3c11410a00fd100104'
2022-07-25 11:00:53,472 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=99), 255, -13, 0xb424, 255, 255, b'\x1c<\x11A\n\x00\xfd\x10\x01']
2022-07-25 11:00:54,330 DEBUG   :Data frame: b'46a6b1a90d2a35e8ed889bdb5579f875048c273b787e'
2022-07-25 11:01:01,408 DEBUG   :Sending: b'8520dd7e'
2022-07-25 11:01:01,411 DEBUG   :Data frame: b'56a6b1a90d2a35e8ed889bdb5579f875048c270b257e'
2022-07-25 11:01:01,412 DEBUG   :Application frame 89 (incomingRouteRecordHandler) received: b'205ab41cd1feff2c6a3c98c200'
2022-07-25 11:01:01,413 DEBUG   :Sending: b'8610be7e'
2022-07-25 11:01:01,414 DEBUG   :Received incomingRouteRecordHandler frame with [0x5a20, 3c:6a:2c:ff:fe:d1:1c:b4, 152, -62, []]
2022-07-25 11:01:01,416 DEBUG   :Data frame: b'66a6b1a9112a15b658954824ab1593499c8abf69cd949874fade3583b97e0fa2e957c77e'
2022-07-25 11:01:01,417 DEBUG   :Processing route record request: (0x5a20, 3c:6a:2c:ff:fe:d1:1c:b4, 152, -62, [])
2022-07-25 11:01:01,418 DEBUG   :Sending: b'87009f7e'
2022-07-25 11:01:01,420 DEBUG   :Application frame 89 (incomingRouteRecordHandler) received: b'205ab41cd1feff2c6a3c98c200'
2022-07-25 11:01:01,421 DEBUG   :Data frame: b'76a6b1a9112a15b658954824ab1593499c8bbf69cd949874f4da5f98ab743f5afbccdc6cfc7e'
2022-07-25 11:01:01,422 DEBUG   :Received incomingRouteRecordHandler frame with [0x5a20, 3c:6a:2c:ff:fe:d1:1c:b4, 152, -62, []]
2022-07-25 11:01:01,423 DEBUG   :Sending: b'8070787e'
2022-07-25 11:01:01,424 DEBUG   :Processing route record request: (0x5a20, 3c:6a:2c:ff:fe:d1:1c:b4, 152, -62, [])
2022-07-25 11:01:01,426 DEBUG   :Data frame: b'4ea6b1a90d2a35e8ed889bdb5579f875048c27ab467e'
2022-07-25 11:01:01,428 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'0004010102010140010000c498c2205affff0718560a4500300502'
2022-07-25 11:01:01,429 DEBUG   :Sending: b'8520dd7e'
2022-07-25 11:01:01,434 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=196), 152, -62, 0x5a20, 255, 255, b'\x18V\nE\x000\x05']
2022-07-25 11:01:01,435 DEBUG   :Data frame: b'5ea6b1a90d2a35e8ed889bdb5579f875048c279b1b7e'
2022-07-25 11:01:01,445 DEBUG   :Sending: b'8610be7e'
2022-07-25 11:01:01,441 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'0004010102010140010000c598c2205affff091c3c11570a00fd100102'
2022-07-25 11:01:01,457 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=197), 152, -62, 0x5a20, 255, 255, b'\x1c<\x11W\n\x00\xfd\x10\x01']
2022-07-25 11:01:01,448 DEBUG   :Data frame: b'6ea6b1a9112a15b658954824ab1593499c8abf69cd949874fade3583b97e0fa2e979a37e'
2022-07-25 11:01:01,464 DEBUG   :Application frame 89 (incomingRouteRecordHandler) received: b'205ab41cd1feff2c6a3c98c200'
2022-07-25 11:01:01,464 DEBUG   :Sending: b'87009f7e'
2022-07-25 11:01:01,465 DEBUG   :Received incomingRouteRecordHandler frame with [0x5a20, 3c:6a:2c:ff:fe:d1:1c:b4, 152, -62, []]
2022-07-25 11:01:01,469 DEBUG   :Processing route record request: (0x5a20, 3c:6a:2c:ff:fe:d1:1c:b4, 152, -62, [])
2022-07-25 11:01:01,468 DEBUG   :Data frame: b'7ea6b1a9112a15b658954824ab1593499c8bbf69cd949874f4da5f98ab743f5afbccdc65377e'
2022-07-25 11:01:01,475 DEBUG   :Application frame 89 (incomingRouteRecordHandler) received: b'205ab41cd1feff2c6a3c98c200'
2022-07-25 11:01:01,477 DEBUG   :Sending: b'8070787e'
2022-07-25 11:01:01,480 DEBUG   :Received incomingRouteRecordHandler frame with [0x5a20, 3c:6a:2c:ff:fe:d1:1c:b4, 152, -62, []]
2022-07-25 11:01:01,481 DEBUG   :Data frame: b'4ea6b1a90d2a35e8ed889bdb5579f875048c27ab467e'
2022-07-25 11:01:01,484 DEBUG   :Processing route record request: (0x5a20, 3c:6a:2c:ff:fe:d1:1c:b4, 152, -62, [])
2022-07-25 11:01:01,485 DEBUG   :Sending: b'8520dd7e'
2022-07-25 11:01:01,486 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'0004010102010140010000c498c2205affff0718560a4500300502'
2022-07-25 11:01:01,488 DEBUG   :Data frame: b'5ea6b1a90d2a35e8ed889bdb5579f875048c279b1b7e'
2022-07-25 11:01:01,493 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=196), 152, -62, 0x5a20, 255, 255, b'\x18V\nE\x000\x05']
2022-07-25 11:01:01,494 DEBUG   :Sending: b'8610be7e'
2022-07-25 11:01:01,498 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'0004010102010140010000c598c2205affff091c3c11570a00fd100102'
2022-07-25 11:01:01,500 DEBUG   :Data frame: b'6ea6b1a9112a15b658954824ab1593499c8abf69cd949874fade3583b97e0fa2e979a37e'
2022-07-25 11:01:01,505 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=197), 152, -62, 0x5a20, 255, 255, b'\x1c<\x11W\n\x00\xfd\x10\x01']
2022-07-25 11:01:01,507 DEBUG   :Sending: b'87009f7e'
2022-07-25 11:01:01,510 DEBUG   :Application frame 89 (incomingRouteRecordHandler) received: b'205ab41cd1feff2c6a3c98c200'
2022-07-25 11:01:01,512 DEBUG   :Data frame: b'7ea6b1a9112a15b658954824ab1593499c8bbf69cd949874f4da5f98ab743f5afbccdc65377e'
2022-07-25 11:01:01,513 DEBUG   :Received incomingRouteRecordHandler frame with [0x5a20, 3c:6a:2c:ff:fe:d1:1c:b4, 152, -62, []]
2022-07-25 11:01:01,513 DEBUG   :Sending: b'8070787e'
2022-07-25 11:01:01,514 DEBUG   :Processing route record request: (0x5a20, 3c:6a:2c:ff:fe:d1:1c:b4, 152, -62, [])
2022-07-25 11:01:01,519 DEBUG   :Data frame: b'4ea6b1a90d2a35e8ed889bdb5579f875048c27ab467e'
2022-07-25 11:01:01,520 DEBUG   :Application frame 89 (incomingRouteRecordHandler) received: b'205ab41cd1feff2c6a3c98c200'
2022-07-25 11:01:01,521 DEBUG   :Sending: b'8520dd7e'
2022-07-25 11:01:01,522 DEBUG   :Received incomingRouteRecordHandler frame with [0x5a20, 3c:6a:2c:ff:fe:d1:1c:b4, 152, -62, []]
2022-07-25 11:01:01,524 DEBUG   :Data frame: b'5ea6b1a90d2a35e8ed889bdb5579f875048c279b1b7e'
2022-07-25 11:01:01,525 DEBUG   :Processing route record request: (0x5a20, 3c:6a:2c:ff:fe:d1:1c:b4, 152, -62, [])
2022-07-25 11:01:01,525 DEBUG   :Sending: b'8610be7e'
2022-07-25 11:01:01,527 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'0004010102010140010000c498c2205affff0718560a4500300502'
2022-07-25 11:01:01,529 DEBUG   :Data frame: b'6ea6b1a9112a15b658954824ab1593499c8abf69cd949874fade3583b97e0fa2e979a37e'
2022-07-25 11:01:01,530 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=196), 152, -62, 0x5a20, 255, 255, b'\x18V\nE\x000\x05']
2022-07-25 11:01:01,533 DEBUG   :Sending: b'87009f7e'
2022-07-25 11:01:01,535 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'0004010102010140010000c598c2205affff091c3c11570a00fd100102'
2022-07-25 11:01:01,537 DEBUG   :Data frame: b'7ea6b1a9112a15b658954824ab1593499c8bbf69cd949874f4da5f98ab743f5afbccdc65377e'
2022-07-25 11:01:01,538 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=197), 152, -62, 0x5a20, 255, 255, b'\x1c<\x11W\n\x00\xfd\x10\x01']
2022-07-25 11:01:01,540 DEBUG   :Sending: b'8070787e'
2022-07-25 11:01:01,543 DEBUG   :Application frame 89 (incomingRouteRecordHandler) received: b'205ab41cd1feff2c6a3c98c200'
2022-07-25 11:01:01,545 DEBUG   :Received incomingRouteRecordHandler frame with [0x5a20, 3c:6a:2c:ff:fe:d1:1c:b4, 152, -62, []]
2022-07-25 11:01:01,545 DEBUG   :Data frame: b'06a6b1a90d2a26f5bab99bdb5579f87563ab26dee553607e'
2022-07-25 11:01:01,546 DEBUG   :Processing route record request: (0x5a20, 3c:6a:2c:ff:fe:d1:1c:b4, 152, -62, [])
2022-07-25 11:01:01,550 DEBUG   :Sending: b'8160597e'
2022-07-25 11:01:01,552 DEBUG   :Application frame 89 (incomingRouteRecordHandler) received: b'205ab41cd1feff2c6a3c98c200'
2022-07-25 11:01:01,553 DEBUG   :Error code: ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT, Version: 2, frame: b'c20251a8bd7e'
2022-07-25 11:01:01,553 DEBUG   :Received incomingRouteRecordHandler frame with [0x5a20, 3c:6a:2c:ff:fe:d1:1c:b4, 152, -62, []]
2022-07-25 11:01:01,555 DEBUG   :Processing route record request: (0x5a20, 3c:6a:2c:ff:fe:d1:1c:b4, 152, -62, [])
2022-07-25 11:01:01,556 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'0004010102010140010000c498c2205affff0718560a4500300502'
2022-07-25 11:01:01,558 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=196), 152, -62, 0x5a20, 255, 255, b'\x18V\nE\x000\x05']
2022-07-25 11:01:01,563 DEBUG   :Application frame 69 (incomingMessageHandler) received: b'0004010102010140010000c598c2205affff091c3c11570a00fd100102'
2022-07-25 11:01:01,565 DEBUG   :Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=513, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY|APS_OPTION_RETRY: 320>, groupId=0, sequence=197), 152, -62, 0x5a20, 255, 255, b'\x1c<\x11W\n\x00\xfd\x10\x01']
2022-07-25 11:01:01,566 DEBUG   :Error code: ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT, Version: 2, frame: b'c20251a8bd7e'
2022-07-25 11:01:01,572 DEBUG   :Application frame 89 (incomingRouteRecordHandler) received: b'3347e32dd1feff2c6a3cffe5017508'
2022-07-25 11:01:01,574 DEBUG   :Error code: ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT, Version: 2, frame: b'c20251a8bd7e'
2022-07-25 11:01:01,575 DEBUG   :Received incomingRouteRecordHandler frame with [0x4733, 3c:6a:2c:ff:fe:d1:2d:e3, 255, -27, [0x0875]]
2022-07-25 11:01:01,579 DEBUG   :Processing route record request: (0x4733, 3c:6a:2c:ff:fe:d1:2d:e3, 255, -27, [0x0875])
2022-07-25 11:01:01,580 ERROR   :NCP entered failed state. Requesting APP controller restart
2022-07-25 11:01:01,582 DEBUG   :Received _reset_controller_application frame with (<NcpResetCode.ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT: 81>,)
2022-07-25 11:01:01,583 DEBUG   :Resetting ControllerApplication. Cause: 'NcpResetCode.ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT'
2022-07-25 11:01:01,584 DEBUG   :Closed serial connection
2022-07-25 11:01:01,585 ERROR   :NCP entered failed state. Requesting APP controller restart
2022-07-25 11:01:01,587 DEBUG   :Received _reset_controller_application frame with (<NcpResetCode.ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT: 81>,)
2022-07-25 11:01:01,587 DEBUG   :Resetting ControllerApplication. Cause: 'NcpResetCode.ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT'
2022-07-25 11:01:01,588 DEBUG   :Preempting ControllerApplication reset
2022-07-25 11:01:01,588 ERROR   :NCP entered failed state. Requesting APP controller restart
2022-07-25 11:01:01,589 DEBUG   :Received _reset_controller_application frame with (<NcpResetCode.ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT: 81>,)
2022-07-25 11:01:01,592 DEBUG   :Resetting ControllerApplication. Cause: 'NcpResetCode.ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT'
2022-07-25 11:01:01,593 DEBUG   :Preempting ControllerApplication reset
2022-07-25 11:04:16,693 ERROR   :Task exception was never retrieved
future: <Task finished coro=<transport_request() done, defined at /home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py:575> exception=ControllerError('ApplicationController is not running')>
Traceback (most recent call last):
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 595, in transport_request
    result, msg = await self.app.request( destination, Profile, Cluster, sEp, dEp, sequence, payload, expect_reply, use_ieee )
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/bellows/zigbee/application.py", line 727, in request
    raise ControllerError("ApplicationController is not running")
bellows.exception.ControllerError: ApplicationController is not running
2022-07-25 11:04:16,729 ERROR   :Task exception was never retrieved
future: <Task finished coro=<transport_request() done, defined at /home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py:575> exception=ControllerError('ApplicationController is not running')>
Traceback (most recent call last):
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 595, in transport_request
    result, msg = await self.app.request( destination, Profile, Cluster, sEp, dEp, sequence, payload, expect_reply, use_ieee )
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/bellows/zigbee/application.py", line 727, in request
    raise ControllerError("ApplicationController is not running")
bellows.exception.ControllerError: ApplicationController is not running
2022-07-25 11:04:16,730 ERROR   :Task exception was never retrieved
future: <Task finished coro=<transport_request() done, defined at /home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py:575> exception=ControllerError('ApplicationController is not running')>
Traceback (most recent call last):
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/Classes/ZigpyTransport/zigpyThread.py", line 595, in transport_request
    result, msg = await self.app.request( destination, Profile, Cluster, sEp, dEp, sequence, payload, expect_reply, use_ieee )
  File "/home/pi/domoticz/plugins/Domoticz-Zigbee/bellows/zigbee/application.py", line 727, in request
    raise ControllerError("ApplicationController is not running")
bellows.exception.ControllerError: ApplicationController is not running

pi@CasaiaProV4-test:~/domoticz/plugins/Domoticz-Zigbee$ bellows -d /dev/ttyAMA0 -b 115200 info
[60:a4:23:ff:fe:aa:33:ac]
[0x0000]
[<EmberNetworkStatus.JOINED_NETWORK: 2>]
[<EmberStatus.SUCCESS: 0>, <EmberNodeType.COORDINATOR: 1>, EmberNetworkParameters(extendedPanId=79:a7:ee:a4:e1:b3:a6:bf, panId=0xfaa2, radioTxPower=8, radioChannel=15, joinMethod=<EmberJoinMethod.USE_MAC_ASSOCIATION: 0>, nwkManagerId=0x0000, nwkUpdateId=0, channels=<Channels.ALL_CHANNELS: 134215680>)]
[<EmberStatus.SUCCESS: 0>, EmberCurrentSecurityState(bitmask=<EmberCurrentSecurityBitmask.TRUST_CENTER_USES_HASHED_LINK_KEY|64|32|HAVE_TRUST_CENTER_LINK_KEY|GLOBAL_LINK_KEY: 244>, trustCenterLongAddress=60:a4:23:ff:fe:aa:33:ac)]
Manufacturer: Elelabs
Board name: ELR023
EmberZNet version: 6.10.3.0 build 297

[MattWestb]

PHY_CCA_FAIL_COUNT is very likely interference that is blocking the PHY = its the radio channel in Zigbee.
If you have one nice RF sounding and no bad WiFi network its being zero and if its ticking you shall looking for eliminating the interference.

First mobil app for scanning WiFi channels around the coordinator and looking in the wiki for how its Zigbee is mapping channels https://github.com/zigpy/zigpy/wiki/Zigbee---Changing-channel.

Also USB 3 cables and devices away from the coordinator and other bad hardware.