zigpy couldn't start after update to core-2021.7.0

[Bascht74]

I updated to the lastest beta version of HA and after updating ZHA isn't working any more.
Even after cold restart it doesn't come up...

If I revert back to 2021.6.6 everything is fine again right away. Between that I did not change anything in the configuration.

I know that asyncio.exceptions.TimeoutError might mean that the device is used by something else.
But I don't know what this should be...

2021-07-06 21:34:48 WARNING (MainThread) [zigpy_deconz.zigbee.application] No watchdog response
The No watchdog response warning means there's no communication with the ConBee and also the cause of the asyncio.TmeoutError, as zigpy-deconz queries the ConBee for the node descriptor, but does not get any response.
I don't know what setup you are running, but:
Replug ConBee
Make sure the serial port path you have in the core.config_entries is the correct one and did not change on 2021.7.0b0

1. I Repluged the ConBee -> no change, I did a cold start (Shutdown, Power off, Power on) -> no change
2. Entry in core.config_entries, see below:

As I use Home Assistant OS 6.1 can I use the following procedure to test it and get further logs to see what is wrong?
I am not shure about the line If you are using Supervised Home Assistant (formerly known as the Hassio/Hass.io distro): and "interferance" between native ZHA and the add-on-variant. So I did not tried that to mess anything up...
source: https://github.com/zigpy/zigpy-deconz#testing-new-releases

Thx for any help,

Sebastian

