Mysql foreign key failure during db migration from 9 to 10

Bug #1233861 reported by Francois Deppierraz on 2013-10-01
22
This bug affects 3 people
Affects Status Importance Assigned to Milestone
Cinder
Critical
John Griffith
Fedora
Fix Released
Undecided

Bug Description

This happens during the upgrade from grizzly to havana using packages from the Ubuntu Cloud Archive on an Ubuntu 12.04.3 system.

root@openstack01:~# cinder-manage db sync
2013-10-01 23:35:04.977 7923 INFO migrate.versioning.api [-] 9 -> 10...
2013-10-01 23:35:05.000 7923 ERROR 010_add_transfers_table [-] Table |Table('transfers', MetaData(bind=Engine(mysql://cinder:eNgoyam3@127.0.0.1/cinder?charset=utf8)), Col
umn('created_at', DateTime(), table=<transfers>), Column('updated_at', DateTime(), table=<transfers>), Column('deleted_at', DateTime(), table=<transfers>), Column('delete
d', Boolean(), table=<transfers>), Column('id', String(length=36), table=<transfers>, primary_key=True, nullable=False), Column('volume_id', String(length=36), ForeignKey
('volumes.id'), table=<transfers>), Column('display_name', String(length=255), table=<transfers>), Column('salt', String(length=255), table=<transfers>), Column('crypt_ha
sh', String(length=255), table=<transfers>), Column('expires_at', DateTime(), table=<transfers>), schema=None)| not created!
2013-10-01 23:35:05.003 7923 CRITICAL cinder [-] (OperationalError) (1005, "Can't create table 'cinder.transfers' (errno: 150)") '\nCREATE TABLE transfers (\n\tcreated_at
 DATETIME, \n\tupdated_at DATETIME, \n\tdeleted_at DATETIME, \n\tdeleted BOOL, \n\tid VARCHAR(36) NOT NULL, \n\tvolume_id VARCHAR(36), \n\tdisplay_name VARCHAR(255), \n\t
salt VARCHAR(255), \n\tcrypt_hash VARCHAR(255), \n\texpires_at DATETIME, \n\tPRIMARY KEY (id), \n\tCHECK (deleted IN (0, 1)), \n\tFOREIGN KEY(volume_id) REFERENCES volume
s (id)\n)ENGINE=InnoDB\n\n' ()
2013-10-01 23:35:05.003 7923 TRACE cinder Traceback (most recent call last):
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/bin/cinder-manage", line 695, in <module>
2013-10-01 23:35:05.003 7923 TRACE cinder main()
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/bin/cinder-manage", line 692, in main
2013-10-01 23:35:05.003 7923 TRACE cinder fn(*fn_args)
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/bin/cinder-manage", line 228, in sync
2013-10-01 23:35:05.003 7923 TRACE cinder return migration.db_sync(version)
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/lib/python2.7/dist-packages/cinder/db/migration.py", line 33, in db_sync
2013-10-01 23:35:05.003 7923 TRACE cinder return IMPL.db_sync(version=version)
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/migration.py", line 77, in db_sync
2013-10-01 23:35:05.003 7923 TRACE cinder return versioning_api.upgrade(get_engine(), repository, version)
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/lib/python2.7/dist-packages/migrate/versioning/api.py", line 186, in upgrade
2013-10-01 23:35:05.003 7923 TRACE cinder return _migrate(url, repository, version, upgrade=True, err=err, **opts)
2013-10-01 23:35:05.003 7923 TRACE cinder File "<string>", line 2, in _migrate
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/migration.py", line 43, in patched_with_engine
2013-10-01 23:35:05.003 7923 TRACE cinder return f(*a, **kw)
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/lib/python2.7/dist-packages/migrate/versioning/api.py", line 366, in _migrate
2013-10-01 23:35:05.003 7923 TRACE cinder schema.runchange(ver, change, changeset.step)
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/lib/python2.7/dist-packages/migrate/versioning/schema.py", line 91, in runchange
2013-10-01 23:35:05.003 7923 TRACE cinder change.run(self.engine, step)
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/lib/python2.7/dist-packages/migrate/versioning/script/py.py", line 145, in run
2013-10-01 23:35:05.003 7923 TRACE cinder script_func(engine)
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/migrate_repo/versions/010_add_transfers_table.py", line 47, in upg
rade
2013-10-01 23:35:05.003 7923 TRACE cinder transfers.create()
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/lib/python2.7/dist-packages/sqlalchemy/schema.py", line 614, in create
2013-10-01 23:35:05.003 7923 TRACE cinder checkfirst=checkfirst)
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1479, in _run_visitor
2013-10-01 23:35:05.003 7923 TRACE cinder conn._run_visitor(visitorcallable, element, **kwargs)
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1122, in _run_visitor
2013-10-01 23:35:05.003 7923 TRACE cinder **kwargs).traverse_single(element)
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/lib/python2.7/dist-packages/sqlalchemy/sql/visitors.py", line 111, in traverse_single
2013-10-01 23:35:05.003 7923 TRACE cinder return meth(obj, **kw)
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/ddl.py", line 89, in visit_table
2013-10-01 23:35:05.003 7923 TRACE cinder self.connection.execute(schema.CreateTable(table))
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 662, in execute
2013-10-01 23:35:05.003 7923 TRACE cinder params)
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 720, in _execute_ddl
2013-10-01 23:35:05.003 7923 TRACE cinder compiled
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 874, in _execute_context
2013-10-01 23:35:05.003 7923 TRACE cinder context)
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1024, in _handle_dbapi_exception
2013-10-01 23:35:05.003 7923 TRACE cinder exc_info
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/lib/python2.7/dist-packages/sqlalchemy/util/compat.py", line 195, in raise_from_cause
2013-10-01 23:35:05.003 7923 TRACE cinder reraise(type(exception), exception, tb=exc_tb)
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 867, in _execute_context
2013-10-01 23:35:05.003 7923 TRACE cinder context)
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 324, in do_execute
2013-10-01 23:35:05.003 7923 TRACE cinder cursor.execute(statement, parameters)
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/lib/python2.7/dist-packages/MySQLdb/cursors.py", line 174, in execute
2013-10-01 23:35:05.003 7923 TRACE cinder self.errorhandler(self, exc, value)
2013-10-01 23:35:05.003 7923 TRACE cinder File "/usr/lib/python2.7/dist-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
2013-10-01 23:35:05.003 7923 TRACE cinder raise errorclass, errorvalue
2013-10-01 23:35:05.003 7923 TRACE cinder OperationalError: (OperationalError) (1005, "Can't create table 'cinder.transfers' (errno: 150)") '\nCREATE TABLE transfers (\n\
tcreated_at DATETIME, \n\tupdated_at DATETIME, \n\tdeleted_at DATETIME, \n\tdeleted BOOL, \n\tid VARCHAR(36) NOT NULL, \n\tvolume_id VARCHAR(36), \n\tdisplay_name VARCHAR
(255), \n\tsalt VARCHAR(255), \n\tcrypt_hash VARCHAR(255), \n\texpires_at DATETIME, \n\tPRIMARY KEY (id), \n\tCHECK (deleted IN (0, 1)), \n\tFOREIGN KEY(volume_id) REFERE
NCES volumes (id)\n)ENGINE=InnoDB\n\n' ()
2013-10-01 23:35:05.003 7923 TRACE cinder

