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
73.43k stars 30.68k forks source link

Couldn't Start Deconz Coordinator #33651

Closed carlos-sarmiento closed 4 years ago

carlos-sarmiento commented 4 years ago

The problem

I'm having issues using a Conbee II stick to build a zigbee network using home assistant. The issue is intermitent and it tends to go away with a full reboot of the host machine. The log indicate a timeout error when trying to start the deconz coordinator on the home-assistant docker instance.

My docker setup is correct because the integration does work sometimes (the device is passed on correctly and if this error doesn't happen, everything works perfectly). I've tried removing the USB stick, making sure it has enough electric power (I have it connected to a powered USB hub but nothing makes the issue go away.

I've considered changing to another stick, but would rather avoid that unless strictly necessary.

Environment

Problem-relevant configuration.yaml

Configured through UI

Traceback/Error logs

2020-04-04 11:36:41 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for hacs which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant.
2020-04-04 11:36:41 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for garbage_collection which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant.
2020-04-04 11:36:41 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for nodered which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant.
2020-04-04 11:36:41 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for fontawesome which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant.
2020-04-04 11:36:46 ERROR (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start Deconz coordinator
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 142, in async_initialize
    res = await self.application_controller.startup(auto_form=True)
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/zigbee/application.py", line 45, in startup
    self.version = await self._api.version()
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/api.py", line 310, in version
    (self._proto_ver,) = await self[NetworkParameter.protocol_version]
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/api.py", line 280, in read_parameter
    r = await self._command(Command.read_parameter, 1 + len(data), param, data)
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/api.py", line 210, in _command
    return await asyncio.wait_for(fut, timeout=COMMAND_TIMEOUT)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 449, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError
2020-04-04 11:36:47 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 425, in _async_add_entity
    raise HomeAssistantError(msg)
homeassistant.exceptions.HomeAssistantError: Entity id already exists: sensor.keggerator_co2_pressure. Platform esphome does not generate unique IDs
2020-04-04 11:36:47 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 425, in _async_add_entity
    raise HomeAssistantError(msg)
homeassistant.exceptions.HomeAssistantError: Entity id already exists: sensor.keggerator_flow_meter. Platform esphome does not generate unique IDs
2020-04-04 11:36:47 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 425, in _async_add_entity
    raise HomeAssistantError(msg)
homeassistant.exceptions.HomeAssistantError: Entity id already exists: sensor.whole_house_energy_tde. Platform esphome does not generate unique IDs
2020-04-04 11:36:47 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 425, in _async_add_entity
    raise HomeAssistantError(msg)
homeassistant.exceptions.HomeAssistantError: Entity id already exists: sensor.whole_house_energy_total_mains_amps. Platform esphome does not generate unique IDs
2020-04-04 11:36:47 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 425, in _async_add_entity
    raise HomeAssistantError(msg)
homeassistant.exceptions.HomeAssistantError: Entity id already exists: sensor.whole_house_energy_mains_watts. Platform esphome does not generate unique IDs
2020-04-04 11:36:47 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 425, in _async_add_entity
    raise HomeAssistantError(msg)
homeassistant.exceptions.HomeAssistantError: Entity id already exists: sensor.whole_house_energy_mains_voltage. Platform esphome does not generate unique IDs
2020-04-04 11:36:47 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 425, in _async_add_entity
    raise HomeAssistantError(msg)
homeassistant.exceptions.HomeAssistantError: Entity id already exists: sensor.whole_house_energy_mains_a_amps. Platform esphome does not generate unique IDs
2020-04-04 11:36:47 ERROR (MainThread) [homeassistant.core] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 425, in _async_add_e2020-04-04 11:36:52 ERROR (SyncWorker_7) [homeassistant.components.uvc.camera] Authorization failure while connecting to NVR
2020-04-04 11:36:52 ERROR (MainThread) [homeassistant.components.sensor]2020-04-04 11:36:53 ERROR (SyncWorker_17) [homeassistant.components.uvc.camera] Authorization failure while connecting to NVR
2020-04-04 11:36:53 ERROR (MainThread) [homeassistant.components.sensor] octoprint: Error on device update!
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 312, in _async_add_entity
    await entity.async_device_update(warning=False)
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 476, in async_device_update
    await self.hass.async_add_executor_job(self.update)
  File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/src/homeassistant/homeassistant/components/octoprint/sensor.py", line 130, in update
    self.sensor_type, self.api_endpoint, self.api_group, self.api_tool
  File "/usr/src/homeassistant/homeassistant/components/octoprint/__init__.py", line 269, in update
    return get_value_from_json(response, sensor_type, group, tool)
  File "/usr/src/homeassistant/homeassistant/components/octoprint/__init__.py", line 284, in get_value_from_json
    if sensor_type in json_dict[group][tool]:
KeyError: 'tool1'
2020-04-04 11:36:53 ERROR (MainThread) [homeassistant.components.sensor] octoprint: Error on device update!
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 312, in _async_add_entity
    await entity.async_device_update(warning=False)
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 476, in async_device_update
    await self.hass.async_add_executor_job(self.update)
  File "/usr/local/lib/python3.7/concurrent/futures/thread.py", line 57, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/src/homeassistant/homeassistant/components/octoprint/sensor.py", line 130, in update
    self.sensor_type, self.api_endpoint, self.api_group, self.api_tool
  File "/usr/src/homeassistant/homeassistant/components/octoprint/__init__.py", line 269, in update
    return get_value_from_json(response, senso2020-04-04 11:36:56 ERROR (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start Deconz coordinator
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 142, in async_initialize
    res = await self.application_controller.startup(auto_form=True)
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/zigbee/application.py", line 46, in startup
    await self._api.device_state()
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/api.py", line 210, in _command
    return await asyncio.wait_for(fut, timeout=COMMAND_TIMEOUT)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 449, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError
2020-04-04 11:37:09 ERROR (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start Deconz coordinator
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 142, in async_initialize
    res = await self.application_controller.startup(auto_form=True)
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/zigbee/application.py", line 51, in startup
    await self._api[NetworkParameter.nwk_extended_panid]
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/api.py", line 280, in read_parameter
    r = await self._command(Command.read_parameter, 1 + len(data), param, data)
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/api.py", line 210, in _command
    return await asyncio.wait_for(fut, timeout=COMMAND_TIMEOUT)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 449, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError
2020-04-04 11:37:32 ERROR (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start Deconz coordinator
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 142, in async_initialize
    res = await self.application_controller.startup(auto_form=True)
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/zigbee/application.py", line 45, in startup
    self.version = await self._api.version()
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/api.py", line 310, in version
    (self._proto_ver,) = await self[NetworkParameter.protocol_version]
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/api.py", line 280, in read_parameter
    r = await self._command(Command.read_parameter, 1 + len(data), param, data)
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/api.py", line 210, in _command
    return await asyncio.wait_for(fut, timeout=COMMAND_TIMEOUT)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 449, in wait_for
  2020-04-04 11:37:32 ERROR (MainThread) [homeassistant.components.zha.2020-04-04 11:38:15 ERROR (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start Deconz coordinator
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 142, in async_initialize
    res = await self.application_controller.startup(auto_form=True)
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/zigbee/application.py", line 45, in startup
    self.version = await self._api.version()
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/api.py", line 311, in version
    version = await self._command(Command.version)
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/api.py", line 210, in _command
    return await asyncio.wait_for(fut, timeout=COMMAND_TIMEOUT)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 449, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError
l/lib/python3.7/asyncio/tasks.py", line 449, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError
2020-04-04 11:38:15 ERROR (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start Deconz coordinator
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 142, in async_initialize
    res = await self.application_controller.startup(auto_form=True)
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/zigbee/application.py", line 50, in startup
    await self._api[NetworkParameter.nwk_address]
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/api.py", line 280, in read_parameter
    r = await self._command(Command.read_parameter, 1 + len(data), param, data)
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/api.py", line 210, in _command
    return await asyncio.wait_for(fut, timeout=COMMAND_TIMEOUT)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 449, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError
2020-04-04 11:39:39 ERROR (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start Deconz coordinator
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 142, in async_initialize
    res = await self.application_controller.startup(auto_form=True)
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/zigbee/application.py", line 45, in startup
    self.version = await self._api.version()
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/api.py", line 310, in version
    (self._proto_ver,) = await self[NetworkParameter.protocol_version]
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/api.py", line 280, in read_parameter
    r = await self._command(Command.read_parameter, 1 + len(data), param, data)
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/api.py", line 210, in _command
    return await asyncio.wait_for(fut, timeout=COMMAND_TIMEOUT)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 449, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError
2020-04-04 11:41:02 ERROR (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start Deconz coordinator
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 142, in async_initialize
    res = await self.application_controller.startup(auto_form=True)
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/zigbee/application.py", line 45, in startup
    self.version = await self._api.version()
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/api.py", line 310, in version
    (self._proto_ver,) = await self[NetworkParameter.protocol_version]
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/api.py", line 280, in read_parameter
    r = await self._command(Command.read_parameter, 1 + len(data), param, data)
  File "/usr/local/lib/python3.7/site-packages/zigpy_deconz/api.py", line 210, in _command
    return await asyncio.wait_for(fut, timeout=COMMAND_TIMEOUT)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 449, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError

Additional information

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

Hey there @kane610, mind taking a look at this issue as its been labeled with a integration (deconz) you are listed as a codeowner for? Thanks!

Kane610 commented 4 years ago

This is ZHA not deconz

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

Hey there @dmulcahey, @adminiuga, mind taking a look at this issue as its been labeled with a integration (zha) you are listed as a codeowner for? Thanks!

Adminiuga commented 4 years ago

What is host os?

carlos-sarmiento commented 4 years ago

Host is Ubuntu 19.10, with the modem stuff removed.

carlos-sarmiento commented 4 years ago

Decided to try with a HUSBZB-1 stick I had laying around and got pretty much the same error:

2020-04-05 14:00:18 ERROR (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start EZSP coordinator
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 142, in async_initialize
    res = await self.application_controller.startup(auto_form=True)
  File "/usr/local/lib/python3.7/site-packages/bellows/zigbee/application.py", line 135, in startup
    await self.initialize()
  File "/usr/local/lib/python3.7/site-packages/bellows/zigbee/application.py", line 72, in initialize
    await e.reset()
  File "/usr/local/lib/python3.7/site-packages/bellows/ezsp.py", line 57, in reset
    await self._gw.reset()
  File "/usr/local/lib/python3.7/site-packages/bellows/uart.py", line 222, in reset
    return await asyncio.wait_for(self._reset_future, timeout=RESET_TIMEOUT)
  File "/usr/local/lib/python2020-04-05 14:00:24 ERROR (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start EZSP coordinator
Adminiuga commented 4 years ago

Does it start at all with husbzb-1? After it fails on restart, does it try to start again?

rubenvisscher commented 4 years ago

I've got the same issue with an Elelabs stick. After failing on reboot, it tries to start again after 80 seconds. 

2020-04-08 11:07:55 WARNING (MainThread) [homeassistant.config_entries] Config entry for zha not ready yet. Retrying in 80 seconds.
2020-04-08 11:09:21 ERROR (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start EZSP coordinator
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 149, in async_initialize
    res = await self.application_controller.startup(auto_form=True)
  File "/usr/local/lib/python3.7/site-packages/bellows/zigbee/application.py", line 137, in startup
    await self.initialize()
  File "/usr/local/lib/python3.7/site-packages/bellows/zigbee/application.py", line 74, in initialize
    await e.reset()
  File "/usr/local/lib/python3.7/site-packages/bellows/ezsp.py", line 79, in reset
    await self._gw.reset()
  File "/usr/local/lib/python3.7/site-packages/bellows/uart.py", line 220, in reset
    return await asyncio.wait_for(self._reset_future, timeout=RESET_TIMEOUT)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 449, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError

2020-04-08 11:09:21 WARNING (MainThread) [homeassistant.config_entries] Config entry for zha not ready yet. Retrying in 80 seconds.
2020-04-08 11:10:47 ERROR (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start EZSP coordinator
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 149, in async_initialize
    res = await self.application_controller.startup(auto_form=True)
  File "/usr/local/lib/python3.7/site-packages/bellows/zigbee/application.py", line 137, in startup
    await self.initialize()
  File "/usr/local/lib/python3.7/site-packages/bellows/zigbee/application.py", line 74, in initialize
    await e.reset()
  File "/usr/local/lib/python3.7/site-packages/bellows/ezsp.py", line 79, in reset
    await self._gw.reset()
  File "/usr/local/lib/python3.7/site-packages/bellows/uart.py", line 220, in reset
    return await asyncio.wait_for(self._reset_future, timeout=RESET_TIMEOUT)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 449, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError
2020-04-08 11:10:47 WARNING (MainThread) [homeassistant.config_entries] Config entry for zha not ready yet. Retrying in 80 seconds.
Adminiuga commented 4 years ago

it is failing on reboot or is it failing on restart? How did you configure it? what hardware and host os?

rubenvisscher commented 4 years ago

I'm running home-assistant in docker on a CentOS 7 host. This is my docker-compose: 

 homeassistant:
    container_name: home-assistant
    image: homeassistant/home-assistant:rc
    volumes:
      - /home/docker/homeassistant/config/:/config
      - /etc/localtime:/etc/localtime:ro
    environment:
      - TZ=Europe/Amsterdam
    ports:
      - 8123:8123
    devices:
      - /dev/ttyACM0:/dev/ttyACM0
      - /dev/ttyUSB0:/dev/ttyUSB0
    restart: always

ttyACM0 is a Z-Wave stick and ttyUSB0 is a Zigbee stick. This morning I updated to RC because in issue 32726 you said that there are some changes made in handeling port disconnects.

In the configuration.yaml I configured the ZHA component: 

zha:
  usb_path: /dev/ttyUSB0
  database_path: zigbee1.db

It is failing on both. I've tried to reboot the host, restart the docker container and did a restart via the home-assistant interface.

Adminiuga commented 4 years ago

Check elelabs documentation. They've changed the default baudrate. Add baudrate: 115200 to the zha config section in configuration.yaml.

https://elelabs.com/wp-content/uploads/2019/12/ELU012_UG_11_HomeAssistant.pdf

rubenvisscher commented 4 years ago

I'm getting the same error with baudrate: 115200. I've had the USB stick for two years and it has always worked with the default baud rate

Adminiuga commented 4 years ago

if it is an old stick, then leave the default baudrate, as I think they've changed it with newer sticks. can you try installing bellows-homeassistant in python venv on the host machine and run bellows -d /dev/ttyUSB0 info ?

rubenvisscher-topicus commented 4 years ago

The logging from bellows: 

/config # bellows -d /dev/ttyUSB0 info
Traceback (most recent call last):
  File "/usr/local/bin/bellows", line 8, in <module>
    sys.exit(main())
  File "/usr/local/lib/python3.7/site-packages/click/core.py", line 829, in __call__
    return self.main(*args, **kwargs)
  File "/usr/local/lib/python3.7/site-packages/click/core.py", line 782, in main
    rv = self.invoke(ctx)
  File "/usr/local/lib/python3.7/site-packages/click/core.py", line 1259, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/usr/local/lib/python3.7/site-packages/click/core.py", line 1066, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/usr/local/lib/python3.7/site-packages/click/core.py", line 610, in invoke
    return callback(*args, **kwargs)
  File "/usr/local/lib/python3.7/site-packages/click/decorators.py", line 21, in new_func
    return f(get_current_context(), *args, **kwargs)
  File "/usr/local/lib/python3.7/site-packages/bellows/cli/util.py", line 36, in inner
    loop.run_until_complete(f(*args, **kwargs))
  File "/usr/local/lib/python3.7/asyncio/base_events.py", line 587, in run_until_complete
    return future.result()
  File "/usr/local/lib/python3.7/site-packages/bellows/cli/ncp.py", line 66, in info
    s = await util.setup(ctx.obj["device"], ctx.obj["baudrate"])
  File "/usr/local/lib/python3.7/site-packages/bellows/cli/util.py", line 102, in setup
    await s.reset()
  File "/usr/local/lib/python3.7/site-packages/bellows/ezsp.py", line 79, in reset
    await self._gw.reset()
  File "/usr/local/lib/python3.7/site-packages/bellows/uart.py", line 220, in reset
    return await asyncio.wait_for(self._reset_future, timeout=RESET_TIMEOUT)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 449, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError
carlos-sarmiento commented 4 years ago

For everyone here, if you are using docker and a custom command to start home assistant, 0.107 adds a new init system that makes it so that you are effectively running two HA instances at the same time. This means you have two instances trying to connect to your ZHA devices which will definitely cause trouble. This seems to have been my issue and now it looks like it is fixed (after I removed the custom docker command).

For more details see #32992

Adminiuga commented 4 years ago

The logging from bellows: 

/config # bellows -d /dev/ttyUSB0 info
Traceback (most recent call last):
  ...
    return f(get_current_contex timeout=RESET_TIMEOUT)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 449, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError

The stick is not responding. Is ttyUSB0 the right port? Have you removed modem manager? What is in /dev/serial/by-id ?

dekimsey commented 4 years ago

edit: I have no idea what changed but its suddenly started working again. I've been fiddling with my configuration environment (after accidentally corrupting my home-assistant_v2.db trying to debug this, restored the database file from backup while hass was running).

I did make some changes to my jail to expose the cuaU0.init and cuaU0.lock devices, but I'm not sure if that's related. I've never needed to in the past and I'm enforcing any device settings in the host system.

original report

I'm seeing a similar issue (but with EZSP instead) after upgrading homeassistant from 0.104.3 to 0.108.2 with a HUSBZB-1 stick. I'm running on FreeBSD 12.1 i386. The ZHA component no longer works, the zwave(/dev/cuaU0) device on the same usb stick does work (confirmed with pyozw_check).

bellows-homeassistant==0.15.2
homeassistant==0.108.3
zigpy-cc==0.3.1
zigpy-deconz==0.8.0
zigpy-homeassistant==0.18.2
zigpy-xbee-homeassistant==0.11.0
zigpy-zigate==0.5.1

I've also tried the bellows command on the CLI to no effect. (Setting a baudrate of 57600 doesn't change the outcome).

$bellows -v debug -d /dev/cuaU1 info
debug: Using selector: KqueueSelector
debug: Using selector: KqueueSelector
debug: Connected. Resetting.
debug: Resetting EZSP
debug: Resetting ASH
debug: Sending: b'1ac038bc7e'
Traceback (most recent call last):
  File "/usr/home/hass/.hass-venv/bin/bellows", line 10, in <module>
    sys.exit(main())
  File "/usr/home/hass/.hass-venv/lib/python3.7/site-packages/click/core.py", line 764, in __call__
    return self.main(*args, **kwargs)
  File "/usr/home/hass/.hass-venv/lib/python3.7/site-packages/click/core.py", line 717, in main
    rv = self.invoke(ctx)
  File "/usr/home/hass/.hass-venv/lib/python3.7/site-packages/click/core.py", line 1137, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/usr/home/hass/.hass-venv/lib/python3.7/site-packages/click/core.py", line 956, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/usr/home/hass/.hass-venv/lib/python3.7/site-packages/click/core.py", line 555, in invoke
    return callback(*args, **kwargs)
  File "/usr/home/hass/.hass-venv/lib/python3.7/site-packages/click/decorators.py", line 17, in new_func
    return f(get_current_context(), *args, **kwargs)
  File "/usr/home/hass/.hass-venv/lib/python3.7/site-packages/bellows/cli/util.py", line 38, in inner
    loop.run_until_complete(f(*args, **kwargs))
  File "/usr/local/lib/python3.7/asyncio/base_events.py", line 583, in run_until_complete
    return future.result()
  File "/usr/home/hass/.hass-venv/lib/python3.7/site-packages/bellows/cli/ncp.py", line 66, in info
    s = await util.setup(ctx.obj["device"], ctx.obj["baudrate"])
  File "/usr/home/hass/.hass-venv/lib/python3.7/site-packages/bellows/cli/util.py", line 102, in setup
    await s.reset()
  File "/usr/home/hass/.hass-venv/lib/python3.7/site-packages/bellows/ezsp.py", line 57, in reset
    await self._gw.reset()
  File "/usr/home/hass/.hass-venv/lib/python3.7/site-packages/bellows/uart.py", line 222, in reset
    return await asyncio.wait_for(self._reset_future, timeout=RESET_TIMEOUT)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 449, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError

I have noticed some dmesg spam that seems new:

Set baudrate failed (ignored)

The following is the a logging excerpt show HASS trying to reset the coordinator but never succeeding (raising the TimeoutError).

2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.appdb] Loading application state from /home/hass/config/zigbee.db
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'Jasco Products'
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'45853'
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'Jasco Products'
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'45853'
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'Jasco Products'
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'45853'
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'45853'
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: Jasco Products
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Checking quirks for Jasco Products 45853 (00:22:a3:00:00:01:58:8d)
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'bellows.zigbee.application.EZSPCoordinator'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 2}
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.gledopto.soposhgu10.SoposhGU10'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {11, 13} {1, 2}
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.lutron.lzl4bwhl01remote.LutronLZL4BWHL01Remote2'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 2}
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.netvox.z308e3ed.Z308E3ED'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 2}
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.osram.a19twhite.A19TunableWhite'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {3} {1, 2}
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.philips.rom001.PhilipsROM001'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 2}
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.philips.rwl020.PhilipsRWL020'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because profile_id mismatch on at least one endpoint
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.philips.rwl021.PhilipsRWL021'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because profile_id mismatch on at least one endpoint
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.smartthings.multi.SmartthingsMultiPurposeSensor'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 2}
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.smartthings.tag_v4.SmartThingsTagV4'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 2}
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.xbee.xbee3_io.XBee3Sensor'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {232, 230} {1, 2}
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.xbee.xbee_io.XBeeSensor'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {232, 230} {1, 2}
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.xiaomi.mija.smoke.MijiaHoneywellSmokeDetectorSensor'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 2}
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Checking quirks for Jasco Products 45853 (00:22:a3:00:00:01:51:77)
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'bellows.zigbee.application.EZSPCoordinator'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 2}
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.gledopto.soposhgu10.SoposhGU10'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {11, 13} {1, 2}
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.lutron.lzl4bwhl01remote.LutronLZL4BWHL01Remote2'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 2}
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.netvox.z308e3ed.Z308E3ED'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 2}
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.osram.a19twhite.A19TunableWhite'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {3} {1, 2}
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.philips.rom001.PhilipsROM001'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 2}
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.philips.rwl020.PhilipsRWL020'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because profile_id mismatch on at least one endpoint
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.philips.rwl021.PhilipsRWL021'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because profile_id mismatch on at least one endpoint
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.smartthings.multi.SmartthingsMultiPurposeSensor'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 2}
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.smartthings.tag_v4.SmartThingsTagV4'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 2}
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.xbee.xbee3_io.XBee3Sensor'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {232, 230} {1, 2}
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.xbee.xbee_io.XBeeSensor'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {232, 230} {1, 2}
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.xiaomi.mija.smoke.MijiaHoneywellSmokeDetectorSensor'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 2}
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Checking quirks for None None (00:0d:6f:00:12:00:e3:5e)
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'bellows.zigbee.application.EZSPCoordinator'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.quirks.registry] Found custom device replacement for 00:0d:6f:00:12:00:e3:5e: <class 'bellows.zigbee.application.EZSPCoordinator'>
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'Jasco Products'
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'45853'
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'Jasco Products'
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'45853'
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: b'Jasco Products'
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'45853'
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.appdb] Attribute id: 5 value: b'45853'
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1024 value: 0
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.appdb] Attribute id: 4 value: Jasco Products
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.appdb] Attribute id: 1024 value: 224
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.appdb] Attribute id: 0 value: 1
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 1
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.appdb] Attribute id: 7 value: 1
2020-04-11 18:08:26 DEBUG (MainThread) [bellows.ezsp] Resetting EZSP
2020-04-11 18:08:26 DEBUG (bellows.thread_0) [bellows.uart] Resetting ASH
2020-04-11 18:08:26 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'1ac038bc7e'
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.ota] Initialize OTA providers
2020-04-11 18:08:26 DEBUG (MainThread) [zigpy.ota.provider] OTA image directory '/home/hass/config/zigpy_ota/' does not exist
2020-04-11 18:08:31 ERROR (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start EZSP coordinator
Traceback (most recent call last):
  File "/usr/home/hass/.hass-venv/lib/python3.7/site-packages/homeassistant/components/zha/core/gateway.py", line 152, in async_initialize
    res = await self.application_controller.startup(auto_form=True)
  File "/usr/home/hass/.hass-venv/lib/python3.7/site-packages/bellows/zigbee/application.py", line 137, in startup
    await self.initialize()
  File "/usr/home/hass/.hass-venv/lib/python3.7/site-packages/bellows/zigbee/application.py", line 74, in initialize
    await e.reset()
  File "/usr/home/hass/.hass-venv/lib/python3.7/site-packages/bellows/ezsp.py", line 79, in reset
    await self._gw.reset()
  File "/usr/home/hass/.hass-venv/lib/python3.7/site-packages/bellows/uart.py", line 220, in reset
    return await asyncio.wait_for(self._reset_future, timeout=RESET_TIMEOUT)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 449, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError
2020-04-11 18:08:31 WARNING (MainThread) [homeassistant.config_entries] Config entry for zha not ready yet. Retrying in 5 seconds.
2020-04-11 18:08:31 DEBUG (bellows.thread_0) [bellows.uart] Closed serial connection
arnefm commented 4 years ago

For everyone here, if you are using docker and a custom command to start home assistant, 0.107 adds a new init system that makes it so that you are effectively running two HA instances at the same time. This means you have two instances trying to connect to your ZHA devices which will definitely cause trouble. This seems to have been my issue and now it looks like it is fixed (after I removed the custom docker command).

For more details see #32992

I've been pulling my hair out over this issue for the past two weeks! Can't thank you enough!

Adminiuga commented 4 years ago

@dekimsey there was a similar report for FreeBSD that was fixed by un-plugging/plugging stick back 🤷

dekimsey commented 4 years ago

@Adminiuga so weird. I did try a reboot thinking the stick was in a bad state. But I did not ever reseat it. I don't think I did anything in trying to debug it that would have meaningfully changed the behavior.

Thank you for letting me know though. I'll keep that in mind if it happens again. To be honest it's been rock solid since I've installed it a year and a half ago or so.

carlos-sarmiento commented 4 years ago

Should we close this issue? Or is it still something going on?

50l3r commented 4 years ago

I have the same problem:

2020-04-28 13:48:36 WARNING (MainThread) [homeassistant.components.sensor] Platform rest not ready yet. Retrying in 180 seconds. 2020-04-28 13:48:36 ERROR (MainThread) [homeassistant.components.zha.core.gateway] Couldn't start EZSP coordinator Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/components/zha/core/gateway.py", line 152, in async_initialize res = await self.application_controller.startup(auto_form=True) File "/usr/local/lib/python3.7/site-packages/bellows/zigbee/application.py", line 137, in startup await self.initialize() File "/usr/local/lib/python3.7/site-packages/bellows/zigbee/application.py", line 74, in initialize await e.reset() File "/usr/local/lib/python3.7/site-packages/bellows/ezsp.py", line 79, in reset await self._gw.reset() File "/usr/local/lib/python3.7/site-packages/bellows/uart.py", line 220, in reset return await asyncio.wait_for(self._reset_future, timeout=RESET_TIMEOUT) File "/usr/local/lib/python3.7/asyncio/tasks.py", line 449, in wait_for raise futures.TimeoutError() concurrent.futures._base.TimeoutError 2020-04-28 13:48:36 WARNING (MainThread) [homeassistant.config_entries] Config entry for zha not ready yet. Retrying in 80 seconds.

I have an elelabs usb stick and this is my zha config:

usb_path: /dev/ttyUSB0 database_path: zigbee.db baudrate: 115200