Received an unhandled command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=

[overas]

The problem

Hello. I have migrated from z2m to zha because I like the native integration of zha. But I get these warning and error logs everytime I restart HA and when HA is running. When I used z2m I did not get any error og warning as I have with zha now.

I have tried a lot of things to get rid of the error and warning logs.
The coordinator is a Zigbee Usb dongle (RF-STAR RF-BM-2652P2: https://github.com/egony/cc2652p_cc1352p_RF-STAR/tree/main/firmware/coordinator) attached to a usb2 port with a 3 meter usb extension cable trying to reduce interference.

I have configured my 2.4 Ghz Wi-Fi network to use channel 1 and the coordinator to use channel 25. I have used WiFiAnalyzer on my mobile for checking the channels used on the Wifi. My neightbors use wifi routers configured with channels 11 and 6 and sometime I think I get interference from them. The signals are weak (-82 dBm), but maybe they interfere with my zigbee signals. Sometimes I get in the log "TXStatus.MAC_CHANNEL_ACCESS_FAILURE" in the log, but not so often as "Received an unhandled command:".

I follow the advice from bug report zigpy/zigpy-znp#100, where it might be problems with mains-powered device that are offline. It was two devices which was offline, but after removing them the log was coming back. I have in my Zigbee network Hue and Ikea lamps, Ikea repeters, one Ikea blind, and three Zigstart routers with firmware 20 dbm power (https://github.com/egony/cc2652p_cc1352p_RF-STAR/tree/main/firmware/router) + other main power routers from slash.

More of the log here:
https://gist.github.com/overas/d0e7f2ad7161a103ef13665c9489fc33

Hope somebody can help me.

What version of Home Assistant Core has the issue?

core-2021.11.4

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

zha or zigpy znp

Link to integration documentation on our website

https://www.home-assistant.io/integrations/zha/

Example YAML snippet

configuration.yaml

zha:
  zigpy_config:
    network:
      channel: 25
    znp_config:
      tx_power: 20

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

Anything in the logs that might be useful for us?

2021-11-21 21:07:09 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-11-21 21:07:09 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.Group: 1>, address=0x0005), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=46, Options=<TransmitOptions.NONE: 0>, Radius=0, Data=b'\x01\x2E\x00')
2021-11-21 21:07:09 DEBUG (MainThread) [homeassistant.components.zha.entity] light.kjokkenbord_zha_group_0x0004: turned off: [0, <Status.SUCCESS: 0>]
2021-11-21 21:07:09 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.kjokkenbord_zha_group_0x0004, old_state=<state light.kjokkenbord_zha_group_0x0004=on; min_mireds=153, max_mireds=454, supported_color_modes=['color_temp'], color_mode=color_temp, brightness=243, color_temp=454, hs_color=(29.79, 84.553), rgb_color=(255, 146, 39), xy_color=(0.579, 0.388), off_brightness=None, friendly_name=Kjokkenbord_zha_group_0x0004, supported_features=43 @ 2021-11-21T20:01:44.305319+01:00>, new_state=<state light.kjokkenbord_zha_group_0x0004=off; min_mireds=153, max_mireds=454, supported_color_modes=['color_temp'], off_brightness=None, friendly_name=Kjokkenbord_zha_group_0x0004, supported_features=43 @ 2021-11-21T21:07:09.721485+01:00>>
2021-11-21 21:07:09 DEBUG (MainThread) [homeassistant.components.zha.entity] light.pare1_kjokkenbord_level_light_color_on_off: polling current state
2021-11-21 21:07:09 DEBUG (MainThread) [homeassistant.components.zha.entity] light.pare3_kjokkenbord_level_light_color_on_off: polling current state
2021-11-21 21:07:09 DEBUG (MainThread) [homeassistant.components.zha.entity] light.pare2_kjokkenbord_level_light_color_on_off: polling current state
2021-11-21 21:07:09 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.SUCCESS: 0>, Endpoint=1, TSN=45)
2021-11-21 21:07:09 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-11-21 21:07:09 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x5493), DstEndpoint=11, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=47, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x00\x2F\x00\x00\x00')
2021-11-21 21:07:09 DEBUG (MainThread) [homeassistant.components.zha.entity] light.kjokkendrivere_zha_group_0x0005: turned off: [0, <Status.SUCCESS: 0>]
2021-11-21 21:07:09 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=light.kjokkendrivere_zha_group_0x0005, old_state=<state light.kjokkendrivere_zha_group_0x0005=on; supported_color_modes=['brightness'], color_mode=brightness, brightness=245, off_brightness=None, friendly_name=Kjokkendrivere_zha_group_0x0005, supported_features=41 @ 2021-11-21T20:01:44.753712+01:00>, new_state=<state light.kjokkendrivere_zha_group_0x0005=off; supported_color_modes=['brightness'], off_brightness=None, friendly_name=Kjokkendrivere_zha_group_0x0005, supported_features=41 @ 2021-11-21T21:07:09.738451+01:00>>
2021-11-21 21:07:09 DEBUG (MainThread) [homeassistant.components.zha.entity] light.driver_bakebenk_level_on_off: polling current state
2021-11-21 21:07:09 DEBUG (MainThread) [homeassistant.components.zha.entity] light.driver_kjokkenvask_level_on_off: polling current state
2021-11-21 21:07:09 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.SrcRtgInd.Callback(DstAddr=0x5493, Relays=[])
2021-11-21 21:07:09 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/zigpy_znp/api.py", line 452, in callback_handler
    await callback_rsp
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/zigpy_znp/api.py", line 452, in callback_handler
    await callback_rsp
  File "/usr/local/lib/python3.9/site-packages/async_timeout/__init__.py", line 55, in __aexit__
    self._do_exit(exc_type)
  File "/usr/local/lib/python3.9/site-packages/async_timeout/__init__.py", line 92, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError

