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.44k stars 30.67k forks source link

Recorder database migration to schema 23 fails #63386

Closed mstovenour closed 2 years ago

mstovenour commented 2 years ago

The problem

Every time I start home assistant core I receive a traceback indicating an error with a column name that already exists while performing schema migration for recorder. I see that there was a previous issue reported #60488 like this one which includes a fix that I have. However in reviewing both my traceback and the traceback of the previous issue it seems that the provided fix was not complete. There are two try/except blocks and, while the error will happen in both places, it happens first at line 200 which you can see from both my traceback below and the traceback in issue #60488.

I tried some simple things to catch / ignore that error in the first ALTER however I ran into issues with the overall transaction rollback. I'm not sure exactly how to fix the issue. I think that multi-table ALTER at line 200 needs to be wrapped in its own transaction so the error handler can roll it back. Also, this particular error is caught by neither InternalError nor OperationalError. I had to add a generic "except Exception as err:" handler to catch this error.

I then tried commenting out the entire first ALTER and changing the second exception handler to "except Exception as err:". This also did not work because the failed ALTER left the transaction in a bad state. After adding a nested transaction, the migration was able to complete. I use PostgreSQL; don't know if all the supported databases allow nested transactions so this might not be a good long term solution. I also think that something like this could wrap the first ALTER but I didn't try that.

Below is the hack I used to get the database migrated:

diff --git a/homeassistant/components/recorder/migration.py b/homeassistant/components/recorder/migration.py
index 2e6e5a7bd1..1de58459c7 100644
--- a/homeassistant/components/recorder/migration.py
+++ b/homeassistant/components/recorder/migration.py
@@ -196,30 +196,31 @@ def _add_columns(connection, table_name, columns_def):

     columns_def = [f"ADD {col_def}" for col_def in columns_def]

-    try:
-        connection.execute(
-            text(
-                "ALTER TABLE {table} {columns_def}".format(
-                    table=table_name, columns_def=", ".join(columns_def)
-                )
-            )
-        )
-        return
-    except (InternalError, OperationalError):
-        # Some engines support adding all columns at once,
-        # this error is when they don't
-        _LOGGER.info("Unable to use quick column add. Adding 1 by 1")
+    #try:
+    #    connection.execute(
+    #        text(
+    #            "ALTER TABLE {table} {columns_def}".format(
+    #                table=table_name, columns_def=", ".join(columns_def)
+    #            )
+    #        )
+    #    )
+    #    return
+    #except (InternalError, OperationalError):
+    #    # Some engines support adding all columns at once,
+    #    # this error is when they don't
+    #    _LOGGER.info("Unable to use quick column add. Adding 1 by 1")

     for column_def in columns_def:
         try:
-            connection.execute(
-                text(
-                    "ALTER TABLE {table} {column_def}".format(
-                        table=table_name, column_def=column_def
+            with connection.begin_nested():
+                connection.execute(
+                    text(
+                        "ALTER TABLE {table} {column_def}".format(
+                            table=table_name, column_def=column_def
+                        )
                     )
                 )
-            )
-        except (InternalError, OperationalError) as err:
+        except Exception as err:
             raise_if_exception_missing_str(err, ["already exists", "duplicate"])
             _LOGGER.warning(
                 "Column %s already exists on %s, continuing",

What version of Home Assistant Core has the issue?

core-2021.12.5

What was the last working version of Home Assistant Core?

core-2021.6.6

What type of installation are you running?

Home Assistant Container

Integration causing the issue

Recorder

Link to integration documentation on our website

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

2022-01-03 18:50:00 WARNING (Recorder) [homeassistant.components.recorder.migration] Database is about to upgrade. Schema version: 16
2022-01-03 18:50:00 INFO (Recorder) [homeassistant.components.recorder.migration] Upgrading recorder db schema to version 17
2022-01-03 18:50:00 INFO (Recorder) [homeassistant.components.recorder.migration] Upgrade to version 17 done
2022-01-03 18:50:00 INFO (Recorder) [homeassistant.components.recorder.migration] Upgrading recorder db schema to version 18
2022-01-03 18:50:00 INFO (MainThread) [custom_components.hacs] Stage changed: HacsStage.STARTUP
2022-01-03 18:50:00 INFO (MainThread) [homeassistant.components.zeroconf] Starting Zeroconf broadcast
2022-01-03 18:50:00 INFO (MainThread) [custom_components.hacs] Executing task: load_hacs_repository
2022-01-03 18:50:00 INFO (MainThread) [custom_components.hacs] Loading known repositories
2022-01-03 18:50:01 INFO (Recorder) [homeassistant.components.recorder.migration] Upgrade to version 18 done
2022-01-03 18:50:01 INFO (Recorder) [homeassistant.components.recorder.migration] Upgrading recorder db schema to version 19
2022-01-03 18:50:01 INFO (Recorder) [homeassistant.components.recorder.migration] Upgrade to version 19 done
2022-01-03 18:50:01 INFO (Recorder) [homeassistant.components.recorder.migration] Upgrading recorder db schema to version 20
2022-01-03 18:50:01 WARNING (Recorder) [homeassistant.components.recorder.migration] Modifying columns mean, min, max, state, sum in table statistics. Note: this can take several minutes on large databases and slow computers. Please be patient!
2022-01-03 18:50:01 INFO (Recorder) [homeassistant.components.recorder.migration] Upgrade to version 20 done
2022-01-03 18:50:01 INFO (Recorder) [homeassistant.components.recorder.migration] Upgrading recorder db schema to version 21
2022-01-03 18:50:01 INFO (Recorder) [homeassistant.components.recorder.migration] Upgrade to version 21 done
2022-01-03 18:50:01 INFO (Recorder) [homeassistant.components.recorder.migration] Upgrading recorder db schema to version 22
2022-01-03 18:50:01 INFO (Recorder) [homeassistant.components.recorder.migration] Upgrade to version 22 done
2022-01-03 18:50:01 INFO (Recorder) [homeassistant.components.recorder.migration] Upgrading recorder db schema to version 23
2022-01-03 18:50:01 WARNING (Recorder) [homeassistant.components.recorder.migration] Adding columns name to table statistics_meta. Note: this can take several minutes on large databases and slow computers. Please be patient!
2022-01-03 18:50:01 ERROR (Recorder) [homeassistant.components.recorder.util] Error executing query: (psycopg2.errors.DuplicateColumn) column "name" of relation "statistics_meta" already exists

[SQL: ALTER TABLE statistics_meta ADD name VARCHAR(255)]
(Background on this error at: https://sqlalche.me/e/14/f405)
2022-01-03 18:50:01 ERROR (Recorder) [homeassistant.components.recorder] Database error during schema migration
Traceback (most recent call last):
  File "/usr/local/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1802, in _execute_context
    self.dialect.do_execute(
  File "/usr/local/lib/python3.9/site-packages/sqlalchemy/engine/default.py", line 719, in do_execute
    cursor.execute(statement, parameters)
psycopg2.errors.DuplicateColumn: column "name" of relation "statistics_meta" already exists

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

Traceback (most recent call last):
  File "/workspaces/mstovenour-home-assistant.git/homeassistant/components/recorder/__init__.py", line 760, in _migrate_schema_and_setup_run
    migration.migrate_schema(self, current_version)
  File "/workspaces/mstovenour-home-assistant.git/homeassistant/components/recorder/migration.py", line 78, in migrate_schema
    _apply_update(instance, session, new_version, current_version)
  File "/workspaces/mstovenour-home-assistant.git/homeassistant/components/recorder/migration.py", line 589, in _apply_update
    _add_columns(session, "statistics_meta", ["name VARCHAR(255)"])
  File "/workspaces/mstovenour-home-assistant.git/homeassistant/components/recorder/migration.py", line 200, in _add_columns
    connection.execute(
  File "/usr/local/lib/python3.9/site-packages/sqlalchemy/orm/session.py", line 1689, in execute
    result = conn._execute_20(statement, params or {}, execution_options)
  File "/usr/local/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1614, in _execute_20
    return meth(self, args_10style, kwargs_10style, execution_options)
  File "/usr/local/lib/python3.9/site-packages/sqlalchemy/sql/elements.py", line 325, in _execute_on_connection
    return connection._execute_clauseelement(
  File "/usr/local/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1481, in _execute_clauseelement
    ret = self._execute_context(
  File "/usr/local/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1845, in _execute_context
    self._handle_dbapi_exception(
  File "/usr/local/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 2026, in _handle_dbapi_exception
    util.raise_(
  File "/usr/local/lib/python3.9/site-packages/sqlalchemy/util/compat.py", line 207, in raise_
    raise exception
  File "/usr/local/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1802, in _execute_context
    self.dialect.do_execute(
  File "/usr/local/lib/python3.9/site-packages/sqlalchemy/engine/default.py", line 719, in do_execute
    cursor.execute(statement, parameters)
sqlalchemy.exc.ProgrammingError: (psycopg2.errors.DuplicateColumn) column "name" of relation "statistics_meta" already exists

[SQL: ALTER TABLE statistics_meta ADD name VARCHAR(255)]
(Background on this error at: https://sqlalche.me/e/14/f405)

Additional information

Running PostgreSQL

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

recorder documentation recorder source (message by IssueLinks)

probot-home-assistant[bot] commented 2 years 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! (message by CodeOwnersMention)

wfscot commented 2 years ago

FWIW, I encountered the same problem upgrading from 2021.2.3 to 2021.12. Also using Postgres. Relevant logs at https://gist.github.com/wfscot/c2bb9b0d87fc563900102ade8b54638a.

Let me know if you need any more info.

emontnemery commented 2 years ago

@mstovenour Can you verify the patch in #65680 please?

github-actions[bot] commented 2 years ago

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment šŸ‘ This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.