cc2531 error when booting ha 108 about zigpy-cc

[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