mysql> SHOW ENGINE INNODB STATUS;
[...]
LATEST FOREIGN KEY ERROR
------------------------
131001 23:30:06 Error in foreign key constraint of table cinder/transfers:
FOREIGN KEY(volume_id) REFERENCES volumes (id) )ENGINE=InnoDB:
Cannot find an index in the referenced table where the
referenced columns appear as the first columns, or column types
in the table and the referenced table do not match for constraint.
Note that the internal storage type of ENUM and SET changed in
tables created with >= InnoDB-4.1.12, and such columns in old tables
cannot be referenced by such columns in new tables.
See http://dev.mysql.com/doc/refman/5.5/en/innodb-foreign-key-constraints.html
for correct foreign key definition.
[...]

Description of problem:
When upgrading from RHOS 2.1 to 3.0 (I'm using RDO) the cinder db migrate fails to add a new table.

Version-Release number of selected component (if applicable):
upgrade from 2.1 to 3.0

How reproducible:
evertime

Steps to Reproduce:
1. start with a working copy of 2.1
2. stop cinder services
3. yum update
4. update config files so you're using the new config files with the existing ips and users and passwords etc.
5. start services and do an cinder-manage db migrate.

Actual results:
OperationalError: (OperationalError) (1005, "Can't create table 'cinder.volume_glance_metadata' (errno: 150)") '\nCREATE TABLE volume_glance_metadata (\n\tcreated_at DATETIME, \n\tupdated_at DATETIME, \n\tdeleted_at DATETIME, \n\tdeleted BOOL, \n\tid INTEGER NOT NULL AUTO_INCREMENT, \n\tvolume_id VARCHAR(36), \n\tsnapshot_id VARCHAR(36), \n\t`key` VARCHAR(255), \n\tvalue TEXT, \n\tPRIMARY KEY (id), \n\tCHECK (deleted IN (0, 1)), \n\tFOREIGN KEY(volume_id) REFERENCES volumes (id), \n\tFOREIGN KEY(snapshot_id) REFERENCES snapshots (id)\n)ENGINE=InnoDB\n\n' ()
notice: /Stage[main]/Cinder::Api/Exec[cinder-manage db_sync]/returns: 2013-05-08 06:09:54 CRITICAL [cinder] (OperationalError) (1005, "Can't create table 'cinder.volume_glance_metadata' (errno: 150)") '\nCREATE TABLE volume_glance_metadata (\n\tcreated_at DATETIME, \n\tupdated_at DATETIME, \n\tdeleted_at DATETIME, \n\tdeleted BOOL, \n\tid INTEGER NOT NULL AUTO_INCREMENT, \n\tvolume_id VARCHAR(36), \n\tsnapshot_id VARCHAR(36), \n\t`key` VARCHAR(255), \n\tvalue TEXT, \n\tPRIMARY KEY (id), \n\tCHECK (deleted IN (0, 1)), \n\tFOREIGN KEY(volume_id) REFERENCES volumes (id), \n\tFOREIGN KEY(snapshot_id) REFERENCES snapshots (id)\n)ENGINE=InnoDB\n\n' ()

Expected results:
new table created

Additional info:
http://stackoverflow.com/questions/1457305/mysql-creating-tables-with-foreign-keys-giving-errno-150
suggests the relationships are a good starting point for a solution

F->G upstream upgrade testing (Grenade) seems to be working fine:
e.g. http://logs.openstack.org/28440/1/check/gate-grenade-devstack-vm/2643/console.html.gz

2013-05-07 17:25:34.174 | + cinder-manage db sync
2013-05-07 17:25:34.687 | 2013-05-07 17:25:34 INFO [migrate.versioning.api] 2 -> 3...
2013-05-07 17:25:34.723 | 2013-05-07 17:25:34 INFO [migrate.versioning.api] done
2013-05-07 17:25:34.724 | 2013-05-07 17:25:34 INFO [migrate.versioning.api] 3 -> 4...
2013-05-07 17:25:34.741 | 2013-05-07 17:25:34 INFO [004_volume_type_to_uuid] Created foreign key volume_type_extra_specs_ibfk_1
2013-05-07 17:25:34.744 | 2013-05-07 17:25:34 INFO [migrate.versioning.api] done
2013-05-07 17:25:34.745 | 2013-05-07 17:25:34 INFO [migrate.versioning.api] 4 -> 5...
2013-05-07 17:25:34.760 | 2013-05-07 17:25:34 INFO [migrate.versioning.api] done
2013-05-07 17:25:34.760 | 2013-05-07 17:25:34 INFO [migrate.versioning.api] 5 -> 6...
2013-05-07 17:25:34.780 | 2013-05-07 17:25:34 INFO [migrate.versioning.api] done
2013-05-07 17:25:34.780 | 2013-05-07 17:25:34 INFO [migrate.versioning.api] 6 -> 7...
2013-05-07 17:25:34.795 | 2013-05-07 17:25:34 INFO [migrate.versioning.api] done
2013-05-07 17:25:34.795 | 2013-05-07 17:25:34 INFO [migrate.versioning.api] 7 -> 8...
2013-05-07 17:25:34.805 | 2013-05-07 17:25:34 INFO [migrate.versioning.api] done
2013-05-07 17:25:34.817 | 2013-05-07 17:25:34 INFO [migrate.versioning.api] 8 -> 9...
2013-05-07 17:25:34.817 | 2013-05-07 17:25:34 INFO [migrate.versioning.api] done

Looks like you might have inconsistent (missing) data in volumes or snapshots tables?

> 5. start services and do an cinder-manage db migrate.

Which services you mean -db should be migrated before starting services.

Download full text (8.8 KiB)

so I've been using packstack to test my upgrade. I used RHOS 2.1 this time and follow the steps above.

For #5 I merged a generated packstack answer file with the original answer file from the install. Then I ran packstack --answer-file with the merged file. Results are the same. volumes and snapshots tables are empty as shown. cinder-manage db sync throws the same error I get when running packstack.

[root@radez ~(keystone_admin)]$ packstack --answer-file packstack-answers-20130509-150633.txt
Welcome to Installer setup utility
Packstack changed given value to required value /root/.ssh/id_rsa.pub

Installing:
Clean Up... [ DONE ]
Setting up ssh keys... [ DONE ]
Adding pre install manifest entries... [ DONE ]
Adding MySQL manifest entries... [ DONE ]
Adding QPID manifest entries... [ DONE ]
Adding Keystone manifest entries... [ DONE ]
Adding Glance Keystone manifest entries... [ DONE ]
Adding Glance manifest entries... [ DONE ]
Adding Cinder Keystone manifest entries... [ DONE ]
Installing dependencies for Cinder... [ DONE ]
Checking if the Cinder server has a cinder-volumes vg... [ DONE ]
Adding Cinder manifest entries... [ DONE ]
Adding Nova API manifest entries... [ DONE ]
Adding Nova Keystone manifest entries... [ DONE ]
Adding Nova Cert manifest entries... [ DONE ]
Adding Nova Conductor manifest entries... [ DONE ]
Adding Nova Compute manifest entries... [ DONE ]
Adding Nova Network manifest entries... [ DONE ]
Adding Nova Scheduler manifest entries... [ DONE ]
Adding Nova VNC Proxy manifest entries... [ DONE ]
Adding Nova Common manifest entries... [ DONE ]
Adding OpenStack Client manifest entries... [ DONE ]
Adding Horizon manifest entries... [ DONE ]
Preparing servers... [ DONE ]
Adding post install manifest entries... [ DONE ]
Installing Dependencies... [ DONE ]
Copying Puppet modules and manifests... [ DONE ]
Applying Puppet manifests...
Applying 10.13.128.22_prescript.pp
10.13.128.22_prescript.pp : [ DONE ]
Applying 10.13.128.22_mysql.pp
Applying 10.13.128.22_qpid.pp
10.13.128.22_mysql.pp : [ DONE ]
10.13.128.22_qpid.pp : [ DONE ]
Applying 10.13.128.22_keystone.pp
Applying 10.13.128.22_glance.pp
Applying 10.13.128.22_cinder.pp
10.13.128.22_keystone.pp : [ DONE ]

ERROR : Error during puppet run : notice: /Stage[main]/Cinder::Api/Exec[cinder-manage db_sync]/returns: OperationalError: (OperationalError) (1005, "Can't create table 'cinder.volume_glance_metad...

Read more...

I just reran my upgrade, but I ran cinder-manage db sync before I ran packstack, and the sync worked.

Used these steps:
1. install RHOS 2.1 using packstack
2. installed rdo-release
3. yum update
4. stoped cinder services
5. cinder-manage db sync
6. packstack --answer-file merged-ans-file.txt

after the packstack run RDO came up and seemed mostly happy.

So maybe this ends up being a packstack bug?

I'm not sure exactly what to make of this yet.

There are two cases here:

1) The initial failure. It looks like this is maybe expected because you have to run cinder-manage db sync before restarting the services?
2) Failure when using packstack to do an upgrade.

I tried to use packstack to upgrade from RHOS 2.1 to RDO as Dan did, basing my answer file on the RHOS 2.1 one and adding the required fields. Packstack says it completes successfully but the Cinder packages are still 2012.2.4. I'm not sure what is expected behavior -- can a packstack expert shed some light here? (Either way I didn't hit the same failure while using packstack.)

upgrades with packstack were never tested functionality so I'm not surprised your hitting problems. I'm not sure its something we would even want to attempt to support with packstack.

Of course we would want to allow people to upgrade an install that was originally setup with packstack. Do we know if this works with RHOS cinder where packstack was never involved?

Eric, I've just seen another error about packstack missing errors in the puppet logs, https://bugzilla.redhat.com/show_bug.cgi?id=965620 you may not still have them but if you do can you check the packstack logs for puppet errors, it may explain your false positive.

Eric, why is this still on Cinder?

Changing component to packstack -- the core of this issue is around what happens when you attempt to use packstack to upgrade. From Cinder's POV things are ok when following supported procedures.

The following workaround seems fixed the issue in my lab.

--- 010_add_transfers_table.py.orig 2013-10-01 23:27:19.357435528 +0200
+++ 010_add_transfers_table.py 2013-10-02 09:51:37.538980420 +0200
@@ -34,13 +34,13 @@
         Column('deleted_at', DateTime(timezone=False)),
         Column('deleted', Boolean),
         Column('id', String(36), primary_key=True, nullable=False),
