core-2024.4.0b0, HAOS 12.2.rc1 VM with USB Bluetooth, rest is irrelevant :innocent:
Checklist
[X] I have enabled debug logging for my installation.
[X] I have filled out the issue template to the best of my ability.
[X] This issue only contains 1 issue (if you have multiple issues, open one issue for each issue).
[X] This issue is not a duplicate issue of currently previous issues..
Describe the issue
Changes in HAOS 2024.4 triggered a race condition, when the poll method of NukiDataUpdateCoordinator gets called earlier than its async_wait_ready(). This causes early return from the await in async_setup_entry, ultimately leading to initialization of integration's platforms too early.
For better understanding, here's a traceback printed from NukiDataUpdateCoordinator._async_update:
2024-03-28 10:39:19.651 INFO (MainThread) [pyNukiBT.nuki] Nuki: 54:D2:72:D8:BC:FC, RSSI: -72
File "<frozen runpy>", line 198, in _run_module_as_main
File "<frozen runpy>", line 88, in _run_code
File "/usr/src/homeassistant/homeassistant/__main__.py", line 222, in <module>
sys.exit(main())
File "/usr/src/homeassistant/homeassistant/__main__.py", line 210, in main
exit_code = runner.run(runtime_conf)
File "/usr/src/homeassistant/homeassistant/runner.py", line 189, in run
return loop.run_until_complete(setup_and_run_hass(runtime_config))
File "/usr/local/lib/python3.12/asyncio/base_events.py", line 672, in run_until_complete
self.run_forever()
File "/usr/local/lib/python3.12/asyncio/base_events.py", line 639, in run_forever
self._run_once()
File "/usr/local/lib/python3.12/asyncio/base_events.py", line 1988, in _run_once
handle._run()
File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
self._context.run(self._callback, *self._args)
File "/usr/src/homeassistant/homeassistant/setup.py", line 165, in async_setup_component
result = await _async_setup_component(hass, domain, config)
File "/usr/src/homeassistant/homeassistant/setup.py", line 444, in _async_setup_component
await asyncio.gather(
File "/usr/src/homeassistant/homeassistant/setup.py", line 446, in <genexpr>
create_eager_task(
File "/usr/src/homeassistant/homeassistant/util/async_.py", line 33, in create_eager_task
return Task(
File "/usr/src/homeassistant/homeassistant/config_entries.py", line 551, in async_setup
result = await component.async_setup_entry(hass, self)
File "/config/custom_components/hass_nuki_bt/__init__.py", line 85, in async_setup_entry
entry.async_on_unload(coordinator.async_start())
File "/usr/src/homeassistant/homeassistant/components/bluetooth/update_coordinator.py", line 52, in async_start
self._async_start()
File "/config/custom_components/hass_nuki_bt/coordinator.py", line 70, in _async_start
return super()._async_start()
File "/usr/src/homeassistant/homeassistant/components/bluetooth/update_coordinator.py", line 95, in _async_start
async_register_callback(
File "/usr/src/homeassistant/homeassistant/components/bluetooth/api.py", line 130, in async_register_callback
return _get_manager(hass).async_register_callback(callback, match_dict)
File "/usr/src/homeassistant/homeassistant/components/bluetooth/manager.py", line 187, in async_register_callback
callback(service_info, BluetoothChange.ADVERTISEMENT)
File "/config/custom_components/hass_nuki_bt/coordinator.py", line 146, in _async_handle_bluetooth_event
super()._async_handle_bluetooth_event(service_info, change)
File "/usr/src/homeassistant/homeassistant/components/bluetooth/active_update_coordinator.py", line 173, in _async_handle_bluetooth_event
self._debounced_poll.async_schedule_call()
File "/usr/src/homeassistant/homeassistant/helpers/debounce.py", line 72, in async_schedule_call
self._on_debounce()
File "/usr/src/homeassistant/homeassistant/helpers/debounce.py", line 175, in _on_debounce
self.hass.async_create_background_task(
File "/usr/src/homeassistant/homeassistant/core.py", line 760, in async_create_background_task
task = create_eager_task(target, name=name, loop=self.loop)
File "/usr/src/homeassistant/homeassistant/util/async_.py", line 33, in create_eager_task
return Task(
File "/usr/src/homeassistant/homeassistant/helpers/debounce.py", line 137, in _handle_timer_finish
if task := self.hass.async_run_hass_job(
File "/usr/src/homeassistant/homeassistant/core.py", line 836, in async_run_hass_job
return self.async_add_hass_job(
File "/usr/src/homeassistant/homeassistant/core.py", line 679, in async_add_hass_job
task = create_eager_task(
File "/usr/src/homeassistant/homeassistant/util/async_.py", line 33, in create_eager_task
return Task(
File "/usr/src/homeassistant/homeassistant/components/bluetooth/active_update_coordinator.py", line 131, in _async_poll
self.data = await self._async_poll_data(self._last_service_info)
File "/usr/src/homeassistant/homeassistant/components/bluetooth/active_update_coordinator.py", line 124, in _async_poll_data
return await self._poll_method(last_service_info)
File "/config/custom_components/hass_nuki_bt/coordinator.py", line 111, in _async_update
traceback.print_stack()
2024-03-28 10:39:19.656 INFO (MainThread) [pyNukiBT.nuki] Querying Nuki state
File "<frozen runpy>", line 198, in _run_module_as_main
File "<frozen runpy>", line 88, in _run_code
File "/usr/src/homeassistant/homeassistant/__main__.py", line 222, in <module>
sys.exit(main())
File "/usr/src/homeassistant/homeassistant/__main__.py", line 210, in main
exit_code = runner.run(runtime_conf)
File "/usr/src/homeassistant/homeassistant/runner.py", line 189, in run
return loop.run_until_complete(setup_and_run_hass(runtime_config))
File "/usr/local/lib/python3.12/asyncio/base_events.py", line 672, in run_until_complete
self.run_forever()
File "/usr/local/lib/python3.12/asyncio/base_events.py", line 639, in run_forever
self._run_once()
File "/usr/local/lib/python3.12/asyncio/base_events.py", line 1988, in _run_once
handle._run()
File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
self._context.run(self._callback, *self._args)
File "/usr/src/homeassistant/homeassistant/setup.py", line 165, in async_setup_component
result = await _async_setup_component(hass, domain, config)
File "/usr/src/homeassistant/homeassistant/setup.py", line 444, in _async_setup_component
await asyncio.gather(
File "/usr/src/homeassistant/homeassistant/setup.py", line 446, in <genexpr>
create_eager_task(
File "/usr/src/homeassistant/homeassistant/util/async_.py", line 33, in create_eager_task
return Task(
File "/usr/src/homeassistant/homeassistant/config_entries.py", line 551, in async_setup
result = await component.async_setup_entry(hass, self)
File "/config/custom_components/hass_nuki_bt/__init__.py", line 87, in async_setup_entry
if not await coordinator.async_wait_ready():
File "/config/custom_components/hass_nuki_bt/coordinator.py", line 153, in async_wait_ready
await self._async_update()
File "/config/custom_components/hass_nuki_bt/coordinator.py", line 111, in _async_update
traceback.print_stack()
Reproduction steps
Update to HA 2024.4+
The integration initializes but all entities are unavailable
Debug logs
2024-03-28 13:47:50.770 INFO (MainThread) [homeassistant.setup] Setting up hass_nuki_bt
2024-03-28 13:47:50.770 INFO (MainThread) [homeassistant.setup] Setup of domain hass_nuki_bt took 0.00 seconds
2024-03-28 13:47:50.773 INFO (MainThread) [pyNukiBT.nuki] Nuki: 54:D2:72:D8:BC:FC, RSSI: -73
2024-03-28 13:47:50.773 INFO (MainThread) [pyNukiBT.nuki] Querying Nuki state
2024-03-28 13:47:50.788 INFO (MainThread) [pyNukiBT.nuki] Querying Nuki state
2024-03-28 13:47:50.788 INFO (MainThread) [pyNukiBT.nuki] update state already in progress. ignoring
2024-03-28 13:47:50.815 INFO (MainThread) [homeassistant.setup] Setting up ibeacon
2024-03-28 13:47:50.815 INFO (MainThread) [homeassistant.setup] Setup of domain ibeacon took 0.00 seconds
2024-03-28 13:47:50.829 INFO (MainThread) [homeassistant.setup] Setting up bthome
2024-03-28 13:47:50.829 INFO (MainThread) [homeassistant.setup] Setup of domain bthome took 0.00 seconds
2024-03-28 13:47:51.522 INFO (MainThread) [homeassistant.setup] Setting up homekit_controller
2024-03-28 13:47:51.528 INFO (MainThread) [homeassistant.setup] Setup of domain homekit_controller took 0.01 seconds
2024-03-28 13:47:51.533 INFO (MainThread) [homeassistant.setup] Setting up rapt_ble
2024-03-28 13:47:51.533 INFO (MainThread) [homeassistant.setup] Setup of domain rapt_ble took 0.00 seconds
2024-03-28 13:47:51.548 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up hass_nuki_bt.binary_sensor
2024-03-28 13:47:51.549 ERROR (MainThread) [homeassistant.components.binary_sensor] Error while setting up hass_nuki_bt platform for binary_sensor
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 356, in _async_setup_platform
await asyncio.shield(awaitable)
File "/config/custom_components/hass_nuki_bt/binary_sensor.py", line 65, in async_setup_entry
entities = [NukiBinarySensor(coordinator, sensor) for sensor in SENSOR_TYPES]
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/config/custom_components/hass_nuki_bt/binary_sensor.py", line 75, in __init__
super().__init__(coordinator)
File "/config/custom_components/hass_nuki_bt/entity.py", line 42, in __init__
str(x) for x in coordinator.device.config["hardware_revision"]
~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^
KeyError: 'hardware_revision'
2024-03-28 13:47:51.554 INFO (MainThread) [homeassistant.components.lock] Setting up hass_nuki_bt.lock
2024-03-28 13:47:51.554 ERROR (MainThread) [homeassistant.components.lock] Error while setting up hass_nuki_bt platform for lock
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 356, in _async_setup_platform
await asyncio.shield(awaitable)
File "/config/custom_components/hass_nuki_bt/lock.py", line 23, in async_setup_entry
async_add_entities([NukiLock(coordinator)])
^^^^^^^^^^^^^^^^^^^^^
File "/config/custom_components/hass_nuki_bt/lock.py", line 33, in __init__
super().__init__(coordinator)
File "/config/custom_components/hass_nuki_bt/entity.py", line 42, in __init__
str(x) for x in coordinator.device.config["hardware_revision"]
~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^
KeyError: 'hardware_revision'
2024-03-28 13:47:51.556 INFO (MainThread) [homeassistant.components.sensor] Setting up hass_nuki_bt.sensor
2024-03-28 13:47:51.557 ERROR (MainThread) [homeassistant.components.sensor] Error while setting up hass_nuki_bt platform for sensor
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 356, in _async_setup_platform
await asyncio.shield(awaitable)
File "/config/custom_components/hass_nuki_bt/sensor.py", line 116, in async_setup_entry
entities = [NukiSensor(coordinator, sensor) for sensor in SENSOR_TYPES]
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/config/custom_components/hass_nuki_bt/sensor.py", line 125, in __init__
super().__init__(coordinator)
File "/config/custom_components/hass_nuki_bt/entity.py", line 42, in __init__
str(x) for x in coordinator.device.config["hardware_revision"]
~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^
KeyError: 'hardware_revision'
2024-03-28 13:47:51.558 INFO (MainThread) [homeassistant.components.button] Setting up hass_nuki_bt.button
2024-03-28 13:47:51.558 ERROR (MainThread) [homeassistant.components.button] Error while setting up hass_nuki_bt platform for button
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/entity_platform.py", line 356, in _async_setup_platform
await asyncio.shield(awaitable)
File "/config/custom_components/hass_nuki_bt/button.py", line 46, in async_setup_entry
async_add_entities([NukiButton(coordinator, btn) for btn in BUTTON_TYPES])
^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/config/custom_components/hass_nuki_bt/button.py", line 58, in __init__
super().__init__(coordinator)
File "/config/custom_components/hass_nuki_bt/entity.py", line 42, in __init__
str(x) for x in coordinator.device.config["hardware_revision"]
~~~~~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^^^^^^^^
KeyError: 'hardware_revision'
System Health details
core-2024.4.0b0, HAOS 12.2.rc1 VM with USB Bluetooth, rest is irrelevant :innocent:
Checklist
Describe the issue
Changes in HAOS 2024.4 triggered a race condition, when the poll method of
NukiDataUpdateCoordinator
gets called earlier than itsasync_wait_ready()
. This causes early return from the await inasync_setup_entry
, ultimately leading to initialization of integration's platforms too early.For better understanding, here's a traceback printed from
NukiDataUpdateCoordinator._async_update
:Reproduction steps
Debug logs
Diagnostics dump
No response