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.61k stars 30.77k forks source link

Turn of polling creates error on duplicate unique_id #73400

Closed gjohansson-ST closed 2 years ago

gjohansson-ST commented 2 years ago

The problem

Not entirely sure where the problem is but if you for a config entry turn off polling it tries to create entities twice and thereby complaining about not unique id. Therefore services such as update_entity does not work any longer

2022-06-12 17:58:08 DEBUG (SyncWorker_2) [homeassistant.components.sql.config_flow] Return value from query: 8512
2022-06-12 17:58:08 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.sql
2022-06-12 17:58:08 DEBUG (SyncWorker_0) [homeassistant.components.sql.sensor] Query select count(*) as states from states LIMIT 1; result in ROMappingView({'states': 8512})
2022-06-12 17:58:08 INFO (MainThread) [homeassistant.helpers.entity_registry] Registered new sensor.sql entity: sensor.select_sql_query

Turn off polling from config entry system options

2022-06-12 17:58:25 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.sql
2022-06-12 17:58:25 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.sql
2022-06-12 17:58:25 DEBUG (SyncWorker_3) [homeassistant.components.sql.sensor] Query select count(*) as states from states LIMIT 1; result in ROMappingView({'states': 8513})
2022-06-12 17:58:25 DEBUG (SyncWorker_1) [homeassistant.components.sql.sensor] Query select count(*) as states from states LIMIT 1; result in ROMappingView({'states': 8513})
2022-06-12 17:58:25 ERROR (MainThread) [homeassistant.components.sensor] Platform sql does not generate unique IDs. ID 23adb940c442279b96d879dfcf03c9bb already exists - ignoring sensor.select_sql_query

What version of Home Assistant Core has the issue?

dev

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Core

Integration causing the issue

core

Link to integration documentation on our website

No response

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

No response

gjohansson-ST commented 2 years ago

Tried to figure out which function was doing something but didn't so far...

bdraco commented 2 years ago

Does this happen on dev after #73387 or only in 2022.6/pre dev?

gjohansson-ST commented 2 years ago

Let me try it again as I'm not sure if my testing was before or after merging of the linked PR.

gjohansson-ST commented 2 years ago

I rebased my dev now with all the last changes and verified the commit from #73387 is included. Still same outcome.

bdraco commented 2 years ago

I can replicate this problem. It happens when switching off polling but seems fine after a restart. Is that what you are seeing as well?

bdraco commented 2 years ago 
entry_id: "374f06d20134f0d14ef428aa63c98217"
id: 34
pref_disable_new_entities: false
pref_disable_polling: false
type: "config_entries/update"

Seems to be a problem with this config api

bdraco commented 2 years ago

So I think whats happening is the entry is updated here

https://github.com/home-assistant/core/blob/a77ea1c39003d2be959c8e73fc8f4e7521a09e84/homeassistant/components/config/config_entries.py#L332

Then the reload listener fires and reloads https://github.com/home-assistant/core/blob/a77ea1c39003d2be959c8e73fc8f4e7521a09e84/homeassistant/components/sql/__init__.py#L12

And config also reloads https://github.com/home-assistant/core/blob/a77ea1c39003d2be959c8e73fc8f4e7521a09e84/homeassistant/components/config/config_entries.py#L343

bdraco commented 2 years ago

So its yet another reload race 😢

bdraco commented 2 years ago 
2022-06-14 21:49:11 WARNING (MainThread) [homeassistant.config_entries] finished unload of DB Size -- sensor
2022-06-14 21:49:11 WARNING (MainThread) [homeassistant.config_entries] finished unload of DB Size -- sql
2022-06-14 21:49:11 WARNING (MainThread) [homeassistant.config_entries] Set unload of DB Size to ConfigEntryState.NOT_LOADED -- sql
2022-06-14 21:49:11 WARNING (MainThread) [homeassistant.config_entries] async_forward_entry_setup: ConfigEntryState.LOADED
2022-06-14 21:49:11 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.sql
2022-06-14 21:49:11 WARNING (MainThread) [homeassistant.components.sql.sensor] called async_add_entities
2022-06-14 21:49:11 WARNING (MainThread) [homeassistant.config_entries] finished unload of DB Size -- sensor
2022-06-14 21:49:11 WARNING (MainThread) [homeassistant.config_entries] finished unload of DB Size -- sql
2022-06-14 21:49:11 WARNING (MainThread) [homeassistant.config_entries] Set unload of DB Size to ConfigEntryState.NOT_LOADED -- sql
2022-06-14 21:49:11 WARNING (MainThread) [homeassistant.config_entries] async_forward_entry_setup: ConfigEntryState.LOADED
2022-06-14 21:49:11 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.sql
2022-06-14 21:49:11 WARNING (MainThread) [homeassistant.components.sql.sensor] called async_add_entities
2022-06-14 21:49:11 ERROR (MainThread) [homeassistant.components.sensor] Platform sql does not generate unique IDs. ID 374f06d20134f0d14ef428aa63c98217 already exists - ignoring sensor.db_size
bdraco commented 2 years ago

