home-assistant / addons

:heavy_plus_sign: Docker add-ons for Home Assistant
https://home-assistant.io/hassio/
Apache License 2.0
1.56k stars 1.51k forks source link

Sky connect not running #3090

Closed weaseel closed 1 year ago

weaseel commented 1 year ago

Describe the issue you are experiencing

My Sky connect stick is not running since I updated to 2023.6 (Silicon Labs Multiprotocol 2.1.0).

At first it couldn't be found. Reboot didn't change anything. After disconnecting and reconnecting it to usb, it was found again and the Silicon Labs Multiprotocol is running (no error in logs).

In Settings -> Devices -> Zigbee Home Automation: the entry is red and saying: 'Failed to set up'. Reload doesn't fix it

What type of installation are you running?

Home Assistant OS

Which operating system are you running on?

Home Assistant Operating System

Which add-on are you reporting an issue with?

Silicon Labs Multiprotocol

What is the version of the add-on?

2.1.0

Steps to reproduce the issue

  1. Plug in sky connect usb stick
  2. Restart home assistant

System Health information

System Information

version core-2023.6.0
installation_type Home Assistant OS
dev false
hassio true
docker true
user root
virtualenv false
python_version 3.11.3
os_name Linux
os_version 6.1.21-v8
arch aarch64
timezone Europe/Berlin
config_dir /config
Home Assistant Community Store GitHub API | ok -- | -- GitHub Content | ok GitHub Web | ok GitHub API Calls Remaining | 4784 Installed Version | 1.32.1 Stage | running Available Repositories | 1287 Downloaded Repositories | 15
Home Assistant Cloud logged_in | false -- | -- can_reach_cert_server | ok can_reach_cloud_auth | ok can_reach_cloud | ok
Home Assistant Supervisor host_os | Home Assistant OS 10.2 -- | -- update_channel | stable supervisor_version | supervisor-2023.06.1 agent_version | 1.5.1 docker_version | 23.0.6 disk_total | 57.8 GB disk_used | 27.8 GB healthy | true supported | true board | rpi4-64 supervisor_api | ok version_api | ok installed_addons | Terminal & SSH (9.7.1), File editor (5.6.0), ESPHome (2023.5.5), FTP (4.7.0), Mosquitto broker (6.2.1), Studio Code Server (5.6.1), Grafana (8.3.0), ioBroker (0.8.0), InfluxDB (4.7.0), Warema Bridge (dev), Silicon Labs Multiprotocol (2.1.0), Baby Buddy (1.16.0)
Dashboards dashboards | 13 -- | -- resources | 2 views | 12 mode | storage
Miele component_version | 0.1.13 -- | -- reach_miele_cloud | ok
Recorder oldest_recorder_run | 26 May 2023 at 11:01 -- | -- current_recorder_run | 8 June 2023 at 15:06 estimated_db_size | 1230.58 MiB database_engine | sqlite database_version | 3.41.2

Anything in the Supervisor logs that might be useful for us?

Logger: zigpy.application
Source: /usr/local/lib/python3.11/site-packages/zigpy/application.py:196
First occurred: 10:42:11 (9 occurrences)
Last logged: 10:57:44

Couldn't start application
Traceback (most recent call last):
  File "/usr/local/lib/python3.11/site-packages/zigpy/application.py", line 193, in startup
    await self.connect()
  File "/usr/local/lib/python3.11/site-packages/bellows/zigbee/application.py", line 131, in connect
    self._ezsp = await bellows.ezsp.EZSP.initialize(self.config)
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/bellows/ezsp/__init__.py", line 150, in initialize
    await ezsp._startup_reset()
  File "/usr/local/lib/python3.11/site-packages/bellows/ezsp/__init__.py", line 141, in _startup_reset
    await self.reset()
  File "/usr/local/lib/python3.11/site-packages/bellows/ezsp/__init__.py", line 170, in reset
    await self._gw.reset()
TimeoutError

Logger: homeassistant.components.zha.core.gateway
Source: components/zha/core/gateway.py:205
Integration: Zigbee Home Automation (documentation, issues)
First occurred: 10:42:15 (9 occurrences)
Last logged: 10:57:44

