search

zigpy / zigpy-znp

TI CC2531, CC13x2, CC26x2 radio support for Zigpy and ZHA
GNU General Public License v3.0
146 stars 40 forks source link

Connection failure to CC2530 after upgrade to 0.7.0 #132

Open reef-actor opened 2 years ago

reef-actor commented 2 years ago

I have upgraded HomeAssistant from 2021.11.3 to 2022.2 and my ZHA integration is failing. My hardware is CC2530 + CC2591, serial over TCP with tasmota. It has been reliable until the upgrade.

It appears to be blowing up during initialisation shortly after connection. Seems to have similarities to #106 

2022-02-03 20:19:01 DEBUG (MainThread) [zigpy_znp.uart] Connecting to socket://zigbeebridge:8888 at 115200 baud
2022-02-03 20:19:01 DEBUG (MainThread) [zigpy_znp.uart] Opened socket://zigbeebridge:8888 serial port
2022-02-03 20:19:01 DEBUG (MainThread) [zigpy_znp.uart] Connected to socket://zigbeebridge:8888 at 115200 baud
2022-02-03 20:19:01 DEBUG (MainThread) [zigpy_znp.api] Toggling RTS/DTR pins to skip bootloader or reset chip
2022-02-03 20:19:01 DEBUG (MainThread) [zigpy_znp.uart] Setting serial pin states: DTR=False, RTS=False
2022-02-03 20:19:01 DEBUG (MainThread) [zigpy_znp.uart] Setting serial pin states: DTR=False, RTS=True
2022-02-03 20:19:01 DEBUG (MainThread) [zigpy_znp.uart] Setting serial pin states: DTR=False, RTS=False
2022-02-03 20:19:01 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2022-02-03 20:19:02 DEBUG (MainThread) [zigpy_znp.api] Sending CC253x bootloader skip bytes
2022-02-03 20:19:04 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2022-02-03 20:19:05 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2022-02-03 20:19:06 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2022-02-03 20:19:07 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2022-02-03 20:19:09 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2022-02-03 20:19:10 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2022-02-03 20:19:11 DEBUG (MainThread) [zigpy_znp.api] Connection to socket://zigbeebridge:8888 failed, cleaning up
2022-02-03 20:19:11 DEBUG (MainThread) [zigpy_znp.uart] Closing serial port
2022-02-03 20:19:11 ERROR (MainThread) [zigpy.application] Couldn't start application
2022-02-03 20:19:11 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback SerialTransport._call_connection_lost(None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "/home/home/hass_venv/lib/python3.9/site-packages/serial_asyncio/__init__.py", line 417, in _call_connection_lost
    self._serial.close()
  File "/home/home/hass_venv/lib/python3.9/site-packages/serial/urlhandler/protocol_socket.py", line 104, in close
    time.sleep(0.3)
  File "/home/home/hass_venv/lib/python3.9/site-packages/homeassistant/util/async_.py", line 166, in protected_loop_func
    check_loop(func, strict=strict)
  File "/home/home/hass_venv/lib/python3.9/site-packages/homeassistant/util/async_.py", line 129, in check_loop
    raise RuntimeError(
RuntimeError: Detected blocking call inside the event loop. This is causing stability issues. Please report issue
2022-02-03 20:19:11 ERROR (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start ZNP = Texas Instruments Z-Stack ZNP protocol: CC253x, CC26x2, CC13x2 coordinator
Traceback (most recent call last):
  File "/home/home/hass_venv/lib/python3.9/site-packages/zigpy_znp/api.py", line 530, in _skip_bootloader
    result = await responses.get()
  File "/usr/local/lib/python3.9/asyncio/queues.py", line 166, in get
    await getter
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/home/hass_venv/lib/python3.9/site-packages/homeassistant/components/zha/core/gateway.py", line 152, in async_initialize
    self.application_controller = await app_controller_cls.new(
  File "/home/home/hass_venv/lib/python3.9/site-packages/zigpy/application.py", line 69, in new
    await app.startup(auto_form)
  File "/home/home/hass_venv/lib/python3.9/site-packages/zigpy_znp/zigbee/application.py", line 152, in startup
    return await self._startup(
  File "/home/home/hass_venv/lib/python3.9/site-packages/zigpy_znp/zigbee/application.py", line 165, in _startup
    await znp.connect()
  File "/home/home/hass_venv/lib/python3.9/site-packages/zigpy_znp/api.py", line 572, in connect
    self.capabilities = (await self._skip_bootloader()).Capabilities
  File "/home/home/hass_venv/lib/python3.9/site-packages/zigpy_znp/api.py", line 530, in _skip_bootloader
    result = await responses.get()
  File "/home/home/hass_venv/lib/python3.9/site-packages/async_timeout/__init__.py", line 129, in __aexit__
    self._do_exit(exc_type)
  File "/home/home/hass_venv/lib/python3.9/site-packages/async_timeout/__init__.py", line 212, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError
2022-02-03 20:19:11 DEBUG (MainThread) [homeassistant.config_entries] Config entry 'socket://zigbeebridge:8888' for zha integration not ready yet; Retrying in 80 seconds
puddly commented 2 years ago

Try cutting power to your coordinator for a few seconds and plugging it back in.

Does it start working again if you downgrade to 2021.11.3?

Serial over TCP doesn't have a way to toggle RTS and DTR pins so while the linked issue also mentioned a coordinator failing to start up, that problem was different.

reef-actor commented 2 years ago

I downgraded and the behaviour persisted, but a power cycle brought it back. Hopefully the same will work for 2022.2. I don't remember upgrades being anything but seamless before, but I am glad to be back online. Thanks for your help. I will close this when I have confirmed 2022.2 is working too.

reef-actor commented 2 years ago

Back on 2022.2 and unfortunately pulling the power isn't allowing the connection to return. The log does contain something a little different though, is it failing to migrate data?

2022-02-04 09:31:51 DEBUG (MainThread) [zigpy_znp.uart] Connecting to socket://zigbeebridge:8888 at 115200 baud
2022-02-04 09:31:52 DEBUG (MainThread) [zigpy_znp.uart] Opened socket://zigbeebridge:8888 serial port
2022-02-04 09:31:52 DEBUG (MainThread) [zigpy_znp.uart] Connected to socket://zigbeebridge:8888 at 115200 baud
2022-02-04 09:31:52 DEBUG (MainThread) [zigpy_znp.api] Toggling RTS/DTR pins to skip bootloader or reset chip
2022-02-04 09:31:52 DEBUG (MainThread) [zigpy_znp.uart] Setting serial pin states: DTR=False, RTS=False
2022-02-04 09:31:52 DEBUG (MainThread) [zigpy_znp.uart] Setting serial pin states: DTR=False, RTS=True
2022-02-04 09:31:52 DEBUG (MainThread) [zigpy_znp.uart] Setting serial pin states: DTR=False, RTS=False
2022-02-04 09:31:52 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.Ping.Req()
2022-02-04 09:31:52 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP|UTIL|SAPI|ZDO|AF|SYS: 377>)
2022-02-04 09:31:52 DEBUG (MainThread) [zigpy_znp.api] Radio is alive: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP|UTIL|SAPI|ZDO|AF|SYS: 377>)
2022-02-04 09:31:52 DEBUG (MainThread) [zigpy_znp.nvram] Detecting struct alignment
2022-02-04 09:31:52 DEBUG (MainThread) [zigpy_znp.api] Sending request: UTIL.AssocFindDevice.Req(Index=0)
2022-02-04 09:31:52 DEBUG (MainThread) [zigpy_znp.api] Received command: UTIL.AssocFindDevice.Rsp(Device=b'\x9E\x0A\x00\x00\x04\x0B\x00\xE6\x02\x01\xAA\x00\x00\x00\x00\x00\xDF\x00\x46\xE6\x05\xD5\x91\xDB\x00\x0E\xD3\xE6')
2022-02-04 09:31:52 DEBUG (MainThread) [zigpy_znp.nvram] Detected struct alignment: False
2022-02-04 09:31:52 DEBUG (MainThread) [zigpy_znp.api] Detected Z-Stack 1.2
2022-02-04 09:31:52 DEBUG (MainThread) [zigpy_znp.api] Connected to socket://zigbeebridge:8888 at 115200 baud
2022-02-04 09:31:52 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.ZIGPY_ZNP_MIGRATION_ID: 95>)
2022-02-04 09:31:52 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=0)
2022-02-04 09:31:52 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.ADDRMGR: 35>)
2022-02-04 09:31:52 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=209)
2022-02-04 09:31:52 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.ADDRMGR: 35>, Offset=0)
2022-02-04 09:32:07 DEBUG (MainThread) [zigpy_znp.uart] Closing serial port
2022-02-04 09:32:07 ERROR (MainThread) [zigpy.application] Couldn't start application
2022-02-04 09:32:07 ERROR (MainThread) [homeassistant] Error doing job: Exception in callback SerialTransport._call_connection_lost(None)
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/asyncio/events.py", line 80, in _run
    self._context.run(self._callback, *self._args)
  File "/home/home/hass_venv/lib/python3.9/site-packages/serial_asyncio/__init__.py", line 417, in _call_connection_lost
    self._serial.close()
  File "/home/home/hass_venv/lib/python3.9/site-packages/serial/urlhandler/protocol_socket.py", line 104, in close
    time.sleep(0.3)
  File "/home/home/hass_venv/lib/python3.9/site-packages/homeassistant/util/async_.py", line 166, in protected_loop_func
    check_loop(func, strict=strict)
  File "/home/home/hass_venv/lib/python3.9/site-packages/homeassistant/util/async_.py", line 129, in check_loop
    raise RuntimeError(
RuntimeError: Detected blocking call inside the event loop. This is causing stability issues. Please report issue
2022-02-04 09:32:07 ERROR (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start ZNP = Texas Instruments Z-Stack ZNP protocol: CC253x, CC26x2, CC13x2 coordinator
Traceback (most recent call last):
  File "/home/home/hass_venv/lib/python3.9/site-packages/zigpy_znp/api.py", line 847, in request
    response = await response_future
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/home/hass_venv/lib/python3.9/site-packages/homeassistant/components/zha/core/gateway.py", line 152, in async_initialize
    self.application_controller = await app_controller_cls.new(
  File "/home/home/hass_venv/lib/python3.9/site-packages/zigpy/application.py", line 69, in new
    await app.startup(auto_form)
  File "/home/home/hass_venv/lib/python3.9/site-packages/zigpy_znp/zigbee/application.py", line 152, in startup
    return await self._startup(
  File "/home/home/hass_venv/lib/python3.9/site-packages/zigpy_znp/zigbee/application.py", line 172, in _startup
    await self._migrate_nvram()
  File "/home/home/hass_venv/lib/python3.9/site-packages/zigpy_znp/zigbee/application.py", line 953, in _migrate_nvram
    entries = await security.read_addr_manager_entries(self._znp)
  File "/home/home/hass_venv/lib/python3.9/site-packages/zigpy_znp/znp/security.py", line 167, in read_addr_manager_entries
    await znp.nvram.osal_read(
  File "/home/home/hass_venv/lib/python3.9/site-packages/zigpy_znp/nvram.py", line 177, in osal_read
    read_rsp = await self.znp.request(
  File "/home/home/hass_venv/lib/python3.9/site-packages/zigpy_znp/api.py", line 847, in request
    response = await response_future
  File "/home/home/hass_venv/lib/python3.9/site-packages/async_timeout/__init__.py", line 129, in __aexit__
    self._do_exit(exc_type)
  File "/home/home/hass_venv/lib/python3.9/site-packages/async_timeout/__init__.py", line 212, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError
2022-02-04 09:32:07 DEBUG (MainThread) [homeassistant.config_entries] Config entry 'socket://zigbeebridge:8888' for zha integration not ready yet; Retrying in 80 seconds
puddly commented 2 years ago

It connected this time and zigpy-znp is trying reading some entries from NVRAM. The problem is that your coordinator just stops responding:

# Reading the ADDRMGR NVRAM entry
2022-02-04 09:31:52 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVReadExt.Req(Id=<OsalNvIds.ADDRMGR: 35>, Offset=0)

# No response after 15 seconds, connection is assumed dead and closed
2022-02-04 09:32:07 DEBUG (MainThread) [zigpy_znp.uart] Closing serial port

Are you able to connect if you downgrade back to 2021.11.3?

puddly commented 2 years ago

The CC2530 has been notoriously finicky with serial connections when I last tried using it. Can you post your exact hardware and firmware configuration so that I can try replicating this setup myself?

Adminiuga commented 2 years ago

And having a serial over TCP connection does not help.

reef-actor commented 2 years ago

Are you able to connect if you downgrade back to 2021.11.3?

Back on 11.3 it is connected and stable again.

My hardware setup is CC2530 + CC2591 connected to sonoff basic via hardware serial (pins 1&3). Sonoff is running tasmota 9.2.0.3. I will find out what firmware the radio is running. I have <10 connected devices.

reef-actor commented 2 years ago

Firmware is build 20190608, should I go ahead and update to the latest Z-Stack_Home_3.x.0_20211217?

puddly commented 2 years ago

Sure, give it a try. Make sure to make a network backup first and restore after, upgrading will erase your network settings.

puddly commented 2 years ago

Your stick is only compatible with the Z-Stack Home 1.2 firmware, it won't work with anything 3.x.