Setting up database schema with db_sync fails in migration 039 (SQLITE)

Bug #1371620 reported by David Charles Kennedy
12
This bug affects 2 people
Affects Status Importance Assigned to Milestone
OpenStack Identity (keystone)
Fix Released
Medium
Nathan Kinder
keystone (Ubuntu)
Fix Released
High
Unassigned

Bug Description

A fresh clone of master (commit ee4ee3b7f570d448f9053547febd86591e600697) won't set up the database.

On a fresh install of ubuntu 12.04.3 (yes, I know, but it's what I had kicking about) in a VM (Vmware), with no special config except for web proxies (excluding localhost) I followed

http://docs.openstack.org/developer/keystone/setup.html

and, once able to import keystone

http://docs.openstack.org/developer/keystone/developing.html

up to the point of running

bin/keystone-manage db_sync

this last command results in a stack trace as follows:

(.venv)david@ubuntu:~/keystone$ bin/keystone-manage db_sync
2014-09-19 06:54:16.321 12991 CRITICAL keystone [-] OperationalError: (OperationalError) database is locked u'DELETE FROM user_project_metadata' ()
2014-09-19 06:54:16.321 12991 TRACE keystone Traceback (most recent call last):
2014-09-19 06:54:16.321 12991 TRACE keystone File "bin/keystone-manage", line 44, in <module>
2014-09-19 06:54:16.321 12991 TRACE keystone cli.main(argv=sys.argv, config_files=config_files)
2014-09-19 06:54:16.321 12991 TRACE keystone File "/home/david/keystone/keystone/cli.py", line 307, in main
2014-09-19 06:54:16.321 12991 TRACE keystone CONF.command.cmd_class.main()
2014-09-19 06:54:16.321 12991 TRACE keystone File "/home/david/keystone/keystone/cli.py", line 74, in main
2014-09-19 06:54:16.321 12991 TRACE keystone migration_helpers.sync_database_to_version(extension, version)
2014-09-19 06:54:16.321 12991 TRACE keystone File "/home/david/keystone/keystone/common/sql/migration_helpers.py", line 204, in sync_database_to_version
2014-09-19 06:54:16.321 12991 TRACE keystone _sync_common_repo(version)
2014-09-19 06:54:16.321 12991 TRACE keystone File "/home/david/keystone/keystone/common/sql/migration_helpers.py", line 160, in _sync_common_repo
2014-09-19 06:54:16.321 12991 TRACE keystone init_version=init_version)
2014-09-19 06:54:16.321 12991 TRACE keystone File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/oslo/db/sqlalchemy/migration.py", line 79, in db_sync
2014-09-19 06:54:16.321 12991 TRACE keystone return versioning_api.upgrade(engine, repository, version)
2014-09-19 06:54:16.321 12991 TRACE keystone File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/migrate/versioning/api.py", line 186, in upgrade
2014-09-19 06:54:16.321 12991 TRACE keystone return _migrate(url, repository, version, upgrade=True, err=err, **opts)
2014-09-19 06:54:16.321 12991 TRACE keystone File "<string>", line 2, in _migrate
2014-09-19 06:54:16.321 12991 TRACE keystone File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/migrate/versioning/util/__init__.py", line 160, in with_engine
2014-09-19 06:54:16.321 12991 TRACE keystone return f(*a, **kw)
2014-09-19 06:54:16.321 12991 TRACE keystone File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/migrate/versioning/api.py", line 366, in _migrate
2014-09-19 06:54:16.321 12991 TRACE keystone schema.runchange(ver, change, changeset.step)
2014-09-19 06:54:16.321 12991 TRACE keystone File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/migrate/versioning/schema.py", line 93, in runchange
2014-09-19 06:54:16.321 12991 TRACE keystone change.run(self.engine, step)
2014-09-19 06:54:16.321 12991 TRACE keystone File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/migrate/versioning/script/py.py", line 148, in run
2014-09-19 06:54:16.321 12991 TRACE keystone script_func(engine)
2014-09-19 06:54:16.321 12991 TRACE keystone File "/home/david/keystone/keystone/common/sql/migrate_repo/versions/039_grant_to_assignment.py", line 223, in upgrade
2014-09-19 06:54:16.321 12991 TRACE keystone migrate_grant_table(meta, migrate_engine, session, table_name)
2014-09-19 06:54:16.321 12991 TRACE keystone File "/home/david/keystone/keystone/common/sql/migrate_repo/versions/039_grant_to_assignment.py", line 85, in migrate_grant_table
2014-09-19 06:54:16.321 12991 TRACE keystone migrate_engine.execute(upgrade_table.delete())
2014-09-19 06:54:16.321 12991 TRACE keystone File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1752, in execute
2014-09-19 06:54:16.321 12991 TRACE keystone return connection.execute(statement, *multiparams, **params)
2014-09-19 06:54:16.321 12991 TRACE keystone File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 729, in execute
2014-09-19 06:54:16.321 12991 TRACE keystone return meth(self, multiparams, params)
2014-09-19 06:54:16.321 12991 TRACE keystone File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/sqlalchemy/sql/elements.py", line 321, in _execute_on_connection
2014-09-19 06:54:16.321 12991 TRACE keystone return connection._execute_clauseelement(self, multiparams, params)
2014-09-19 06:54:16.321 12991 TRACE keystone File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 826, in _execute_clauseelement
2014-09-19 06:54:16.321 12991 TRACE keystone compiled_sql, distilled_params
2014-09-19 06:54:16.321 12991 TRACE keystone File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 958, in _execute_context
2014-09-19 06:54:16.321 12991 TRACE keystone context)
2014-09-19 06:54:16.321 12991 TRACE keystone File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1156, in _handle_dbapi_exception
2014-09-19 06:54:16.321 12991 TRACE keystone util.raise_from_cause(newraise, exc_info)
2014-09-19 06:54:16.321 12991 TRACE keystone File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/sqlalchemy/util/compat.py", line 199, in raise_from_cause
2014-09-19 06:54:16.321 12991 TRACE keystone reraise(type(exception), exception, tb=exc_tb)
2014-09-19 06:54:16.321 12991 TRACE keystone File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 951, in _execute_context
2014-09-19 06:54:16.321 12991 TRACE keystone context)
2014-09-19 06:54:16.321 12991 TRACE keystone File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 436, in do_execute
2014-09-19 06:54:16.321 12991 TRACE keystone cursor.execute(statement, parameters)
2014-09-19 06:54:16.321 12991 TRACE keystone OperationalError: (OperationalError) database is locked u'DELETE FROM user_project_metadata' ()
2014-09-19 06:54:16.321 12991 TRACE keystone

repeating the command gets the same result (same point of failure - 039_grant_to_assignment.py). I cannot initialise the database so it can be no suprise that running tools/sample_data.sh doesn't succeed.

2014-09-19 07:03:16.105 13337 TRACE keystone.common.wsgi File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/sqlalchemy/orm/persistence.py", line 570, in _emit_insert_statements
2014-09-19 07:03:16.105 13337 TRACE keystone.common.wsgi execute(statement, multiparams)
2014-09-19 07:03:16.105 13337 TRACE keystone.common.wsgi File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 729, in execute
2014-09-19 07:03:16.105 13337 TRACE keystone.common.wsgi return meth(self, multiparams, params)
2014-09-19 07:03:16.105 13337 TRACE keystone.common.wsgi File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/sqlalchemy/sql/elements.py", line 321, in _execute_on_connection
2014-09-19 07:03:16.105 13337 TRACE keystone.common.wsgi return connection._execute_clauseelement(self, multiparams, params)
2014-09-19 07:03:16.105 13337 TRACE keystone.common.wsgi File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 826, in _execute_clauseelement
2014-09-19 07:03:16.105 13337 TRACE keystone.common.wsgi compiled_sql, distilled_params
2014-09-19 07:03:16.105 13337 TRACE keystone.common.wsgi File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 958, in _execute_context
2014-09-19 07:03:16.105 13337 TRACE keystone.common.wsgi context)
2014-09-19 07:03:16.105 13337 TRACE keystone.common.wsgi File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1156, in _handle_dbapi_exception
2014-09-19 07:03:16.105 13337 TRACE keystone.common.wsgi util.raise_from_cause(newraise, exc_info)
2014-09-19 07:03:16.105 13337 TRACE keystone.common.wsgi File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/sqlalchemy/util/compat.py", line 199, in raise_from_cause
2014-09-19 07:03:16.105 13337 TRACE keystone.common.wsgi reraise(type(exception), exception, tb=exc_tb)
2014-09-19 07:03:16.105 13337 TRACE keystone.common.wsgi File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 951, in _execute_context
2014-09-19 07:03:16.105 13337 TRACE keystone.common.wsgi context)
2014-09-19 07:03:16.105 13337 TRACE keystone.common.wsgi File "/home/david/keystone/.venv/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 436, in do_execute
2014-09-19 07:03:16.105 13337 TRACE keystone.common.wsgi cursor.execute(statement, parameters)
2014-09-19 07:03:16.105 13337 TRACE keystone.common.wsgi OperationalError: (OperationalError) table service has no column named enabled u'INSERT INTO service (id, type, enabled, extra) VALUES (?, ?, ?, ?)' ('37d8cf9ccdb146e4b88b23a7152bffcc', u'object-store', 1, '{"name": "swift", "description": "Swift Service"}')
2014-09-19 07:03:16.105 13337 TRACE keystone.common.wsgi
An unexpected error prevented the server from fulfilling your request. (HTTP 500)

So I appear to be hosed. However, I believe I cloned about a week ago and ran the same process on another machine (laptop, xubuntu 14.04) with some success - so is this a bug that has been introduced in a recent commit?

Changed in keystone:
status: New → Incomplete
Revision history for this message
Steve Martinelli (stevemar) wrote :

Looks like an issue in upgrade script 39, specifically the migrate_grant_table function. Not really sure whats going on.

Changed in keystone:
status: Incomplete → New
Revision history for this message
Dolph Mathews (dolph) wrote :

This looks to be a potential RC blocker if it's blocking people from installing master/Juno.

tags: added: juno-rc-potential
Changed in keystone:
importance: Undecided → High
Revision history for this message
Dolph Mathews (dolph) wrote :

(I'm hoping it's just because the DB was in a strange state though.)

David: were you able to reproduce this behavior more than once?

Revision history for this message
Morgan Fainberg (mdrnstm) wrote :

I've tried multiple ways to duplicate this issue (venv, no venv, old VM, new VM, 12.04, 14.04) and I can't seem to duplicate the issue. There haven't been any recent changes to migration 039. If you can provide me with a little more insight to how you got wedged here that would be great.

Since this is a new install, it would be possble to just drop the Keystone DB (there should be no info in the DB yet) and recreate it, allowing you to re-run db_sync.

Changed in keystone:
importance: High → Undecided
status: New → Incomplete
Revision history for this message
Morgan Fainberg (mdrnstm) wrote :

Ah, this is a SQLite issue. I believe I know what the fix will end up being, looking into it now.

Changed in keystone:
status: Incomplete → Confirmed
importance: Undecided → Medium
summary: - Setting up database schema with db_sync fails with OperationalError:
- (OperationalError) database is locked u'DELETE FROM
- user_project_metadata' ()
+ Setting up database schema with db_sync fails in migration 039 (SQLITE)
tags: added: db sqlite
tags: added: sql
removed: db
Changed in keystone:
milestone: none → juno-rc1
tags: added: icehouse-backport-potential
Changed in keystone:
assignee: nobody → David Stanek (dstanek)
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to keystone (master)

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

Changed in keystone:
status: Confirmed → In Progress
Changed in keystone:
assignee: David Stanek (dstanek) → Nathan Kinder (nkinder)
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to keystone (master)

Reviewed: https://review.openstack.org/124533
Committed: https://git.openstack.org/cgit/openstack/keystone/commit/?id=4da0bccfef467036d83fc87b51c962438004d9f0
Submitter: Jenkins
Branch: master

commit 4da0bccfef467036d83fc87b51c962438004d9f0
Author: David Stanek <email address hidden>
Date: Fri Sep 26 22:34:07 2014 +0000

    Uses session in migration to stop DB locking

    Using both the engine and session in a migration causes the DB to
    become locked.

    Change-Id: Icbd867ff4e385f4430bfa9b7c5680b870475176d
    Closes-bug: #1371620

Changed in keystone:
status: In Progress → Fix Committed
Revision history for this message
David Charles Kennedy (dkennedy-p) wrote :

Good work Morgan, David, Dolph.

I am sorry, I've been offline for the whole weekend so I didn't get to respond to Dolph's query. Yes, it was totally reproducible (as I think Dolph established) and eventually I resolved my particular roadblock by using mysql to get going but it's good to see the fix going in.

When I have a moment I'll update from master and just check it over but I don't doubt the fix.

Thanks, all.

James Page (james-page)
Changed in keystone (Ubuntu):
importance: Undecided → High
status: New → Triaged
Revision history for this message
Launchpad Janitor (janitor) wrote :

This bug was fixed in the package keystone - 1:2014.2~b3-0ubuntu2

---------------
keystone (1:2014.2~b3-0ubuntu2) utopic; urgency=medium

  * Start failing package builds on unit test failures again:
    - d/rules: Fail build on any test failures.
    - d/p/skip-pysaml2.patch: Skip federation tests for now as pysaml2 is
      not yet in Ubuntu main and federation is only a contrib module.
    - d/p/bug-1371620.patch: Cherry pick fix from upstream VCS for db locking
      issues with sqlite during package install (LP: #1371620).
    - d/p/bug-1367354.patch: Cherry pick fix from upstream VCS to ensure that
      downgrade tests on sqlite complete successfully (LP: #1367354).
    - d/control: Add missing python-ldappool to BD's.
  * d/control: Align version requirements for pycadf and six with upstream.
  * d/p/series: Re-enable disabled add-version-info.patch.
 -- James Page <email address hidden> Mon, 29 Sep 2014 15:34:45 +0100

Changed in keystone (Ubuntu):
status: Triaged → Fix Released
Thierry Carrez (ttx)
Changed in keystone:
status: Fix Committed → Fix Released
Thierry Carrez (ttx)
Changed in keystone:
milestone: juno-rc1 → 2014.2
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

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