So the entity is still updating from the first reload when the second reload starts happening

2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.config_entries] finished unload of DB Size -- sensor
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.config_entries] finished unload of DB Size -- sql
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.config_entries] Set unload of DB Size to ConfigEntryState.NOT_LOADED -- sql
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.config_entries] async_forward_entry_setup: ConfigEntryState.LOADED
2022-06-14 22:15:17 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.sql
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.components.sql.sensor] called async_add_entities
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.config_entries] finished unload of DB Size -- sensor
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.helpers.entity_platform] _async_add_entity: <Entity DB Size> -- entry_state: ConfigEntryState.LOADED
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.helpers.entity_platform] _async_add_entity finished add_to_platform_start: <Entity DB Size: None> -- entry_state: ConfigEntryState.LOADED
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.helpers.entity_platform] _async_add_entity calling update_before_add: <Entity DB Size: None> -- entry_state: ConfigEntryState.LOADED
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.config_entries] finished unload of DB Size -- sql
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.config_entries] Set unload of DB Size to ConfigEntryState.NOT_LOADED -- sql
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.config_entries] async_forward_entry_setup: ConfigEntryState.LOADED
2022-06-14 22:15:17 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.sql
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.helpers.entity_platform] _async_add_entity finished update_before_add: <Entity DB Size: 540049408> -- entry_state: ConfigEntryState.LOADED
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.helpers.entity_platform] _async_add_entity finished registry check: <Entity DB Size: 540049408> -- entry_state: ConfigEntryState.LOADED
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.helpers.entity_platform] _async_add_entity finished Generate entity ID: <Entity DB Size: 540049408> -- entry_state: ConfigEntryState.LOADED
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.helpers.entity_platform] _async_add_entity finished valid_entity_id: <Entity DB Size: 540049408> -- entry_state: ConfigEntryState.LOADED
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.helpers.entity_platform] last chance _async_add_entity: <Entity DB Size: 540049408> -- entry_state: ConfigEntryState.LOADED
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.components.sql.sensor] called async_add_entities
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.helpers.entity_platform] _async_add_entity: <Entity DB Size> -- entry_state: ConfigEntryState.LOADED
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.helpers.entity_platform] _async_add_entity finished add_to_platform_start: <Entity DB Size: None> -- entry_state: ConfigEntryState.LOADED
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.helpers.entity_platform] _async_add_entity calling update_before_add: <Entity DB Size: None> -- entry_state: ConfigEntryState.LOADED
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.helpers.entity_platform] _async_add_entity finished update_before_add: <Entity DB Size: 540049408> -- entry_state: ConfigEntryState.LOADED
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.helpers.entity_platform] _async_add_entity finished registry check: <Entity DB Size: 540049408> -- entry_state: ConfigEntryState.LOADED
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.helpers.entity_platform] _async_add_entity finished Generate entity ID: <Entity DB Size: 540049408> -- entry_state: ConfigEntryState.LOADED
2022-06-14 22:15:17 WARNING (MainThread) [homeassistant.helpers.entity_platform] _async_add_entity finished valid_entity_id: <Entity DB Size: 540049408> -- entry_state: ConfigEntryState.LOADED
2022-06-14 22:15:17 ERROR (MainThread) [homeassistant.components.sensor] Platform sql does not generate unique IDs. ID 374f06d20134f0d14ef428aa63c98217 already exists - ignoring sensor.db_size
bdraco commented 2 years ago

Maybe we need some type of reload debouncer

bdraco commented 2 years ago

I can't think of any other way to solve this

bdraco commented 2 years ago

At least some type of guard to prevent reloading more than once every 10-20s as thats unlikely to ever end up with a good result

gjohansson-ST commented 2 years ago

I can replicate this problem. It happens when switching off polling but seems fine after a restart. Is that what you are seeing as well?

Yepp. Seems also some guard should be in place here so check if a reload is already happening in one way or another.

bdraco commented 2 years ago

The problem is the reload is done at that point as reloads are already done under a lock. The entity is still setting up from the previous reload which happens in a task which happens asynchronously and is is not awaited from to the config entry setup.

bdraco commented 2 years ago

https://github.com/home-assistant/core/blob/4ace2c4d3ad92860dab5036f15197d5578d0352e/homeassistant/config_entries.py#L1022

bdraco commented 2 years ago

Candidates to fix this are the debouncer we use in the coordinator and the ratelimiter we use for templates

Most of the UI messages say entities will appear in 30s so that seems like the right cooldown period

We want these to fire immediately and then cool down for 30s before allowing another reload