Seeing odd timeouts in the db test_migrations
======================================================================
2013-09-19 20:19:52.147 | FAIL: nova.tests.db.test_migrations.TestNovaMigrations.test_mysql_opportunistically
2013-09-19 20:19:52.147 | tags: worker-2
2013-09-19 20:19:52.147 | ----------------------------------------------------------------------
2013-09-19 20:19:52.147 | Empty attachments:
2013-09-19 20:19:52.148 | stderr
2013-09-19 20:19:52.148 | stdout
2013-09-19 20:19:52.148 |
2013-09-19 20:19:52.148 | pythonlogging:'': {{{
2013-09-19 20:19:52.148 | 132 -> 133...
2013-09-19 20:19:52.148 | done
2013-09-19 20:19:52.148 | 133 -> 134...
2013-09-19 20:19:52.149 | done
2013-09-19 20:19:52.149 | 134 -> 135...
2013-09-19 20:19:52.149 | done
2013-09-19 20:19:52.149 | 135 -> 136...
2013-09-19 20:19:52.149 | done
2013-09-19 20:19:52.149 | 136 -> 137...
2013-09-19 20:19:52.149 | done
2013-09-19 20:19:52.150 | 137 -> 138...
2013-09-19 20:19:52.150 | done
2013-09-19 20:19:52.150 | 138 -> 139...
2013-09-19 20:19:52.150 | done
2013-09-19 20:19:52.150 | 139 -> 140...
2013-09-19 20:19:52.150 | done
2013-09-19 20:19:52.150 | 140 -> 141...
2013-09-19 20:19:52.151 | done
2013-09-19 20:19:52.151 | 141 -> 142...
2013-09-19 20:19:52.151 | done
2013-09-19 20:19:52.151 | 142 -> 143...
2013-09-19 20:19:52.151 | done
2013-09-19 20:19:52.151 | 143 -> 144...
2013-09-19 20:19:52.151 | done
2013-09-19 20:19:52.151 | 144 -> 145...
2013-09-19 20:19:52.152 | done
2013-09-19 20:19:52.152 | 145 -> 146...
2013-09-19 20:19:52.152 | done
2013-09-19 20:19:52.152 | 146 -> 147...
2013-09-19 20:19:52.152 | done
2013-09-19 20:19:52.152 | 147 -> 148...
2013-09-19 20:19:52.152 | Failed to migrate to version 148 on engine Engine(mysql+mysqldb://openstack_citest:openstack_citest@localhost/openstack_citest)
2013-09-19 20:19:52.153 | }}}
2013-09-19 20:19:52.153 |
2013-09-19 20:19:52.153 | Traceback (most recent call last):
2013-09-19 20:19:52.153 | File "nova/tests/db/test_migrations.py", line 162, in test_mysql_opportunistically
2013-09-19 20:19:52.153 | self._test_mysql_opportunistically()
2013-09-19 20:19:52.153 | File "nova/tests/db/test_migrations.py", line 321, in _test_mysql_opportunistically
2013-09-19 20:19:52.153 | self._walk_versions(engine, False, False)
2013-09-19 20:19:52.154 | File "nova/tests/db/test_migrations.py", line 378, in _walk_versions
2013-09-19 20:19:52.154 | self._migrate_up(engine, version, with_data=True)
2013-09-19 20:19:52.154 | File "nova/tests/db/test_migrations.py", line 436, in _migrate_up
2013-09-19 20:19:52.154 | self.migration_api.upgrade(engine, self.REPOSITORY, version)
2013-09-19 20:19:52.154 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/migrate/versioning/api.py", line 186, in upgrade
2013-09-19 20:19:52.154 | return _migrate(url, repository, version, upgrade=True, err=err, **opts)
2013-09-19 20:19:52.154 | File "<string>", line 2, in _migrate
2013-09-19 20:19:52.155 | File "nova/db/sqlalchemy/migration.py", line 40, in patched_with_engine
2013-09-19 20:19:52.155 | return f(*a, **kw)
2013-09-19 20:19:52.155 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/migrate/versioning/api.py", line 366, in _migrate
2013-09-19 20:19:52.155 | schema.runchange(ver, change, changeset.step)
2013-09-19 20:19:52.155 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/migrate/versioning/schema.py", line 91, in runchange
2013-09-19 20:19:52.155 | change.run(self.engine, step)
2013-09-19 20:19:52.155 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/migrate/versioning/script/py.py", line 145, in run
2013-09-19 20:19:52.156 | script_func(engine)
2013-09-19 20:19:52.156 | File "/home/jenkins/workspace/gate-nova-python27/nova/db/sqlalchemy/migrate_repo/versions/148_add_instance_actions.py", line 67, in upgrade
2013-09-19 20:19:52.156 | instance_actions.create()
2013-09-19 20:19:52.156 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/schema.py", line 593, in create
2013-09-19 20:19:52.156 | checkfirst=checkfirst)
2013-09-19 20:19:52.156 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 2302, in _run_visitor
2013-09-19 20:19:52.156 | conn._run_visitor(visitorcallable, element, **kwargs)
2013-09-19 20:19:52.157 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1972, in _run_visitor
2013-09-19 20:19:58.686 | **kwargs).traverse_single(element)
2013-09-19 20:19:58.686 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/sql/visitors.py", line 106, in traverse_single
2013-09-19 20:19:58.686 | return meth(obj, **kw)
2013-09-19 20:19:58.687 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/ddl.py", line 86, in visit_table
2013-09-19 20:19:58.687 | self.connection.execute(schema.CreateTable(table))
2013-09-19 20:19:58.687 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1449, in execute
2013-09-19 20:19:58.687 | params)
2013-09-19 20:19:58.687 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1542, in _execute_ddl
2013-09-19 20:19:58.688 | compiled
2013-09-19 20:19:58.688 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1691, in _execute_context
2013-09-19 20:19:58.688 | context)
2013-09-19 20:19:58.688 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 331, in do_execute
2013-09-19 20:19:58.688 | cursor.execute(statement, parameters)
2013-09-19 20:19:58.688 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/MySQLdb/cursors.py", line 201, in execute
2013-09-19 20:19:58.688 | self.errorhandler(self, exc, value)
2013-09-19 20:19:58.689 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
2013-09-19 20:19:58.689 | raise errorclass, errorvalue
2013-09-19 20:19:58.689 | TimeoutException
2013-09-19 20:19:58.689 | ======================================================================
2013-09-19 20:19:58.689 | FAIL: nova.tests.db.test_migrations.TestNovaMigrations.test_postgresql_opportunistically
2013-09-19 20:19:58.690 | tags: worker-2
2013-09-19 20:19:58.690 | ----------------------------------------------------------------------
2013-09-19 20:19:58.690 | Empty attachments:
2013-09-19 20:19:58.690 | stderr
2013-09-19 20:19:58.690 | stdout
2013-09-19 20:19:58.690 |
2013-09-19 20:19:58.690 | pythonlogging:'': {{{
2013-09-19 20:19:58.691 | 132 -> 133...
2013-09-19 20:19:58.691 | done
2013-09-19 20:19:58.691 | 133 -> 134...
2013-09-19 20:19:58.691 | done
2013-09-19 20:19:58.691 | 134 -> 135...
2013-09-19 20:19:58.691 | done
2013-09-19 20:19:58.691 | 135 -> 136...
2013-09-19 20:19:58.692 | done
2013-09-19 20:19:58.692 | 136 -> 137...
2013-09-19 20:19:58.692 | done
2013-09-19 20:19:58.692 | 137 -> 138...
2013-09-19 20:19:58.692 | done
2013-09-19 20:19:58.692 | 138 -> 139...
2013-09-19 20:19:58.693 | done
2013-09-19 20:19:58.693 | 139 -> 140...
2013-09-19 20:19:58.693 | done
2013-09-19 20:19:58.693 | 140 -> 141...
2013-09-19 20:19:58.693 | done
2013-09-19 20:19:58.693 | 141 -> 142...
2013-09-19 20:19:58.693 | done
2013-09-19 20:19:58.694 | 142 -> 143...
2013-09-19 20:19:58.694 | done
2013-09-19 20:19:58.694 | 143 -> 144...
2013-09-19 20:19:58.694 | done
2013-09-19 20:19:58.694 | 144 -> 145...
2013-09-19 20:19:58.694 | done
2013-09-19 20:19:58.694 | 145 -> 146...
2013-09-19 20:19:58.695 | done
2013-09-19 20:19:58.695 | 146 -> 147...
2013-09-19 20:19:58.695 | done
2013-09-19 20:19:58.695 | 147 -> 148...
2013-09-19 20:19:58.695 | done
2013-09-19 20:19:58.695 | 148 -> 149...
2013-09-19 20:19:58.696 | done
2013-09-19 20:19:58.696 | 149 -> 150...
2013-09-19 20:19:58.696 | done
2013-09-19 20:19:58.696 | 150 -> 151...
2013-09-19 20:19:58.696 | done
2013-09-19 20:19:58.696 | 151 -> 152...
2013-09-19 20:19:58.696 | done
2013-09-19 20:19:58.697 | 152 -> 153...
2013-09-19 20:19:58.697 | done
2013-09-19 20:19:58.697 | Failed to migrate to version 154 on engine Engine(postgresql+psycopg2://openstack_citest:openstack_citest@localhost/openstack_citest)
2013-09-19 20:19:58.697 | }}}
2013-09-19 20:19:58.698 |
2013-09-19 20:19:58.698 | Traceback (most recent call last):
2013-09-19 20:19:58.698 | File "nova/tests/db/test_migrations.py", line 174, in test_postgresql_opportunistically
2013-09-19 20:19:58.698 | self._test_postgresql_opportunistically()
2013-09-19 20:19:58.698 | File "nova/tests/db/test_migrations.py", line 357, in _test_postgresql_opportunistically
2013-09-19 20:19:58.698 | self._walk_versions(engine, False, False)
2013-09-19 20:19:58.699 | File "nova/tests/db/test_migrations.py", line 378, in _walk_versions
2013-09-19 20:19:58.699 | self._migrate_up(engine, version, with_data=True)
2013-09-19 20:19:58.699 | File "nova/tests/db/test_migrations.py", line 434, in _migrate_up
2013-09-19 20:19:58.699 | data = pre_upgrade(engine)
2013-09-19 20:19:58.699 | File "nova/tests/db/test_migrations.py", line 928, in _pre_upgrade_154
2013-09-19 20:19:58.699 | meta.reflect(engine)
2013-09-19 20:19:58.700 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/schema.py", line 2548, in reflect
2013-09-19 20:19:58.700 | Table(name, self, **reflect_opts)
2013-09-19 20:19:58.700 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/schema.py", line 318, in __new__
2013-09-19 20:19:58.700 | table._init(name, metadata, *args, **kw)
2013-09-19 20:19:58.700 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/schema.py", line 381, in _init
2013-09-19 20:19:58.701 | self._autoload(metadata, autoload_with, include_columns)
2013-09-19 20:19:58.701 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/schema.py", line 397, in _autoload
2013-09-19 20:19:58.701 | self, include_columns, exclude_columns
2013-09-19 20:19:58.701 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 2425, in run_callable
2013-09-19 20:19:58.701 | return conn.run_callable(callable_, *args, **kwargs)
2013-09-19 20:19:58.701 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1968, in run_callable
2013-09-19 20:19:58.701 | return callable_(self, *args, **kwargs)
2013-09-19 20:26:20.634 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 260, in reflecttable
2013-09-19 20:26:20.634 | return insp.reflecttable(table, include_columns, exclude_columns)
2013-09-19 20:26:20.634 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/reflection.py", line 370, in reflecttable
2013-09-19 20:26:20.634 | for col_d in self.get_columns(table_name, schema, **tblkw):
2013-09-19 20:26:20.634 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/reflection.py", line 223, in get_columns
2013-09-19 20:26:20.634 | **kw)
2013-09-19 20:26:20.635 | File "<string>", line 1, in <lambda>
2013-09-19 20:26:20.635 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/reflection.py", line 47, in cache
2013-09-19 20:26:20.635 | ret = fn(self, con, *args, **kw)
2013-09-19 20:26:20.635 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/dialects/postgresql/base.py", line 1335, in get_columns
2013-09-19 20:26:20.635 | enums = self._load_enums(connection)
2013-09-19 20:26:20.635 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/dialects/postgresql/base.py", line 1646, in _load_enums
2013-09-19 20:26:20.635 | c = connection.execute(s)
2013-09-19 20:26:20.636 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1449, in execute
2013-09-19 20:26:20.636 | params)
2013-09-19 20:26:20.636 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1584, in _execute_clauseelement
2013-09-19 20:26:20.636 | compiled_sql, distilled_params
2013-09-19 20:26:20.636 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1651, in _execute_context
2013-09-19 20:26:20.636 | None, None)
2013-09-19 20:26:20.637 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/base.py", line 1647, in _execute_context
2013-09-19 20:26:20.637 | context = constructor(dialect, self, conn, *args)
2013-09-19 20:26:20.637 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/engine/default.py", line 452, in _init_compiled
2013-09-19 20:26:20.637 | processors = compiled._bind_processors
2013-09-19 20:26:20.637 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/util/langhelpers.py", line 496, in __get__
2013-09-19 20:26:20.637 | obj.__dict__[self.__name__] = result = self.fget(obj)
2013-09-19 20:26:20.637 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/sqlalchemy/sql/compiler.py", line 308, in _bind_processors
2013-09-19 20:26:20.638 | for bindparam in self.bind_names )
2013-09-19 20:26:20.638 | File "/home/jenkins/workspace/gate-nova-python27/.tox/py27/local/lib/python2.7/site-packages/fixtures/_fixtures/timeout.py", line 52, in signal_handler
2013-09-19 20:26:20.638 | raise TimeoutException()
2013-09-19 20:26:20.638 | StatementError: (original cause: TimeoutException) '\n SELECT t.typname as "name",\n -- no enum defaults in 8.4 at least\n -- t.typdefault as "default",\n pg_catalog.pg_type_is_visible(t.oid) as "visible",\n n.nspname as "schema",\n e.enumlabel as "label"\n FROM pg_catalog.pg_type t\n LEFT JOIN pg_catalog.pg_namespace n ON n.oid = t.typnamespace\n LEFT JOIN pg_catalog.pg_enum e ON t.oid = e.enumtypid\n WHERE t.typtype = \'e\'\n ORDER BY "name", e.oid -- e.oid gives us label order\n ' []
2013-09-19 20:26:20.638 | ======================================================================
This happens due to the per test timeout in Nova's testr config. If that timeout isn't sufficient it should be increased in Nova itself. I have removed openstack-ci and added nova to the bug for this reason.