wrong migration version record in DB

[Valeriy Ponomaryov]

Alembic[?] writes wrong version of current migration that leads to errors with further actions with migrations. Because it tries to run migrations that already are applied.

Here is logs for clean installation:

$ manila-manage db sync
2015-07-10 18:56:09.519 DEBUG manila.utils [-] backend <module 'manila.db.migrations.alembic.migration' from '/opt/stack/manila/manila/db/migrations/alembic/migration.pyc'> from (pid=19435) __get_backend /opt/stack/manila/manila/utils.py:172
2015-07-10 18:56:09.535 DEBUG oslo_db.sqlalchemy.session [-] MySQL server mode set to STRICT_TRANS_TABLES,STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,TRADITIONAL,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION from (pid=19435) _check_effective_sql_mode /usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/session.py:513
2015-07-10 18:56:09.538 INFO alembic.migration [-] Context impl MySQLImpl.
2015-07-10 18:56:09.538 INFO alembic.migration [-] Will assume non-transactional DDL.
2015-07-10 18:56:09.585 INFO alembic.migration [-] Running upgrade -> 162a3e673105, manila_init
2015-07-10 18:56:10.270 DEBUG alembic.migration [-] new branch insert 162a3e673105 from (pid=19435) update_to_step /usr/local/lib/python2.7/dist-packages/alembic/migration.py:470
2015-07-10 18:56:10.274 INFO alembic.migration [-] Running upgrade 162a3e673105 -> 211836bf835c, add access level
2015-07-10 18:56:10.288 DEBUG alembic.migration [-] update 162a3e673105 to 211836bf835c from (pid=19435) update_to_step /usr/local/lib/python2.7/dist-packages/alembic/migration.py:493
2015-07-10 18:56:10.292 INFO alembic.migration [-] Running upgrade 211836bf835c -> 38e632621e5a, change volume_type to share_type
2015-07-10 18:56:10.292 INFO 38e632621e5a_change_volume_type_to_share_type_py [-] Renaming column name shares.volume_type_id to shares.share_type.id
2015-07-10 18:56:10.307 INFO 38e632621e5a_change_volume_type_to_share_type_py [-] Renaming volume_types table to share_types
2015-07-10 18:56:10.349 INFO 38e632621e5a_change_volume_type_to_share_type_py [-] Creating share_type_extra_specs table
2015-07-10 18:56:10.410 INFO 38e632621e5a_change_volume_type_to_share_type_py [-] Migrating volume_type_extra_specs to share_type_extra_specs
2015-07-10 18:56:10.413 INFO 38e632621e5a_change_volume_type_to_share_type_py [-] Dropping volume_type_extra_specs table
2015-07-10 18:56:10.446 DEBUG alembic.migration [-] update 211836bf835c to 38e632621e5a from (pid=19435) update_to_step /usr/local/lib/python2.7/dist-packages/alembic/migration.py:493
2015-07-10 18:56:10.454 INFO alembic.migration [-] Running upgrade 38e632621e5a -> 17115072e1c3, add_nova_net_id_column_to_share_networks
2015-07-10 18:56:10.610 DEBUG alembic.migration [-] update 38e632621e5a to 17115072e1c3 from (pid=19435) update_to_step /usr/local/lib/python2.7/dist-packages/alembic/migration.py:493
2015-07-10 18:56:10.733 INFO alembic.migration [-] Running upgrade 17115072e1c3 -> 4ee2cf4be19a, Remove share_snapshots.export_location
2015-07-10 18:56:11.436 DEBUG alembic.migration [-] update 17115072e1c3 to 4ee2cf4be19a from (pid=19435) update_to_step /usr/local/lib/python2.7/dist-packages/alembic/migration.py:493
2015-07-10 18:56:11.444 INFO alembic.migration [-] Running upgrade 4ee2cf4be19a -> 59eb64046740, Add required extra spec
/usr/local/lib/python2.7/dist-packages/sqlalchemy/sql/default_comparator.py:153: SAWarning: The IN-predicate on "share_types.id" was invoked with an empty sequence. This results in a contradiction, which nonetheless can be expensive to evaluate. Consider alternative strategies for improved performance.
  'strategies for improved performance.' % expr)
2015-07-10 18:56:11.450 DEBUG alembic.migration [-] update 4ee2cf4be19a to 59eb64046740 from (pid=19435) update_to_step /usr/local/lib/python2.7/dist-packages/alembic/migration.py:493
2015-07-10 18:56:11.523 INFO alembic.migration [-] Running upgrade 59eb64046740 -> ef0c02b4366, Add_share_type_projects
2015-07-10 18:56:11.991 DEBUG alembic.migration [-] update 59eb64046740 to ef0c02b4366 from (pid=19435) update_to_step /usr/local/lib/python2.7/dist-packages/alembic/migration.py:493
2015-07-10 18:56:11.992 INFO alembic.migration [-] Running upgrade ef0c02b4366 -> 30cb96d995fa, add public column for share
2015-07-10 18:56:12.14 DEBUG alembic.migration [-] update ef0c02b4366 to 30cb96d995fa from (pid=19435) update_to_step /usr/local/lib/python2.7/dist-packages/alembic/migration.py:493
2015-07-10 18:56:12.15 INFO alembic.migration [-] Running upgrade 30cb96d995fa -> 56cdbe267881, Add share_export_locations table
2015-07-10 18:56:12.52 DEBUG alembic.migration [-] update 30cb96d995fa to 56cdbe267881 from (pid=19435) update_to_step /usr/local/lib/python2.7/dist-packages/alembic/migration.py:493
2015-07-10 18:56:12.53 INFO alembic.migration [-] Running upgrade 56cdbe267881 -> 3a482171410f, add_driver_private_data_table
2015-07-10 18:56:12.63 DEBUG alembic.migration [-] update 56cdbe267881 to 3a482171410f from (pid=19435) update_to_step /usr/local/lib/python2.7/dist-packages/alembic/migration.py:493
2015-07-10 18:56:12.64 INFO alembic.migration [-] Running upgrade 3a482171410f -> 533646c7af38, Remove unused attr status
2015-07-10 18:56:12.103 DEBUG alembic.migration [-] update 3a482171410f to 533646c7af38 from (pid=19435) update_to_step /usr/local/lib/python2.7/dist-packages/alembic/migration.py:493
2015-07-10 18:56:12.104 INFO alembic.migration [-] Running upgrade 533646c7af38 -> 3db9992c30f3, Transform statuses to lowercase
2015-07-10 18:56:12.177 DEBUG alembic.migration [-] update 533646c7af38 to 3db9992c30f3 from (pid=19435) update_to_step /usr/local/lib/python2.7/dist-packages/alembic/migration.py:493

-----------------------

mysql> select version_num from alembic_version;
+--------------+
| version_num |
+--------------+
| 3a482171410f |
+--------------+
1 row in set (0.01 sec)

-----------------------

Alembic did not count last two versions '533646c7af38' and '3db9992c30f3'.
If we downgrade it to first, we will have DB record having value of second migration '211836bf835c' and not first '162a3e673105'.

==========
WORKAROUND
==========

Workaround is to change value of current version in DB:

DB 'manila'
table 'alembic_version'
set here version_num to required value:

UPDATE alembic_version SET version_num = 'fooversion';

[Valeriy Ponomaryov (vponomaryov)]

Proof that CI has such problem: http://logs.openstack.org/22/200622/3/check/gate-manila-tempest-dsvm-neutron/1e4df60/logs/devstacklog.txt.gz#_2015-07-11_15_14_19_686

[Valeriy Ponomaryov (vponomaryov)]

Some digging-up discovered that problems appear with oslo.db equal to or greater than version 1.12.0

Where one of big changes for this version - usage of "PyMySQL" lib, pure python lib instead of C-based "MySQL-python".

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/200848

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/200848
Committed: https://git.openstack.org/cgit/openstack/manila/commit/?id=503203e243d42d26d73d0aef16774871b3496d6d
Submitter: Jenkins
Branch: master

commit 503203e243d42d26d73d0aef16774871b3496d6d
Author: Valeriy Ponomaryov <email address hidden>
Date: Sun Jul 12 00:04:22 2015 +0300

    Close DB migration sessions explicitly for compatibility with PyMySQL

    oslo.db lib starting with version 1.12.0 uses PyMySQL as mysql client.
    We get problem with it as it does not close opened sessions by default.
    And if we do some actions with migration sessions and do not close sessions,
    then alembic, as db migration tool does not write to DB updated migration
    version, that is final step of each migration.
    It breaks further attempts to perform some migration actions in case some
    migration can not be applied twice. Because of improper versions in DB,
    alembic tries to execute same migrations again and again.

    So, close migration sessions explicitly since PyMySQL does not do it itself.
    Also, print version in devstack for getting more details in future debug of
    devstack installation output.

    Change-Id: I5c729f10bac23b1853e18127b50b1d9f053ab629
    Closes-Bug: #1473400