(old entry: home-assistant/core#52394 )

{
                "entry_id": "e9e6eb4ed32747fd85c5f88bd8e5fef5",
                "version": 2,
                "domain": "zha",
                "title": "/dev/serial/by-id/usb-dresden_elektronik_ingenieurtechnik_GmbH_ConBee_II_DE2252350-if00",
                "data": {
                    "device": {
                        "path": "/dev/serial/by-id/usb-dresden_elektronik_ingenieurtechnik_GmbH_ConBee_II_DE2252350-if00"
                    },
                    "radio_type": "deconz"
                },
                "options": {},
                "pref_disable_new_entities": false,
                "pref_disable_polling": false,
                "source": "user",
                "unique_id": null,
                "disabled_by": null
            },

configuration.yaml:

zha:
  zigpy_config:
    network:
      channel: 11             # What channel the radio should try to use.
      channels: [11, 12]  # Channel mask
    ota:
      ikea_provider: true                        # Auto update Trådfri devices
      ledvance_provider: true                    # Auto update LEDVANCE devices
      otau_directory: /config/zigpy_ota  # Utilize .ota files to update everything else 

ttyACM0
/dev/serial/by-id/usb-dresden_elektronik_ingenieurtechnik_GmbH_ConBee_II_DE2252350-if00
Subsystem:
tty
Gerätepfad:
/dev/ttyACM0
ID:
/dev/serial/by-id/usb-dresden_elektronik_ingenieurtechnik_GmbH_ConBee_II_DE2252350-if00
Attribute:
DEVLINKS: >-
  /dev/serial/by-id/usb-dresden_elektronik_ingenieurtechnik_GmbH_ConBee_II_DE2252350-if00
  /dev/serial/by-path/platform-xhci-hcd.4.auto-usb-0:1.1:1.0
DEVNAME: /dev/ttyACM0
DEVPATH: >-
  /devices/platform/soc/ffe09000.usb/ff500000.usb/xhci-hcd.4.auto/usb1/1-1/1-1.1/1-1.1:1.0/tty/ttyACM0
ID_BUS: usb
ID_MODEL: ConBee_II
ID_MODEL_ENC: ConBee\x20II
ID_MODEL_ID: '0030'
ID_PATH: platform-xhci-hcd.4.auto-usb-0:1.1:1.0
ID_PATH_TAG: platform-xhci-hcd_4_auto-usb-0_1_1_1_0
ID_REVISION: '0100'
ID_SERIAL: dresden_elektronik_ingenieurtechnik_GmbH_ConBee_II_DE2252350
ID_SERIAL_SHORT: DE2252350
ID_TYPE: generic
ID_USB_DRIVER: cdc_acm
ID_USB_INTERFACES: ':020201:0a0000:'
ID_USB_INTERFACE_NUM: '00'
ID_VENDOR: dresden_elektronik_ingenieurtechnik_GmbH
ID_VENDOR_ENC: dresden\x20elektronik\x20ingenieurtechnik\x20GmbH
ID_VENDOR_ID: 1cf1
MAJOR: '166'
MINOR: '0'
SUBSYSTEM: tty
TAGS: ':systemd:'
USEC_INITIALIZED: '512107800968'

log:

2021-07-06 21:30:08 ERROR (MainThread) [zigpy.application] Couldn't start application
2021-07-06 21:30:08 ERROR (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start deCONZ = dresden elektronik deCONZ protocol: ConBee I/II, RaspBee I/II coordinator
Traceback (most recent call last):
File "/usr/local/lib/python3.9/asyncio/tasks.py", line 492, in wait_for
fut.result()
asyncio.exceptions.CancelledError
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 152, in async_initialize
self.application_controller = await app_controller_cls.new(
File "/usr/local/lib/python3.9/site-packages/zigpy/application.py", line 74, in new
await app.startup(auto_form)
File "/usr/local/lib/python3.9/site-packages/zigpy_deconz/zigbee/application.py", line 93, in startup
coordinator = await DeconzDevice.new(
File "/usr/local/lib/python3.9/site-packages/zigpy_deconz/zigbee/application.py", line 435, in new
await dev._initialize()
File "/usr/local/lib/python3.9/site-packages/zigpy/util.py", line 110, in retry
r = await func()
File "/usr/local/lib/python3.9/site-packages/zigpy/device.py", line 178, in _initialize
await self.get_node_descriptor()
File "/usr/local/lib/python3.9/site-packages/zigpy/device.py", line 137, in get_node_descriptor
status, _, node_desc = await self.zdo.Node_Desc_req(
File "/usr/local/lib/python3.9/site-packages/zigpy/util.py", line 110, in retry
r = await func()
File "/usr/local/lib/python3.9/site-packages/zigpy/device.py", line 300, in request
result = await asyncio.wait_for(req.result, timeout)
File "/usr/local/lib/python3.9/asyncio/tasks.py", line 494, in wait_for
raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError
2021-07-06 21:30:08 WARNING (MainThread) [homeassistant.config_entries] Config entry '/dev/serial/by-id/usb-dresden_elektronik_ingenieurtechnik_GmbH_ConBee_II_DE2252350-if00' for zha integration not ready yet; Retrying in background
2021-07-06 21:30:36 WARNING (MainThread) [zigpy.appdb] Discarding _save_attribute event
2021-07-06 21:34:01 ERROR (MainThread) [zigpy.application] Couldn't start application
2021-07-06 21:34:01 ERROR (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start deCONZ = dresden elektronik deCONZ protocol: ConBee I/II, RaspBee I/II coordinator
Traceback (most recent call last):
File "/usr/local/lib/python3.9/asyncio/tasks.py", line 492, in wait_for
fut.result()
asyncio.exceptions.CancelledError
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 152, in async_initialize
self.application_controller = await app_controller_cls.new(
File "/usr/local/lib/python3.9/site-packages/zigpy/application.py", line 74, in new
await app.startup(auto_form)
File "/usr/local/lib/python3.9/site-packages/zigpy_deconz/zigbee/application.py", line 93, in startup
coordinator = await DeconzDevice.new(
File "/usr/local/lib/python3.9/site-packages/zigpy_deconz/zigbee/application.py", line 435, in new
await dev._initialize()
File "/usr/local/lib/python3.9/site-packages/zigpy/util.py", line 110, in retry
r = await func()
File "/usr/local/lib/python3.9/site-packages/zigpy/device.py", line 178, in _initialize
await self.get_node_descriptor()
File "/usr/local/lib/python3.9/site-packages/zigpy/device.py", line 137, in get_node_descriptor
status, _, node_desc = await self.zdo.Node_Desc_req(
File "/usr/local/lib/python3.9/site-packages/zigpy/util.py", line 110, in retry
r = await func()
File "/usr/local/lib/python3.9/site-packages/zigpy/device.py", line 300, in request
result = await asyncio.wait_for(req.result, timeout)
File "/usr/local/lib/python3.9/asyncio/tasks.py", line 494, in wait_for
raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError
2021-07-06 21:34:48 WARNING (MainThread) [zigpy_deconz.zigbee.application] No watchdog response
2021-07-06 21:35:09 WARNING (MainThread) [zigpy.appdb] Discarding _save_attribute event

[Adminiuga]

Can you revert back to 2021.6.x enable debug logging https://www.home-assistant.io/integrations/zha/#debug-logging and post the start up log or link to the log here?

[Bascht74]

I used:

logger:
  default: info
  logs:
    homeassistant.core: debug
    homeassistant.components.zha: debug
    bellows.zigbee.application: debug
    bellows.ezsp: debug
    zigpy: debug
    zigpy_cc: 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

log:
https://www.dropbox.com/s/iq7im5ntm4fkr40/home-assistant.zip?dl=0

I found some warnings, but that might be something different:

2021-07-07 22:20:59 WARNING (MainThread) [zigpy.device] [0x0000] Requesting Node Descriptor failed
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/zigpy/device.py", line 102, in get_node_descriptor
    status, _, node_desc = await self.zdo.Node_Desc_req(
  File "/usr/local/lib/python3.8/site-packages/zigpy/util.py", line 110, in retry
    r = await func()
  File "/usr/local/lib/python3.8/site-packages/zigpy/device.py", line 225, in request
    result = await asyncio.wait_for(req.result, timeout)
  File "/usr/local/lib/python3.8/asyncio/tasks.py", line 501, in wait_for
    raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError
2021-07-07 22:20:59 INFO (MainThread) [zigpy.device] [0x0000] Discovering endpoints
...
2021-07-07 22:21:13 WARNING (MainThread) [homeassistant.bootstrap] Waiting on integrations to complete setup: zha
2021-07-07 22:22:25 WARNING (MainThread) [zigpy.device] [0x0000] Failed to discover active endpoints
Traceback (most recent call last):
  File "/usr/local/lib/python3.8/site-packages/zigpy/device.py", line 119, in _initialize
    status, _, endpoints = await self.zdo.Active_EP_req(
  File "/usr/local/lib/python3.8/site-packages/zigpy/util.py", line 110, in retry
    r = await func()
  File "/usr/local/lib/python3.8/site-packages/zigpy/device.py", line 225, in request
    result = await asyncio.wait_for(req.result, timeout)
  File "/usr/local/lib/python3.8/asyncio/tasks.py", line 501, in wait_for
    raise exceptions.TimeoutError()
asyncio.exceptions.TimeoutError

I looked out for something unusual and I found one thing:

            {
                "config_entries": [
                    "e9e6eb4ed32747fd85c5f88bd8e5fef5"
                ],
                "connections": [
                    [
                        "zigbee",
                        "00:21:2e:ff:ff:06:20:d3"
                    ]
                ],
                "identifiers": [
                    [
                        "zha",
                        "00:21:2e:ff:ff:06:20:d3"
                    ]
                ],
                "manufacturer": "unk_manufacturer",
                "model": "unk_model",
                "name": "unk_manufacturer unk_model",
                "sw_version": null,
                "entry_type": null,
                "id": "25b583fc226cc2a2f000c648cf567eac",
                "via_device_id": null,
                "area_id": "194e385ac9ce2704479b065c6a5a5dde",
                "name_by_user": "Zigbee Coordinator",
                "disabled_by": null
            },

            {
                "config_entries": [
                    "e9e6eb4ed32747fd85c5f88bd8e5fef5"
                ],
                "connections": [
                    [
                        "zigbee",
                        "00:21:2e:ff:ff:06:57:d6"
                    ]
                ],
                "identifiers": [
                    [
                        "zha",
                        "00:21:2e:ff:ff:06:57:d6"
                    ]
                ],
                "manufacturer": "ZHA",
                "model": "deCONZ = dresden elektronik deCONZ protocol: ConBee I/II, RaspBee I/II",
                "name": "Zigbee Coordinator",
                "sw_version": null,
                "entry_type": null,
                "id": "9f5c9ad868614f3b916b1895a604fb93",
                "via_device_id": null,
                "area_id": "194e385ac9ce2704479b065c6a5a5dde",
                "name_by_user": null,
                "disabled_by": null
            },

I don't know where the other entry came from. Maybe from zigbee.db?
But I don't know how to access it to search for that.

Seb

[MattWestb]

Your system have 2 coordinator configured and is trying "talking" to the not connected one.

Its better @Adminiuga is helping you deleting / cleaning the records of the not active one but hi is sleeping for the moment so need waiting little (US TZ).

I have getting the same the dong firmware updating and was putting the wrong back in the production system.

[Bascht74]

@MattWestb I downloaded an app to look into the zigbee.db. I found several entries with 00:21:2e:ff:ff:06:20:d3 and I deleted those (made a copy of the original zigbee.db before)...

[Bascht74]

@MattWestb Thanks for that hint.

@Adminiuga That was it! After I deleted the entries with 00:21:2e:ff:ff:06:20:d3 and the entry from core.device_registry and updated to 2021.7.0 everything is OK so far.
Maybe having more than one coordinators should be detected (=log-entry)?
Maybe it can even more be corrected automatically in the database?

Anyway, thx for your hints and I am a little bit proud that I could solve the problem myself.
If you like I can close the issue...

Sebastian

[Adminiuga]

can you try removing the one with "00:21:2e:ff:ff:06:20:d3" IEEE address?
Or if you can get sqlite shell access, do the following on zigbee.db

1. stop HA
2. open sqlite zigbee.db
3. run the following:

DELETE FROM attributes WHERE ieee='00:21:2e:ff:ff:06:20:d3';
DELETE FROM clusters WHERE ieee='00:21:2e:ff:ff:06:20:d3';
DELETE FROM output_clusters WHERE ieee='00:21:2e:ff:ff:06:20:d3';
DELETE FROM endpoints WHERE ieee='00:21:2e:ff:ff:06:20:d3';
DELETE FROM node_descriptors_v4 WHERE ieee='00:21:2e:ff:ff:06:20:d3';
DELETE FROM neighbors_v4 WHERE device_ieee='00:21:2e:ff:ff:06:20:d3';
DELETE FROM devices WHERE ieee='00:21:2e:ff:ff:06:20:d3';

4. start HA

[Adminiuga]

So this issue was cause by the older coordinator being. present in the database. Should be fixed in zigpy==0.35.2 and would be in the next HA patch release 2021.7.2 or .3

Fixed by home-assistant/core#52611

[MattWestb]

Correct fix link: zigpy/zigpy#771 👍

[Bascht74]

can you try removing the one with "00:21:2e:ff:ff:06:20:d3" IEEE address?

Yes, I did and ZHA started again in HA!

So this issue was cause by the older coordinator being.

Yes, seems to. After deleting the old one in the database everything went back to normal so far...