search

home-assistant / addons

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

SiLabs Multiprotocol stops working / fails to start after update to 2023.3.3 #2909

Closed coolapso closed 1 year ago

coolapso commented 1 year ago

Describe the issue you are experiencing

Addon Starts, but integrations are not able to communicate with device.

OpenThread border router is not automatically detected by home assistant, and when trying to connect to it fails. ZHA is automatically detected with Skyconnect multi PAN, but when clicking configure it reports "unknwon error" when trying to configure ZHA manually as per documentation, it reports that can't connect to the device.

Logs show addon always on kind of startup boot. Web interface is not accessible by any means, even though the ports are exposed.

Seems the Addon fail to start but keeps looping on same error and never stops.

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?

1.0.0

Steps to reproduce the issue

Can't really tell steps to reproduce this. this are the conditions that I have been able to get to:

  1. latest RCP Multi-PAN firmware
  2. homeassistant 2023.3.3, was working with 2023.3.2 but downgrading version didn't help.
  3. Silabs Addon v1.0.0 with OpenThread border router enabled, and web interfaces open

System Health information

There are currently no repairs available

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

-03-11 12:57:07.219 WARNING (MainThread) [homeassistant.setup] Setup of hassio is taking over 10 seconds.
2023-03-11 12:57:07.410 WARNING (MainThread) [homeassistant.setup] Setup of bluetooth is taking over 10 seconds.
2023-03-11 12:57:08.635 WARNING (MainThread) [homeassistant.setup] Setup of ssdp is taking over 10 seconds.
2023-03-11 12:57:42.082 WARNING (MainThread) [homeassistant.setup] Setup of input_datetime is taking over 10 seconds.
2023-03-11 12:57:42.091 WARNING (MainThread) [homeassistant.setup] Setup of input_button is taking over 10 seconds.
2023-03-11 12:57:46.612 WARNING (SyncWorker_1) [homeassistant.components.rpi_power.binary_sensor] Under-voltage was detected. Consider getting a uninterruptible power supply for your Raspberry Pi.
2023-03-11 12:58:03.876 WARNING (MainThread) [homeassistant.config_entries] Config entry 'Office2' for yeelight integration not ready yet: Failed to read from the socket at 192.168.11.7:55443: [Errno 113] Connect call failed ('192.168.11.7', 55443).; Retrying in background
2023-03-11 12:58:03.901 WARNING (MainThread) [homeassistant.config_entries] Config entry 'Office1' for yeelight integration not ready yet: Failed to read from the socket at 192.168.11.144:55443: [Errno 113] Connect call failed ('192.168.11.144', 55443).; Retrying in background
2023-03-11 12:58:03.909 WARNING (MainThread) [homeassistant.config_entries] Config entry 'Bedroom' for yeelight integration not ready yet: Failed to read from the socket at 192.168.11.80:55443: [Errno 113] Connect call failed ('192.168.11.80', 55443).; Retrying in background
2023-03-11 12:59:11.723 ERROR (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:EB:CE:23:DE): Error stopping scanner: [org.bluez.Error.InProgress] Operation already in progress
2023-03-11 12:59:50.808 ERROR (MainThread) [homeassistant.core] Error executing service: <ServiceCall light.turn_off (c:01GV88M38ZTSQM4W2SV3RN7DA2): entity_id=['light.secretlab_magrgb_75po'], params=>
Traceback (most recent call last):
File "/usr/local/lib/python3.10/site-packages/bleak_retry_connector/__init__.py", line 342, in establish_connection
await client.connect(
File "/usr/src/homeassistant/homeassistant/components/bluetooth/wrappers.py", line 235, in connect
wrapped_backend = self._async_get_best_available_backend_and_device(manager)
File "/usr/src/homeassistant/homeassistant/components/bluetooth/wrappers.py", line 332, in _async_get_best_available_backend_and_device
raise BleakError(
bleak.exc.BleakError: No backend with an available connection slot that can reach address CC:3A:61:A2:30:7B was found
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/usr/local/lib/python3.10/site-packages/aiohomekit/controller/ble/connection.py", line 47, in establish_connection
return await retry_establish_connection(
File "/usr/local/lib/python3.10/site-packages/bleak_retry_connector/__init__.py", line 419, in establish_connection
_raise_if_needed(name, device.address, exc)
File "/usr/local/lib/python3.10/site-packages/bleak_retry_connector/__init__.py", line 311, in _raise_if_needed
raise BleakOutOfConnectionSlotsError(
bleak_retry_connector.BleakOutOfConnectionSlotsError: Secretlab MAGRGB 75PO [CC:3A:61:A2:30:7B] (id=FA:06:C6:DD:8B:EF) - CC:3A:61:A2:30:7B: Failed to connect: No backend with an available connection slot that can reach address CC:3A:61:A2:30:7B was found: The proxy/adapter is out of connection slots; Add additional proxies near this device
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/core.py", line 1826, in catch_exceptions
await coro_or_task
File "/usr/src/homeassistant/homeassistant/core.py", line 1845, in _execute_service
await cast(Callable[[ServiceCall], Awaitable[None]], handler.job.target)(
File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 213, in handle_service
await service.entity_service_call(
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 686, in entity_service_call
future.result() # pop exception if have
File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 961, in async_request_call
await coro
File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 726, in _handle_entity_call
await result
File "/usr/src/homeassistant/homeassistant/components/light/__init__.py", line 583, in async_handle_light_off_service
await light.async_turn_off(**filter_turn_off_params(light, params))
File "/usr/src/homeassistant/homeassistant/components/homekit_controller/light.py", line 167, in async_turn_off
await self.async_put_characteristics({CharacteristicsTypes.ON: False})
File "/usr/src/homeassistant/homeassistant/components/homekit_controller/entity.py", line 89, in async_put_characteristics
return await self._accessory.put_characteristics(payload)
File "/usr/src/homeassistant/homeassistant/components/homekit_controller/connection.py", line 776, in put_characteristics
await self.pairing.put_characteristics(characteristics)
File "/usr/local/lib/python3.10/site-packages/aiohomekit/controller/ble/pairing.py", line 189, in _async_operation_lock_wrap
return await func(self, *args, **kwargs)
File "/usr/local/lib/python3.10/site-packages/bleak_retry_connector/__init__.py", line 447, in _async_wrap_bluetooth_connection_error_retry
return await func(*args, **kwargs)
File "/usr/local/lib/python3.10/site-packages/aiohomekit/controller/ble/pairing.py", line 205, in _async_disconnect_on_missing_services_wrap
return await func(self, *args, **kwargs)
File "/usr/local/lib/python3.10/site-packages/aiohomekit/controller/ble/pairing.py", line 229, in _async_restore_and_resume
await self._populate_accessories_and_characteristics()
File "/usr/local/lib/python3.10/site-packages/aiohomekit/controller/ble/pairing.py", line 1099, in _populate_accessories_and_characteristics
made_connection = await self._ensure_connected(attempts)
File "/usr/local/lib/python3.10/site-packages/aiohomekit/controller/ble/pairing.py", line 500, in _ensure_connected
self.client = await establish_connection(
File "/usr/local/lib/python3.10/site-packages/aiohomekit/controller/ble/connection.py", line 61, in establish_connection
raise AccessoryDisconnectedError(ex) from ex
aiohomekit.exceptions.AccessoryDisconnectedError: Secretlab MAGRGB 75PO [CC:3A:61:A2:30:7B] (id=FA:06:C6:DD:8B:EF) - CC:3A:61:A2:30:7B: Failed to connect: No backend with an available connection slot that can reach address CC:3A:61:A2:30:7B was found: The proxy/adapter is out of connection slots; Add additional proxies near this device
2023-03-11 13:01:11.631 ERROR (MainThread) [homeassistant.components.bluetooth.scanner] hci0 (B8:27:EB:CE:23:DE): Error stopping scanner: [org.bluez.Error.InProgress] Operation already in progress
2023-03-11 13:12:20.968 ERROR (MainThread) [aiohttp.server] Error handling request
Traceback (most recent call last):
File "/usr/local/lib/python3.10/site-packages/aiohttp/web_protocol.py", line 433, in _handle_request
resp = await request_handler(request)
File "/usr/local/lib/python3.10/site-packages/aiohttp/web_app.py", line 504, in _handle
resp = await handler(request)
File "/usr/local/lib/python3.10/site-packages/aiohttp/web_middlewares.py", line 117, in impl
return await handler(request)
File "/usr/src/homeassistant/homeassistant/components/http/security_filter.py", line 67, in security_filter_middleware
return await handler(request)
File "/usr/src/homeassistant/homeassistant/components/http/forwarded.py", line 227, in forwarded_middleware
return await handler(request)
File "/usr/src/homeassistant/homeassistant/components/http/request_context.py", line 28, in request_context_middleware
return await handler(request)
File "/usr/src/homeassistant/homeassistant/components/http/ban.py", line 80, in ban_middleware
return await handler(request)
File "/usr/src/homeassistant/homeassistant/components/http/auth.py", line 235, in auth_middleware
return await handler(request)
File "/usr/src/homeassistant/homeassistant/components/http/view.py", line 146, in handle
result = await result
File "/usr/src/homeassistant/homeassistant/components/config/config_entries.py", line 180, in post
return await super().post(request, flow_id)
File "/usr/src/homeassistant/homeassistant/components/http/data_validator.py", line 72, in wrapper
result = await method(view, request, data, *args, **kwargs)
File "/usr/src/homeassistant/homeassistant/helpers/data_entry_flow.py", line 110, in post
result = await self._flow_mgr.async_configure(flow_id, data)
File "/usr/src/homeassistant/homeassistant/data_entry_flow.py", line 271, in async_configure
result = await self._async_handle_step(
File "/usr/src/homeassistant/homeassistant/data_entry_flow.py", line 367, in _async_handle_step
result: FlowResult = await getattr(flow, method)(user_input)
File "/usr/src/homeassistant/homeassistant/components/zha/config_flow.py", line 519, in async_step_confirm
return await self.async_step_choose_formation_strategy()
File "/usr/src/homeassistant/homeassistant/components/zha/config_flow.py", line 296, in async_step_choose_formation_strategy
await self._radio_mgr.async_load_network_settings()
File "/usr/src/homeassistant/homeassistant/components/zha/radio_manager.py", line 194, in async_load_network_settings
async with self._connect_zigpy_app() as app:
File "/usr/local/lib/python3.10/contextlib.py", line 199, in __aenter__
return await anext(self.gen)
File "/usr/src/homeassistant/homeassistant/components/zha/radio_manager.py", line 138, in _connect_zigpy_app
await app.connect()
File "/usr/local/lib/python3.10/site-packages/bellows/zigbee/application.py", line 124, in connect
self._ezsp = await bellows.ezsp.EZSP.initialize(self.config)
File "/usr/local/lib/python3.10/site-packages/bellows/ezsp/__init__.py", line 102, in initialize
await ezsp.connect(use_thread=zigpy_config[conf.CONF_USE_THREAD])
File "/usr/local/lib/python3.10/site-packages/bellows/ezsp/__init__.py", line 119, in connect
self._gw = await bellows.uart.connect(self._config, self, use_thread=use_thread)
File "/usr/local/lib/python3.10/site-packages/bellows/uart.py", line 398, in connect
protocol, connection_done = await thread.run_coroutine_threadsafe(
File "/usr/local/lib/python3.10/site-packages/bellows/uart.py", line 377, in _connect
transport, protocol = await zigpy.serial.create_serial_connection(
File "/usr/local/lib/python3.10/site-packages/zigpy/serial.py", line 32, in create_serial_connection
transport, protocol = await loop.create_connection(
File "/usr/local/lib/python3.10/asyncio/base_events.py", line 1076, in create_connection
raise exceptions[0]
File "/usr/local/lib/python3.10/asyncio/base_events.py", line 1060, in create_connection
sock = await self._connect_sock(
File "/usr/local/lib/python3.10/asyncio/base_events.py", line 969, in _connect_sock
await self.sock_connect(sock, address)
File "/usr/local/lib/python3.10/asyncio/selector_events.py", line 501, in sock_connect
return await fut
File "/usr/local/lib/python3.10/asyncio/selector_events.py", line 541, in _sock_connect_cb
raise OSError(err, f'Connect call failed {address}')
ConnectionRefusedError: [Errno 111] Connect call failed ('172.30.32.1', 9999)
2023-03-11 13:12:39.901 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!

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

[13:21:11] INFO: Web UI and REST API port are exposed, starting otbr-web.
s6-rc: info: service mdns: starting
s6-rc: info: service s6rc-oneshot-runner: starting
s6-rc: info: service mdns successfully started
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
[13:21:13] INFO: Starting mDNS Responder...
Default: mDNSResponder (Engineering Build) (Mar  1 2023 17:49:54) starting
Default: mDNS_AddDNSServer: Lock not held! mDNS_busy (0) mDNS_reentrancy (0)
cont-init: info: /etc/cont-init.d/check-cpcd-shm.sh exited 0
cont-init: info: running /etc/cont-init.d/config.sh
[13:21:21] INFO: Generating cpcd configuration.
cont-init: info: /etc/cont-init.d/config.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.0.0
 You are running the latest version of this add-on.
 System: Home Assistant OS 9.5  (aarch64 / raspberrypi3-64)
 Home Assistant Core: 2023.3.3
 Home Assistant Supervisor: 2023.03.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
[13:21:34] INFO: Flashing firmware is disabled
s6-rc: info: service universal-silabs-flasher successfully started
s6-rc: info: service cpcd: starting
[13:21:34] 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.
FATAL in function 'protocol_version_check' in file /usr/src/cpc-daemon/server_core/server_core.c at line #666 : Secondary Protocol v2 doesn't match CPCd Protocol v3
[13:21:34:949091] Info : [CPCd v4.2.1.0] [Library API v3] [RCP Protocol v3]
[13:21:34:949673] Info : Git commit: 038cccb2222f18096b6f7f43f73f4220479239ef / branch: 
[13:21:34:949686] Info : Sources hash: 5d47e3b41b2e023f52d5d5d2814ddf2dc2219a62e8d6e9e5f22f08f7d54206dc
[13:21:34:949707] 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.
[13:21:34:949834] Info : Reading cli arguments
[13:21:34:949858] Info : /usr/local/bin/cpcd 
[13:21:34:955044] Info : Reading configuration
[13:21:34:955083] Info : file_path = /usr/local/etc/cpcd.conf
[13:21:34:955093] Info : instance_name = cpcd_0
[13:21:34:955100] Info : socket_folder = /dev/shm
[13:21:34:955108] Info : operation_mode = MODE_NORMAL
[13:21:34:955116] Info : use_encryption = false
[13:21:34:955123] Info : binding_key_file = /etc/binding-key.key
[13:21:34:955131] Info : binding_key_override = false
[13:21:34:955138] Info : binding_method = 
[13:21:34:955145] Info : stdout_tracing = false
[13:21:34:955152] Info : file_tracing = false
[13:21:34:955160] Info : lttng_tracing = false
[13:21:34:955167] Info : enable_frame_trace = false
[13:21:34:955174] Info : traces_folder = /dev/shm/cpcd-traces
[13:21:34:955182] Info : bus = UART
[13:21:34:955189] Info : uart_baudrate = 115200
[13:21:34:955199] Info : uart_hardflow = true
[13:21:34:955206] Info : uart_file = /dev/ttyUSB0
[13:21:34:955213] Info : spi_file = /dev/spidev0.0
[13:21:34:955220] Info : spi_bitrate = 1000000
[13:21:34:955228] Info : spi_mode = SPI_MODE_0
[13:21:34:955235] Info : spi_bit_per_word = 8
[13:21:34:955243] Info : spi_cs_chip = gpiochip0
[13:21:34:955250] Info : spi_cs_pin = 8
[13:21:34:955257] Info : spi_irq_chip = gpiochip0
[13:21:34:955264] Info : spi_irq_pin = 22
[13:21:34:955271] Info : fu_reset_chip = gpiochip0
[13:21:34:955278] Info : fu_spi_reset_pin = 23
[13:21:34:955285] Info : fu_wake_chip = gpiochip0
[13:21:34:955292] Info : fu_spi_wake_pin = 24
[13:21:34:955299] Info : fu_recovery_enabled = false
[13:21:34:955306] Info : fu_connect_to_bootloader = false
[13:21:34:955314] Info : fu_enter_bootloader = false
[13:21:34:955321] Info : fu_file = 
[13:21:34:955328] Info : restart_cpcd = false
[13:21:34:955335] Info : board_controller_ip_addr = 
[13:21:34:955342] Info : application_version_validation = false
[13:21:34:955349] Info : print_secondary_versions_and_exit = false
[13:21:34:955356] Info : use_noop_keep_alive = false
[13:21:34:955445] Info : reset_sequence = true
[13:21:34:955454] Info : uart_validation_test_option = 
[13:21:34:955461] Info : stats_interval = 0
[13:21:34:955469] Info : rlimit_nofile = 2000
[13:21:34:955477] Info : ENCRYPTION IS DISABLED 
[13:21:34:955484] Info : Starting daemon in normal mode
[13:21:34:971323] Info : Connecting to Secondary...
[13:21:35:065694] Info : Connected to Secondary
[13:21:35:072111] Info : Secondary Protocol v2
[13:21:35:072158] *** ASSERT *** : FATAL in function 'protocol_version_check' in file /usr/src/cpc-daemon/server_core/server_core.c at line #666 : Secondary Protocol v2 doesn't match CPCd Protocol v3
[13:21:36:076770] Info : Daemon exiting with status EXIT_FAILURE
Logger buffer size = 28672, highwater mark = 3139 : 10.95%. Lost logs : 0
[13:21:36] INFO: CPC ended with exit code 1 (signal 0)...```

Additional information

Sorry if I missed any detail, but feel free to request anything you might need and ill be glad to provide it.

coolapso commented 1 year ago

Nevermind. Fixed it after enabling "automatic firmware upgrade" after digging a bit more through the github issues.