Update to 3.8 fails with relation "customuserattribute_seq" already exists

[Ma27]

Top-level intent

I tried to upgrade my PI instance from 3.7.4 to 3.8.

Steps to reproduce

1. Install PI at version 3.7.4
2. Update to 3.8
3. Run pi-manage db upgrade

Expected outcome

Upgrade working fine without any issues.

Actual outcome

DB migration failed like this:

(psycopg2.errors.DuplicateTable) relation "customuserattribute_seq" already exists

Context

This was probably introduced by #3384 which also creates the db sequence customuserattribute_seq even though the corresponding data-structures seem to exist since 3.6 which seems questionable on its own already.

I just installed another instance of PrivacyIDEA at version 3.7.4 and on that instance the sequence customuserattribute_seq also existed already, so updating this test instance to 3.8 would cause the same problem.

Configuration

• privacyIDEA version: 3.7.4, issue occurred while upgrading to 3.8
• Installation method: NixOS module (services.privacyidea
• Python version: 3.9.16
• Operating system: NixOS
• Webserver: nginx
• Token database: PostgreSQL 13.9

Log file

n/a

[cornelinux]

Are you sure, it fails? I guess it does not

If the sequence already exist, we simply output this information. So it should not fail or stop.
I.e. running

pi-manage db upgrade

a 2nd time should not result in an error - even if the sequence exist.

Please check,

a) if the sequence exists and
b) if the pi-manage db current -d .... output this:

Running online
006d4747f858 (head)

Note: In version 3.6 or 3.7 pi-manage did not create the customeruserattribute_seq. Maybe the nixos-install method did.
But this migrations script now only tries to add this sequence but does not fail, if it already exists.
See here:
https://github.com/privacyidea/privacyidea/blob/master/migrations/versions/a28f2733897b_.py#L32

Waiting for your comment, before closing this issue.

[Ma27]

(note: will comment in a week, currently on vacation)

[Ma27]

OK, just took another look.

It is correct that if the creation of the customeruserattribute_seq sequence fails the exception is printed and the migration is resumed:

Jan 17 09:03:09 primary privacyidea-pre-start[23499]: (psycopg2.errors.DuplicateTable) relation "customuserattribute_seq" already exists
Jan 17 09:03:09 primary privacyidea-pre-start[23499]: [SQL: CREATE SEQUENCE customuserattribute_seq]
Jan 17 09:03:09 primary privacyidea-pre-start[23499]: (Background on this error at: http://sqlalche.me/e/13/f405)

However, we're in a failed transaction then and psycopg2 refuses to continue:

Jan 17 09:03:09 primary privacyidea-pre-start[23499]: (psycopg2.errors.InFailedSqlTransaction) current transaction is aborted, commands ignored until end of transaction block
Jan 17 09:03:09 primary privacyidea-pre-start[23499]: [SQL: CREATE SEQUENCE tokengroup_seq]
Jan 17 09:03:09 primary privacyidea-pre-start[23499]: (Background on this error at: http://sqlalche.me/e/13/2j85)
Jan 17 09:03:09 primary privacyidea-pre-start[23499]: (psycopg2.errors.InFailedSqlTransaction) current transaction is aborted, commands ignored until end of transaction block
Jan 17 09:03:09 primary privacyidea-pre-start[23499]: [SQL: CREATE SEQUENCE tokentokengroup_seq]
Jan 17 09:03:09 primary privacyidea-pre-start[23499]: (Background on this error at: http://sqlalche.me/e/13/2j85)

Finally, when committing, an exception will be thrown (and not caught, hence the calltrace) and thus pi-manage db upgrade fails:

Jan 17 09:03:09 primary privacyidea-pre-start[23499]: psycopg2.errors.InFailedSqlTransaction: current transaction is aborted, commands ignored until end of transaction block
Jan 17 09:03:09 primary privacyidea-pre-start[23499]: The above exception was the direct cause of the following exception:
Jan 17 09:03:09 primary privacyidea-pre-start[23499]: Traceback (most recent call last):
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/pbb4csdm2iz7paz59s6vxzjk7g03mp8a-python3.9-privacyIDEA-3.8/bin/.pi-manage-wrapped", line 1739, in <module>
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     manager.run()
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/python3.9/site-packages/flask_script/__init__.py", line 417, in run
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     result = self.handle(argv[0], argv[1:])
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/python3.9/site-packages/flask_script/__init__.py", line 386, in handle
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     res = handle(*args, **config)
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/python3.9/site-packages/flask_script/commands.py", line 216, in __call__
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     return self.run(*args, **kwargs)
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/python3.9/site-packages/flask_migrate/__init__.py", line 96, in wrapped
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     f(*args, **kwargs)
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/python3.9/site-packages/flask_migrate/__init__.py", line 271, in upgrade
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     command.upgrade(config, revision, sql=sql, tag=tag)
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/python3.9/site-packages/alembic/command.py", line 322, in upgrade
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     script.run_env()
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/python3.9/site-packages/alembic/script/base.py", line 569, in run_env
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     util.load_python_file(self.dir, "env.py")
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/python3.9/site-packages/alembic/util/pyfiles.py", line 94, in load_python_file
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     module = load_module_py(module_id, path)
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/python3.9/site-packages/alembic/util/pyfiles.py", line 110, in load_module_py
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     spec.loader.exec_module(module)  # type: ignore
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "<frozen importlib._bootstrap_external>", line 850, in exec_module
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "<frozen importlib._bootstrap>", line 228, in _call_with_frames_removed
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/privacyidea/migrations/env.py", line 111, in <module>
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     run_migrations_online()
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/privacyidea/migrations/env.py", line 101, in run_migrations_online
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     context.run_migrations()
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "<string>", line 8, in run_migrations
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/python3.9/site-packages/alembic/runtime/environment.py", line 853, in run_migrations
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     self.get_context().run_migrations(**kw)
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/python3.9/site-packages/alembic/runtime/migration.py", line 630, in run_migrations
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     head_maintainer.update_to_step(step)
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/python3.9/site-packages/alembic/runtime/migration.py", line 854, in update_to_step
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     self._update_version(from_, to_)
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/python3.9/site-packages/alembic/runtime/migration.py", line 791, in _update_version
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     ret = self.context.impl._exec(
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/python3.9/site-packages/alembic/ddl/impl.py", line 195, in _exec
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     return conn.execute(construct, multiparams)
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1011, in execute
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     return meth(self, multiparams, params)
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/python3.9/site-packages/sqlalchemy/sql/elements.py", line 298, in _execute_on_connection
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     return connection._execute_clauseelement(self, multiparams, params)
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1124, in _execute_clauseelement
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     ret = self._execute_context(
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1316, in _execute_context
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     self._handle_dbapi_exception(
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1510, in _handle_dbapi_exception
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     util.raise_(
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/python3.9/site-packages/sqlalchemy/util/compat.py", line 182, in raise_
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     raise exception
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/python3.9/site-packages/sqlalchemy/engine/base.py", line 1276, in _execute_context
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     self.dialect.do_execute(
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:   File "/nix/store/splfvyzxipcd0289cvqnii6w22p23jfv-python3-3.9.16-env/lib/python3.9/site-packages/sqlalchemy/engine/default.py", line 608, in do_execute
Jan 17 09:03:09 primary privacyidea-pre-start[23499]:     cursor.execute(statement, parameters)
Jan 17 09:03:09 primary privacyidea-pre-start[23499]: sqlalchemy.exc.InternalError: (psycopg2.errors.InFailedSqlTransaction) current transaction is aborted, commands ignored until end of transaction block
Jan 17 09:03:09 primary privacyidea-pre-start[23499]: [SQL: UPDATE alembic_version SET version_num='a28f2733897b' WHERE alembic_version.version_num = '89e57ed16379']
Jan 17 09:03:09 primary privacyidea-pre-start[23499]: (Background on this error at: http://sqlalche.me/e/13/2j85)

When checking the current version of alembic in my test VM I get:

[root@primary:/var/lib/privacyidea]# su -l postgres -c "psql -d privacyidea <<<'select * from alembic_version'"
 version_num
--------------
 ef29ba43e290
(1 row)

This is a migration version from 3.7 which I deployed before into that test VM. That means that the entire migration transaction upon the 3.8 upgrade is not committed and thus pi-manage db upgrade retries the migration and fails again.

Hope this helps!

[plettich]

Hi @Ma27
unfortunately i could not reproduce this, neither with postgres 10 nor 13 (running in docker).
I am using the db driver psycopg2-binary==2.9.3.

[Ma27]

@plettich may I ask how you did it? As described in https://github.com/privacyidea/privacyidea#setup? Also, on which distro (and version)?

Asking because I'd like to check if I can get a reproducer on the setup you used (or if I find an error on my side while doing so :p)

[plettich]

@Ma27 mostly like described there.
I used the same virtualenv for both setups (with the requirements for v3.8).

1. checked out branch-3.7
2. create database, stamp database, add some data
3. checkout branch-3.8
4. run pi-manage db upgrade

[Ma27]

So tl;dr it is still reproducible for me.

Used components:

• Python 3.10.9
• virtualenv 20.16.5
• postgresql 11.8
• Config file (just a local testing thing, so using pw auth here):

SUPERUSER_REALM = ['super', 'administrators']
SQLALCHEMY_DATABASE_URI = 'postgresql://pi:snens@localhost/pi'
SECRET_KEY = 't0p s3cr3t'
PI_PEPPER = "Never know..."
PI_AUDIT_SQL_TRUNCATE = True
PI_ENCFILE = '/home/ma27/Projects/privacyidea/enckey'
PI_AUDIT_KEY_PRIVATE = '/home/ma27/Projects/privacyidea/private.pem'
PI_AUDIT_KEY_PUBLIC = '/home/ma27/Projects/privacyidea/public.pem'
PI_LOGCONFIG = './log.cfg'

What I did:

• git checkout tags/v3.7
• Setup (in virtualenv)
  • pip install -r requirements.txt
  • pip install psycopg2>=2.8.3
  • export PRIVACYIDEA_CONFIGFILE=$(pwd)/pi.cfg
  • ./pi-manage create_enckey
  • ./pi-manage create_audit_keys
    * ./pi-manage createdb
  • ./pi-manage admin add admin -e my@email.host -p snens
  • ./pi-manage db stamp head -d ./migrations/
  • ./pi-manage db upgrade -d ./migrations/
  • ./pi-manage runserver (and check that everything works fine).
• Upgrade to 3.8:
  • g checkout tags/v3.8
  • pip install -r requirements.txt
  • ./pi-manage db upgrade -d ./migrations/

The last commit fails with the error I reported above, i.e.:

$ ./pi-manage db upgrade -d ./migrations/
[2023-02-01 22:12:14,696][390083][140256179423040][INFO][privacyidea.lib.utils:1224] We are not able to determine the privacyidea version number.
[2023-02-01 22:12:14,696][390083][140256179423040][INFO][privacyidea.lib.utils:1224] We are not able to determine the privacyidea version number.

             _                    _______  _______
   ___  ____(_)  _____ _______ __/  _/ _ \/ __/ _ |
  / _ \/ __/ / |/ / _ `/ __/ // // // // / _// __ |
 / .__/_/ /_/|___/\_,_/\__/\_, /___/____/___/_/ |_|
/_/                       /___/
                                           vunknown

Running online
(psycopg2.errors.DuplicateTable) relation "customuserattribute_seq" already exists

[SQL: CREATE SEQUENCE customuserattribute_seq]
(Background on this error at: http://sqlalche.me/e/13/f405)
(psycopg2.errors.InFailedSqlTransaction) current transaction is aborted, commands ignored until end of transaction block

[SQL: CREATE SEQUENCE tokengroup_seq]
(Background on this error at: http://sqlalche.me/e/13/2j85)
(psycopg2.errors.InFailedSqlTransaction) current transaction is aborted, commands ignored until end of transaction block

[SQL: CREATE SEQUENCE tokentokengroup_seq]
(Background on this error at: http://sqlalche.me/e/13/2j85)
Traceback (most recent call last):
  File "/home/ma27/Projects/privacyidea/venv/lib/python3.10/site-packages/sqlalchemy/engine/base.py", line 1276, in _execute_context
    self.dialect.do_execute(
  File "/home/ma27/Projects/privacyidea/venv/lib/python3.10/site-packages/sqlalchemy/engine/default.py", line 608, in do_execute
    cursor.execute(statement, parameters)
psycopg2.errors.InFailedSqlTransaction: current transaction is aborted, commands ignored until end of transaction block


The above exception was the direct cause of the following exception:
(and the other backtraces, basically the same as above)

Did I miss something here or did I do something wrong during the upgrade procedure?

[plettich]

Ok, i could reproduce this now and found the issue. Please use postgresql+psycopg2://... for Your SQLALCHEMY_DATABASE_URI. This way the db engine for the upgrade will be created with the AUTOCOMMIT feature and will automatically rollback the transaction in case of an error.

[Ma27]

Yup that fixes the issue, thank you! %)