Nova DB migrations fail with timeout

[Bob Ball]

2013-07-11 15:41:00.262 | ======================================================================
2013-07-11 15:41:00.262 | FAIL: nova.tests.db.test_migrations.TestNovaMigrations.test_mysql_opportunistically
2013-07-11 15:41:00.262 | tags: worker-3
2013-07-11 15:41:00.262 | ----------------------------------------------------------------------
2013-07-11 15:41:00.262 | Empty attachments:
2013-07-11 15:41:00.262 | stderr
2013-07-11 15:41:00.262 | stdout
2013-07-11 15:41:00.262 |
2013-07-11 15:41:00.262 | pythonlogging:'': {{{
2013-07-11 15:41:00.262 | 132 -> 133...
2013-07-11 15:41:00.262 | Failed to migrate to version 133 on engine Engine(mysql+mysqldb://openstack_citest:openstack_citest@localhost/openstack_citest)
2013-07-11 15:41:00.262 | }}}
2013-07-11 15:41:00.262 |
2013-07-11 15:41:00.263 | Traceback (most recent call last):
2013-07-11 15:41:00.263 | File "/home/jenkins/workspace/gate-nova-python26/nova/tests/db/test_migrations.py", line 161, in test_mysql_opportunistically
2013-07-11 15:41:00.263 | self._test_mysql_opportunistically()
2013-07-11 15:41:00.263 | File "/home/jenkins/workspace/gate-nova-python26/nova/tests/db/test_migrations.py", line 317, in _test_mysql_opportunistically
2013-07-11 15:41:00.263 | self._walk_versions(engine, False, False)
2013-07-11 15:41:00.263 | File "/home/jenkins/workspace/gate-nova-python26/nova/tests/db/test_migrations.py", line 374, in _walk_versions
2013-07-11 15:41:00.263 | self._migrate_up(engine, version, with_data=True)
2013-07-11 15:41:00.263 | File "/home/jenkins/workspace/gate-nova-python26/nova/tests/db/test_migrations.py", line 432, in _migrate_up
2013-07-11 15:41:00.263 | self.migration_api.upgrade(engine, self.REPOSITORY, version)
2013-07-11 15:41:00.263 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/migrate/versioning/api.py", line 186, in upgrade
2013-07-11 15:41:00.263 | return _migrate(url, repository, version, upgrade=True, err=err, **opts)
2013-07-11 15:41:00.263 | File "<string>", line 2, in _migrate
2013-07-11 15:41:00.263 | File "/home/jenkins/workspace/gate-nova-python26/nova/db/sqlalchemy/migration.py", line 39, in patched_with_engine
2013-07-11 15:41:00.263 | return f(*a, **kw)
2013-07-11 15:41:00.263 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/migrate/versioning/api.py", line 366, in _migrate
2013-07-11 15:41:00.264 | schema.runchange(ver, change, changeset.step)
2013-07-11 15:41:00.264 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/migrate/versioning/schema.py", line 91, in runchange
2013-07-11 15:41:00.264 | change.run(self.engine, step)
2013-07-11 15:41:00.264 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/migrate/versioning/script/py.py", line 145, in run
2013-07-11 15:41:00.264 | script_func(engine)
2013-07-11 15:41:00.264 | File "/home/jenkins/workspace/gate-nova-python26/nova/db/sqlalchemy/migrate_repo/versions/133_folsom.py", line 1108, in upgrade
2013-07-11 15:41:00.264 | index.create(migrate_engine)
2013-07-11 15:41:00.264 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/sqlalchemy/schema.py", line 2277, in create
2013-07-11 15:41:00.264 | bind._run_visitor(ddl.SchemaGenerator, self)
2013-07-11 15:41:00.264 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/sqlalchemy/engine/base.py", line 2302, in _run_visitor
2013-07-11 15:41:00.264 | conn._run_visitor(visitorcallable, element, **kwargs)
2013-07-11 15:41:00.264 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/sqlalchemy/engine/base.py", line 1972, in _run_visitor
2013-07-11 15:41:00.264 | **kwargs).traverse_single(element)
2013-07-11 15:45:58.437 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/sqlalchemy/slibvir: error : internal error could not initialize domain event timer
2013-07-11 15:46:43.233 | ql/visitors.py", line 106, in traverse_single
2013-07-11 15:46:43.233 | return meth(obj, **kw)
2013-07-11 15:46:43.233 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/sqlalchemy/engine/ddl.py", line 102, in visit_index
2013-07-11 15:46:43.233 | self.connection.execute(schema.CreateIndex(index))
2013-07-11 15:46:43.233 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/sqlalchemy/engine/base.py", line 1449, in execute
2013-07-11 15:46:43.233 | params)
2013-07-11 15:46:43.233 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/sqlalchemy/engine/base.py", line 1542, in _execute_ddl
2013-07-11 15:46:43.233 | compiled
2013-07-11 15:46:43.234 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/sqlalchemy/engine/base.py", line 1691, in _execute_context
2013-07-11 15:46:43.234 | context)
2013-07-11 15:46:43.234 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/sqlalchemy/engine/default.py", line 331, in do_execute
2013-07-11 15:46:43.234 | cursor.execute(statement, parameters)
2013-07-11 15:46:43.234 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/MySQLdb/cursors.py", line 201, in execute
2013-07-11 15:46:43.234 | self.errorhandler(self, exc, value)
2013-07-11 15:46:43.234 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
2013-07-11 15:46:43.234 | raise errorclass, errorvalue
2013-07-11 15:46:43.234 | TimeoutException
2013-07-11 15:46:43.234 | ======================================================================
2013-07-11 15:46:43.234 | FAIL: nova.tests.db.test_migrations.TestNovaMigrations.test_postgresql_opportunistically
2013-07-11 15:46:43.234 | tags: worker-3
2013-07-11 15:46:43.234 | ----------------------------------------------------------------------
2013-07-11 15:46:43.234 | Empty attachments:
2013-07-11 15:46:43.234 | pythonlogging:''
2013-07-11 15:46:43.235 | stderr
2013-07-11 15:46:43.235 | stdout
2013-07-11 15:46:43.235 |
2013-07-11 15:46:43.235 | Traceback (most recent call last):
2013-07-11 15:46:43.235 | File "/home/jenkins/workspace/gate-nova-python26/nova/tests/db/test_migrations.py", line 173, in test_postgresql_opportunistically
2013-07-11 15:46:43.235 | self._test_postgresql_opportunistically()
2013-07-11 15:46:43.235 | File "/home/jenkins/workspace/gate-nova-python26/nova/tests/db/test_migrations.py", line 352, in _test_postgresql_opportunistically
2013-07-11 15:46:43.235 | self._reset_databases()
2013-07-11 15:46:43.235 | File "/home/jenkins/workspace/gate-nova-python26/nova/tests/db/test_migrations.py", line 299, in _reset_databases
2013-07-11 15:46:43.235 | self._reset_pg(conn_pieces)
2013-07-11 15:46:43.235 | File "/home/jenkins/workspace/gate-nova-python26/nova/openstack/common/lockutils.py", line 232, in inner
2013-07-11 15:46:43.235 | retval = f(*args, **kwargs)
2013-07-11 15:46:43.235 | File "/home/jenkins/workspace/gate-nova-python26/nova/tests/db/test_migrations.py", line 269, in _reset_pg
2013-07-11 15:46:43.235 | self.execute_cmd(createtable)
2013-07-11 15:46:43.236 | File "/home/jenkins/workspace/gate-nova-python26/nova/tests/db/test_migrations.py", line 246, in execute_cmd
2013-07-11 15:46:43.236 | status, output = commands.getstatusoutput(cmd)
2013-07-11 15:46:43.236 | File "/usr/lib64/python2.6/commands.py", line 56, in getstatusoutput
2013-07-11 15:46:43.236 | text = pipe.read()
2013-07-11 15:46:43.236 | File "/home/jenkins/workspace/gate-nova-python26/.tox/py26/lib/python2.6/site-packages/fixtures/_fixtures/timeout.py", line 52, in signal_handler
2013-07-11 15:46:43.236 | raise TimeoutException()
2013-07-11 15:46:43.236 | TimeoutException
2013-07-11 15:46:43.236 | ======================================================================

