"New entity_id is already in use" error when renaming any entity

tomlut commented 4 months ago

The problem

Whenever an entity is renamed via the UI it generates an error claiming the entity is already in use.

e.g.

Before: 38a22bd354f7b19e4dbf1dc3f5ccf04a930dd9f6_2_343x500

After (there was no sensor that ended in "foobar"): 86efcabc09ceb4a390f96093c42242aecb56aeb8_2_343x500

Result:

Logger: homeassistant.components.recorder.entity_registry
Source: components/recorder/entity_registry.py:72
integration: Recorder (documentation, issues)
First occurred: 13:44:44 (2 occurrences)
Last logged: 13:46:47

Cannot migrate history for entity_id `sensor.cinema_window_voltage` to `sensor.cinema_window_voltage_foobar` because the new entity_id is already in use

What version of Home Assistant Core has the issue?

core-2024.4.3

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

No response

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

home-assistant[bot] commented 4 months ago

Hey there @home-assistant/core, mind taking a look at this issue as it has been labeled with an integration (recorder) you are listed as a code owner for? Thanks!

Code owner commands

Code owners of `recorder` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign recorder` Removes the current integration label and assignees on the issue, add the integration domain after the command. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

_{^{(message by CodeOwnersMention)}}

recorder documentation recorder source _{^{(message by IssueLinks)}}

Krispkiwi commented 4 months ago

Also getting this.

tdejneka commented 4 months ago

I can confirm the warning message has appeared every time I have renamed an entity_id. In all cases, the new entity_id didn't already exist.

2024-04-15 16:56:59.486 WARNING (Recorder) [homeassistant.components.recorder.entity_registry] Cannot migrate history for entity_id calendar.family_anniversaries to calendar.family_anniversary because the new entity_id is already in use

rrooggiieerr commented 4 months ago

Maybe it's related to #115334 and #115411

polskikrol commented 2 months ago

I have the same issue on latest HA. Since zwave-js-ui doest grab and name/location during interview, I have to manually rename devices and lose past history with this error.

muddro1 commented 2 months ago

I am having the same issue on two instances. Not sure if related to using mariadb

catsmanac commented 2 months ago

Same here. New entity_id was not existing.

When checking statistices_meta table, the entity_id was updated and history is accessible.
When checking the states_meta table, a new entry is created with new metadata_id and the new entity_id. The existing entry was unaltered. So all state data is not attached to the new entity_id, nor visible anymore.

Logger: homeassistant.components.recorder.entity_registry
Source: components/recorder/entity_registry.py:76
integration: Recorder (documentation, issues)
First occurred: 4:35:37 PM (1 occurrences)
Last logged: 4:35:37 PM

Cannot migrate history for entity_id `sensor.envoy_122302045041_inverter_122219084557` to `sensor.inverter_122219084557` because the new entity_id is already in use

Tried twice in a dev environment, same issue in both cases.

This is the HA log file with recorder debug enabled. home-assistant_2024-07-03T14-38-53.562Z.log

Problem seems to be that components/recorder/entity_registry.py:76/update_states_metadata calls update_metadata which calls get which calls get_many which performs self._id_map.get(entity_id) for the new entity_id. By the time get_many executes, the _id_map already contains the new/updated entity_id and hence it's signaled as already existing. So we have a race condition on timing or some logic flaw that didn't realize the new id would be in the table already.

Stepped through it in dev debug and have screenshots if needed. Still finding when the new id gets inserted.

catsmanac commented 2 months ago

Similar to #114559 !?

catsmanac commented 2 months ago

Adding some debug log to the issue. Renaming sensor.inverter_482246047880 to sensor.inverter_482246047880_added leading to the Cannot migrate history error.

2024-07-07 14:46:43.284 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [140668635779216] 
Arie from 172.17.0.1 (Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:127.0) Gecko/20100101 Firefox/127.0): 
Received {'type': 'config/entity_registry/update', 
'entity_id': 'sensor.inverter_482246047880', 'name': None, 'icon': None, 'area_id': None, 'labels': [], 
'new_entity_id': 'sensor.inverter_482246047880_added', 'options_domain': 'sensor', 'options': {'display_precision': None}, 'id': 54}

2024-07-07 14:46:43.303 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event entity_registry_updated[L]: 
action=update, 
entity_id=sensor.inverter_482246047880_added, changes=entity_id=sensor.inverter_482246047880, 
old_entity_id=sensor.inverter_482246047880>

2024-07-07 14:46:43.339 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: 
entity_id=sensor.inverter_482246047880, 
old_state=<state sensor.inverter_482246047880=0; state_class=measurement, unit_of_measurement=W, device_class=power, icon=mdi:flash, friendly_name=Inverter 482246047880 @ 2024-07-07T16:43:24.116413+02:00>, 
new_state=None>

2024-07-07 14:46:43.352 DEBUG (Recorder) [homeassistant.components.recorder.core] Processing task: <Event state_changed[L]: 
entity_id=sensor.inverter_482246047880, 
old_state=<state sensor.inverter_482246047880=0; state_class=measurement, unit_of_measurement=W, device_class=power, icon=mdi:flash, friendly_name=Inverter 482246047880 @ 2024-07-07T16:43:24.116413+02:00>, 
new_state=None>

2024-07-07 14:46:43.376 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: 
entity_id=sensor.inverter_482246047880_added, 
old_state=None, 
new_state=<state sensor.inverter_482246047880_added=0; state_class=measurement, unit_of_measurement=W, device_class=power, icon=mdi:flash, friendly_name=Inverter 482246047880 @ 2024-07-07T16:46:43.372239+02:00>>

2024-07-07 14:46:43.384 DEBUG (Recorder) [homeassistant.components.recorder.core] 
Processing task: <Event state_changed[L]: entity_id=sensor.inverter_482246047880_added, 
old_state=None, 
new_state=<state sensor.inverter_482246047880_added=0; state_class=measurement, unit_of_measurement=W, device_class=power, icon=mdi:flash, friendly_name=Inverter 482246047880 @ 2024-07-07T16:46:43.372239+02:00>>

2024-07-07 14:46:43.398 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event entity_registry_updated[L]: 
action=update, entity_id=sensor.inverter_482246047880_added, changes=options=conversation=should_expose=False>

2024-07-07 14:46:43.400 DEBUG (Recorder) [homeassistant.components.recorder.pool.RecorderPool] Connection <sqlite3.Connection object at 0x7ff0384ec7c0> checked out from pool

2024-07-07 14:46:43.412 DEBUG (Recorder) [homeassistant.components.recorder.core] Processing task: UpdateStatisticsMetadataTask(
statistic_id='sensor.inverter_482246047880', new_statistic_id='sensor.inverter_482246047880_added', new_unit_of_measurement=<UndefinedType._singleton: 0>)

2024-07-07 14:46:43.459 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_reported[L]: 
entity_id=sensor.inverter_482246047880_added, old_last_reported=2024-07-07T16:46:43.372239+02:00, 
new_state=<state sensor.inverter_482246047880_added=0; state_class=measurement, unit_of_measurement=W, device_class=power, icon=mdi:flash, friendly_name=Inverter 482246047880 @ 2024-07-07T16:46:43.372239+02:00>>

2024-07-07 14:46:43.547 DEBUG (Recorder) [homeassistant.components.recorder.core] Processing task: UpdateStatesMetadataTask(
entity_id='sensor.inverter_482246047880', new_entity_id='sensor.inverter_482246047880_added')

2024-07-07 14:46:43.553 WARNING (Recorder) [homeassistant.components.recorder.entity_registry] 
Cannot migrate history for entity_id `sensor.inverter_482246047880` to `sensor.inverter_482246047880_added` because the new entity_id is already in use

2024-07-07 14:46:43.553 DEBUG (Recorder) [homeassistant.components.recorder.core] Processing task: <Event entity_registry_updated[L]: 
action=update, entity_id=sensor.inverter_482246047880_added, changes=entity_id=sensor.inverter_482246047880, old_entity_id=sensor.inverter_482246047880>

YannickvanVugt commented 2 months ago

@bdraco Thanks for your work on this integration, as we already found out it started after the 2024.4 release, so this might be in the ballpark where you're looking for: https://github.com/home-assistant/core/commits/c84fe04d6bea6c265781a25ef199a21b9e828243/homeassistant/components/recorder/entity_registry.py

Do you have any idea when this will be fixed? It has become quite a major feature in my opinion, especially with the long-term statistics and such.

rrooggiieerr commented 2 months ago

https://github.com/home-assistant/core/issues/114559 is also related and there core-2024.3.3 was used

polskikrol commented 2 months ago

Believe some work is needed here in general. Making sure renaming properly carries over history/logs. Additionally, the ability to merge device data. If you replace a sensor, and don’t give two hoots about the ID or keeping separate logs or history and want to merge the data, there should be an option. These items may go hand in hand and improvements are needed in this database specific realm.

On Thu, Jul 11, 2024 at 23:44 rrooggiieerr @.***> wrote:

114559 https://github.com/home-assistant/core/issues/114559 is also

related and there core-2024.3.3 was used

— Reply to this email directly, view it on GitHub https://github.com/home-assistant/core/issues/115747#issuecomment-2224374855, or unsubscribe https://github.com/notifications/unsubscribe-auth/AKAGRDFOHHYZ6VAAZHFSPNTZL5GI3AVCNFSM6AAAAABGK4W5BOVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDEMRUGM3TIOBVGU . You are receiving this because you commented.Message ID: @.***>

YannickvanVugt commented 2 months ago

@polskikrol Let's don't get off track here, merging data is a whole other topic. If this issue is fixed you can replace a device, give it the old entity id and data capture will pick up where it left off. Then, if you didn't use a certain entity ID before and change it to that new ID, it will hold the history data.

catsmanac commented 3 weeks ago

As I needed entity rename for an integration device replacement I tried it again on 2024.9.0.dev202408170220.

2024-08-18 14:08:00.440 WARNING (Recorder) [homeassistant.components.recorder.entity_registry] Cannot migrate history for entity_id `sensor.envoy_123456789003_current_power_production` to `sensor.envoy_123456789004_current_power_production` because the new entity_id is already in use

Looking into the states table I see new entity-id is added and takes over state logging, but old entity-id states are not transferred, i.e. old entity_id is not renamed. As mentioned in the log entry, something inserted the new entity-id in state-meta and the recorder found it there already and held back renaming existing entries or so. Entity-id change was at 14:08

afbeelding

Event data:

{
"action":"update",
"entity_id":"sensor.envoy_123456789004_current_power_production",
"changes":{"entity_id":"sensor.envoy_123456789003_current_power_production"},
"old_entity_id":"sensor.envoy_123456789003_current_power_production"
}

{
"action":"update",
"entity_id":"sensor.envoy_123456789004_current_power_production",
"changes":{"options":{"sensor.private":{"suggested_unit_of_measurement":"kW"},
"sensor":{"suggested_display_precision":3},
"conversation":{"should_expose":false}}}
}

Entries in state table

afbeelding

Entries in statistic_short_term table. Here entity-id was updated in the meta.

afbeelding

catsmanac commented 3 weeks ago

Did some more testing to determine what is going on.

observations

changing entity-id sensor.envoy_123456789006_lifetime_energy_production to sensor.envoy_123456789005_lifetime_energy_production
log entries of recorder/sqlalchemy debug modes (lines starting with >>)
Mariadb log entries from GLOBAL general_log ON (lines marked <<)
my comments in lines starting with --
HA docker and mariadb docker running in same docker environment so timestamps will be the same or close.
mariadb log timestamps are rounded to the second, merged these into HA log after the sqlalchemy log entries
the log file: entity_rename_sqllog.txt
The whole sequence starts with the recorder core processing 2 events Event state_changed[L], one for the old entity-id and one for the new entity-id.
- Event for the old entity-id new state to none
- Event for new entity-id state from none to data of old entity-id
the state_meta table is checked for existence of the new entity-id, which is not found
recorder core reports Processing task: UpdateStatisticsMetadataTask
a query to insert the new entity-id into the states_meta is executed resulting in the addition of the new entity-id
successful update of statistics_meta entry takes place
recorder core reports Processing task: UpdateStatesMetadataTask
this fails with Cannot migrate history for entity_id ... because the new entity_id is already in use

Analysis

the Event state_changed[L] for the new entity-id results in creating the new entity-id in states_meta
by the time the UpdateStatesMetadataTask executes the new entity-id is found and state history migration is abandoned because of this.
statistics_meta entry is successfully updated to new entity-id.

What is happening seems obvious, why not though. Did something change in timing with code changes over time, some race condition introduced.

Only state data/history is impacted. Statistics and statistics_short_term as the statistics_meta entry update works fine.

EDIT1: version 2024.3.1 shows same issue, behavior and sequence of events/tasks

EDIT2: Before 202403.0 other query error occur. Not testing older versions.

home-assistant / core