- Column('volume_id', String(length=36), ForeignKey('volumes.id'),
- nullable=False),
+ Column('volume_id', String(length=36), ForeignKey('volumes.id')),
         Column('display_name', String(length=255)),
         Column('salt', String(length=255)),
         Column('crypt_hash', String(length=255)),
         Column('expires_at', DateTime(timezone=False)),
- mysql_engine='InnoDB'
+ mysql_engine='InnoDB',
+ mysql_charset='utf8'
     )

     try:

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

Changed in cinder:
assignee: nobody → Francois Deppierraz (francois-ctrlaltdel)
status: New → In Progress
Changed in cinder:
status: In Progress → Confirmed
importance: Undecided → Critical
assignee: Francois Deppierraz (francois-ctrlaltdel) → John Griffith (john-griffith)

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

Changed in cinder:
status: Confirmed → In Progress
Thierry Carrez (ttx) on 2013-10-15
tags: added: havana-rc-potential
Thierry Carrez (ttx) on 2013-10-15
Changed in cinder:
milestone: none → havana-rc3

Reviewed: https://review.openstack.org/51917
Committed: http://github.com/openstack/cinder/commit/645a84f990c90e28548cf35b4b5f242eb0e0c286
Submitter: Jenkins
Branch: master

commit 645a84f990c90e28548cf35b4b5f242eb0e0c286
Author: John Griffith <email address hidden>
Date: Tue Oct 15 13:57:48 2013 -0600

    FK lookup failures during migration

    There are a couple of cases where migrations have failed
    upgrading from Grizzly to Havana, this seems to be isolated
    to a couple of migrations so far and the error message is a
    failure to lookup/associate the volume-id FK dependency.

    It appears that this is caused by not setting the charset
    in the migration, so the result is that the initial db setup
    uses utf8 and the migrations are using the default latin1.

    This patch goes through all of the migrations in Havana that
    specify InnoDB and explicitly sets the charset to utf8 to match
    the volumes table (and the other original tables).

    Change-Id: I43b219ff5e4eea10a7391ad65ef68a80b7460370
    Closes-Bug: #1233861