Additional information

No response

[probot-home-assistant]

Hey there @dmulcahey, @Adminiuga, mind taking a look at this issue as it has been labeled with an integration (zha) you are listed as a code owner for? Thanks!
_{^{(message by CodeOwnersMention)}}

---

zha documentation
zha source
_{^{(message by IssueLinks)}}

[MattWestb]

What i can remember is the "TXStatus.MAC_CHANNEL_ACCESS_FAILURE" can the coordinator not getting in contact with the device then the radio channel is blocked.
Also time out is normally problem with the mesh network if not having one software bug that is making crazy things.
I have not looking in the log but if you have strong signal from your neighbors WiFi on channel 11 can blocking some device that is near the WiFi source. If you have sleeping end device make sure they is having one good router in the near so they can communicating thru them and not being killed of the WiFi (sleeping end device is normally only using 1/10 of the chip power).
Also do more checks if you can finding one better channel for the Zigbee network but then you must re paring all your devices is you is changing it.

[puddly]

Sometimes I get in the log "TXStatus.MAC_CHANNEL_ACCESS_FAILURE" in the log

MAC_CHANNEL_ACCESS_FAILURE is not good. Your coordinator refuses to transmit because it thinks something else is constantly transmitting (too much noise).

WiFi scanners can pick up WiFi networks but they won't tell you about other sources of interference, such as USB 3.0 ports, Raspberry Pis, 2.4GHz routers, etc. Run the energy scan tool (https://github.com/zigpy/zigpy-znp/blob/dev/TOOLS.md#energy-scan) and confirm that your network is actually on channel 20, the current network settings will be in your home-assistant.log file.

but not so often as "Received an unhandled command:".

The request confirmation timeout is currently 8 seconds. If it takes longer than that for a device to respond, zigpy-znp gives up on expecting a response. However, it seems like a response is eventually sent back, causing that warning to be logged. It should probably be moved to the INFO or DEBUG log level. Or maybe the timeout should be increased.

Can you enable https://www.home-assistant.io/integrations/zha/#debug-logging and post your full log after you get a couple of these? It would be helpful to know how long some of your devices take to respond, so that I can potentially increase the timeout.

[Adminiuga]

However, it seems like a response is eventually sent back, causing that warning to be logged.

Is the device causing these unexpected confirmations a zigbee end device or a router?