Failure at http://logs.openstack.org/36668/1/check/gate-nova-python26/27935/

[Boris Pavlovic (boris-42)]

pretty strange that it fails on first migariton script.

[Viktor Serhieiev (vsergeyev)]

Please give us more information about this bug.
This error happens every time or not? If not - can you please provide steps to reproduce.

[Bob Ball (bob-ball)]

This only occurred once in the gate for me. Re-running resolved this.

[OpenStack Infra (hudson-openstack)]

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

[Bob Ball (bob-ball)]

I'm concerned that I've now seen this twice - yet others don't seem to be seeing this... I can't see any possibly way it's a result of the change I've made though

[Kurt Taylor (krtaylor)]

Just came across this, similar to a problem I have also seen: https://bugs.launchpad.net/nova/+bug/1105284

[Joshua Hesketh (joshua.hesketh)]

Hi Bob,

Are you still having trouble running the tests. The timeout in .testr.conf was increased recently although extra stress was added to this function. Could you please try running the tests again against trunk and if it fails perhaps see how increasing the value for tests to timeout in .testr.conf goes.

Cheers,
Josh

[Bob Ball (bob-ball)]

I've not seen it anywhere other than gate - but I saw it on two separate changesets in gate. If the belief is it's been fixed, I'm happy for the issue to be closed. If it's seen again in gate then we'll clearly re-open it.