search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
71.03k stars 29.7k forks source link

Error setting up entry Sonoff Zigbee 3.0 USB Dongle Plus #62808

Closed tassadar81 closed 2 years ago

tassadar81 commented 2 years ago

The problem

Just after choosing the tty, the configuration crashes after a while, it seems a timeout

What version of Home Assistant Core has the issue?

core-2021.12.5

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

ZHA

Link to integration documentation on our website

https://www.home-assistant.io/integrations/zha/

Example YAML snippet

No response

Anything in the logs that might be useful for us?

2021-12-26 18:58:57 INFO (MainThread) [zigpy_znp.zigbee.application] ZNP is not configured, forming a new network
2021-12-26 18:58:57 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.HAS_CONFIGURED_ZSTACK1: 3840>)
2021-12-26 18:58:57 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=0)
2021-12-26 18:58:57 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.HAS_CONFIGURED_ZSTACK3: 96>)
2021-12-26 18:58:57 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=0)
2021-12-26 18:58:57 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.ZIGPY_ZNP_MIGRATION_ID: 95>)
2021-12-26 18:58:57 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-12-26 18:58:57 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVDelete.Req(Id=<OsalNvIds.ZIGPY_ZNP_MIGRATION_ID: 95>, ItemLen=1)
2021-12-26 18:58:57 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVDelete.Rsp(Status=<Status.SUCCESS: 0>)
2021-12-26 18:58:57 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.BDBNODEISONANETWORK: 85>)
2021-12-26 18:58:57 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-12-26 18:58:57 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVDelete.Req(Id=<OsalNvIds.BDBNODEISONANETWORK: 85>, ItemLen=1)
2021-12-26 18:58:57 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVDelete.Rsp(Status=<Status.SUCCESS: 0>)
2021-12-26 18:58:57 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.STARTUP_OPTION: 3>)
2021-12-26 18:58:57 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-12-26 18:58:57 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.STARTUP_OPTION: 3>, Offset=0, Value=b'\x03')
2021-12-26 18:58:57 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-12-26 18:58:57 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.ResetReq.Req(Type=<ResetType.Soft: 1>)
2021-12-26 18:58:57 DEBUG (MainThread) [zigpy_znp.api] Request has no response, not waiting for one.
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.ResetInd.Callback(Reason=<ResetReason.PowerUp: 0>, TransportRev=2, ProductId=1, MajorRel=2, MinorRel=7, MaintRel=1)
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.PANID: 131>)
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=2)
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.PANID: 131>, Offset=0, Value=b'\xFF\xFF')
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.APS_USE_EXT_PANID: 71>)
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=8)
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.APS_USE_EXT_PANID: 71>, Offset=0, Value=b'\x9A\xDD\x81\xC7\xA5\xB9\xB8\xA2')
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.PRECFGKEY: 98>)
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=16)
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.PRECFGKEY: 98>, Offset=0, Value=b'\x54\x48\x5E\x17\xF0\x7C\xA3\x60\x5E\x25\x2A\x16\xDE\xF8\x01\xBD')
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.PRECFGKEYS_ENABLE: 99>)
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=1)
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.PRECFGKEYS_ENABLE: 99>, Offset=0, Value=b'\x00')
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVLength.Req(Id=<OsalNvIds.CHANLIST: 132>)
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVLength.Rsp(ItemLen=4)
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Sending request: SYS.OSALNVWriteExt.Req(Id=<OsalNvIds.CHANLIST: 132>, Offset=0, Value=b'\x00\x80\x10\x02')
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Received command: SYS.OSALNVWriteExt.Rsp(Status=<Status.SUCCESS: 0>)
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Sending request: AppConfig.BDBSetChannel.Req(IsPrimary=<Bool.true: 1>, Channel=<Channels.CHANNEL_25|CHANNEL_20|CHANNEL_15: 34635776>)
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBSetChannel.Rsp(Status=<Status.SUCCESS: 0>)
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Sending request: AppConfig.BDBSetChannel.Req(IsPrimary=<Bool.false: 0>, Channel=<Channels.NO_CHANNELS: 0>)
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBSetChannel.Rsp(Status=<Status.SUCCESS: 0>)
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Forming temporary network
2021-12-26 18:58:59 DEBUG (MainThread) [zigpy_znp.api] Sending request: AppConfig.BDBStartCommissioning.Req(Mode=<BDBCommissioningMode.NwkFormation: 4>)
2021-12-26 18:59:02 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBStartCommissioning.Rsp(Status=<Status.SUCCESS: 0>)
2021-12-26 18:59:02 DEBUG (MainThread) [zigpy_znp.api] Received command: AppConfig.BDBCommissioningNotification.Callback(Status=<BDBCommissioningStatus.InProgress: 1>, Mode=<BDBCommissioningMode.NwkSteering: 2>, RemainingModes=<BDBCommissioningMode.NwkFormation: 4>)
2021-12-26 18:59:03 DEBUG (MainThread) [zigpy_znp.api] Received command: ZDO.StateChangeInd.Callback(State=<DeviceState.StartingAsCoordinator: 8>)
2021-12-26 18:59:29 DEBUG (MainThread) [zigpy_znp.uart] Closing serial port
2021-12-26 18:59:29 ERROR (MainThread) [zigpy.application] Couldn't start application
2021-12-26 18:59:29 ERROR (MainThread) [homeassistant.config_entries] Error setting up entry Sonoff Zigbee 3.0 USB Dongle Plus, s/n: 32f1fa3bfd19ec11b38b7fe5f01c6278 - ITead for zha
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/zigpy_znp/api.py", line 867, in request_callback_rsp
    return await callback_rsp
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/zigpy_znp/api.py", line 261, in write_network_info
    commissioning_rsp = await self.request_callback_rsp(
  File "/usr/local/lib/python3.9/site-packages/zigpy_znp/api.py", line 867, in request_callback_rsp
    return await callback_rsp
  File "/usr/local/lib/python3.9/site-packages/async_timeout/__init__.py", line 128, in __aexit__
    self._do_exit(exc_type)
  File "/usr/local/lib/python3.9/site-packages/async_timeout/__init__.py", line 203, in _do_exit
    raise asyncio.TimeoutError
asyncio.exceptions.TimeoutError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/config_entries.py", line 313, in async_setup
    result = await component.async_setup_entry(hass, self)  # type: ignore
  File "/usr/src/homeassistant/homeassistant/components/zha/__init__.py", line 102, in async_setup_entry
    await zha_gateway.async_initialize()
  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 69, in new
    await app.startup(auto_form)
  File "/usr/local/lib/python3.9/site-packages/zigpy_znp/zigbee/application.py", line 175, in startup
    return await self._startup(
  File "/usr/local/lib/python3.9/site-packages/zigpy_znp/zigbee/application.py", line 230, in _startup
    await self.form_network()
  File "/usr/local/lib/python3.9/site-packages/zigpy_znp/zigbee/application.py", line 407, in form_network
    await self.write_network_info(network_info=network_info, node_info=node_info)
  File "/usr/local/lib/python3.9/site-packages/zigpy_znp/zigbee/application.py", line 1188, in write_network_info
    return await self._znp.write_network_info(
  File "/usr/local/lib/python3.9/site-packages/zigpy_znp/api.py", line 290, in write_network_info
    raise RuntimeError(
RuntimeError: Network formation refused, RF environment is likely too noisy. Temporarily unscrew the antenna or shield the coordinator with metal until a network is formed.
2021-12-26 18:59:29 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event component_loaded[L]: component=zha>
2021-12-26 19:03:48 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [548475923376] Received invalid command: zha/configuration
2021-12-26 19:12:13 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event lovelace_updated[L]: url_path=None>
2021-12-26 19:13:07 INFO (MainThread) [homeassistant.components.analytics] Submitted analytics to Home Assistant servers. Information submitted includes {'uuid': '9f0ee20ad0024ec3a95a646b510888ae', 'version': '2021.12.5', 'installation_type': 'Home Assistant OS', 'supervisor': {'healthy': True, 'supported': True, 'arch': 'aarch64'}, 'operating_system': {'board': 'rpi4-64', 'version': '7.0'}, 'integrations': ['dhcp', 'system_health', 'media_source', 'config', 'recorder', 'stream', 'updater', 'weather', 'binary_sensor', 'group', 'zha', 'history', 'map', 'timer', 'websocket_api', 'zone', 'input_boolean', 'default_config', 'tag', 'mobile_app', 'cloud', 'frontend', 'lovelace', 'my', 'search', 'onboarding', 'system_log', 'http', 'analytics', 'input_datetime', 'notify', 'trace', 'auth', 'image', 'network', 'automation', 'input_select', 'webhook', 'energy', 'logger', 'blueprint', 'tts', 'usb', 'ssdp', 'device_automation', 'counter', 'input_text', 'rpi_power', 'zeroconf', 'api', 'logbook', 'met', 'sun', 'scene', 'homeassistant', 'google_translate', 'persistent_notification', 'sensor', 'person', 'script', 'input_number', 'hassio'], 'custom_integrations': [], 'addons': [{'slug': 'core_zwave_js', 'protected': True, 'version': '0.1.50', 'auto_update': False}, {'slug': 'core_configurator', 'protected': True, 'version': '5.3.3', 'auto_update': False}], 'energy': {'configured': False}, 'state_count': 7, 'automation_count': 0, 'integration_count': 62, 'addon_count': 2, 'user_count': 1}

Additional information

No response

probot-home-assistant[bot] commented 2 years ago

Hey there @dmulcahey, @adminiuga, mind taking a look at this issue as it has been labeled with an integration (zha) you are listed as a code owner for? Thanks! (message by CodeOwnersMention)

zha documentation zha source (message by IssueLinks)

Adminiuga commented 2 years ago

This line caught my eye

raise RuntimeError(
RuntimeError: Network formation refused, RF environment is likely too noisy. Temporarily unscrew the antenna or shield the coordinator with metal until a network is formed.

Have you tried using an USB extension cable?

@puddly shouldn't this be propagated above?

puddly commented 2 years ago

shouldn't this be propagated above?

Do you mean logging it explicitly as an error message instead of just as part of traceback?

tassadar81 commented 2 years ago

This line caught my eye

raise RuntimeError(
RuntimeError: Network formation refused, RF environment is likely too noisy. Temporarily unscrew the antenna or shield the coordinator with metal until a network is formed.

Have you tried using an USB extension cable?

@puddly shouldn't this be propagated above?

Yes, it's connected with a 1 metre extension cable. but is this the problem? I can't get working the dongle itself not to scan for new devices

tassadar81 commented 2 years ago

I can get working know just configuring it manually and specifying the port and the rate, leaving the data flow control blank

puddly commented 2 years ago

zigpy-znp gives the stick 30s to form a network. Instead of forming a network, the stick locks up (likely because the network formation scan fails). It's an environment problem. While it works for now, I would suggest investigating why a network can't be formed because that same problem will likely prevent you from adding new devices and communicate effectively with the ones you manage to join.

Do you have it plugged into a USB 3.0 port? Near a 3.0 port? Near a SSD? A 2.4GHz WiFi router? Raspberry Pi? Another computer? Is it being powered from an external USB hub?

tassadar81 commented 2 years ago

It's plugged into a usb 2.0 port. now it's working and quite close to a WiFi router. I also was able to add two ikea bulb and to do some turn off/on roundtrip and change the light level. The adapter is attached into a rpi4 4gb ram booted from an SSD

Adminiuga commented 2 years ago

shouldn't this be propagated above?

Do you mean logging it explicitly as an error message instead of just as part of traceback?

No, i mean if the runtime exception is thrown, then there shouldn't be a timeout in request_cb_response? Alternatively, the timeout exception should be risen from the runtime exception

puddly commented 2 years ago

The runtime error is a result of a timeout: Z-Stack never sends a final response callback to the network formation command and the 30s timeout is triggered. There's no "failed" status indication, the RuntimeError is just adding some text to the otherwise unhelpful TimeoutError that happens when Z-Stack's internal formation scans fail.