[overas]

Thank all of you for your help.

post your full log after you get a couple of these

Here are the home-assistant.log for today
home-assistant.zip

and summary of the logs:

Run the energy scan tool (https://github.com/zigpy/zigpy-znp/blob/dev/TOOLS.md#energy-scan)

Here are a energy-scan of my network after I shutdown my Deco mesh network which, used the channels that were not crowded on the 2.4 MHz channels.
https://gist.github.com/overas/a3019d84231af86ed1f2cb9aaa924e1f

I tried to configure the deco to only use 5 MHz, but the app WiFiAnalyzer says the routers continue to use 2.4 MHz channels. So I have shut it down for the moment. Now I have only two routers running (SSID Telenor0432orm: Zyxel and SSID Telenor0432ormute: Tp link), which are configured to use channel 1 on 2.4 MHZ.

Here is a WiFiAnalyzer picture of the WiFi channels in use at the moment. As you can see I have a router in the neighborhood which use channel 11, but it is a weak signal.

confirm that your network is actually on channel 25

How can I confirm this. Can I trust the energy-scan information?
2021-11-23 20:56:22.515 homeassistant zigpy_znp.zigbee.application INFO Channel: 25

The energy-scan shows that the network is crowded around channel 23 and 13. I have configured zha to use channel 25, but it looks like I should be using channel 20.
I used this website for checking which channels I should be using: http://ostgardh.se/wifi_zigbee/index.html

I get sometimes "MAC_CHANNEL_ACCESS_FAILURE" in the log, so I have interference still. I have tried to find the 2.4 MHz interference from other sources than Wi-Fi, but I have not yet found the interference. Maybe it is my neighbours routers which gives me problems?

Is the device causing these unexpected confirmations a zigbee end device or a router?

I am not very good reading logs, but from the logs it looks like the problems are maybe from Ikea drivers I have in my kitchen. https://www.zigbee2mqtt.io/devices/ICPSHC24-30EU-IL-1.html . Can you confirm this from the homeassistant.log?

[puddly]

Thanks for the debug log, I think I've identified the bug causing the warnings. If you want to try out the fix, follow the installation instructions here but use the following config:

pypi:
  - git+https://github.com/puddly/zigpy-znp.git@puddly/background-req-timeout-bug
  - zigpy==0.41.1  # I think this might be necessary as well

As for your second issue, the channel access failures seem to occur when you send a few multicast requests in a row and then try sending a unicast request.

2021-11-22 23:19:17 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.Group: 1>, address=0x0004), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=167, Options=<TransmitOptions.NONE: 0>, Radius=0, Data=b'\x01\xA7\x01')
2021-11-22 23:19:17 DEBUG (MainThread) [zigpy_znp.api] Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.Group: 1>, address=0x0005), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=6, TSN=168, Options=<TransmitOptions.NONE: 0>, Radius=0, Data=b'\x01\xA8\x01')
2021-11-22 23:19:17 DEBUG (MainThread) [zigpy_znp.api] Received command: AF.DataConfirm.Callback(Status=<Status.MAC_CHANNEL_ACCESS_FAILURE: 225>, Endpoint=1, TSN=168)

Maybe the default multicast radius of 0 (maximum) is too aggressive and the channel is occupied for too long? Alternatively, maybe we should queue up multicast requests to prevent so many from being sent at once?

[overas]

Thanks for the fix.
When I try to use the fix I get errors about Can't install zigpy==0.41.1 https://gist.github.com/overas/77e8c517a843ef784346a1acf8bb9f92. Can you check again which zigpy version I should use?

[puddly]

My mistake. It's just 0.41.0.

[overas]

I have now performed a backup and restore from my old Intel nuc i5 to a raspberry pi 4. After restore I installed the fix.
The warnings and errors ("MAC_CHANNEL_ACCESS_FAILURE" and "Received an unhandled command") seems to be gone.
I think there was something wrong with my intel nuc, because i got these messages when i used it.

So now I'm happy. The case can be closed for me.
I attach the homeassistant.log if you need it. Thanks again for all the help
home-assistant.zip