cc2531 error when booting ha 108

[ministryofsillywalks]

Running a cc2531 on a Nuc with Ubuntu server as base.
I just updated to HA 108 and am getting an error in the logs when restarting homeassistant:

2020-04-09 10:20:53 ERROR (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start TI CC coordinator
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 142, in async_initialize
    res = await self.application_controller.startup(auto_form=True)
  File "/usr/local/lib/python3.7/site-packages/zigpy_cc/zigbee/application.py", line 64, in startup
    self.version = await self._api.version()
  File "/usr/local/lib/python3.7/site-packages/zigpy_cc/api.py", line 206, in version
    version = await self._command(Subsystem.SYS, "version", {})
  File "/usr/local/lib/python3.7/site-packages/zigpy_cc/api.py", line 84, in _command
    return await self.request(subsystem, command, payload)
  File "/usr/local/lib/python3.7/site-packages/zigpy_cc/api.py", line 88, in request
    return await self.request_raw(obj, expectedStatus)
  File "/usr/local/lib/python3.7/site-packages/zigpy_cc/api.py", line 105, in request_raw
    result = await waiter.wait()
  File "/usr/local/lib/python3.7/site-packages/zigpy_cc/api.py", line 35, in wait
    return await asyncio.wait_for(self.future, self.timeout / 1000)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 449, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError
2020-04-09 10:20:53 WARNING (MainThread) [homeassistant.config_entries] Config entry for zha not ready yet. Retrying in 5 seconds.
2020-04-09 10:20:53 INFO (MainThread) [homeassistant.setup] Setting up zha_map
2020-04-09 10:20:53 INFO (MainThread) [homeassistant.setup] Setup of domain zha_map took 0.0 seconds.
2020-04-09 10:20:53 ERROR (MainThread) [homeassistant.setup] Setup failed for zha_map: Integration failed to initialize.

This in turn leads to an issue that zha_map integration cant be setup.
However when then using zha it works fine. New devices can be paired and status of devices is reported.

[sanyatuning]

Can't reproduce
Try unplug and restart

[jorticus]

I am also encountering this, and I have the same setup (CC2531 on NUC running Ubuntu, HA 0.112.2):

...
Jul 12 22:42:02 edoras hass[15789]: 2020-07-12 22:42:02 DEBUG (MainThread) [zigpy_cc.api] --> SREQ SYS osalNvRead tsn: None {'id': <NvItemsIds.PANID: 131>, 'len': 2, 'offset': 0, 'value': b'b\x1a'}
Jul 12 22:42:02 edoras hass[15789]: 2020-07-12 22:42:02 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x03!\x08\x83\x00\x00\xa9'
Jul 12 22:42:02 edoras hass[15789]: 2020-07-12 22:42:02 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.SYS command_id=8 data=b'\x00\x02b\x1a' length=4 fcs=23>
Jul 12 22:42:02 edoras hass[15789]: 2020-07-12 22:42:02 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP SYS osalNvRead tsn: None {'status': 0, 'len': 2, 'value': b'b\x1a'}

Jul 12 22:42:58 edoras hass[15789]: 2020-07-12 22:42:58 INFO (MainThread) [homeassistant.bootstrap] Waiting on integrations to complete setup: zha
Jul 12 22:43:02 edoras hass[15789]: 2020-07-12 22:43:02 WARNING (MainThread) [zigpy_cc.api] Waiter timeout: <Waiter matcher=<Matcher type=CommandType.AREQ subsystem=Subsystem.ZDO command=stateChangeInd payload={'state': 9}> future=<Future pending cb=[_release_waiter(<Future pendi...8049c3528>()]>)() at /usr/lib/python3.7/asyncio/tasks.py:366]> timeout=60000 sequence=None>
Jul 12 22:43:02 edoras hass[15789]: 2020-07-12 22:43:02 ERROR (MainThread) [zigpy.application] Couldn't start application
Jul 12 22:43:02 edoras hass[15789]: 2020-07-12 22:43:02 ERROR (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start TI_CC = Texas Instruments Z-Stack ZNP protocol: CC253x, CC26x2, CC13x2 coordinator

The integration still shows up in the HA UI, but I am unable to pair any devices.

I have tried unplugging, restarting, and even erase/re-flashing the CC2531, to no avail.

[jorticus]

It looks like start_znp is waiting for a 'stateChangeInd' event with state=9, but on first startup all I receive are state=8:

Jul 12 23:01:37 edoras hass[15789]: 2020-07-12 23:01:37 DEBUG (MainThread) [zigpy_cc.zigbee.start_znp] Start ZNP as coordinator...
Jul 12 23:01:37 edoras hass[15789]: 2020-07-12 23:01:37 DEBUG (MainThread) [zigpy_cc.api] --> SREQ ZDO startupFromApp tsn: None {'startdelay': 100}
Jul 12 23:01:37 edoras hass[15789]: 2020-07-12 23:01:37 DEBUG (MainThread) [zigpy_cc.uart] Send: b'\xfe\x02%@d\x00\x03'
Jul 12 23:01:38 edoras hass[15789]: 2020-07-12 23:01:38 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.SRSP subsystem=Subsystem.ZDO command_id=64 data=b'\x01' length=1 fcs=37>
Jul 12 23:01:38 edoras hass[15789]: 2020-07-12 23:01:38 DEBUG (MainThread) [zigpy_cc.api] <-- SRSP ZDO startupFromApp tsn: None {'status': 1}
Jul 12 23:01:38 edoras hass[15789]: 2020-07-12 23:01:38 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=192 data=b'\x08' length=1 fcs=140>
Jul 12 23:01:38 edoras hass[15789]: 2020-07-12 23:01:38 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO stateChangeInd tsn: None {'state': 8}
Jul 12 23:01:38 edoras hass[15789]: 2020-07-12 23:01:38 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: stateChangeInd
Jul 12 23:01:38 edoras hass[15789]: 2020-07-12 23:01:38 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=192 data=b'\x08' length=1 fcs=140>
Jul 12 23:01:38 edoras hass[15789]: 2020-07-12 23:01:38 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO stateChangeInd tsn: None {'state': 8}
Jul 12 23:01:38 edoras hass[15789]: 2020-07-12 23:01:38 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: stateChangeInd
Jul 12 23:01:39 edoras hass[15789]: 2020-07-12 23:01:39 DEBUG (MainThread) [zigpy_cc.uart] Frame received: <UnpiFrame type=CommandType.AREQ subsystem=Subsystem.ZDO command_id=192 data=b'\x08' length=1 fcs=140>
Jul 12 23:01:39 edoras hass[15789]: 2020-07-12 23:01:39 DEBUG (MainThread) [zigpy_cc.api] <-- AREQ ZDO stateChangeInd tsn: None {'state': 8}
Jul 12 23:01:39 edoras hass[15789]: 2020-07-12 23:01:39 DEBUG (MainThread) [zigpy_cc.zigbee.application] message ignored: stateChangeInd

This of course times out since the event you're expecting never arrives.

Then any future attempts never get any 'stateChangeInd' events, which explains the trace I got above.

Any idea what 'stateChangeInd' state=8 is supposed to mean?

Also it's a little confusing that the HomeAssistant UI implies everything is fine even though the initialization failed. I suggest bubbling this error up somehow, or unregistering the integration or something to let the user know the Zigbee integration isn't working properly.

[jorticus]

I think it may be related to this: Koenkk/zigbee2mqtt#2726
After pressing the mentioned button I no longer see the timeout when starting HA.
It would be nice to have some better error handling around this