Changed in cinder:
status: In Progress → Fix Committed

Reviewed: https://review.openstack.org/51975
Committed: http://github.com/openstack/cinder/commit/5e489f475f4fe0529280f419b4708aa22c13ad39
Submitter: Jenkins
Branch: milestone-proposed

commit 5e489f475f4fe0529280f419b4708aa22c13ad39
Author: John Griffith <email address hidden>
Date: Tue Oct 15 13:57:48 2013 -0600

    FK lookup failures during migration

    There are a couple of cases where migrations have failed
    upgrading from Grizzly to Havana, this seems to be isolated
    to a couple of migrations so far and the error message is a
    failure to lookup/associate the volume-id FK dependency.

    It appears that this is caused by not setting the charset
    in the migration, so the result is that the initial db setup
    uses utf8 and the migrations are using the default latin1.

    This patch goes through all of the migrations in Havana that
    specify InnoDB and explicitly sets the charset to utf8 to match
    the volumes table (and the other original tables).

    Change-Id: I43b219ff5e4eea10a7391ad65ef68a80b7460370
    Closes-Bug: #1233861
    (cherry picked from commit 645a84f990c90e28548cf35b4b5f242eb0e0c286)

Changed in cinder:
status: Fix Committed → Fix Released
Thierry Carrez (ttx) on 2013-10-17
Changed in cinder:
milestone: havana-rc3 → 2013.2

I believe this has been fixed in Cinder 2013.2.

Auto adding >= MODIFIED bugs to beta

Folsom to Grizzly or Folsom to Havana will not be tested Grizzly to Havana was tested by Ami's team using

http://shell.bos.redhat.com/~lkellogg/rhos-upgrade-docs/database-upgrades.html

I am moving this to verified.

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHEA-2013-1859.html

Changed in fedora:
importance: Unknown → Undecided
status: Unknown → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Duplicates of this bug

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.