Couldn't start EZSP = Silicon Labs EmberZNet protocol: Elelabs, HUSBZB-1, Telegesis coordinator (attempt 1 of 3)
Couldn't start EZSP = Silicon Labs EmberZNet protocol: Elelabs, HUSBZB-1, Telegesis coordinator (attempt 2 of 3)
Couldn't start EZSP = Silicon Labs EmberZNet protocol: Elelabs, HUSBZB-1, Telegesis coordinator (attempt 3 of 3)
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 205, in async_initialize
    self.application_controller = await app_controller_cls.new(
                                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/zigpy/application.py", line 219, in new
    await app.startup(auto_form=auto_form)
  File "/usr/local/lib/python3.11/site-packages/zigpy/application.py", line 193, in startup
    await self.connect()
  File "/usr/local/lib/python3.11/site-packages/bellows/zigbee/application.py", line 131, in connect
    self._ezsp = await bellows.ezsp.EZSP.initialize(self.config)
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/bellows/ezsp/__init__.py", line 150, in initialize
    await ezsp._startup_reset()
  File "/usr/local/lib/python3.11/site-packages/bellows/ezsp/__init__.py", line 141, in _startup_reset
    await self.reset()
  File "/usr/local/lib/python3.11/site-packages/bellows/ezsp/__init__.py", line 170, in reset
    await self._gw.reset()
TimeoutError

Logger: homeassistant.config_entries
Source: components/zha/core/gateway.py:205
First occurred: 10:42:55 (3 occurrences)
Last logged: 10:57:44

Error setting up entry SkyConnect Multi-PAN for zha
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 387, in async_setup
    result = await component.async_setup_entry(hass, self)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/zha/__init__.py", line 122, in async_setup_entry
    await zha_gateway.async_initialize()
  File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 220, in async_initialize
    raise exc
  File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 205, in async_initialize
    self.application_controller = await app_controller_cls.new(
                                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/zigpy/application.py", line 219, in new
    await app.startup(auto_form=auto_form)
  File "/usr/local/lib/python3.11/site-packages/zigpy/application.py", line 193, in startup
    await self.connect()
  File "/usr/local/lib/python3.11/site-packages/bellows/zigbee/application.py", line 131, in connect
    self._ezsp = await bellows.ezsp.EZSP.initialize(self.config)
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/bellows/ezsp/__init__.py", line 150, in initialize
    await ezsp._startup_reset()
  File "/usr/local/lib/python3.11/site-packages/bellows/ezsp/__init__.py", line 141, in _startup_reset
    await self.reset()
  File "/usr/local/lib/python3.11/site-packages/bellows/ezsp/__init__.py", line 170, in reset
    await self._gw.reset()
TimeoutError

Anything in the add-on logs that might be useful for us?

-----------------------------------------------------------
 Add-on: Silicon Labs Multiprotocol
 Zigbee and OpenThread multiprotocol add-on
-----------------------------------------------------------
 Add-on version: 2.1.0
 You are running the latest version of this add-on.
 System: Home Assistant OS 10.2  (aarch64 / raspberrypi4-64)
 Home Assistant Core: 2023.6.0
 Home Assistant Supervisor: 2023.06.1
-----------------------------------------------------------
 Please, share the above information when looking for help
 or support in, e.g., GitHub, forums or the Discord chat.
-----------------------------------------------------------
s6-rc: info: service banner successfully started
s6-rc: info: service universal-silabs-flasher: starting
[15:14:11] INFO: Checking /dev/ttyUSB1 identifying SkyConnect v1.0 from Nabu Casa.
[15:14:11] INFO: Starting universal-silabs-flasher with /dev/ttyUSB1
2023-06-08 15:14:12 homeassistant universal_silabs_flasher.flash[170] INFO Extracted GBL metadata: NabuCasaMetadata(metadata_version=1, sdk_version='4.2.3', ezsp_version=None, ot_rcp_version=None, fw_type=<FirmwareImageType.RCP_UART_802154: 'rcp-uart-802154'>, baudrate=460800)
2023-06-08 15:14:12 homeassistant universal_silabs_flasher.flasher[170] INFO Probing ApplicationType.GECKO_BOOTLOADER at 115200 baud
2023-06-08 15:14:14 homeassistant universal_silabs_flasher.flasher[170] INFO Probing ApplicationType.CPC at 460800 baud
2023-06-08 15:14:14 homeassistant universal_silabs_flasher.flasher[170] INFO Detected ApplicationType.CPC, version '4.2.3' at 460800 baudrate (bootloader baudrate None)
2023-06-08 15:14:14 homeassistant universal_silabs_flasher.flash[170] INFO Firmware version '4.2.3' is flashed, not re-installing
s6-rc: info: service universal-silabs-flasher successfully started
s6-rc: info: service cpcd-config: starting
[15:14:15] INFO: Using known baudrate of 460800 for cpcd!
[15:14:16] INFO: Generating cpcd configuration.
s6-rc: info: service cpcd-config successfully started
s6-rc: info: service cpcd: starting
[15:14:16] INFO: Starting cpcd...
WARNING in function 'main' in file /usr/src/cpc-daemon/main.c at line #188 : Running CPCd as 'root' is not recommended. Proceed at your own risk.
s6-rc: info: service cpcd successfully started
s6-rc: info: service zigbeed: starting
s6-rc: info: service zigbeed successfully started
s6-rc: info: service legacy-services: starting
s6-rc: info: service legacy-services successfully started
[15:14:17] INFO: Starting zigbeed...
[15:14:16:945379] Info : [CPCd v4.2.2.0] [Library API v3] [RCP Protocol v3]
[15:14:16:945553] Info : Git commit: a4f53d8357b5432689773ec2eea117654f526705 / branch: 
[15:14:16:945558] Info : Sources hash: 24f9802026e003036eec3dda618f8cf060114efc9551b2fdd5eb331416b64f31
[15:14:16:945581] WARNING : In function 'main' in file /usr/src/cpc-daemon/main.c at line #188 : Running CPCd as 'root' is not recommended. Proceed at your own risk.
[15:14:16:945791] Info : Reading cli arguments
[15:14:16:945805] Info : /usr/local/bin/cpcd 
[15:14:16:951363] Info : Reading configuration
[15:14:16:951381] Info : file_path = /usr/local/etc/cpcd.conf
[15:14:16:951384] Info : instance_name = cpcd_0
[15:14:16:951387] Info : socket_folder = /dev/shm
[15:14:16:951389] Info : operation_mode = MODE_NORMAL
[15:14:16:951392] Info : use_encryption = false
[15:14:16:951394] Info : binding_key_file = /etc/binding-key.key
[15:14:16:951397] Info : binding_key_override = false
[15:14:16:951399] Info : binding_method = 
[15:14:16:951402] Info : stdout_tracing = false
[15:14:16:951404] Info : file_tracing = false
[15:14:16:951406] Info : lttng_tracing = false
[15:14:16:951408] Info : enable_frame_trace = false
[15:14:16:951411] Info : traces_folder = /dev/shm/cpcd-traces
[15:14:16:951413] Info : bus = UART
[15:14:16:951416] Info : uart_baudrate = 460800
[15:14:16:951419] Info : uart_hardflow = true
[15:14:16:951421] Info : uart_file = /dev/ttyUSB1
[15:14:16:951424] Info : spi_file = /dev/spidev0.0
[15:14:16:951426] Info : spi_bitrate = 1000000
[15:14:16:951429] Info : spi_mode = SPI_MODE_0
[15:14:16:951431] Info : spi_bit_per_word = 8
[15:14:16:951433] Info : spi_cs_chip = gpiochip0
[15:14:16:951436] Info : spi_cs_pin = 8
[15:14:16:951438] Info : spi_irq_chip = gpiochip0
[15:14:16:951440] Info : spi_irq_pin = 22
[15:14:16:951442] Info : fu_reset_chip = gpiochip0
[15:14:16:951445] Info : fu_spi_reset_pin = 23
[15:14:16:951447] Info : fu_wake_chip = gpiochip0
[15:14:16:951449] Info : fu_spi_wake_pin = 24
[15:14:16:951452] Info : fu_recovery_enabled = false
[15:14:16:951454] Info : fu_connect_to_bootloader = false
[15:14:16:951456] Info : fu_enter_bootloader = false
[15:14:16:951459] Info : fu_file = 
[15:14:16:951461] Info : restart_cpcd = false
[15:14:16:951463] Info : board_controller_ip_addr = 
[15:14:16:951466] Info : application_version_validation = false
[15:14:16:951468] Info : print_secondary_versions_and_exit = false
[15:14:16:951470] Info : use_noop_keep_alive = false
[15:14:16:951473] Info : reset_sequence = true
[15:14:16:951475] Info : uart_validation_test_option = 
[15:14:16:951477] Info : stats_interval = 0
[15:14:16:951480] Info : rlimit_nofile = 2000
[15:14:16:951483] Info : ENCRYPTION IS DISABLED 
[15:14:16:951485] Info : Starting daemon in normal mode
[15:14:16:969287] Info : Connecting to Secondary...
[15:14:17:054522] Info : Connected to Secondary
[15:14:17:057939] Info : Secondary Protocol v3
[15:14:17:064985] Info : Secondary CPC v4.2.3
[15:14:17:068438] Info : Secondary bus speed is 460800
[15:14:17:071966] Info : Secondary APP vUNDEFINED
[15:14:17:072378] Info : Daemon startup was successful. Waiting for client connections
[15:14:18:709592] Info : New client connection using library v4.2.2.0
[15:14:18:715704] Info : Opened connection socket for ep#12
[15:14:18:716496] Info : Endpoint socket #12: Client connected. 1 connections
Listening on port 9999 for connection...
Accepting connection.

Additional information

No response

MattWestb commented 1 year ago

Nirmall restarting the addon from its panel in the addon manager and looking if the log looks OK. Then reloading ZHA and look if its loading OK or getting error. If getting error and ZHA is not starting re power the system so its starting all in the right sequence.

weaseel commented 1 year ago

That’s what I already tried. restarted the addon silicon labs multiprotocol and reloaded zha. Rebooted the system. Reflashed the sky connect stick. Reverted to silicon labs multiprotocol 1.1.3. unfortunately I can’t go back to 2023.5 because the backup didn’t work … All that leads to the same error in the zha plugin.

MattWestb commented 1 year ago

Double check that you have putting in the port 9999 for EZSP in the addon config.

weaseel commented 1 year ago

Stupid question: where is that setting? I can’t find it in the zha config

MattWestb commented 1 year ago

The lower part of settings:

Network Change the ports on your host that are exposed by the add-on

9999 9999/tcp EmberZNet EZSP/ASH port 8080 8080/tcp OpenThread Web port 8081 8081/tcp OpenThread REST API port

weaseel commented 1 year ago

Ah in the silicon labs multiprotocol. Yeah those ports are set.

MattWestb commented 1 year ago

Can you posting the long then restarting the addon and then one more then restarting ZHA ?

weaseel commented 1 year ago
The otbr-agent is disabled.
s6-rc: info: service s6rc-oneshot-runner: starting
s6-rc: info: service s6rc-oneshot-runner successfully started
s6-rc: info: service fix-attrs: starting
s6-rc: info: service fix-attrs successfully started
s6-rc: info: service legacy-cont-init: starting
cont-init: info: running /etc/cont-init.d/check-cpcd-shm.sh
cont-init: info: /etc/cont-init.d/check-cpcd-shm.sh exited 0
s6-rc: info: service legacy-cont-init successfully started
s6-rc: info: service banner: starting
-----------------------------------------------------------
 Add-on: Silicon Labs Multiprotocol
 Zigbee and OpenThread multiprotocol add-on
-----------------------------------------------------------
 Add-on version: 1.1.3
 There is an update available for this add-on!
 Latest add-on version: 2.1.0
 Please consider upgrading as soon as possible.
 System: Home Assistant OS 10.2  (aarch64 / raspberrypi4-64)
 Home Assistant Core: 2023.6.0
 Home Assistant Supervisor: 2023.06.1
-----------------------------------------------------------
 Please, share the above information when looking for help
 or support in, e.g., GitHub, forums or the Discord chat.
-----------------------------------------------------------
s6-rc: info: service banner successfully started
s6-rc: info: service universal-silabs-flasher: starting
[21:59:34] INFO: Checking /dev/ttyUSB1 identifying SkyConnect v1.0 from Nabu Casa.
[21:59:34] INFO: Starting universal-silabs-flasher with /dev/ttyUSB1
2023-06-10 21:59:35 homeassistant universal_silabs_flasher.flash[175] INFO Extracted GBL metadata: NabuCasaMetadata(metadata_version=1, sdk_version='4.2.3', ezsp_version=None, ot_rcp_version=None, fw_type=<FirmwareImageType.RCP_UART_802154: 'rcp-uart-802154'>, baudrate=460800)
2023-06-10 21:59:35 homeassistant universal_silabs_flasher.flasher[175] INFO Probing ApplicationType.GECKO_BOOTLOADER at 115200 baud
2023-06-10 21:59:37 homeassistant universal_silabs_flasher.flasher[175] INFO Probing ApplicationType.CPC at 460800 baud
2023-06-10 21:59:41 homeassistant universal_silabs_flasher.flasher[175] INFO Probing ApplicationType.CPC at 115200 baud
2023-06-10 21:59:46 homeassistant universal_silabs_flasher.flasher[175] INFO Probing ApplicationType.CPC at 230400 baud
2023-06-10 21:59:50 homeassistant universal_silabs_flasher.flasher[175] INFO Probing ApplicationType.EZSP at 115200 baud
2023-06-10 21:59:55 homeassistant universal_silabs_flasher.flasher[175] INFO Probing ApplicationType.SPINEL at 460800 baud
Error: Failed to probe running application type
s6-rc: warning: unable to start service universal-silabs-flasher: command exited 1
/run/s6/basedir/scripts/rc.init: warning: s6-rc failed to properly bring all the services up! Check your logs (in /run/uncaught-logs/current if you have in-container logging) for more information.
/run/s6/basedir/scripts/rc.init: fatal: stopping the container.
s6-rc: info: service banner: stopping
s6-rc: info: service banner successfully stopped
s6-rc: info: service legacy-cont-init: stopping
s6-rc: info: service legacy-cont-init successfully stopped
s6-rc: info: service fix-attrs: stopping
s6-rc: info: service fix-attrs successfully stopped
s6-rc: info: service s6rc-oneshot-runner: stopping
s6-rc: info: service s6rc-oneshot-runner successfully stopped`

I restarted it and the addon seems to not start anymore now. Strange 
For your information I flashed the zigbee one firmware yesterday evening 
MattWestb commented 1 year ago

The silabs flasher trying flashing one new firmware but cant finding the sky-connect hardware that is working.

Try disabling the automatic flashing in the config and its shall try loading the OTBR.

weaseel commented 1 year ago

22:24:08:293389] Info : Connecting to Secondary... [22:24:10:294145] Info : Failed to connect, secondary seems unresponsive [22:24:10:294187] Info : Connecting to Secondary... … I’ll try again tomorrow. I’m only on mobile at the moment. Thanks for your help

weaseel commented 1 year ago

Okay, so I reinstalled the Silicon Labs Multiprotocol addon and let it flash the stick by itself. Seems to be running now. This is the log of the first start:


 System: Home Assistant OS 10.2  (aarch64 / raspberrypi4-64)
 Home Assistant Core: 2023.6.0
 Home Assistant Supervisor: 2023.06.1
-----------------------------------------------------------
 Please, share the above information when looking for help
 or support in, e.g., GitHub, forums or the Discord chat.
-----------------------------------------------------------
s6-rc: info: service banner successfully started
s6-rc: info: service universal-silabs-flasher: starting
[10:29:18] INFO: Checking /dev/ttyUSB1 identifying SkyConnect v1.0 from Nabu Casa.
[10:29:18] INFO: Starting universal-silabs-flasher with /dev/ttyUSB1
2023-06-11 10:29:20 homeassistant universal_silabs_flasher.flash[170] INFO Extracted GBL metadata: NabuCasaMetadata(metadata_version=1, sdk_version='4.2.3', ezsp_version=None, ot_rcp_version=None, fw_type=<FirmwareImageType.RCP_UART_802154: 'rcp-uart-802154'>, baudrate=460800)
2023-06-11 10:29:20 homeassistant universal_silabs_flasher.flasher[170] INFO Probing ApplicationType.GECKO_BOOTLOADER at 115200 baud
2023-06-11 10:29:22 homeassistant universal_silabs_flasher.flasher[170] INFO Probing ApplicationType.CPC at 460800 baud
2023-06-11 10:29:27 homeassistant universal_silabs_flasher.flasher[170] INFO Probing ApplicationType.CPC at 115200 baud
2023-06-11 10:29:31 homeassistant universal_silabs_flasher.flasher[170] INFO Probing ApplicationType.CPC at 230400 baud
2023-06-11 10:29:35 homeassistant universal_silabs_flasher.flasher[170] INFO Probing ApplicationType.EZSP at 115200 baud
2023-06-11 10:29:37 homeassistant universal_silabs_flasher.flasher[170] INFO Detected ApplicationType.EZSP, version '7.1.1.0 build 273' (7.1.1.0.273) at 115200 baudrate (bootloader baudrate None)
2023-06-11 10:29:37 homeassistant universal_silabs_flasher.flash[170] INFO Cross-flashing from FirmwareImageType.NCP_UART_HW to FirmwareImageType.RCP_UART_802154
2023-06-11 10:29:38 homeassistant universal_silabs_flasher.flasher[170] INFO Probing ApplicationType.GECKO_BOOTLOADER at 115200 baud
2023-06-11 10:29:38 homeassistant universal_silabs_flasher.flasher[170] INFO Detected bootloader version '2.1.1'
2023-06-11 10:29:38 homeassistant universal_silabs_flasher.flasher[170] INFO Detected ApplicationType.EZSP, version '7.1.1.0 build 273' (7.1.1.0.273) at 115200 baudrate (bootloader baudrate 115200)
NabuCasa_SkyConnect_RCP_v4.2.3_rcp-uart-hw-802154_460800.gbl
s6-rc: info: service universal-silabs-flasher successfully started
s6-rc: info: service cpcd-config: starting
[10:30:02] INFO: Using known baudrate of 460800 for cpcd!
[10:30:02] INFO: Generating cpcd configuration.
s6-rc: info: service cpcd-config successfully started
s6-rc: info: service cpcd: starting
[10:30:03] INFO: Starting cpcd...
WARNING in function 'main' in file /usr/src/cpc-daemon/main.c at line #188 : Running CPCd as 'root' is not recommended. Proceed at your own risk.
s6-rc: info: service cpcd successfully started
s6-rc: info: service zigbeed: starting
s6-rc: info: service zigbeed successfully started
s6-rc: info: service legacy-services: starting
s6-rc: info: service legacy-services successfully started
[10:30:04] INFO: Starting zigbeed...
[10:30:03:638443] Info : [CPCd v4.2.2.0] [Library API v3] [RCP Protocol v3]
[10:30:03:638677] Info : Git commit: a4f53d8357b5432689773ec2eea117654f526705 / branch: 
[10:30:03:638682] Info : Sources hash: 24f9802026e003036eec3dda618f8cf060114efc9551b2fdd5eb331416b64f31
[10:30:03:638691] WARNING : In function 'main' in file /usr/src/cpc-daemon/main.c at line #188 : Running CPCd as 'root' is not recommended. Proceed at your own risk.
[10:30:03:638744] Info : Reading cli arguments
[10:30:03:638757] Info : /usr/local/bin/cpcd 
[10:30:03:647546] Info : Reading configuration
[10:30:03:647566] Info : file_path = /usr/local/etc/cpcd.conf
[10:30:03:647569] Info : instance_name = cpcd_0
[10:30:03:647571] Info : socket_folder = /dev/shm
[10:30:03:647574] Info : operation_mode = MODE_NORMAL
[10:30:03:647576] Info : use_encryption = false
[10:30:03:647578] Info : binding_key_file = /etc/binding-key.key
[10:30:03:647581] Info : binding_key_override = false
[10:30:03:647583] Info : binding_method = 
[10:30:03:647585] Info : stdout_tracing = false
[10:30:03:647587] Info : file_tracing = false
[10:30:03:647588] Info : lttng_tracing = false
[10:30:03:647590] Info : enable_frame_trace = false
[10:30:03:647593] Info : traces_folder = /dev/shm/cpcd-traces
[10:30:03:647595] Info : bus = UART
[10:30:03:647597] Info : uart_baudrate = 460800
[10:30:03:647600] Info : uart_hardflow = true
[10:30:03:647602] Info : uart_file = /dev/ttyUSB1
[10:30:03:647604] Info : spi_file = /dev/spidev0.0
[10:30:03:647607] Info : spi_bitrate = 1000000
[10:30:03:647609] Info : spi_mode = SPI_MODE_0
[10:30:03:647611] Info : spi_bit_per_word = 8
[10:30:03:647613] Info : spi_cs_chip = gpiochip0
[10:30:03:647615] Info : spi_cs_pin = 8
[10:30:03:647617] Info : spi_irq_chip = gpiochip0
[10:30:03:647619] Info : spi_irq_pin = 22
[10:30:03:647622] Info : fu_reset_chip = gpiochip0
[10:30:03:647624] Info : fu_spi_reset_pin = 23
[10:30:03:647626] Info : fu_wake_chip = gpiochip0
[10:30:03:647628] Info : fu_spi_wake_pin = 24
[10:30:03:647630] Info : fu_recovery_enabled = false
[10:30:03:647632] Info : fu_connect_to_bootloader = false
[10:30:03:647634] Info : fu_enter_bootloader = false
[10:30:03:647636] Info : fu_file = 
[10:30:03:647638] Info : restart_cpcd = false
[10:30:03:647640] Info : board_controller_ip_addr = 
[10:30:03:647642] Info : application_version_validation = false
[10:30:03:647644] Info : print_secondary_versions_and_exit = false
[10:30:03:647646] Info : use_noop_keep_alive = false
[10:30:03:647649] Info : reset_sequence = true
[10:30:03:647651] Info : uart_validation_test_option = 
[10:30:03:647653] Info : stats_interval = 0
[10:30:03:647655] Info : rlimit_nofile = 2000
[10:30:03:647658] Info : ENCRYPTION IS DISABLED 
[10:30:03:647660] Info : Starting daemon in normal mode
[10:30:03:665512] Info : Connecting to Secondary...
[10:30:03:751353] Info : Connected to Secondary
[10:30:03:755213] Info : Secondary Protocol v3
[10:30:03:762041] Info : Secondary CPC v4.2.3
[10:30:03:765348] Info : Secondary bus speed is 460800
[10:30:03:768742] Info : Secondary APP vUNDEFINED
[10:30:03:769107] Info : Daemon startup was successful. Waiting for client connections
[10:30:05:363425] Info : New client connection using library v4.2.2.0
[10:30:05:368271] Info : Opened connection socket for ep#12
[10:30:05:368697] Info : Endpoint socket #12: Client connected. 1 connections
Listening on port 9999 for connection...
Accepting connection.```

But restarting ZHA still shows this Error
```txt
2023-06-11 10:30:47.672 ERROR (MainThread) [zigpy.application] Couldn't start application
Traceback (most recent call last):
File "/usr/local/lib/python3.11/site-packages/zigpy/application.py", line 193, in startup
await self.connect()
File "/usr/local/lib/python3.11/site-packages/bellows/zigbee/application.py", line 131, in connect
self._ezsp = await bellows.ezsp.EZSP.initialize(self.config)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/bellows/ezsp/__init__.py", line 150, in initialize
await ezsp._startup_reset()
File "/usr/local/lib/python3.11/site-packages/bellows/ezsp/__init__.py", line 141, in _startup_reset
await self.reset()
File "/usr/local/lib/python3.11/site-packages/bellows/ezsp/__init__.py", line 170, in reset
await self._gw.reset()
TimeoutError

2023-06-11 10:30:47.798 WARNING (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start EZSP = Silicon Labs EmberZNet protocol: Elelabs, HUSBZB-1, Telegesis coordinator (attempt 3 of 3)
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 205, in async_initialize
self.application_controller = await app_controller_cls.new(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/zigpy/application.py", line 219, in new
await app.startup(auto_form=auto_form)
File "/usr/local/lib/python3.11/site-packages/zigpy/application.py", line 193, in startup
await self.connect()
File "/usr/local/lib/python3.11/site-packages/bellows/zigbee/application.py", line 131, in connect
self._ezsp = await bellows.ezsp.EZSP.initialize(self.config)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/bellows/ezsp/__init__.py", line 150, in initialize
await ezsp._startup_reset()
File "/usr/local/lib/python3.11/site-packages/bellows/ezsp/__init__.py", line 141, in _startup_reset
await self.reset()
File "/usr/local/lib/python3.11/site-packages/bellows/ezsp/__init__.py", line 170, in reset
await self._gw.reset()
TimeoutError

2023-06-11 10:30:47.812 ERROR (MainThread) [homeassistant.config_entries] Error setting up entry SkyConnect Multi-PAN for zha
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/config_entries.py", line 387, in async_setup
result = await component.async_setup_entry(hass, self)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/components/zha/__init__.py", line 122, in async_setup_entry
await zha_gateway.async_initialize()
File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 220, in async_initialize
raise exc
File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 205, in async_initialize
self.application_controller = await app_controller_cls.new(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/zigpy/application.py", line 219, in new
await app.startup(auto_form=auto_form)
File "/usr/local/lib/python3.11/site-packages/zigpy/application.py", line 193, in startup
await self.connect()
File "/usr/local/lib/python3.11/site-packages/bellows/zigbee/application.py", line 131, in connect
self._ezsp = await bellows.ezsp.EZSP.initialize(self.config)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.11/site-packages/bellows/ezsp/__init__.py", line 150, in initialize
await ezsp._startup_reset()
File "/usr/local/lib/python3.11/site-packages/bellows/ezsp/__init__.py", line 141, in _startup_reset
await self.reset()
File "/usr/local/lib/python3.11/site-packages/bellows/ezsp/__init__.py", line 170, in reset
await self._gw.reset()
TimeoutError```

I can't configure anything inside ZHA. I can't even download a backup of my network. I still have a full Backup of HA were all devices are included, does that help. But I don't want to fully revert back to that one, since it is already 2 weeks old.
MattWestb commented 1 year ago

Yiur stick was running EZSP NCP 7.1.1.0 build 273 but now its flashed with RCP v4.2.3 that very good also the addon can communicating with the chip.

[10:30:05:363425] Info : New client connection using library v4.2.2.0
[10:30:05:368271] Info : Opened connection socket for ep#12
[10:30:05:368697] Info : Endpoint socket #12: Client connected. 1 connections
Listening on port 9999 for connection...

Now try reload ZHA and looking if it can connecting and if not restart addon and then reload ZHA. Its happening its being timing problem then restarting the hardware and HA is trying starting all things at the same time and the addon is not ready then ZHA is trying starting and its ending up with timeout.

weaseel commented 1 year ago

IMG_2066 ZHA is still showing the same error. i am a Little confused, why it says: 1 client connected. That shouldn’t be if zha is not working right? Regarding ezsp firmware: yesterday I flashed the ezsp firmware because I’m only using zigbee and others reported that this might fix the problem. updating to 2023.6.1 won’t make any difference right? I attached my addon settings

MattWestb commented 1 year ago

Endpoint socket #12: Client connected. 1 connections is the handle for ZHA but its can being timing problems then starting so its not getting all right. I have running addon with ZHA for one and a half year and its normal nearly production quality but i have not addon new hardware so ZHA is trying forming one network that have being some problem with but it shall being fixed. Try deleting the ZHA integration and restart HA and then its stable adding ZHA and see if it can connecting to the addon OK and if it can forming one new network.

weaseel commented 1 year ago

But if I delete it, all my settings and devices (20+) are gone, correct? That would be a lot of work to get it running again. It worked for half a year now. But stopped working after the update to 2023.6.0

MattWestb commented 1 year ago

Do you have one backup of the coordinator ? then you can restoring it then installing ZHA also you can do it later if you like but can being problems with the frame counters is its too old.

weaseel commented 1 year ago

I have a 2 week old backup of the whole system. don’t want to restore that one because of the other data (energy consumption of the house and so on). And a very recent one of the addon. But that seems to be working fine. can I extract the data from the backup file?

weaseel commented 1 year ago

Anything else I can try or do I have to Setup everything by hand?

weaseel commented 1 year ago

I reverted back to zigbee only. Now it’s running.

agners commented 1 year ago
Error: Failed to probe running application type
s6-rc: warning: unable to start service universal-silabs-flasher: command exited 1

As for the Multi-Protocol add-on issue: That usually indicates that something else was accessing the serial port.

At first it couldn't be found. Reboot didn't change anything. After disconnecting and reconnecting it to usb, it was found again and the Silicon Labs Multiprotocol is running (no error in logs).

Hm, that might have caused ZHA to configure SkyConnect directly. Did a "discovered device" appear?

@puddly the stack traces look to me as if UART is being used directly no? I wonder what happens if the add-on is late/doesn't startup correctly. Maybe we need to handle that case a bit better.

weaseel commented 1 year ago

The ZHA integration showed the SkyConnect Multi-PAN stick but couldn’t connect. All devices were still there but obviously without new data. What I did when I wrote I reverted back to zigbee only: delete silabs addon, flashed zigbee only firmware on the stick, clicked migrate radio in ZHA integration and followed the wizard. i can’t use thread now, but I have never used it anyway until now.

What I also realized: after disabling the „thread“ integration, I was not able to connect to the usb stick anymore. I hat to remove it and replug it. Maybe this integration broke something? It was running without error the whole time btw. Just realized that today.

puddly commented 1 year ago

the stack traces look to me as if UART is being used directly no?

It's hard to tell at this point since the original setup is now gone but there should be no way for the serial port path to revert back to /dev/serial/by-id/... from socket://...:9999 on its own, without an explicit migration being initiated.

@weaseel how long ago did you enable multiprotocol support for the first time? Do you recall ever restarting Home Assistant after doing this, or could you have done it recently enough for this upgrade to have been the first time you restarted HA?

I wonder what happens if the add-on is late/doesn't startup correctly. Maybe we need to handle that case a bit better.

ZHA should treat most connection errors as ConfigEntryNotReady and retry indefinitely. I'll check if there are more status codes that I haven't accounted for.

weaseel commented 1 year ago

I have been running multi protocol since it was kind of stable. At least a few months. So many restarts. i always had a problem when I updated homeassistant. After a reboot, the ikea buttons didn’t work anymore. I had to go into the automation and then add the same trigger again, save and then delete the old trigger. After that the yaml was 100% the same but it worked.

MattWestb commented 1 year ago

HA is often failing loading device automation then running RCP and can need restarting HA after have doing one cold boot then ZHA is not ready then the automatons is loaded and timing out. Also its not possible deleting automatons from the GUI if the device is not coming online and must deleting then in the yaml file.

agners commented 1 year ago

Thanks for the additional info. Unfortunately since the device is no longer in a state where we see these things its kinda hard to reconstruct what happened. In case you see it again, please reopen and share the latest logs again.

I reverted back to zigbee only. Now it’s running.

Good to see that things are back working now :+1: