core: Recorder fails during FK creation on states table (MS SQL)

The problem

I use an MS SQL database for my recorder database. When I start Home Assistant, I get the error messages in the section below. It looks like an FK on the states table is being created incorrectly, and this prevents the states table from being upgraded. When I dropped all tables thinking that it would be recreated at the next start of Home Assistant, now it cannot create the states table at all. The other 3 tables did get recreated successfully though.

I believe this may be the same issue in #44736 that was fixed in PR #44757, however when I tried running Home Assistant 2021.1.0b2, which includes that PR, the issue is still present.

Environment

  • Home Assistant Core release with the issue: 2021.1.0 (still present in 2021.1.0b2, which included PR #44757 that should have fixed this for MySQL and Postgres)
  • Last working Home Assistant Core release (if known): unknown
  • Operating environment (OS/Container/Supervised/Core): Docker Container
  • Integration causing this issue: Recorder
  • Link to integration documentation on our website: https://www.home-assistant.io/integrations/recorder/

Problem-relevant configuration.yaml

The below is obfuscated to protect confidential data:

recorder:
  db_url: 'mssql+pyodbc://<login>:<password>@<instance>/<database>?charset=utf8;DRIVER={FreeTDS};Port=1433;'

Traceback/Error logs

1/8/2021 12:35:39 PM2021-01-08 17:35:39 ERROR (MainThread) [homeassistant.setup] Setup of recorder is taking longer than 300 seconds. Startup will proceed without waiting any longer
1/8/2021 12:35:40 PM2021-01-08 17:35:40 ERROR (Recorder) [sqlalchemy.pool.impl.QueuePool] Exception during reset or similar
1/8/2021 12:35:40 PMTraceback (most recent call last):
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1276, in _execute_context
1/8/2021 12:35:40 PM    self.dialect.do_execute(
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/default.py", line 593, in do_execute
1/8/2021 12:35:40 PM    cursor.execute(statement, parameters)
1/8/2021 12:35:40 PMpyodbc.ProgrammingError: ('42000', "[42000] [FreeTDS][SQL Server]Introducing FOREIGN KEY constraint 'FK__states__old_stat__6EF57B66' on table 'states' may cause cycles or multiple cascade paths. Specify ON DELETE NO ACTION or ON UPDATE NO ACTION, or modify other FOREIGN KEY constraints. (1785) (SQLExecDirectW)")
1/8/2021 12:35:40 PM
1/8/2021 12:35:40 PMDuring handling of the above exception, another exception occurred:
1/8/2021 12:35:40 PM
1/8/2021 12:35:40 PMTraceback (most recent call last):
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 749, in _rollback_impl
1/8/2021 12:35:40 PM    self.engine.dialect.do_rollback(self.connection)
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/default.py", line 543, in do_rollback
1/8/2021 12:35:40 PM    dbapi_connection.rollback()
1/8/2021 12:35:40 PMpyodbc.ProgrammingError: ('25000', '[25000] [FreeTDS][SQL Server]The ROLLBACK TRANSACTION request has no corresponding BEGIN TRANSACTION. (3903) (SQLEndTran)')
1/8/2021 12:35:40 PM
1/8/2021 12:35:40 PMThe above exception was the direct cause of the following exception:
1/8/2021 12:35:40 PM
1/8/2021 12:35:40 PMTraceback (most recent call last):
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 2087, in _optional_conn_ctx_manager
1/8/2021 12:35:40 PM    yield conn
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 2095, in _run_visitor
1/8/2021 12:35:40 PM    conn._run_visitor(visitorcallable, element, **kwargs)
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1656, in _run_visitor
1/8/2021 12:35:40 PM    visitorcallable(self.dialect, self, **kwargs).traverse_single(element)
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/sql/visitors.py", line 145, in traverse_single
1/8/2021 12:35:40 PM    return meth(obj, **kw)
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/sql/ddl.py", line 783, in visit_metadata
1/8/2021 12:35:40 PM    self.traverse_single(
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/sql/visitors.py", line 145, in traverse_single
1/8/2021 12:35:40 PM    return meth(obj, **kw)
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/sql/ddl.py", line 827, in visit_table
1/8/2021 12:35:40 PM    self.connection.execute(
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1011, in execute
1/8/2021 12:35:40 PM    return meth(self, multiparams, params)
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/sql/ddl.py", line 72, in _execute_on_connection
1/8/2021 12:35:40 PM    return connection._execute_ddl(self, multiparams, params)
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1068, in _execute_ddl
1/8/2021 12:35:40 PM    ret = self._execute_context(
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1316, in _execute_context
1/8/2021 12:35:40 PM    self._handle_dbapi_exception(
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1505, in _handle_dbapi_exception
1/8/2021 12:35:40 PM    self._autorollback()
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/util/langhelpers.py", line 82, in __exit__
1/8/2021 12:35:40 PM    compat.raise_(value, with_traceback=traceback)
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/util/compat.py", line 182, in raise_
1/8/2021 12:35:40 PM    raise exception
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1505, in _handle_dbapi_exception
1/8/2021 12:35:40 PM    self._autorollback()
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 888, in _autorollback
1/8/2021 12:35:40 PM    self._root._rollback_impl()
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 751, in _rollback_impl
1/8/2021 12:35:40 PM    self._handle_dbapi_exception(e, None, None, None, None)
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 1405, in _handle_dbapi_exception
1/8/2021 12:35:40 PM    util.raise_(
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/util/compat.py", line 182, in raise_
1/8/2021 12:35:40 PM    raise exception
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/base.py", line 749, in _rollback_impl
1/8/2021 12:35:40 PM    self.engine.dialect.do_rollback(self.connection)
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/default.py", line 543, in do_rollback
1/8/2021 12:35:40 PM    dbapi_connection.rollback()
1/8/2021 12:35:40 PMsqlalchemy.exc.ProgrammingError: (pyodbc.ProgrammingError) ('25000', '[25000] [FreeTDS][SQL Server]The ROLLBACK TRANSACTION request has no corresponding BEGIN TRANSACTION. (3903) (SQLEndTran)')
1/8/2021 12:35:40 PM(Background on this error at: http://sqlalche.me/e/13/f405)
1/8/2021 12:35:40 PM
1/8/2021 12:35:40 PMDuring handling of the above exception, another exception occurred:
1/8/2021 12:35:40 PM
1/8/2021 12:35:40 PMTraceback (most recent call last):
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/pool/base.py", line 697, in _finalize_fairy
1/8/2021 12:35:40 PM    fairy._reset(pool)
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/pool/base.py", line 893, in _reset
1/8/2021 12:35:40 PM    pool._dialect.do_rollback(self)
1/8/2021 12:35:40 PM  File "/usr/local/lib/python3.8/site-packages/sqlalchemy/engine/default.py", line 543, in do_rollback
1/8/2021 12:35:40 PM    dbapi_connection.rollback()
1/8/2021 12:35:40 PMpyodbc.ProgrammingError: ('25000', '[25000] [FreeTDS][SQL Server]The ROLLBACK TRANSACTION request has no corresponding BEGIN TRANSACTION. (3903) (SQLEndTran)')
1/8/2021 12:35:40 PM2021-01-08 17:35:40 ERROR (Recorder) [homeassistant.components.recorder] Error during connection setup: (pyodbc.ProgrammingError) ('25000', '[25000] [FreeTDS][SQL Server]The ROLLBACK TRANSACTION request has no corresponding BEGIN TRANSACTION. (3903) (SQLEndTran)')

Additional information

About this issue

  • Original URL
  • State: closed
  • Created 3 years ago
  • Reactions: 1
  • Comments: 21 (9 by maintainers)

Most upvoted comments

This probably will work, but it is a workaround. This is a bug and I will wait for official fix.

I have some reporting over the database and creating a new one is not a solution for me unfortunately